From 8cd8818d5bfea3f36b84f3433e903ff096ab4acf Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Thu, 13 Aug 2015 23:27:02 -0400
Subject: [PATCH 01/12] record command output and add trace information

---
 xCAT-server/sbin/xcatd | 353 ++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 352 insertions(+), 1 deletion(-)

diff --git a/xCAT-server/sbin/xcatd b/xCAT-server/sbin/xcatd
index d6ad7304b..f514663c5 100755
--- a/xCAT-server/sbin/xcatd
+++ b/xCAT-server/sbin/xcatd
@@ -27,6 +27,11 @@ my $sslctl;
 my $udpctl;
 my $pid_UDP;
 my $pid_MON;
+
+#----used for command log start---------
+my $cmdlog_svrpid;
+#----used for command log end---------
+
 # if AIX - make sure we include perl 5.8.2 in INC path.
 #       Needed to find perl dependencies shipped in deps tarball.
 if ($^O =~ /^aix/i) {
@@ -156,7 +161,6 @@ if (xCAT::Utils->isLinux()) {
   }  
 }
 
-
 my $quit = 0;
 my $port;
 my $sport;
@@ -197,7 +201,18 @@ my $plugins_dir=$::XCATROOT.'/lib/perl/xCAT_plugin';
 ($tmp) = $sitetab->getAttribs({'key'=>'xcatconfdir'},'value');
 $xcatdir = (($tmp and $tmp->{value}) ? $tmp->{value} : "/etc/xcat");
 
+#----used for command log start-------
+my $cmdlog_logfile="/var/log/xcat/commands.log";
+my $cmdlog_port=3003;
+($tmp) = $sitetab->getAttribs({'key'=>'xcatcport'},'value');
+if ($tmp) {
+	$cmdlog_port = $tmp->{value};
+}
+my $cmdlog_alllog="====================================================\n";
+#----used for command log end---------
+
 $sitetab->close;
+
 my $progname;
 my $pipeexpected;
 $SIG{PIPE} = sub { 
@@ -943,6 +958,13 @@ $SIG{TERM} = $SIG{INT} = sub {
    if ($dbmaster) {
       kill 2, $dbmaster;
    }
+   
+   #----used for command log start---------
+   if ($cmdlog_svrpid) {
+       kill 2, $cmdlog_svrpid;
+   }
+   #----used for command log end--------- 
+   
    $SIG{ALRM} = sub { xexit 0; }; #die "Did not close out in time for 5 second grace period"; };
    alarm(2);
    };
@@ -1122,6 +1144,53 @@ if ($startupparent) {
    close($startupparent);
 }
 
+#----used for command log start---------
+$cmdlog_svrpid = fork();
+if( !defined($cmdlog_svrpid)){
+    print "xCAT command log sever unable to fork";
+	xCAT::MsgUtils->message("S","xCAT command log sever unable to fork");
+}elsif($cmdlog_svrpid ==0){
+    $$progname="xcatd: Command log writer";
+	my $clientsock;
+	my @waittowritepro;
+	
+	xCAT::MsgUtils->trace(0,"I","xcatd: command log process start");
+	
+	unless (open (CMDLOGFILE, ">>$cmdlog_logfile")) {
+        #print "Can't open xcat command log file $cmdlog_logfile";
+	    #xCAT::MsgUtils->message("S","Can't open xcat command log file $cmdlog_logfile");
+	
+	    xCAT::MsgUtils->trace(0,"E","xcatd: Can't open xcat command log file $cmdlog_logfile");
+	    xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
+		exit(0);
+    }
+	select(CMDLOGFILE);
+	$|=1;
+   
+	my $cmdlogsvrlistener = IO::Socket::INET->new(LocalPort => $cmdlog_port,
+							   Type => SOCK_STREAM,
+							   Reuse => 1,
+							   Listen => 8192);
+	while (1)
+	{
+	    my $clientsock = $cmdlogsvrlistener->accept;
+	    unless ($clientsock) { next; } 
+	    my $log = "";
+	    my $bytesread;
+	    do { 
+	    $bytesread=sysread($clientsock,$log,65536,length($log)) 
+	    } while ($bytesread);
+	    close($clientsock);
+		#print "[server]<<<<<<<<<<<<<<<<<<<<<<<<<\n$log";
+		print CMDLOGFILE $log;
+	}
+	
+	close($cmdlogsvrlistener);
+	close(CMDLOGFILE);
+	
+	xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
+}
+#----used for command log end---------
 
 #only write to pid file if we have listener, listener ownership serves as lock to protect integrity
 open($mainpidfile,">","/var/run/xcat/mainservice.pid"); #if here, everyone else has unlinked mainservicepid or doesn't care
@@ -1281,8 +1350,15 @@ if ($inet6support) {
     $peerhost && $peerhost =~ s/-myri\d*$//;
     $peerhost && $peerhost =~ s/-ib\d*$//;
     #printf('info'.": xcatd: connection from ".($peername ? $peername . "@" . $peerhost : $peerhost)."\n");
+	
+	my $debugmsg = "xcatd: connection from ".($peername ? $peername . "@" . $peerhost : $peerhost)."\n";
+	xCAT::MsgUtils->trace(0,"D","$debugmsg");
+	
     $$progname="xCATd SSL: Instance for ".($peername ? $peername ."@".$peerhost : $peerhost) if $peerhost;
     service_connection($connection,$peername,$peerhost,$peerfqdn,$peerhostorg);
+	
+    $debugmsg = "xcatd: close connection with ".($peername ? $peername . "@" . $peerhost : $peerhost)."\n";
+    xCAT::MsgUtils->trace(0,"D","$debugmsg");
     xexit(0);
   }
   if ($sslfudgefactor) { $sslfudgefactor -= 1; }
@@ -1552,6 +1628,9 @@ sub plugin_command {
                    store_fd(\$rescanrequest,$rescanwritepipe);
                  }
                } else {
+                 my $debuglog= "xcatd: call plugin <$modname> to handle command <$req->{command}->[0]>";
+                 xCAT::MsgUtils->trace(0,"D","$debuglog");
+				 
                  ${"xCAT_plugin::".$modname."::"}{process_request}->($req,$callback,\&do_request);
                }
             }
@@ -1822,6 +1901,23 @@ sub dispatch_request {
    # save the old signal
    my $old_sig_chld = $SIG{CHLD};
 
+   #----used for trace start---------
+   my $str_cmd=$req->{command}->[0]." ";
+   if(exists($req->{noderange})){
+       foreach my $n (@{$req->{noderange}}) {
+           $str_cmd .= $n.",";
+       }
+       $str_cmd =~ s/(.+),$/$1 /g;
+    }
+   if(exists($req->{arg})){
+       foreach my $arg (@{$req->{arg}}) {
+           $str_cmd .= $arg." ";
+       }
+	   $str_cmd =~ s/(.+) $/$1/g;
+    }
+   xCAT::MsgUtils->trace(0,"D","xcatd: dispatch request '$str_cmd' to plugin '$modname'");
+   #----used for trace end---------
+   
    #Hierarchy support.  Originally, the default scope for noderange commands was
    #going to be the servicenode associated unless overriden.
    #However, assume for example that you have blades and a blade is the service node
@@ -1832,6 +1928,7 @@ sub dispatch_request {
    #If the plugin offers a preprocess method, use it to set the request array
    if ((not (defined $req->{_xcatpreprocessed}->[0] and $req->{_xcatpreprocessed}->[0] == 1)) and (defined(${"xCAT_plugin::".$modname."::"}{preprocess_request}))) {
     $SIG{CHLD}='DEFAULT';
+    xCAT::MsgUtils->trace(0,"D","xcatd: handle request '$req->{command}->[0]' by plugin '$modname''s preprocess_request");
     $reqs = ${"xCAT_plugin::".$modname."::"}{preprocess_request}->($req,$dispatch_cb,\&do_request);
    } else { #otherwise, pass it in without hierarchy support
     $reqs = [$req];
@@ -1889,6 +1986,7 @@ sub dispatch_request {
             store_fd(\$rescanrequest,$rescanwritepipe);
           }
         } else {
+          xCAT::MsgUtils->trace(0,"D","xcatd: handle request '$_->{command}->[0]' by plugin '$modname''s process_request");
           ${"xCAT_plugin::".$modname."::"}{process_request}->($_,$dispatch_cb,\&do_request);
         }
         return;
@@ -1951,6 +2049,8 @@ sub dispatch_request {
             undef $_->{'_xcatdest'};
             #mainly used by SN to filter out the incorrect module that xcat command came into
             $_->{'_modname'} = $modname;
+			
+            xCAT::MsgUtils->trace(0,"D","dispatch hierarchical sub-command $_->{command}->[0] to $ENV{XCATHOST}");
             xCAT::Client::submit_request($_,\&dispatch_callback,$xcatdir."/cert/server-cred.pem",$xcatdir."/cert/server-cred.pem",$xcatdir."/cert/ca.pem"); 
             };
             if ($@) {
@@ -1984,6 +2084,7 @@ sub dispatch_request {
                 store_fd(\$rescanrequest,$rescanwritepipe);
               }
             } else {
+              xCAT::MsgUtils->trace(0,"D","handle command $_->{command}->[0] by plugin $modname 's process_request"); 
               ${"xCAT_plugin::".$modname."::"}{process_request}->($_,\&dispatch_callback,\&do_request);
             }
             last;
@@ -2203,6 +2304,11 @@ sub send_response {
                 } while (($! == EAGAIN) or ($! == ECHILD));
             }
 	    };
