Skip to content

Step execution random timeouts

An error (probably a timeout) randomly occurred when trying to execute a Step.

Worker logs:

2022-09-27 11:46:26,601.601 DEBUG [140481107314240] {task} [start] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "event": "Starting Task in a process.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.601643Z"}
2022-09-27 11:46:26,708.708 DEBUG [140481107314240] {task} [__call__] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "event": "Processing Task.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.708272Z"}
Processing Task. correlation_id: eb3d0d74-5cea-410b-9177-a6e73876b5c8
2022-09-27 11:46:26,709.709 INFO [140481107314240] {task} [_execute] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "event": "Running AttackTask._execute().", "logger": "cryton-worker-debug", "level": "info", "timestamp": "2022-09-27T09:46:26.709521Z"}
2022-09-27 11:46:26,710.710 DEBUG [140481107314240] {util} [run_attack_module_on_worker] {"module_name": "mod_nmap", "arguments": {"ports": [22], "target": "127.0.0.1"}, "event": "Running module.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.710613Z"}
2022-09-27 11:46:26,710.710 DEBUG [140481107314240] {util} [execute_attack_module_on_worker] {"module_name": "mod_nmap", "arguments": {"ports": [22], "target": "127.0.0.1"}, "event": "Executing module on worker.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.710844Z"}
2022-09-27 11:46:26,711.711 DEBUG [140481355830848] {worker} [_send_message] {"request": {"data": {"return_code": 0, "correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8"}, "queue_name": "40944d5c-3e40-11ed-a77b-1c697a95211f", "properties": {}}, "event": "Calling process _send_message", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.710914Z"}
2022-09-27 11:46:26,711.711 DEBUG [140481107314240] {util} [import_module] {"module_name": "mod_nmap", "event": "Importing module.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.711054Z"}
2022-09-27 11:46:26,711.711 DEBUG [140481355830848] {consumer} [send_message] {"queue": "40944d5c-3e40-11ed-a77b-1c697a95211f", "message": {"return_code": 0, "correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8"}, "properties": {"content_encoding": "utf-8", "timestamp": "datetime.datetime(2022, 9, 27, 10, 32, 10, 632316)"}, "event": "Sending message.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.711250Z"}
2022-09-27 11:46:26,768.768 DEBUG [140481107314240] {util} [execute_attack_module_on_worker] {"module_name": "mod_nmap", "arguments": {"ports": [22], "target": "127.0.0.1"}, "result": {"return_code": 0, "output": "<nmaprun scanner=\"nmap\" args=\"/usr/bin/nmap -oX - -p22 127.0.0.1\" start=\"1664271986\" startstr=\"Tue Sep 27 11:46:26 2022\" version=\"7.92\" xmloutputversion=\"1.05\">\n<scaninfo type=\"connect\" protocol=\"tcp\" numservices=\"1\" services=\"22\" />\n<verbose level=\"0\" />\n<debugging level=\"0\" />\n<hosthint><status state=\"up\" reason=\"unknown-response\" reason_ttl=\"0\" />\n<address addr=\"127.0.0.1\" addrtype=\"ipv4\" />\n<hostnames>\n</hostnames>\n</hosthint>\n<host starttime=\"1664271986\" endtime=\"1664271986\"><status state=\"up\" reason=\"conn-refused\" reason_ttl=\"0\" />\n<address addr=\"127.0.0.1\" addrtype=\"ipv4\" />\n<hostnames>\n<hostname name=\"localhost\" type=\"PTR\" />\n</hostnames>\n<ports><port protocol=\"tcp\" portid=\"22\"><state state=\"closed\" reason=\"conn-refused\" reason_ttl=\"0\" /><service name=\"ssh\" method=\"table\" conf=\"3\" /></port>\n</ports>\n<times srtt=\"47\" rttvar=\"3757\" to=\"100000\" />\n</host>\n<runstats><finished time=\"1664271986\" timestr=\"Tue Sep 27 11:46:26 2022\" summary=\"Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds\" elapsed=\"0.03\" exit=\"success\" /><hosts up=\"1\" down=\"0\" total=\"1\" />\n</runstats>\n</nmaprun>", "serialized_output": {"127.0.0.1": {"osmatch": {}, "ports": [{"protocol": "tcp", "portid": "22", "state": "closed", "reason": "conn-refused", "reason_ttl": "0", "service": {"name": "ssh", "method": "table", "conf": "3"}, "cpe": [], "scripts": []}], "hostname": [{"name": "localhost", "type": "PTR"}], "macaddress": null, "state": {"state": "up", "reason": "conn-refused", "reason_ttl": "0"}}, "stats": {"scanner": "nmap", "args": "/usr/bin/nmap -oX - -p22 127.0.0.1", "start": "1664271986", "startstr": "Tue Sep 27 11:46:26 2022", "version": "7.92", "xmloutputversion": "1.05"}, "runtime": {"time": "1664271986", "timestr": "Tue Sep 27 11:46:26 2022", "summary": "Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds", "elapsed": "0.03", "exit": "success"}}}, "event": "Module execution finished.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.768596Z"}
2022-09-27 11:46:26,768.768 DEBUG [140481107314240] {util} [run_attack_module_on_worker] {"module_name": "mod_nmap", "arguments": {"ports": [22], "target": "127.0.0.1"}, "ret": {"return_code": 0, "output": "<nmaprun scanner=\"nmap\" args=\"/usr/bin/nmap -oX - -p22 127.0.0.1\" start=\"1664271986\" startstr=\"Tue Sep 27 11:46:26 2022\" version=\"7.92\" xmloutputversion=\"1.05\">\n<scaninfo type=\"connect\" protocol=\"tcp\" numservices=\"1\" services=\"22\" />\n<verbose level=\"0\" />\n<debugging level=\"0\" />\n<hosthint><status state=\"up\" reason=\"unknown-response\" reason_ttl=\"0\" />\n<address addr=\"127.0.0.1\" addrtype=\"ipv4\" />\n<hostnames>\n</hostnames>\n</hosthint>\n<host starttime=\"1664271986\" endtime=\"1664271986\"><status state=\"up\" reason=\"conn-refused\" reason_ttl=\"0\" />\n<address addr=\"127.0.0.1\" addrtype=\"ipv4\" />\n<hostnames>\n<hostname name=\"localhost\" type=\"PTR\" />\n</hostnames>\n<ports><port protocol=\"tcp\" portid=\"22\"><state state=\"closed\" reason=\"conn-refused\" reason_ttl=\"0\" /><service name=\"ssh\" method=\"table\" conf=\"3\" /></port>\n</ports>\n<times srtt=\"47\" rttvar=\"3757\" to=\"100000\" />\n</host>\n<runstats><finished time=\"1664271986\" timestr=\"Tue Sep 27 11:46:26 2022\" summary=\"Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds\" elapsed=\"0.03\" exit=\"success\" /><hosts up=\"1\" down=\"0\" total=\"1\" />\n</runstats>\n</nmaprun>", "serialized_output": {"127.0.0.1": {"osmatch": {}, "ports": [{"protocol": "tcp", "portid": "22", "state": "closed", "reason": "conn-refused", "reason_ttl": "0", "service": {"name": "ssh", "method": "table", "conf": "3"}, "cpe": [], "scripts": []}], "hostname": [{"name": "localhost", "type": "PTR"}], "macaddress": null, "state": {"state": "up", "reason": "conn-refused", "reason_ttl": "0"}}, "stats": {"scanner": "nmap", "args": "/usr/bin/nmap -oX - -p22 127.0.0.1", "start": "1664271986", "startstr": "Tue Sep 27 11:46:26 2022", "version": "7.92", "xmloutputversion": "1.05"}, "runtime": {"time": "1664271986", "timestr": "Tue Sep 27 11:46:26 2022", "summary": "Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds", "elapsed": "0.03", "exit": "success"}}}, "event": "Module run finished.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.768892Z"}
2022-09-27 11:46:26,769.769 INFO [140481107314240] {task} [_execute] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "step_type": "worker/execute", "event": "Finished AttackTask._execute().", "logger": "cryton-worker-debug", "level": "info", "timestamp": "2022-09-27T09:46:26.769106Z"}
Finished Task processing. correlation_id: eb3d0d74-5cea-410b-9177-a6e73876b5c8
2022-09-27 11:46:26,769.769 DEBUG [140481107314240] {task} [__call__] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "event": "Finished Task processing.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.769597Z"}
2022-09-27 11:46:26,770.770 DEBUG [140481364223552] {worker} [_finish_task] {"request": {"data": "{\"return_code\": 0, \"output\": \"<nmaprun scanner=\\\"nmap\\\" args=\\\"/usr/bin/nmap -oX - -p22 127.0.0.1\\\" start=\\\"1664271986\\\" startstr=\\\"Tue Sep 27 11:46:26 2022\\\" version=\\\"7.92\\\" xmloutputversion=\\\"1.05\\\">\\n<scaninfo type=\\\"connect\\\" protocol=\\\"tcp\\\" numservices=\\\"1\\\" services=\\\"22\\\" />\\n<verbose level=\\\"0\\\" />\\n<debugging level=\\\"0\\\" />\\n<hosthint><status state=\\\"up\\\" reason=\\\"unknown-response\\\" reason_ttl=\\\"0\\\" />\\n<address addr=\\\"127.0.0.1\\\" addrtype=\\\"ipv4\\\" />\\n<hostnames>\\n</hostnames>\\n</hosthint>\\n<host starttime=\\\"1664271986\\\" endtime=\\\"1664271986\\\"><status state=\\\"up\\\" reason=\\\"conn-refused\\\" reason_ttl=\\\"0\\\" />\\n<address addr=\\\"127.0.0.1\\\" addrtype=\\\"ipv4\\\" />\\n<hostnames>\\n<hostname name=\\\"localhost\\\" type=\\\"PTR\\\" />\\n</hostnames>\\n<ports><port protocol=\\\"tcp\\\" portid=\\\"22\\\"><state state=\\\"closed\\\" reason=\\\"conn-refused\\\" reason_ttl=\\\"0\\\" /><service name=\\\"ssh\\\" method=\\\"table\\\" conf=\\\"3\\\" /></port>\\n</ports>\\n<times srtt=\\\"47\\\" rttvar=\\\"3757\\\" to=\\\"100000\\\" />\\n</host>\\n<runstats><finished time=\\\"1664271986\\\" timestr=\\\"Tue Sep 27 11:46:26 2022\\\" summary=\\\"Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds\\\" elapsed=\\\"0.03\\\" exit=\\\"success\\\" /><hosts up=\\\"1\\\" down=\\\"0\\\" total=\\\"1\\\" />\\n</runstats>\\n</nmaprun>\", \"serialized_output\": {\"127.0.0.1\": {\"osmatch\": {}, \"ports\": [{\"protocol\": \"tcp\", \"portid\": \"22\", \"state\": \"closed\", \"reason\": \"conn-refused\", \"reason_ttl\": \"0\", \"service\": {\"name\": \"ssh\", \"method\": \"table\", \"conf\": \"3\"}, \"cpe\": [], \"scripts\": []}], \"hostname\": [{\"name\": \"localhost\", \"type\": \"PTR\"}], \"macaddress\": null, \"state\": {\"state\": \"up\", \"reason\": \"conn-refused\", \"reason_ttl\": \"0\"}}, \"stats\": {\"scanner\": \"nmap\", \"args\": \"/usr/bin/nmap -oX - -p22 127.0.0.1\", \"start\": \"1664271986\", \"startstr\": \"Tue Sep 27 11:46:26 2022\", \"version\": \"7.92\", \"xmloutputversion\": \"1.05\"}, \"runtime\": {\"time\": \"1664271986\", \"timestr\": \"Tue Sep 27 11:46:26 2022\", \"summary\": \"Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds\", \"elapsed\": \"0.03\", \"exit\": \"success\"}}}", "correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8"}, "event": "Calling process _finish_task", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.769837Z"}
2022-09-27 11:46:26,770.770 DEBUG [140481364223552] {consumer} [pop_task] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "event": "Popping (searching) Task using correlation_id.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.770222Z"}
2022-09-27 11:46:26,770.770 DEBUG [140481364223552] {consumer} [pop_task] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "event": "Task popping (search) succeeded.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.770462Z"}
2022-09-27 11:46:26,770.770 DEBUG [140481364223552] {task} [reply] {"correlation_id": "eb3d0d74-5cea-410b-9177-a6e73876b5c8", "reply_to": "cryton_core.attack.response", "message_body": "{\"return_code\": 0, \"output\": \"<nmaprun scanner=\\\"nmap\\\" args=\\\"/usr/bin/nmap -oX - -p22 127.0.0.1\\\" start=\\\"1664271986\\\" startstr=\\\"Tue Sep 27 11:46:26 2022\\\" version=\\\"7.92\\\" xmloutputversion=\\\"1.05\\\">\\n<scaninfo type=\\\"connect\\\" protocol=\\\"tcp\\\" numservices=\\\"1\\\" services=\\\"22\\\" />\\n<verbose level=\\\"0\\\" />\\n<debugging level=\\\"0\\\" />\\n<hosthint><status state=\\\"up\\\" reason=\\\"unknown-response\\\" reason_ttl=\\\"0\\\" />\\n<address addr=\\\"127.0.0.1\\\" addrtype=\\\"ipv4\\\" />\\n<hostnames>\\n</hostnames>\\n</hosthint>\\n<host starttime=\\\"1664271986\\\" endtime=\\\"1664271986\\\"><status state=\\\"up\\\" reason=\\\"conn-refused\\\" reason_ttl=\\\"0\\\" />\\n<address addr=\\\"127.0.0.1\\\" addrtype=\\\"ipv4\\\" />\\n<hostnames>\\n<hostname name=\\\"localhost\\\" type=\\\"PTR\\\" />\\n</hostnames>\\n<ports><port protocol=\\\"tcp\\\" portid=\\\"22\\\"><state state=\\\"closed\\\" reason=\\\"conn-refused\\\" reason_ttl=\\\"0\\\" /><service name=\\\"ssh\\\" method=\\\"table\\\" conf=\\\"3\\\" /></port>\\n</ports>\\n<times srtt=\\\"47\\\" rttvar=\\\"3757\\\" to=\\\"100000\\\" />\\n</host>\\n<runstats><finished time=\\\"1664271986\\\" timestr=\\\"Tue Sep 27 11:46:26 2022\\\" summary=\\\"Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds\\\" elapsed=\\\"0.03\\\" exit=\\\"success\\\" /><hosts up=\\\"1\\\" down=\\\"0\\\" total=\\\"1\\\" />\\n</runstats>\\n</nmaprun>\", \"serialized_output\": {\"127.0.0.1\": {\"osmatch\": {}, \"ports\": [{\"protocol\": \"tcp\", \"portid\": \"22\", \"state\": \"closed\", \"reason\": \"conn-refused\", \"reason_ttl\": \"0\", \"service\": {\"name\": \"ssh\", \"method\": \"table\", \"conf\": \"3\"}, \"cpe\": [], \"scripts\": []}], \"hostname\": [{\"name\": \"localhost\", \"type\": \"PTR\"}], \"macaddress\": null, \"state\": {\"state\": \"up\", \"reason\": \"conn-refused\", \"reason_ttl\": \"0\"}}, \"stats\": {\"scanner\": \"nmap\", \"args\": \"/usr/bin/nmap -oX - -p22 127.0.0.1\", \"start\": \"1664271986\", \"startstr\": \"Tue Sep 27 11:46:26 2022\", \"version\": \"7.92\", \"xmloutputversion\": \"1.05\"}, \"runtime\": {\"time\": \"1664271986\", \"timestr\": \"Tue Sep 27 11:46:26 2022\", \"summary\": \"Nmap done at Tue Sep 27 11:46:26 2022; 1 IP address (1 host up) scanned in 0.03 seconds\", \"elapsed\": \"0.03\", \"exit\": \"success\"}}}", "event": "Sending reply.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.770673Z"}
2022-09-27 11:46:26,771.771 WARNING [140481364223552] {worker} [_threaded_processor] {"request": "PrioritizedItem(priority=0, item={}, timestamp=1664267530700261180)", "error": "Channel 1 was closed by remote server: PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more", "event": "Request threw an exception in the process.", "logger": "cryton-worker-debug", "level": "warning", "timestamp": "2022-09-27T09:46:26.771013Z"}
2022-09-27 11:46:26,773.773 WARNING [140481355830848] {worker} [_threaded_processor] {"request": "PrioritizedItem(priority=0, item={}, timestamp=1664267530700261180)", "error": "Connection was closed by remote server: CHANNEL_ERROR - expected 'channel.open'", "event": "Request threw an exception in the process.", "logger": "cryton-worker-debug", "level": "warning", "timestamp": "2022-09-27T09:46:26.773349Z"}
2022-09-27 11:46:26,773.773 DEBUG [140481098921536] {consumer} [_threaded_consumer] {"thread_id": 3, "error": "connection closed", "event": "Threaded consumer encountered an error.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.773837Z"}
2022-09-27 11:46:26,775.775 DEBUG [140481364223552] {worker} [_threaded_processor] {"request": "PrioritizedItem(priority=0, item={}, timestamp=1664267530700261180)", "error": "Channel 1 was closed by remote server: PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more", "traceback": "Traceback (most recent call last):\n  File \"/home/sad/dev/cryton/cryton-worker/cryton_worker/lib/worker.py\", line 134, in _threaded_processor\n    action_callable(request.item)\n  File \"/home/sad/dev/cryton/cryton-worker/cryton_worker/lib/worker.py\", line 182, in _finish_task\n    task_obj.reply(data)\n  File \"/home/sad/dev/cryton/cryton-worker/cryton_worker/lib/task.py\", line 101, in reply\n    self.message.channel.queue.declare(self.message.reply_to)\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/queue.py\", line 55, in declare\n    return self._channel.rpc_request(declare_frame)\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/channel.py\", line 340, in rpc_request\n    return self.rpc.get_request(\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/rpc.py\", line 99, in get_request\n    self._wait_for_request(\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/rpc.py\", line 133, in _wait_for_request\n    connection_adapter.check_for_errors()\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/channel.py\", line 225, in check_for_errors\n    self.check_for_exceptions()\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/channel.py\", line 241, in check_for_exceptions\n    raise exception\namqpstorm.exception.AMQPChannelError: Channel 1 was closed by remote server: PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more\n", "event": "Request threw an exception in the process.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.775192Z"}
2022-09-27 11:46:26,776.776 DEBUG [140481115706944] {consumer} [_threaded_consumer] {"thread_id": 1, "error": "connection closed", "event": "Threaded consumer encountered an error.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.775995Z"}
2022-09-27 11:46:26,776.776 DEBUG [140481107314240] {consumer} [_threaded_consumer] {"thread_id": 2, "error": "connection closed", "event": "Threaded consumer encountered an error.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.776321Z"}
2022-09-27 11:46:26,777.777 DEBUG [140481355830848] {worker} [_threaded_processor] {"request": "PrioritizedItem(priority=0, item={}, timestamp=1664267530700261180)", "error": "Connection was closed by remote server: CHANNEL_ERROR - expected 'channel.open'", "traceback": "Traceback (most recent call last):\n  File \"/home/sad/dev/cryton/cryton-worker/cryton_worker/lib/worker.py\", line 134, in _threaded_processor\n    action_callable(request.item)\n  File \"/home/sad/dev/cryton/cryton-worker/cryton_worker/lib/worker.py\", line 197, in _send_message\n    self._consumer.send_message(queue_name, msg_body, msg_properties)\n  File \"/home/sad/dev/cryton/cryton-worker/cryton_worker/lib/consumer.py\", line 255, in send_message\n    message.publish(queue)\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/message.py\", line 181, in publish\n    return self._channel.basic.publish(body=self._body,\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/basic.py\", line 209, in publish\n    self._channel.write_frames(frames_out)\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/channel.py\", line 400, in write_frames\n    self.check_for_errors()\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/channel.py\", line 220, in check_for_errors\n    self._connection.check_for_errors()\n  File \"/home/sad/.local/pypoetry/virtualenvs/cryton-worker-XPOOUZia-py3.10/lib/python3.10/site-packages/amqpstorm/connection.py\", line 211, in check_for_errors\n    raise self.exceptions[0]\namqpstorm.exception.AMQPConnectionError: Connection was closed by remote server: CHANNEL_ERROR - expected 'channel.open'\n", "event": "Request threw an exception in the process.", "logger": "cryton-worker-debug", "level": "debug", "timestamp": "2022-09-27T09:46:26.777344Z"}

