http://qs321.pair.com?node_id=625632

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.