PHP Script randomly restarts itself with blank post data

[holdorfold]

I've managed to isolate a problem I'm having with my php script. It would seem the script randomly restarts itself with blank post data while it's running.

I've managed to mimick the problem using a very basic php script which just pauses and writes to a log:

<?php

$q = $_POST['q'];

if ($q==""){
  writelog ("MISFIRE!!!");
  die;
}

writelog("\n*** Error check started ***");

for ($i = 1; $i <= 50; $i++) {
   writelog ($i);
     sleep(rand(2,20));
}

 function writelog($towrite)
{
  $tdate=date('d/m/Y H:i:s');
  $file = 'log/testlog.txt';
  $current = $towrite." --- ".$tdate."\n";
  file_put_contents($file, $current, FILE_APPEND);
}

writelog("*** Error check ended ***");
?>

To rule out any problems with my AJAX htmlhttp requests, I simply send the script some irrelevant post data using Chrome's Advanced Restful client.

This is the ouput of the log from an example test run:

*** Error check started *** --- 05/06/2014 18:27:30

1 --- 05/06/2014 18:27:30
2 --- 05/06/2014 18:27:44
3 --- 05/06/2014 18:27:49
4 --- 05/06/2014 18:27:59
5 --- 05/06/2014 18:28:04
6 --- 05/06/2014 18:28:22
7 --- 05/06/2014 18:28:33
8 --- 05/06/2014 18:28:39
9 --- 05/06/2014 18:28:52
10 --- 05/06/2014 18:29:08
11 --- 05/06/2014 18:29:22
12 --- 05/06/2014 18:29:30
13 --- 05/06/2014 18:29:43
MISFIRE!!! --- 05/06/2014 18:29:46
14 --- 05/06/2014 18:29:56
15 --- 05/06/2014 18:30:07
16 --- 05/06/2014 18:30:09
17 --- 05/06/2014 18:30:15
18 --- 05/06/2014 18:30:32
19 --- 05/06/2014 18:30:52
20 --- 05/06/2014 18:30:54

Note the logged "Misfire" after the 13th entry.  This shows the script tried to run again with blank post data, the same problem I'm having in my more complex script.

Why could this be happening? It's not anyone else calling the script, nobody knows about the site and I've ruled it out by logging the IP in my real script.

Edited June 5, 2014 by holdorfold

[Psycho]

Are you sure no one else is accessing it? There are bots out there (both benign and malicious) that will find pages. You could add some data to that logging to include the IP address. Not saying that is it, but it would help. In fact, I would have that script output a lot of other details such as the POST/GET data, etc. Then you can review the log to see exactly what is happening.

 

It looks to me it is being called separately from the one instance that is running the loop.

[mac_gyver]

also log the user agent to get the browser/search engine info being put into the request

[holdorfold]

Ok I've just tested with the IP logged and post data, and it shows it's coming from my IP:
 

IP Logged: 86.31.**.99 --- 05/06/2014 19:42:46Post data: foobar --- 05/06/2014 19:42:46*** Error check started *** --- 05/06/2014 19:42:461 --- 05/06/2014 19:42:462 --- 05/06/2014 19:42:553 --- 05/06/2014 19:43:014 --- 05/06/2014 19:43:115 --- 05/06/2014 19:43:256 --- 05/06/2014 19:43:337 --- 05/06/2014 19:43:518 --- 05/06/2014 19:44:099 --- 05/06/2014 19:44:1310 --- 05/06/2014 19:44:2311 --- 05/06/2014 19:44:4212 --- 05/06/2014 19:44:49IP Logged: 86.31.**.99 --- 05/06/2014 19:45:02Post data:  --- 05/06/2014 19:45:02MISFIRE!!! --- 05/06/2014 19:45:0213 --- 05/06/2014 19:45:0714 --- 05/06/2014 19:45:2415 --- 05/06/2014 19:45:3916 --- 05/06/2014 19:45:55Updated script:[code]<?php$q = $_POST['q'];$ip = $_SERVER['REMOTE_ADDR'];writelog("IP Logged: ".$ip);writelog("Post data: " . $q);if ($q==""){  writelog ("MISFIRE!!!");  die;}writelog("\n*** Error check started ***");for ($i = 1; $i <= 50; $i++) {   writelog ($i);     sleep(rand(2,20));} function writelog($towrite){  $tdate=date('d/m/Y H:i:s');  $file = 'log/testlog.txt';  $current = $towrite." --- ".$tdate."\n";  file_put_contents($file, $current, FILE_APPEND);}writelog("*** Error check ended ***");?>[/code]

