Beefy Boxes and Bandwidth Generously Provided by pair Networks
Problems? Is your data what you think it is?
 
PerlMonks  

Merged lines with Apache::LogFile-based log handler

by bronto (Priest)
on Jul 09, 2007 at 15:24 UTC ( [id://625632]=perlquestion: print w/replies, xml ) Need Help??

bronto has asked for the wisdom of the Perl Monks concerning the following question:

Dearest Monks

I built a small mod_perl handler that logs a message in a custom log file depending on the presence and the value of an HTTP header. It is named Tiscali::LogLoadBalancer and uses the Apache::LogFile module this way in httpd.conf:

PerlModule Apache::LogFile PerlModule Apache::LogFile::Config PerlLogFile "logs/loadbalancer.log" Tiscali::LoadBalancerLogFile <Location /> PerlFixuphandler Tiscali::LogLoadBalancer </Location>

The handler works almost well: header's values are correctly logged into the logs/loadbalancer.log file. E.g.:

Mon Jul  9 16:53:56 2007 [25102] X-Loadbalancer: 0 (OK)

Unfortunately, when the server is heavily stressed (like launching three parallel instances of the ab utility with three different values for that header) it happens quite often that two (or more!) different log messages are merged togehter, e.g.:

Mon Jul  9 16:53:56 2007 [25101] X-Loadbalancer: 2 (INVALID)Mon Jul  9 16:53:56 2007 [25108] X-Loadbalancer: 1 (OK)

or

Mon Jul 9 16:53:56 2007 [25101] X-Loadbalancer: 2 (INVALID)Mon Jul 9 + 16:53:56 2007 [25108] X-Loadbalancer: 1 (OK)Mon Jul 9 16:53:56 2007 + [25102] X-Loadbalancer: 0 (OK) Mon Jul 9 16:53:56 2007 [25101] X-Loadbalancer: 2 (INVALID)

Is there any way to avoid that side effect? When I opted for an Apache::LogFile-based solution I did it also because I believed that this kind of issue was already taken care of by the author, who has a well respected name in the community. I guess I am probably doing something wrong, but I can't tell what... any help?

Module's code follows:

package Tiscali::LogLoadBalancer ; use strict ; use warnings ; use Apache::Constants qw{:common} ; sub handler { my ($self,$r) = @_ ; $r ||= Apache->request() ; my $status ; my $lb = $r->header_in( q{X-Loadbalancer} ) ; if (defined $lb) { $status = q{INVALID} ; $status = q{OK} if $lb == 0 ; $status = q{OK} if $lb == 1 ; } else { $lb = q{UNDEF} ; $status = q{OK} ; } _logger($lb,$status) ; return DECLINED ; } sub _logger { my ($lb_value,$status) = @_ ; my $now = localtime ; my $pid = $$ ; my $message = qq{$now [$pid] X-Loadbalancer: $lb_value ($status)} ; print Tiscali::LoadBalancerLogFile $message ; } 1 ;

Ciao!
--bronto


In theory, there is no difference between theory and practice. In practice, there is.

Replies are listed 'Best First'.
Re: Merged lines with Apache::LogFile-based log handler
by derby (Abbot) on Jul 09, 2007 at 19:18 UTC

    Normally writes (of this size) are atomic so I doubt you need any type of locking mechanism. Looking at the XS code for Apache::LogFile, I see it does mutiple writes - for the message(s) and for the newline if the message(s) does not contain a newline:

    int print(self, ...) Apache::LogFile self ALIAS: Apache::LogFile::PRINT = 1 PREINIT: int i; STRLEN len; char *str; CODE: for(i=1; i<items; i++) { str = SvPV(ST(i),len); RETVAL += write(self->log_fd, str, len); } if(*(SvEND(ST(i-1)) - 1) != '\n') RETVAL += write(self->log_fd, "\n", 1); OUTPUT: RETVAL
    Under heavy load, what you're seeing is one process being put into a wait state before the newline is output. You don't mention it, but did your logfile also contain blank lines? It should've.

    Since you have control, if you append a newline to $message in your _logger method before you print, your logs should come out fine under heavy load.

    my $message = qq{$now [$pid] X-Loadbalancer: $lb_value ($status)\n} ; print Tiscali::LoadBalancerLogFile $message ;

    -derby

      Hello derby

      First things first: it worked! Thanks a lot

      Second: a small change in apache's configuration is needed: I erroneously configured my module as a Fixup handler, which caused it to be called a huge number of times per line, that amplified the problem. Configuring it as a log handler correctly writes one line at a time. Anyway, I also tested it with the wrong apache configuration, and it still worked, so your solution is absolutely right.

      Under heavy load, what you're seeing is one process being put into a wait state before the newline is output. You don't mention it, but did your logfile also contain blank lines? It should've.

      Right. I didn't mention it since I pasted an example that contained a blank line. Nevertheless, it was not completely evident. My fault.

      Big thanks!!!

      Ciao!
      --bronto


      In theory, there is no difference between theory and practice. In practice, there is.
Re: Merged lines with Apache::LogFile-based log handler
by jasonk (Parson) on Jul 09, 2007 at 16:50 UTC

    Looking at the source for Apache::LogFile, it doesn't appear to do any kind of locking to prevent this problem. This isn't that uncommon for logfiles, where you have to decide between using some sort of locking to make sure you don't get this situation, or just accepting that this can happen once in a while and not locking, because holding the lock will slow the application down as other processes wait to lock the same file.

    In this situation, one possibility would be to make sure the logfile isn't being shared by multiple applications, perhaps by including the process id in the logfile name, and opening a new log if the current process id does not match the one in the opened log file. The best solution for this though is probably to change how you are logging that information, either logging to an external logging process that can deal with the locking and concurrency (like syslog) or logging to a database.


    We're not surrounded, we're in a target-rich environment!

Log In?
Username:
Password:

What's my password?
Create A New User
Domain Nodelet?
Node Status?
node history
Node Type: perlquestion [id://625632]
Approved by varian
help
Chatterbox?
and the web crawler heard nothing...

How do I use this?Last hourOther CB clients
Other Users?
Others wandering the Monastery: (7)
As of 2024-03-28 22:06 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    No recent polls found