I recently got a new server for our website, and installed RH7.2 on it and shipped it off to the colo. Since then, I've been getting lots of 404 server errors, so I added debugging code to the stacked content handler (a modified version of Apache::NavBar). What showed up in the error_log is unbelieveable.
- variables randomly get corrupted - statements either fail, or are skipped (hence the Alzheimers reference) I've tried both the apache and mod_perl that come with RH7.2 as well as on the latest versions of both that I compiled by hand, and there's no change in behavior between them. Here's the relevant sections of code from the module (I can also send a copy of the module if people think having the whole thing would help). ##The PRINT method for the Apache::OutputChain handler sub PRINT { my $self = shift; my $r = $self->[0]; my $bar = load_nav($r); my $plate = load_plate($r); local $_ = join '', @_; my ($header, $content); ($header,$content) = m#<HEAD>(.+)</HEAD>.*<BODY.*?>(.+)</BODY>#si; my $thash = { 'left_nav_java' => $bar->java, 'header' => $header, 'navigation_table' => $bar->table, 'content' => $content }; warn join ':', $$, $r->filename, ref($plate), "\n"; if (ref($plate) ne 'Text::Template') { warn join '', "NavGraphics($$) PRINT: >", $plate, "<\n"; } my $result = $plate->fill_in(HASH => $thash); if (defined $result) { $self->Apache::OutputChain::PRINT($result); } else { warn "ERROR: $Text::Template::ERROR\n"; } return OK; } ##The template object caching subroutine ##Note the warn statements and their order sub load_plate { my ($r) = @_; my $conf_file = $r->server_root_relative($r->dir_config('MyTemplate')); my $mod_time; if (-e $conf_file) { $mod_time = (stat _)[9]; } else { $conf_file = ''; $mod_time = 0; } warn "NavGraphics($$): conf_file = >$conf_file<\n"; warn "NavGraphics($$) time=$mod_time\n"; warn join '', "NavGraphics($$): exists ", exists $TB{$conf_file}, "\n"; return $TB{$conf_file}->template() if exists($TB{$conf_file}) && ($TB{$conf_file}->modified() >= $mod_time) && (ref($TB{$conf_file}->template()) eq 'Text::Template'); warn "NavGraphics($$): plate not cached\n"; warn "NavGraphics($$): plate $TB{$conf_file}\n"; warn "NavGraphics($$): before new $TB{$conf_file}\n"; $TB{$conf_file} = Apache::NavGraphics::NavTemplate->new($conf_file); warn "NavGraphics($$): after new $TB{$conf_file}\n"; warn join '', "NavGraphics plate($$): ", ref($TB{$conf_file}->template()), "\n"; return $TB{$conf_file}->template(); } ##The new method for Apache::NavGraphics::NavTemplate package Apache::NavGraphics::NavTemplate; sub new { my ($class, $templateFile) = @_; warn "NavPlate($$): new <$templateFile>\n"; unless ($templateFile) { warn "NavPlate($$) Empty templateFile sent\n"; return bless { 'template' => '', 'modified' => 0 }, $class; } my $fh = Apache::File->new($templateFile) || return; warn "NavPlate($$): after fh\n"; my $template = Text::Template->new( TYPE => 'FILEHANDLE', SOURCE => $fh, DELIMITERS => ['{{', '}}'] ) or warn "($$)Problem with template: $Text::Template::ERROR\n"; warn join '', "NavPlate($$) ref: ", ref($template), "\n"; return bless({ 'template' => $template, 'modified' => (stat $templateFile)[9] }, $class); } And here's some error_log output: NavGraphics(30166): conf_file = >/etc/httpd/etc/Sunset6.template< NavGraphics(30166) time=1025358762 NavGraphics(30166): exists 1 NavGraphics(30166): plate not cached NavGraphics(30166): plate Apache::NavGraphics::NavTemplate=HASH(0x8268adc) NavGraphics(30166): before new Apache::NavGraphics::NavTemplate=HASH(0x8268adc) NavGraphics(30166): after new Apache::NavGraphics::NavTemplate=HASH(0x82688a8) NavGraphics plate(30166): 30166:/home/httpd/html/Web/WebPolicy.html:: Please note the flow. This page has been accessed several times, but now the caching code says that it isn't cached, which means that the cached Text::Template object isn't there anymore, even though the hash entry exists. Without worrying why that happens, look at the rest of this section. There should be additional debugging output between these lines: NavGraphics(30166): before new Apache::NavGraphics::NavTemplate=HASH(0x8268adc) NavGraphics(30166): after new Apache::NavGraphics::NavTemplate=HASH(0x82688a8) from this call to create a new object: $TB{$conf_file} = Apache::NavGraphics::NavTemplate->new($conf_file); There isn't, but the hash has changed, as shown by the change in address! What's more, the last two lines show that whatever is returned by load_plate isn't an object. It turns out that it's the template itself (the file). Sometimes, the debugging code will look like this: Graphics(30166): conf_file = >/etc/httpd/etc/Sunset6.template< NavGraphics(30166) time=1025358762 NavGraphics(30166): exists NavGraphics(30166): plate not cached NavGraphics(30166): plate NavGraphics(30166): before new NavGraphics(30166): after new Apache::NavGraphics::NavTemplate=HASH(0x82689a4) NavGraphics plate(30166): 30166:/home/httpd/html/Ministries/index.html:: In this case, the debugging output shows that the whole hash key/value pair has been lost, and similar to before, no debugging output from the call to new. And another snippet, where the thing actually worked: NavGraphics(30165): conf_file = >/etc/httpd/etc/Sunset6.template< NavGraphics(30165) time=1025358762 NavGraphics(30165): exists NavGraphics(30165): plate not cached NavGraphics(30165): plate NavGraphics(30165): before new NavPlate(30165): new </etc/httpd/etc/Sunset6.template> NavPlate(30165): after fh NavPlate(30165) ref: Text::Template NavGraphics(30165): after new Apache::NavGraphics::NavTemplate=HASH(0x8270b7c) NavGraphics plate(30165): Text::Template 30165:/home/httpd/html/index.html:Text::Template: The frequency of this all happening is very low, and interestingly enough, almost never happens during stress testing of the machine. Several nights ago, I pushed about 16000 hits onto the machine over 3 hours with no errors, only to have errors in the log show up a few hours later. At this point, I feel like I'm in way over my head. I'd appreciate any help or suggestions for additional debugging tests to run. Thanks, Colin httpd.conf snippet: NameVirtualHost 199.108.225.3 PerlModule Apache::OutputChain PerlModule Apache::NavGraphics PerlModule Apache::SendFile ##Main site, www <VirtualHost 199.108.225.3> ServerName www.sunsetpres.org DocumentRoot /home/httpd/html <Directory "/"> SetHandler perl-script PerlHandler Apache::OutputChain Apache::NavGraphics Apache::SendFile PerlSetVar MyTemplate etc/Sunset6.template PerlSetVar NavGraphicsDir /navgraphics </Directory> </VirtualHost> perl -V: Summary of my perl5 (revision 5.0 version 6 subversion 1) configuration: Platform: osname=linux, osvers=2.4.17-0.13smp, archname=i386-linux uname='linux daffy.perf.redhat.com 2.4.17-0.13smp #1 smp fri feb 1 10:30:48 est 2002 i686 unknown ' config_args='-des -Doptimize=-O2 -march=i386 -mcpu=i686 -Dcc=gcc -Dcf_by=Red Hat, Inc. -Dcccdlflags=-fPIC -Dinstallprefix=/usr -Dprefix=/usr -Darchname=i386-linux -Uusethreads -Uuseithreads -Uuselargefiles -Dd_dosuid -Dd_semctl_semun -Di_db -Di_ndbm -Di_gdbm -Di_shadow -Di_syslog -Dman3ext=3pm -Dlocincpth=' hint=recommended, useposix=true, d_sigaction=define usethreads=undef use5005threads=undef useithreads=undef usemultiplicity=undef useperlio=undef d_sfio=undef uselargefiles=undef usesocks=undef use64bitint=undef use64bitall=undef uselongdouble=undef Compiler: cc='gcc', ccflags ='-fno-strict-aliasing -I/usr/local/include', optimize='-O2 -march=i386 -mcpu=i686', cppflags='-fno-strict-aliasing -I/usr/local/include' ccversion='', gccversion='2.96 20000731 (Red Hat Linux 7.1 2.96-98)', gccosandvers='' intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12 ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=4 alignbytes=4, usemymalloc=n, prototype=define Linker and Libraries: ld='gcc', ldflags =' -L/usr/local/lib' libpth=/usr/local/lib /lib /usr/lib libs=-lnsl -ldl -lm -lc -lcrypt -lutil perllibs=-lnsl -ldl -lm -lc -lcrypt -lutil libc=/lib/libc-2.2.4.so, so=so, useshrplib=false, libperl=libperl.a Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-rdynamic' cccdlflags='-fPIC', lddlflags='-shared -L/usr/local/lib' Characteristics of this binary (from libperl): Compile-time options: Built under linux Compiled at Feb 20 2002 15:01:16 @INC: /usr/lib/perl5/5.6.1/i386-linux /usr/lib/perl5/5.6.1 /usr/lib/perl5/site_perl/5.6.1/i386-linux /usr/lib/perl5/site_perl/5.6.1 /usr/lib/perl5/site_perl/5.6.0/i386-linux /usr/lib/perl5/site_perl/5.6.0 /usr/lib/perl5/site_perl . Apache versions: apache-1.3.22-6 (from RH7.2) apache_1.3.26 mod_perl: mod_perl-1.26-2 (from RH7.2) mod_perl-1.27