php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #38757 MultiPart Form Uploads fail with FastCGI
Submitted: 2006-09-08 22:04 UTC Modified: 2006-10-04 14:49 UTC
Votes:2
Avg. Score:5.0 ± 0.0
Reproduced:2 of 2 (100.0%)
Same Version:0 (0.0%)
Same OS:0 (0.0%)
From: davidb at pins dot net Assigned: dmitry (profile)
Status: Closed Package: Apache related
PHP Version: 5.1.6 OS: Solaris 8
Private report: No CVE-ID: None
Welcome back! If you're the original bug submitter, here's where you can edit the bug or add additional notes.
If you forgot your password, you can retrieve your password here.
Password:
Status:
Package:
Bug Type:
Summary:
From: davidb at pins dot net
New email:
PHP Version: OS:

 

 [2006-09-08 22:04 UTC] davidb at pins dot net
Description:
------------
Greetings.

I'm currently observing a reproducible version of bug #26647 in the PHP 5.1 train.  For a subset of users running mostly Mac but some PC browsers, the PHP process unceremoniously exists witout comment when the form is POST'ed.  A truss of the PHP FastCGI process shows PHP reading in the text (incidently, it's also pointed out a performance issue where php's doing a read() of 8 bytes at a time from the FastCGI stream instead of 8kB at at a time, but I digress).  The problem appears to go away when I switch to a non-FastCGI version.

The broken users are broken consistently - it would be possible (and easy) to gdb trace it and see why it's exiting.  Here's the start/end of the truss:

accept(0, 0xFFBEDA50, 0xFFBED99C, 1)            = 4
fcntl(0, F_SETLK, 0xFFBEDA28)                   = 0
poll(0xFFBED8F0, 1, 1000)                       = 0
shutdown(4, 1, 1)                               = 0
recv(4, "0101\001\0\b\0\0", 8, 0)               = 8
recv(4, "\001\0\0\0\0\0\0", 8, 0)               = 8
recv(4, "0104\001\015\0\0", 8, 0)               = 8
recv(4, "0E05 C O N T E N", 8, 0)               = 8
recv(4, " T _ L E N G T H", 8, 0)               = 8
recv(4, " 8 3 5 1 90104\0", 8, 0)               = 8
recv(4, "01\0 d\0\0\f V C", 8, 0)               = 8
recv(4, " O N T E N T _ T", 8, 0)               = 8
recv(4, " Y P E m u l t i", 8, 0)               = 8
recv(4, " p a r t / f o r", 8, 0)               = 8
recv(4, " m - d a t a ;  ", 8, 0)               = 8
recv(4, " b o u n d a r y", 8, 0)               = 8
recv(4, " m L b O u N d A", 8, 0)               = 8
(many many lines)
recv(4, " r Y - -\r\n0105", 8, 0)               = 8
recv(4, "\001\0\0\0\0", 8, 0)                   = 6
recv(4, 0xFFBEDA28, 8, 0)                       = 0
close(4)                                        = 0
fcntl(0, F_SETLKW, 0xFFBEDA28)                  = 0
accept(0, 0xFFBEDA50, 0xFFBED99C, 1) (sleeping...)

Bam.  Goodbye.  No error, no nothing.



Reproduce code:
---------------
<html>
<head>
</head>
<body>
<form method="post" action="response.php" enctype="multipart/form-data">
        <input name="test" type="file">
        <input name="submit" value="submit" type="submit" />
</form>
</body>
</html>

Expected result:
----------------
The response.php should work - note, however, that php never even attempts to open the response.php file, which is just a trivial "file uploaded" message, no attempt to save.

Actual result:
--------------
See above truss - php just exits.

Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2006-09-08 22:09 UTC] tony2001@php.net
Please try using this CVS snapshot:

  http://snaps.php.net/php5.2-latest.tar.gz
 
For Windows:
 
  http://snaps.php.net/win32/php5.2-win32-latest.zip


 [2006-09-09 02:05 UTC] davidb at pins dot net
