[This is an update from my earlier posting which was entitled
"mod_perl has Alzheimers?". Since then I've read through the
mod_perl guide, searched the mailing list archives, and done a
more thorough job of analyzing the debug output.]
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).
Here's the debug output from a "good" process. There are snippets of
code down below so that you can understand the flow. The code itself is
attached to the email.
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 handler sees that it's cache is empty (it was just spawned), so it
calls new to create a new entry in the cache, which calls new for
Text::Template to get the templating object. The template object is
returned to the handler and information from the page is used to
populate the object.
Here's the debug output from a newly spawned "bad" child.
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::
[Thu Aug 1 10:27:18 2002] [error] Can't call method "fill_in" without a package or
object reference at /usr/lib/perl5/site_perl/5.6.1/Apache/NavGraphics.pm line 48.
This is similar to the "good" child, except notice that there's no
output from the templating object code (which was prefaced NavPlate).
However, "something" is placed into the cache and is returned to the
handler, but it isn't a Text::Template object.
Here's the debug output from a "bad" child on it's second request:
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::
[Thu Aug 1 11:03:41 2002] [error] Can't call method "fill_in" without a package or
object reference at /usr/lib/perl5/site_perl/5.6.1/Apache/NavGraphics.pm line 48.
As above, except now the object is cached. However, the caching code
correctly determines that the cache doesn't contain a Text::Template
object and tries to create a new object. However, it fails. There's
no debug output from the new method, and whatever is created by new
doesn't contain a Text::Template object. Interestingly though,
something different from last time is returned, which indicates that
the call to new did something. And if you print out what it did
return, you find the text of the template instead of the template
object.
As a stopgap, I tried making a second call to new if the first call to
new failed to return a Text::Template object, it also fails with no
debugging output so it appears that no calls to new will work in a
"bad" child process.
Here's the relevant sections of code from the module:
##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);
}
The spawning of a bad child appears completely random and load
independent, which probably means that it isn't a memory problem.
However, I had the memory of the machine scanned and I've been able to
duplicate the problem on a completely different machine.
I've tested and seen the problem on:
RH6.2, with updated mod_perl and apache rpms (I forget the exact versions)
RH7.2
mod_perl-1.26-2 (from rpm)
apache-1.3.22-6 (from rpm)
mod_perl-1.27 (compiled from source)
apache_1.3.26 (compiled from source)
RH7.3
apache_1.3.26 (from rpm)
mod_perl-1.27 (from rpm)
At this point, I don't understand why the output from warn in the "new"
method aren't going to the log file, or why Text::Template is returning
the template code instead of an object. The debugging examples
from the website are pretty daunting, I could generate 100 Mb's of
log files with no errors, only to find that when I restart the server
that a "bad" child is started right away (which happened the night
before last. I put about 240K hits on the server with no errors.
Then I made a few modifications to httpd.conf, restarted the server
and got an error right away. Changing the config back to the original,
however, didn't make the problem go away).
Has anyone seen behavior like this, or have suggestions on how to
make the debugging a little easier? Should I just wade in and see
what happens? Is there some other combination of software that I
should try, like a different version of Perl itself?
Thanks for your help,
Colin Kuskie
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
.
