[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