Well, I tried with the latest 5.2b snapshot, and now it's broken for my PC at home also.  Appears to be the identical problem - php just silently stops processing after it reads in the POST data, closes the socket, and then waits for the next request, throwing a 500 server error.

Please.
 [2006-09-09 21:09 UTC] tony2001@php.net
Dmitry, could you plz check it out?
 [2006-09-11 07:55 UTC] dmitry@php.net
From the strace log I see: PHP FastCGI server accepts connection and waits 1 sec (in pool()) for any input from HTTP client. It doesn't get any data in a second and does save connection close.

Could you describe your environment: CPU speed, WebServer, fastcgi plugin, fastcgi configuraion...

 [2006-09-12 15:50 UTC] davidb at pins dot net
Greetings.

Is the poll() timing out, even though it appeared to get all of the data in fd4?  Or, is there additional data that isn't getting passed on for some reason?  I can send the entire truss if you'd like.

We're running Apache 1.3.33, Solaris 8, on a dual-processor SPARC.  I believe it's the 2.4.2 FastCGI.  I do note that the read() that a valid post gets is different.

In a good truss:

poll(0xFFBED8F0, 1, 1000)                       = 1
read(4, "0101\001\0\b\0\0", 8)                  = 8
read(4, "\001\0\0\0\0\0\0", 8)                  = 8
read(4, "0104\001\015\0\0", 8)                  = 8
read(4, 0xFFBDD918, 21)                         = 21
  0E05 C O N T E N T _ L E N G T H 6 1 0 1 5
read(4, "0104\001\0 V\0\0", 8)                  = 8
read(4, 0xFFBDD918, 86)                         = 86
  \f H C O N T E N T _ T Y P E m u l t i p a r t / f o r m - d a t
   a ;   b o u n d a r y = - - - - - - - - - - - - - - - - - - - -
   - - - - - - - 1 9 1 9 4 1 1 2 6 6 2 0 5 9 7
read(4, "0104\001\0 =\0\0", 8)                  = 8
read(4, 0xFFBDD918, 61)                         = 61
  \r . D O C U M E N T _ R O O T / e x p o r t / h t t p d / D O M
   A I N S / t e s t 2 . f o r w a r d . c o m / h t d o c s

The poll seems to return with a 1, but the data that's read in is the same.  Is there something about the submit from different users that would cause the poll() to return differently?  I have network snoops, as well.
 [2006-09-12 16:03 UTC] davidb at pins dot net
A few other quick comments:

-  Perl + CGI::Fast hasn't reported any of these problems
-  This is only affecting a small subset of users, but those users tend to continue to have the problems recur
-  The users with recurring problems will sometimes suddenly, and without warning, start working again

I strongly suspect some odd network interaction, but I'm not entirely sure where to dig deeper just yet.

The FastCGI PHP instance is linked as a local UNIX socket:

  FastCgiServer /export/httpd/DOMAINS/host.forward.com/cgi-bin/php -port 9050
  AddHandler php-fastcgi .php
  <Location /cgi-bin/php>
    SetHandler fastcgi-script
  </Location>
  Action php-fastcgi /cgi-bin/php

There are several other vhosts that use teh FastCgiExternalServer directive.  We are using the PHP process manager to front-end the PHP work threads by setting PHP_FCGI_CHILDREN.
 [2006-09-13 13:08 UTC] dmitry@php.net
The bug should be fixed in CVS HEAD and PHP_5_2.
Please verify and close or reopen bug.

I just incrised the data waiting timeout from 1 to 5 sec.

It is good idea to use SO_ACCEPTFILTER instead of timeout, but it is avbailable only on BSD.
 [2006-09-15 03:51 UTC] davidb at pins dot net
Greetings.

I tried with the latest 5.2 (downloaded today).  It doesn't seem to make a difference.  The poll() still exits with 0, then proceeds to read everything in anyway.  Heres the truss, with timestamps this time:

94.3878 accept(0, 0xFFBEDC78, 0xFFBEDBC4, 1)            = 4
        AF_UNIX  name =