+		
+	    #----used for command log start-------
+	    cmdlog_collectlog($response);
+	    #----used for command log end -------- 
+		
     } elsif ($encode eq "storable") {
         if ($response->{xcatresponse}) {
             $response = $response->{xcatresponse};
@@ -2279,6 +2385,32 @@ sub service_connection {
       #}
       $req = get_request($sock,$globalencode,$line);
       unless ($req) { last; }
+	  
+      #----used for command log start----------
+      my ($sec,$min,$hour,$mday,$mon,$year) = localtime(time());
+      $year += 1900;
+      $cmdlog_alllog .= "[Date]       $year-$mon-$mday $hour:$min:$sec\n"; 
+	  
+      #print ">>>>>>>cmdlog request dumper>>>>>>>>\n";
+      #print Dumper $req;
+	  
+      $cmdlog_alllog .= "[ClientType] ".$req->{clienttype}->[0]." \n";   
+      $cmdlog_alllog .= "[Request]    ".$req->{command}->[0]." "; 
+      if(exists($req->{noderange})){
+          foreach my $node (@{$req->{noderange}}) {
+              $cmdlog_alllog .= $node.",";
+          }
+          $cmdlog_alllog =~ s/(.+),$/$1 /g;
+    }
+    
+    if(exists($req->{arg})){
+        foreach my $arg (@{$req->{arg}}) {
+	        $cmdlog_alllog .= $arg." ";
+        }
+    }
+    $cmdlog_alllog .= "\n[Response]\n";
+    #----used for command log end----------
+	  
       { #TODO: find closing brace..
         #first change peername on 'becomeuser' tag if present and valid
         if (defined $req->{becomeuser}) {
@@ -2344,6 +2476,10 @@ sub service_connection {
 	  if($peerhost){
           	$$progname .= " for ".($peername ? $peername ."@".$peerhost : $peerhost);
 	  }
+	  
+          my $debuglog= "xcatd: open new process : $$progname";
+          xCAT::MsgUtils->trace(0,"D","$debuglog");
+	  
           if ($req->{command}->[0] eq "authcheck") { #provide a method for UI to verify a user without actually requesting action
               my $resp;
               if ($peername or $peername eq "0") {
@@ -2432,6 +2568,11 @@ sub service_connection {
       #should be no longer possible to hit this condition.
       send_response({error=>"A child jumped to where it should never ever be, this shouldn't be possible, please report this bug"},$sock);
   }
+  
+  #----used for command log start-------
+  cmdlog_submitlog();
+  #----used for command log end---------
+  
   $SIG{ALRM}= sub { xCAT::MsgUtils->message("S","$$ failed shutting down"); die;};
   alarm(10);
   foreach (keys %tables) {
@@ -2493,6 +2634,12 @@ sub relay_fds { #Relays file descriptors from pipes to children to the SSL socke
             close($cin);
          }
          xCAT::MsgUtils->message("S", "Client abort requested");
+		 
+         #----used for command log start-------  
+         $cmdlog_alllog .= "Client abort requested\n";
+         cmdlog_submitlog(); 
+         #----used for command log end---------
+		 
          exit(0);
       }
    }
@@ -2709,5 +2856,209 @@ sub disable_callingtrace {
   xCAT::MsgUtils->stop_logging();
 }
 
+sub cmdlog_collectlog(){
+    my $rsponse= shift;
+    my $rsp_log="";
+=pod
+    print ">>>>[$$]cmdlog_collectlog dumper all rsponse>>>>>\n";
+    print Dumper $rsponse;   
+    return 0;
+=cut    
 
+    if((exists($rsponse->{serverdone})) && (! exists($rsponse->{error}) )){return 0;}
+    my $rsp;
+    if(exists($rsponse->{xcatresponse})){
+        $rsp = $rsponse->{xcatresponse};
+    }else{
+        $rsp = $rsponse;
+    }
+	if (ref($rsp) ne 'ARRAY') {return 0;}
+    if (scalar(@$rsp) == 0) {return 0;}
+	
+	foreach my $tmprsp (@{$rsp}) {
+        $rsp = $tmprsp;
+
+    #print ">>>>[$$]cmdlog_collectlog dumper valid rsponse>>>>>\n";
+    #print Dumper $rsponse;  
+    #return 0;
+
+    #handle response 
+    #Handle errors
+    if ($rsp->{error}) {
+        if (ref($rsp->{error}) eq 'ARRAY') {
+            foreach my $text (@{$rsp->{error}}) {
+                if ($rsp->{NoErrorPrefix}) {
+                    $rsp_log.=$text;
+                } else {
+                    $rsp_log.="Error: $text\n";
+                }
+            }
+        }
+        else {
+            if ($rsp->{NoErrorPrefix}) {
+                $rsp_log.= $rsp->{error}."\n";
+            } else {
+                $rsp_log.= "Error: ".$rsp->{error}."\n";
+            }
+        }
+    }
+    
+    if ($rsp->{warning}) {
+        if (ref($rsp->{warning}) eq 'ARRAY') {
+            foreach my $text (@{$rsp->{warning}}) {
+                if ($rsp->{NoWarnPrefix}) {
+                    $rsp_log.= "$text\n";
+                } else {
+                    $rsp_log.= "Warning: $text\n";
+                }
+            }
+        }
+        else {
+            if ($rsp->{NoWarnPrefix}) {
+                $rsp_log.= $rsp->{warning}."\n";
+            } else {
+                $rsp_log.= "Warning: ".$rsp->{warning}."\n";
+            }
+        }
+    }
+    
+    if ($rsp->{info}) {
+        if (ref($rsp->{info}) eq 'ARRAY') {
+            foreach my $text (@{$rsp->{info}}) {
+                $rsp_log.= "$text\n";
+            }
+        }
+        else {
+            $rsp_log.= $rsp->{info}."\n";
+        }
+    }
+
+    if ($rsp->{sinfo}) {
+        if (ref($rsp->{sinfo}) eq 'ARRAY') {
+            foreach my $text (@{$rsp->{sinfo}}) {
+                $rsp_log.= "$text\r";
+            }
+        }
+        else {
+            $rsp_log.= $rsp->{sinfo}."\r";
+        }
+    }
+    
+    #Handle {node} structure
+    my $errflg=0;
+    my $nodes=($rsp->{node});
+    unless (ref $nodes eq 'ARRAY') {
+        $nodes = [$nodes];
+    }
+    if (scalar @{$nodes}) {
+        my $node;
+        foreach $node (@$nodes) {
+            my $desc;
+            if (ref($node->{name}) eq 'ARRAY') {
+                $desc=$node->{name}->[0];
+            } else {
+                $desc=$node->{name};
+            }
+            if ($node->{error}) {
+                $desc.=": Error: ".$node->{error}->[0];
+                $errflg=1;
+            }
+            if ($node->{warning}) {
+                $desc.=": Warning: ".$node->{warning}->[0];
+                $errflg=1;
+            }
+            if ($node->{data}) {
+                if (ref(\($node->{data})) eq 'SCALAR') {
+                    $desc=$desc.": ".$node->{data};
+                } elsif (ref($node->{data}) eq 'HASH') {
+                    if ($node->{data}->{desc}) {
+                        if (ref($node->{data}->{desc}) eq 'ARRAY') {
+                            $desc=$desc.": ".$node->{data}->{desc}->[0];
+                        } else {
+                            $desc=$desc.": ".$node->{data}->{desc};
+                        }
+                    }
+                    if ($node->{data}->{contents}) {
+                        if (ref($node->{data}->{contents}) eq 'ARRAY') {
+                            $desc="$desc: ".$node->{data}->{contents}->[0];
+                        } else {
+                            $desc="$desc: ".$node->{data}->{contents};
+                        }
+                    }
+                } elsif (ref(\($node->{data}->[0])) eq 'SCALAR') {
+                    $desc=$desc.": ".$node->{data}->[0];
+                } else {
+                    if ($node->{data}->[0]->{desc}) {
+                        $desc=$desc.": ".$node->{data}->[0]->{desc}->[0];
+                    }
+                    if ($node->{data}->[0]->{contents}) {
+                        $desc="$desc: ".$node->{data}->[0]->{contents}->[0];
+                    }
+                }
+            }
+            if ($desc) {
+                if ($errflg == 1) {
+                    $rsp_log.= "$desc\n";
+                } else {
+                    $rsp_log.= "$desc\n";
+                }
+            }
+        }
+    }
+
+    # Handle {data} structure with no nodes
+	foreach my $mykey ( keys %{$rsp} ) 
+	{
+	if ($mykey ne "data") {next;}
+    if ($rsp->{data}) {
+        my $data=($rsp->{data});
+        my $data_entry;
+        foreach $data_entry (@$data) {
+            my $desc;
+            if (ref(\($data_entry)) eq 'SCALAR') {
+                $desc=$data_entry;
+            } else {
+                if ($data_entry->{desc}) {
+                    $desc=$data_entry->{desc}->[0];
+                }
+                if ($data_entry->{contents}) {
+                    if ($desc) {
+                        $desc="$desc: ".$data_entry->{contents}->[0];
+                    } else {
+                        $desc=$data_entry->{contents}->[0];
+                    }
+                }
+            }
+            if ($desc) { 
+                $rsp_log.= "$desc\n";
+            }
+        }
+    }
+	}
+	}
+    #print "$rsp_log\n";
+    $cmdlog_alllog .= $rsp_log; 
+   
+    return 0;
+}
+
+sub cmdlog_submitlog() {
+
+   if( $cmdlog_alllog =~ /getipmicons/) {return 1;}
+=pod   
+   print ">>>>[$$]cmdlog_submitlog >>>>>>>>>>>>>>>>>>>>>>>>>>>>>\n";
+   print $cmdlog_alllog;
+   return 0;
+=cut
+    my $mysocket;
+    while (1){
+        $mysocket = IO::Socket::INET->new(PeerAddr => "127.0.0.1",
+									   PeerPort => $cmdlog_port,
+									   Proto => "tcp");
+        if($mysocket) { last;}
+    }
+    print $mysocket $cmdlog_alllog;
+	#print "[client]>>>>>>>>>>>>>>>>>>>>>>>>>>\n$cmdlog_alllog";
+    close ($mysocket);
+}
 

From 61d8537e9022a1e4cf0bee818ded06a0bfc5ef47 Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Thu, 13 Aug 2015 23:28:41 -0400
Subject: [PATCH 02/12] add trace function

---
 perl-xCAT/xCAT/MsgUtils.pm | 47 ++++++++++++++++++++++++++++++++++++++
 1 file changed, 47 insertions(+)

diff --git a/perl-xCAT/xCAT/MsgUtils.pm b/perl-xCAT/xCAT/MsgUtils.pm
index 0e9cd3028..cd8369625 100644
--- a/perl-xCAT/xCAT/MsgUtils.pm
+++ b/perl-xCAT/xCAT/MsgUtils.pm
@@ -740,5 +740,52 @@ sub verbose_message
         xCAT::MsgUtils->message("I", $data);
     }
 }
+
+sub trace(){
+    shift;
+    my $verbose = shift;
+    my $level = shift;
+	my $logcontent = shift;
+
+	my $prefix = "";
+	if(($level eq "E")||($level eq "e")){$prefix="ERR";}
+	if(($level eq "W")||($level eq "w")){$prefix="WARNING";}
+	if(($level eq "I")||($level eq "i")){$prefix="INFO";}
+	if(($level eq "D")||($level eq "d")){$prefix="DEBUG";}
+	#print "prefix = $prefix\n";	
+
+	my @tmp = xCAT::TableUtils->get_site_attribute("xcatdebugmode");
+	my $xcatdebugmode=$tmp[0];
+	#print ">>>>>>>xcatdebugmode = $xcatdebugmode  >>>>>>>>>>>>\n";
+
+	if (($level eq "E") 
+	  ||($level eq "e")
+	  ||($level eq "I")
+	  ||($level eq "i") 
+	  ||($level eq "W")
+	  ||($level eq "w")){
+		my $msg = $prefix." ".$logcontent;
+		eval {
+			#print "msg = $msg\n";
+			openlog("xCAT", "nofatal,pid", "local4");
+			syslog("$prefix", $msg);
+			closelog();
+		};
+	}
+	
+    if (($level eq "D") 
+	  ||($level eq "d")){
+          if(($verbose == 1 )||($xcatdebugmode  eq "1")){
+            my $msg = $prefix." ".$logcontent;
+            eval {
+                #print "msg = $msg\n";
+                openlog("xCAT", "nofatal,pid", "local4");
+                syslog("$prefix", $msg);
+                closelog();
+            }
+        }
+    }
+}
+
 1;
 

From a35ca71281e64cf4e5cd3eb9f7a316d884e85e7d Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Thu, 13 Aug 2015 23:31:30 -0400
Subject: [PATCH 03/12] add trace information

---
 xCAT-server/lib/xcat/plugins/anaconda.pm   | 42 ++++++++++++++++-
 xCAT-server/lib/xcat/plugins/debian.pm     | 31 +++++++++++-
 xCAT-server/lib/xcat/plugins/destiny.pm    | 12 ++++-
 xCAT-server/lib/xcat/plugins/dhcp.pm       | 42 +++++++++++++++--
 xCAT-server/lib/xcat/plugins/grub2.pm      | 55 ++++++++++++++++++++--
 xCAT-server/lib/xcat/plugins/petitboot.pm  | 46 +++++++++++++++++-
 xCAT-server/lib/xcat/plugins/prescripts.pm | 31 +++++++++++-
 xCAT-server/lib/xcat/plugins/pxe.pm        | 43 ++++++++++++++++-
 xCAT-server/lib/xcat/plugins/sles.pm       | 47 ++++++++++++++++--
 xCAT-server/lib/xcat/plugins/xnba.pm       | 41 +++++++++++++++-
 xCAT-server/lib/xcat/plugins/yaboot.pm     | 54 ++++++++++++++++++++-
 11 files changed, 419 insertions(+), 25 deletions(-)

diff --git a/xCAT-server/lib/xcat/plugins/anaconda.pm b/xCAT-server/lib/xcat/plugins/anaconda.pm
index c9ce10bed..3b2803a1c 100755
--- a/xCAT-server/lib/xcat/plugins/anaconda.pm
+++ b/xCAT-server/lib/xcat/plugins/anaconda.pm
@@ -952,6 +952,21 @@ sub mkinstall
     $installroot = "/install";
     $globaltftpdir = "/tftpboot";
 
+    #>>>>>>>used for trace log start>>>>>>>
+    my @args=();
+    my %opt;
+    if (ref($request->{arg})) {
+        @args=@{$request->{arg}};
+    } else {
+        @args=($request->{arg});
+    }
+    @ARGV = @args;
+    GetOptions('V'  => \$opt{V});
+    my $verbose_on_off=0;
+    if($opt{V}){$verbose_on_off=1;}
+    xCAT::MsgUtils->trace(0,"d","anaconda->mkinstall: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
+    #>>>>>>>used for trace log end>>>>>>>
+	
     #if ($sitetab)
     #{
     #    (my $ref) = $sitetab->getAttribs({key => 'installdir'}, 'value');
@@ -961,6 +976,9 @@ sub mkinstall
     {
         $installroot = $site_ent;
     }
+	
+    xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: installroot = $installroot");
+		
     #( $ref) = $sitetab->getAttribs({key => 'tftpdir'}, 'value');
     @ents = xCAT::TableUtils->get_site_attribute("tftpdir");
     $site_ent = $ents[0];
@@ -968,6 +986,7 @@ sub mkinstall
     {
         $globaltftpdir = $site_ent;
     }
+    xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: globaltftpdir = $globaltftpdir");
     #}
 
     my $node;
@@ -1035,13 +1054,17 @@ sub mkinstall
             $xcatmaster = '!myipfn!';
         }
 
+        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: xcatmaster = $xcatmaster");
+		
         my $osinst;
         if ($rents{$node}->[0] and $rents{$node}->[0]->{tftpdir}) {
 		$tftpdir = $rents{$node}->[0]->{tftpdir};
         } else {
 		$tftpdir = $globaltftpdir;
         }
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: tftpdir = $tftpdir");
         my $ent = $osents{$node}->[0]; #$ostab->getNodeAttribs($node, ['profile', 'os', 'arch']);
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: provmethod = $ent->{provmethod}");
         if ($ent and $ent->{provmethod} and ($ent->{provmethod} ne 'install') and ($ent->{provmethod} ne 'netboot') and ($ent->{provmethod} ne 'statelite')) {
 	    $imagename=$ent->{provmethod};
 	    #print "imagename=$imagename\n";
@@ -1155,6 +1178,12 @@ sub mkinstall
 	    $netdrivers = $ph->{netdrivers};
 	    $driverupdatesrc = $ph->{driverupdatesrc};
 	    $osupdir = $ph->{'osupdir'};
+		
+        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: imagename = $imagename");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkgdir = $pkgdir");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkglistfile = $pkglistfile");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: tmplfile = $tmplfile");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: partfile = $partfile");
 	}
 	else {
 	    $os = $ent->{os};
@@ -1184,6 +1213,11 @@ sub mkinstall
         #get the partition file from the linuximage table
         my $imgname = "$os-$arch-install-$profile";
 
+        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: imagename = $imgname");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkgdir = $pkgdir");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkglistfile = $pkglistfile");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: tmplfile = $tmplfile");
+		
         if ( ! $linuximagetab ) {
             $linuximagetab = xCAT::Table->new('linuximage');
         }
@@ -1192,6 +1226,7 @@ sub mkinstall
             (my $ref1) = $linuximagetab->getAttribs({imagename => $imgname}, 'partitionfile');
             if ( $ref1 and $ref1->{'partitionfile'}){
                 $partfile = $ref1->{'partitionfile'};
+				xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: partfile = $partfile");
             }
         }
         #can not find the linux osiamge object, tell users to run "nodeset <nr> osimage=***"
@@ -1366,6 +1401,7 @@ sub mkinstall
                         &insert_dd($callback, $os, $arch, "$tftppath/initrd.img", "$tftppath/vmlinuz", $driverupdatesrc, $netdrivers, $osupdir, $ignorekernelchk);
                     }
                 }
+                xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: copy initrd.img and vmlinuz to $tftppath");
             }
 
             #We have a shot...
@@ -1581,7 +1617,11 @@ sub mkinstall
                     $k = "$rtftppath/vmlinuz";
                     $i = "$rtftppath/initrd.img";
             }
-
+			
+			xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: kcmdline = $kcmdline");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: kernal = $k");
+			xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: initrd = $i");
+			
             $bptab->setNodeAttribs(
                 $node,
                 {
diff --git a/xCAT-server/lib/xcat/plugins/debian.pm b/xCAT-server/lib/xcat/plugins/debian.pm
index c23c99498..9a3971cb6 100755
--- a/xCAT-server/lib/xcat/plugins/debian.pm
+++ b/xCAT-server/lib/xcat/plugins/debian.pm
@@ -445,6 +445,21 @@ sub mkinstall {
     my $osimagetab;
     my %img_hash=();
 
+    #>>>>>>>used for trace log start>>>>>>>
+    my @args=();
+    my %opt;
+    if (ref($request->{arg})) {
+        @args=@{$request->{arg}};
+    } else {
+        @args=($request->{arg});
+    }
+    @ARGV = @args;
+    GetOptions('V'  => \$opt{V});
+    my $verbose_on_off=0;
+    if($opt{V}){$verbose_on_off=1;}
+    xCAT::MsgUtils->trace(0,"d","debian->mkinstall: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
+    #>>>>>>>used for trace log end>>>>>>>
+	
     my $installroot;
     $installroot = "/install";
     if ($sitetab)
@@ -455,7 +470,9 @@ sub mkinstall {
             $installroot = $ref->{value};
         }
     }
-
+	
+    xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: installroot = $installroot");
+	
     my $node;
     my $ostab = xCAT::Table->new('nodetype');
     my %donetftp;
@@ -602,6 +619,11 @@ sub mkinstall {
                 $pkgdir="$installroot/$os/$arch";
             }
             $pkglistfile=$ph->{pkglist};
+			
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: imagename = $imagename");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkgdir = $pkgdir");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkglistfile = $pkglistfile");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: tmplfile = $tmplfile");
         }
         else {
             $os = $ent->{os};
@@ -622,6 +644,9 @@ sub mkinstall {
             }
 
             $pkgdir="$installroot/$os/$arch";
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkgdir = $pkgdir");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkglistfile = $pkglistfile");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: tmplfile = $tmplfile");
         }
 
         if ($arch eq "x86_64") {
@@ -880,6 +905,10 @@ sub mkinstall {
                 $kcmdline .= " live-installer/net-image=http://${instserver}${pkgdir}/install/filesystem.squashfs";
             }
 
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: kcmdline = $kcmdline");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: kernal = $rtftppath/vmlinuz");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: initrd = $rtftppath/initrd.img");
+			
             $bptab->setNodeAttribs($node, { kernel   => "$rtftppath/vmlinuz",
                                             initrd   => "$rtftppath/initrd.img",
                                             kcmdline => $kcmdline });
diff --git a/xCAT-server/lib/xcat/plugins/destiny.pm b/xCAT-server/lib/xcat/plugins/destiny.pm
index a62d00abb..15d78c0f8 100755
--- a/xCAT-server/lib/xcat/plugins/destiny.pm
+++ b/xCAT-server/lib/xcat/plugins/destiny.pm
@@ -93,9 +93,16 @@ sub setdestiny {
     @ARGV = @{$req->{arg}};
     my $noupdateinitrd;
     my $ignorekernelchk;
+    my $verbose;  #>>>>>>>used for trace log>>>>>>>
     GetOptions('noupdateinitrd' => \$noupdateinitrd,
-               'ignorekernelchk' => \$ignorekernelchk,);
-    
+               'ignorekernelchk' => \$ignorekernelchk,
+			   'V'  => \$verbose);      #>>>>>>>used for trace log>>>>>>>
+   
+    #>>>>>>>used for trace log start>>>>>>>
+    my $verbose_on_off=0;
+    if($verbose){$verbose_on_off=1;}
+    #>>>>>>>used for trace log end>>>>>>>
+   
     my $state = $ARGV[0];
     my $reststates;
 
@@ -360,6 +367,7 @@ sub setdestiny {
 	foreach my $tempstate (keys %state_hash1) {
 	    my $samestatenodes=$state_hash1{$tempstate};
 	    #print "state=$tempstate nodes=@$samestatenodes\n";	
+		 xCAT::MsgUtils->trace($verbose_on_off,"d","destiny->process_request: issue mk$tempstate request");	
 	    $errored=0;
 	    $subreq->({command=>["mk$tempstate"],
 		       node=>$samestatenodes, 
diff --git a/xCAT-server/lib/xcat/plugins/dhcp.pm b/xCAT-server/lib/xcat/plugins/dhcp.pm
index 96ef87cf7..84b7d4f03 100755
--- a/xCAT-server/lib/xcat/plugins/dhcp.pm
+++ b/xCAT-server/lib/xcat/plugins/dhcp.pm
@@ -1020,7 +1020,9 @@ sub preprocess_request
     my $callback = shift;
     my $rc       = 0;
    
-
+    #>>>>>>>used for trace log>>>>>>>
+    my $verbose_on_off=0;
+	
     Getopt::Long::Configure("bundling");
     $Getopt::Long::ignorecase = 0;
     Getopt::Long::Configure("no_pass_through");
@@ -1042,7 +1044,8 @@ sub preprocess_request
                      'n'  => \$opt{n},
                      'r'  => \$opt{r},
                      's=s'  => \$statements,  # $statements is declared globally
-                     'q'  => \$opt{q}
+                     'q'  => \$opt{q},
+					  'V'  => \$opt{V}     #>>>>>>>used for trace log>>>>>>>
                    ))
     {
         # If the arguements do not pass GetOptions then issue error message and return
@@ -1052,9 +1055,13 @@ sub preprocess_request
         return 1;
     }
 
+    #>>>>>>>used for trace log>>>>>>>
+	if($opt{V}){ $verbose_on_off=1;}
+	
     # check the syntax
     $rc = check_options($req, \%opt,$callback);
     if ( $rc ) {
+        xCAT::MsgUtils->trace($verbose_on_off,"e","dhcp: command syntax error");
         return [];
     }
     
@@ -1064,6 +1071,7 @@ sub preprocess_request
     if (defined($t_entry)) {
 	$snonly=$t_entry;
     }
+    xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: disjointdhcps = $t_entry");
     my @requests=();
     my $hasHierarchy=0;
 
@@ -1134,6 +1142,11 @@ sub preprocess_request
 	}
 	}
 
+	#>>>>>>>used for trace log>>>>>>>
+	my $str_node;
+	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+	xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: nodes are $str_node");
+
     # If service node and not -n option
     if (($snonly == 1) && (!$opt{n})) {
 	# if a list of nodes are specified
@@ -1193,6 +1206,8 @@ sub preprocess_request
 	}
     }
 
+    xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: hasHierarchy = $hasHierarchy");
+	
     if ( $hasHierarchy)
     {  
         #hierarchy detected, enforce more rigorous sanity
@@ -1228,6 +1243,9 @@ sub process_request
     my $rsp;
     #print Dumper($req);
 
+    #>>>>>>>used for trace log>>>>>>>
+    my $verbose_on_off=0;
+	
     Getopt::Long::Configure("bundling");
     $Getopt::Long::ignorecase = 0;
     Getopt::Long::Configure("no_pass_through");
@@ -1247,7 +1265,8 @@ sub process_request
                      'n'  => \$opt{n},
                      'r'  => \$opt{r},
                      's=s'  => \$statements,  # $statements is declared globally
-                     'q'  => \$opt{q}
+                     'q'  => \$opt{q},
+					 'V'  => \$opt{V}     #>>>>>>>used for trace log>>>>>>>
                    ))
     {
         # If the arguements do not pass GetOptions then issue error message and return
@@ -1257,12 +1276,15 @@ sub process_request
         return 1;
      }
 
-
+     #>>>>>>>used for trace log>>>>>>>
+     if($opt{V}){ $verbose_on_off=1;}
+	
     # Check options again in case we are called from plugin and options have not been processed
     my $rc       = 0;
     $rc = check_options($req, \%opt,$callback);
 
     if ( $rc ) {
+        xCAT::MsgUtils->trace($verbose_on_off,"e","dhcp: there is invalid option in command");
         return [];
     }
 
