[BUG] Bad refcounting in Apache->push_handlers()

[prev] [thread] [next] [Date index for 2005/03/09]

From: Dominique Quatravaux
Subject: [BUG] Bad refcounting in Apache->push_handlers()
Date: 12:28 on 09 Mar 2005
-------------8<---------- Start Bug Report ------------8<----------
1. Problem Description:

I'm trying to make a PerlFixupHandler that reads:

sub ssl_is_mandatory {
  my $r = shift;
  require Apache::RequestRec;
  return 403 unless defined($r->subprocess_env("SSL_SERVER_S_DN"));
  return 0
}
Apache->push_handlers("PerlFixupHandler", \&ssl_is_mandatory);

So far so good, but when I try to do this instead:

Apache->push_handlers("PerlFixupHandler", sub { ... });

with the exact same Perl code inside the sub as above, I get extremely 
weird error messages, namely a warning ("Use of uninitialized value in 
null operation") and an error ("Undefined subroutine &main:: called"), 
neither of which having any useful backtrace information according to 
Apache::DB and some crocky breakpoints in $SIG{__WARN__} and 
$SIG{__DIE__} that I put together: for example,

  DB<1> T
$ = IDX::Debug::_die_with_stack_trace('Undefined subroutine &main:: 
called.^J') called from -e line 0
$ = eval {...} called from -e line 0


Attaching gdb on a mod_perl recompiled with -ldebugperl (*not* the 
configuration described in the report below, but close), I get this, 
just before the "Undefined subroutine &main:: called" is thrown:

#0  0x4040538e in read () from /lib/tls/libc.so.6
#1  0x4046bc60 in sys_sigabbrev () from /lib/tls/libc.so.6
#2  0x403a6ece in _IO_file_underflow () from /lib/tls/libc.so.6
#3  0x403a91dd in _IO_default_uflow () from /lib/tls/libc.so.6
#4  0x403a8ffe in __uflow () from /lib/tls/libc.so.6
#5  0x403a32e8 in getc () from /lib/tls/libc.so.6
#6  0x406133b1 in Perl_sv_gets (sv=0x88a5910, fp=0x86d8480, append=0)
    at sv.c:4481
#7  0x40603e1b in Perl_do_readline () at pp_hot.c:1453
#8  0x405fff60 in Perl_pp_readline () at pp_hot.c:227
#9  0x405fef2d in Perl_runops_debug () at run.c:53
#10 0x40639833 in S_docatch_body () at pp_ctl.c:2598
#11 0x40639919 in S_docatch (o=0x88d47d0) at pp_ctl.c:2624
#12 0x4063c486 in Perl_pp_entereval () at pp_ctl.c:3367
#13 0x405fef2d in Perl_runops_debug () at run.c:53
#14 0x405a52ed in S_call_body (myop=0xbffff7e4, is_eval=0) at perl.c:1892
#15 0x405a4be6 in perl_call_sv (sv=0x861b0ec, flags=2) at perl.c:1771
#16 0x405ef2fb in Perl_vdie (pat=0x4067c480 "Undefined subroutine &%s 
called",
    args=0xbffff890) at util.c:1606
#17 0x405ef504 in Perl_die (pat=0x4067c480 "Undefined subroutine &%s 
called")
    at util.c:1641
#18 0x40607d37 in Perl_pp_entersub () at pp_hot.c:2416
#19 0x405a52d5 in S_call_body (myop=0xbffffa54, is_eval=0) at perl.c:1889
#20 0x405a4f54 in perl_call_sv (sv=0x8753310, flags=4) at perl.c:1810
#21 0x40588a47 in modperl_callback (handler=0x8813aa0, p=0x888a998, r=0x0,
    s=0x80bab50, args=0x87348c0) at modperl_callback.c:100
#22 0x4058919f in modperl_callback_run_handlers (idx=0, type=1, r=0x0, 
c=0x0,
    s=0x80bab50, pconf=0x888a998, plog=0x0, ptemp=0x0, 
run_mode=MP_HOOK_VOID)
    at modperl_callback.c:261
#23 0x40589798 in modperl_callback_process (idx=0, p=0x888a998, 
s=0x80bab50,
    run_mode=MP_HOOK_VOID) at modperl_callback.c:403
#24 0x4059edf0 in modperl_child_init_handler (p=0x888a998, s=0x80bab50)
    at modperl_hooks.c:17
#25 0x0807817d in ap_run_child_init ()
#26 0x080765d1 in ap_graceful_stop_signalled ()
#27 0x08076a07 in ap_graceful_stop_signalled ()
#28 0x08076b28 in ap_graceful_stop_signalled ()
#29 0x0807739a in ap_mpm_run ()
#30 0x0807d96d in main ()
#31 0x40350904 in __libc_start_main () from /lib/tls/libc.so.6

So this looks a lot like modperl_callback is calling a CV that has been 
free()d before at modperl_callback line 100. Being a nearly complete 
ignorant in XS, I cannot investigate much further on my own, but I can 
certainly run experiments on your behalf, apply patches, etc.

This problem isn't blocking me anymore as I found an adequate 
workaround, namely to not use an anonymous sub (albeit after 2 days of 
debugging). So please, Stas and all, don't rush to rescue me, it's very 
nice of you but a bit embarassing at times :-)