[holdorfold]

Ok, I'm logging the user agent with: $agent = $_SERVER['HTTP_USER_AGENT'];


And I got this on a test run (error after 12th entry):
 

IP Logged: 86.31.**.99 --- 05/06/2014 19:56:22User agent: Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/35.0.1916.114 Safari/537.36 --- 05/06/2014 19:56:22Post data: foobar --- 05/06/2014 19:56:22*** Error check started *** --- 05/06/2014 19:56:221 --- 05/06/2014 19:56:222 --- 05/06/2014 19:56:393 --- 05/06/2014 19:56:544 --- 05/06/2014 19:57:125 --- 05/06/2014 19:57:196 --- 05/06/2014 19:57:327 --- 05/06/2014 19:57:448 --- 05/06/2014 19:57:569 --- 05/06/2014 19:57:5910 --- 05/06/2014 19:58:0211 --- 05/06/2014 19:58:1312 --- 05/06/2014 19:58:26IP Logged: 86.31.**.99 --- 05/06/2014 19:58:38User agent: Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/35.0.1916.114 Safari/537.36 --- 05/06/2014 19:58:38Post data:  --- 05/06/2014 19:58:38MISFIRE!!! --- 05/06/2014 19:58:3813 --- 05/06/2014 19:58:4014 --- 05/06/2014 19:58:5515 --- 05/06/2014 19:59:04

Edited June 5, 2014 by holdorfold

[mac_gyver]

your symptom is (most likely) due to the browser making a get request to the code. in each case that you have posted, it is about 2-3 seconds after the first request.

 

your post data processing code isn't testing either if a method = 'post' request was made to it or if the post variable is set before referencing the value in it. i'm betting if php error_reporting was on and log_errors was on that $_POST['q'] is throwing undefined index errors when the second request is made and that $_SERVER['REQUEST_METHOD'] is GET for those second requests.

 

if so, this is either something your browser is doing (browser debuggers have a habit of doing this), something your client code is doing, or something your server is doing.

[holdorfold]

OK thanks, I'll have to look into this. I'm pretty sure it is something the server is doing because I was hosting my original script on a different host and I wasn't having the exact same issue. Also the problem happens in different browser including a restful client.

 

What could the server possibly be doing, (just so I have a vague idea if what to look for)? Thanks

 

(Note I use shared hosting)

Edited June 5, 2014 by holdorfold

[holdorfold]

By the way, I've logged the $_SERVER['REQUEST_METHOD'] and the second request is always GET, you're right.

[mac_gyver]

let me correct something i wrote above, the second request is occurring 2-3 minutes after the first one. but the fact remains you are receiving a get request that's fairly consistently timed after your original post request.
 
have you done what Psycho suggested so that you know what is in the get request -
 

In fact, I would have that script output a lot of other details such as the POST/GET data, etc. Then you can review the log to see exactly what is happening.

 

because the request contains the user agent, this is probably actually coming from the browser. is this test page you are showing us the same url as the main (or only) page that was requested by the browser? it seems to be some sort of keep-alive ping.

 

in any case, after you have determined what the get request contains, you may not have any control over it. if the overall all problem is that this get request is interfering with your ongoing processing of the post request (what exactly are you doing that requires that?) the solution is for your php code that's responsible for servicing the post request to actually test for and only respond to post requests (i mentioned two ways of doing this in post #6.)

 

 

 

[holdorfold]

I logged the contents of the GET request which ends up being just an empty array.

