> > Web servers itself starts spinning on 100% CPU once this happens.
> >
> > Log has this entry:
> >
> > [Thu Jan 06 18:52:18 2005] [error] APR::Socket::recv:
> > (11) Resource temporarily unavailable at
> > /local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/echo_block.pm
> > line 41
>
> I suppose that's t/protocol/echo_block.t (and not t/protocol/echo_filter),
> right?
No - the test output at this stage looks like this:
t/protocol/echo_block...................# Failed test 3 in
t/protocol/echo_block.t at line 22 fail #2
FAILED test 3
Failed 1/3 tests, 66.67% okay
t/protocol/echo_filter..................
(there no no newline on that last line.)
> Wow, irix. It's a first time I see anybody trying modperl on it.
Really? I've had it running v1.25 on Apache1.3.x for years.
> Can you identify where the process spins? e.g. try the technique explained
> in: 21.7.4.1. Using the Perl trace
> http://modperlbook.org/html/ch21_07.html or some tracing tool.
>
> any difference if you put an eval {} block around that line?
Well, I doubt it will make much difference given that it was reported for a
different script.
It all seems to be pointing to issues around (non-)blocking sockets? The
echo_block and echo_filter tests both refer to fixes on Apache2.0.52 for
Open/NetBSD here.
Anyway - here's what you requested (after adding t/conf/modperl_extra.pl):
I removed all of the dirs (expect lib) from t which preceded protocol then
ran "make test". This is the resulting log (I've wrapped some bits, but the
longer lines may still wrap...).
=====================================================================================
[Mon Jan 10 17:52:05 2005] [info]
Init: Initializing OpenSSL library
[Mon Jan 10 17:52:05 2005] [info]
Init: Seeding PRNG with 0 bytes of entropy
[Mon Jan 10 17:52:05 2005] [info]
Init: Generating temporary RSA private keys (512/1024 bits)
[Mon Jan 10 17:52:06 2005] [info]
Init: Generating temporary DH parameters (512/1024 bits)
[Mon Jan 10 17:52:06 2005] [warn]
Init: Session Cache is not configured [hint: SSLSessionCache]
[Mon Jan 10 17:52:06 2005] [info]
Init: Initializing (virtual) servers for SSL
[Mon Jan 10 17:52:06 2005] [info]
Server: Apache/2.0.52, Interface: mod_ssl/2.0.52, Library: OpenSSL/0.9.7d
[Mon Jan 10 17:52:06 2005] [info]
Init: Initializing OpenSSL library
[Mon Jan 10 17:52:06 2005] [info]
Init: Seeding PRNG with 0 bytes of entropy
[Mon Jan 10 17:52:06 2005] [info]
Init: Generating temporary RSA private keys (512/1024 bits)
[Mon Jan 10 17:52:07 2005] [info]
Init: Generating temporary DH parameters (512/1024 bits)
[Mon Jan 10 17:52:07 2005] [info]
Init: Initializing (virtual) servers for SSL
[Mon Jan 10 17:52:07 2005] [info]
Server: Apache/2.0.52, Interface: mod_ssl/2.0.52, Library: OpenSSL/0.9.7d
[Mon Jan 10 17:52:07 2005] [notice]
Digest: generating secret for digest authentication ...
[Mon Jan 10 17:52:07 2005] [notice]
Digest: done
[Mon Jan 10 17:52:07 2005] [notice]
Apache/2.0.52 (Unix) DAV/2 mod_ssl/2.0.52 OpenSSL/0.9.7d
mod_perl/1.999.20 Perl/v5.8.5 configured -- resuming normal operations
[Mon Jan 10 17:52:07 2005] [info]
Server built: Jan 6 2005 14:00:24
[Mon Jan 10 17:52:07 2005] [debug]
prefork.c(955): AcceptMutex: sysvsem (default: sysvsem)
[Mon Jan 10 17:52:16 2005] [error]
recv() has returned untainted data:
at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/echo_block.pm
line 38.\n
[Mon Jan 10 17:52:41 2005] [error]
Caught SIGUSR2! at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/conf/modperl_extra.pl line 6
Book::Startup::__ANON__('USR2')
called at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/echo_filter.pm
line 22
eval {...} called at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/echo_filter.pm
line 22
TestProtocol::echo_filter::uc_filter('Apache::Filter=SCALAR(0x102b00d0)',
'APR::Brigade=SCALAR(0x102b0100)') called at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/echo_filter.pm
line 50
eval {...} called at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/echo_filter.pm
line 50
TestProtocol::echo_filter::handler('Apache::Connection=SCALAR(0x101ab0c8)')
called at -e line 0
eval {...} called at -e line 0
[Mon Jan 10 17:52:41 2005] [error]
Apache::Filter::fflush: (500) Block not fully transferred at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/echo_filter.pm
line 50
[Mon Jan 10 17:52:50 2005] [error]
APR::Socket::recv: (11) Resource temporarily unavailable at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/pseudo_http.pm
line 118
[Mon Jan 10 17:52:50 2005] [error]
APR::Socket::recv: (11) Resource temporarily unavailable at
/local/GML/Apache2/mod_perl-2.0.0-RC3/t/protocol/TestProtocol/pseudo_http.pm
line 118
*** The following error entry is expected and harmless ***
[Mon Jan 10 17:52:50 2005] [info]
removed PID file /local/GML/Apache2/mod_perl-2.0.0-RC3/t/logs/httpd.pid
(pid=328342)
[Mon Jan 10 17:52:50 2005] [notice]
caught SIGTERM, shutting down
