Return-Path: Delivered-To: apmail-perl-dev-archive@www.apache.org Received: (qmail 27395 invoked from network); 24 Jul 2009 13:08:53 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 24 Jul 2009 13:08:53 -0000 Received: (qmail 35014 invoked by uid 500); 24 Jul 2009 13:09:58 -0000 Delivered-To: apmail-perl-dev-archive@perl.apache.org Received: (qmail 34961 invoked by uid 500); 24 Jul 2009 13:09:57 -0000 Mailing-List: contact dev-help@perl.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: List-Id: Delivered-To: mailing list dev@perl.apache.org Received: (qmail 34941 invoked by uid 99); 24 Jul 2009 13:09:57 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 24 Jul 2009 13:09:57 +0000 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: local policy) Received: from [81.169.183.48] (HELO manager-game.de) (81.169.183.48) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 24 Jul 2009 13:09:45 +0000 Received: from [172.24.1.213] (yian-ho01.nir.cronon.net [192.166.201.94]) by manager-game.de (Postfix) with ESMTPSA id 225FE5CC01D for ; Fri, 24 Jul 2009 15:09:24 +0200 (CEST) Message-ID: <4A69B284.9000204@jan-o-sch.net> Date: Fri, 24 Jul 2009 15:09:24 +0200 From: Jan Schmidt User-Agent: Thunderbird 2.0.0.19 (X11/20090114) MIME-Version: 1.0 To: dev@perl.apache.org Subject: [mp2] perl-script handler messes with fd 0 and fd 1 X-Enigmail-Version: 0.95.7 Content-Type: text/plain; charset=ISO-8859-15 Content-Transfer-Encoding: 7bit X-Virus-Checked: Checked by ClamAV on apache.org Hi there! I just ran into a problem concerning mod_perl in combination with mod_cgi. That problem has been reported two years ago on this mailing list ([1], continued in [2] and [3]). I am seeing pretty much the same behaviour: -------------8<---------- Start Bug Report ------------8<---------- 1. Problem Description: When one Apache worker first executes a mod_perl request and then gets to somethins else (mod_cgi request for example), that "else" part sometimes failes due to the usage of fd 0 or fd 1 by mod_perl. Starting from the back (solaris truss output): --- exec of a cgi [pid 29891] --- fork1() (returning as child ...) = 29771 getpid() = 29891 [29771] lwp_self() = 1 lwp_sigmask(SIG_SETMASK, 0x00000000, 0x00000000) = 0xFFBFFEFF [0x0000FFFF] close(10) = 0 close(3) = 0 close(4) = 0 close(12) = 0 close(11) = 0 close(9) = 0 close(8) = 0 close(7) = 0 close(14) = 0 close(13) = 0 close(6) = 0 close(5) = 0 close(16) = 0 close(19) = 0 close(18) = 0 fcntl(0, F_DUP2FD, 0x00000000) = 0 close(0) = 0 fcntl(20, F_DUP2FD, 0x00000001) = 1 close(20) = 0 fcntl(22, F_DUP2FD, 0x00000002) = 2 close(22) = 0 [...] mod_cgi calls 3 times dup2() to arrange stdin, stdout and stderr. However, the first looks odd. mod_cgi does not take into account that the pipe it dup()s from is on fd 0 and so dup()s fd 0 to fd 0 (does nothing) and then closes the source - fd 0. The cgi won't be able to read from the client socket. I don't think mod_cgi has to cope with the pipe being on fd 0. One step backwards: The parent of the cgi, the Apache worker process, looks like this: --- the corresponding Apache worker [pid 29771] --- pollsys(0x08047408, 1, 0x080473D0, 0x00000000) (sleeping...) pollsys(0x08047408, 1, 0x080473D0, 0x00000000) = 1 read(16, " P O S T / c g i - b i".., 8000) = 590 stat64("/some/path/cgi-bin/program", 0x080474D0) = 0 getpid() = 29771 [20698] pipe() = 0 [18] fcntl(18, F_GETFL) = 2 fcntl(18, F_SETFL, FWRITE|FNONBLOCK) = 0 pipe() = 19 [20] fcntl(19, F_GETFL) = 2 fcntl(19, F_SETFL, FWRITE|FNONBLOCK) = 0 pipe() = 21 [22] fcntl(21, F_GETFL) = 2 fcntl(21, F_SETFL, FWRITE|FNONBLOCK) = 0 fork1() = 29891 There are the 3 pipe()s which fds were then used by mod_cgi to call dup2(). The first pipe is on fd 0 and 18, which is why mod_cgi does the odd dup2() call. How comes fd 0 is closed before pipe()? See what happened exactly before - the worker handled a mod_perl request: --- the mod_perl request immediately before [pid 29771] --- 47.9468 pollsys(0x08047408, 1, 0x080473D0, 0x00000000) = 1 47.9468 read(16, " G E T / p e r l / p r".., 8000) = 455 47.9469 stat64("/some/path/perl/prog.pl", 0x080474D0) = 0 47.9476 dup(0) = 17 47.9476 fcntl(17, F_GETFD, 0x084D26E4) = 0 47.9477 fstat64(17, 0x08340C00) = 0 47.9477 fcntl(17, F_SETFD, 0x00000001) = 0 47.9477 llseek(0, 0, SEEK_CUR) = 0 47.9478 close(0) = 0 47.9479 dup(1) = 0 47.9479 fcntl(0, F_GETFD, 0x084D26E8) = 0 47.9479 fstat64(0, 0x08340C00) = 0 47.9479 fcntl(0, F_SETFD, 0x00000000) = 0 47.9480 fcntl(0, F_GETFD, 0x08047400) = 0 47.9480 close(1) = 0 47.9484 stat64("/opt/RZperl/lib/5.8.5/i86pc-solaris/ModPerl/RegistryBB.pmc", 0x0 80470A0) Err#2 ENOENT [...] 48.1087 brk(0x0885D188) = 0 48.1088 dup(17) = 1 48.1088 fcntl(1, F_GETFD, 0x084D26F0) = 0 48.1089 fstat64(1, 0x08340C00) = 0 48.1089 fcntl(1, F_SETFD, 0x00000000) = 0 48.1089 llseek(17, 0, SEEK_CUR) = 0 48.1089 close(17) = 0 48.1090 writev(16, 0x08047340, 7) = 9009 48.1091 dup(0) = 17 48.1091 fcntl(17, F_GETFD, 0x084D26F4) = 0 48.1091 fstat64(17, 0x08340C00) = 0 48.1091 fcntl(17, F_SETFD, 0x00000001) = 0 48.1092 fcntl(17, F_GETFD, 0x080473F0) = 1 48.1092 dup(0) = 18 48.1092 close(18) = 0 48.1092 close(0) = 0 perl-script tries to allow reading from STDIN and writing to STDOUT to prog.pl, I guess that's what can be seen at the beginning. However, as close(0) is called before the dup() for STDOUT, that dup() then returns 0 - and things go wrong badly. I tried to look into modperl_io.c (especially modperl_io_perlio_override_stdin and modperl_io_perlio_restore_stdin) to figure out what is going on there, but I got stuck in the PerlIO layers and Perl's do_open9()/do_openn(). As a workaround, I switched to handler "modperl" instead of "perl-script", which does not try to set up STDIN and STDOUT. But perl-script should be able to "do the right thing", shouldn't it? 2. Used Components and their Configuration: *** mod_perl version 2.000004 *** using /waflhome/janosch/cvs-x86/pkgs/RZstgapache/mod_perl-2.0.4/lib/Apache2/BuildConfig.pm *** Makefile.PL options: MP_APR_LIB => aprext MP_AP_CONFIGURE => --with-mpm=prefork --prefix=/opt/RZstgapache --enable-dav=static --enable-auth-rdbm=static --enable-headers=static --enable-rewrite=shared --enable-deflate=shared --enable-logio=shared --enable-ssl=static --with-ssl=/waflhome/janosch/cvs-x86/pkgs/RZstgapache/local/openssl-0.9.8h.x86/usr/local/ssl --enable-suexec --with-suexec-bin=/opt/RZstgapache/bin/suexec --with-suexec-uidmin=1000 --with-suexec-gidmin=1000 --with-dbmd=/waflhome/janosch/obj-x86 MP_AP_PREFIX => /waflhome/janosch/cvs-x86/pkgs/RZstgapache/mod_perl-2.0.4/../httpd-2.2.11 MP_COMPAT_1X => 1 MP_GENERATE_XS => 1 MP_LIBNAME => mod_perl MP_USE_STATIC => 1 *** The httpd binary was not found *** (apr|apu)-config linking info -L/waflhome/janosch/cvs-x86/pkgs/RZstgapache/httpd-2.2.11/srclib/apr-util/.libs -L/waflhome/janosch/cvs-x86/pkgs/RZstgapache/httpd-2.2.11/srclib/apr-util -laprutil-1 -lexpat -liconv -L/waflhome/janosch/cvs-x86/pkgs/RZstgapache/httpd-2.2.11/srclib/apr/.libs -L/waflhome/janosch/cvs-x86/pkgs/RZstgapache/httpd-2.2.11/srclib/apr -lapr-1 -luuid -lsendfile -lrt -lsocket -lnsl -lpthread *** /opt/RZperl/bin/perl -V Summary of my perl5 (revision 5 version 8 subversion 5) configuration: Platform: osname=solaris, osvers=2.10, archname=i86pc-solaris uname='sunos fate 5.10 generic_125101-10 i86pc i386 i86pc ' config_args='-d -e -Dcc=gcc -Dcpp=cpp -Di_stdarg=define -Di_varargs=undef -Di_varhdr=stdarg.h -Dneed_va_copy=undef -Dprefix=/opt/RZperl -Dinstallprefix=/opt/RZperl' hint=recommended, useposix=true, d_sigaction=define usethreads=undef use5005threads=undef useithreads=undef usemultiplicity=undef useperlio=define d_sfio=undef uselargefiles=define usesocks=undef use64bitint=undef use64bitall=undef uselongdouble=undef usemymalloc=n, bincompat5005=undef Compiler: cc='gcc', ccflags ='-fno-strict-aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64', optimize='-O', cppflags='-fno-strict-aliasing -pipe -I/usr/local/include' ccversion='', gccversion='3.4.3 (csl-sol210-3_4-branch+sol_rpath)', gccosandvers='solaris2.10' 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, prototype=define Linker and Libraries: ld='gcc', ldflags =' -L/usr/local/lib ' libpth=/usr/local/lib /usr/lib /usr/ccs/lib libs=-lsocket -lnsl -lgdbm -ldl -lm -lc perllibs=-lsocket -lnsl -ldl -lm -lc libc=/lib/libc.so, so=so, useshrplib=false, libperl=libperl.a gnulibc_version='' Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags=' ' cccdlflags='-fPIC', lddlflags='-G -L/usr/local/lib' Characteristics of this binary (from libperl): Compile-time options: USE_LARGE_FILES Built under solaris Compiled at Apr 7 2009 17:24:25 %ENV: PERL_LWP_USE_HTTP_10="1" @INC: /opt/RZperl/lib/5.8.5/i86pc-solaris /opt/RZperl/lib/5.8.5 /opt/RZperl/lib/site_perl/5.8.5/i86pc-solaris /opt/RZperl/lib/site_perl/5.8.5 /opt/RZperl/lib/site_perl . *** Packages of interest status: Apache2 : - Apache2::Request : - CGI : 3.05 ExtUtils::MakeMaker: 6.17 LWP : - mod_perl : - mod_perl2 : 2.000004 3. This is the core dump trace: (if you get a core dump): none This report was generated by t/REPORT on Fri Jul 24 12:29:24 2009 GMT. -------------8<---------- End Bug Report --------------8<---------- [1] http://mail-archives.apache.org/mod_mbox/perl-modperl/200703.mbox/%3c20070328104615.GO10979@artesyncp.com%3e [2] http://mail-archives.apache.org/mod_mbox/perl-modperl/200703.mbox/%3c20070329151928.4964dd4e.frank@wiles.org%3e [3] http://mail-archives.apache.org/mod_mbox/perl-modperl/200704.mbox/ajax/%3c46118942.3040606@stason.org%3e --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org For additional commands, e-mail: dev-help@perl.apache.org