Cryton Core - Step execution start:

2022-09-27 08:34:14,269.269 DEBUG [139669790400960] {listener} [__init__] {"event": "Listener created.", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:34:14.269353Z"}, 
2022-09-27 08:34:14,270.270 DEBUG [139669790400960] {listener} [__init__] {"queue": "cryton_core.attack.response", "callback": "<bound method Listener.step_resp_callback of <cryton_core.lib.services.listener.Listener object at 0x7f07557851b0>>", "event": "ProcessListener created.", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:34:14.270030Z"}, 
2022-09-27 08:34:14,270.270 DEBUG [139669790400960] {listener} [__init__] {"queue": "cryton_core.agent.response", "callback": "<bound method Listener.step_resp_callback of <cryton_core.lib.services.listener.Listener object at 0x7f07557851b0>>", "event": "ProcessListener created.", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:34:14.270506Z"}, 
2022-09-27 08:34:14,271.271 DEBUG [139669790400960] {listener} [__init__] {"queue": "cryton_core.control.response", "callback": "<bound method Listener.control_resp_callback of <cryton_core.lib.services.listener.Listener object at 0x7f07557851b0>>", "event": "ProcessListener created.", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:34:14.270937Z"}, 
2022-09-27 08:34:14,271.271 DEBUG [139669790400960] {listener} [__init__] {"queue": "cryton_core.event.response", "callback": "<function Listener.event_callback at 0x7f0755795510>", "event": "ProcessListener created.", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:34:14.271359Z"}, 
2022-09-27 08:34:14,271.271 DEBUG [139669790400960] {listener} [__init__] {"queue": "cryton_core.control.request", "callback": "<function Listener.control_req_callback at 0x7f0755795480>", "event": "ProcessListener created.", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:34:14.271785Z"}, 
2022-09-27 08:34:14,289.289 INFO [139669790400960] {listener} [start] {"test": 1, "event": "Started listener", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:34:14.289612Z"}, 
2022-09-27 08:34:14,475.475 INFO [139669790400960] {listener} [start] {"queue": "cryton_core.attack.response", "event": "Queue declared and consuming", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:34:14.475396Z"}, 
2022-09-27 08:34:14,477.477 INFO [139669790400960] {listener} [start] {"queue": "cryton_core.agent.response", "event": "Queue declared and consuming", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:34:14.477083Z"}, 
2022-09-27 08:34:14,481.481 INFO [139669790400960] {listener} [start] {"queue": "cryton_core.control.response", "event": "Queue declared and consuming", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:34:14.481560Z"}, 
2022-09-27 08:34:14,487.487 INFO [139669790400960] {listener} [start] {"queue": "cryton_core.event.response", "event": "Queue declared and consuming", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:34:14.487526Z"}, 
2022-09-27 08:34:14,489.489 INFO [139669790400960] {listener} [start] {"queue": "cryton_core.control.request", "event": "Queue declared and consuming", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:34:14.488918Z"}, 
2022-09-27 08:41:59,781.781 DEBUG [139669375280704] {listener} [_custom_callback] {"callback": "<function Listener.control_req_callback at 0x7f0755795480>", "message": {"body": "b'{\"event_t\": \"SCHEDULER\", \"event_v\": {\"action\": \"add_job\", \"args\": {\"execute_function\": \"cryton_core.lib.models.stage:execution\", \"function_args\": [1], \"start_time\": \"2022-09-27T08:41:59.680096+00:00\"}}}'", "method": {"consumer_tag": "amq.ctag-6PWwAgjST0vxkAL860WtHg", "delivery_tag": 1, "redelivered": false, "exchange": "", "routing_key": "cryton_core.control.request"}, "properties": {"content_type": "", "content_encoding": "utf-8", "headers": null, "delivery_mode": null, "priority": null, "correlation_id": "b77167e1-ceb9-4c89-b1e3-e53abc12dab0", "reply_to": "405bf34e-3e40-11ed-83c9-1c697a95211f", "expiration": "", "message_id": "82bdd3d4-4bbd-452e-b0e6-5a7d5e62b641", "timestamp": [2022, 9, 27, 8, 41, 59, 1, 270, 0], "message_type": "", "user_id": "", "app_id": "", "cluster_id": ""}, "channel": "<amqpstorm.channel.Channel object at 0x7f0764f324d0>"}, "event": "Running callback.", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.781422Z"}, 
2022-09-27 08:41:59,782.782 DEBUG [139669375280704] {listener} [control_req_callback] {"message_id": "82bdd3d4-4bbd-452e-b0e6-5a7d5e62b641", "event": "Received control request callback", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.782085Z"}, 
2022-09-27 08:41:59,782.782 INFO [139669375280704] {event} [process_control_request] {"event_v": {"action": "add_job", "args": {"execute_function": "cryton_core.lib.models.stage:execution", "function_args": [1], "start_time": "2022-09-27T08:41:59.680096+00:00"}}, "event": "Processing control request", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:41:59.782396Z"}, 
2022-09-27 08:41:59,782.782 DEBUG [139669375280704] {event} [process_scheduler] {"event_v": {"action": "add_job", "args": {"execute_function": "cryton_core.lib.models.stage:execution", "function_args": [1], "start_time": "2022-09-27T08:41:59.680096+00:00"}}, "event": "Processing scheduler event", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.782612Z"}, 
2022-09-27 08:41:59,792.792 DEBUG [139669375280704] {scheduler} [exposed_add_job] {"execute_function": "cryton_core.lib.models.stage:execution", "event": "Scheduling job in scheduler service", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.792280Z"}, 
2022-09-27 08:41:59,798.798 DEBUG [139669375280704] {scheduler} [__del__] {"scheduler": 1, "event": "SCHEDULER DELETED", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.798568Z"}, 
2022-09-27 08:41:59,799.799 DEBUG [139669375280704] {util} [send_response] {"response": "{\"return_value\": \"824c756e8d8241fbbd36eba5f16d214f\"}", "event": "Sending RPC response", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.799281Z"}, 
2022-09-27 08:41:59,799.799 INFO [139669375280704] {util} [send_response] {"response": "{\"return_value\": \"824c756e8d8241fbbd36eba5f16d214f\"}", "reply_to": "405bf34e-3e40-11ed-83c9-1c697a95211f", "event": "sending message", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:41:59.799731Z"}, 
2022-09-27 08:41:59,800.800 INFO [139669375280704] {util} [send_response] {"response": "{\"return_value\": \"824c756e8d8241fbbd36eba5f16d214f\"}", "reply_to": "405bf34e-3e40-11ed-83c9-1c697a95211f", "event": "message sent", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:41:59.800358Z"}, 
2022-09-27 08:41:59,800.800 DEBUG [139669350102592] {stage} [execution] {"stage_execution_it": 1, "event": "Starting Stage execution", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.800803Z"}, 
2022-09-27 08:41:59,809.809 DEBUG [139669350102592] {stage} [execute] {"stage_id": 1, "event": "Executing Stage", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.808986Z"}, 
2022-09-27 08:41:59,837.837 DEBUG [139669350102592] {stage} [state] {"state_from": "SCHEDULED", "state_to": "RUNNING", "event": "stagexecution changed state", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:41:59.837364Z"}, 
2022-09-27 08:41:59,849.849 INFO [139669350102592] {stage} [execute] {"stage_execution_id": 1, "stage_name": "stage-get-etc-passwd", "status": "success", "event": "stage execution executed", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:41:59.849495Z"}, 
2022-09-27 08:41:59,880.880 INFO [139669790400960] {listener} [start] {"queue": "cryton_core.control.request", "event": "Queue declared and consuming", "logger": "cryton-core-debug", "level": "info", "timestamp": "2022-09-27T08:41:59.880639Z"}, 
2022-09-27 08:42:00,034.034 DEBUG [139669460739648] {step} [_prepare_execution] {"step_id": 1, "event": "Executing Step", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:42:00.034441Z"}, 
2022-09-27 08:42:00,055.055 DEBUG [139669460739648] {step} [state] {"state_from": "PENDING", "state_to": "STARTING", "event": "stepexecution changed state", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T08:42:00.055558Z"},

Cryton Core - Step execution timeout

2022-09-27 10:12:17,430.430 DEBUG [139669460739648] {step} [state] {"state_from": "STARTING", "state_to": "ERROR", "event": "stepexecution changed state", "logger": "cryton-core-debug", "level": "debug", "timestamp": "2022-09-27T10:12:17.430772Z"}, 
2022-09-27 10:12:17,433.433 ERROR [139669460739648] {exceptions} [__init__] {"message": "No response from Worker.", "status": "fail", "event": "Rabbit connection failed", "logger": "cryton-core-debug", "level": "error", "timestamp": "2022-09-27T10:12:17.433824Z"}, 
Traceback (most recent call last):
  File "/usr/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/home/sad/dev/cryton/cryton-core/cryton_core/lib/util/util.py", line 388, in run_step_executions
    step_execution.execute(channel)
  File "/home/sad/dev/cryton/cryton-core/cryton_core/lib/models/step.py", line 1123, in execute
    correlation_id = self.send_step_execution_request(rabbit_channel, message_body, reply_queue, target_queue)
  File "/home/sad/dev/cryton/cryton-core/cryton_core/lib/models/step.py", line 740, in send_step_execution_request
    raise exceptions.RabbitConnectionError("No response from Worker.")
cryton_core.lib.util.exceptions.RabbitConnectionError: {'message': 'No response from Worker.'}
Exception in thread Thread-23 (run_step_executions):
Traceback (most recent call last):
  File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/home/sad/dev/cryton/cryton-core/cryton_core/lib/util/util.py", line 388, in run_step_executions
    step_execution.execute(channel)
  File "/home/sad/dev/cryton/cryton-core/cryton_core/lib/models/step.py", line 1123, in execute
    correlation_id = self.send_step_execution_request(rabbit_channel, message_body, reply_queue, target_queue)
  File "/home/sad/dev/cryton/cryton-core/cryton_core/lib/models/step.py", line 740, in send_step_execution_request
    raise exceptions.RabbitConnectionError("No response from Worker.")
cryton_core.lib.util.exceptions.RabbitConnectionError: {'message': 'No response from Worker.'}