Bug #46629 for mod_perl: [mp1] fix for a bug in perl_restart which causes module reloads in apache children

Hi. I found a bug in mod_perl's perl_restart in perl_util.c which caused module reload in the children. It occured as many log entries in virtual server logs (not the main error_log) on first page opening after restart. That means if we start clean apache (with mod_perl) and open a page then we immediatelly get many records in an access log of the virtual server we call. The error look like this: [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine globber redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 22. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine globmap redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 50. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine new redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 60. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine _retError redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 120. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine _unmatched redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 127. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine _parseBit redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 135. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine _parseInputGlob redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 195. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine _parseOutputGlob redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 282. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine _getFiles redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 327. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine getFileMap redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 358. [Thu May 7 16:32:00 2009] GlobMapper.pm: Subroutine getHash redefined at /usr/local/my/perl/lib/site_perl/5.6.2/File/GlobMapper.pm line 365. ... many other lines like that The httpd.conf looks like this: PerlFreshRestart On PerlSetEnv PERL_RLIMIT_DATA 96:150 PerlSetEnv PERL_RLIMIT_CORE 0 PerlModule Apache::Resource PerlModule Apache::DBI PerlChildInitHandler Apache::Resource PerlInitHandler Apache::Reload PerlModule Apache::Registry PerlRequire /home/xxx/apache_2/startup.pl ErrorLog /home/xxxx/apache_2/logs/error_log <VirtualHost _default_> ServerName vip.xxxx.com DocumentRoot /home/xxxx/release/cart.my.com/html ErrorLog /home/xxxx/apache/logs/vip-errors TransferLog /home/xxxx/apache/logs/vip-access DirectoryIndex vip SetHandler perl-script PerlHandler Apache::Registry PerlSendHeader On </VirtualHost> Perl version: Summary of my perl5 (revision 5.0 version 6 subversion 2) configuration: Platform: osname=linux, osvers=2.6.18-92.el5, archname=x86_64-linux uname='linux dev.my.com 2.6.18-92.el5 #1 smp tue jun 10 18:51:06 edt 2008 x86_64 x86_64 x86_64 gnulinux ' config_args='-Dprefix=/usr/local/my/perl -Doptimize=-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic -frename-registers -ftracer -de' 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=define use64bitall=define uselongdouble=undef Compiler: cc='cc', ccflags ='-DDEBUGGING -fno-strict-aliasing -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64', optimize='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic -frename-registers -ftracer', cppflags='-DDEBUGGING -fno-strict-aliasing -I/usr/local/include' ccversion='', gccversion='4.1.2 20080704 (Red Hat 4.1.2-44)', gccosandvers='' intsize=4, longsize=8, ptrsize=8, doublesize=8, byteorder=12345678 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=16 ivtype='long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8 alignbytes=8, usemymalloc=n, prototype=define Linker and Libraries: ld='cc', ldflags =' -L/usr/local/lib' libpth=/usr/local/lib /lib /usr/lib libs=-lnsl -ldb -ldl -lm -lc -lcrypt -lutil perllibs=-lnsl -ldl -lm -lc -lcrypt -lutil libc=/lib/libc-2.5.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: DEBUGGING USE_64_BIT_INT USE_64_BIT_ALL USE_LARGE_FILES Built under linux Compiled at May 11 2009 13:27:26 @INC: /usr/local/my/perl/lib/5.6.2/x86_64-linux /usr/local/my/perl/lib/5.6.2 /usr/local/my/perl/lib/site_perl/5.6.2/x86_64-linux /usr/local/my/perl/lib/site_perl/5.6.2 /usr/local/my/perl/lib/site_perl Perl compile options: See above. Just FYI - Failed tests: Failed Test Stat Wstat Total Fail Failed List of Failed ------------------------------------------------------------------------------- internal/auth.t 2 1 50.00% 2 error_log (main log, each virtual host has its own log) shows something like this on its start: [Thu May 7 16:30:25 2009] RawInflate.pm: Subroutine new redefined at /usr/local/my/perl/lib/site_perl/5.6.2/IO/Uncompress/RawInflate.pm line 33. [Thu May 7 16:30:25 2009] RawInflate.pm: Subroutine rawinflate redefined at /usr/local/my/perl/lib/site_perl/5.6.2/IO/Uncompress/RawInflate.pm line 40. [Thu May 7 16:30:25 2009] RawInflate.pm: Subroutine getExtraParams redefined at /usr/local/my/perl/lib/site_perl/5.6.2/IO/Uncompress/RawInflate.pm line 46. [Thu May 7 16:30:25 2009] RawInflate.pm: Subroutine ckParams redefined at /usr/local/my/perl/lib/site_perl/5.6.2/IO/Uncompress/RawInflate.pm line 51. ... [Thu May 7 16:30:25 2009] (eval 375): String found where operator expected at (eval 375) line 1, at end of line [Thu May 7 16:30:25 2009] (eval 375): (Missing operator before ?) [Thu May 7 16:30:25 2009] (eval 376): String found where operator expected at (eval 376) line 1, at end of line [Thu May 7 16:30:25 2009] (eval 376): (Missing operator before ?) [Thu May 7 16:30:25 2009] (eval 377): String found where operator expected at (eval 377) line 1, at end of line [Thu May 7 16:30:25 2009] (eval 377): (Missing operator before ?) [Thu May 7 16:30:25 2009] (eval 378): String found where operator expected at (eval 378) line 1, at end of line ... many lines like this... How I fixed that. After some investigations I found that those eval lines are generated by perl_require_pv() call in perl_restart function here: hv_delete_ent(hash, keysv, G_DISCARD, 0); MP_TRACE_g(fprintf(stderr, "reloading %s\n", elts[i].key)); perl_require_pv(elts[i].key); I replaced it with perl_do_file and played with it (because it does the same and code is the same as in perl_require_pv. void perl_do_file(char *pv) { SV* sv = sv_newmortal(); sv_setpv(sv, "require '"); sv_catpv(sv, pv); sv_catpv(sv, "'"); perl_eval_sv(sv, G_DISCARD); /*(void)hv_delete(GvHV(incgv), pv, strlen(pv), G_DISCARD);*/ } I found that sv_setpv() overwrites pv string (which equals elts[i].key). I've added Carp dumps for any error and found that eval string (sv in perl_eval_sv(sv, G_DISCARD);) was actually "require ''';" (three consecutive single quotes). My guess is that hv_delete_ent call frees memory which elts[i].key occupies. So sv_setpv starts using the same memory. I tried to use a copy of elts[i].key and everything works fine for me now. I dont know if my guess was right or not, but it works. I tried both SvPV_nolen(keysv) and strdup, they work both. hv_delete_ent(hash, keysv, G_DISCARD, 0); MP_TRACE_g(fprintf(stderr, "reloading %s\n", SvPV_nolen(keysv))); perl_require_pv(SvPV_nolen(keysv)); Please, analyze that and tell me if this fix is right. I've attached the patch for the latest mod_perl-1.31. --- mod_perl-1.31.orig/src/modules/perl/perl_util.c 2007-12-03 09:19:59.000000000 +0200 +++ mod_perl-1.31/src/modules/perl/perl_util.c 2009-05-30 13:33:36.000000000 +0300 @@ -501,8 +501,8 @@ continue; } hv_delete_ent(hash, keysv, G_DISCARD, 0); - MP_TRACE_g(fprintf(stderr, "reloading %s\n", elts[i].key)); - perl_require_pv(elts[i].key); + MP_TRACE_g(fprintf(stderr, "reloading %s\n", SvPV_nolen(keysv))); + perl_require_pv(SvPV_nolen(keysv)); } SvREFCNT_dec(keysv); } Thanks. / Pavel Merdin P.S. I found the same problem on a production server. But number of 'eval' errors is much less. The pattern is the same.

--- mod_perl-1.31.orig/src/modules/perl/perl_util.c 2007-12-03 09:19:59.000000000 +0200 +++ mod_perl-1.31/src/modules/perl/perl_util.c 2009-05-30 13:33:36.000000000 +0300 @@ -501,8 +501,8 @@ continue; } hv_delete_ent(hash, keysv, G_DISCARD, 0); - MP_TRACE_g(fprintf(stderr, "reloading %s\n", elts[i].key)); - perl_require_pv(elts[i].key); + MP_TRACE_g(fprintf(stderr, "reloading %s\n", SvPV_nolen(keysv))); + perl_require_pv(SvPV_nolen(keysv)); } SvREFCNT_dec(keysv); }