The main PHP script receives parsed POST data from my javascript application, processes it and then when it's finished the AJAX sends the next packet... and so on. But these stray GET requests interrupt the AJAX which receives a blank response in the middle of the processing instead of the response from the POST request when it's finished and so it doesn't send the next packet and doesn't know when the previoius packet is finished processing because of the interruption.

The strange thing is that this was all working on a different server as I made the application for a friend. But when I copied it to my server so I could use the app myself  I get these GET requests so it doesn't work.

I just had a look at your post 6, and I'm still not sure how to ignore GET requests? In my code I make the script die if the data sent to it is blank, but that's not working. Sorry I'm a bit of a newb, how would I make it so the script completely ignores GET requests?

Edited June 9, 2014 by holdorfold

[mac_gyver]

the empty get data means that the browser isn't placing any query string parameters on the end of the url, but it is making a get request to the same url that was used by the ajax call. is the url of the main page and the url used in the ajax call the same page/url? you didn't exactly clarify if it is. the reason i asked if this url is the same as for the main page, is that when browsers re-request pages due to debuggers/character set encoding differences (two of the reasons i know they do this) they request the page they are on, which would be the main page's url. if the url that your ajax is requesting is different from the main page, this problem likely won't occur.

 

actually, your die() statement when the post data is empty and what i am suggesting of testing for a post request will result in the same symptom, as both will cause an empty http 200 ok response to be sent back to the browser.

 

beyond the url being the same or different for the main page and the ajax page, at this point we would probably need your client side code in order to fully see what it is doing and to try and reproduce the problem.

Edited June 9, 2014 by mac_gyver

[holdorfold]

Thanks, the URL of the javascript client is different than the php script which the AJAX calls (I think that's what you're asking).

 

But I must stress that I'm using the Chrome Restful Client to debug what's going on to eliminate any javascript being the issue. The problem happens the same using either my client or the Restful Client.

To try and fix the issue, I recently tried to change the .htaccess file to not allow any GET requests in the directory that the php script is in. It works in that it won't run the script for the GET request, but the Restful Client still gets a response. In this case the response is the entire HTML of the frontpage of my wordpress website which I guess has something to do with wordpress' error handling or something... but the problem is that it still gets a response.

It's weird that it seems the restful client is even sending GET requests though right? Otherwise it shouldn't receive any responses surely.

 

This is the javascript though if it's still relevant:

function SendPHP(str, callback){

str = "q=" + encodeURIComponent(str);


$.ajax({
    type: "POST",
    url: "test/errortest.php",
    data: str,
    contentType: "application/x-www-form-urlencoded",
    success: function(msg) {
        callback(msg);
    },
    error: function(err) {
        alert(err.toString());
        if (err.status == 200) {
            callback(err);
        }
        else { alert('Error:' + err.responseText + '  Status: ' + err.status); }
    }
});

}

  Edited June 9, 2014 by holdorfold

[Psycho]

While this is an odd issue, how much time are you wanting to invest into understanding it rather than just fixing the problem. In fact, this is something you should plan for anyway. If the URL is accessible through AJAX then anyone could try and access it with other data or no data. Your script should prevent errors in those conditions anyway.

 

Why not just exit the script if the POST data you are expecting isn't present:

if(!isset($POST['q']))
{
    exit();
}

Edited June 9, 2014 by Psycho

[holdorfold]

That was pretty much one of the first things I tried, the script already dies when post data is blank. Pretty much the same thing, no?

The problem is not so much the script running but that a response is sent to the client from the stray request (whether that be my javascript client or the restful client). I'm not really concerned about other people running it as long as I don't get a response on my client from their request.  

Edited June 9, 2014 by holdorfold

[Psycho]

Then add logic to the client-side to handle scenarios where unanticipated return values are appropriately handled. I always try to code processes such as this to elegantly handle scenarios where unanticipated data is returned.

[holdorfold]

By receiving the response from the GET request it seems to close the AJAX connection so it doesn't receive the response from the POST request. Yeah I suppose I'll have to figure out how to fix that.

