why is my single jquery .ajax GET call showing up multiple times in apache log?

Question

I am having a problem where my single call to .ajax is being repeated every 60 seconds until the remote side returns. As I write out my problem this way it makes me think of some kind of long-response call - but I have not done anything to set that up or request it.

My app runs on Linux, served by Apache and calls a CGI script hosted locally by the same Apache server. That CGI script makes a backend call and returns only after the backend call finishes. Lately that remote server has been occasionally taking many minutes instead of several seconds to return.

My webapp logging shows one call, and my Apache access_log shows that call repeating every 60 seconds. So I make a single GET request to the CGI script and the Apache log shows that request repeating every 60 seconds for however long it takes for the backend to return.

And because the cgi is getting called over and over again I have been making multiple requests to the remote service, which is very bad.

What is going on?

relevant javascript snippet

let call = {
  callName: 'AddWithFulfillment',
  cardholder: 'cardholderRecord',
  cardholderHash: 'cardholderHash',
  transactionNumber: 6206419,
};

console.log(new Date().toString(), 'call:', JSON.stringify(call));
$.ajax({
  data: {
    task: JSON.stringify(call)
  },
  url: '/cgi-bin/makeCall.sh',
  dataType: 'json',
  cache: false
}).then(
  function success(data, textStatus, jqXHR) {
    console.log(new Date().toString(), 'success:', JSON.stringify(data));
  },
  function fail(jqXHR, textStatus, errorThrown) {
    console.log(new Date().toString(), 'fail:', errorThrown.message, JSON.stringify(data));
  }
);

relevant bash script

