Uncaught 'TimerItem' object has no attribute 'json' exception sometimes stops Depicted

[cloudspeech]

After running for some time, our depicted installation stops throwing the following exception:

INFO queue_worker.py:205] Fetching 1 tasks from queue_url='http://localhost:5000/api/work_queue/capture' for workflow=<class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>
INFO _internal.py:119] 127.0.0.1 - - [31/Oct/2013 05:58:42] "POST /api/work_queue/capture/lease HTTP/1.1" 200 -
ERROR workers.py:436] WorkflowThread:-1244660928 error item=dpxdt.client.timer_worker.TimerItem({ready_time: 1383195523.093645, delay_seconds: 2, done: True})
Traceback (most recent call last):
File "/home/ubuntu/dpxdt/dpxdt/client/workers.py", line 428, in handle_item
next_item = generator.send(item)
File "/home/ubuntu/dpxdt/dpxdt/client/queue_worker.py", line 217, in run
if next_item.json:
AttributeError: 'TimerItem' object has no attribute 'json'

[bslatkin]

Thanks for the report. This indicates some kind of issue in the core workers library about which pending task to reinject into a generator. I'll look into it.

[bslatkin]

I haven't heard any reports of this since, so I'm going to close for now. Please reopen if you see it again!

[olivierbouwman]

Hi Brett,

First of all, thanks for this great testing tool, I've been trying it out for a couple projects and am really liking it so far. A very similar error has popped up for me a number of times, the log messages are pasted below. Any recommendations on things I can try to fix this? Thanks!

