App Engine task failed for no apparent reason (on the development server)

Posted by

So I ran into an interesting issue with App Engine task queues today. They would fail for no apparent reason, without even executing any of my code (but on the development server only). In the log, I would see the following:

WARNING  2012-05-07 11:56:25,644 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.100 seconds
WARNING  2012-05-07 11:56:25,746 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.200 seconds
WARNING  2012-05-07 11:56:25,947 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.400 seconds
WARNING  2012-05-07 11:56:25,644 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.100 seconds
WARNING  2012-05-07 11:56:25,746 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.200 seconds
WARNING  2012-05-07 11:56:25,947 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.400 seconds

I was a little confused, so I had a look in taskqueue_stub.py around line 1936. I could see basically all it was doing was connecting to my URL and issuing a GET just like I had configured it to. On a whim, I added an extra line of logging so that it now output the following:

WARNING  2012-05-07 11:56:25,643 taskqueue_stub.py:1828] Connecting to: 192.168.1.4 (default host is 0.0.0.0:8271)
WARNING  2012-05-07 11:56:25,644 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.100 seconds
WARNING  2012-05-07 11:56:25,745 taskqueue_stub.py:1828] Connecting to: 192.168.1.4 (default host is 0.0.0.0:8271)
WARNING  2012-05-07 11:56:25,746 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.200 seconds
WARNING  2012-05-07 11:56:25,946 taskqueue_stub.py:1828] Connecting to: 192.168.1.4 (default host is 0.0.0.0:8271)
WARNING  2012-05-07 11:56:25,947 taskqueue_stub.py:1936] Task task1 failed to execute. This task will retry in 0.400 seconds

Here, the "default host" is what I specified in the command-line for the development server to listen on (all IPs, port 8271). However, 192.168.1.4 is my machine's IP address -- but note there's no port specified. It would try to connect to port 80!

I couldn't figure out why until I looked at the code I was calling that was enqueueing the task to begin with. It's an Android app, and it uses HttpCore to manage the HTTP requests it makes to my App Engine app (I'm thinking of switching to the built-in URLConnection after all, but we'll see...) and the code has the following lines:

// This is paraphrasing slightly
String requestUrl = uri.getPath();
if (uri.getQuery() != null && uri.getQuery() != "") {
    requestUrl += "?"+uri.getQuery();
}

BasicHttpRequest request = new BasicHttpRequest(method, requestUrl)
request.addHeader("Host", uri.getHost());
// ...

You might see the problem already...

The problem is, we were setting the "Host" header to 192.168.1.4 (no port number!) and the task library was then using the Host header we supplied to know which host to connect to in order to execute the task.

The solution is actually simple:

String host = uri.getHost();
if ((uri.getScheme().equals("http") && uri.getPort() != 80) ||
        (uri.getScheme().equals("https") && uri.getPort() != 443)) {
    host += ":"+uri.getPort();
}
request.addHeader("Host", host);

Basically, if we're using the default HTTP or HTTPS port, don't include it in the Host field. Otherwise, make sure the port number is included.

This would never be a problem if you were executing tasks from a browser (or using a more high-level library that auto-populated the Host header for me!) so it's understandable that I couldn't really find any other people having this problem. Maybe I should just switch to using URLConnection

blog comments powered by Disqus