You are viewing a plain text version of this content. The canonical link for it is here.
Posted to modperl@perl.apache.org by Colin Kuskie <ck...@dalsemi.com> on 2002/08/02 20:45:37 UTC
mod_perl/Apache has Alzheimers?
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
Re: [mp1.2x] Intermittent code execution errors
Posted by Colin Kuskie <ck...@dalsemi.com>.
On Wed, Aug 21, 2002 at 10:55:35AM -0700, Colin Kuskie wrote:
> [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 forgot to attach the perl code.
Colin Kuskie
[mp1.2x] Intermittent code execution errors
Posted by Colin Kuskie <ck...@dalsemi.com>.
[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
.