Crazy Bug: Apache execs script mutliple times for one req.
Posted: Tue Jun 26, 2007 11:15 am
Hi All,
I'm hoping someone has seen something even slightly resembling this strange problem. I'll do my best to describe it properly.:
SHORT VERSION:
I think apache executed my php script repeatedly in response to one http request.
LONG VERSION:
Server=Apache/1.3.37 (Unix) PHP/4.4.3 FrontPage/5.0.2.2623 mod_psoft_traffic/0.1 mod_ssl/2.8.28 OpenSSL/0.9.7a
The Script:
Nothing major, and all basic php 4.x code. When it runs fully, it makes a series of http/https requests out to other servers to collect data, runs one sql select command, and sends at most two emails. So, every time someone uses the script, I get an email containing the log of that instance. The logging is controlled by a 'startLog' call at start of the app, and an 'endLog' call and the end. If http requests were made by the script during execution, those files are zipped up and attached to the mail. Once that mail is sent, the log zip is deleted.
The Problem:
Last week I got a call from the sites owner to say that he was being flooded with mails from that script. I check my gmail, and sure enough, there's 1864 emails awaiting my attention. I take a quick look at one of them (they all appear to be the same) and there's nothing out of the ordinary in there. The log shows the script starting, performing some actions, then finishing. I ftp into the site, and throw an 'exit' into the top of the script. That seems to halt the emails, thank god.
The Investigation:
First thing I did was check the apache access logs to see what moron was bashing my script, and there's no such moron. There is only one incoming request matching the email logs that I received, and it appears at the time I STOPPED the script (using the exit call).
So, to recap. The first email log I received contained a server timestamp of 18:27. The apache server access logs showed that request as happening at 19:01. I check other scripts email logs against the access logs, and the timestamps all match up. This leads me to believe that apache received the request, ran the script in an infinite loop until I modified the code with the exit call, then finally stopped running it and added the request and timestamp to the access log.
The average run time for my script sis approx 20 seconds due to the large amount of http requests it has to make to different servers. In the case of the script that failed, it would have run very quickly as the request was malformed. ie: no processing was required, the script simply had to reply to say that they got it wrong. At the time of fault, there was one bug in the code where even though no zip file was created, the script tried to delete the zip file. This resulted in a call to 'unlink($zipFile)' where the $zipFile var was undefined.
- - - -
So, what do people think? Has anyone ever heard of a situation where apache runs the script multiple times? And by multiple times, I mean forever. If I didn't kill it with code, it would never have stopped.
If you read the whole thing, thank you! If you didn't, well then I don't blame you.
-
I'm hoping someone has seen something even slightly resembling this strange problem. I'll do my best to describe it properly.:
SHORT VERSION:
I think apache executed my php script repeatedly in response to one http request.
LONG VERSION:
Server=Apache/1.3.37 (Unix) PHP/4.4.3 FrontPage/5.0.2.2623 mod_psoft_traffic/0.1 mod_ssl/2.8.28 OpenSSL/0.9.7a
The Script:
Nothing major, and all basic php 4.x code. When it runs fully, it makes a series of http/https requests out to other servers to collect data, runs one sql select command, and sends at most two emails. So, every time someone uses the script, I get an email containing the log of that instance. The logging is controlled by a 'startLog' call at start of the app, and an 'endLog' call and the end. If http requests were made by the script during execution, those files are zipped up and attached to the mail. Once that mail is sent, the log zip is deleted.
The Problem:
Last week I got a call from the sites owner to say that he was being flooded with mails from that script. I check my gmail, and sure enough, there's 1864 emails awaiting my attention. I take a quick look at one of them (they all appear to be the same) and there's nothing out of the ordinary in there. The log shows the script starting, performing some actions, then finishing. I ftp into the site, and throw an 'exit' into the top of the script. That seems to halt the emails, thank god.
The Investigation:
First thing I did was check the apache access logs to see what moron was bashing my script, and there's no such moron. There is only one incoming request matching the email logs that I received, and it appears at the time I STOPPED the script (using the exit call).
So, to recap. The first email log I received contained a server timestamp of 18:27. The apache server access logs showed that request as happening at 19:01. I check other scripts email logs against the access logs, and the timestamps all match up. This leads me to believe that apache received the request, ran the script in an infinite loop until I modified the code with the exit call, then finally stopped running it and added the request and timestamp to the access log.
The average run time for my script sis approx 20 seconds due to the large amount of http requests it has to make to different servers. In the case of the script that failed, it would have run very quickly as the request was malformed. ie: no processing was required, the script simply had to reply to say that they got it wrong. At the time of fault, there was one bug in the code where even though no zip file was created, the script tried to delete the zip file. This resulted in a call to 'unlink($zipFile)' where the $zipFile var was undefined.
- - - -
So, what do people think? Has anyone ever heard of a situation where apache runs the script multiple times? And by multiple times, I mean forever. If I didn't kill it with code, it would never have stopped.
If you read the whole thing, thank you! If you didn't, well then I don't blame you.
-