Stackstorm Concurrency Error

st2scheduler-scrubbed.log

2018-12-18 23:18:56,684 140672270229168 INFO handler [-] Scheduling liveaction: second_task_run (queue_item_id=5c19c6b022edb20192bc631f) (queue_item_id='5c19c6b022edb20192bc631f',liveaction_id='second_task_run')
2018-12-18 23:18:56,688 140672270229168 DEBUG policies [-] Applying pre-run policies for liveaction "second_task_run".
2018-12-18 23:18:56,690 140672270229168 DEBUG policies [-] Getting driver for policy "my_pack.my_pack.concurrency" (action.concurrency).
2018-12-18 23:18:56,690 140672270229168 DEBUG policies [-] Identified 1 policies for the action "my_pack.my-task".
2018-12-18 23:18:56,693 140672270229168 DEBUG concurrency [-] ConcurrencyApplicator is attempting to acquire lock "action=my_pack.my-task,policy_type=action.concurrency".
2018-12-18 23:18:56,693 140672270229168 INFO policies [-] Applying policy "my_pack.my_pack.concurrency" (action.concurrency) for liveaction "second_task_run".
2018-12-18 23:18:56,694 140672265936400 DEBUG connection [-] Sending request(xid=18): Exists(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:56,696 140672265936400 DEBUG connection [-] Received response(xid=18): ZnodeStat(czxid=12885214118, mzxid=12885214118, ctime=1544833063414, mtime=1544833063414, version=0, cversion=894, aversion=0, ephemeralOwner=0, dataLength=0, numChildren=0, pzxid=12885225248)
2018-12-18 23:18:56,697 140672265936400 DEBUG connection [-] Sending request(xid=19): Create(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/c434fe8305cf419e8271a1a4513fb275__lock__', data='1982-sstorm-p02.veriskdom.com_402', acl=[ACL(perms=31, acl_list=['ALL'], id=Id(scheme='world', id='anyone'))], flags=3)
2018-12-18 23:18:56,699 140672265936400 DEBUG connection [-] Received response(xid=19): u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/c434fe8305cf419e8271a1a4513fb275__lock__0000000447'
2018-12-18 23:18:56,700 140672265936400 DEBUG connection [-] Sending request(xid=20): GetChildren(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:56,701 140672265936400 DEBUG connection [-] Received response(xid=20): [u'c434fe8305cf419e8271a1a4513fb275__lock__0000000447']
2018-12-18 23:18:56,708 140672270229168 DEBUG concurrency [-] There are 0 instances of my_pack.my-task in scheduled or running status. Threshold of my_pack.my_pack.concurrency is not reached. Action execution will be scheduled.
2018-12-18 23:18:56,709 140672265936400 DEBUG connection [-] Sending request(xid=21): Delete(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/c434fe8305cf419e8271a1a4513fb275__lock__0000000447', version=-1)
2018-12-18 23:18:56,710 140672265936400 DEBUG connection [-] Received response(xid=21): True
2018-12-18 23:18:56,711 140672270229168 INFO handler [-] Liveaction (second_task_run) Status Pre-Run: requested (5c19c6b022edb20192bc631f) (liveaction_status=u'requested',queue_item_id='5c19c6b022edb20192bc631f',liveaction_id='second_task_run')
2018-12-18 23:18:56,711 140672270229168 INFO handler [-] Liveaction (second_task_run) Status Update to Scheduled 1: requested (5c19c6b022edb20192bc631f) (liveaction_status=u'requested',queue_item_id='5c19c6b022edb20192bc631f',liveaction_id='second_task_run')
2018-12-18 23:18:56,715 140672270229168 DEBUG action_db [-] Updating ActionExection: "second_task_run" with status="scheduled" (liveaction_db={'status': u'requested', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:56.406848+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6ae22edb27fdb1f656a', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6ae22edb27fdb1f656c', u'trace_tag': u'tracetagfor_second_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'second_task_run', 'end_timestamp': None})
2018-12-18 23:18:56,764 140672270229168 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:56,765 140672270229168 DEBUG channel [-] Channel open
2018-12-18 23:18:56,767 140672270229168 DEBUG action_db [-] Updated status for LiveAction object. (liveaction_db={'status': 'scheduled', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:56.406848+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6ae22edb27fdb1f656a', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6ae22edb27fdb1f656c', u'trace_tag': u'tracetagfor_second_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'second_task_run', 'end_timestamp': None})
2018-12-18 23:18:56,767 140672270229168 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:56,851 140672270229168 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:56,853 140672270229168 DEBUG channel [-] Channel open
2018-12-18 23:18:56,873 140615979540144 INFO handler [-] Scheduling liveaction: fourth_task_run (queue_item_id=5c19c6b0e3a1f15386fe1924) (queue_item_id='5c19c6b0e3a1f15386fe1924',liveaction_id='fourth_task_run')
2018-12-18 23:18:56,876 140615979540144 DEBUG policies [-] Applying pre-run policies for liveaction "fourth_task_run".
2018-12-18 23:18:56,878 140615979540144 DEBUG policies [-] Getting driver for policy "my_pack.my_pack.concurrency" (action.concurrency).
2018-12-18 23:18:56,878 140615979540144 DEBUG policies [-] Identified 1 policies for the action "my_pack.my-task".
2018-12-18 23:18:56,881 140615979540144 DEBUG concurrency [-] ConcurrencyApplicator is attempting to acquire lock "action=my_pack.my-task,policy_type=action.concurrency".
2018-12-18 23:18:56,881 140615979540144 INFO policies [-] Applying policy "my_pack.my_pack.concurrency" (action.concurrency) for liveaction "fourth_task_run".
2018-12-18 23:18:56,882 140615979539984 DEBUG connection [-] Sending request(xid=26): Exists(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:56,883 140615979539984 DEBUG connection [-] Received response(xid=26): ZnodeStat(czxid=12885214118, mzxid=12885214118, ctime=1544833063414, mtime=1544833063414, version=0, cversion=896, aversion=0, ephemeralOwner=0, dataLength=0, numChildren=0, pzxid=12885225924)
2018-12-18 23:18:56,884 140615979539984 DEBUG connection [-] Sending request(xid=27): Create(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/b1b90455223f4dbd97903a7d67062be3__lock__', data='1982-sstorm-p01.veriskdom.com_21382', acl=[ACL(perms=31, acl_list=['ALL'], id=Id(scheme='world', id='anyone'))], flags=3)
2018-12-18 23:18:56,886 140615979539984 DEBUG connection [-] Received response(xid=27): u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/b1b90455223f4dbd97903a7d67062be3__lock__0000000448'
2018-12-18 23:18:56,887 140615979539984 DEBUG connection [-] Sending request(xid=28): GetChildren(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:56,888 140615979539984 DEBUG connection [-] Received response(xid=28): [u'b1b90455223f4dbd97903a7d67062be3__lock__0000000448']
2018-12-18 23:18:56,891 140615979539984 DEBUG connection [-] Sending request(xid=29): Delete(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/b1b90455223f4dbd97903a7d67062be3__lock__0000000448', version=-1)
2018-12-18 23:18:56,891 140615979540144 DEBUG concurrency [-] There are 0 instances of my_pack.my-task in scheduled or running status. Threshold of my_pack.my_pack.concurrency is not reached. Action execution will be scheduled.
2018-12-18 23:18:56,893 140615979539984 DEBUG connection [-] Received response(xid=29): True
2018-12-18 23:18:56,893 140615979540144 INFO handler [-] Liveaction (fourth_task_run) Status Pre-Run: requested (5c19c6b0e3a1f15386fe1924) (liveaction_status=u'requested',queue_item_id='5c19c6b0e3a1f15386fe1924',liveaction_id='fourth_task_run')
2018-12-18 23:18:56,894 140615979540144 INFO handler [-] Liveaction (fourth_task_run) Status Update to Scheduled 1: requested (5c19c6b0e3a1f15386fe1924) (liveaction_status=u'requested',queue_item_id='5c19c6b0e3a1f15386fe1924',liveaction_id='fourth_task_run')
2018-12-18 23:18:56,898 140615979540144 DEBUG action_db [-] Updating ActionExection: "fourth_task_run" with status="scheduled" (liveaction_db={'status': u'requested', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:56.422983+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6ae22edb27fdb1f656b', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6ae22edb27fdb1f656d', u'trace_tag': u'tracetagfor_fourth_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'fourth_task_run', 'end_timestamp': None})
2018-12-18 23:18:56,901 140672270229168 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:56,902 140672270229168 AUDIT action [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=second_task_run, ActionExecution.id=5c19c6b022edb27fdb1f6570> (liveaction_db={'status': 'scheduled', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:56.406848+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'user': u'stanley', u'trigger_instance': {u'id': u'5c19c6ae22edb27fdb1f656a', u'name': None}, u'trace_context': {u'id_': u'5c19c6ae22edb27fdb1f656c', u'trace_tag': u'tracetagfor_second_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'pack': u'my_pack'}, 'action': u'my_pack.my-task', 'id': 'second_task_run', 'end_timestamp': None},action_execution_db={'scrubbed': True})
2018-12-18 23:18:56,937 140615979540144 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:56,938 140615979540144 DEBUG channel [-] Channel open
2018-12-18 23:18:56,945 140615979540144 DEBUG action_db [-] Updated status for LiveAction object. (liveaction_db={'status': 'scheduled', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:56.422983+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6ae22edb27fdb1f656b', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6ae22edb27fdb1f656d', u'trace_tag': u'tracetagfor_fourth_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'fourth_task_run', 'end_timestamp': None})
2018-12-18 23:18:56,945 140615979540144 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:57,041 140615979540144 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:57,048 140615979540144 DEBUG channel [-] Channel open
2018-12-18 23:18:57,061 140672270229168 INFO action [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=second_task_run, ActionExecution.id=5c19c6b022edb27fdb1f6570>
2018-12-18 23:18:57,062 140672270229168 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:57,063 140672270229168 DEBUG channel [-] Channel open
2018-12-18 23:18:57,065 140672270229168 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:57,067 140672270229168 INFO handler [-] Liveaction (second_task_run) Status Update to Scheduled 2: scheduled (5c19c6b022edb20192bc631f)
2018-12-18 23:18:57,069 140615979540144 AUDIT action [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=fourth_task_run, ActionExecution.id=5c19c6b022edb27fdb1f6571> (liveaction_db={'status': 'scheduled', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:56.422983+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'user': u'stanley', u'trigger_instance': {u'id': u'5c19c6ae22edb27fdb1f656b', u'name': None}, u'trace_context': {u'id_': u'5c19c6ae22edb27fdb1f656d', u'trace_tag': u'tracetagfor_fourth_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'pack': u'my_pack'}, 'action': u'my_pack.my-task', 'id': 'fourth_task_run', 'end_timestamp': None},action_execution_db={'scrubbed': True})
2018-12-18 23:18:57,069 140615979540144 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:57,329 140615979540144 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:57,329 140615979540144 INFO action [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=fourth_task_run, ActionExecution.id=5c19c6b022edb27fdb1f6571>
2018-12-18 23:18:57,354 140615979540144 DEBUG channel [-] Channel open
2018-12-18 23:18:57,357 140615979540144 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:57,362 140615979540144 INFO handler [-] Liveaction (fourth_task_run) Status Update to Scheduled 2: scheduled (5c19c6b0e3a1f15386fe1924)
2018-12-18 23:18:58,060 140615979540304 INFO handler [-] Scheduling liveaction: first_task_run (queue_item_id=5c19c6b122edb20192bc6320) (queue_item_id='5c19c6b122edb20192bc6320',liveaction_id='first_task_run')
2018-12-18 23:18:58,084 140615979540304 DEBUG policies [-] Applying pre-run policies for liveaction "first_task_run".
2018-12-18 23:18:58,089 140615979540304 DEBUG policies [-] Getting driver for policy "my_pack.my_pack.concurrency" (action.concurrency).
2018-12-18 23:18:58,089 140615979540304 DEBUG policies [-] Identified 1 policies for the action "my_pack.my-task".
2018-12-18 23:18:58,097 140615979540304 INFO policies [-] Applying policy "my_pack.my_pack.concurrency" (action.concurrency) for liveaction "first_task_run".
2018-12-18 23:18:58,098 140615979539984 DEBUG connection [-] Sending request(xid=30): Exists(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:58,098 140615979540304 DEBUG concurrency [-] ConcurrencyApplicator is attempting to acquire lock "action=my_pack.my-task,policy_type=action.concurrency".
2018-12-18 23:18:58,099 140615979539984 DEBUG connection [-] Received response(xid=30): ZnodeStat(czxid=12885214118, mzxid=12885214118, ctime=1544833063414, mtime=1544833063414, version=0, cversion=898, aversion=0, ephemeralOwner=0, dataLength=0, numChildren=0, pzxid=12885225926)
2018-12-18 23:18:58,100 140615979539984 DEBUG connection [-] Sending request(xid=31): Create(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/186f1c549c3f4064b897041ce2d3870f__lock__', data='1982-sstorm-p01.veriskdom.com_21382', acl=[ACL(perms=31, acl_list=['ALL'], id=Id(scheme='world', id='anyone'))], flags=3)
2018-12-18 23:18:58,103 140615979539984 DEBUG connection [-] Received response(xid=31): u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/186f1c549c3f4064b897041ce2d3870f__lock__0000000449'
2018-12-18 23:18:58,104 140615979539984 DEBUG connection [-] Sending request(xid=32): GetChildren(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:58,107 140615979539984 DEBUG connection [-] Received response(xid=32): [u'186f1c549c3f4064b897041ce2d3870f__lock__0000000449']
2018-12-18 23:18:58,112 140615979540304 DEBUG concurrency [-] There are 2 instances of my_pack.my-task in scheduled or running status. Threshold of my_pack.my_pack.concurrency is reached. Action execution will be delayed.
2018-12-18 23:18:58,115 140615979540304 DEBUG action_db [-] Updating ActionExection: "first_task_run" with status="policy-delayed" (liveaction_db={'status': u'requested', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:57.483067+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6aee3a1f152f1ff1468', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6aee3a1f152f1ff146a', u'trace_tag': u'tracetagfor_first_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'first_task_run', 'end_timestamp': None})
2018-12-18 23:18:58,240 140615979540304 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:58,242 140615979540304 DEBUG channel [-] Channel open
2018-12-18 23:18:58,243 140615979540304 DEBUG action_db [-] Updated status for LiveAction object. (liveaction_db={'status': 'policy-delayed', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:57.483067+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6aee3a1f152f1ff1468', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6aee3a1f152f1ff146a', u'trace_tag': u'tracetagfor_first_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'first_task_run', 'end_timestamp': None})
2018-12-18 23:18:58,243 140615979540304 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:58,260 140672270229328 INFO handler [-] Scheduling liveaction: third_task_run (queue_item_id=5c19c6b222edb20192bc6321) (queue_item_id='5c19c6b222edb20192bc6321',liveaction_id='third_task_run')
2018-12-18 23:18:58,263 140672270229328 DEBUG policies [-] Applying pre-run policies for liveaction "third_task_run".
2018-12-18 23:18:58,265 140672270229328 DEBUG policies [-] Getting driver for policy "my_pack.my_pack.concurrency" (action.concurrency).
2018-12-18 23:18:58,265 140672270229328 DEBUG policies [-] Identified 1 policies for the action "my_pack.my-task".
2018-12-18 23:18:58,267 140672270229328 INFO policies [-] Applying policy "my_pack.my_pack.concurrency" (action.concurrency) for liveaction "third_task_run".
2018-12-18 23:18:58,268 140672265936400 DEBUG connection [-] Sending request(xid=22): Exists(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:58,268 140672270229328 DEBUG concurrency [-] ConcurrencyApplicator is attempting to acquire lock "action=my_pack.my-task,policy_type=action.concurrency".
2018-12-18 23:18:58,270 140672265936400 DEBUG connection [-] Received response(xid=22): ZnodeStat(czxid=12885214118, mzxid=12885214118, ctime=1544833063414, mtime=1544833063414, version=0, cversion=899, aversion=0, ephemeralOwner=0, dataLength=0, numChildren=1, pzxid=12885225927)
2018-12-18 23:18:58,270 140672265936400 DEBUG connection [-] Sending request(xid=23): Create(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/165d4ddd950a41b49c6600f5da699c3e__lock__', data='1982-sstorm-p02.veriskdom.com_402', acl=[ACL(perms=31, acl_list=['ALL'], id=Id(scheme='world', id='anyone'))], flags=3)
2018-12-18 23:18:58,272 140672265936400 DEBUG connection [-] Received response(xid=23): u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/165d4ddd950a41b49c6600f5da699c3e__lock__0000000450'
2018-12-18 23:18:58,273 140672265936400 DEBUG connection [-] Sending request(xid=24): GetChildren(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:58,274 140672265936400 DEBUG connection [-] Received response(xid=24): [u'186f1c549c3f4064b897041ce2d3870f__lock__0000000449', u'165d4ddd950a41b49c6600f5da699c3e__lock__0000000450']
2018-12-18 23:18:58,275 140672265936400 DEBUG connection [-] Sending request(xid=25): GetData(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/186f1c549c3f4064b897041ce2d3870f__lock__0000000449', watcher=<bound method Lock._watch_predecessor of <kazoo.recipe.lock.Lock object at 0x7ff0d06a9410>>)
2018-12-18 23:18:58,276 140672265936400 DEBUG connection [-] Received response(xid=25): ('1982-sstorm-p01.veriskdom.com_21382', ZnodeStat(czxid=12885225927, mzxid=12885225927, ctime=1545193138193, mtime=1545193138193, version=0, cversion=0, aversion=0, ephemeralOwner=172870643966426114, dataLength=35, numChildren=0, pzxid=12885225927))
2018-12-18 23:18:58,426 140615979540304 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:58,428 140615979540304 DEBUG channel [-] Channel open
2018-12-18 23:18:58,449 140615979540304 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:58,450 140615979540304 AUDIT action [-] The status of action execution is changed from requested to policy-delayed. <LiveAction.id=first_task_run, ActionExecution.id=5c19c6b1e3a1f152f1ff1470> (liveaction_db={'status': 'policy-delayed', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:57.483067+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'user': u'stanley', u'trigger_instance': {u'id': u'5c19c6aee3a1f152f1ff1468', u'name': None}, u'trace_context': {u'id_': u'5c19c6aee3a1f152f1ff146a', u'trace_tag': u'tracetagfor_first_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'pack': u'my_pack'}, 'action': u'my_pack.my-task', 'id': 'first_task_run', 'end_timestamp': None},action_execution_db={'scrubbed': True})
2018-12-18 23:18:58,456 140615979540144 INFO handler [-] Scheduling liveaction: fifth_task_run (queue_item_id=5c19c6b2e3a1f15386fe1925) (queue_item_id='5c19c6b2e3a1f15386fe1925',liveaction_id='fifth_task_run')
2018-12-18 23:18:58,505 140672265936400 DEBUG connection [-] Received EVENT: Watch(type=2, state=3, path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/186f1c549c3f4064b897041ce2d3870f__lock__0000000449')
2018-12-18 23:18:58,505 140672265936400 DEBUG connection [-] Sending request(xid=26): GetChildren(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency', watcher=None)
2018-12-18 23:18:58,506 140672265936400 DEBUG connection [-] Received response(xid=26): [u'165d4ddd950a41b49c6600f5da699c3e__lock__0000000450']
2018-12-18 23:18:58,509 140672270229328 DEBUG concurrency [-] There are 2 instances of my_pack.my-task in scheduled or running status. Threshold of my_pack.my_pack.concurrency is reached. Action execution will be delayed.
2018-12-18 23:18:58,512 140672270229328 DEBUG action_db [-] Updating ActionExection: "third_task_run" with status="policy-delayed" (liveaction_db={'status': u'requested', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:57.545804+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6aee3a1f152f1ff1469', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6aee3a1f152f1ff146b', u'trace_tag': u'tracetagfor_third_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'third_task_run', 'end_timestamp': None})
2018-12-18 23:18:58,539 140672270229328 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:58,540 140672270229328 DEBUG channel [-] Channel open
2018-12-18 23:18:58,543 140672270229328 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:58,544 140672270229328 DEBUG action_db [-] Updated status for LiveAction object. (liveaction_db={'status': 'policy-delayed', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:57.545804+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'trigger_instance': {u'id': u'5c19c6aee3a1f152f1ff1469', u'name': None}, u'pack': u'my_pack', u'trace_context': {u'id_': u'5c19c6aee3a1f152f1ff146b', u'trace_tag': u'tracetagfor_third_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'user': u'stanley'}, 'action': u'my_pack.my-task', 'id': 'third_task_run', 'end_timestamp': None})
2018-12-18 23:18:58,620 140672270229328 DEBUG channel [-] using channel_id: 1
2018-12-18 23:18:58,621 140672270229328 DEBUG channel [-] Channel open
2018-12-18 23:18:58,646 140672270229328 DEBUG channel [-] Closed channel #1
2018-12-18 23:18:58,647 140615979540304 INFO action [-] The status of action execution is changed from requested to policy-delayed. <LiveAction.id=first_task_run, ActionExecution.id=5c19c6b1e3a1f152f1ff1470>
2018-12-18 23:18:58,647 140672270229328 AUDIT action [-] The status of action execution is changed from requested to policy-delayed. <LiveAction.id=third_task_run, ActionExecution.id=5c19c6b1e3a1f152f1ff1473> (liveaction_db={'status': 'policy-delayed', 'runner_info': {}, 'workflow_execution': None, 'parameters': {u'cmd': u'sleep 90', u'timeout': 300}, 'action_is_workflow': True, 'start_timestamp': '2018-12-19 04:18:57.545804+00:00', 'delay': None, 'callback': {}, 'task_execution': None, 'notify': None, 'result': {}, 'context': {u'user': u'stanley', u'trigger_instance': {u'id': u'5c19c6aee3a1f152f1ff1469', u'name': None}, u'trace_context': {u'id_': u'5c19c6aee3a1f152f1ff146b', u'trace_tag': u'tracetagfor_third_task_run'}, u'rule': {u'id': u'5b919f16cfbada5ec6b8cd04', u'name': u'run_my_task'}, u'pack': u'my_pack'}, 'action': u'my_pack.my-task', 'id': 'third_task_run', 'end_timestamp': None},action_execution_db={'scrubbed': True})
2018-12-18 23:18:58,652 140615979539984 DEBUG connection [-] Sending request(xid=33): Delete(path=u'/tooz/locks/action=my_pack.my-task,policy_type=action.concurrency/186f1c549c3f4064b897041ce2d3870f__lock__0000000449', version=-1)