From 320356d66c6b264d090726b0d73ddf543a4d8006 Mon Sep 17 00:00:00 2001 From: Sitaram Chamarty Date: Wed, 21 Mar 2012 16:23:50 +0530 Subject: [PATCH] cleaned up logging quite a bit; details: - a remote "id" (usually the IP) is generated and logged on the first log message in a "transaction" - speaking of which, a new "transaction ID" is logged that stays the same for each input command/invocation, tying together all the spawned commands - so now time stamps can be generated each time they are needed, rather than re-use the one at the beginning - log messages have a keyword at the start now remote, (create), check1 -- from gitolite-shell update, check2 -- from update post-up -- from post-update command -- from gitolite die, system -- from anywhere --- src/Gitolite/Common.pm | 30 ++++++++++++++++++++---------- src/Gitolite/Hooks/PostUpdate.pm | 2 +- src/Gitolite/Hooks/Update.pm | 6 ++++-- src/Gitolite/Rc.pm | 9 ++++++--- src/gitolite | 4 +++- src/gitolite-shell | 26 ++++++++++++++++++-------- t/0-me-first.t | 2 +- 7 files changed, 53 insertions(+), 26 deletions(-) diff --git a/src/Gitolite/Common.pm b/src/Gitolite/Common.pm index 6dbc6e3..0dc503f 100644 --- a/src/Gitolite/Common.pm +++ b/src/Gitolite/Common.pm @@ -10,7 +10,7 @@ package Gitolite::Common; say2 _die _system slurp tsh_lines trace cleanup_conf_line tsh_try usage tsh_run - gen_ts_lfn + gen_lfn gl_log ); #>>> @@ -72,7 +72,7 @@ sub _warn { } sub _die { - gl_log( "_die:", @_ ); + gl_log( 'die', @_ ); if ( $ENV{D} and $ENV{D} >= 3 ) { confess "FATAL: " . join( ",", @_ ) . "\n" if defined( $ENV{D} ); } elsif ( defined( $ENV{D} ) ) { @@ -112,7 +112,7 @@ sub _system { # run system(), catch errors. Be verbose only if $ENV{D} exists. If not, # exit with if it applies, else just "exit 1". trace( 2, @_ ); - gl_log( "_system:", @_ ); + gl_log( 'system', @_ ); if ( system(@_) != 0 ) { trace( 1, "system() failed", @_, "-> $?" ); if ( $? == -1 ) { @@ -205,9 +205,8 @@ sub cleanup_conf_line { } } -# generate a timestamp. If a template is passed generate a log file name -# based on it also -sub gen_ts_lfn { +# generate a timestamp +sub gen_ts { my ( $s, $min, $h, $d, $m, $y ) = (localtime)[ 0 .. 5 ]; $y += 1900; $m++; # usual adjustments for ( $s, $min, $h, $d, $m ) { @@ -215,7 +214,16 @@ sub gen_ts_lfn { } my $ts = "$y-$m-$d.$h:$min:$s"; - return $ts unless @_; + return $ts; +} + +# generate a log file name +sub gen_lfn { + my ( $s, $min, $h, $d, $m, $y ) = (localtime)[ 0 .. 5 ]; + $y += 1900; $m++; # usual adjustments + for ( $s, $min, $h, $d, $m ) { + $_ = "0$_" if $_ < 10; + } my ($template) = shift; # substitute template parameters and set the logfile name @@ -223,7 +231,7 @@ sub gen_ts_lfn { $template =~ s/%m/$m/g; $template =~ s/%d/$d/g; - return ( $ts, $template ); + return $template; } sub gl_log { @@ -231,13 +239,15 @@ sub gl_log { # called even before they are set, we have no choice but to dump to STDERR # (and probably call "logger"). my $msg = join( "\t", @_ ); + $msg =~ s/[\n\r]+/<>/g; - my $ts = $ENV{GL_TS} || gen_ts_lfn(); + my $ts = gen_ts(); + my $tid = $ENV{GL_TID} ||= $$; my $fh; logger_plus_stderr( "$ts no GL_LOGFILE env var", "$ts $msg" ) if not $ENV{GL_LOGFILE}; open my $lfh, ">>", $ENV{GL_LOGFILE} or logger_plus_stderr( "open log failed: $!", $msg ); - print $lfh "$ts\t$msg\n"; + print $lfh "$ts\t$tid\t$msg\n"; close $lfh; } diff --git a/src/Gitolite/Hooks/PostUpdate.pm b/src/Gitolite/Hooks/PostUpdate.pm index d60c3fa..d9fa47a 100644 --- a/src/Gitolite/Hooks/PostUpdate.pm +++ b/src/Gitolite/Hooks/PostUpdate.pm @@ -20,7 +20,7 @@ use warnings; sub post_update { trace( 2, @ARGV ); - gl_log( 'post-update', @ARGV ); + gl_log( 'post-up', @ARGV ); # this is the *real* post_update hook for gitolite tsh_try("git ls-tree --name-only master"); diff --git a/src/Gitolite/Hooks/Update.pm b/src/Gitolite/Hooks/Update.pm index dae4412..53be05a 100644 --- a/src/Gitolite/Hooks/Update.pm +++ b/src/Gitolite/Hooks/Update.pm @@ -28,20 +28,21 @@ sub update { my $ret = access( $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref ); trace( 1, "access($ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref)", "-> $ret" ); - gl_log( 'update:check', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref, '->', $ret ); trigger( 'ACCESS_CHECK', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref, $ret ); _die $ret if $ret =~ /DENIED/; check_vrefs( $ref, $oldsha, $newsha, $oldtree, $newtree, $aa ); - gl_log( 'update:OK', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, @ARGV ); + gl_log( 'check2', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, @ARGV, '->', $ret ); exit 0; } sub check_vrefs { my ( $ref, $oldsha, $newsha, $oldtree, $newtree, $aa ) = @_; my $name_seen = 0; + my $n_vrefs = 0; for my $vref ( vrefs( $ENV{GL_REPO}, $ENV{GL_USER} ) ) { + $n_vrefs++; if ( $vref =~ m(^VREF/NAME/) ) { # this one is special; we process it right here, and only once next if $name_seen++; @@ -64,6 +65,7 @@ sub check_vrefs { : "$vref: helper program exit status $?"; } } + return $n_vrefs; } sub check_vref { diff --git a/src/Gitolite/Rc.pm b/src/Gitolite/Rc.pm index 7b83e9b..ad2de11 100644 --- a/src/Gitolite/Rc.pm +++ b/src/Gitolite/Rc.pm @@ -72,9 +72,12 @@ do $ENV{G3T_RC} if exists $ENV{G3T_RC} and -r $ENV{G3T_RC}; $ENV{PATH} = "$ENV{GL_BINDIR}:$ENV{PATH}"; { - my ( $ts, $lfn ) = gen_ts_lfn( $rc{LOG_TEMPLATE} ); - $rc{GL_LOGFILE} = $ENV{GL_LOGFILE} = $lfn; - $rc{GL_TS} = $ENV{GL_TS} = $ts; + $rc{GL_TID} = $ENV{GL_TID} ||= $$; + # TID: loosely, transaction ID. The first PID at the entry point passes + # it down to all its children so you can track each access, across all the + # various commands it spawns and actions it generates. + + $rc{GL_LOGFILE} = $ENV{GL_LOGFILE} ||= gen_lfn( $rc{LOG_TEMPLATE} ); } # these two are meant to help externally written commands (see diff --git a/src/gitolite b/src/gitolite index 7217bb9..341657f 100755 --- a/src/gitolite +++ b/src/gitolite @@ -46,7 +46,7 @@ use warnings; # ---------------------------------------------------------------------- my ( $command, @args ) = @ARGV; -gl_log( 'gitolite', @ARGV ) if -d $rc{GL_ADMIN_BASE}; +gl_log( 'command', @ARGV ) if -d $rc{GL_ADMIN_BASE}; args(); # the first two commands need options via @ARGV, as they have their own @@ -91,6 +91,8 @@ if ( $command eq 'setup' ) { _die "unknown gitolite sub-command"; } +gl_log( '==end==' ) if $$ == $ENV{GL_TID}; + sub args { usage() if not $command or $command eq '-h'; } diff --git a/src/gitolite-shell b/src/gitolite-shell index 584c5f4..870dc74 100755 --- a/src/gitolite-shell +++ b/src/gitolite-shell @@ -15,17 +15,20 @@ use strict; use warnings; # the main() sub expects ssh-ish things; set them up... +my $id = ''; if ( exists $ENV{G3T_USER} ) { - in_local(); # file:// masquerading as ssh:// for easy testing + $id = in_local(); # file:// masquerading as ssh:// for easy testing } elsif ( exists $ENV{SSH_CONNECTION} ) { - in_ssh(); + $id = in_ssh(); } elsif ( exists $ENV{REQUEST_URI} ) { - in_http(); + $id = in_http(); } else { _die "who the *heck* are you?"; } -main(); +main($id); + +gl_log( '==end==' ) if $$ == $ENV{GL_TID}; exit 0; @@ -38,6 +41,7 @@ sub in_local { print STDERR "TRACE: gsh(", join( ")(", @ARGV ), ")\n"; print STDERR "TRACE: gsh(SOC=$ENV{SSH_ORIGINAL_COMMAND})\n"; } + return 'local'; } sub in_http { @@ -49,6 +53,10 @@ sub in_ssh { my $soc = $ENV{SSH_ORIGINAL_COMMAND}; $soc =~ s/[\n\r]+/<>/g; _die "I don't like newlines in the command: $soc\n" if $ENV{SSH_ORIGINAL_COMMAND} ne $soc; + + my $ip; + ($ip = $ENV{SSH_CONNECTION} || '(no-IP)') =~ s/ .*//; + return $ip; } # ---------------------------------------------------------------------- @@ -56,7 +64,9 @@ sub in_ssh { # call this once you are sure arg-1 is the username and SSH_ORIGINAL_COMMAND # has been setup (even if it's not actually coming via ssh). sub main { - gl_log( 'gitolite-shell', @ARGV, $ENV{SSH_ORIGINAL_COMMAND} ); + my $id = shift; + + gl_log( 'remote', $id, @ARGV, $ENV{SSH_ORIGINAL_COMMAND} ); umask $rc{UMASK}; # set up the user @@ -73,7 +83,7 @@ sub main { require Gitolite::Conf::Store; Gitolite::Conf::Store->import; new_wild_repo( $repo, $user ); - gl_log( 'gitolite-shell:new_wild_repo', $repo, $user ); + gl_log( 'create', $repo, $user ); } # a ref of 'any' signifies that this is a pre-git check, where we don't @@ -82,9 +92,9 @@ sub main { # more information. my $ret = access( $repo, $user, $aa, 'any' ); trace( 1, "access($repo, $user, $aa, 'any')", "-> $ret" ); - gl_log( 'gitolite-shell:check', $repo, $user, $aa, 'any', '->', $ret ); + gl_log( 'check1', $repo, $user, $aa, 'any', '->', $ret ); trigger( 'ACCESS_CHECK', $repo, $user, $aa, 'any', $ret ); - _die $ret if $ret =~ /DENIED/; + _die $ret . "\n(or you mis-spelled the reponame)" if $ret =~ /DENIED/; check_repo_write_enabled($repo) if $aa eq 'W'; trigger( 'PRE_GIT', $repo, $user, $aa, 'any', $verb ); diff --git a/t/0-me-first.t b/t/0-me-first.t index cc732e3..0661a13 100755 --- a/t/0-me-first.t +++ b/t/0-me-first.t @@ -53,7 +53,7 @@ try " # log file cat \$(gitolite query-rc GL_LOGFILE); - ok; /update:OK/ + ok; /check2/ /aa\tu1\t\\+\trefs/heads/master/ /2d066fb4860c29cf321170c17695c6883f3d50e8/ /284951dfa11d58f99ab76b9f4e4c1ad2f2461236/