AT Bug

[Torsten Foertsch]

Hi,

on my Linux box sometimes (quite often) the httpd don't start during make
test. The error_log doesn't say anything useful:

[Wed Jul 16 13:08:53 2008] [info] mod_unique_id: using ip addr 192.168.0.4
[Wed Jul 16 13:08:54 2008] [info] Init: Seeding PRNG with 0 bytes of entropy
[Wed Jul 16 13:08:54 2008] [info] Init: Generating temporary RSA private keys (512/1024 bits)
[Wed Jul 16 13:08:54 2008] [info] Init: Generating temporary DH parameters (512/1024 bits)
[Wed Jul 16 13:08:54 2008] [warn] Init: Session Cache is not configured [hint: SSLSessionCache]
[Wed Jul 16 13:08:54 2008] [info] Init: Initializing (virtual) servers for SSL
[Wed Jul 16 13:08:54 2008] [info] mod_ssl/2.2.9 compiled against Server: Apache/2.2.9, Library: OpenSSL/0.9.8g
END in modperl_extra.pl, pid=7145

However, it should because httpd fails to start because an undefined value is
passed to Apache::TestConfig::untaint_path and hence perl croaks. Why it
sometimes do start I don't know.

To see the actual perl error I had to start httpd with:

strace -ff -ostrace -s 4096 /opt/apache22-prefork/sbin/httpd  -d $PWD/t \
       -f $PWD/t/conf/httpd.conf -D APACHE2 -D PERL_USEITHREADS -e debug

and look into the strace.PID file with the largest PID. There at the end I
found the error message.

So I instrumented the code a bit:

...
# return an untainted PATH
sub untaint_path {
    my $path = shift;
#    return '' unless( defined $path );
    unless( defined $path ) {
      use Carp;
      use Data::Dumper;
      Carp::confess(Data::Dumper->Dump([\%ENV], ['*ENV']));
    }
    ($path) = ( $path =~ /(.*)/ );
...

Now I found (manually formatted):

[Wed Jul 16 13:18:16 2008] [error] %ENV = (
         'TestDirective__env_srv1' => 'env_srv1',
         'IFS' => undef,
         'HARNESS_ACTIVE' => 1,
         'APACHE_TEST_HTTP_09_OK' => 0,
         'PERL_LWP_USE_HTTP_10' => 1,
         'ENV' => undef,
         'MOD_PERL_API_VERSION' => 2,
         'TestDirective__env_srv2' => 'env_srv2',
         'HARNESS_VERSION' => '2.64',
         'CDPATH' => undef,
         'BASH_ENV' => undef,
         'MOD_PERL' => 'mod_perl/2.0.5-dev'
       ); at /home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm line 1776
        Apache::TestConfig::untaint_path(undef) called at /home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm line 1102
        Apache::TestConfig::open_cmd('Apache::TestConfig=HASH(0x137bff8)', '"/opt/apache22-prefork/sbin/httpd" -l') called
at /home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm line 436
        Apache::TestConfig::get_httpd_static_modules('Apache::TestConfig=HASH(0x137bff8)') called at /home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm line 361
        Apache::TestConfig::inherit_config('Apache::TestConfig=HASH(0x137bff8)') called at /home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm line 417
        Apache::TestConfig::httpd_config('Apache::TestConfig=HASH(0x137bff8)') called at /home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/Test.pm line 110
        Apache::Test::config() called at /home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/Test.pm line 121
        Apache::Test::vars('documentroot') called at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_extra.pl line 129
        main::test_hooks_startup() called at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_extra.pl line 42
        require conf/modperl_extra.pl called at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_startup.pl line 18
        eval {...} called at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_startup.pl line 19
        main::BEGIN() called at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_extra.pl line 0
        eval {...} called at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_extra.pl line 0
        require /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_startup.pl called at (eval 2) line 1
        eval 'require qCompilation failed in require at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_startup.pl line 18.
BEGIN failed--compilation aborted at /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_startup.pl line 36.
Compilation failed in require at (eval 2) line 1.
[Wed Jul 16 13:18:16 2008] [error] Can't load Perl file: /home/r2/work/mp2/trunk/clean-trunk-prefork/t/conf/modperl_startup.pl for server localhost:8529, exiting...


Now, AT experts are needed to mull over:

1) why don't the error message show up in the error_log
2) is the enclosed patch a sufficient cure or does it rather hide a real
problem (why is $ENV{PATH} undef in the first place)

The strace output for that process starts with these lines:

setsid()                                = 7719
close(0)                                = 0
open("/dev/null", O_RDONLY)             = 0
close(1)                                = 0
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 1
close(2)                                = 0
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 2
stat("/opt/apache22-prefork/bin/suexec", 0x7fffb935fda0) = -1 ENOENT (No such file or directory)

So the first question is answered. However I don't know if it is wise
to redirect STDERR to /dev/null. The string "error_log" doesn't appear
in combination with an open syscall in that trace.

Torsten

[attachment removed]
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...

[Geoffrey Young]

