diff --git a/perl-xCAT/xCAT/Enabletrace.pm b/perl-xCAT/xCAT/Enabletrace.pm new file mode 100644 index 000000000..ad75a8280 --- /dev/null +++ b/perl-xCAT/xCAT/Enabletrace.pm @@ -0,0 +1,53 @@ +#!/usr/bin/env perl +# IBM(c) 2007 EPL license http://www.eclipse.org/legal/epl-v10.html + +package xCAT::Enabletrace; +use Filter::Util::Call; + +our @ISA = qw(Exporter); +our @EXPORT_OK = qw(loadtrace filter); + +sub loadtrace{ + my (undef, $filename) = caller(); + my (%args) = ( + filename => $filename, + inside => 0, + lineno => 0, + ); + + filter_add(bless \%args); +} + +sub filter { + my ($self) = @_; + my $line= filter_read(); + $self->{lineno}++; + # deal with EOF/error first + if ($line<= 0) { + if ($self->{inside}) { + die "Do not find the END of the trace block. [$self->{filename}:$self->{lineno}]"; + } + return $line; + } + if ($self->{inside}) { + if (/^\s*##\s*TRACE_BEGIN/ ) { + die "The trace block is nested. [$self->{filename}:$self->{lineno}]"; + } elsif (/^\s*##\s*TRACE_END/) { + $self->{inside} = 0; + } else { + # remove the #.. at the begin of the line + s/^\s*#+//; + } + } elsif ( /^\s*##\s*TRACE_BEGIN/ ) { + $self->{inside} = 1; + } elsif ( /^\s*##\s*TRACE_END/ ) { + die "Do not see the BEGIN of the trace block. [$self->{filename}:$self->{lineno}]"; + } elsif ( /^\s*##\s*TRACE_LINE/ ) { + s/^\s*##\s*TRACE_LINE//; + } + + return $line; + } + + +1; diff --git a/perl-xCAT/xCAT/MsgUtils.pm b/perl-xCAT/xCAT/MsgUtils.pm index b97e6657d..77e2a8803 100644 --- a/perl-xCAT/xCAT/MsgUtils.pm +++ b/perl-xCAT/xCAT/MsgUtils.pm @@ -616,6 +616,8 @@ sub start_logging $::LOG_FILE_HANDLE = \*LOGFILE; $::LOG_FILE_NAME = $logfile; + # Make the file to be unbuffered + binmode( $::LOG_FILE_HANDLE, ":unix" ); # Print the program name and date to the top of the logfile my $sdate = `/bin/date`; chomp $sdate; diff --git a/xCAT-client/pods/man8/xcatdebug.8.pod b/xCAT-client/pods/man8/xcatdebug.8.pod index 8368f0823..42233e8bf 100644 --- a/xCAT-client/pods/man8/xcatdebug.8.pod +++ b/xCAT-client/pods/man8/xcatdebug.8.pod @@ -1,48 +1,152 @@ =head1 NAME -B - Starts the xCAT daemon (xcatd) in trace mode. +B - Enable or disable the trace facilities for xCAT. -B {B} +B { [B<-f enable|disable> [B<-c configuration file | subroutine list>]] | [ B<-d enable |disable>]} =head1 DESCRIPTION -The xcatdebug command starts the xcatd daemon in Perl Debug Trace mode. It is to be used for diagnosing xCAT problems. The trace outputs the paramters passed into the xcatd subroutines, listed in the tracefiles. The tracefiles are located in /opt/xcat/share/xcat/tools/tracelevel. The amount of trace data collected varies with the levelnumber. levelnumber 0 being the least amount of trace and increasing with the number. You can add more tracelevel files to suit the problem being debugged. +xCAT offers two trace facilities to debug the xCAT: -You must have perl-Debug-Trace installed. +=over 3 -Before running this command, you should stop xcatd on your system. -After running the command, you will have to kill all the xcatd processes and possibly the xcatdebug process. -Run ps -ef | grep xcatd and kill any processes -Run ps -ef | grep xcatdebug +=item * + +B + +Display the calling trace for subroutine when it is called. + +The trace message includes: The name of the called subroutine; The arguments which passed to the called subroutine; The calling stack of the subroutine. By default, the trace will be enabled to all the subroutines in the xcatd and plugin modules. The target subroutine can be configured by configuration file or through xcatdebug command line. + +The flag B<-c> is used to specify the subroutine list for B, it can only work with B<-f>. The value of B<-c> can be a configuration file or a subroutine list. + B: a file contains multiple lines of B + B: B|B|... + +B: is the element for the B<-c> to specify the subroutine list. + +The format of B: [plugin](subroutine1,subroutine2,...) + +If ignoring the [plugin], the subroutines in the () should be defined in the xcatd. + e.g. (daemonize,do_installm_service,do_udp_service) + +Otherwise, the package name of the plugin should be specified. + e.g. xCAT::Utils(isMN,Version) + e.g. xCAT_plugin::DBobjectdefs(defls,process_request) + +The trace log will be written to /var/log/xcat/subcallingtrace. The log file subcallingtrace will be backed up for each running of the B. + + +=item * + +B + +The trace log code is presented as comments in the code of xCAT. In general mode, it will be kept as comments. But in debug mode, it will be commented back as common code to display the trace log. + +NOTE: This facility can be enabled by pass the B global variable when running the xcatd. e.g. ENABLE_TRACE_CODE=1 xcatd -f + +This facility offers two formats for the trace log code: + +=over 2 + +=item * + +Trace section + ## TRACE_BEGIN + # print "In the debug\n"; + ## TRACE_END + +=item * + +Trace in a single line + ## TRACE_LINE print "In the trace line\n"; + +=back + +The B can be added in xcatd and plugin modules. But following section has been added into the BEGIN {} section of the target plugin module to enable the facility. + + if (defined $ENV{ENABLE_TRACE_CODE}) { + use xCAT::Enabletrace qw(loadtrace filter); + loadtrace(); + } + +=back =head1 OPTIONS =over 6 -=item B +=item B<-f> -The levelnumber that will be run. This determines the filename of trace input - from /opt/xcat/share/xcat/tools/tracelevel +Enable or disable the B. -=back +For B, if ignoring the B<-c> flag, all the subroutines in the xcatd and plugin modules will be enabled. -=head1 ENVIRONMENT VARIABLES +For B, all the subroutines which has been enabled by B<-f enable> will be disabled. B<-c> will be ignored. -=head1 EXAMPLES +=item B<-c> + +Specify the configuration file or subroutine list. =over 2 =item * -Run the xcatdebug routine with /opt/xcat/share/xcat/tools/tracelevel0 and output to the screen: +B: a file contains multiple lines of B + e.g. + (plugin_command) + xCAT_plugin::DBobjectdefs(defls,process_request) + xCAT::DBobjUtils(getobjdefs) + +=item * +B: a string like B|B|... + e.g. + "(plugin_command)|xCAT_plugin::DBobjectdefs(defls,process_request)|xCAT::DBobjUtils(getobjdefs)" + +=back + +=item B<-d> + +Enable or disable the B. + +Note: The xcatd will be restarted for the performing of B<-d>. + +=back + + +=head1 EXAMPLES + +=over 4 + +=item 1 + +Enable the B for all the subroutines in the xcatd and plugin modules. + B -f enable + +=item 2 + +Enable the B for the subroutines configured in the /opt/xcat/share/xcat/tools/tracelevel0 + B -f enable -c /opt/xcat/share/xcat/tools/tracelevel0 + +=item 3 + +Enable the B for the plugin_command in xcatd and defls,process_request in the xCAT_plugin::DBobjectdefs module. + B -f enable -c "xCAT_plugin::DBobjectdefs(defls,process_request)|(plugin_command)" + +=item 4 + +Disable the B for all the subroutines which have been enabled by B. + B -f disable + +=item 5 + +Enable the B + B -d enable + +=item 6 + +Enable both the B and B + B -f enable -c /opt/xcat/share/xcat/tools/tracelevel0 -d enable -B I<0> - -=item * - -Run the xcatdebug routine with /opt/xcat/share/xcat/tools/tracelevel1 and output to /tmp/traceoutput: - -B I<1> > /tmp/traceoutput 2>&1 =back diff --git a/xCAT-server/sbin/xcatd b/xCAT-server/sbin/xcatd index e88cc314e..e7e373d4d 100755 --- a/xCAT-server/sbin/xcatd +++ b/xCAT-server/sbin/xcatd @@ -9,6 +9,13 @@ BEGIN # Required when using DB2 as the xCAT database: $ENV{'DB2INSTANCE'} = 'xcatdb'; $ENV{'EXTSHM'} = 'ON'; + + if (defined $ENV{ENABLE_TRACE_CODE}) { + use lib "$ENV{'XCATROOT'}/lib/perl"; + use lib "/opt/xcat/lib/perl"; + use xCAT::Enabletrace qw(loadtrace filter); + loadtrace(); + } } # if AIX - make sure we include perl 5.8.2 in INC path. @@ -72,7 +79,7 @@ $XML::Simple::PREFERRED_PARSER='XML::Parser'; use xCAT::Table; my $dbmaster; use xCAT::ExtTab; -#use Data::Dumper; +use Data::Dumper; use Getopt::Long; use Sys::Syslog qw(:DEFAULT setlogsock); openlog("xcatd",,"local4"); @@ -700,6 +707,10 @@ unless ($pid_MON) { } $$progname="xcatd: SSL listener"; +# Enable the signals for the subroutine calling trace +$SIG{NUM50} = \&enable_callingtrace; +$SIG{NUM51} = \&disable_callingtrace; + #setup signal in NotifHandler so that the cache can be updated xCAT::NotifHandler::setup($$, $dbmaster); @@ -2000,3 +2011,210 @@ sub validate { return 0; } + +# Enable the trace of subroutine calling. +# Replace the original subroutine with a trace added subroutine to output more debug trace +sub enable_callingtrace{ + my $enableall = 0; # if $enableall=1, enable trace for all the functions of xcat + my @pluginfuncs = (); # function list that will be enabled for plugins + my @xcatdfuncs = (); # function list that will be enabled for xcatd + + + # Backup the trace log + my ($sec,$min,$hour,$mday,$mon,$year) = localtime(); + $year -= 100; + $mon += 1; + my $time = sprintf "%02s%02s%02s%02s%02s%02s", $year, $mon, $mday, $hour, $min, $sec; + if (-e "/var/log/xcat/subcallingtrace") { + system("mv /var/log/xcat/subcallingtrace /var/log/xcat/subcallingtrace$time"); + } + + # Start the trace log + xCAT::MsgUtils->start_logging("subcallingtrace"); + + # Read the subroutine list from the configuration file + if (-f "/tmp/xcatcallingtrace.cfg") { + if (! open (FUNLIST, "message("SL", "Enable subroutine calling trace failed: cannot open /tmp/xcatcallingtrace.cfg"); + xCAT::MsgUtils->stop_logging(); + return 1; + } + my $cfg = ; + chomp($cfg); + my @funlist; + if (-f $cfg) { # Specified a configuration file + if (! open (CFG, "<$cfg")) { + xCAT::MsgUtils->message("SL", "Enable subroutine calling trace failed: cannot open $cfg"); + xCAT::MsgUtils->stop_logging(); + return 1; + } else { # read the configuration file + while () { + push @funlist, $_; + } + close (CFG); + } + } else { + # Specified the function list + # The format of the function list should be package(func1,func2,...),package(func1,func2,...) + push @funlist, split /\|/, $cfg; + } + + # Parse the function list + foreach (@funlist) { + if (/(.*::.*)\((.*)\)/) { # if the format is xCAT::plugin(f1,f2) + my $pkg = $1; + my @funcs = split /,/, $2; + foreach (@funcs) { + chomp; + s/^\s*//; + push @pluginfuncs, "\*".$pkg."::".$_; + } + } else { # if the format is f1,f2, only for the functions in the xcatd + s/^\s*\(//; + s/\)\s*$//; + my @funcs = split /,/; + foreach (@funcs) { + chomp; + s/^\s*//; + push @xcatdfuncs, "\*main::".$_; + } + } + } + close (FUNLIST); + } else { + $enableall = 1; + } + + no strict 'refs'; + + my @debugfuns = (); + # Get the functions of xcatd + my $xcatdpath = $::XCATROOT."/sbin/xcatd"; + if (! open (XCATDLINES, "<$xcatdpath")) { + xCAT::MsgUtils->message("SL", "Enable subroutine calling trace failed: cannot open $xcatdpath"); + } else { + my @sub_in_xcatd; + # Get all the name of subroutines except the xxx_callingtrace + while () { + if (/^\s*sub\s+([^\s]*)/) { + if (! /enable_callingtrace|disable_callingtrace|add_callingtrace/) { + push @sub_in_xcatd, $1; + } + } + } + close(XCATDLINES); + # Get all the symbols from the %main:: space + foreach my $fun (keys %main::) { + my $symfun = $main::{$fun}; + if (($symfun =~ /^\*/) # must be a symbol + && *{$symfun}{CODE} # must be a subroutine + && grep (/\Q$fun\E/, @sub_in_xcatd) # must be defined in the xcatd + && ($enableall || grep (/\Q$symfun\E/, @xcatdfuncs))) { # all or configured in the configuration file + push @debugfuns, $symfun; + } + } + } + + # Get the functions of xCAT plugins + foreach my $plugin (\%xCAT::, \%xCAT_plugin::) { + # Get the path of the plugins + my $path = ""; + foreach (keys %$plugin) { + my $glob = $plugin->{$_}; + if ($glob =~ /\*([^:]*)::/) { + $path = $::XCATROOT."/lib/perl/$1/"; + last; + } + } + # For each plugin moduel, search the matched functions + foreach my $xcatplugin (keys %$plugin) { + if ($xcatplugin =~ /[^\*].*::$/) { + # get the subroutines in the plugin file + my $pluginfile = $xcatplugin; + $pluginfile =~ s/:://; + # Ignore to enable the trace for the subroutines in the MsgUtils + if ($pluginfile eq "MsgUtils") { + next; + } + my $module_file = $path.$pluginfile.".pm"; + my @sub_in_pm = (); + if (-r $module_file) { + open (LINES, "<$module_file") or last; + while () { + if (/^\s*sub\s+([^\s]*)/) { + push @sub_in_pm, $1; + } + } + close (LINES); + } + # Search the symbol from the space of plugin + foreach my $fun (keys %{$plugin->{$xcatplugin}}) { + my $symfun = $plugin->{$xcatplugin}{$fun}; + if ($symfun =~ /^\*/ # must be a symbol + && *{$symfun}{CODE} # must be a subroutine + && grep (/\Q$fun\E/, @sub_in_pm) # must be defined in the plugin modules + && ($enableall || grep (/\Q$symfun\E/, @pluginfuncs))) { # all or configured in the configuration file + push @debugfuns, $symfun; + } + } + } + } + } + + # return a new subroutine with some debug code to output the trace log + # and calling the original subroutine at the last + sub add_callingtrace { + my ($funname, $orig) = @_; + sub { + my $args = Dumper(@_); + #$args =~ s{\A\$VAR\d+\s*=\s*}{}; + my $callstack = Carp::longmess; + + # write the trace log to the trace file + print $::LOG_FILE_HANDLE "\n***************Calling of subroutine $funname***************\n"; + print $::LOG_FILE_HANDLE localtime()."\n"; + print $::LOG_FILE_HANDLE "Arguments: \n$args\n"; + print $::LOG_FILE_HANDLE "Calling stack: \n $callstack\n"; + &$orig; + }; + } + + # Replace the original subroutine with a trace log added one + print $::LOG_FILE_HANDLE "##########Enabled the calling trace for: ###########\n"; + foreach my $debugfun (@debugfuns) { + print $::LOG_FILE_HANDLE " $debugfun\n"; + if (defined ($::DEBUG_FUN{"$debugfun"}{'debug'})) { + # if the trace added subroutine has been defined + *{"$debugfun"} = $::DEBUG_FUN{"$debugfun"}{'debug'}; + #print " => $::DEBUG_FUN{$debugfun}{debug}\n"; + } else { + my $oldfun = *{$debugfun}{CODE}; + # Bakcup the original subroutine + $::DEBUG_FUN{"$debugfun"}{'orig'} = $oldfun; + #print "$debugfun".": $::DEBUG_FUN{$debugfun}{orig}"; + # otherise creating a trace added subroutine from scratch + *{"$debugfun"} = add_callingtrace($debugfun, $oldfun); + $::DEBUG_FUN{"$debugfun"}{'debug'} = *{"$debugfun"}{CODE}; + #print " => $::DEBUG_FUN{$debugfun}{debug}\n"; + } + } + print $::LOG_FILE_HANDLE "####################################################\n"; +} + +# Go through all the trace log added subroutines, replace it with the original one +sub disable_callingtrace { + no strict 'refs'; + print $::LOG_FILE_HANDLE "##########Disabled the calling trace for: ##########\n" if ($::LOG_FILE_HANDLE); + foreach my $glob (keys %::DEBUG_FUN) { + if (defined $::DEBUG_FUN{$glob}{'orig'}) { + *{"$glob"} = $::DEBUG_FUN{$glob}{'orig'}; + print $::LOG_FILE_HANDLE "$glob\n"; + #print "$glob".": => $::DEBUG_FUN{$glob}{orig}\n"; + } + } + print $::LOG_FILE_HANDLE "####################################################\n" if ($::LOG_FILE_HANDLE); + xCAT::MsgUtils->stop_logging(); +} + + + diff --git a/xCAT-server/sbin/xcatdebug b/xCAT-server/sbin/xcatdebug index 7aae8d696..1dd159747 100755 --- a/xCAT-server/sbin/xcatdebug +++ b/xCAT-server/sbin/xcatdebug @@ -1,24 +1,107 @@ -#!/bin/sh +#!/usr/bin/env perl # IBM(c) 2007 EPL license http://www.eclipse.org/legal/epl-v10.html -#------------------------------------------------------------------------------- -#=head1 xcatdebug -# To run: xcatdebug 0 where 0 is the number of the tracelevel (0,1) -#=head2 xcatdebug provides a debug trace of the xcatd daemon. -# Perl Debug::Trace must be installed from the xcat deps package -# Shutdown xcatd -# Link /opt/xcat/share/xcat/tools/tracelevel to the traceleve* file you -# wish to use -# run xcatdebug > /mydir/myoutput file or just to STDOUT -# To stop ctl-C, you may have to kill processes after -# ps -ef |grep xcatd, kill the listener process, it should stop the -# other xcatd processes -# 7405808 8454216 0 10:04:37 pts/1 0:03 xcatd: SSL listener -# You may also have to kill the xcatdebug process, check for it. -# -#=cut -#------------------------------------------------------------------------------- -export PERL5DEBUGTRACE=":warn:indent(2):nomaxdepth:quotekeys" -echo "running:perl -MDebug::Trace=`cat /opt/xcat/share/xcat/tools/tracelevel$1` /opt/xcat/sbin/xcatd -f" -perl -MDebug::Trace=`cat /opt/xcat/share/xcat/tools/tracelevel$1` /opt/xcat/sbin/xcatd -f -exit 0 +# This command can be used to +# 1. Enable/Disbale the subroutine calling trace. +# 2. Enable the commented trace log inside a subroutine. + +# The example of -c +# (daemonize,do_installm_service,do_udp_service)|xCAT::Utils(isMN,Version)|xCAT_plugin::DBobjectdefs(defls,process_request) +# If specifying a file +# (daemonize,do_installm_service,do_udp_service) +# xCAT::Utils(isMN,Version) +# xCAT_plugin::DBobjectdefs(defls,process_request) +# +# Following three lines need to be added to enable the capability of commented trace +#if (defined $ENV{ENABLE_TRACE_CODE}) { +# use xCAT::Enabletrace qw(loadtrace filter); +# loadtrace(); +#} +#The commented trace can be two formats: +#1. trace section +# ## TRACE_BEGIN +# # print "In the debug\n"; +# ## TRACE_END +#2. trace in single line +# ## TRACE_LINE print "In the trace line\n"; + +use Getopt::Long; + +my $usage = "xcatdebug { [-f enable|disable [-c configuration file | subroutine list]] | [ -d enable |disable]} + -f: enable or disable the subroutine calling trace + -c: configure the subroutine list + configuration file: a file contains multiple lines of + subroutine list: SUBROUTINE_DEFINITION|SUBROUTINE_DEFINITION|... + SUBROUTINE_DEFINITION: [plugin](subroutine1,subroutine2,...) + e.g. (daemonize,do_installm_service,do_udp_service) + e.g. xCAT::Utils(isMN,Version) + e.g. xCAT_plugin::DBobjectdefs(defls,process_request) + -d: enable or disable the commented trace log inside a subroutine\n"; + +Getopt::Long::Configure("bundling"); +Getopt::Long::Configure("no_pass_through"); +if ( + !GetOptions( + 'f=s' => \$::FUNC, + 'c=s' => \$::CONFIG, + 'd=s' => \$::DEBUG,)) { + print "$usage"; + exit 1; +} + +if (!($::FUNC || $::DEBUG)) { + print "$usage"; + exit 1; +} + +# The action that enable the commented debug log should be done firstly +# In this case the xcatd need to be restart +if (defined($::DEBUG)) { + if ($::DEBUG eq "enable") { + `XCATRELOAD=yes ENABLE_TRACE_CODE=1 xcatd -p /var/run/xcatd.pid`; + print "Enabled the commented trace log.\n"; + } elsif ($::DEBUG eq "disable") { + `XCATRELOAD=yes xcatd -p /var/run/xcatd.pid`; + print "Disabled the commented trace log.\n"; + } else { + print "$usage"; + exit 1; + } +} + + +if (defined($::FUNC)) { + # Get the pid of xcatd + my $pid; + if (-e "/var/run/xcatd.pid") { + open (PID, "; + close (PID); + } elsif ($pid = `ps -ef | grep 'xcatd: SSL listener' | grep -v 'grep' | awk '{print \$2}'`) { + } else { + die "Cannot find the pid in the /var/run/xcatd.pid\n"; + } + if ($::FUNC eq "enable") { + # Enable the function trace + if (defined $::CONFIG) { + open(CFG, ">/tmp/xcatcallingtrace.cfg") or die "Cannot open /tmp/xcatcallingtrace.cfg\n"; + print CFG $::CONFIG; + close (CFG); + } else { + unlink "/tmp/xcatcallingtrace.cfg"; + } + kill 50, $pid; + print "Enabled the subroutine calling trace.\n"; + } elsif ($::FUNC eq "disable") { + kill 51, $pid; + print "Disabled the subroutine calling trace.\n"; + } else { + print "$usage"; + exit 1; + } + print " Get the trace log from the /var/log/xcat/subcallingtrace\n"; +} + + +0 +