INFO queue_worker.py:205] Fetching 5 tasks from queue_url='http://localhost:5000/api/work_queue/capture' for workflow=<class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>
DEBUG workers.py:119] WorkflowThread:139688586147584 processed item=dpxdt.client.timer_worker.TimerItem({ready_time: 1426867506.64173, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker...4})#139688107424464
INFO _internal.py:119] 127.0.0.1 - - [20/Mar/2015 16:05:06] "POST /api/work_queue/capture/lease HTTP/1.1" 200 -
DEBUG fetch_worker.py:165] Rate limiting URL fetch for 0.990205 seconds
DEBUG workers.py:439] Sending workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>), root: True, kwargs: {max_tasks: 5, wait_seconds: 3}})#39746704 finished item=dpxdt.client.timer_worker.TimerItem({ready_time: 1426867507.651917, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker...4})#139688111617040
ERROR workers.py:452] Error in workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>), root: True, kwargs: {max_tasks: 5, wait_seconds: 3}})#39746704 from item=dpxdt.client.timer_worker.TimerItem({ready_time: 1426867507.651917, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker...4})#139688111617040, error=None
Traceback (most recent call last):
File "/usr/local/lib/dpxdt/dpxdt/client/workers.py", line 440, in handle_item
next_item = generator.send(item)
File "/usr/local/lib/dpxdt/dpxdt/client/queue_worker.py", line 217, in run
if next_item.json:
AttributeError: 'TimerItem' object has no attribute 'json'
DEBUG workers.py:119] FetchThread:139688602932992 processed item=dpxdt.client.fetch_worker.FetchItem({username: None, result_path: None, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow({done: True, args: ('capture', <class 'dpxdt.client.ca...4, url: 'http://localhost:5000/api/work_queue/capture/lease', status_code: 200, timeout_seconds: 30, headers: <httplib.HTTPMessage instance at 0x7f0bac26d680>, post: {count: 5}, password: None, data: '{\n "tasks": []\n}', _data_json: None})#139688111576016
DEBUG workers.py:119] WorkflowThread:139688586147584 processed item=dpxdt.client.timer_worker.TimerItem({ready_time: 1426867507.651917, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow({done: True, args: ('capture', <class 'dpxdt.client.ca...4})#139688111617040
DEBUG workers.py:439] Sending workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({done: True, args: ('capture', <class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>), root: True, error: (<type 'exceptions.AttributeError'>, AttributeError("'TimerItem' object has no attribute 'json'",), ...), kwargs: {max_tasks: 5, wait_seconds: 3}})#39746704 finished item=dpxdt.client.fetch_worker.FetchItem({username: None, result_path: None, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow({done: True, args: ('capture', <class 'dpxdt.client.ca...4, url: 'http://localhost:5000/api/work_queue/capture/lease', status_code: 200, timeout_seconds: 30, headers: <httplib.HTTPMessage instance at 0x7f0bac26d680>, done: True, post: {count: 5}, password: None, data: '{\n "tasks": []\n}', _data_json: None})#139688111576016
DEBUG workers.py:442] Exhausted workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({done: True, args: ('capture', <class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>), root: True, error: (<type 'exceptions.AttributeError'>, AttributeError("'TimerItem' object has no attribute 'json'",), ...), kwargs: {max_tasks: 5, wait_seconds: 3}})#39746704
DEBUG workers.py:119] WorkflowThread:139688586147584 processed item=dpxdt.client.fetch_worker.FetchItem({username: None, result_path: None, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow({done: True, args: ('capture', <class 'dpxdt.client.ca...4, url: 'http://localhost:5000/api/work_queue/capture/lease', status_code: 200, timeout_seconds: 30, headers: <httplib.HTTPMessage instance at 0x7f0bac26d680>, done: True, post: {count: 5}, password: None, data: '{\n "tasks": []\n}', _data_json: None})#139688111576016

[bslatkin]

Thanks for more info

[dmg3]

I love the idea of this project and am excited about trying to use where I work. During my evaluation though, I'm also receiving the first error mentioned in this issue. The issue happens to me after leaving the server running overnight (after about 16 hours of uptime, and no usage of the server at all during that time). It is just using the sql lite db, and while running in a docker container I created. If you want to import it into a docker instance, I have it my dropbox account: https://www.dropbox.com/s/vmfjo2rgpxbgtl1/dpxdt.tar?dl=0
Then:

1. docker load < dpxdt.tar to import the image
2. docker run -d -P asg/dpxdt
   My Dockerfile to create it is here: https://www.dropbox.com/s/j96lxgykerts8sl/Dockerfile?dl=0

The exception I am getting is here:
ERROR workers.py:476] Error in workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>), root: True, kwargs: {max_tasks: 5, wait_seconds: 3}})#139819610772304 from item=dpxdt.client.timer_worker.TimerItem({ready_time: 1439278674.04146, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow#139819610772304})#139819574073744, error=None
Traceback (most recent call last):
File "/dpxdt/dpxdt/client/workers.py", line 464, in handle_item
next_item = generator.send(item)
File "/dpxdt/dpxdt/client/queue_worker.py", line 220, in run
if next_item.json:
AttributeError: 'TimerItem' object has no attribute 'json'

[bslatkin]

Thanks for the report. Sounds like it's a fundamental bug in the Workflow module. I haven't been able to write a test to reproduce it yet.

[ygravrand]

Same here after dpxdt server being idle for a number of hours. Traceback:

ERROR workers.py:476] Error in workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('run-pdiff', <class 'dpxdt.client.pdiff_worker.DoPdiffQueueWorkflow'>), root: True, kwargs: {max_tasks: 1, wait_seconds: 3}})#140530213227536 from item=dpxdt.client.timer_worker.TimerItem({ready_time: 1441232530.90254, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow#140530213227536})#140530193477328, error=None
Traceback (most recent call last):
  File "/tmp/dpxdt/src/dpxdt/client/workers.py", line 464, in handle_item
    next_item = generator.send(item)
  File "/tmp/dpxdt/src/dpxdt/client/queue_worker.py", line 220, in run
    if next_item.json:
AttributeError: 'TimerItem' object has no attribute 'json'

Seems that a TimerItem has been sent into the generator instead of a FetchItem that we could have expected seeing the yield at line 210.
But isn't it a valid use case since the worker queue seems to accept any WorkItem?
So, could we just ignore these types of WorkItem in that context?
I would suggest to:

• either add a json property to WorkItem returning None
• or test existence of the json attribute with an hasattr call - not so pretty..
• even more explicit, uglier and not so pythonic: isinstance(item, fetch_worker.FetchItem) test

I think a way to reproduce the error would be to inject a TimerItem in the generator. Haven't had time to do that yet.

[elsigh]

I'm getting this exception as well, but it's immediately after a LeaseExpired exception (in case that's helpful info)

[scrofts]

I'm also getting this issue regularly after the server has been running for a few hours:

INFO process_worker.py:62] item=dpxdt.client.pdiff_worker.PdiffWorkflow({parent: dpxdt.client.pdiff_worker.DoPdiffQueueWorkflow#139629591435728, kwargs: {timeout_seconds: 20}, args: ('/tmp/tmpHednsl/log.txt',), output_path: '/tmp/tmpHednsl/diff.png', ref_path: '/tmp/tmpHednsl/ref_resized', run_path: '/tmp/tmpHednsl/run'})#139628914612752 Running subprocess: ['compare', '-verbose', '-metric', 'RMSE', '-highlight-color', 'Red', '-compose', 'Src', '/tmp/tmpHednsl/ref_resized', '/tmp/tmpHednsl/run', '/tmp/tmpHednsl/diff.png']
INFO process_worker.py:82] item=dpxdt.client.pdiff_worker.PdiffWorkflow({parent: dpxdt.client.pdiff_worker.DoPdiffQueueWorkflow#139629591435728, kwargs: {timeout_seconds: 20}, args: ('/tmp/tmpHednsl/log.txt',), output_path: '/tmp/tmpHednsl/diff.png', ref_path: '/tmp/tmpHednsl/ref_resized', run_path: '/tmp/tmpHednsl/run'})#139628914612752 Polling pid=5318
INFO process_worker.py:82] item=dpxdt.client.pdiff_worker.PdiffWorkflow({parent: dpxdt.client.pdiff_worker.DoPdiffQueueWorkflow#139629591435728, kwargs: {timeout_seconds: 20}, args: ('/tmp/tmpHednsl/log.txt',), output_path: '/tmp/tmpHednsl/diff.png', ref_path: '/tmp/tmpHednsl/ref_resized', run_path: '/tmp/tmpHednsl/run'})#139628914612752 Polling pid=5318
INFO process_worker.py:90] item=dpxdt.client.pdiff_worker.PdiffWorkflow({parent: dpxdt.client.pdiff_worker.DoPdiffQueueWorkflow#139629591435728, kwargs: {timeout_seconds: 20}, args: ('/tmp/tmpHednsl/log.txt',), output_path: '/tmp/tmpHednsl/diff.png', ref_path: '/tmp/tmpHednsl/ref_resized', run_path: '/tmp/tmpHednsl/run'})#139628914612752 Subprocess finished pid=5318, returncode=0
ERROR workers.py:476] Error in workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>), root: True, kwargs: {max_tasks: 5, wait_seconds: 3}})#139629637054224 from item=dpxdt.client.timer_worker.TimerItem({ready_time: 1443188988.519612, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow#139629637054224})#139628913510480, error=None
Traceback (most recent call last):
  File "/home/stan/dpxdt/dpxdt/client/workers.py", line 464, in handle_item
    next_item = generator.send(item)
  File "/home/stan/dpxdt/dpxdt/client/queue_worker.py", line 220, in run
    if next_item.json:
AttributeError: 'TimerItem' object has no attribute 'json'
ERROR workers.py:140] FetchThread:140477006534400 error item=dpxdt.client.fetch_worker.FetchItem({username: None, result_path: '/tmp/tmpPcWCbo/run', parent: dpxdt.client.release_worker.DownloadArtifactWorkflow#140476972232464, url: u'http://localhost:5000/api/download?sha1sum=afec0e7e0d75f3120303ee4fb9cf743fb6381882&build_id=3', status_code: None, timeout_seconds: 30, content_type: None, error: (<class 'httplib.BadStatusLine'>, BadStatusLine("''",), <traceback object at 0x7fc358073908>), post: None, password: None, data: None, _data_json: None})#140476972231440
Traceback (most recent call last):
  File "/home/stan/dpxdt/dpxdt/client/workers.py", line 137, in run
    next_item = self.handle_item(item)
  File "/home/stan/dpxdt/dpxdt/client/fetch_worker.py", line 232, in handle_item
    return fetch_normal(item, request)
  File "/home/stan/dpxdt/dpxdt/client/fetch_worker.py", line 166, in fetch_normal
    conn = urllib2.urlopen(request, timeout=item.timeout_seconds)
  File "/opt/python-2.7.7/lib/python2.7/urllib2.py", line 127, in urlopen
    return _opener.open(url, data, timeout)
  File "/opt/python-2.7.7/lib/python2.7/urllib2.py", line 404, in open
    response = self._open(req, data)
  File "/opt/python-2.7.7/lib/python2.7/urllib2.py", line 422, in _open
    '_open', req)
  File "/opt/python-2.7.7/lib/python2.7/urllib2.py", line 382, in _call_chain
    result = func(*args)
  File "/home/stan/dpxdt/lib/python2.7/site-packages/poster/streaminghttp.py", line 142, in http_open
    return self.do_open(StreamingHTTPConnection, req)
  File "/opt/python-2.7.7/lib/python2.7/urllib2.py", line 1187, in do_open
    r = h.getresponse(buffering=True)
  File "/opt/python-2.7.7/lib/python2.7/httplib.py", line 1067, in getresponse
    response.begin()
  File "/opt/python-2.7.7/lib/python2.7/httplib.py", line 409, in begin
    version, status, reason = self._read_status()
  File "/opt/python-2.7.7/lib/python2.7/httplib.py", line 373, in _read_status
    raise BadStatusLine(line)
BadStatusLine: ''

[bslatkin]

I wasn't able to reproduce this in tests, unfortunately. But I think it may have been caused by the looping nature of the old barrier handling code and some timing-dependent race conditions. I think the cause is a barrier gets triggered to finish twice, causing an old result to be returned back to a workflow when it shouldn't have been. In the old loop the dequeue_barrier() call doesn't happen at the bottom of the loop, which could lead to this problem.

I've updated this flow in these changes and gotten rid of the inner loop:

cc97142
520ced4
941f2a6

Now dequeueing barriers should always be consistent. I hope this causes the problem to go away. Please reopen if you see it again!

[scrofts]

I'm still getting what looks like the same error after having left the server running overnight. I have updated and the last commit I have is 1f40122.

ERROR workers.py:504] Error in workflow=dpxdt.client.queue_worker.RemoteQueueWorkflow({args: ('capture', <class 'dpxdt.client.capture_worker.DoCaptureQueueWorkflow'>), root: True, interrupted: False, kwargs: {max_tasks: 5, wait_seconds: 3}})#139715014742544 from item=dpxdt.client.timer_worker.TimerItem({ready_time: 1444193644.233015, delay_seconds: 10, done: True, parent: dpxdt.client.queue_worker.RemoteQueueWorkflow#139715014742544})#139714952756112, error=None
Traceback (most recent call last):
  File "/home/stan/dpxdt/dpxdt/client/workers.py", line 492, in _progress_workflow
    next_item = generator.send(item)
  File "/home/stan/dpxdt/dpxdt/client/queue_worker.py", line 220, in run
    if next_item.json:
AttributeError: 'TimerItem' object has no attribute 'json'

[NicoHaase]

Same here. Is there any way we can help you find the problem?

[elsigh]

I've been getting it consistently as well, but interestingly, only after I changed the flags.cfg to be more aggressive.

[NicoHaase]

What do you mean by "more aggressive"? Is there any configuration I can change to avoid this error?