Crazy Bug: Apache execs script mutliple times for one req.

PHP programming forum. Ask questions or help people concerning PHP code. Don't understand a function? Need help implementing a class? Don't understand a class? Here is where to ask. Remember to do your homework!

Moderator: General Moderators

Post Reply
daveokeeffe
Forum Newbie
Posts: 5
Joined: Tue Jun 26, 2007 10:29 am

Crazy Bug: Apache execs script mutliple times for one req.

Post by daveokeeffe »

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.

-
mentor
Forum Contributor
Posts: 100
Joined: Sun Mar 11, 2007 11:10 am
Location: Pakistan

Post by mentor »

I have read the whole thread 8)

It seems to be a really strange problem and I never faced such problem. In my humble opinion, this is due to some bug in your script :cry:.
daveokeeffe
Forum Newbie
Posts: 5
Joined: Tue Jun 26, 2007 10:29 am

Post by daveokeeffe »

mentor wrote:I have read the whole thread 8)

It seems to be a really strange problem and I never faced such problem. In my humble opinion, this is due to some bug in your script :cry:.
Fair point, and I assumed the same myself. However, my logs show that the script gets from start to finish every time. The start and finish is outside any loops in the code (there are only two, and they're deep inside the code and very small), and apache won't allow one script to run for more than thirty seconds. After 30 seconds, apache will kill the process.

Here's some pseudo code showing the basic layout of my script:

Code: Select all

// start log (outputs timestamp to log)

// perform actions (once only, no loops in here except in deep processing code)

// end log (outputs timestamp to log)
// add log text to email var
// attach log zip file to email
// send email
// delete log zip file
I'm not saying it's definitely not a bug in my code, but I am saying that all signs point to the problem being external to my code. Is it possible that something my code is doing is telling the apache server to 'try again'?
User avatar
feyd
Neighborhood Spidermoddy
Posts: 31559
Joined: Mon Mar 29, 2004 3:24 pm
Location: Bothell, Washington, USA

Post by feyd »

Sounds like an include loop.
daveokeeffe
Forum Newbie
Posts: 5
Joined: Tue Jun 26, 2007 10:29 am

Post by daveokeeffe »

feyd wrote:Sounds like an include loop.
True, it does, but no file includes this file. And remember, the first email received from the script was timestamped a full 30 minutes before the Apache server logs the request. If it was an include loop, one script would have to be running to be including it the whole time, and this would cause apache to kill it after 30 seconds.

Come on lads and lassies, someone must have an innovative idea about this! How can I be the only one who's seen this problem?
User avatar
Benjamin
Site Administrator
Posts: 6935
Joined: Sun May 19, 2002 10:24 pm

Post by Benjamin »

I'll agree with feyd and say it's most likely an include loop. Regardless however, there is a bug in the code. It's not an apache issue.
daveokeeffe
Forum Newbie
Posts: 5
Joined: Tue Jun 26, 2007 10:29 am

Post by daveokeeffe »

Maybe I don't know what an include loop is? Is it where file A includes file B, and then file B includes file A? Well that definitely does not happen in my code.

I just searched through my script, and there is only one while loop in the entire script, and it controls a http retry that isn't even executed in the case of the failure being described now.

The problem is not caused by an infinite loop in my code, and the problem is not caused by an include loop. Something happens on the server (be it inside apache or not) that makes my script execute multiple times. It is NOT inside my code. In fact, it is impossible for it to be inside my code as the thousands of email logs all contain different timestamps. The different timestamps tell me that each log is from a different execution.
User avatar
feyd
Neighborhood Spidermoddy
Posts: 31559
Joined: Mon Mar 29, 2004 3:24 pm
Location: Bothell, Washington, USA

Post by feyd »

Post the code and we can judge for ourselves if it is a code problem.
User avatar
onion2k
Jedi Mod
Posts: 5263
Joined: Tue Dec 21, 2004 5:03 pm
Location: usrlab.com

Post by onion2k »

Sounds more like a problem with the mail server repeating the same outgoing emails than an Apache issue to me. What do the mail logs say?
daveokeeffe
Forum Newbie
Posts: 5
Joined: Tue Jun 26, 2007 10:29 am

Post by daveokeeffe »

feyd, I will post the code, just can't do it right now. onion2k, I don't think it's a problem with the mail system as every email log is different. Basic content is the same, but the timestamps (output by the php script itself) differ by 1-3 seconds in each mail.
Post Reply