I have a task queue that handles deferred tasks that need to be processed in real time (I have heard this isn't a good idea but can't find any supporting documentation on this.). This queue is hit with an large influx of tasks (2500/min) and then often receives nothing for a minute or two.
queue.yaml
- name: event-message
rate: 200/s
bucket_size: 200
retry_parameters:
task_retry_limit: 2
min_backoff_seconds: 1
What I have noticed is that I often get "Process terminated because the request deadline was exceeded. (Error code 123)" messages for some tasks that aren't even started. The task sits in the queue for 10min without being run and then times out. I thought it may be related to my queue configuration so I have included that here.
2015-06-18 10:22:45.842 /_ah/queue/deferred 500 641080ms 0kb AppEngine-Google; (+http://code.google.com/appengine) module=default version=1-0-21
0.1.0.2 - - [18/Jun/2015:07:22:45 -0700] "POST /_ah/queue/deferred HTTP/1.1" 500 0 "http://*******/_ah/queue/deferred" "AppEngine-Google; (+http://code.google.com/appengine)" "********" ms=641081 cpu_ms=0 queue_name=event-message task_name=0477163503045474472 exit_code=123 app_engine_release=1.9.22 instance=00c61b117c8af1f4df1247032afd14111a19f302
E 2015-06-18 10:22:45.842
Process terminated because the request deadline was exceeded. (Error code 123)
Can anyone explain this? Any ideas how I can figure out why these tasks are never run?
So I was looking at the logs more and found additional support for my theory that the tasks weren't even starting. Here the "This request caused a new process to be started for your application" appears after the task 10min deadline has been reached.
2015-06-24 17:16:59.554 /_ah/queue/deferred 500 641631ms 0kb AppEngine-Google; (+http://code.google.com/appengine) module=default version=1-0-27
0.1.0.2 - - [24/Jun/2015:14:16:59 -0700] "POST /_ah/queue/deferred HTTP/1.1" 500 0 "https://integrate.versature.com/api/netsapiens_events/96615760-cac7-40d6-b80d-13a1ffade2c8/" "AppEngine-Google; (+http://code.google.com/appengine)" "integrate.versature.com" ms=641632 cpu_ms=0 queue_name=event-message task_name=59067488044178506841 pending_ms=1061 exit_code=123 app_engine_release=1.9.22 instance=00c61b117c8f2db4ade6be8d30165cb84f0a17ab
E 2015-06-24 17:16:59.554
Process terminated because the request deadline was exceeded. (Error code 123)
Here is another:
I 2015-06-23 13:48:22.970
X-Appengine-Taskretrycount:0, X-Appengine-Tasketa:1435081701.5576639, X-Appengine-Default-Namespace:versature.com, X-Appengine-Taskname:89115825957976957021, X-Appengine-Taskexecutioncount:0, X-Appengine-Queuename:event-message, X-Appengine-Current-Namespace:, X-Appengine-Country:ZZ
E 2015-06-23 13:58:21.669
Traceback (most recent call last):
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/runtime/wsgi.py", line 267, in Handle
result = handler(dict(self._environ), self._StartResponse)
File "/base/data/home/runtimes/python27/python27_lib/versions/third_party/webapp2-2.3/webapp2.py", line 1505, in __call__
rv = self.router.dispatch(request, response)
File "/base/data/home/runtimes/python27/python27_lib/versions/third_party/webapp2-2.3/webapp2.py", line 1253, in default_dispatcher
return route.handler_adapter(request, response)
File "/base/data/home/runtimes/python27/python27_lib/versions/third_party/webapp2-2.3/webapp2.py", line 1077, in __call__
return handler.dispatch()
File "/base/data/home/runtimes/python27/python27_lib/versions/third_party/webapp2-2.3/webapp2.py", line 545, in dispatch
return method(*args, **kwargs)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/deferred/deferred.py", line 310, in post
self.run_from_request()
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/deferred/deferred.py", line 305, in run_from_request
run(self.request.body)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/deferred/deferred.py", line 147, in run
return func(*args, **kwds)
File "/base/data/home/apps/s~versature-integrate-2/1-0-26.385226646541088482/app/api/resources/constructs/netsapiens_event/process_netsapiens_event.py", line 66, in process_data_for_endpoint
logging.info("Process data for specific endpoint. Endpoint Key: %s", endpoint_key_url_safe)
File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/logging/__init__.py", line 1611, in info
root.info(msg, *args, **kwargs)
File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/logging/__init__.py", line 1149, in info
self._log(INFO, msg, args, **kwargs)
File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/logging/__init__.py", line 1268, in _log
self.handle(record)
File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/logging/__init__.py", line 1278, in handle
self.callHandlers(record)
File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/logging/__init__.py", line 1318, in callHandlers
hdlr.handle(record)
File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/logging/__init__.py", line 749, in handle
self.emit(record)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/app_logging.py", line 79, in emit
self._AppLogsLocation())
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/logservice/logservice.py", line 457, in write_record
logs_buffer().write_record(level, created, message, source_location)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/logservice/logservice.py", line 270, in write_record
message = cleanup_message(message)
DeadlineExceededError
I 2015-06-23 13:58:21.684
This request caused a new process to be started for your application, and thus caused your application code to be loaded for the first time. This request may thus take longer and use more CPU than a typical request for your application.