@@ -1293,6 +1315,7 @@ sub process_request
     }
     
     if($isok == 0) { #do nothing if it is a service node, but not dhcpserver
+	xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: it is a service node, but not dhcpserver. Do nothing");
 	print "Do nothing\n";
 	return;  
     }
@@ -1387,6 +1410,11 @@ sub process_request
         } else {
 			$site_domain = $t_entry;
 		}
+		
+		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: sitelogservers = $sitelogservers");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: sitentpservers = $sitentpservers");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: sitenameservers = $sitenameservers");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: site_domain = $site_domain");
     }
 
     @dhcpconf = ();
@@ -1397,6 +1425,7 @@ sub process_request
     flock($dhcplockfd,LOCK_EX);
     if ($::XCATSITEVALS{externaldhcpservers}) { 
         # do nothing if remote dhcpservers at this point
+		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: remote dhcpservers at this point, do nothing");
     } elsif ($opt{n}) {
         if (-e $dhcpconffile) {
             if ($^O eq 'aix') {
@@ -1426,10 +1455,12 @@ sub process_request
 
             my $bakname = "$dhcpconffile.xcatbak";
             rename("$dhcpconffile", $bakname);
+			xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: Renamed existing dhcp configuration file to  $dhcpconffile.xcatbak");
         }
     }
     else
     {
+        xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: load dhcp config file $dhcpconffile");
         my $rconf;
         open($rconf, $dhcpconffile);    # Read file into memory
         if ($rconf)
@@ -1920,7 +1951,8 @@ sub process_request
     }
     writeout();
     if (not $::XCATSITEVALS{externaldhcpservers} and $restartdhcp) {
-        if ( $^O eq 'aix')
+        xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: restart dhcp service");       
+	   if ( $^O eq 'aix')
         {
             restart_dhcpd_aix();
         }
diff --git a/xCAT-server/lib/xcat/plugins/grub2.pm b/xCAT-server/lib/xcat/plugins/grub2.pm
index 5aea7433e..0f1d70884 100644
--- a/xCAT-server/lib/xcat/plugins/grub2.pm
+++ b/xCAT-server/lib/xcat/plugins/grub2.pm
@@ -341,9 +341,15 @@ sub preprocess_request {
     @ARGV = @args;
     my $nodes = $req->{node};
     #use Getopt::Long;
+    my $HELP;
+    my $VERSION;
+    my $VERBOSE;
     Getopt::Long::Configure("bundling");
     Getopt::Long::Configure("pass_through");
-    if (!GetOptions('h|?|help'  => \$HELP, 'v|version' => \$VERSION) ) {
+    if (!GetOptions('h|?|help'  => \$HELP, 
+	'v|version' => \$VERSION,
+	'V'  => \$VERBOSE    #>>>>>>>used for trace log>>>>>>>
+	) ) {
       if($usage{$command}) {
           my %rsp;
           $rsp{data}->[0]=$usage{$command};
@@ -352,6 +358,12 @@ sub preprocess_request {
       return;
     }
 
+    #>>>>>>>used for trace log start>>>>>>
+    my $verbose_on_off=0;  
+	if($VERBOSE){$verbose_on_off=1;}
+	#xCAT::MsgUtils->trace(1,"d","grub2: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
+	#>>>>>>>used for trace log end>>>>>>>
+	
     if ($HELP) { 
         if($usage{$command}) {
             my %rsp;
@@ -384,6 +396,8 @@ sub preprocess_request {
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
    
+   xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: sharedtftp = $t_entry");
+   
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
       my @SN;
@@ -423,6 +437,21 @@ sub process_request {
     my @args;
     my @nodes;
     my @rnodes;
+	
+    #>>>>>>>used for trace log start>>>>>>>
+    #my @args=();
+    my %opt;
+    my $verbose_on_off=0;
+    if (ref($::XNBA_request->{arg})) {
+        @args=@{$::XNBA_request->{arg}};
+    } else {
+        @args=($::XNBA_request->{arg});
+    }
+    @ARGV = @args;
+    GetOptions('V'  => \$opt{V});
+    if($opt{V}){$verbose_on_off=1;}
+    #>>>>>>>used for trace log end>>>>>>>	
+
     if (ref($request->{node})) {
         @rnodes = @{$request->{node}};
     } else {
@@ -448,7 +477,12 @@ sub process_request {
     } else {
         @nodes = @rnodes;
     }
-  
+	
+    #>>>>>>>used for trace log>>>>>>>
+	my $str_node;
+	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+	xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: nodes are $str_node");
+	  
     # return directly if no nodes in the same network
     unless (@nodes) {
         xCAT::MsgUtils->message("S", "xCAT: grub2 netboot: no valid nodes. Stop the operation on this server.");
@@ -465,11 +499,15 @@ sub process_request {
     unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
         $errored=0;
         if ($request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
-  	  $sub_req->({command=>['runbeginpre'],
+	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: the call is distrubuted to the service node already, so only need to handles my own children");
+	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runbeginpre request");  	 
+	 $sub_req->({command=>['runbeginpre'],
   		      node=>\@nodes,
   		      arg=>[$args[0], '-l']},\&pass_along);
         } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
-  	  $sub_req->({command=>['runbeginpre'],   
+  	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: nodeset did not distribute to the service node");
+	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runbeginpre request");  	 
+	 $sub_req->({command=>['runbeginpre'],   
   		      node=>\@rnodes,
   		      arg=>[$args[0]]},\&pass_along);
         }
@@ -488,6 +526,7 @@ sub process_request {
     if (!$inittime) { $inittime=0;}
     $errored=0;
     unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
+	xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue setdestiny request");
       $sub_req->({command=>['setdestiny'],
   		node=>\@nodes,
   		inittime=>[$inittime],
@@ -594,9 +633,11 @@ sub process_request {
             }
             if ($do_dhcpsetup) {
                 if ($request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
+				xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}}, $callback);
                 } else {
+				xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}},$callback);
                 }
@@ -610,10 +651,12 @@ sub process_request {
         }
         if ($do_dhcpsetup) {
           if ($request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
+		  xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
               $sub_req->({command=>['makedhcp'],
                node=>\@breaknetboot,
                arg=>['-l']},$callback);
           } else {
+		  xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
               $sub_req->({command=>['makedhcp'],
                node=>\@breaknetboot},$callback);
           }
@@ -624,10 +667,12 @@ sub process_request {
     unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') 
         $errored=0;
         if ($request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
-  	  $sub_req->({command=>['runendpre'],
+  	  xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runendpre request");
+	  $sub_req->({command=>['runendpre'],
   		      node=>\@nodes,
   		      arg=>[$args[0], '-l']},\&pass_along);
         } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+		xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runendpre request");
   	  $sub_req->({command=>['runendpre'],   
   		      node=>\@rnodes,
   		      arg=>[$args[0]]},\&pass_along);
diff --git a/xCAT-server/lib/xcat/plugins/petitboot.pm b/xCAT-server/lib/xcat/plugins/petitboot.pm
index 789eaf385..7e8f5aaa8 100644
--- a/xCAT-server/lib/xcat/plugins/petitboot.pm
+++ b/xCAT-server/lib/xcat/plugins/petitboot.pm
@@ -248,9 +248,15 @@ sub preprocess_request {
     @ARGV = @args;
     my $nodes = $req->{node};
     #use Getopt::Long;
+    my $HELP;
+    my $VERSION;
+    my $VERBOSE;
     Getopt::Long::Configure("bundling");
     Getopt::Long::Configure("pass_through");
-    if (!GetOptions('h|?|help'  => \$HELP, 'v|version' => \$VERSION) ) {
+    if (!GetOptions('h|?|help'  => \$HELP, 
+	'v|version' => \$VERSION,
+	'V'  => \$VERBOSE    #>>>>>>>used for trace log>>>>>>>
+	) ) {
       if($usage{$command}) {
           my %rsp;
           $rsp{data}->[0]=$usage{$command};
@@ -259,6 +265,12 @@ sub preprocess_request {
       return;
     }
 
+    #>>>>>>>used for trace log start>>>>>>
+    my $verbose_on_off=0;  
+	if($VERBOSE){$verbose_on_off=1;}
+	#xCAT::MsgUtils->trace(1,"d","petitboot: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
+	#>>>>>>>used for trace log end>>>>>>>
+	
     if ($HELP) { 
 	if($usage{$command}) {
 	    my %rsp;
@@ -290,6 +302,7 @@ sub preprocess_request {
    #if they specify no sharedtftp in site table
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
+   xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: sharedtftp = $t_entry");
    if ( defined($t_entry)  and ($t_entry == 0 or $t_entry =~ /no/i)) {
       # check for  computenodes and servicenodes from the noderange, if so error out
        my @SN;
@@ -324,10 +337,25 @@ sub process_request {
   my $command  = $request->{command}->[0];
   %breaknetbootnodes=();
   %normalnodes=();
+  
+  #>>>>>>>used for trace log start>>>>>>>
+  my @args=();
+  my %opt;
+  my $verbose_on_off=0;
+  if (ref($::request->{arg})) {
+    @args=@{$::request->{arg}};
+  } else {
+    @args=($::request->{arg});
+  }
+  @ARGV = @args;
+  GetOptions('V'  => \$opt{V});
+  if($opt{V}){$verbose_on_off=1;}
+  #>>>>>>>used for trace log end>>>>>>>
+  
   if ($::XCATSITEVALS{"httpmethod"}) { $httpmethod = $::XCATSITEVALS{"httpmethod"}; }
   if ($::XCATSITEVALS{"httpport"}) { $httpport = $::XCATSITEVALS{"httpport"}; }
 
-  my @args;
+  #my @args;
   my @nodes;
   my @rnodes;
   if (ref($request->{node})) {
@@ -356,6 +384,11 @@ sub process_request {
      @nodes = @rnodes;
   }
 
+  #>>>>>>>used for trace log>>>>>>>
+  my $str_node;
+  foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: nodes are $str_node");
+  
   # return directly if no nodes in the same network
   unless (@nodes) {
      xCAT::MsgUtils->message("S", "xCAT: petitboot netboot: no valid nodes. Stop the operation on this server.");
@@ -372,10 +405,14 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
       $errored=0;
       if ($request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: the call is distrubuted to the service node already, so only need to handles my own children");
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+      xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: nodeset did not distribute to the service node");
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);
@@ -395,6 +432,7 @@ sub process_request {
   if (!$inittime) { $inittime=0;}
   $errored=0;
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
+    xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue setdestiny request");
     $sub_req->({command=>['setdestiny'],
 		node=>\@nodes,
 		inittime=>[$inittime],
@@ -475,11 +513,13 @@ sub process_request {
       if ($do_dhcpsetup) {
           foreach my $node (@normalnodeset) {
               if ($request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
+                  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue makedhcp request");
                   $sub_req->({command=>['makedhcp'],
                               node=> [$node],
                               arg=>['-l']},$callback);
                               #arg=>['-l','-s','option conf-file \"'.$fpath.'\";']},$callback);
               } else {
+			  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue makedhcp request");                  
                   $sub_req->({command=>['makedhcp'],
                               node=> [$node]}, $callback);
                               #arg=>['-s','option conf-file \"'.$fpath.'\";']},$callback);
@@ -492,10 +532,12 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') 
       $errored=0;
       if ($request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue runendpre request");
 	  $sub_req->({command=>['runendpre'],
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue runendpre request");
 	  $sub_req->({command=>['runendpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);
diff --git a/xCAT-server/lib/xcat/plugins/prescripts.pm b/xCAT-server/lib/xcat/plugins/prescripts.pm
index 505e2659f..24c522799 100644
--- a/xCAT-server/lib/xcat/plugins/prescripts.pm
+++ b/xCAT-server/lib/xcat/plugins/prescripts.pm
@@ -43,6 +43,21 @@ sub preprocess_request
     my $req = shift;
     my $cb  = shift;
 
+    #>>>>>>>used for trace log start>>>>>>>
+    my @args=();
+    my %opt;
+    my $verbose_on_off=0;
+    if (ref($req->{arg})) {
+        @args=@{$req->{arg}};
+    } else {
+        @args=($req->{arg});
+    }
+    @ARGV = @args;
+    GetOptions('V'  => \$opt{V});
+    if($opt{V}){$verbose_on_off=1;}
+    xCAT::MsgUtils->trace(0,"d","prescripts->preprocess_request: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
+    #>>>>>>>used for trace log end>>>>>>>
+	
     #if already preprocessed, go straight to request
     if ($req->{_xcatpreprocessed}->[0] == 1) { return [$req]; }
 
@@ -78,10 +93,13 @@ sub preprocess_request
     }
     
     # if no nodes left to process, we are done
-    if (! @nodes) { return; }
+    if (! @nodes) { 
+        xCAT::MsgUtils->trace($verbose_on_off,"d",        "prescripts->preprocess_request: no nodes left to process, we are done");
+        return; 
+	}
 
     my $service = "xcat";
-    my @args=();
+    @args=();
     if (ref($req->{arg})) {
 	@args=@{$req->{arg}};
     } else {
@@ -91,6 +109,13 @@ sub preprocess_request
 
     #print "prepscripts: preprocess_request get called, args=@args, nodes=@$nodes\n";
     
+    #>>>>>>>used for trace log>>>>>>
+    my $str_node;
+	my $str_args;
+	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+    foreach my $str_a (@args){$str_args .=  $str_a." ";}
+    xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts->preprocess_request: get called, args=$str_args, nodes=$str_node");
+	
     #use Getopt::Long;
     Getopt::Long::Configure("bundling");
     Getopt::Long::Configure("pass_through");
@@ -117,6 +142,7 @@ sub preprocess_request
 	    $reqcopy->{'_xcatdest'} = $hostinfo[0];
 	    $reqcopy->{_xcatpreprocessed}->[0] = 1;
 	    push @requests, $reqcopy;
+		xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts: handle request in $hostinfo[0]");
 	    return \@requests;
 	}
     } else { #run on mn and need to dispatch the requests to the service nodes
@@ -130,6 +156,7 @@ sub preprocess_request
 	    $reqcopy->{node} = $sn->{$snkey};
 	    $reqcopy->{'_xcatdest'} = $snkey;
 	    $reqcopy->{_xcatpreprocessed}->[0] = 1;
+	    xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts: handle request in $snkey");
 	    push @requests, $reqcopy;
 	    
 	}   # end foreach
diff --git a/xCAT-server/lib/xcat/plugins/pxe.pm b/xCAT-server/lib/xcat/plugins/pxe.pm
index abc766aef..745ef8a8c 100644
--- a/xCAT-server/lib/xcat/plugins/pxe.pm
+++ b/xCAT-server/lib/xcat/plugins/pxe.pm
@@ -295,9 +295,15 @@ sub preprocess_request {
         @args=($req->{arg});
     }
     @ARGV = @args;
+    my $HELP;
+    my $VERSION;
+    my $VERBOSE;	
     Getopt::Long::Configure("bundling");
     Getopt::Long::Configure("pass_through");
-    if (!GetOptions('h|?|help' => \$HELP, 'v|version' => \$VERSION) ) {
+    if (!GetOptions('h|?|help' => \$HELP, 
+	'v|version' => \$VERSION,
+	'V'  => \$VERBOSE    #>>>>>>>used for trace log>>>>>>>	
+	) ) {
         if($usage{$command}) {
             my %rsp;
             $rsp{data}->[0]=$usage{$command};
@@ -306,6 +312,12 @@ sub preprocess_request {
         return;
     }
 
+    #>>>>>>>used for trace log start>>>>>>
+    my $verbose_on_off=0;  
+	if($VERBOSE){$verbose_on_off=1;}
+	#xCAT::MsgUtils->trace(1,"d","pxe: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
+	#>>>>>>>used for trace log end>>>>>>>
+	
     if ($HELP) {
         if($usage{$command}) {
             my %rsp;
@@ -335,6 +347,7 @@ sub preprocess_request {
    #my $sent = $stab->getAttribs({key=>'sharedtftp'},'value');
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
+   xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: sharedtftp = $t_entry");
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
       my @SN;
@@ -370,6 +383,20 @@ sub process_request {
   my @args;
   my @nodes;
   my @rnodes;
+  
+  #>>>>>>>used for trace log start>>>>>>>
+  my %opt;
+  my $verbose_on_off=0;
+  if (ref($::PXE_request->{arg})) {
+    @args=@{$::PXE_request->{arg}};
+  } else {
+    @args=($::PXE_request->{arg});
+  }
+  @ARGV = @args;
+  GetOptions('V'  => \$opt{V});
+  if($opt{V}){$verbose_on_off=1;}
+  #>>>>>>>used for trace log end>>>>>>>
+  
   if (ref($::PXE_request->{node})) {
     @rnodes = @{$::PXE_request->{node}};
   } else {
@@ -397,6 +424,11 @@ sub process_request {
      @nodes = @rnodes;
   }
 
+  #>>>>>>>used for trace log>>>>>>>
+  my $str_node;
+  foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+  xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: nodes are $str_node");
+  
   # return directly if no nodes in the same network
   unless (@nodes) {
      xCAT::MsgUtils->message("S", "xCAT: pxe netboot: no valid nodes. Stop the operation on this server.");
@@ -413,10 +445,14 @@ sub process_request {
    unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
        $errored=0;
        if ($::PXE_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: the call is distrubuted to the service node already, so only need to handles my own children");
+       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runbeginpre request");
            $sub_req->({command=>['runbeginpre'],
            node=>\@nodes,
            arg=>[$args[0], '-l']},\&pass_along);
        } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: nodeset did not distribute to the service node");
+       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runbeginpre request");
         $sub_req->({command=>['runbeginpre'],   
                     node=>\@rnodes,
                     arg=>[$args[0]]},\&pass_along);
@@ -453,6 +489,7 @@ sub process_request {
   if (exists($::PXE_request->{inittime})) { $inittime= $::PXE_request->{inittime}->[0];}
   if (!$inittime) { $inittime=0;}
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
+   xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue setdestiny request");
     $sub_req->({command=>['setdestiny'],
                node=>\@nodes,
                inittime=>[$inittime],
@@ -518,9 +555,11 @@ sub process_request {
       
       if ($do_dhcpsetup) {
         if ($::PXE_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
+            xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],arg=>['-l'],
                         node=>\@nodes},$::PXE_callback);
         } else {
+            xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],
                        node=>\@nodes},$::PXE_callback);
         }
@@ -575,10 +614,12 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') 
       $errored=0;
       if ($::PXE_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+         xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runendpre request");
          $sub_req->({command=>['runendpre'],
                      node=>\@nodes,
                      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+         xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runendpre request");
          $sub_req->({command=>['runendpre'],   
                      node=>\@rnodes,
                      arg=>[$args[0]]},\&pass_along);
diff --git a/xCAT-server/lib/xcat/plugins/sles.pm b/xCAT-server/lib/xcat/plugins/sles.pm
index ff0fbbc0a..94f28989d 100755
--- a/xCAT-server/lib/xcat/plugins/sles.pm
+++ b/xCAT-server/lib/xcat/plugins/sles.pm
@@ -752,6 +752,21 @@ sub mkinstall
     my $osimagetab;
     my $osdistrouptab;
 
+    #>>>>>>>used for trace log start>>>>>>>
+    my @args=();
+    my %opt;
+    if (ref($request->{arg})) {
+        @args=@{$request->{arg}};
+    } else {
+        @args=($request->{arg});
+    }
+    @ARGV = @args;
+    GetOptions('V'  => \$opt{V});
+    my $verbose_on_off=0;
+    if($opt{V}){$verbose_on_off=1;}
+    xCAT::MsgUtils->trace(0,"d","sles->mkinstall: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
+    #>>>>>>>used for trace log end>>>>>>>
+	
     my $ntents = $ostab->getNodesAttribs($request->{node}, ['os', 'arch', 'profile', 'provmethod']);
     my %img_hash=();
     my $installroot;
@@ -779,7 +794,9 @@ sub mkinstall
             $installroot = $t_entry;
         }
     #}
-
+	
+    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: installroot = $installroot");
+	
     my %donetftp;
     require xCAT::Template; #only used here, load so memory can be COWed
     # Define a variable for driver update list
@@ -829,7 +846,9 @@ sub mkinstall
         } else {
 	   $tftpdir = $globaltftpdir;
         }
-
+		
+        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: tftpdir = $tftpdir");
+		
         if ($ent and $ent->{provmethod} and ($ent->{provmethod} ne 'install') and ($ent->{provmethod} ne 'netboot') and ($ent->{provmethod} ne 'statelite')) {
 	    $imagename=$ent->{provmethod};
 	    if (!exists($img_hash{$imagename})) {
@@ -914,6 +933,12 @@ sub mkinstall
 	    $netdrivers = $ph->{netdrivers};
 	    $driverupdatesrc = $ph->{driverupdatesrc};
 	    $osupdir = $ph->{'osupdir'};
+		
+	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: imagename = $imagename");
+	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkgdir = $pkgdir");
+	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkglistfile = $pkglistfile");
+	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: tmplfile = $tmplfile");
+	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: partfile = $partfile");
 	}
 	else {
 	    $os = $ent->{os};
@@ -939,7 +964,12 @@ sub mkinstall
 
         #get the partition file from the linuximage table
         my $imgname = "$os-$arch-install-$profile";
-
+		
+        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: imagename = $imgname");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkgdir = $pkgdir");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkglistfile = $pkglistfile");
+		xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: tmplfile = $tmplfile");
+		
         if (! $linuximagetab) {
             $linuximagetab = xCAT::Table->new('linuximage');
         }
@@ -948,6 +978,7 @@ sub mkinstall
             (my $ref1) = $linuximagetab->getAttribs({imagename => $imgname}, 'partitionfile');
             if ( $ref1 and $ref1->{'partitionfile'}){
                 $partfile = $ref1->{'partitionfile'};
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: partfile = $partfile");
             }
         }
         else {
@@ -1080,18 +1111,21 @@ sub mkinstall
                         copy("$pkgdir/1/boot/$arch/loader/linux", "$tftppath");
                         copy("$pkgdir/1/boot/$arch/loader/initrd", "$tftppath");
                         @dd_drivers = &insert_dd($callback, $os, $arch, "$tftppath/initrd", "$tftppath/linux", $driverupdatesrc, $netdrivers, $osupdir, $ignorekernelchk);
+                        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: copy initrd.img and linux to $tftppath");
                     }
                 } elsif ($arch =~ /x86/) {
                     unless ($noupdateinitrd) {
                         copy("$pkgdir/1/boot/i386/loader/linux", "$tftppath");
                         copy("$pkgdir/1/boot/i386/loader/initrd", "$tftppath");
                         @dd_drivers = &insert_dd($callback, $os, $arch, "$tftppath/initrd", "$tftppath/linux", $driverupdatesrc, $netdrivers, $osupdir, $ignorekernelchk);
+                        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: copy initrd.img and linux to $tftppath");
                     }
                 } elsif ($arch eq "ppc64le") {
                     unless ($noupdateinitrd) {
                         copy("$pkgdir/1/boot/$arch/linux", "$tftppath");
                         copy("$pkgdir/1/boot/$arch/initrd", "$tftppath");
                         @dd_drivers = &insert_dd($callback, $os, $arch, "$tftppath/initrd", "$tftppath/linux", $driverupdatesrc, $netdrivers, $osupdir, $ignorekernelchk);
+                        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: copy initrd.img and linux to $tftppath");
                     }
                 }
                 elsif ($arch =~ /ppc/)
@@ -1099,6 +1133,7 @@ sub mkinstall
                     unless ($noupdateinitrd) {
                         copy("$pkgdir/1/suseboot/inst64", "$tftppath");
                         @dd_drivers = &insert_dd($callback, $os, $arch, "$tftppath/inst64", undef, $driverupdatesrc, $netdrivers, $osupdir, $ignorekernelchk);
+                        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: copy inst64 to $tftppath");
                     }
                 }
             }
@@ -1278,6 +1313,9 @@ sub mkinstall
             {
                 $kernelpath = "$rtftppath/linux";
                 $initrdpath = "$rtftppath/initrd";
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kcmdline = $kcmdline");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kernal = $kernelpath");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: initrd = $initrdpath");
                 $bptab->setNodeAttribs(
                                         $node,
                                         {
@@ -1290,6 +1328,9 @@ sub mkinstall
             elsif ($arch =~ /ppc/)
             {
                 $kernelpath = "$rtftppath/inst64";
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kcmdline = $kcmdline");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kernal = $kernelpath");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: initrd = ");
                 $bptab->setNodeAttribs(
                                         $node,
                                         {
diff --git a/xCAT-server/lib/xcat/plugins/xnba.pm b/xCAT-server/lib/xcat/plugins/xnba.pm
index 78012e387..cbc1bd8f9 100644
--- a/xCAT-server/lib/xcat/plugins/xnba.pm
+++ b/xCAT-server/lib/xcat/plugins/xnba.pm
@@ -317,7 +317,11 @@ sub preprocess_request {
     Getopt::Long::Configure("pass_through");
     my $HELP;
     my $VERSION;
-    if (!GetOptions('h|?|help'  => \$HELP, 'v|version' => \$VERSION) ) {
+	my $VERBOSE;
+    if (!GetOptions('h|?|help'  => \$HELP,
+	'v|version' => \$VERSION,
+	'V'  => \$VERBOSE    #>>>>>>>used for trace log>>>>>>>
+	) ) {
       if($usage{$command}) {
           my %rsp;
           $rsp{data}->[0]=$usage{$command};
@@ -326,6 +330,12 @@ sub preprocess_request {
       return;
     }
 
+    #>>>>>>>used for trace log start>>>>>>
+    my $verbose_on_off=0;  
+	if($VERBOSE){$verbose_on_off=1;}
+	#xCAT::MsgUtils->trace(1,"d","xnba: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
+	#>>>>>>>used for trace log end>>>>>>>
+	
     if ($HELP) { 
 	if($usage{$command}) {
 	    my %rsp;
@@ -357,6 +367,7 @@ sub preprocess_request {
    #they specify no sharedtftp in site table
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
+   xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: sharedtftp = $t_entry");
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
       my @SN;
@@ -392,6 +403,20 @@ sub process_request {
   my @args;
   my @nodes;
   my @rnodes;
+  
+  #>>>>>>>used for trace log start>>>>>>>
+  my %opt;
+  my $verbose_on_off=0;
+  if (ref($::XNBA_request->{arg})) {
+      @args=@{$::XNBA_request->{arg}};
+  } else {
+      @args=($::XNBA_request->{arg});
+  }
+  @ARGV = @args;
+  GetOptions('V'  => \$opt{V});
+  if($opt{V}){$verbose_on_off=1;}
+  #>>>>>>>used for trace log end>>>>>>>
+  
   if (ref($::XNBA_request->{node})) {
     @rnodes = @{$::XNBA_request->{node}};
   } else {
@@ -419,6 +444,11 @@ sub process_request {
      @nodes = @rnodes;
   }
 
+  #>>>>>>>used for trace log>>>>>>>
+  my $str_node;
+  foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+  xCAT::MsgUtils->trace(0,"d","xnba: nodes are $str_node");
+  
   # return directly if no nodes in the same network
   unless (@nodes) {
      xCAT::MsgUtils->message("S", "xCAT: xnba netboot: no valid nodes. Stop the operation on this server.");
@@ -435,10 +465,14 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
       $errored=0;
       if ($::XNBA_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: the call is distrubuted to the service node already, so only need to handles my own children");
+	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: nodeset did not distribute to the service node");
+	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);
@@ -472,6 +506,7 @@ sub process_request {
   if (!$inittime) { $inittime=0;}
   $errored=0;
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
+  xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue setdestiny request");
       $sub_req->({command=>['setdestiny'],
 		  node=>\@nodes,
 		  inittime=>[$inittime],
@@ -550,9 +585,11 @@ sub process_request {
       
       if ($do_dhcpsetup) {
         if ($::XNBA_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
+            xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],arg=>['-l'],
                         node=>\@nodes},$::XNBA_callback);
         } else {
+            xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],
                        node=>\@nodes},$::XNBA_callback);
         }
@@ -563,10 +600,12 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') 
       $errored=0;
       if ($::XNBA_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runendpre request");
 	  $sub_req->({command=>['runendpre'],
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runendpre request");
 	  $sub_req->({command=>['runendpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);
diff --git a/xCAT-server/lib/xcat/plugins/yaboot.pm b/xCAT-server/lib/xcat/plugins/yaboot.pm
index 7061270ba..7781448b7 100644
--- a/xCAT-server/lib/xcat/plugins/yaboot.pm
+++ b/xCAT-server/lib/xcat/plugins/yaboot.pm
@@ -358,9 +358,15 @@ sub preprocess_request {
     @ARGV = @args;
     my $nodes = $req->{node};
     #use Getopt::Long;
+    my $HELP;
+    my $VERSION;
+    my $VERBOSE;	
     Getopt::Long::Configure("bundling");
     Getopt::Long::Configure("pass_through");
-    if (!GetOptions('h|?|help'  => \$HELP, 'v|version' => \$VERSION) ) {
+    if (!GetOptions('h|?|help'  => \$HELP, 
+	'v|version' => \$VERSION,
+	'V'  => \$VERBOSE    #>>>>>>>used for trace log>>>>>>>
+	) ) {
       if($usage{$command}) {
           my %rsp;
           $rsp{data}->[0]=$usage{$command};
@@ -368,7 +374,13 @@ sub preprocess_request {
       }
       return;
     }
-
+	
+	#>>>>>>>used for trace log start>>>>>>
+    my $verbose_on_off=0;  
+	if($VERBOSE){$verbose_on_off=1;}
+	#xCAT::MsgUtils->trace(1,"d","yaboot: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
+	#>>>>>>>used for trace log end>>>>>>>
+	
     if ($HELP) { 
 	if($usage{$command}) {
 	    my %rsp;
@@ -401,6 +413,8 @@ sub preprocess_request {
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
    
+   xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: sharedtftp = $t_entry");
+   
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
       my @SN;
@@ -438,6 +452,22 @@ sub process_request {
   %normalnodes=();
 
   my @args;
+  
+  #>>>>>>>used for trace log start>>>>>>>
+  my @args=();
+  my %opt;
+  my $verbose_on_off=0;
+  if (ref($::YABOOT_request->{arg})) {
+      @args=@{$::YABOOT_request->{arg}};
+  } else {
+      @args=($::YABOOT_request->{arg});
+  }
+  @ARGV = @args;
+  GetOptions('V'  => \$opt{V});
+  if($opt{V}){$verbose_on_off=1;}
+  #>>>>>>>used for trace log end>>>>>>>
+  
+  
   my @nodes;
   my @rnodes;
   if (ref($::YABOOT_request->{node})) {
@@ -466,6 +496,11 @@ sub process_request {
      @nodes = @rnodes;
   }
 
+      #>>>>>>>used for trace log>>>>>>>
+	my $str_node;
+	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+	xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: nodes are $str_node");
+  
   # return directly if no nodes in the same network
   unless (@nodes) {
      xCAT::MsgUtils->message("S", "xCAT: yaboot netboot: no valid nodes. Stop the operation on this server.");
@@ -482,10 +517,14 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
       $errored=0;
       if ($::YABOOT_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: the call is distrubuted to the service node already, so only need to handles my own children");
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: nodeset did not distribute to the service node");
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);
@@ -504,6 +543,7 @@ sub process_request {
   if (!$inittime) { $inittime=0;}
   $errored=0;
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
+    xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue setdestiny request");
     $sub_req->({command=>['setdestiny'],
 		node=>\@nodes,
 		inittime=>[$inittime],
@@ -710,10 +750,12 @@ sub process_request {
                         }
                     }
                     if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
+					xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}},
                          arg=>['-l']},$::YABOOT_callback);
                     } else {
+					xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}},$::YABOOT_callback);
                     }
@@ -725,9 +767,11 @@ sub process_request {
                     }
 
                     if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command, only change local settings if already farmed
+					xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],arg=>['-l'],
                            node=>\@{$osimagenodehash{$osimage}}},$::YABOOT_callback);
                     } else {
+					 xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}},$::YABOOT_callback);
                     }
@@ -735,9 +779,11 @@ sub process_request {
             }
         } else {
             if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command, only change local settings if already farmed
+			xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],arg=>['-l'],
                    node=>\@normalnodeset},$::YABOOT_callback);
             } else {
+			xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],
                  node=>\@normalnodeset},$::YABOOT_callback);
             }
@@ -748,10 +794,12 @@ sub process_request {
             }
         }
         if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
+		    xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],
              node=>\@breaknetboot,
              arg=>['-l']},$::YABOOT_callback);
         } else {
+		    xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],
              node=>\@breaknetboot}, $::YABOOT_callback);
         }
@@ -762,10 +810,12 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') 
       $errored=0;
       if ($::YABOOT_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue runendpre request");
 	  $sub_req->({command=>['runendpre'],
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
+	  xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue runendpre request");
 	  $sub_req->({command=>['runendpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);

From a81a5e1a45adb9c85e55339ec71d83e9b0d403d7 Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Tue, 18 Aug 2015 04:11:59 -0400
Subject: [PATCH 04/12] fix the indent issue and combine trace message

---
 xCAT-server/lib/xcat/plugins/anaconda.pm   | 30 +++++----------
 xCAT-server/lib/xcat/plugins/debian.pm     | 16 ++------
 xCAT-server/lib/xcat/plugins/destiny.pm    |  5 ++-
 xCAT-server/lib/xcat/plugins/dhcp.pm       | 36 ++++++++---------
 xCAT-server/lib/xcat/plugins/grub2.pm      | 45 ++++++++++------------
 xCAT-server/lib/xcat/plugins/petitboot.pm  | 15 +++-----
 xCAT-server/lib/xcat/plugins/prescripts.pm | 15 +++-----
 xCAT-server/lib/xcat/plugins/pxe.pm        | 22 +++++------
 xCAT-server/lib/xcat/plugins/sles.pm       | 26 ++++---------
 xCAT-server/lib/xcat/plugins/xnba.pm       | 24 ++++++------
 xCAT-server/lib/xcat/plugins/yaboot.pm     | 40 +++++++++----------
 11 files changed, 112 insertions(+), 162 deletions(-)
 mode change 100755 => 100644 xCAT-server/lib/xcat/plugins/anaconda.pm
 mode change 100755 => 100644 xCAT-server/lib/xcat/plugins/debian.pm
 mode change 100755 => 100644 xCAT-server/lib/xcat/plugins/dhcp.pm
 mode change 100755 => 100644 xCAT-server/lib/xcat/plugins/sles.pm

diff --git a/xCAT-server/lib/xcat/plugins/anaconda.pm b/xCAT-server/lib/xcat/plugins/anaconda.pm
old mode 100755
new mode 100644
index 3b2803a1c..bf7fff333
--- a/xCAT-server/lib/xcat/plugins/anaconda.pm
+++ b/xCAT-server/lib/xcat/plugins/anaconda.pm
@@ -964,7 +964,6 @@ sub mkinstall
     GetOptions('V'  => \$opt{V});
     my $verbose_on_off=0;
     if($opt{V}){$verbose_on_off=1;}
-    xCAT::MsgUtils->trace(0,"d","anaconda->mkinstall: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
     #>>>>>>>used for trace log end>>>>>>>
 	
     #if ($sitetab)
@@ -976,8 +975,6 @@ sub mkinstall
     {
         $installroot = $site_ent;
     }
-	
-    xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: installroot = $installroot");
 		
     #( $ref) = $sitetab->getAttribs({key => 'tftpdir'}, 'value');
     @ents = xCAT::TableUtils->get_site_attribute("tftpdir");
@@ -986,7 +983,7 @@ sub mkinstall
     {
         $globaltftpdir = $site_ent;
     }
-    xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: globaltftpdir = $globaltftpdir");
+    xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: installroot=$installroot globaltftpdir=$globaltftpdir");
     #}
 
     my $node;
@@ -1053,8 +1050,6 @@ sub mkinstall
         } else {
             $xcatmaster = '!myipfn!';
         }
-
-        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: xcatmaster = $xcatmaster");
 		
         my $osinst;
         if ($rents{$node}->[0] and $rents{$node}->[0]->{tftpdir}) {
@@ -1062,9 +1057,11 @@ sub mkinstall
         } else {
 		$tftpdir = $globaltftpdir;
         }
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: tftpdir = $tftpdir");
         my $ent = $osents{$node}->[0]; #$ostab->getNodeAttribs($node, ['profile', 'os', 'arch']);
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: provmethod = $ent->{provmethod}");
+        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: xcatmaster=$xcatmaster tftpdir=$tftpdir provmethod=$ent->{provmethod}");
+		
+		
+		
         if ($ent and $ent->{provmethod} and ($ent->{provmethod} ne 'install') and ($ent->{provmethod} ne 'netboot') and ($ent->{provmethod} ne 'statelite')) {
 	    $imagename=$ent->{provmethod};
 	    #print "imagename=$imagename\n";
@@ -1179,11 +1176,7 @@ sub mkinstall
 	    $driverupdatesrc = $ph->{driverupdatesrc};
 	    $osupdir = $ph->{'osupdir'};
 		
-        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: imagename = $imagename");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkgdir = $pkgdir");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkglistfile = $pkglistfile");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: tmplfile = $tmplfile");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: partfile = $partfile");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: imagename=$imagename pkgdir=$pkgdir pkglistfile=$pkglistfile tmplfile=$tmplfile partfile=$partfile");
 	}
 	else {
 	    $os = $ent->{os};
@@ -1213,10 +1206,7 @@ sub mkinstall
         #get the partition file from the linuximage table
         my $imgname = "$os-$arch-install-$profile";
 
-        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: imagename = $imgname");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkgdir = $pkgdir");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: pkglistfile = $pkglistfile");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: tmplfile = $tmplfile");
+        xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: imagename=$imgname pkgdir=$pkgdir pkglistfile=$pkglistfile tmplfile=$tmplfile");
 		
         if ( ! $linuximagetab ) {
             $linuximagetab = xCAT::Table->new('linuximage');
@@ -1226,7 +1216,7 @@ sub mkinstall
             (my $ref1) = $linuximagetab->getAttribs({imagename => $imgname}, 'partitionfile');
             if ( $ref1 and $ref1->{'partitionfile'}){
                 $partfile = $ref1->{'partitionfile'};
-				xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: partfile = $partfile");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: partfile = $partfile");
             }
         }
         #can not find the linux osiamge object, tell users to run "nodeset <nr> osimage=***"
@@ -1618,9 +1608,7 @@ sub mkinstall
                     $i = "$rtftppath/initrd.img";
             }
 			
-			xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: kcmdline = $kcmdline");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: kernal = $k");
-			xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: initrd = $i");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: kcmdline=$kcmdline kernal=$k initrd=$i");
 			
             $bptab->setNodeAttribs(
                 $node,
diff --git a/xCAT-server/lib/xcat/plugins/debian.pm b/xCAT-server/lib/xcat/plugins/debian.pm
old mode 100755
new mode 100644
index 9a3971cb6..90a18bf7c
--- a/xCAT-server/lib/xcat/plugins/debian.pm
+++ b/xCAT-server/lib/xcat/plugins/debian.pm
@@ -457,7 +457,6 @@ sub mkinstall {
     GetOptions('V'  => \$opt{V});
     my $verbose_on_off=0;
     if($opt{V}){$verbose_on_off=1;}
-    xCAT::MsgUtils->trace(0,"d","debian->mkinstall: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
     #>>>>>>>used for trace log end>>>>>>>
 	
     my $installroot;
@@ -471,7 +470,7 @@ sub mkinstall {
         }
     }
 	
-    xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: installroot = $installroot");
+    xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: installroot=$installroot");
 	
     my $node;
     my $ostab = xCAT::Table->new('nodetype');
@@ -620,10 +619,7 @@ sub mkinstall {
             }
             $pkglistfile=$ph->{pkglist};
 			
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: imagename = $imagename");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkgdir = $pkgdir");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkglistfile = $pkglistfile");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: tmplfile = $tmplfile");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: imagename=$imagename pkgdir=$pkgdir pkglistfile=$pkglistfile tmplfile=$tmplfile");
         }
         else {
             $os = $ent->{os};
@@ -644,9 +640,7 @@ sub mkinstall {
             }
 
             $pkgdir="$installroot/$os/$arch";
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkgdir = $pkgdir");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkglistfile = $pkglistfile");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: tmplfile = $tmplfile");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: pkgdir=$pkgdir pkglistfile=$pkglistfile tmplfile=$tmplfile");
         }
 
         if ($arch eq "x86_64") {
@@ -905,9 +899,7 @@ sub mkinstall {
                 $kcmdline .= " live-installer/net-image=http://${instserver}${pkgdir}/install/filesystem.squashfs";
             }
 
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: kcmdline = $kcmdline");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: kernal = $rtftppath/vmlinuz");
-            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: initrd = $rtftppath/initrd.img");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","debian->mkinstall: kcmdline=$kcmdline kernal=$rtftppath/vmlinuz initrd=$rtftppath/initrd.img");
 			
             $bptab->setNodeAttribs($node, { kernel   => "$rtftppath/vmlinuz",
                                             initrd   => "$rtftppath/initrd.img",
diff --git a/xCAT-server/lib/xcat/plugins/destiny.pm b/xCAT-server/lib/xcat/plugins/destiny.pm
index 15d78c0f8..0fd8916f5 100755
--- a/xCAT-server/lib/xcat/plugins/destiny.pm
+++ b/xCAT-server/lib/xcat/plugins/destiny.pm
@@ -93,10 +93,11 @@ sub setdestiny {
     @ARGV = @{$req->{arg}};
     my $noupdateinitrd;
     my $ignorekernelchk;
-    my $verbose;  #>>>>>>>used for trace log>>>>>>>
+    #>>>>>>>used for trace log>>>>>>>
+    my $verbose; 
     GetOptions('noupdateinitrd' => \$noupdateinitrd,
                'ignorekernelchk' => \$ignorekernelchk,
-			   'V'  => \$verbose);      #>>>>>>>used for trace log>>>>>>>
+	       'V'  => \$verbose);      #>>>>>>>used for trace log>>>>>>>
    
     #>>>>>>>used for trace log start>>>>>>>
     my $verbose_on_off=0;
diff --git a/xCAT-server/lib/xcat/plugins/dhcp.pm b/xCAT-server/lib/xcat/plugins/dhcp.pm
old mode 100755
new mode 100644
index 84b7d4f03..0fb5d45e2
--- a/xCAT-server/lib/xcat/plugins/dhcp.pm
+++ b/xCAT-server/lib/xcat/plugins/dhcp.pm
@@ -1045,7 +1045,7 @@ sub preprocess_request
                      'r'  => \$opt{r},
                      's=s'  => \$statements,  # $statements is declared globally
                      'q'  => \$opt{q},
-					  'V'  => \$opt{V}     #>>>>>>>used for trace log>>>>>>>
+                     'V'  => \$opt{V}     #>>>>>>>used for trace log>>>>>>>
                    ))
     {
         # If the arguements do not pass GetOptions then issue error message and return
@@ -1056,7 +1056,7 @@ sub preprocess_request
     }
 
     #>>>>>>>used for trace log>>>>>>>
-	if($opt{V}){ $verbose_on_off=1;}
+    if($opt{V}){ $verbose_on_off=1;}
 	
     # check the syntax
     $rc = check_options($req, \%opt,$callback);
@@ -1071,7 +1071,7 @@ sub preprocess_request
     if (defined($t_entry)) {
 	$snonly=$t_entry;
     }
-    xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: disjointdhcps = $t_entry");
+    xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: disjointdhcps=$t_entry");
     my @requests=();
     my $hasHierarchy=0;
 
@@ -1140,12 +1140,11 @@ sub preprocess_request
 			xCAT::MsgUtils->message("I", $rsp, $callback);
 		}
 	}
-	}
+    }
 
-	#>>>>>>>used for trace log>>>>>>>
-	my $str_node;
-	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
-	xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: nodes are $str_node");
+    #>>>>>>>used for trace log>>>>>>>
+    my $str_node=join(" ",@nodes);
+    xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: nodes are $str_node");
 
     # If service node and not -n option
     if (($snonly == 1) && (!$opt{n})) {
@@ -1206,7 +1205,7 @@ sub preprocess_request
 	}
     }
 
-    xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: hasHierarchy = $hasHierarchy");
+    xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: hasHierarchy=$hasHierarchy");
 	
     if ( $hasHierarchy)
     {  
@@ -1266,7 +1265,7 @@ sub process_request
                      'r'  => \$opt{r},
                      's=s'  => \$statements,  # $statements is declared globally
                      'q'  => \$opt{q},
-					 'V'  => \$opt{V}     #>>>>>>>used for trace log>>>>>>>
+                     'V'  => \$opt{V}     #>>>>>>>used for trace log>>>>>>>
                    ))
     {
         # If the arguements do not pass GetOptions then issue error message and return
@@ -1276,8 +1275,8 @@ sub process_request
         return 1;
      }
 
-     #>>>>>>>used for trace log>>>>>>>
-     if($opt{V}){ $verbose_on_off=1;}
+    #>>>>>>>used for trace log>>>>>>>
+    if($opt{V}){ $verbose_on_off=1;}
 	
     # Check options again in case we are called from plugin and options have not been processed
     my $rc       = 0;
@@ -1409,12 +1408,9 @@ sub process_request
         #    return;
         } else {
 			$site_domain = $t_entry;
-		}
+	}
 		
-		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: sitelogservers = $sitelogservers");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: sitentpservers = $sitentpservers");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: sitenameservers = $sitenameservers");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: site_domain = $site_domain");
+        xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: sitelogservers=$sitelogservers sitentpservers=$sitentpservers sitenameservers=$sitenameservers site_domain=$site_domain");
     }
 
     @dhcpconf = ();
@@ -1425,7 +1421,7 @@ sub process_request
     flock($dhcplockfd,LOCK_EX);
     if ($::XCATSITEVALS{externaldhcpservers}) { 
         # do nothing if remote dhcpservers at this point
-		xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: remote dhcpservers at this point, do nothing");
+        xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: remote dhcpservers at this point, do nothing");
     } elsif ($opt{n}) {
         if (-e $dhcpconffile) {
             if ($^O eq 'aix') {
@@ -1455,7 +1451,7 @@ sub process_request
 
             my $bakname = "$dhcpconffile.xcatbak";
             rename("$dhcpconffile", $bakname);
-			xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: Renamed existing dhcp configuration file to  $dhcpconffile.xcatbak");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: Renamed existing dhcp configuration file to  $dhcpconffile.xcatbak");
         }
     }
     else
@@ -1952,7 +1948,7 @@ sub process_request
     writeout();
     if (not $::XCATSITEVALS{externaldhcpservers} and $restartdhcp) {
         xCAT::MsgUtils->trace($verbose_on_off,"d","dhcp: restart dhcp service");       
-	   if ( $^O eq 'aix')
+        if ( $^O eq 'aix')
         {
             restart_dhcpd_aix();
         }
diff --git a/xCAT-server/lib/xcat/plugins/grub2.pm b/xCAT-server/lib/xcat/plugins/grub2.pm
index 0f1d70884..018566e0f 100644
--- a/xCAT-server/lib/xcat/plugins/grub2.pm
+++ b/xCAT-server/lib/xcat/plugins/grub2.pm
@@ -360,9 +360,8 @@ sub preprocess_request {
 
     #>>>>>>>used for trace log start>>>>>>
     my $verbose_on_off=0;  
-	if($VERBOSE){$verbose_on_off=1;}
-	#xCAT::MsgUtils->trace(1,"d","grub2: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
-	#>>>>>>>used for trace log end>>>>>>>
+    if($VERBOSE){$verbose_on_off=1;}
+    #>>>>>>>used for trace log end>>>>>>>
 	
     if ($HELP) { 
         if($usage{$command}) {
@@ -396,7 +395,7 @@ sub preprocess_request {
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
    
-   xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: sharedtftp = $t_entry");
+   xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: sharedtftp=$t_entry");
    
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
@@ -439,7 +438,6 @@ sub process_request {
     my @rnodes;
 	
     #>>>>>>>used for trace log start>>>>>>>
-    #my @args=();
     my %opt;
     my $verbose_on_off=0;
     if (ref($::XNBA_request->{arg})) {
@@ -479,9 +477,8 @@ sub process_request {
     }
 	
     #>>>>>>>used for trace log>>>>>>>
-	my $str_node;
-	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
-	xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: nodes are $str_node");
+    my $str_node = join(" ",@nodes);
+    xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: nodes are $str_node");
 	  
     # return directly if no nodes in the same network
     unless (@nodes) {
@@ -499,15 +496,15 @@ sub process_request {
     unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
         $errored=0;
         if ($request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
-	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: the call is distrubuted to the service node already, so only need to handles my own children");
-	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runbeginpre request");  	 
-	 $sub_req->({command=>['runbeginpre'],
+            xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: the call is distrubuted to the service node already, so only need to handles my own children");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runbeginpre request");  	 
+            $sub_req->({command=>['runbeginpre'],
   		      node=>\@nodes,
   		      arg=>[$args[0], '-l']},\&pass_along);
         } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
-  	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: nodeset did not distribute to the service node");
-	 xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runbeginpre request");  	 
-	 $sub_req->({command=>['runbeginpre'],   
+            xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: nodeset did not distribute to the service node");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runbeginpre request");  	 
+            $sub_req->({command=>['runbeginpre'],   
   		      node=>\@rnodes,
   		      arg=>[$args[0]]},\&pass_along);
         }
@@ -526,8 +523,8 @@ sub process_request {
     if (!$inittime) { $inittime=0;}
     $errored=0;
     unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
-	xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue setdestiny request");
-      $sub_req->({command=>['setdestiny'],
+        xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue setdestiny request");
+        $sub_req->({command=>['setdestiny'],
   		node=>\@nodes,
   		inittime=>[$inittime],
   		arg=>\@args},\&pass_along);
@@ -633,11 +630,11 @@ sub process_request {
             }
             if ($do_dhcpsetup) {
                 if ($request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
-				xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
+                    xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}}, $callback);
                 } else {
-				xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
+                    xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}},$callback);
                 }
@@ -651,12 +648,12 @@ sub process_request {
         }
         if ($do_dhcpsetup) {
           if ($request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
-		  xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
+              xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
               $sub_req->({command=>['makedhcp'],
                node=>\@breaknetboot,
                arg=>['-l']},$callback);
           } else {
-		  xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
+              xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue makedhcp request");
               $sub_req->({command=>['makedhcp'],
                node=>\@breaknetboot},$callback);
           }
@@ -667,13 +664,13 @@ sub process_request {
     unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') 
         $errored=0;
         if ($request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
-  	  xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runendpre request");
-	  $sub_req->({command=>['runendpre'],
+            xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runendpre request");
+            $sub_req->({command=>['runendpre'],
   		      node=>\@nodes,
   		      arg=>[$args[0], '-l']},\&pass_along);
         } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
-		xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runendpre request");
-  	  $sub_req->({command=>['runendpre'],   
+            xCAT::MsgUtils->trace($verbose_on_off,"d","grub2: issue runendpre request");
+            $sub_req->({command=>['runendpre'],   
   		      node=>\@rnodes,
   		      arg=>[$args[0]]},\&pass_along);
         }
diff --git a/xCAT-server/lib/xcat/plugins/petitboot.pm b/xCAT-server/lib/xcat/plugins/petitboot.pm
index 7e8f5aaa8..6346d4e93 100644
--- a/xCAT-server/lib/xcat/plugins/petitboot.pm
+++ b/xCAT-server/lib/xcat/plugins/petitboot.pm
@@ -267,9 +267,8 @@ sub preprocess_request {
 
     #>>>>>>>used for trace log start>>>>>>
     my $verbose_on_off=0;  
-	if($VERBOSE){$verbose_on_off=1;}
-	#xCAT::MsgUtils->trace(1,"d","petitboot: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
-	#>>>>>>>used for trace log end>>>>>>>
+    if($VERBOSE){$verbose_on_off=1;}
+    #>>>>>>>used for trace log end>>>>>>>
 	
     if ($HELP) { 
 	if($usage{$command}) {
@@ -355,7 +354,6 @@ sub process_request {
   if ($::XCATSITEVALS{"httpmethod"}) { $httpmethod = $::XCATSITEVALS{"httpmethod"}; }
   if ($::XCATSITEVALS{"httpport"}) { $httpport = $::XCATSITEVALS{"httpport"}; }
 
-  #my @args;
   my @nodes;
   my @rnodes;
   if (ref($request->{node})) {
@@ -385,8 +383,7 @@ sub process_request {
   }
 
   #>>>>>>>used for trace log>>>>>>>
-  my $str_node;
-  foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+  my $str_node = join(" ",@nodes);
   xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: nodes are $str_node");
   
   # return directly if no nodes in the same network
@@ -411,8 +408,8 @@ sub process_request {
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
-      xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: nodeset did not distribute to the service node");
-	  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue runbeginpre request");
+          xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: nodeset did not distribute to the service node");
+          xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);
@@ -519,7 +516,7 @@ sub process_request {
                               arg=>['-l']},$callback);
                               #arg=>['-l','-s','option conf-file \"'.$fpath.'\";']},$callback);
               } else {
-			  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue makedhcp request");                  
+                  xCAT::MsgUtils->trace($verbose_on_off,"d","petitboot: issue makedhcp request");                  
                   $sub_req->({command=>['makedhcp'],
                               node=> [$node]}, $callback);
                               #arg=>['-s','option conf-file \"'.$fpath.'\";']},$callback);
diff --git a/xCAT-server/lib/xcat/plugins/prescripts.pm b/xCAT-server/lib/xcat/plugins/prescripts.pm
index 24c522799..6181b5acc 100644
--- a/xCAT-server/lib/xcat/plugins/prescripts.pm
+++ b/xCAT-server/lib/xcat/plugins/prescripts.pm
@@ -55,7 +55,6 @@ sub preprocess_request
     @ARGV = @args;
     GetOptions('V'  => \$opt{V});
     if($opt{V}){$verbose_on_off=1;}
-    xCAT::MsgUtils->trace(0,"d","prescripts->preprocess_request: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
     #>>>>>>>used for trace log end>>>>>>>
 	
     #if already preprocessed, go straight to request
@@ -94,9 +93,9 @@ sub preprocess_request
     
     # if no nodes left to process, we are done
     if (! @nodes) { 
-        xCAT::MsgUtils->trace($verbose_on_off,"d",        "prescripts->preprocess_request: no nodes left to process, we are done");
+        xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts->preprocess_request: no nodes left to process, we are done");
         return; 
-	}
+    }
 
     my $service = "xcat";
     @args=();
@@ -110,11 +109,9 @@ sub preprocess_request
     #print "prepscripts: preprocess_request get called, args=@args, nodes=@$nodes\n";
     
     #>>>>>>>used for trace log>>>>>>
-    my $str_node;
-	my $str_args;
-	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
-    foreach my $str_a (@args){$str_args .=  $str_a." ";}
-    xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts->preprocess_request: get called, args=$str_args, nodes=$str_node");
+    my $str_node=join(" ",@nodes);
+    my $str_args=join(" ",@args);
+    xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts->preprocess_request: get called, args='$str_args', nodes='$str_node'");
 	
     #use Getopt::Long;
     Getopt::Long::Configure("bundling");
@@ -142,7 +139,7 @@ sub preprocess_request
 	    $reqcopy->{'_xcatdest'} = $hostinfo[0];
 	    $reqcopy->{_xcatpreprocessed}->[0] = 1;
 	    push @requests, $reqcopy;
-		xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts: handle request in $hostinfo[0]");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","prescripts: handle request in $hostinfo[0]");
 	    return \@requests;
 	}
     } else { #run on mn and need to dispatch the requests to the service nodes
diff --git a/xCAT-server/lib/xcat/plugins/pxe.pm b/xCAT-server/lib/xcat/plugins/pxe.pm
index 745ef8a8c..49d2b82b2 100644
--- a/xCAT-server/lib/xcat/plugins/pxe.pm
+++ b/xCAT-server/lib/xcat/plugins/pxe.pm
@@ -314,9 +314,8 @@ sub preprocess_request {
 
     #>>>>>>>used for trace log start>>>>>>
     my $verbose_on_off=0;  
-	if($VERBOSE){$verbose_on_off=1;}
-	#xCAT::MsgUtils->trace(1,"d","pxe: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
-	#>>>>>>>used for trace log end>>>>>>>
+    if($VERBOSE){$verbose_on_off=1;}
+    #>>>>>>>used for trace log end>>>>>>>
 	
     if ($HELP) {
         if($usage{$command}) {
@@ -347,7 +346,7 @@ sub preprocess_request {
    #my $sent = $stab->getAttribs({key=>'sharedtftp'},'value');
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
-   xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: sharedtftp = $t_entry");
+   xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: sharedtftp=$t_entry");
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
       my @SN;
@@ -425,8 +424,7 @@ sub process_request {
   }
 
   #>>>>>>>used for trace log>>>>>>>
-  my $str_node;
-  foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+  my $str_node = join(" ",@nodes);
   xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: nodes are $str_node");
   
   # return directly if no nodes in the same network
@@ -445,15 +443,15 @@ sub process_request {
    unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
        $errored=0;
        if ($::PXE_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
-       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: the call is distrubuted to the service node already, so only need to handles my own children");
-       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runbeginpre request");
+           xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: the call is distrubuted to the service node already, so only need to handles my own children");
+           xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runbeginpre request");
            $sub_req->({command=>['runbeginpre'],
            node=>\@nodes,
            arg=>[$args[0], '-l']},\&pass_along);
        } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
-       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: nodeset did not distribute to the service node");
-       xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runbeginpre request");
-        $sub_req->({command=>['runbeginpre'],   
+            xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: nodeset did not distribute to the service node");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue runbeginpre request");
+            $sub_req->({command=>['runbeginpre'],   
                     node=>\@rnodes,
                     arg=>[$args[0]]},\&pass_along);
        }
@@ -489,7 +487,7 @@ sub process_request {
   if (exists($::PXE_request->{inittime})) { $inittime= $::PXE_request->{inittime}->[0];}
   if (!$inittime) { $inittime=0;}
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
-   xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue setdestiny request");
+    xCAT::MsgUtils->trace($verbose_on_off,"d","pxe: issue setdestiny request");
     $sub_req->({command=>['setdestiny'],
                node=>\@nodes,
                inittime=>[$inittime],
diff --git a/xCAT-server/lib/xcat/plugins/sles.pm b/xCAT-server/lib/xcat/plugins/sles.pm
old mode 100755
new mode 100644
index 94f28989d..0a0967ae7
--- a/xCAT-server/lib/xcat/plugins/sles.pm
+++ b/xCAT-server/lib/xcat/plugins/sles.pm
@@ -764,7 +764,6 @@ sub mkinstall
     GetOptions('V'  => \$opt{V});
     my $verbose_on_off=0;
     if($opt{V}){$verbose_on_off=1;}
-    xCAT::MsgUtils->trace(0,"d","sles->mkinstall: opt{V}=$opt{V} verbose_on_off=$verbose_on_off");
     #>>>>>>>used for trace log end>>>>>>>
 	
     my $ntents = $ostab->getNodesAttribs($request->{node}, ['os', 'arch', 'profile', 'provmethod']);
@@ -795,7 +794,7 @@ sub mkinstall
         }
     #}
 	
-    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: installroot = $installroot");
+    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: installroot=$installroot");
 	
     my %donetftp;
     require xCAT::Template; #only used here, load so memory can be COWed
@@ -847,7 +846,7 @@ sub mkinstall
 	   $tftpdir = $globaltftpdir;
         }
 		
-        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: tftpdir = $tftpdir");
+        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: tftpdir=$tftpdir");
 		
         if ($ent and $ent->{provmethod} and ($ent->{provmethod} ne 'install') and ($ent->{provmethod} ne 'netboot') and ($ent->{provmethod} ne 'statelite')) {
 	    $imagename=$ent->{provmethod};
@@ -934,11 +933,7 @@ sub mkinstall
 	    $driverupdatesrc = $ph->{driverupdatesrc};
 	    $osupdir = $ph->{'osupdir'};
 		
-	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: imagename = $imagename");
-	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkgdir = $pkgdir");
-	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkglistfile = $pkglistfile");
-	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: tmplfile = $tmplfile");
-	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: partfile = $partfile");
+	    xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: imagename=$imagename pkgdir=$pkgdir pkglistfile=$pkglistfile tmplfile=$tmplfile partfile=$partfile");
 	}
 	else {
 	    $os = $ent->{os};
@@ -965,10 +960,7 @@ sub mkinstall
         #get the partition file from the linuximage table
         my $imgname = "$os-$arch-install-$profile";
 		
-        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: imagename = $imgname");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkgdir = $pkgdir");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: pkglistfile = $pkglistfile");
-		xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: tmplfile = $tmplfile");
+        xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: imagename=$imgname pkgdir=$pkgdir pkglistfile=$pkglistfile tmplfile=$tmplfile");
 		
         if (! $linuximagetab) {
             $linuximagetab = xCAT::Table->new('linuximage');
@@ -978,7 +970,7 @@ sub mkinstall
             (my $ref1) = $linuximagetab->getAttribs({imagename => $imgname}, 'partitionfile');
             if ( $ref1 and $ref1->{'partitionfile'}){
                 $partfile = $ref1->{'partitionfile'};
-                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: partfile = $partfile");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: partfile=$partfile");
             }
         }
         else {
@@ -1313,9 +1305,7 @@ sub mkinstall
             {
                 $kernelpath = "$rtftppath/linux";
                 $initrdpath = "$rtftppath/initrd";
-                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kcmdline = $kcmdline");
-                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kernal = $kernelpath");
-                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: initrd = $initrdpath");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kcmdline=$kcmdline kernal=$kernelpath initrd=$initrdpath");
                 $bptab->setNodeAttribs(
                                         $node,
                                         {
@@ -1328,9 +1318,7 @@ sub mkinstall
             elsif ($arch =~ /ppc/)
             {
                 $kernelpath = "$rtftppath/inst64";
-                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kcmdline = $kcmdline");
-                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kernal = $kernelpath");
-                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: initrd = ");
+                xCAT::MsgUtils->trace($verbose_on_off,"d","sles->mkinstall: kcmdline=$kcmdline kernal=$kernelpath initrd=");
                 $bptab->setNodeAttribs(
                                         $node,
                                         {
diff --git a/xCAT-server/lib/xcat/plugins/xnba.pm b/xCAT-server/lib/xcat/plugins/xnba.pm
index cbc1bd8f9..0c65661f6 100644
--- a/xCAT-server/lib/xcat/plugins/xnba.pm
+++ b/xCAT-server/lib/xcat/plugins/xnba.pm
@@ -332,9 +332,8 @@ sub preprocess_request {
 
     #>>>>>>>used for trace log start>>>>>>
     my $verbose_on_off=0;  
-	if($VERBOSE){$verbose_on_off=1;}
-	#xCAT::MsgUtils->trace(1,"d","xnba: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
-	#>>>>>>>used for trace log end>>>>>>>
+    if($VERBOSE){$verbose_on_off=1;}
+    #>>>>>>>used for trace log end>>>>>>>
 	
     if ($HELP) { 
 	if($usage{$command}) {
@@ -367,7 +366,7 @@ sub preprocess_request {
    #they specify no sharedtftp in site table
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
-   xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: sharedtftp = $t_entry");
+   xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: sharedtftp=$t_entry");
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
       my @SN;
@@ -438,15 +437,14 @@ sub process_request {
         push @nodes,$_;
      } else {
         xCAT::MsgUtils->message("S", "$_: xnba netboot: stop configuration because of none sharedtftp and not on same network with its xcatmaster.");
-     }
+    } 
    }
   } else {
      @nodes = @rnodes;
   }
 
   #>>>>>>>used for trace log>>>>>>>
-  my $str_node;
-  foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
+  my $str_node = join(" ",@nodes);
   xCAT::MsgUtils->trace(0,"d","xnba: nodes are $str_node");
   
   # return directly if no nodes in the same network
@@ -465,14 +463,14 @@ sub process_request {
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
       $errored=0;
       if ($::XNBA_request->{'_disparatetftp'}->[0]) {  #the call is distrubuted to the service node already, so only need to handles my own children
-	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: the call is distrubuted to the service node already, so only need to handles my own children");
-	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runbeginpre request");
+          xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: the call is distrubuted to the service node already, so only need to handles my own children");
+          xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],
 		      node=>\@nodes,
 		      arg=>[$args[0], '-l']},\&pass_along);
       } else { #nodeset did not distribute to the service node, here we need to let runednpre to distribute the nodes to their masters
-	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: nodeset did not distribute to the service node");
-	 xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runbeginpre request");
+          xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: nodeset did not distribute to the service node");
+          xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue runbeginpre request");
 	  $sub_req->({command=>['runbeginpre'],   
 		      node=>\@rnodes,
 		      arg=>[$args[0]]},\&pass_along);
@@ -506,8 +504,8 @@ sub process_request {
   if (!$inittime) { $inittime=0;}
   $errored=0;
   unless ($args[0] eq 'stat') { # or $args[0] eq 'enact') {
-  xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue setdestiny request");
-      $sub_req->({command=>['setdestiny'],
+    xCAT::MsgUtils->trace($verbose_on_off,"d","xnba: issue setdestiny request");
+    $sub_req->({command=>['setdestiny'],
 		  node=>\@nodes,
 		  inittime=>[$inittime],
 		  arg=>\@args},\&pass_along);
diff --git a/xCAT-server/lib/xcat/plugins/yaboot.pm b/xCAT-server/lib/xcat/plugins/yaboot.pm
index 7781448b7..37b939631 100644
--- a/xCAT-server/lib/xcat/plugins/yaboot.pm
+++ b/xCAT-server/lib/xcat/plugins/yaboot.pm
@@ -375,11 +375,10 @@ sub preprocess_request {
       return;
     }
 	
-	#>>>>>>>used for trace log start>>>>>>
+    #>>>>>>>used for trace log start>>>>>>
     my $verbose_on_off=0;  
-	if($VERBOSE){$verbose_on_off=1;}
-	#xCAT::MsgUtils->trace(1,"d","yaboot: VERBOSE=$VERBOSE  verbose_on_off=$verbose_on_off ");
-	#>>>>>>>used for trace log end>>>>>>>
+    if($VERBOSE){$verbose_on_off=1;}
+    #>>>>>>>used for trace log end>>>>>>>
 	
     if ($HELP) { 
 	if($usage{$command}) {
@@ -413,7 +412,7 @@ sub preprocess_request {
    my @entries =  xCAT::TableUtils->get_site_attribute("sharedtftp");
    my $t_entry = $entries[0];
    
-   xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: sharedtftp = $t_entry");
+   xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: sharedtftp=$t_entry");
    
    if ( defined($t_entry)  and ($t_entry eq "0" or $t_entry eq "no" or $t_entry eq "NO")) {
       # check for  computenodes and servicenodes from the noderange, if so error out
@@ -496,10 +495,9 @@ sub process_request {
      @nodes = @rnodes;
   }
 
-      #>>>>>>>used for trace log>>>>>>>
-	my $str_node;
-	foreach my $str_n (@nodes){$str_node .=  $str_n." ";}
-	xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: nodes are $str_node");
+  #>>>>>>>used for trace log>>>>>>>
+  my $str_node = join(" ",@nodes);
+  xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: nodes are $str_node");
   
   # return directly if no nodes in the same network
   unless (@nodes) {
@@ -750,12 +748,12 @@ sub process_request {
                         }
                     }
                     if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
-					xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+                    xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}},
                          arg=>['-l']},$::YABOOT_callback);
                     } else {
-					xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+                    xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
                     $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}},$::YABOOT_callback);
                     }
@@ -767,24 +765,24 @@ sub process_request {
                     }
 
                     if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command, only change local settings if already farmed
-					xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
-                    $sub_req->({command=>['makedhcp'],arg=>['-l'],
+                        xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+                        $sub_req->({command=>['makedhcp'],arg=>['-l'],
                            node=>\@{$osimagenodehash{$osimage}}},$::YABOOT_callback);
                     } else {
-					 xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
-                    $sub_req->({command=>['makedhcp'],
+                        xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+                        $sub_req->({command=>['makedhcp'],
                          node=>\@{$osimagenodehash{$osimage}}},$::YABOOT_callback);
                     }
                 }
             }
         } else {
             if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command, only change local settings if already farmed
-			xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
-            $sub_req->({command=>['makedhcp'],arg=>['-l'],
+                xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+                $sub_req->({command=>['makedhcp'],arg=>['-l'],
                    node=>\@normalnodeset},$::YABOOT_callback);
             } else {
-			xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
-            $sub_req->({command=>['makedhcp'],
+                xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+                $sub_req->({command=>['makedhcp'],
                  node=>\@normalnodeset},$::YABOOT_callback);
             }
         }
@@ -794,12 +792,12 @@ sub process_request {
             }
         }
         if ($::YABOOT_request->{'_disparatetftp'}->[0]) { #reading hint from preprocess_command
-		    xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],
              node=>\@breaknetboot,
              arg=>['-l']},$::YABOOT_callback);
         } else {
-		    xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
+            xCAT::MsgUtils->trace($verbose_on_off,"d","yaboot: issue makedhcp request");
             $sub_req->({command=>['makedhcp'],
              node=>\@breaknetboot}, $::YABOOT_callback);
         }

From 4dcbe0ea48a08f74c3642189cb8e5c2a4c701f4a Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Tue, 18 Aug 2015 04:17:37 -0400
Subject: [PATCH 05/12] modify many things depending on xiao peng and victor's
 comments

---
 xCAT-server/sbin/xcatd | 470 ++++++++++++++++++++++-------------------
 1 file changed, 255 insertions(+), 215 deletions(-)
 mode change 100755 => 100644 xCAT-server/sbin/xcatd

diff --git a/xCAT-server/sbin/xcatd b/xCAT-server/sbin/xcatd
old mode 100755
new mode 100644
index f514663c5..724d1765e
--- a/xCAT-server/sbin/xcatd
+++ b/xCAT-server/sbin/xcatd
@@ -204,7 +204,7 @@ $xcatdir = (($tmp and $tmp->{value}) ? $tmp->{value} : "/etc/xcat");
 #----used for command log start-------
 my $cmdlog_logfile="/var/log/xcat/commands.log";
 my $cmdlog_port=3003;
-($tmp) = $sitetab->getAttribs({'key'=>'xcatcport'},'value');
+($tmp) = $sitetab->getAttribs({'key'=>'xcatlport'},'value');
 if ($tmp) {
 	$cmdlog_port = $tmp->{value};
 }
@@ -1148,47 +1148,51 @@ if ($startupparent) {
 $cmdlog_svrpid = fork();
 if( !defined($cmdlog_svrpid)){
     print "xCAT command log sever unable to fork";
-	xCAT::MsgUtils->message("S","xCAT command log sever unable to fork");
+    xCAT::MsgUtils->message("S","xCAT command log sever unable to fork");
 }elsif($cmdlog_svrpid ==0){
     $$progname="xcatd: Command log writer";
-	my $clientsock;
-	my @waittowritepro;
+    my $clientsock;
+    my @waittowritepro;
 	
-	xCAT::MsgUtils->trace(0,"I","xcatd: command log process start");
-	
-	unless (open (CMDLOGFILE, ">>$cmdlog_logfile")) {
-        #print "Can't open xcat command log file $cmdlog_logfile";
-	    #xCAT::MsgUtils->message("S","Can't open xcat command log file $cmdlog_logfile");
-	
-	    xCAT::MsgUtils->trace(0,"E","xcatd: Can't open xcat command log file $cmdlog_logfile");
-	    xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
-		exit(0);
+    $SIG{TERM} = $SIG{INT} = sub {
+        if ($cmdlog_svrpid) {
+            kill 2, $cmdlog_svrpid;
+        }
+        $SIG{ALRM} = sub { xexit 0; };
+        alarm(2);
+    };   
+
+    xCAT::MsgUtils->trace(0,"I","xcatd: command log process start");
+    
+    unless (open (CMDLOGFILE, ">>$cmdlog_logfile")) {
+        xCAT::MsgUtils->trace(0,"E","xcatd: Can't open xcat command log file $cmdlog_logfile");
+        xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
+        exit(0);
     }
-	select(CMDLOGFILE);
-	$|=1;
-   
-	my $cmdlogsvrlistener = IO::Socket::INET->new(LocalPort => $cmdlog_port,
-							   Type => SOCK_STREAM,
-							   Reuse => 1,
-							   Listen => 8192);
-	while (1)
-	{
-	    my $clientsock = $cmdlogsvrlistener->accept;
-	    unless ($clientsock) { next; } 
-	    my $log = "";
-	    my $bytesread;
-	    do { 
-	    $bytesread=sysread($clientsock,$log,65536,length($log)) 
-	    } while ($bytesread);
-	    close($clientsock);
-		#print "[server]<<<<<<<<<<<<<<<<<<<<<<<<<\n$log";
-		print CMDLOGFILE $log;
-	}
-	
-	close($cmdlogsvrlistener);
-	close(CMDLOGFILE);
-	
-	xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
+    select(CMDLOGFILE);
+    $|=1;
+    
+    my $cmdlogsvrlistener = IO::Socket::INET->new(LocalPort => $cmdlog_port,
+        Type => SOCK_STREAM,
+        Reuse => 1,
+        Listen => 8192);
+    while (1)
+    {
+        my $clientsock = $cmdlogsvrlistener->accept;
+        unless ($clientsock) { next; } 
+        my $log = "";
+        my $bytesread;
+        do { 
+            $bytesread=sysread($clientsock,$log,65536,length($log)) 
+        } while ($bytesread);
+        close($clientsock);
+        print CMDLOGFILE $log;
+    }
+
+    close($cmdlogsvrlistener);
+    close(CMDLOGFILE);
+
+    xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
 }
 #----used for command log end---------
 
@@ -1908,13 +1912,13 @@ sub dispatch_request {
            $str_cmd .= $n.",";
        }
        $str_cmd =~ s/(.+),$/$1 /g;
-    }
+   }
    if(exists($req->{arg})){
        foreach my $arg (@{$req->{arg}}) {
            $str_cmd .= $arg." ";
        }
-	   $str_cmd =~ s/(.+) $/$1/g;
-    }
+       $str_cmd =~ s/(.+) $/$1/g;
+   }
    xCAT::MsgUtils->trace(0,"D","xcatd: dispatch request '$str_cmd' to plugin '$modname'");
    #----used for trace end---------
    
@@ -2856,14 +2860,21 @@ sub disable_callingtrace {
   xCAT::MsgUtils->stop_logging();
 }
 
+#--------------------------------------------------------------------------------
+=head3 cmdlog_collectlog
+
+    Used by recording command output feature.
+    collecting each output for one specific command
+    The most part of this subroutine logic comes from handle_response subroutine in Client.pm
+	
+    Returns:
+        0 -> successful
+        1 -> failed
+=cut
+#--------------------------------------------------------------------------------
 sub cmdlog_collectlog(){
     my $rsponse= shift;
     my $rsp_log="";
-=pod
-    print ">>>>[$$]cmdlog_collectlog dumper all rsponse>>>>>\n";
-    print Dumper $rsponse;   
-    return 0;
-=cut    
 
     if((exists($rsponse->{serverdone})) && (! exists($rsponse->{error}) )){return 0;}
     my $rsp;
@@ -2872,193 +2883,222 @@ sub cmdlog_collectlog(){
     }else{
         $rsp = $rsponse;
     }
-	if (ref($rsp) ne 'ARRAY') {return 0;}
+    if (ref($rsp) ne 'ARRAY') {return 0;}
     if (scalar(@$rsp) == 0) {return 0;}
 	
-	foreach my $tmprsp (@{$rsp}) {
+    foreach my $tmprsp (@{$rsp}) {
         $rsp = $tmprsp;
 
-    #print ">>>>[$$]cmdlog_collectlog dumper valid rsponse>>>>>\n";
-    #print Dumper $rsponse;  
-    #return 0;
-
-    #handle response 
-    #Handle errors
-    if ($rsp->{error}) {
-        if (ref($rsp->{error}) eq 'ARRAY') {
-            foreach my $text (@{$rsp->{error}}) {
-                if ($rsp->{NoErrorPrefix}) {
-                    $rsp_log.=$text;
-                } else {
-                    $rsp_log.="Error: $text\n";
-                }
-            }
-        }
-        else {
-            if ($rsp->{NoErrorPrefix}) {
-                $rsp_log.= $rsp->{error}."\n";
-            } else {
-                $rsp_log.= "Error: ".$rsp->{error}."\n";
-            }
-        }
-    }
-    
-    if ($rsp->{warning}) {
-        if (ref($rsp->{warning}) eq 'ARRAY') {
-            foreach my $text (@{$rsp->{warning}}) {
-                if ($rsp->{NoWarnPrefix}) {
-                    $rsp_log.= "$text\n";
-                } else {
-                    $rsp_log.= "Warning: $text\n";
-                }
-            }
-        }
-        else {
-            if ($rsp->{NoWarnPrefix}) {
-                $rsp_log.= $rsp->{warning}."\n";
-            } else {
-                $rsp_log.= "Warning: ".$rsp->{warning}."\n";
-            }
-        }
-    }
-    
-    if ($rsp->{info}) {
-        if (ref($rsp->{info}) eq 'ARRAY') {
-            foreach my $text (@{$rsp->{info}}) {
-                $rsp_log.= "$text\n";
-            }
-        }
-        else {
-            $rsp_log.= $rsp->{info}."\n";
-        }
-    }
-
-    if ($rsp->{sinfo}) {
-        if (ref($rsp->{sinfo}) eq 'ARRAY') {
-            foreach my $text (@{$rsp->{sinfo}}) {
-                $rsp_log.= "$text\r";
-            }
-        }
-        else {
-            $rsp_log.= $rsp->{sinfo}."\r";
-        }
-    }
-    
-    #Handle {node} structure
-    my $errflg=0;
-    my $nodes=($rsp->{node});
-    unless (ref $nodes eq 'ARRAY') {
-        $nodes = [$nodes];
-    }
-    if (scalar @{$nodes}) {
-        my $node;
-        foreach $node (@$nodes) {
-            my $desc;
-            if (ref($node->{name}) eq 'ARRAY') {
-                $desc=$node->{name}->[0];
-            } else {
-                $desc=$node->{name};
-            }
-            if ($node->{error}) {
-                $desc.=": Error: ".$node->{error}->[0];
-                $errflg=1;
-            }
-            if ($node->{warning}) {
-                $desc.=": Warning: ".$node->{warning}->[0];
-                $errflg=1;
-            }
-            if ($node->{data}) {
-                if (ref(\($node->{data})) eq 'SCALAR') {
-                    $desc=$desc.": ".$node->{data};
-                } elsif (ref($node->{data}) eq 'HASH') {
-                    if ($node->{data}->{desc}) {
-                        if (ref($node->{data}->{desc}) eq 'ARRAY') {
-                            $desc=$desc.": ".$node->{data}->{desc}->[0];
-                        } else {
-                            $desc=$desc.": ".$node->{data}->{desc};
-                        }
-                    }
-                    if ($node->{data}->{contents}) {
-                        if (ref($node->{data}->{contents}) eq 'ARRAY') {
-                            $desc="$desc: ".$node->{data}->{contents}->[0];
-                        } else {
-                            $desc="$desc: ".$node->{data}->{contents};
-                        }
-                    }
-                } elsif (ref(\($node->{data}->[0])) eq 'SCALAR') {
-                    $desc=$desc.": ".$node->{data}->[0];
-                } else {
-                    if ($node->{data}->[0]->{desc}) {
-                        $desc=$desc.": ".$node->{data}->[0]->{desc}->[0];
-                    }
-                    if ($node->{data}->[0]->{contents}) {
-                        $desc="$desc: ".$node->{data}->[0]->{contents}->[0];
-                    }
-                }
-            }
-            if ($desc) {
-                if ($errflg == 1) {
-                    $rsp_log.= "$desc\n";
-                } else {
-                    $rsp_log.= "$desc\n";
-                }
-            }
-        }
-    }
-
-    # Handle {data} structure with no nodes
-	foreach my $mykey ( keys %{$rsp} ) 
-	{
-	if ($mykey ne "data") {next;}
-    if ($rsp->{data}) {
-        my $data=($rsp->{data});
-        my $data_entry;
-        foreach $data_entry (@$data) {
-            my $desc;
-            if (ref(\($data_entry)) eq 'SCALAR') {
-                $desc=$data_entry;
-            } else {
-                if ($data_entry->{desc}) {
-                    $desc=$data_entry->{desc}->[0];
-                }
-                if ($data_entry->{contents}) {
-                    if ($desc) {
-                        $desc="$desc: ".$data_entry->{contents}->[0];
+        #handle response 
+        #Handle errors
+        if ($rsp->{error}) {
+            if (ref($rsp->{error}) eq 'ARRAY') {
+                foreach my $text (@{$rsp->{error}}) {
+                    if ($rsp->{NoErrorPrefix}) {
+                        $rsp_log.=$text;
                     } else {
-                        $desc=$data_entry->{contents}->[0];
+                        $rsp_log.="Error: $text\n";
                     }
                 }
             }
-            if ($desc) { 
-                $rsp_log.= "$desc\n";
+            else {
+                if ($rsp->{NoErrorPrefix}) {
+                    $rsp_log.= $rsp->{error}."\n";
+                } else {
+                    $rsp_log.= "Error: ".$rsp->{error}."\n";
+                }
+            }
+        }
+    
+        if ($rsp->{warning}) {
+            if (ref($rsp->{warning}) eq 'ARRAY') {
+                foreach my $text (@{$rsp->{warning}}) {
+                    if ($rsp->{NoWarnPrefix}) {
+                        $rsp_log.= "$text\n";
+                    } else {
+                        $rsp_log.= "Warning: $text\n";
+                    }
+                }
+            }
+            else {
+                if ($rsp->{NoWarnPrefix}) {
+                    $rsp_log.= $rsp->{warning}."\n";
+                } else {
+                    $rsp_log.= "Warning: ".$rsp->{warning}."\n";
+                }
+            }
+        }
+    
+        if ($rsp->{info}) {
+            if (ref($rsp->{info}) eq 'ARRAY') {
+                foreach my $text (@{$rsp->{info}}) {
+                    $rsp_log.= "$text\n";
+                }
+            }else{
+                $rsp_log.= $rsp->{info}."\n";
+            }
+        }
+
+        if ($rsp->{sinfo}) {
+            if (ref($rsp->{sinfo}) eq 'ARRAY') {
+                foreach my $text (@{$rsp->{sinfo}}) {
+                    $rsp_log.= "$text\r";
+                }
+            }else{
+                $rsp_log.= $rsp->{sinfo}."\r";
+            } 
+        }
+    
+        #Handle {node} structure
+        my $errflg=0;
+        my $nodes=($rsp->{node});
+        unless (ref $nodes eq 'ARRAY') {
+            $nodes = [$nodes];
+        }
+        if (scalar @{$nodes}) {
+            my $node;
+            foreach $node (@$nodes) {
+                my $desc;
+                if (ref($node->{name}) eq 'ARRAY') {
+                    $desc=$node->{name}->[0];
+                } else {
+                    $desc=$node->{name};
+                }
+                if ($node->{error}) {
+                    $desc.=": Error: ".$node->{error}->[0];
+                    $errflg=1;
+                }
+                if ($node->{warning}) {
+                    $desc.=": Warning: ".$node->{warning}->[0];
+                    $errflg=1;
+                }
+                if ($node->{data}) {
+                    if (ref(\($node->{data})) eq 'SCALAR') {
+                        $desc=$desc.": ".$node->{data};
+                    } elsif (ref($node->{data}) eq 'HASH') {
+                        if ($node->{data}->{desc}) {
+                            if (ref($node->{data}->{desc}) eq 'ARRAY') {
+                                $desc=$desc.": ".$node->{data}->{desc}->[0];
+                            } else {
+                                $desc=$desc.": ".$node->{data}->{desc};
+                            }
+                        }
+                        if ($node->{data}->{contents}) {
+                            if (ref($node->{data}->{contents}) eq 'ARRAY') {
+                                $desc="$desc: ".$node->{data}->{contents}->[0];
+                            }else{
+                                $desc="$desc: ".$node->{data}->{contents};
+                            }
+                        }
+                    }elsif (ref(\($node->{data}->[0])) eq 'SCALAR') {
+                        $desc=$desc.": ".$node->{data}->[0];
+                    }else{
+                        if ($node->{data}->[0]->{desc}) {
+                            $desc=$desc.": ".$node->{data}->[0]->{desc}->[0];
+                        }
+                        if ($node->{data}->[0]->{contents}) {
+                            $desc="$desc: ".$node->{data}->[0]->{contents}->[0];
+                        }
+                    }
+                }
+                if ($desc) {
+                    if ($errflg == 1) {
+                        $rsp_log.= "$desc\n";
+                    }else{
+                        $rsp_log.= "$desc\n";
+                    }
+                }
+            }
+        }
+
+        # Handle {data} structure with no nodes
+        foreach my $mykey ( keys %{$rsp} ) {
+            if ($mykey ne "data") {next;}
+            if ($rsp->{data}) {
+                my $data=($rsp->{data});
+                my $data_entry;
+                foreach $data_entry (@$data) {
+                    my $desc;
+                    if (ref(\($data_entry)) eq 'SCALAR') {
+                        $desc=$data_entry;
+                    } else {
+                        if ($data_entry->{desc}) {
+                            $desc=$data_entry->{desc}->[0];
+                        }
+                        if ($data_entry->{contents}) {
+                            if ($desc) {
+                                $desc="$desc: ".$data_entry->{contents}->[0];
+                            } else {
+                                $desc=$data_entry->{contents}->[0];
+                            }
+                        }
+                    }
+                    if ($desc) { 
+                        $rsp_log.= "$desc\n";
+                    }
+                }
             }
         }
     }
-	}
-	}
-    #print "$rsp_log\n";
     $cmdlog_alllog .= $rsp_log; 
-   
     return 0;
 }
 
-sub cmdlog_submitlog() {
+#--------------------------------------------------------------------------------
+=head3 cmdlog_submitlog
 
-   if( $cmdlog_alllog =~ /getipmicons/) {return 1;}
-=pod   
-   print ">>>>[$$]cmdlog_submitlog >>>>>>>>>>>>>>>>>>>>>>>>>>>>>\n";
-   print $cmdlog_alllog;
-   return 0;
+    Used by recording command output feature.
+    After collecting all output for one specific command, using this subroutine to transfer output to 'Command log writer' process
+    
+    Arguments:
+        $cmdlog_alllog: this is a golbal attribute in a specific process which was forked for handle one specific command.
+            $cmdlog_alllog save the whole command output log, the format likes below:
+            ====================================================
+            [Date]       2015-7-13 23:14:45
+            [ClientType] cli 
+            [Request]    nodeset c910f02c02p30 osimage=rhels6.5-ppc64-install-compute 
+            [Response]
+            c910f02c02p30: install rhels6.5-ppc64-compute
+    Returns:
+        0 -> successful
+        1 -> failed
+	
+    Note:
+        When connect with 'Command log writer' process by tcp, cmdlog_submitlog is only try 3 times. 
+        If all 3 times are failed, cmdlog_submitlog will drop the command output log and issue a trace information to systemd to record this drop event.
 =cut
+#--------------------------------------------------------------------------------
+sub cmdlog_submitlog() {
+    my $tmpreq;
     my $mysocket;
-    while (1){
-        $mysocket = IO::Socket::INET->new(PeerAddr => "127.0.0.1",
-									   PeerPort => $cmdlog_port,
-									   Proto => "tcp");
-        if($mysocket) { last;}
+    my $trytime=3;
+    my @tmplog=split(/\n/, $cmdlog_alllog);
+    foreach my $item (@tmplog) {
+        if($item =~ /\[Request\]/){
+            $tmpreq = $item;
+        }
+    }
+    $tmpreq =~ s/\[Request\](.+)/$1/g;
+    if( $tmpreq =~ /getipmicons/) {return 1;}
+	
+    while ($trytime>0){
+        $mysocket = IO::Socket::INET->new(PeerAddr => "127.0.0.1",
+                                          PeerPort => $cmdlog_port,
+                                          Proto => "tcp");
+        if($mysocket) { 
+            last;
+        }else{
+            $trytime--;
+            sleep(0.05);
+        }
+    }
+    if($mysocket){
+        print $mysocket $cmdlog_alllog;
+        close ($mysocket);
+        return 0;
+    }else{
+        xCAT::MsgUtils->trace(0,"I","xcatd: Drop request '$tmpreq' output due to connection with 'Command log writer' process failed");
+        return 1;
     }
-    print $mysocket $cmdlog_alllog;
-	#print "[client]>>>>>>>>>>>>>>>>>>>>>>>>>>\n$cmdlog_alllog";
-    close ($mysocket);
 }
 

From f6eb1d3bb35ab4b83b664bf4d8fdfa4adeb00dc2 Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Tue, 18 Aug 2015 04:24:05 -0400
Subject: [PATCH 06/12] add description for trace subroutine and remove useless
 lines

---
 perl-xCAT/xCAT/MsgUtils.pm | 99 ++++++++++++++++++++++++++------------
 1 file changed, 67 insertions(+), 32 deletions(-)

diff --git a/perl-xCAT/xCAT/MsgUtils.pm b/perl-xCAT/xCAT/MsgUtils.pm
index cd8369625..b94002a1b 100644
--- a/perl-xCAT/xCAT/MsgUtils.pm
+++ b/perl-xCAT/xCAT/MsgUtils.pm
@@ -741,45 +741,80 @@ sub verbose_message
     }
 }
 
+#--------------------------------------------------------------------------------
+
+=head3 trace
+
+    Display different level trace message in systemd.
+    
+    Arguments:
+        $verbose: indicate whether current command is with -V option. 1 is yes and 0 is no.  
+        $level: the level of trace message, can be one of "I","W","E","D","i","w","e","d".
+            "I" or "i": means information level.
+            "W" or "w": means warning level.
+            "E" or "e": means error level.
+            "D" or "d": means debug level.
+        
+            As long as the trace subroutine is called, "information", "warning" and "error" level message will be displayed in systemd.
+            The "debug" level message is displayed in systemd noly when any one of the below two conditions is true
+            1. The current command with -V option. i.e. $verbose=1.
+            2. The xcatdebugmode, which is an attribute of site table, equals 1. 
+        
+            If $level is not any one of "I","W","E","D","i","w","e","d", the trace subroutine do nothing.
+        
+        $logcontent: the specific message wanted to be displayed in systemd
+    
+    Returns:
+        none
+		
+    Error:
+        none
+		
+    Note:
+        Label "xcat" and trace message level, such as "INFO", "ERR", "WARNING" AND "DEBUG", will be added before real trace message automatically. It's convenient to filter in systemd.
+    
+    Example:
+        xCAT::MsgUtils->trace(1,"D","this is debug trace message");
+        xCAT::MsgUtils->trace(0,"i","this is information trace message");
+        xCAT::MsgUtils->trace(0,"E","this is error trace message");
+=cut
+
+#--------------------------------------------------------------------------------
 sub trace(){
     shift;
     my $verbose = shift;
     my $level = shift;
-	my $logcontent = shift;
-
-	my $prefix = "";
-	if(($level eq "E")||($level eq "e")){$prefix="ERR";}
-	if(($level eq "W")||($level eq "w")){$prefix="WARNING";}
-	if(($level eq "I")||($level eq "i")){$prefix="INFO";}
-	if(($level eq "D")||($level eq "d")){$prefix="DEBUG";}
-	#print "prefix = $prefix\n";	
-
-	my @tmp = xCAT::TableUtils->get_site_attribute("xcatdebugmode");
-	my $xcatdebugmode=$tmp[0];
-	#print ">>>>>>>xcatdebugmode = $xcatdebugmode  >>>>>>>>>>>>\n";
-
-	if (($level eq "E") 
-	  ||($level eq "e")
-	  ||($level eq "I")
-	  ||($level eq "i") 
-	  ||($level eq "W")
-	  ||($level eq "w")){
-		my $msg = $prefix." ".$logcontent;
-		eval {
-			#print "msg = $msg\n";
-			openlog("xCAT", "nofatal,pid", "local4");
-			syslog("$prefix", $msg);
-			closelog();
-		};
-	}
-	
+    my $logcontent = shift;
+    
+    my $prefix = "";
+    if(($level eq "E")||($level eq "e")){$prefix="ERR";}
+    if(($level eq "W")||($level eq "w")){$prefix="WARNING";}
+    if(($level eq "I")||($level eq "i")){$prefix="INFO";}
+    if(($level eq "D")||($level eq "d")){$prefix="DEBUG";}
+    
+    my @tmp = xCAT::TableUtils->get_site_attribute("xcatdebugmode");
+    my $xcatdebugmode=$tmp[0];
+    
+    if (($level eq "E") 
+    ||($level eq "e")
+    ||($level eq "I")
+    ||($level eq "i") 
+    ||($level eq "W")
+    ||($level eq "w")){
+        my $msg = $prefix." ".$logcontent;
+        eval {
+            openlog("xcat", "nofatal,pid", "local4");
+            syslog("$prefix", $msg);
+            closelog();
+        };
+    }
+    
     if (($level eq "D") 
-	  ||($level eq "d")){
-          if(($verbose == 1 )||($xcatdebugmode  eq "1")){
+    ||($level eq "d")){
+        if(($verbose == 1 )||($xcatdebugmode  eq "1")){
             my $msg = $prefix." ".$logcontent;
             eval {
-                #print "msg = $msg\n";
-                openlog("xCAT", "nofatal,pid", "local4");
+                openlog("xcat", "nofatal,pid", "local4");
                 syslog("$prefix", $msg);
                 closelog();
             }

From d96d9a5590ae716468e5463582b074c95f516094 Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Tue, 18 Aug 2015 23:38:16 -0400
Subject: [PATCH 07/12] fix some indent issue

---
 xCAT-server/lib/xcat/plugins/anaconda.pm | 8 ++++----
 xCAT-server/lib/xcat/plugins/destiny.pm  | 2 +-
 2 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/xCAT-server/lib/xcat/plugins/anaconda.pm b/xCAT-server/lib/xcat/plugins/anaconda.pm
index bf7fff333..f348d0026 100644
--- a/xCAT-server/lib/xcat/plugins/anaconda.pm
+++ b/xCAT-server/lib/xcat/plugins/anaconda.pm
@@ -1172,10 +1172,10 @@ sub mkinstall
 	    }
 	    $pkglistfile=$ph->{pkglist};
 
-	    $netdrivers = $ph->{netdrivers};
-	    $driverupdatesrc = $ph->{driverupdatesrc};
-	    $osupdir = $ph->{'osupdir'};
-		
+            $netdrivers = $ph->{netdrivers};
+            $driverupdatesrc = $ph->{driverupdatesrc};
+            $osupdir = $ph->{'osupdir'};
+
             xCAT::MsgUtils->trace($verbose_on_off,"d","anaconda->mkinstall: imagename=$imagename pkgdir=$pkgdir pkglistfile=$pkglistfile tmplfile=$tmplfile partfile=$partfile");
 	}
 	else {
diff --git a/xCAT-server/lib/xcat/plugins/destiny.pm b/xCAT-server/lib/xcat/plugins/destiny.pm
index 0fd8916f5..fd0525356 100755
--- a/xCAT-server/lib/xcat/plugins/destiny.pm
+++ b/xCAT-server/lib/xcat/plugins/destiny.pm
@@ -97,7 +97,7 @@ sub setdestiny {
     my $verbose; 
     GetOptions('noupdateinitrd' => \$noupdateinitrd,
                'ignorekernelchk' => \$ignorekernelchk,
-	       'V'  => \$verbose);      #>>>>>>>used for trace log>>>>>>>
+               'V'  => \$verbose);      #>>>>>>>used for trace log>>>>>>>
    
     #>>>>>>>used for trace log start>>>>>>>
     my $verbose_on_off=0;

From 00c13144fa0066aae1f75539b4053860a1bcab93 Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Tue, 18 Aug 2015 23:40:03 -0400
Subject: [PATCH 08/12] replace systemd by syslog

---
 perl-xCAT/xCAT/MsgUtils.pm | 11 +++++------
 1 file changed, 5 insertions(+), 6 deletions(-)

diff --git a/perl-xCAT/xCAT/MsgUtils.pm b/perl-xCAT/xCAT/MsgUtils.pm
index b94002a1b..8333cd832 100644
--- a/perl-xCAT/xCAT/MsgUtils.pm
+++ b/perl-xCAT/xCAT/MsgUtils.pm
@@ -745,7 +745,7 @@ sub verbose_message
 
 =head3 trace
 
-    Display different level trace message in systemd.
+    Display different level trace message in syslog.
     
     Arguments:
         $verbose: indicate whether current command is with -V option. 1 is yes and 0 is no.  
@@ -755,15 +755,14 @@ sub verbose_message
             "E" or "e": means error level.
             "D" or "d": means debug level.
         
-            As long as the trace subroutine is called, "information", "warning" and "error" level message will be displayed in systemd.
-            The "debug" level message is displayed in systemd noly when any one of the below two conditions is true
+            As long as the trace subroutine is called, "information", "warning" and "error" level message will be displayed in syslog.
+            The "debug" level message is displayed in syslog noly when any one of the below two conditions is true
             1. The current command with -V option. i.e. $verbose=1.
             2. The xcatdebugmode, which is an attribute of site table, equals 1. 
         
             If $level is not any one of "I","W","E","D","i","w","e","d", the trace subroutine do nothing.
         
-        $logcontent: the specific message wanted to be displayed in systemd
-    
+        $logcontent: the specific message wanted to be displayed in syslog   
     Returns:
         none
 		
@@ -771,7 +770,7 @@ sub verbose_message
         none
 		
     Note:
-        Label "xcat" and trace message level, such as "INFO", "ERR", "WARNING" AND "DEBUG", will be added before real trace message automatically. It's convenient to filter in systemd.
+        Label "xcat" and trace message level, such as "INFO", "ERR", "WARNING" AND "DEBUG", will be added before real trace message automatically. It's convenient to filter in syslog.
     
     Example:
         xCAT::MsgUtils->trace(1,"D","this is debug trace message");

From efb4aff9a5d4f98d6944a4e501b70c96d91db9cf Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Tue, 18 Aug 2015 23:45:36 -0400
Subject: [PATCH 09/12] enhance command log process for handling TERM signal

---
 xCAT-server/sbin/xcatd | 27 +++++++++++++++------------
 1 file changed, 15 insertions(+), 12 deletions(-)

diff --git a/xCAT-server/sbin/xcatd b/xCAT-server/sbin/xcatd
index 724d1765e..868b2cf49 100644
--- a/xCAT-server/sbin/xcatd
+++ b/xCAT-server/sbin/xcatd
@@ -961,6 +961,7 @@ $SIG{TERM} = $SIG{INT} = sub {
    
    #----used for command log start---------
    if ($cmdlog_svrpid) {
+       xCAT::MsgUtils->trace(0,"I","xcatd: 'Command log writer' process is killed by parent process");
        kill 2, $cmdlog_svrpid;
    }
    #----used for command log end--------- 
@@ -1153,32 +1154,34 @@ if( !defined($cmdlog_svrpid)){
     $$progname="xcatd: Command log writer";
     my $clientsock;
     my @waittowritepro;
+    my $cmdlogsvrlistener;
+    my $cmdlogfile;
 	
     $SIG{TERM} = $SIG{INT} = sub {
-        if ($cmdlog_svrpid) {
-            kill 2, $cmdlog_svrpid;
-        }
-        $SIG{ALRM} = sub { xexit 0; };
-        alarm(2);
-    };   
+        xCAT::MsgUtils->trace(0,"I","xcatd: 'Command log writer' process is terminated by TERM or INT signal");
+        if($cmdlogfile){close($cmdlogfile);}
+        if($cmdlogsvrlistener){close($cmdlogsvrlistener);}
+        if($clientsock){close($clientsock);}
+        exit(0);
+    };  
 
     xCAT::MsgUtils->trace(0,"I","xcatd: command log process start");
     
-    unless (open (CMDLOGFILE, ">>$cmdlog_logfile")) {
+    unless (open ($cmdlogfile, ">>$cmdlog_logfile")) {
         xCAT::MsgUtils->trace(0,"E","xcatd: Can't open xcat command log file $cmdlog_logfile");
         xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
         exit(0);
     }
-    select(CMDLOGFILE);
+    select($cmdlogfile);
     $|=1;
     
-    my $cmdlogsvrlistener = IO::Socket::INET->new(LocalPort => $cmdlog_port,
+    $cmdlogsvrlistener = IO::Socket::INET->new(LocalPort => $cmdlog_port,
         Type => SOCK_STREAM,
         Reuse => 1,
         Listen => 8192);
     while (1)
     {
-        my $clientsock = $cmdlogsvrlistener->accept;
+        $clientsock = $cmdlogsvrlistener->accept;
         unless ($clientsock) { next; } 
         my $log = "";
         my $bytesread;
@@ -1186,11 +1189,11 @@ if( !defined($cmdlog_svrpid)){
             $bytesread=sysread($clientsock,$log,65536,length($log)) 
         } while ($bytesread);
         close($clientsock);
-        print CMDLOGFILE $log;
+        print $cmdlogfile $log;
     }
 
     close($cmdlogsvrlistener);
-    close(CMDLOGFILE);
+    close($cmdlogfile);
 
     xCAT::MsgUtils->trace(0,"I","xcatd: command log process stop");
 }

From 0a112126d46b6537d3f79ce7b53a9204d74b461f Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Wed, 19 Aug 2015 03:07:51 -0400
Subject: [PATCH 10/12] fix typo

---
 perl-xCAT/xCAT/MsgUtils.pm | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/perl-xCAT/xCAT/MsgUtils.pm b/perl-xCAT/xCAT/MsgUtils.pm
index 8333cd832..6c0dd48cc 100644
--- a/perl-xCAT/xCAT/MsgUtils.pm
+++ b/perl-xCAT/xCAT/MsgUtils.pm
@@ -756,7 +756,7 @@ sub verbose_message
             "D" or "d": means debug level.
         
             As long as the trace subroutine is called, "information", "warning" and "error" level message will be displayed in syslog.
-            The "debug" level message is displayed in syslog noly when any one of the below two conditions is true
+            The "debug" level message is displayed in syslog only when any one of the below two conditions is true
             1. The current command with -V option. i.e. $verbose=1.
             2. The xcatdebugmode, which is an attribute of site table, equals 1. 
         

From cdd1bbf73ea12c2846bc47c1dab1ad205cf9545c Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Wed, 19 Aug 2015 03:16:11 -0400
Subject: [PATCH 11/12] add explaination for xcatlport

---
 perl-xCAT/xCAT/Schema.pm | 1 +
 1 file changed, 1 insertion(+)

diff --git a/perl-xCAT/xCAT/Schema.pm b/perl-xCAT/xCAT/Schema.pm
index a79a792fc..7fb5347e6 100755
--- a/perl-xCAT/xCAT/Schema.pm
+++ b/perl-xCAT/xCAT/Schema.pm
@@ -1207,6 +1207,7 @@ site => {
    "                      Value must be less than xcatmaxconnections. Default is 50.\n\n".
    " xcatdport:  The port used by the xcatd daemon for client/server communication.\n\n".
    " xcatiport:  The port used by xcatd to receive install status updates from nodes.\n\n".
+   " xcatlport:  The port used by xcatd command log writer process to collect command output.\n\n".
    " xcatsslversion:  The ssl version by xcatd. Default is SSLv3.\n\n".
    " xcatsslciphers:  The ssl cipher by xcatd. Default is 3DES.\n\n",
   value => 'The value of the attribute specified in the "key" column.',

From 69ebde1728a5b81b3e1abaee5204f725f4f931fd Mon Sep 17 00:00:00 2001
From: huweihua <huweihua@cn.ibm.com>
Date: Thu, 20 Aug 2015 20:53:57 -0400
Subject: [PATCH 12/12] fix some quit problem of command log writer process

---
 xCAT-server/sbin/xcatd | 9 ++++-----
 1 file changed, 4 insertions(+), 5 deletions(-)

diff --git a/xCAT-server/sbin/xcatd b/xCAT-server/sbin/xcatd
index 868b2cf49..16bb3046a 100644
--- a/xCAT-server/sbin/xcatd
+++ b/xCAT-server/sbin/xcatd
@@ -960,9 +960,8 @@ $SIG{TERM} = $SIG{INT} = sub {
    }
    
    #----used for command log start---------
-   if ($cmdlog_svrpid) {
-       xCAT::MsgUtils->trace(0,"I","xcatd: 'Command log writer' process is killed by parent process");
-       kill 2, $cmdlog_svrpid;
+   if ($cmdlog_svrpid) 
+      kill 2, $cmdlog_svrpid;
    }
    #----used for command log end--------- 
    
@@ -1158,7 +1157,7 @@ if( !defined($cmdlog_svrpid)){
     my $cmdlogfile;
 	
     $SIG{TERM} = $SIG{INT} = sub {
-        xCAT::MsgUtils->trace(0,"I","xcatd: 'Command log writer' process is terminated by TERM or INT signal");
+        xCAT::MsgUtils->message("S","INFO xcatd: 'Command log writer' process is terminated by TERM or INT signal");
         if($cmdlogfile){close($cmdlogfile);}
         if($cmdlogsvrlistener){close($cmdlogsvrlistener);}
         if($clientsock){close($clientsock);}
@@ -3081,7 +3080,7 @@ sub cmdlog_submitlog() {
             $tmpreq = $item;
         }
     }
-    $tmpreq =~ s/\[Request\](.+)/$1/g;
+    $tmpreq =~ s/\[Request\]\s+(.+)/$1/g;
     if( $tmpreq =~ /getipmicons/) {return 1;}
 	
     while ($trytime>0){