#!/bin/bash
# extract the task from the query string into a workfile
q_str=$(echo -e ${QUERY_STRING//%/\\x} | sed 's/+/ /g')
task=$(echo "$q_str" | sed -n 's/^.*task=\([^&]*\).*$/\1/p' | sed "s/%20/ /g")
echo "${task}" > /tmp/workfile.txt 
rm -f /tmp/workfile.result 
touch /tmp/workfile.result

# wait for the result file, dump it into stdout & exit
while [[ 1 ]] ; do
    if [[ -s /tmp/workfile.result ]] ; then
        echo -e $(cat /tmp/workfile.result)
        exit 0
    fi
    sleep 1
done
exit 1

representative console log

"Sun Oct 15 2017 13:13:56 GMT-0400 (EDT)" call: {"callName":"AddWithFulfillment","cardholder":" <...omitted...> ","transactionNumber":6206419}
"Sun Oct 15 2017 14:07:30 GMT-0400 (EDT)" success: {"callName":"AddWithFulfillment","cardholder":" <...omitted...> ","transactionNumber":6206419, "resultId": -1}

actual access_log

127.0.0.1 - - [15/Oct/2017:13:56:24 -0400] "GET /cgi-bin/logger.sh?txt1=%22calling.addWithFufilment+sending%3A%22%2C%22%7B%5C%22isProdCall%5C%22%3Atrue%2C%5C%22deviceAlias%5C%22%3A%5C%22JS-0589.1%5C%22%2C%5C%22callName%5C%22%3A%5C%22AddWithFulfillment%5C%22%2C%5C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%5C%22%3A6206419%7D%22&_=1508040892538 HTTP/1.1" 200 20 "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:13:56:24 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:13:57:24 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:13:58:24 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:13:59:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:00:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:01:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:02:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:03:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:04:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:05:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:06:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 - "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:07:25 -0400] "GET /cgi-bin/makeCall.sh?task=%7B%22isProdCall%22%3Atrue%2C%22deviceAlias%22%3A%22JS-0589.1%22%2C%22callName%22%3A%22AddWithFulfillment%22%2C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> TransactionNumber%22%3A6206419%7D&_=1508040892539 HTTP/1.1" 200 242 "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"
127.0.0.1 - - [15/Oct/2017:14:07:30 -0400] "GET /cgi-bin/logger.sh?txt1=%22recording.addWithFufilment+params%22%2C%22%7B%5C%22isProdCall%5C%22%3Atrue%2C%5C%22deviceAlias%5C%22%3A%5C%22JS-0589.1%5C%22%2C%5C%22callName%5C%22%3A%5C%22AddWithFulfillment%5C%22%2C%5C%22cardholder%5C%22%3A%7B%5C%22 <...omitted...> resultId%5C%22%3A-1%2C%5C%22TransactionNumber%5C%22%3A6206419%7D%22&_=1508040897606 HTTP/1.1" 200 20 "http://localhost/enrollment/" "Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.130 Safari/537.36"

Could it be your bash script making those additional http requests? — James, Oct 24 '17 at 13:42
But how would actions of the bash script show up as requests in the apache log? It really feels like jQuery is "helping" me somehow... And they are so nearly a perfect minute apart. And they are all identical until the remote system returns or times out so that my bash script can complete. I find it hard to believe that Apache is resubmitting it, Apache has a gazillion run-hours on it -- someone would have mentioned it. — Al Joslin, Oct 24 '17 at 14:06
Do you see these once-a-minute requests in the browser developer tools network tab? — James, Oct 24 '17 at 16:12
I can't run a debugger in the actual fielded units (see comment to answer 1) so I've been trying to simulate the long response in my dev environs, but to no avail (I don't run apache in dev.) I'm hoping to pick up a [returned] fielded uint on Thursday to give me an actual production unit to test with. — Al Joslin, Oct 24 '17 at 16:59

score 0 · Answer 1 · answered Oct 24 '17 at 14:22

0

Considering the Apache log is not lying, your browser is repeating that request for sure. Even if we consider that jQuery is configured with a timeout via $.ajaxSetup() (because I can see from your code that $.ajax() is not), jQuery does not automatically retry failed requests AFAIK. So maybe your browser is refreshing the page at every 60 seconds for some reason™, making the ajax request happen again? Maybe some browser plugin is refreshing your page, I don't know.

Anyway, I will propose a different approach to this problem: do not rely on long AJAX calls, as it will probably not work well across different browsers. I heard that IE, for instance, times out after 60 seconds. The best approach is probably to immediatelly return a response saying that the work has been scheduled for processing. The client would then regularly poll that same endpoint, this time passing some request id, and the server would reply back immediatelly, either informing that the processing is still pending or return the result if it's complete. Makes sense?

answered Oct 24 '17 at 14:22

Lucio Paiva

19,015
11
82
104

In this case I am fortunate in saying that there are no other browsers. This is a linux kiosk, so it is running apache which is serving (only to itself) the webpage viewed using google chrome (w/the app flag) which is running in X and displayed on a touchscreen. Unfortunately it's all within the customer network in physically distant states so I can't run any debuggers nor communicate with the actual remote service. I didn't use ajaxSetup() so I expected to get failure at the 120 second mark (I thought that was the default) but I don't see that either. – Al Joslin Oct 24 '17 at 16:51
I see. Well, jQuery does not document what's the default timeout period. I guess it is zero, meaning it won't. Since you don't have easy access to the machine, I guess there's something there that you don't know of and it's making the page refresh once every minute. That's another good reason for implementing a polling system instead, like the one proposed above. In case something refreshes the page, you will still be able to keep track of the request state by periodically checking it. It will be more resilient. – Lucio Paiva Oct 24 '17 at 17:57
Moreover, if some network hop goes down and that machine loses connectivity, you won't notice it, since the AJAX connection is not timing out. Yet another reason for polling. You could, of course, implement some more complex mechanism (for instance, using web sockets), but I think polling will do just fine. – Lucio Paiva Oct 24 '17 at 17:58
This bug has been found on the eve of acceptance of a complete rewrite of the kiosk software (which I rushed to finish in February, and is just now close to being approved.) The new software uses MQTT messaging to talk from the webapp to the [local] backend so that will remove this problem. I wrote this old code almost 3 years ago, it's such a mess and it might be hard to rework it. I'm going to try also to see what adding a timeout adds to the system. I don't think anything is refreshing the page as nothing is showing up in the console log, and there would be a lot... – Al Joslin Oct 24 '17 at 18:14

why is my single jquery .ajax GET call showing up multiple times in apache log?

1 Answers1