> Now, AT experts are needed to mull over:
>
> 1) why don't the error message show up in the error_log
> 2) is the enclosed patch a sufficient cure or does it rather hide a real
> problem (why is $ENV{PATH} undef in the first place)
>
> The strace output for that process starts with these lines:
>
> setsid()                                = 7719
> close(0)                                = 0
> open("/dev/null", O_RDONLY)             = 0
> close(1)                                = 0
> open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 1
> close(2)                                = 0
> open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 2
> stat("/opt/apache22-prefork/bin/suexec", 0x7fffb935fda0) = -1 ENOENT (No such file or directory)
>
> So the first question is answered. However I don't know if it is wise
> to redirect STDERR to /dev/null. The string "error_log" doesn't appear
> in combination with an open syscall in that trace.

yeah, I don't get that.  digging in the recesses of my memory, I seem to
recall errors on one of the initial two startup passes being swallowed,
but it doesn't make sense if it's the first one since we see that all
the time.  maybe it's the second startup pass and the value being passed
to untaint_path() is undef where it wasn't before?  I'd be interested in
recording all the values passed in and see if they match during start
and restart.

as for your patch, it seems reasonable anyway, since there's no
guarantee that the path isn't undef, and we certainly don't want to
cause trouble.  however, it falls within our style to remove the parens :)

   return '' unless defined $path;

--Geoff

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...

[Torsten Foertsch]

On Wed 16 Jul 2008, Geoffrey Young wrote:
> I'd be interested in
> recording all the values passed in and see if they match during start
> and restart.

here you are.

The attached file is written with this print statement:

      print $f "$$=".(syscall 39).": ".($path // "(UNDEF)").": ".
        join( ", ", map {my @l=caller $_; "[$l[1]($l[2]): $l[3]]"} 0..3 )."\n";

I added syscall(39) (getpid) to make sure the correct $$ is reported.

Torsten

--
Need professional mod_perl support?
Just hire me: torsten.foertsch@...

12488=12488: /home/r2/bin:/opt/GMT/bin:/opt/svn/bin:/opt/mod_perl/bin:/opt/apache22-prefork/sbin:/opt/kde3/bin:/usr/local/bin:/usr/bin:/bin:/usr/bin/X11:/usr/X11R6/bin:/usr/games:/usr/lib64/jvm/jre/bin:/usr/lib/mit/bin:/usr/lib/mit/sbin: [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(1102): Apache::TestConfig::untaint_path], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(436): Apache::TestConfig::open_cmd], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(361): Apache::TestConfig::get_httpd_static_modules], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(417): Apache::TestConfig::inherit_config]
12488=12488: /home/r2/bin:/opt/GMT/bin:/opt/svn/bin:/opt/mod_perl/bin:/opt/apache22-prefork/sbin:/opt/kde3/bin:/usr/local/bin:/usr/bin:/bin:/usr/bin/X11:/usr/X11R6/bin:/usr/games:/usr/lib64/jvm/jre/bin:/usr/lib/mit/bin:/usr/lib/mit/sbin: [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(1102): Apache::TestConfig::untaint_path], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(457): Apache::TestConfig::open_cmd], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(362): Apache::TestConfig::get_httpd_defines], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(417): Apache::TestConfig::inherit_config]
12488=12488: /home/r2/bin:/opt/GMT/bin:/opt/svn/bin:/opt/mod_perl/bin:/opt/apache22-prefork/sbin:/opt/kde3/bin:/usr/local/bin:/usr/bin:/bin:/usr/bin/X11:/usr/X11R6/bin:/usr/games:/usr/lib64/jvm/jre/bin:/usr/lib/mit/bin:/usr/lib/mit/sbin: [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(1102): Apache::TestConfig::untaint_path], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(522): Apache::TestConfig::open_cmd], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestServer.pm(64): Apache::TestConfig::httpd_version], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(427): Apache::TestServer::post_config]
12492=12492: (UNDEF): [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(1102): Apache::TestConfig::untaint_path], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(436): Apache::TestConfig::open_cmd], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(361): Apache::TestConfig::get_httpd_static_modules], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(417): Apache::TestConfig::inherit_config]
12492=12492: (UNDEF): [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(1102): Apache::TestConfig::untaint_path], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(457): Apache::TestConfig::open_cmd], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(362): Apache::TestConfig::get_httpd_defines], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(417): Apache::TestConfig::inherit_config]
12492=12492: (UNDEF): [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(1102): Apache::TestConfig::untaint_path], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfigParse.pm(522): Apache::TestConfig::open_cmd], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestServer.pm(64): Apache::TestConfig::httpd_version], [/home/r2/work/mp2/trunk/clean-trunk-prefork/Apache-Test/lib/Apache/TestConfig.pm(427): Apache::TestServer::post_config]


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...

[Geoffrey Young]

Torsten Foertsch wrote:

> On Wed 16 Jul 2008, Geoffrey Young wrote:
>> I'd be interested in
>> recording all the values passed in and see if they match during start
>> and restart.
>
> here you are.
>
> The attached file is written with this print statement:
>
>       print $f "$$=".(syscall 39).": ".($path // "(UNDEF)").": ".
> join( ", ", map {my @l=caller $_; "[$l[1]($l[2]): $l[3]]"} 0..3 )."\n";
>
> I added syscall(39) (getpid) to make sure the correct $$ is reported.

yeah, so the paths are undef the second time around.  if I had to guess,
I'd say that taint is unsetting PERL5LIB or PATH or something and that
yes, the error_log the second time around is /dev/null.  I doubt there
is anything we can do to "fix" the "problem" since both portions are out
of our hands and are probably appropriate.

making Apache::Test not blow up seems like a good compromise :)

--Geoff

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@...
For additional commands, e-mail: dev-help@...