[holdorfold]

Ok, so I'm trying to rack my head around how I can change my AJAX as in post 11 to make it so it will still receive the response from the POST data after receiving the GET response.

I'm not sure how could this be done, do you know how I could do it?

[Psycho]

I've run some tests and cannot even force the problem you are describing. Using the JS function you provided above, I modified it to simply echo the returned value from the AJAX call. I then created the PHP page called by the AJAX request as follows:

 

 

if($_POST['q'])
{
    sleep(10);
    echo "TRUE";
}
else
{
    echo "FALSE";
}

 

I then loaded the AJAX page and clicked a button to call the function passing a POST value for 'q'. Then, before the 10 seconds expired, on a separate tab I made a browser request directly to the PHP page. That page displayed a 'FALSE'. I then went back to the original tab and when the 10 second sleep expired I saw "TRUE" alerted on the page. In other words, I couldn't hijack the original POST request by making a separate request to the same page in a different browser tab.

 

I also ran a test where I called the same SendPHP() function with two different buttons. One would call the PHP with a 'q' post value and the other would call it without. If I clicked the one with the 'q' value first and then the one without, I would first get the FALSE response (since there is no delay for that) and then I would get the one with the TRUE response after the 10 seconds.

 

What this tells me is that a second request to the same page that occurs after the first request will not prevent the response for the first request. So, as a workaround, have the PHP page simple return an empty result if there is no 'q' in the POST data and change the AJAX success parameter to test for a return value. If empty - do nothing.

 

 

       success: function(msg) {
            if(!msg){ return; }
            callback(msg);
        },

 

However, I think the problem is as mac_gyver alluded to and there is something on your PC that is doing this. The server can't make the client initiate a request. Have you tried this on a separate PC?

[holdorfold]

I tried changing the success function and it just does nothing instead and doesn't receive the second response. The problem still occurs when I tested it on my friend's laptop.

Interestingly though, I tried deleting wordpress and now the script functions differently and throws an error when I run the test.

Before the script would startup mid processing and then log "misfire" to the log as in post 15 etc... now that I've uninstalled wordpress, the script no longer logs the misfire but instead I get the following error returned to the client around the same time that it used to send the GET request (I'm using the restful client):
 

Status

500 Internal Server Error Loading time: 45612

Request headers 

User-Agent: Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/35.0.1916.114 Safari/537.36

Origin: chrome-extension://hgmloofddffdnphfgcellkdfbfbjeloo

Content-Type: application/x-www-form-urlencoded 

Accept: */*

Accept-Encoding: gzip,deflate,sdch

Accept-Language: en-GB,en-US;q=0.8,en;q=0.6

Response headers 

Date: Tue, 10 Jun 2014 10:54:36 GMT 

Server: Apache 

Connection: close

Content-Type: text/html; charset=iso-8859-1

 

 

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head..>
<title>500 Internal Server Error</title>
</head><body>
<h1>Internal Server Error</h1>
<p>The server encountered an internal error or
misconfiguration and was unable to complete
your request.</p>
<p>Please contact the server administrator,
webmaster@kingstonmarketing.localpowermarketing.co.uk and inform them of the time the error occurred,
and anything you might have done that may have
caused the error.</p>
<p>More information about this error may be available
in the server error log.</p>
<p>Additionally, a 500 Internal Server Error
error was encountered while trying to use an ErrorDocument to handle the request.</p>
</body></html>

 

Edited June 10, 2014 by holdorfold

[Psycho]

 

 

Origin: chrome-extension://hgmloofddffdnphfgcellkdfbfbjeloo

 

That appears to be the Advanced REST client plug-in. Perhaps that is the cause of these mysterious requests.

[holdorfold]

In the end I contacted my hosting provider and had them look at it.

Apparently it's a server timeout, which is odd because the script still runs but you just don't get a response from it. I can't over-ride their settings, I've tried setting max exucution time to no avail, but at least I know what it is now so I've done a workaround for the problem where the script is called for shorter periods of time.

Thanks for your help though Psycho and mac_gyver!