Alex_Bender Alex_Bender - 1 year ago 58
Python Question

Google App Engine request logs are duplicated with small time difference

Looking into GAE logs of a Python project I found out some amount of duplicated or even triplicated entries with very small difference in their timestamps.

These are the requests triggered by an iPhone device which sends only unique data, so it seems extremely unlikely that this duplication comes from the phone. Especially if you take into account the differences in time between the requests.

00:53:32.139 POST 200 93B 1.6 s APPNAME/1.2 CFNetwork/758.4.3 Darwin/15.5.0 /logData
00:53:32.142 POST 200 93B 930 ms APPNAME/1.2 CFNetwork/758.4.3 Darwin/15.5.0 /logData
00:53:32.279 POST 200 93B 835 ms APPNAME/1.2 CFNetwork/758.4.3 Darwin/15.5.0 /logData

Requests are the same (source ip, headers and so on) with the equal data inside:

{u'version': 1.2, u'data': u'some data', u'user': u'0a9b....0a57'}

And the actual question is "How is that possible"?

Could there be an explanation of such short intervals between duplicated logs?

Answer Source

It happened because of asynchronous tasks: When the iPhone gets a location from its location manager, and when the OS has some free time to run our code, then the application fires an HTTP request to the /logData endpoint. At the same time user activity causes one more HTTP request. Data from local variables will be removed only after the acknowledgment that data is received (HTTP response 200). So as they were triggered almost simultaneously -- both of them got into database and to the GAE logs.