2. Used Components and their Configuration:

Well after my third report I guess you know the drill, but here it goes:

*** mod_perl version 1.999021

*** using /home/dom/ftp/mod_perl-2.0.0-RC4/lib/Apache/BuildConfig.pm

*** Makefile.PL options:
  MP_APR_CONFIG   => /usr/bin/apr-config
  MP_APR_LIB      => aprext
  MP_APXS         => /usr/bin/apxs2
  MP_COMPAT_1X    => 1
  MP_GENERATE_XS  => 1
  MP_INST_APACHE2 => 1
  MP_LIBNAME      => mod_perl
  MP_USE_DSO      => 1


*** /usr/sbin/apache2 -V
Server version: Apache/2.0.52
Server built:   Nov 10 2004 11:57:35
Server's Module Magic Number: 20020903:9
Architecture:   32-bit
Server compiled with....
 -D APACHE_MPM_DIR="server/mpm/prefork"
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D HTTPD_ROOT=""
 -D SUEXEC_BIN="/usr/lib/apache2/suexec2"
 -D DEFAULT_PIDLOG="/var/run/httpd.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_LOCKFILE="/var/run/accept.lock"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="/etc/apache2/mime.types"
 -D SERVER_CONFIG_FILE="/etc/apache2/apache2.conf"


*** (apr|apu)-config linking info

 -L/usr/lib -lapr-0 -lrt -lm -lnsl  -lpthread
 -L/usr/lib -laprutil-0 -lldap -llber -ldb-4.2 -lexpat



*** /usr/bin/perl -V
Summary of my perl5 (revision 5.0 version 6 subversion 1) configuration:
  Platform:
    osname=linux, osvers=2.4.28-es, archname=i386-linux
    uname='linux gluck 2.4.28-es #1 smp sun nov 21 19:05:12 est 2004 
i686 unknown '
    config_args='-Dccflags=-DDEBIAN -Dcccdlflags=-fPIC 
-Darchname=i386-linux -Dprefix=/usr -Dprivlib=/usr/share/perl/5.6.1 
-Darchlib=/usr/lib/perl/5.6.1 -Dvendorprefix=/usr 
-Dvendorlib=/usr/share/perl5 -Dvendorarch=/usr/lib/perl5 
-Dsiteprefix=/usr/local -Dsitelib=/usr/local/share/perl/5.6.1 
-Dsitearch=/usr/local/lib/perl/5.6.1 -Dman1dir=/usr/share/man/man1 
-Dman3dir=/usr/share/man/man3 -Dman1ext=1 -Dman3ext=3perl 
-Dpager=/usr/bin/sensible-pager -Uafs -Ud_csh -Uusesfio -Duseshrplib 
-Dlibperl=libperl.so.5.6.1 -Dd_dosuid -des'
    hint=recommended, useposix=true, d_sigaction=define
    usethreads=undef use5005threads=undef useithreads=undef 
usemultiplicity=undef
    useperlio=undef d_sfio=undef uselargefiles=define usesocks=undef
    use64bitint=undef use64bitall=undef uselongdouble=undef
  Compiler:
    cc='cc', ccflags ='-DDEBIAN -fno-strict-aliasing 
-I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64',
    optimize='-O2',
    cppflags='-DDEBIAN -fno-strict-aliasing -I/usr/local/include'
    ccversion='', gccversion='2.95.4 20011002 (Debian prerelease)', 
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=8
    alignbytes=4, usemymalloc=n, prototype=define
  Linker and Libraries:
    ld='cc', ldflags =' -L/usr/local/lib'
    libpth=/usr/local/lib /lib /usr/lib
    libs=-lgdbm -ldb -ldl -lm -lc -lcrypt
    perllibs=-ldl -lm -lc -lcrypt
    libc=/lib/libc-2.2.5.so, so=so, useshrplib=true, 
libperl=libperl.so.5.6.1
  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: USE_LARGE_FILES
  Built under linux
  Compiled at Dec 23 2004 16:34:22
  %ENV:
    PERL_LWP_USE_HTTP_10="1"
  @INC:
    /usr/local/lib/perl/5.6.1
    /usr/local/share/perl/5.6.1
    /usr/lib/perl5
    /usr/share/perl5
    /usr/lib/perl/5.6.1
    /usr/share/perl/5.6.1
    /usr/local/lib/site_perl
    .

*** Packages of interest status:

Apache::Request: -
CGI            : 2.752
LWP            : 5.800
mod_perl       : 1.26, 1.999021


3. This is the core dump trace: (if you get a core dump):

N/A

This report was generated by ./t/REPORT on Wed Mar  9 11:57:18 2005 GMT.

-------------8<---------- End Bug Report --------------8<----------

        -- 
        << Tout n'y est pas parfait, mais on y honore certainement les jardiniers >>

			Dominique Quatravaux <dom@xxxxxxxxxxxx.xxxxxx.xxx>


[BUG] Bad refcounting in Apache->push_handlers()
Dominique Quatravaux 12:28 on 09 Mar 2005

[PATCH] Re: [BUG] Bad refcounting in Apache->push_handlers()
Dominique Quatravaux 14:26 on 31 Mar 2005

Generated at 14:43 on 11 Apr 2005 by mariachi v0.52