[sf-perl] Log stomping
David Alban
extasia at gmail.com
Tue Aug 23 14:15:17 PDT 2005
Greetings,
Perhaps this is more of a shell question than a perl question, but
here goes anyway.
I've replicated the "real world" problem into a pair of simple perl
programs. "foo" prints a couple lines of data. "foo-flocking" does
the same thing, but only after successfully acquiring an exclusive
flock.
When I ran eight cron invocations of foo, all at the same time, all
appending the same log file, they "stomped" on each other in the log.
When I used foo-flocking instead, I got slightly different results in
the log, but the invocations were still stomping on each other in the
log.
When I ran again, but invoked foo (the non-flocking version) only
after successfully creating a lock directory, no invocation of foo had
its output stomped in the log file.
My purpose in sending this post is to understand why the flocking
version doesn't solve the problem. My hunch is that each of the
shells that runs one of the cron jobs immediately discovers where end
of file is for the log file, since it's shell redirection that appends
the file, and not the program being run. Even though foo-flocking
must wait until it gets an exclusive lock before it has anything to
log. Then when each foo-flocking gets a lock, it appends the log.
But the shell is doing the appending, and its idea of end of file
hasn't changed, even if some other process has appended the log. When
this occurs, it stomps on the data the previous process wrote.
Does this make sense? Is this what's going on?
Here are the specifics:
===== begin foo ========================================================
#!/usr/bin/perl
use strict;
use warnings;
( my $pgm = $0 ) =~ s=^.*/==s;
my $argv0 = shift;
if ( not defined $argv0 ) {
$argv0 = "[undef]";
} # if
else {
$argv0 = "'$argv0'";
} # if
print logstamp(), " $pgm\[$$] argv[ 0 ] => $argv0\n";
print logstamp(), " $pgm\[$$] The rain in Spain falls mainly in the plain.\n";
#- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
sub logstamp {
my @t = localtime;
sprintf "%04d-%02d-%02d %02d:%02d:%02d", $t[ 5 ] + 1900,
$t[ 4 ] + 1,
$t[ 3 ],
$t[ 2 ],
$t[ 1 ],
$t[ 0 ];
} # logstamp
===== end foo ========================================================
===== begin foo-flocking ===============================================
#!/usr/bin/perl
use strict;
use warnings;
use Fcntl ':flock';
( my $pgm = $0 ) =~ s=^.*/==s;
my $argv0 = shift;
my $errormsg = lock_file();
$errormsg and die "$pgm: $errormsg\n";
if ( not defined $argv0 ) {
$argv0 = "[undef]";
} # if
else {
$argv0 = "'$argv0'";
} # if
print logstamp(), " $pgm\[$$] argv[ 0 ] => $argv0\n";
print logstamp(), " $pgm\[$$] The rain in Spain falls mainly in the plain.\n";
#- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
sub logstamp {
my @t = localtime;
sprintf "%04d-%02d-%02d %02d:%02d:%02d", $t[ 5 ] + 1900,
$t[ 4 ] + 1,
$t[ 3 ],
$t[ 2 ],
$t[ 1 ],
$t[ 0 ];
} # logstamp
#- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
sub lock_file {
my $func = "lock_file";
my $lockfile = "/tmp/foo.lock";
open my $handle, '>', $lockfile
or return "$func(): $lockfile: couldn't open for writing: $!";
my $attempts = 20;
my $interval = 1;
my $got_lock = 0;
for my $attempt ( 1..$attempts ) {
if ( flock $handle, LOCK_EX | LOCK_NB ) {
$got_lock = 1;
last;
} # if
sleep $interval if $attempt < $attempts;
} # for
return ( $got_lock
? ""
: "could not acquire lock after $attempts attempts: $!" );
} # lock_file
===== end foo-flocking ===============================================
===== begin cron jobs ==================================================
39 13 * * * $HOME/foo one >> $HOME/log 2>&1
39 13 * * * $HOME/foo two >> $HOME/log 2>&1
39 13 * * * $HOME/foo three >> $HOME/log 2>&1
39 13 * * * $HOME/foo four >> $HOME/log 2>&1
39 13 * * * $HOME/foo five >> $HOME/log 2>&1
39 13 * * * $HOME/foo six >> $HOME/log 2>&1
39 13 * * * $HOME/foo seven >> $HOME/log 2>&1
39 13 * * * $HOME/foo eight >> $HOME/log 2>&1
===== end cron jobs ==================================================
===== begin log ========================================================
2005-08-23 13:39:01 foo[9588] argv[ 0 ] => 'two'
2005-08-23 13:39:01 foo[9588] The rain in Spain falls mainly in the plain.
2005-08-23 13:39:01 foo[9599] argv[ 0 ] => 'five'
2005-08-23 13:39:01 foo[9599] The rain in Spain falls mainly in the plain.
2005-08-23 13:39:01 foo[9602] argv[ 0 ] => 'six'
2005-08-23 13:39:01 foo[9602] The rain in Spain falls mainly in the plain.
2005-08-23 13:39:02 foo[9609] argv[ 0 ] => 'eight'
2005-08-23 13:39:02 foo[9609] The rain in Spain falls mainly in the plain.
===== end log ========================================================
===== begin cron jobs ==================================================
43 13 * * * $HOME/foo-flocking one >> $HOME/log 2>&1
43 13 * * * $HOME/foo-flocking two >> $HOME/log 2>&1
43 13 * * * $HOME/foo-flocking three >> $HOME/log 2>&1
43 13 * * * $HOME/foo-flocking four >> $HOME/log 2>&1
43 13 * * * $HOME/foo-flocking five >> $HOME/log 2>&1
43 13 * * * $HOME/foo-flocking six >> $HOME/log 2>&1
43 13 * * * $HOME/foo-flocking seven >> $HOME/log 2>&1
43 13 * * * $HOME/foo-flocking eight >> $HOME/log 2>&1
===== end cron jobs ==================================================
===== begin log ========================================================
2005-08-23 13:43:01 foo-flocking[9651] argv[ 0 ] => 'three'
2005-08-23 13:43:01 foo-flocking[9651] The rain in Spain falls mainly
in the plain202005-08-23 13:43:02 foo-flocking[9659] argv[ 0 ] =>
'seven'
2005-08-23 13:43:02 foo-flocking[9659] The rain in Spain falls mainly
in the plain.
2005-08-23 13:43:02 foo-flocking[9661] argv[ 0 ] => 'eight'
2005-08-23 13:43:02 foo-flocking[9661] The rain in Spain falls mainly
in the plain.
===== end log ========================================================
The mklockdir program that you see in the last set of cron jobs below
attempts a finite number of times, sleeping a second between attempts,
to create a directory. It returns 0 to the shell if it was
successful, non-zero otherwise. The idea being that creating a
directory is an atomic operation. It will either entirely succeed or
entirely fail without race conditions. So being able to create a
"lock directory" is one implementation of locking.
I think it's preventing the log stomping, because the shell doesn't
start the redirection unless mklockdir is successful.
===== begin cron jobs ==================================================
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo one >> $HOME/log 2>&1; rmdir $lockdir; fi
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo two >> $HOME/log 2>&1; rmdir $lockdir; fi
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo three >> $HOME/log 2>&1; rmdir $lockdir; fi
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo four >> $HOME/log 2>&1; rmdir $lockdir; fi
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo five >> $HOME/log 2>&1; rmdir $lockdir; fi
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo six >> $HOME/log 2>&1; rmdir $lockdir; fi
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo seven >> $HOME/log 2>&1; rmdir $lockdir; fi
48 13 * * * lockdir=/tmp/foo.lock.d; if $HOME/mklockdir $lockdir; then
$HOME/foo eight >> $HOME/log 2>&1; rmdir $lockdir; fi
===== end cron jobs ==================================================
===== begin log ========================================================
2005-08-23 13:48:02 foo[9758] argv[ 0 ] => 'two'
2005-08-23 13:48:02 foo[9758] The rain in Spain falls mainly in the plain.
2005-08-23 13:48:03 foo[9761] argv[ 0 ] => 'three'
2005-08-23 13:48:03 foo[9761] The rain in Spain falls mainly in the plain.
2005-08-23 13:48:04 foo[9763] argv[ 0 ] => 'four'
2005-08-23 13:48:04 foo[9763] The rain in Spain falls mainly in the plain.
2005-08-23 13:48:04 foo[9765] argv[ 0 ] => 'one'
2005-08-23 13:48:04 foo[9765] The rain in Spain falls mainly in the plain.
2005-08-23 13:48:04 foo[9767] argv[ 0 ] => 'seven'
2005-08-23 13:48:04 foo[9767] The rain in Spain falls mainly in the plain.
2005-08-23 13:48:04 foo[9769] argv[ 0 ] => 'eight'
2005-08-23 13:48:04 foo[9769] The rain in Spain falls mainly in the plain.
2005-08-23 13:48:05 foo[9771] argv[ 0 ] => 'six'
2005-08-23 13:48:05 foo[9771] The rain in Spain falls mainly in the plain.
2005-08-23 13:48:05 foo[9773] argv[ 0 ] => 'five'
2005-08-23 13:48:05 foo[9773] The rain in Spain falls mainly in the plain.
===== end log ========================================================
Thanks!!
David
--
Live in a world of your own, but always welcome visitors.
More information about the SanFrancisco-pm
mailing list