94.3880 fcntl(0, F_SETLK, 0xFFBEDC50)                   = 0
        typ=F_UNLCK  whence=SEEK_SET start=0     len=0     sys=4290697848 pid=2086536
95.3952 poll(0xFFBEDB18, 1, 1000)                       = 0
        fd=4  ev=POLLRDNORM rev=0
95.3959 shutdown(4, 1, 1)                               = 0
recv(4, 0xFFBEDC50, 8, 0)       (sleeping...)
signotifywait()                 (sleeping...)
lwp_sema_wait(0xFD70DE60)       (sleeping...)
        sema type: USYNC_THREAD  count = 0
103.4047        recv(4, "0101\001\0\b\0\0", 8, 0)               = 8
103.4050        recv(4, "\001\0\0\0\0\0\0", 8, 0)               = 8
103.4051        recv(4, "0104\001\016\0\0", 8, 0)               = 8
103.4051        recv(4, "0E06 C O N T E N", 8, 0)               = 8
103.4052        recv(4, " T _ L E N G T H", 8, 0)               = 8
103.4053        recv(4, " 1 2 8 9 9 00104", 8, 0)               = 8
103.4054        recv(4, "\001\0 E\0\0\f 7", 8, 0)               = 8
103.4055        recv(4, " C O N T E N T _", 8, 0)               = 8
103.4055        recv(4, " T Y P E m u l t", 8, 0)               = 8
....

I guess the big question is why is poll exiting with 0 when there's a pile of valid data?

David.
 [2006-09-18 21:29 UTC] davidb at pins dot net
One other thing which we noticed - if we take our sample 
(which breaks) and change the multipart-form to a regular 
form, the problem does not occur.

This is weird, and I have no idea how it may bear into the 
problem.  It may be a red herring of some sort.  Any ideas on 
the next step in debugging?
 [2006-09-19 20:43 UTC] dmitry@php.net
You have tested the old version, pool(..., 1000) means 1 second timeout. In new version you should have 5 seconds.
 [2006-09-19 20:52 UTC] davidb at pins dot net
Ummm...well, here's what I installed:

   php5.2-200609141630

Does this have what I need?  If not, can you tell me what URL to go look for?  I went to the snaps.php.net page for this.
 [2006-09-20 14:50 UTC] davidb at pins dot net
I just downloaded the latest snap php5.2-200609200230, but the poll() still shows the same thing:

  poll(0xFFBEDB18, 1, 1000)                       = 1

can you please tell me where to get the right stuff to test?

Thanks.
 [2006-09-26 14:05 UTC] davidb at pins dot net
Greetings.

I pulled the file out of CVS and built it.  I see that the line you changed is the struct tv{} stuff.  After some testing, it looks like moving it to 5 seconds helped, but did not fix the problem 100% of the time.

I moved it to 20 seconds, and that seems to fix the problem for our developers in Australia who were experiencing it the most.  I also backported this into 5.1.6 (it was only the single line change) and that seems to work there as well.

Can we put this on closed for now, and I'll reopen it if it doesn't fix it permenantly?
 [2006-10-03 09:24 UTC] dmitry@php.net
You can address this bug to mod_fastcgi people. It is really terrible to allocate PHP process and make it wait for more then 5 seconds. I don't like make PHP hang because of bugs (or bad decision) in it.

I am closing this bug.

You can try to use ZendEnabler from ZendCore distribution instead of mod_fastcgi.
 [2006-10-04 14:49 UTC] davidb at pins dot net
Greetings.

Does this mean you are *not* going to commit a fix of 20s, but will leave in the 5s?

One can argue about where the error is, but if you consider a submit from a remote site is uploading at 8kb/sec on average over 8 seconds, than that's 8KB in 8 seconds.  Even at 16kb/sec, you're going to take more than 5 seconds to fill a 16KB or 32KB buffer, which is the buffer between HTTP and mod_fastcgi.

Can this be a config option or something so I don't have to keep patching?  The downside of not putting in some sort of patch like this is a slow connection upstream will get regular errors.
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved.
Last updated: Fri Oct 11 22:01:45 2024 UTC