[interchange-cvs] [SCM] Interchange branch, master, updated. REL_5_7_3-11-gaa66f45

Jon Jensen interchange-cvs at icdevgroup.org
Fri Nov 13 01:05:42 UTC 2009


This is an automated email from the git hooks/post-receive script. It was
generated because a ref change was pushed to the repository containing
the project "Interchange".

The branch, master has been updated
       via  aa66f45a8ea472baaf77350cf3001753d4fab65b (commit)
      from  19a761fe3bb5bc4ebe483ed1d79af19b18d310da (commit)

Those revisions listed above that are new to this repository have
not appeared on any other notification email; so we list those
revisions in full, below.

- Log -----------------------------------------------------------------
commit aa66f45a8ea472baaf77350cf3001753d4fab65b
Author: Jon Jensen <jon at endpoint.com>
Date:   Tue Nov 10 21:59:22 2009 -0700

    Overhaul syslog support and offer much faster Sys::Syslog mechanism
    
    Using the logger subprocess was resulting in overhead often many times
    the normal CPU load just for the clone and wait4 syscalls, as measured by
    strace on Interchange PreFork child processes.
    
    By switching to the Sys::Syslog mechanism, there is now little overhead
    to using syslog. This is done in interchange.cfg with:
    
    SysLog  internal  1
    
    along with any other SysLog directives for setting the facility and level.
    If you want to use the original behavior or specify a different argument-
    compatible version of logger, you can still do:
    
    SysLog  command   /usr/bin/logger
    
    Additionally, logDebug and logError now send their output to syslog too.
    
    Debug logging is still enabled by setting DebugFile, even though most of
    it will be routed to syslog. An exception is DBI trace logging, which
    still goes to the DebugFile and not to syslog. Anything that writes
    directly to STDOUT or STDERR will also still go to the DebugLog file.
    
    There is also a new option to specify an alternate socket to send syslog
    data to. This was available before on a per-call basis to &logError but it
    can now be specified in interchange.cfg:
    
    SysLog  socket    /dev/log
    
    You may optionally suffix the socket type (see documentation for Sys::Syslog
    for details):
    
    SysLog  socket    /dev/log unix
    
    Other optional SysLog settings are unchanged, for example:
    
    SysLog  tag       interchange
    SysLog  alert     local5.err
    SysLog  err       local5.err
    SysLog  crit      local5.err
    SysLog  warn      local5.info
    SysLog  notice    local5.info
    SysLog  info      local5.info
    SysLog  debug     local5.info
    
    Behavior is now different in a few minor areas:
    
    1. We no longer call format_log_msg before adding error text to $Vend::Errors,
    since that changes the display of $Vend::Errors text depending on the log
    target type (file vs. pipe vs. internal syslog), for no good reason.
    
    2. Previously, logGlobal didn't use SysLog unless it was called with a hashref
    of leading options, just as a byproduct of the implementation. This is no
    longer the case, so when SysLog is enabled, all global logging goes there.
    
    Thanks to Jim Cody and Spencer Christensen at Backcountry.com for discovering
    the huge overhead of calling logger subprocesses!
    
    Some sample data showing the difference with `strace -p $pid -c` between
    SysLog using logger and the new internal option, each with a fresh Interchange
    daemon with 1 PreFork child process, serving the same page 3 times, with 18
    syslog events per request:
    
    logger:
    % time     seconds  usecs/call     calls    errors syscall
    ------ ----------- ----------- --------- --------- ----------------
     96.17    0.720516       13343        54           clone
      3.60    0.026971         499        54           wait4
      0.12    0.000888           7       119           write
      0.06    0.000451           0      4207       589 stat
      0.02    0.000123           0       502           poll
      0.00    0.000035           0       404           sendto
      0.00    0.000033           0       502           close
      0.00    0.000030           0       432           rt_sigaction
      0.00    0.000029           0       238         8 open
      0.00    0.000023           0        51        13 connect
      0.00    0.000019           0       646           read
      0.00    0.000017           0       448           recvfrom
      0.00    0.000016           1        15           utimes
      0.00    0.000015           0       108           pipe
      0.00    0.000015           0        65           socket
      0.00    0.000012           0       940           rt_sigprocmask
      0.00    0.000000           0       318           fstat
      0.00    0.000000           0       289        84 lseek
      0.00    0.000000           0        56           mmap
      0.00    0.000000           0         1           mprotect
      0.00    0.000000           0        54           munmap
      0.00    0.000000           0        25           brk
      0.00    0.000000           0       296       268 ioctl
      0.00    0.000000           0        34           select
      0.00    0.000000           0        54           dup2
      0.00    0.000000           0         5           accept
      0.00    0.000000           0        13           getsockname
      0.00    0.000000           0        27           setsockopt
      0.00    0.000000           0        13           getsockopt
      0.00    0.000000           0       367           fcntl
      0.00    0.000000           0        19           flock
      0.00    0.000000           0         5           chdir
      0.00    0.000000           0         8           mkdir
      0.00    0.000000           0         9         6 unlink
      0.00    0.000000           0         5           umask
      0.00    0.000000           0        16           getgroups
    ------ ----------- ----------- --------- --------- ----------------
    100.00    0.749193                 10399       968 total
    
    internal syslog:
    % time     seconds  usecs/call     calls    errors syscall
    ------ ----------- ----------- --------- --------- ----------------
     30.28    0.000473           1       496           poll
     28.68    0.000448           1       457           sendto
     27.66    0.000432           0      4349       580 stat
      2.43    0.000038           4         9         6 unlink
      1.86    0.000029           0       586           read
      1.60    0.000025           2        15           utimes
      1.47    0.000023           0       233         8 open
      1.28    0.000020           0        53        13 connect
      1.15    0.000018           0       310           fcntl
      0.83    0.000013           0       224        24 lseek
      0.58    0.000009           0       313           fstat
      0.51    0.000008           0        56           mmap
      0.45    0.000007           0        54           munmap
      0.45    0.000007           0       442           recvfrom
      0.38    0.000006           0       282           close
      0.38    0.000006           0       724           rt_sigprocmask
      0.00    0.000000           0        61           write
      0.00    0.000000           0         1           mprotect
      0.00    0.000000           0        25           brk
      0.00    0.000000           0       232       204 ioctl
      0.00    0.000000           0        28           select
      0.00    0.000000           0        67           socket
      0.00    0.000000           0         4           accept
      0.00    0.000000           0        13           getsockname
      0.00    0.000000           0        27           setsockopt
      0.00    0.000000           0        13           getsockopt
      0.00    0.000000           0        17           flock
      0.00    0.000000           0         4           chdir
      0.00    0.000000           0         2           mkdir
      0.00    0.000000           0         4           umask
      0.00    0.000000           0        16           getgroups
    ------ ----------- ----------- --------- --------- ----------------
    100.00    0.001562                  9117       835 total

