2

I am using Apache/2.2.15 (Unix). On a specific project (using php 5.3) the logs display a request (POST from a complicated form) long time after the request was performed (40-50 minutes).

Sometimes the request times out; sometimes (as the user claims) it goes on normally. But I cannot explain the large time shift between the time of the request being made and the time it is logged.

Do you have any ideas why is this occurring? Have you ever noticed something similar?

Some log lines below:

[12/Oct/2015:11:32:01 -0500] "GET /adm/manageCompanies.php....  
[12/Oct/2015:11:32:04 -0500] "GET /adm/manageCompanies.php....  
[12/Oct/2015:**10:25:00** -0500] "POST /adm/manageCompanies.ph....  
[12/Oct/2015:11:32:04 -0500] "GET /adm/manageCompanies.php....  
[12/Oct/2015:11:32:08 -0500] "GET /adm/manageCompanies.php....  

The line with time in bold is the problem - it is logged completely out of sequence...

One more example below:

[13/Oct/2015:08:18:05 -0500] "POST /adm/manageCompanies.php....  
[13/Oct/2015:08:18:05 -0500] "GET /adm/manageCompanies.php ....  
[13/Oct/2015:08:22:53 -0500] "GET /adm/manageCompanies.php ....  
[13/Oct/2015:**07:37:37** -0500] "POST /adm/manageCompanies.php....  
[13/Oct/2015:08:32:48 -0500] "GET /adm/manageCompanies.php ....  
[13/Oct/2015:08:32:50 -0500] "GET /adm/manageCompanies.php ....  

How can I track down the cause for this issue? It is not a matter of logging, but the submitted form times out and causes "damage".

0

This time is the time Apache has receive the request.

Apache writes to logs after completion of the request.

You can check in the server status which requests are too long, and when you got one, take his PID.

Then you can strace this process to see what it is dooing :

strace -t -tt -p PID

lsof can then help you to see what is at the end of a file descriptor id (connection to a database, a webservice ...)

| improve this answer | |
0

I usually enable the request duration logging, see %D here:

http://httpd.apache.org/docs/2.2/mod/mod_log_config.html

It prints the time in microseconds required to satisfy a request. This way you can easily find which scrpits are the slowest.

That said, in your case i would start debugging the manageCompanies.php script, maybe adding some echo's or print_r's to some file in "strategic" peaces of the script, starting with the part that handles the POST method, before and after loops and eventual DB queries, writing a timestamp and for exxample "Begin loop foo / end loop foo", hope you got the idea.

| improve this answer | |
  • I am not concerned about this particular script behavior. It is accessed thousands of times daily. This problem occurs only from time to time (like weekly); I was able to insulate it down to a specific user - only he triggers this kind of problems. I will add the duration logging parameter, see if I can find anything else. I was hoping to find something about "ghost requests" or similar. – Liviu Nov 6 '15 at 14:30

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.