You are viewing a plain text version of this content. The canonical link for it is here.
Posted to modperl@perl.apache.org by Bill Moseley <mo...@hank.org> on 2000/02/17 18:33:44 UTC
rotate logs redo
If you squint hard this is on topic:
I have a Registry script that keeps a file open for the life of the child.[1]
The file is opened $|=1.
When a request needs to log something it grabs LOCK_EX, prints, and then
LOCK_UN.
Every night at midnight I archive (rotate) this file. Not running as root,
so I can't shut down Apache while rotating the log.
The archive program opens the same log file, also with $| = 1, grabs a
LOCK_EX, waits two seconds (to let Solaris flush??), and makes a copy of
the log file.
Just for fun, I check the file sizes of the original log file and the
copied file to make sure they are the same. I then truncate the original
log file, print a "new log started" time stamp to the log file, and then
close the file, releasing the lock.
This has been working fine every night for almost two months, but now it
reported that the original log file had grown by a line's worth of characters.
My questions:
? Is the OS buffering the writes to the file so long that even waiting two
seconds after I have a LOCK_EX isn't long enough? Is there a time I can
wait where I know the OS has flushed?
? Is the only safe method to wrap an open/close around every write in the
mod_perl application? That seems like a waste of time.[1] Even if I do
close() after each write, should I still wait some amount of time after
grabbing the LOCK_EX to make a copy?
? Is it better just not to test error conditions ;)
--
[1] Each request creates one or more log messages, so why waste the time
opening the file each request, perhaps multiple times. Also, there are
many places in the script that write directly to the log file, so the
program expects the log file to be open and available for writing at all
times for the life of the request.
BTW - yes, the mod_perl program respects the LOCK_EX. If I run my rotate
log program with a really long wait after getting the LOCK_EX, the mod_perl
aps report that they can't get an exclusive lock on the log file.
And no, there aren't any other programs that write to that log file that
wouldn't respect the lock.
Bill Moseley
mailto:moseley@hank.org
Re: rotate logs redo
Posted by Bill Moseley <mo...@hank.org>.
At 01:59 PM 02/17/00 -0500, you wrote:
>>>>>> "BM" == Bill Moseley <mo...@hank.org> writes:
>
>BM> This has been working fine every night for almost two months, but
>BM> now it reported that the original log file had grown by a line's
>BM> worth of characters.
>
>You need to ensure any flushing is done before you LOCK_UN. That is,
>let the close() function do an implicit unlock for you.
That's the rule, but what about a situation where I want to leave the file
open? Besides, $|=1 should flush, and perldoc -f flock states:
"To avoid the possibility of miscoordination, Perl now flushes
FILEHANDLE before locking or unlocking it."
I could rewrite to open and close around every write to the log file, but
that seems like a lot of open and closes just so I can make one copy a day.
Bill Moseley
mailto:moseley@hank.org
Re: rotate logs redo
Posted by Vivek Khera <kh...@kciLink.com>.
>>>>> "BM" == Bill Moseley <mo...@hank.org> writes:
BM> This has been working fine every night for almost two months, but
BM> now it reported that the original log file had grown by a line's
BM> worth of characters.
You need to ensure any flushing is done before you LOCK_UN. That is,
let the close() function do an implicit unlock for you.
Re: rotate logs redo
Posted by Bill Moseley <mo...@hank.org>.
At 10:07 AM 02/17/00 -0800, Randal L. Schwartz wrote:
>>>>>> "Bill" == Bill Moseley <mo...@hank.org> writes:
>
>Bill> When a request needs to log something it grabs LOCK_EX, prints, and
then
>Bill> LOCK_UN.
>
>LOCK_UN is almost always dangerous. Are you using buffered writes at all?
Nope.
open( LOG_FILE, "+>>$path" ) or
die "Failed to Open log File '$path' error:'$!";
# Flushing is nice in mod_perl
select((select( LOG_FILE ), $| = 1)[0]);
>Simpler plan... just have the logroller rename the file. Then execute
>something like this when you want to write:
>
> my @handle_stat = stat(LOG);
> my @file_stat = stat("foo");
> unless ("@handle_stat[0,1]" eq "@file_stat[0,1]") {
> open LOG, ">>foo" or die "...";
> }
I like this, but I'm not sure it solves my problem.
The locking works on the Registry script -- that is, it doesn't write to
the log after the rotate log program has the LOCK_EX. Yours does the same
thing -- well it just writes to a new file instead of just waiting on the
lock.
My problem was that the OS, I'm assuming, is flushing after my rotate log
program has a LOCK_EX. I mean, if I LOCK_EX, wait a few seconds, then copy,
and then the files are different sizes, what else could be happening.
Renaming the file wouldn't help in that case, would it, as the OS would
still flush to the (now renamed) file?
This is important as after I make a copy of the file, and check that their
sizes are the same, I gzip the file. I wouldn't want to start the gzip if
the OS still had something to flush.
Bill Moseley
mailto:moseley@hank.org
Re: rotate logs redo
Posted by Bill McKinnon <mc...@isis2000.com>.
On 17 Feb 2000, Randal L. Schwartz wrote:
> Bill> What determines the 4096 number? Is it a stdio thing or a
> Bill> kernel level param? Any chance it will change from one system to the next?
> Bill> I'm curious because the above is something I suspected, but never knew too
> Bill> much about directly. Always nice to learn more about the underlying
> Bill> mechanisms at work...
>
> There's a constant that's been 4096 since the early days called
> PIPEBUFSIZ or something like that. It's the also been documented (at
> least in the source) as the number of bytes that are guaranteed to be
> atomically delivered through a pipe, and when the O_APPEND boys came
> around, they inherited it as the atomic append size.
>
> Of course, from a fresh implementation like Linux, we can only hope
> that the new guys respected the age-old values.
$ cd /usr/src/linux
$ grep 4096 include/linux/limits.h
#define PIPE_BUF 4096 /* # bytes in atomic write to a pipe */
$
Hope springs eternal. :)
- Bill
Re: rotate logs redo
Posted by "Randal L. Schwartz" <me...@stonehenge.com>.
>>>>> "Bill" == Bill McKinnon <mc...@isis2000.com> writes:
Bill> What determines the 4096 number? Is it a stdio thing or a
Bill> kernel level param? Any chance it will change from one system to the next?
Bill> I'm curious because the above is something I suspected, but never knew too
Bill> much about directly. Always nice to learn more about the underlying
Bill> mechanisms at work...
There's a constant that's been 4096 since the early days called
PIPEBUFSIZ or something like that. It's the also been documented (at
least in the source) as the number of bytes that are guaranteed to be
atomically delivered through a pipe, and when the O_APPEND boys came
around, they inherited it as the atomic append size.
Of course, from a fresh implementation like Linux, we can only hope
that the new guys respected the age-old values.
--
Randal L. Schwartz - Stonehenge Consulting Services, Inc. - +1 503 777 0095
<me...@stonehenge.com> <URL:http://www.stonehenge.com/merlyn/>
Perl/Unix/security consulting, Technical writing, Comedy, etc. etc.
See PerlTraining.Stonehenge.com for onsite and open-enrollment Perl training!
Re: rotate logs redo
Posted by "Jeffrey W. Baker" <jw...@acm.org>.
Bill McKinnon wrote:
>
> On 17 Feb 2000, Randal L. Schwartz wrote:
>
> > LOCK_UN is almost always dangerous. Are you using buffered writes at all?
> >
> > And LOCK_EX isn't needed if you write in a *single* I/O operation and
> > the file is open ">>" on most modern Unix flavors. If you have
> > O_APPEND in open(2), you're safe. Just do the following:
> >
> > open LOG, ">>foo" or die "...";
> >
> > ...
> >
> > $message = "blah blah blah";
> > die "can't atomic write $message" if length $message > 4096;
> > syswrite LOG, $message or die "I/O error: $!";
>
> What determines the 4096 number? Is it a stdio thing or a
> kernel level param? Any chance it will change from one system to the next?
> I'm curious because the above is something I suspected, but never knew too
> much about directly. Always nice to learn more about the underlying
> mechanisms at work...
>
> - Bill
I believe that the 4096 stems from the system's page size.
-jwb
Re: rotate logs redo
Posted by Bill McKinnon <mc...@isis2000.com>.
On 17 Feb 2000, Randal L. Schwartz wrote:
> LOCK_UN is almost always dangerous. Are you using buffered writes at all?
>
> And LOCK_EX isn't needed if you write in a *single* I/O operation and
> the file is open ">>" on most modern Unix flavors. If you have
> O_APPEND in open(2), you're safe. Just do the following:
>
> open LOG, ">>foo" or die "...";
>
> ...
>
> $message = "blah blah blah";
> die "can't atomic write $message" if length $message > 4096;
> syswrite LOG, $message or die "I/O error: $!";
What determines the 4096 number? Is it a stdio thing or a
kernel level param? Any chance it will change from one system to the next?
I'm curious because the above is something I suspected, but never knew too
much about directly. Always nice to learn more about the underlying
mechanisms at work...
- Bill
Re: rotate logs redo
Posted by "Randal L. Schwartz" <me...@stonehenge.com>.
>>>>> "Bill" == Bill Moseley <mo...@hank.org> writes:
Bill> When a request needs to log something it grabs LOCK_EX, prints, and then
Bill> LOCK_UN.
LOCK_UN is almost always dangerous. Are you using buffered writes at all?
And LOCK_EX isn't needed if you write in a *single* I/O operation and
the file is open ">>" on most modern Unix flavors. If you have
O_APPEND in open(2), you're safe. Just do the following:
open LOG, ">>foo" or die "...";
...
$message = "blah blah blah";
die "can't atomic write $message" if length $message > 4096;
syswrite LOG, $message or die "I/O error: $!";
Those "die"s may be a little abrupt. Put your own error handling there. :)
Bill> Every night at midnight I archive (rotate) this file. Not running as root,
Bill> so I can't shut down Apache while rotating the log.
Bill> The archive program opens the same log file, also with $| = 1, grabs a
Bill> LOCK_EX, waits two seconds (to let Solaris flush??), and makes a copy of
Bill> the log file.
Bill> Just for fun, I check the file sizes of the original log file and the
Bill> copied file to make sure they are the same. I then truncate the original
Bill> log file, print a "new log started" time stamp to the log file, and then
Bill> close the file, releasing the lock.
Simpler plan... just have the logroller rename the file. Then execute
something like this when you want to write:
my @handle_stat = stat(LOG);
my @file_stat = stat("foo");
unless ("@handle_stat[0,1]" eq "@file_stat[0,1]") {
open LOG, ">>foo" or die "...";
}
That way, if the file disappears, or someone else creates the new one,
it won't have the same dev/ino as the file you have open on LOG, and
you know it's time to re-open. This works regardless of whether a new
"foo" has been created by a new process yet, since the stat "foo" will
return empty list in that case.
You can cache the @handle_stat if you wish... just be sure to take
a new reading each time you open LOG.
--
Randal L. Schwartz - Stonehenge Consulting Services, Inc. - +1 503 777 0095
<me...@stonehenge.com> <URL:http://www.stonehenge.com/merlyn/>
Perl/Unix/security consulting, Technical writing, Comedy, etc. etc.
See PerlTraining.Stonehenge.com for onsite and open-enrollment Perl training!
Re: rotate logs redo
Posted by Bill McKinnon <mc...@isis2000.com>.
On Thu, 17 Feb 2000, Bill Moseley wrote:
<snip>
> This has been working fine every night for almost two months, but now it
> reported that the original log file had grown by a line's worth of characters.
>
> My questions:
>
> ? Is the OS buffering the writes to the file so long that even waiting two
> seconds after I have a LOCK_EX isn't long enough? Is there a time I can
> wait where I know the OS has flushed?
If you have the file opened with $|, then the buffer should be flushed
on every write, i.e. you shouldn't have the standard i/o buffering
problems. Could a request have come in right then in mid-switch? It sounds
like you just need to have the swap take place without the app writing any
data. Waiting for two seconds might actually increase the chances that a
write might occur during the swap (of course I'm theorizing here.
> ? Is the only safe method to wrap an open/close around every write in the
> mod_perl application? That seems like a waste of time.[1] Even if I do
> close() after each write, should I still wait some amount of time after
> grabbing the LOCK_EX to make a copy?
If you did the open/close thing, then you could just have your log
rotater do a 'mv'. This is probably still open to race conditions though.
> ? Is it better just not to test error conditions ;)
Have you considered just using a normal logrotate util? This would be
cleanest, since they usually run as root and could sighup apache. Sounds
safest to me...
- Bill