-----------------------------------------------------------------------

Summary of changes and diff:
 lib/Vend/Dispatch.pm |    2 +
 lib/Vend/Server.pm   |    2 +-
 lib/Vend/Util.pm     |  222 +++++++++++++++++++++++++++++++-------------------
 3 files changed, 140 insertions(+), 86 deletions(-)

diff --git a/lib/Vend/Dispatch.pm b/lib/Vend/Dispatch.pm
index 5cd8375..577e9f7 100644
--- a/lib/Vend/Dispatch.pm
+++ b/lib/Vend/Dispatch.pm
@@ -1179,6 +1179,8 @@ sub close_cat {
 	put_session() if $Vend::HaveSession;
 	close_session() if $Vend::SessionOpen;
 	close_database();
+	Sys::Syslog::closelog(), undef $Vend::SysLogReady
+		if $Vend::SysLogReady;
 }
 
 sub run_macro {
diff --git a/lib/Vend/Server.pm b/lib/Vend/Server.pm
index 12d102b..240a683 100644
--- a/lib/Vend/Server.pm
+++ b/lib/Vend/Server.pm
@@ -2351,7 +2351,7 @@ sub setup_debug_log {
 		open(Vend::DEBUG, ">>$Global::DebugFile");
 		select Vend::DEBUG;
 		$| = 1;
-		print "Start DEBUG at " . localtime() . "\n";
+		print "Start DEBUG at " . localtime() . "\n" unless $Global::SysLog;
 	}
 	elsif (!$Global::DEBUG) {
 		# May as well turn warnings off, not going anywhere
diff --git a/lib/Vend/Util.pm b/lib/Vend/Util.pm
index 671ab6d..ae64fdd 100644
--- a/lib/Vend/Util.pm
+++ b/lib/Vend/Util.pm
@@ -217,7 +217,7 @@ sub format_log_msg {
     push @params, ($CGI::remote_host || $CGI::remote_addr || '-');
 	push @params, ($Vend::SessionName || '-');
 	push @params, ($CGI::user || '-');
-	push @params, logtime();
+	push @params, logtime() unless $Global::SysLog;
 
 	# Catalog name
 	my $string = ! defined $Vend::Cfg ? '-' : ($Vend::Cat || '-');
@@ -1636,7 +1636,8 @@ sub find_special_page {
 # Log the error MSG to the error file.
 
 sub logDebug {
-    return unless $Global::DebugFile;
+	return unless $Global::DebugFile;
+
 	if(my $re = $Vend::Cfg->{DebugHost}) {
 		return unless
 			 Net::IP::Match::Regexp::match_ip($CGI::remote_addr, $re);
@@ -1646,10 +1647,12 @@ sub logDebug {
 		return unless $sub->();
 	}
 
-    if(my $tpl = $Global::DebugTemplate) {
-        my %debug; 
+	my $msg;
+
+	if (my $tpl = $Global::DebugTemplate) {
+		my %debug;
 		$tpl = POSIX::strftime($tpl, localtime());
-		$tpl =~ s/\s*$/\n/;
+		$tpl =~ s/\s*$//;
 		$debug{page} = $Global::Variable->{MV_PAGE};
 		$debug{tag} = $Vend::CurrentTag;
 		$debug{host} = $CGI::host || $CGI::remote_addr;
@@ -1663,12 +1666,20 @@ sub logDebug {
         }
 		$debug{message} = errmsg(@_);
 
-        print Vend::Interpolate::tag_attr_list($tpl, \%debug, 1);
-    }
-    else {
-        print caller() . ":debug: ", errmsg(@_), "\n";
-    }
-    return;
+		$msg = Vend::Interpolate::tag_attr_list($tpl, \%debug, 1);
+	}
+	else {
+		$msg = caller() . ":debug: " . errmsg(@_);
+	}
+
+	if ($Global::SysLog) {
+		logGlobal({ level => 'debug' }, $msg);
+	}
+	else {
+		print $msg, "\n";
+	}
+
+	return;
 }
 
 sub errmsg {
@@ -1705,118 +1716,157 @@ sub show_times {
 
 sub logGlobal {
 	return 1 if $Vend::ExternalProgram;
-    my($msg) = shift;
+
 	my $opt;
-	if(ref $msg) {
+	my $msg = shift;
+	if (ref $msg) {
 		$opt = $msg;
 		$msg = shift;
 	}
-	if(@_) {
-		$msg = errmsg($msg, @_);
+	else {
+		$opt = {};
 	}
-	my $nolock;
 
-	my $fn = $Global::ErrorFile;
-	my $flags;
-	if($opt and $Global::SysLog) {
-		$fn = "|" . ($Global::SysLog->{command} || 'logger');
+	$msg = errmsg($msg, @_) if @_;
 
-		my $prioritized;
-		my $tagged;
-		my $facility = 'local3';
-		if($opt->{level} and defined $Global::SysLog->{$opt->{level}}) {
-			my $stuff =  $Global::SysLog->{$opt->{level}};
-			if($stuff =~ /\./) {
-				$facility = $stuff;
-			}
-			else {
-				$facility .= ".$stuff";
-			}
-			$prioritized = 1;
+	$Vend::Errors .= $msg if $Global::DisplayErrors;
+
+	my $nl = $opt->{strip} ? '' : "\n";
+	print "$msg$nl"
+		if $Global::Foreground
+			and ! $Vend::Log_suppress
+			and ! $Vend::Quiet
+			and ! $Global::SysLog;
+
+	my ($fn, $facility, $level);
+	if ($Global::SysLog) {
+		my $level_opt = $opt->{level};
+		my $level_mapped;
+		if (
+			$level_opt
+			and $level_mapped = $Global::SysLog->{$level_opt}
+			and $level_mapped =~ /(.+)\.(.+)/
+		) {
+			($facility, $level) = ($1, $2);
 		}
+		$facility ||= 'local3';
+		$level    ||= 'info';
 
 		my $tag = $Global::SysLog->{tag} || 'interchange';
 
-		$facility .= ".info" unless $prioritized;
-
-		$fn .= " -p $facility";
-		$fn .= " -t $tag" unless "\L$tag" eq 'none';
-
-		if($opt->{socket}) {
-			$fn .= " -u $opt->{socket}";
+		my $socket = $opt->{socket} || $Global::SysLog->{socket};
+
+		if ($Global::SysLog->{internal}) {
+			unless ($Vend::SysLogReady) {
+				eval {
+					use Sys::Syslog ();
+					if ($socket) {
+						my ($socket_path, $types) = ($socket =~ /^(\S+)(?:\s+(.*))?/);
+						$types ||= 'native,tcp,udp,unix,pipe,stream,console';
+						my $type_array = [ grep /\S/, split /[,\s]+/, $types ];
+						Sys::Syslog::setlogsock($type_array, $socket_path) or die "Error calling setlogsock\n";
+					}
+					Sys::Syslog::openlog $tag, 'ndelay,pid', $facility;
+				};
+				if ($@) {
+					print "\nError opening syslog: $@\n";
+					print "to report this error:\n", $msg;
+					exit 1;
+				}
+				$Vend::SysLogReady = 1;
+			}
+		}
+		else {
+			$fn = '|' . ($Global::SysLog->{command} || 'logger');
+			$fn .= " -p $facility.$level";
+			$fn .= " -t $tag" unless lc($tag) eq 'none';
+			$fn .= " -u $socket" if $socket;
 		}
 	}
+	else {
+		$fn = $Global::ErrorFile;
+	}
 
-	my $nl = ($opt and $opt->{strip}) ? '' : "\n";
-
-	print "$msg$nl" if $Global::Foreground and ! $Vend::Log_suppress && ! $Vend::Quiet;
-
-	$fn =~ s/^([^|>])/>>$1/
-		or $nolock = 1;
-
-    $msg = format_log_msg($msg) if ! $nolock;
+	if ($fn) {
+		my $lock;
+		if ($fn =~ s/^([^|>])/>>$1/) {
+			$lock = 1;
+			$msg = format_log_msg($msg);
+		}
 
-	$Vend::Errors .= $msg if $Global::DisplayErrors;
+		eval {
+			# We have checked for beginning > or | previously
+			open(MVERROR, $fn) or die "open\n";
+			if ($lock) {
+				lockfile(\*MVERROR, 1, 1) or die "lock\n";
+				seek(MVERROR, 0, 2) or die "seek\n";
+			}
+			print(MVERROR $msg, "\n") or die "write to\n";
+			if ($lock) {
+				unlockfile(\*MVERROR) or die "unlock\n";
+			}
+			close(MVERROR) or die "close\n";
+		};
+	}
+	elsif ($Vend::SysLogReady) {
+		eval {
+			Sys::Syslog::syslog "$level|$facility", $msg;
+		};
+	}
 
-    eval {
-		# We have checked for beginning > or | previously
-		open(MVERROR, $fn) or die "open\n";
-		if(! $nolock) {
-			lockfile(\*MVERROR, 1, 1) or die "lock\n";
-			seek(MVERROR, 0, 2) or die "seek\n";
-		}
-		print(MVERROR $msg, "\n") or die "write to\n";
-		if(! $nolock) {
-			unlockfile(\*MVERROR) or die "unlock\n";
-		}
-		close(MVERROR) or die "close\n";
-    };
-    if ($@) {
+	if ($@) {
 		chomp $@;
 		print "\nCould not $@ error file '";
 		print $Global::ErrorFile, "':\n$!\n";
-		print "to report this error:\n", $msg;
+		print "to report this error:\n", $msg, "\n";
 		exit 1;
-    }
-}
-
+	}
 
-# Log the error MSG to the error file.
+	return 1;
+}
 
 sub logError {
-    my $msg = shift;
 	return unless $Vend::Cfg;
 
+	my $msg = shift;
 	my $opt;
-	if(ref $_[0]) {
-		$opt = shift(@_);
+	if (ref $_[0]) {
+		$opt = shift;
 	}
 	else {
 		$opt = {};
 	}
 
-    if(! $opt->{file}) {
-        my $tag = $opt->{tag} || $msg;
-        if(my $dest = $Vend::Cfg->{ErrorDestination}{$tag}) {
-            $opt->{file} = $dest;
-        }
-    }
-
-	$opt->{file} ||= $Vend::Cfg->{ErrorFile};
-
-	if(@_) {
-		$msg = errmsg($msg, @_);
+	unless ($Global::SysLog) {
+		if (! $opt->{file}) {
+			my $tag = $opt->{tag} || $msg;
+			if (my $dest = $Vend::Cfg->{ErrorDestination}{$tag}) {
+				$opt->{file} = $dest;
+			}
+		}
+		$opt->{file} ||= $Vend::Cfg->{ErrorFile};
 	}
 
-	print "$msg\n" if $Global::Foreground and ! $Vend::Log_suppress && ! $Vend::Quiet;
+	$msg = errmsg($msg, @_) if @_;
+
+	print "$msg\n"
+		if $Global::Foreground
+			and ! $Vend::Log_suppress
+			and ! $Vend::Quiet
+			and ! $Global::SysLog;
 
 	$Vend::Session->{last_error} = $msg;
 
-    $msg = format_log_msg($msg) unless $msg =~ s/^\\//;
+	$msg = format_log_msg($msg) unless $msg =~ s/^\\//;
 
 	$Vend::Errors .= $msg
 		if $Vend::Cfg->{DisplayErrors} || $Global::DisplayErrors;
 
+	if ($Global::SysLog) {
+		logGlobal({ level => 'err' }, $msg);
+		return;
+	}
+
     my $reason;
     if (! allowed_file($opt->{file}, 1)) {
         $@ = 'access';
@@ -1824,7 +1874,7 @@ sub logError {
     }
     else {
         eval {
-            open(MVERROR, ">> $opt->{file}")
+            open(MVERROR, '>>', $opt->{file})
                                         or die "open\n";
             lockfile(\*MVERROR, 1, 1)   or die "lock\n";
             seek(MVERROR, 0, 2)         or die "seek\n";
@@ -1842,7 +1892,9 @@ sub logError {
 					$reason || $!,
 					$msg,
 				);
-    }
+		}
+
+	return;
 }
 
 # Front-end to log routines that ignores repeated identical


hooks/post-receive
-- 
Interchange



More information about the interchange-cvs mailing list