search

project-receptor / python-receptor

Project Receptor is a flexible multi-service relayer with remote execution and orchestration capabilities linking controllers with executors across a mesh of nodes.
Other
32 stars 21 forks source link

Receptor seems to be sending response to wrong nodes #156

Closed elyezer closed 4 years ago

elyezer commented 4 years ago

Considering a 3 nodes mesh:

$ poetry run receptor --debug --node-id=controller -d /tmp/controller controller --listen=receptor://127.0.0.1:9999
$ poetry run receptor --debug --node-id=node-a -d /tmp/node-a node --listen=receptor://127.0.0.1:9998 --peer=receptor://localhost:9999
$ poetry run receptor --debug --node-id=node-b d /tmp/node-b node --listen=receptor://127.0.0.1:9997 --peer=receptor://localhost:9998

Run two ping process in parallel connecting to the controller node, where one targets node-b and the other targets node-c. Observe on the output that WARNING messages are raised saying that a response was received but without having the send record. Also the ping processes continued to be running which means the finished message was not received:

$ poetry run receptor -d /tmp/ping-b ping --peer=receptor://127.0.0.1:9999 --delay 0 --count 10 node-b  
{"initial_time": "2020-03-06T18:27:28.120859", "response_time": "2020-03-06 18:27:28.156398", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.125913", "response_time": "2020-03-06 18:27:28.172401", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.133262", "response_time": "2020-03-06 18:27:28.188726", "active_work": []}
WARNING 2020-03-06 13:27:28,207  receptor Received response to 9762e4e9-3fba-414c-9e4f-496ca0382634 but no record of sent message.
{"initial_time": "2020-03-06T18:27:28.140208", "response_time": "2020-03-06 18:27:28.205756", "active_work": []}
WARNING 2020-03-06 13:27:28,232  receptor Received response to 0e5de5d0-9c3e-40e0-b0db-3672c1b3399b but no record of sent message.
WARNING 2020-03-06 13:27:28,244  receptor Received response to 327ec7dc-d779-451e-988d-ba01e99bb36d but no record of sent message.
WARNING 2020-03-06 13:27:28,250  receptor Received response to c7547678-997e-4c38-8b29-d243d9e0ca4b but no record of sent message.
{"initial_time": "2020-03-06T18:27:28.163389", "response_time": "2020-03-06 18:27:28.237886", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.170925", "response_time": "2020-03-06 18:27:28.246019", "active_work": []}
^C
$ poetry run receptor -d /tmp/ping-a ping --peer=receptor://127.0.0.1:9999 --delay 0 --count 10 node-a  
{"initial_time": "2020-03-06T18:27:28.124886", "response_time": "2020-03-06 18:27:28.158935", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.130734", "response_time": "2020-03-06 18:27:28.164155", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.138053", "response_time": "2020-03-06 18:27:28.179573", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.146100", "response_time": "2020-03-06 18:27:28.192977", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.158007", "response_time": "2020-03-06 18:27:28.206066", "active_work": []}
{"initial_time": "2020-03-06T18:27:28.162428", "response_time": "2020-03-06 18:27:28.211155", "active_work": []}
WARNING 2020-03-06 13:27:28,237  receptor Received response to acccd167-2361-4b85-8d86-655bf1c70489 but no record of sent message.
WARNING 2020-03-06 13:27:28,247  receptor Received response to 2624d5ed-6815-481a-b16a-ef13844087ac but no record of sent message.
WARNING 2020-03-06 13:27:28,252  receptor Received response to 2248820e-0009-42f6-91b6-93cce83ef8df but no record of sent message.
WARNING 2020-03-06 13:27:28,256  receptor Received response to ebd639c8-1d23-4757-8270-247a1b357257 but no record of sent message.
^C
matburt commented 4 years ago

I'd love to see this tried against #130

elyezer commented 4 years ago

I've run the same scenario again but now captured the controller and nodes logs:

Controler:

DEBUG 2020-03-06 13:40:38,739 controller base Unencrypted connection with ('127.0.0.1', 49446).
DEBUG 2020-03-06 13:40:38,739 controller base waiting for HI
DEBUG 2020-03-06 13:40:38,740 controller base sending HI
DEBUG 2020-03-06 13:40:38,740 controller base sending routes
DEBUG 2020-03-06 13:40:38,740 controller receptor Emitting Route Advertisements, excluding set()
DEBUG 2020-03-06 13:40:38,743 controller base starting normal loop
DEBUG 2020-03-06 13:40:38,743 controller receptor spawning message_handler
DEBUG 2020-03-06 13:40:38,743 controller base Watching queue <receptor.connection.sock.RawSocket object at 0x7fb56ffb4c50>
DEBUG 2020-03-06 13:40:38,745 controller receptor message_handler: FramedMessage(msg_id=128038431670327291444162247854347927885, header={'cmd': 'ROUTE', 'id': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12, 'ephemeral': True}, 'groups': [], 'edges': [['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=None)
DEBUG 2020-03-06 13:40:38,745 controller receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller'}
DEBUG 2020-03-06 13:40:38,746 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01;\x97^D\xc5\xc3\x99KS\x8e\xe1j\xecR%\xf8\x87{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'
DEBUG 2020-03-06 13:40:38,746 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01;\x90F\x1d}JZIS\xab\xb0\x19[\x13\xca\x07\x8f{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'
DEBUG 2020-03-06 13:40:38,747 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01\x03\x0f\x8f\x03\xba\xe8\x01J\x89\x8a\xfb\xce\xd0\x01\x1b\xb4\xa0{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'
DEBUG 2020-03-06 13:40:38,751 controller base Unencrypted connection with ('127.0.0.1', 49448).
DEBUG 2020-03-06 13:40:38,751 controller base waiting for HI
DEBUG 2020-03-06 13:40:38,752 controller base sending HI
DEBUG 2020-03-06 13:40:38,752 controller base sending routes
DEBUG 2020-03-06 13:40:38,752 controller receptor Emitting Route Advertisements, excluding set()
DEBUG 2020-03-06 13:40:38,757 controller base starting normal loop
DEBUG 2020-03-06 13:40:38,757 controller receptor spawning message_handler
DEBUG 2020-03-06 13:40:38,757 controller receptor message_handler: FramedMessage(msg_id=177202788294300867399896742248428322357, header={'cmd': 'ROUTE', 'id': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12, 'ephemeral': True}, 'groups': [], 'edges': [['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=None)
DEBUG 2020-03-06 13:40:38,758 controller receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller'}
DEBUG 2020-03-06 13:40:38,758 controller base Watching queue <receptor.connection.sock.RawSocket object at 0x7fb56ffdc450>
DEBUG 2020-03-06 13:40:38,759 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01;\x04_\x19C\xf4\xb8D\x0c\x84v\xf2\x16S\xbbn\xc6{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'
DEBUG 2020-03-06 13:40:38,760 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01;\xab\xb2V\xa4\xf3)N\xc1\xa7:t\xca\xc9\xf2\xfdY{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'
DEBUG 2020-03-06 13:40:38,761 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01\x03K\xad\x93\xb4\x82+C\xba\x93=\x1d_arx\xb0{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'
DEBUG 2020-03-06 13:40:38,851 controller receptor message_handler: FramedMessage(msg_id=31811002701553796399857344553738974372, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "f71adbe2-3c87-47e7-bd74-47b34ea13102", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.840457", "raw_payload": "2020-03-06T18:40:38.840457", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,852 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,852 controller router Forwarding frame 31811002701553796399857344553738974372 to node-a
DEBUG 2020-03-06 13:40:38,856 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\x17\xee\x93\x861\xb5I\x9a\xab\x80W \xf7\x164\xa4{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\x17\xee\x93\x861\xb5I\x9a\xab\x80W \xf7\x164\xa4{"message_id": "f71adbe2-3c87-47e7-bd74-47b34ea13102", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.840457", "raw_payload": "2020-03-06T18:40:38.840457", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,859 controller receptor message_handler: FramedMessage(msg_id=199466449140298318971827489544092947282, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "a0c6af36-248b-4654-a403-98a21519178d", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.843720", "raw_payload": "2020-03-06T18:40:38.843720", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,859 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,860 controller router Forwarding frame 199466449140298318971827489544092947282 to node-a
DEBUG 2020-03-06 13:40:38,863 controller receptor message_handler: FramedMessage(msg_id=212737024853927306290654191935680824550, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "ff298562-3efe-46ad-943c-d61b327e5ffb", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.858348", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.840457\\", \\"response_time\\": \\"2020-03-06 18:40:38.858219\\", \\"active_work\\": []}", "directive": null, "in_response_to": "f71adbe2-3c87-47e7-bd74-47b34ea13102", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,863 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,864 controller router Forwarding frame 212737024853927306290654191935680824550 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,864 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\x96\x0f\xd7:\x14\xa1M\xce\x86\xec\xff\xfc(\x0e\x93R{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\x96\x0f\xd7:\x14\xa1M\xce\x86\xec\xff\xfc(\x0e\x93R{"message_id": "a0c6af36-248b-4654-a403-98a21519178d", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.843720", "raw_payload": "2020-03-06T18:40:38.843720", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,866 controller receptor message_handler: FramedMessage(msg_id=193161040306420869303950570501631469935, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "08cc2897-b998-44db-ad32-8a1608170a58", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.848420", "raw_payload": "2020-03-06T18:40:38.848420", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,867 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,867 controller router Forwarding frame 193161040306420869303950570501631469935 to node-a
DEBUG 2020-03-06 13:40:38,869 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\xa0\x0b\xa9 \x014C\x14\xba\x85P\x8c6\xb6D\xe6{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xa0\x0b\xa9 \x014C\x14\xba\x85P\x8c6\xb6D\xe6{"message_id": "ff298562-3efe-46ad-943c-d61b327e5ffb", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.858348", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.840457\\", \\"response_time\\": \\"2020-03-06 18:40:38.858219\\", \\"active_work\\": []}", "directive": null, "in_response_to": "f71adbe2-3c87-47e7-bd74-47b34ea13102", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,870 controller receptor message_handler: FramedMessage(msg_id=37181601294526994548471001456494144918, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "e0ac0567-9349-493d-a6b6-0bf0bf46be1d", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.865658", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.843720\\", \\"response_time\\": \\"2020-03-06 18:40:38.865587\\", \\"active_work\\": []}", "directive": null, "in_response_to": "a0c6af36-248b-4654-a403-98a21519178d", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,870 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,870 controller router Forwarding frame 37181601294526994548471001456494144918 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,873 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\x91Qv\x91\xc0\xbdH\x7f\x96(\x11\xc3\x041io{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\x91Qv\x91\xc0\xbdH\x7f\x96(\x11\xc3\x041io{"message_id": "08cc2897-b998-44db-ad32-8a1608170a58", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.848420", "raw_payload": "2020-03-06T18:40:38.848420", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,874 controller receptor message_handler: FramedMessage(msg_id=266147695619547756938544810870869362352, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "92613b89-c421-4168-8ee3-bb18a849ff1f", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.852271", "raw_payload": "2020-03-06T18:40:38.852271", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,874 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,874 controller router Forwarding frame 266147695619547756938544810870869362352 to node-a
DEBUG 2020-03-06 13:40:38,876 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\x1b\xf8\xeazy\xedI>\xb4\'d\xb6\x80Vm\x96{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\x1b\xf8\xeazy\xedI>\xb4\'d\xb6\x80Vm\x96{"message_id": "e0ac0567-9349-493d-a6b6-0bf0bf46be1d", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.865658", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.843720\\", \\"response_time\\": \\"2020-03-06 18:40:38.865587\\", \\"active_work\\": []}", "directive": null, "in_response_to": "a0c6af36-248b-4654-a403-98a21519178d", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,877 controller receptor message_handler: FramedMessage(msg_id=314197810552239129117826376669342378528, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "0e5682b6-d3a3-4c16-9d21-f5978917f965", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.874882", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.848420\\", \\"response_time\\": \\"2020-03-06 18:40:38.874822\\", \\"active_work\\": []}", "directive": null, "in_response_to": "08cc2897-b998-44db-ad32-8a1608170a58", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,878 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,878 controller router Forwarding frame 314197810552239129117826376669342378528 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,878 controller receptor message_handler: FramedMessage(msg_id=19514890540755347965401420351227112731, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "34108e58-48dc-422a-b9ba-415960a0219b", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.857175", "raw_payload": "2020-03-06T18:40:38.857175", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,878 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,878 controller router Forwarding frame 19514890540755347965401420351227112731 to node-a
DEBUG 2020-03-06 13:40:38,879 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\xc8:.\x81l:F&\xbb\x94\x90\x88;\xd8\x86\xb0{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\xc8:.\x81l:F&\xbb\x94\x90\x88;\xd8\x86\xb0{"message_id": "92613b89-c421-4168-8ee3-bb18a849ff1f", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.852271", "raw_payload": "2020-03-06T18:40:38.852271", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,880 controller receptor message_handler: FramedMessage(msg_id=304365177226833867948004589269207701424, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "1aad5433-d087-47ab-b840-be2230faf7b6", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.863523", "raw_payload": "2020-03-06T18:40:38.863523", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,881 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,881 controller router Forwarding frame 304365177226833867948004589269207701424 to node-a
DEBUG 2020-03-06 13:40:38,883 controller receptor message_handler: FramedMessage(msg_id=287983166690156464311904418861255058446, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "0cb84377-d48e-49e1-8f5c-22fa7cfd8357", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.879843", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.852271\\", \\"response_time\\": \\"2020-03-06 18:40:38.879796\\", \\"active_work\\": []}", "directive": null, "in_response_to": "92613b89-c421-4168-8ee3-bb18a849ff1f", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,883 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,883 controller router Forwarding frame 287983166690156464311904418861255058446 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,884 controller receptor message_handler: FramedMessage(msg_id=196158750516082067658122326434648918657, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "44fa80b7-a230-4846-abdf-0d8458877c0f", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.866859", "raw_payload": "2020-03-06T18:40:38.866859", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,885 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,885 controller router Forwarding frame 196158750516082067658122326434648918657 to node-a
DEBUG 2020-03-06 13:40:38,886 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\xec`L\x14\x02\xddN/\x92\xf6\xb6\xb2\x91&\xaa {"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xec`L\x14\x02\xddN/\x92\xf6\xb6\xb2\x91&\xaa {"message_id": "0e5682b6-d3a3-4c16-9d21-f5978917f965", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.874882", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.848420\\", \\"response_time\\": \\"2020-03-06 18:40:38.874822\\", \\"active_work\\": []}", "directive": null, "in_response_to": "08cc2897-b998-44db-ad32-8a1608170a58", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,887 controller receptor message_handler: FramedMessage(msg_id=26364922314038397895059331456717319774, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "eebd4d92-990f-4ecc-ab65-8a2f744c34e6", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.869951", "raw_payload": "2020-03-06T18:40:38.869951", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,887 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,887 controller router Forwarding frame 26364922314038397895059331456717319774 to node-a
DEBUG 2020-03-06 13:40:38,887 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\x0e\xaency\xefKQ\x92\x0e\xfa\x0b2U-\x1b{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\x0e\xaency\xefKQ\x92\x0e\xfa\x0b2U-\x1b{"message_id": "34108e58-48dc-422a-b9ba-415960a0219b", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.857175", "raw_payload": "2020-03-06T18:40:38.857175", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,889 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\xd8\xa7\x8aY\x04\x8cL\xb2\xb8"\xc0@a\xc1d\x0e{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xd8\xa7\x8aY\x04\x8cL\xb2\xb8"\xc0@a\xc1d\x0e{"message_id": "0cb84377-d48e-49e1-8f5c-22fa7cfd8357", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.879843", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.852271\\", \\"response_time\\": \\"2020-03-06 18:40:38.879796\\", \\"active_work\\": []}", "directive": null, "in_response_to": "92613b89-c421-4168-8ee3-bb18a849ff1f", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,890 controller receptor message_handler: FramedMessage(msg_id=204767261784784588953178892043641814134, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "b1471785-2de5-437d-ad9d-e1a9f4591793", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.872924", "raw_payload": "2020-03-06T18:40:38.872924", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,890 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,890 controller router Forwarding frame 204767261784784588953178892043641814134 to node-a
DEBUG 2020-03-06 13:40:38,891 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\xe4\xfa\x99\xd3\x99?D\x9a\xac\x8a\x9a\x89H\x17W\xb0{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\xe4\xfa\x99\xd3\x99?D\x9a\xac\x8a\x9a\x89H\x17W\xb0{"message_id": "1aad5433-d087-47ab-b840-be2230faf7b6", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.863523", "raw_payload": "2020-03-06T18:40:38.863523", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,891 controller receptor message_handler: FramedMessage(msg_id=3767690221847966417705667275117099793, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "db7e2b15-3d8e-4dda-9738-ae1cbd075cf6", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.888944", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.857175\\", \\"response_time\\": \\"2020-03-06 18:40:38.888861\\", \\"active_work\\": []}", "directive": null, "in_response_to": "34108e58-48dc-422a-b9ba-415960a0219b", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,891 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,892 controller router Forwarding frame 3767690221847966417705667275117099793 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,892 controller receptor message_handler: FramedMessage(msg_id=274594531869313114818188939946408101493, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8']}, payload=bytearray(b'{"message_id": "fa7c289f-7656-4c89-9778-60e67373f06e", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.876252", "raw_payload": "2020-03-06T18:40:38.876252", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,892 controller router Shortest path to node-a with cost 100 is ['node-a', 'controller']
DEBUG 2020-03-06 13:40:38,892 controller router Forwarding frame 274594531869313114818188939946408101493 to node-a
DEBUG 2020-03-06 13:40:38,893 controller receptor message_handler: FramedMessage(msg_id=95077485895039076120193043945185112266, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "7bdf3894-1fec-429f-b40c-453a7f414f21", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.891884", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.863523\\", \\"response_time\\": \\"2020-03-06 18:40:38.891846\\", \\"active_work\\": []}", "directive": null, "in_response_to": "1aad5433-d087-47ab-b840-be2230faf7b6", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,894 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,894 controller router Forwarding frame 95077485895039076120193043945185112266 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,895 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\x93\x92\xcd\x17\xfcyL[\x81]\xc7`\xb8\xcb\x8a\x81{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\x93\x92\xcd\x17\xfcyL[\x81]\xc7`\xb8\xcb\x8a\x81{"message_id": "44fa80b7-a230-4846-abdf-0d8458877c0f", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.866859", "raw_payload": "2020-03-06T18:40:38.866859", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,896 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\x02\xd5\xa1xM\xd2@\xeb\xa0l\xf8B\x0f\x9c\xfb\x11{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\x02\xd5\xa1xM\xd2@\xeb\xa0l\xf8B\x0f\x9c\xfb\x11{"message_id": "db7e2b15-3d8e-4dda-9738-ae1cbd075cf6", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.888944", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.857175\\", \\"response_time\\": \\"2020-03-06 18:40:38.888861\\", \\"active_work\\": []}", "directive": null, "in_response_to": "34108e58-48dc-422a-b9ba-415960a0219b", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,897 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{G\x87A\xf9m\xc4E\x8e\x89\x13\xc2Fp,p\xca{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5G\x87A\xf9m\xc4E\x8e\x89\x13\xc2Fp,p\xca{"message_id": "7bdf3894-1fec-429f-b40c-453a7f414f21", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.891884", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.863523\\", \\"response_time\\": \\"2020-03-06 18:40:38.891846\\", \\"active_work\\": []}", "directive": null, "in_response_to": "1aad5433-d087-47ab-b840-be2230faf7b6", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,898 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\x13\xd5\xb3\x07\xb9GE\x14\xbf`1\x12\xac`n^{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\x13\xd5\xb3\x07\xb9GE\x14\xbf`1\x12\xac`n^{"message_id": "eebd4d92-990f-4ecc-ab65-8a2f744c34e6", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.869951", "raw_payload": "2020-03-06T18:40:38.869951", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,899 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\x9a\x0c\xbdw\xdb\xd8J\x8f\x8f\xe48o\xf5-\xfcv{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\x9a\x0c\xbdw\xdb\xd8J\x8f\x8f\xe48o\xf5-\xfcv{"message_id": "b1471785-2de5-437d-ad9d-e1a9f4591793", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.872924", "raw_payload": "2020-03-06T18:40:38.872924", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,900 controller receptor message_handler: FramedMessage(msg_id=273448609190744187218348022606124111332, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "0dd47e60-320f-44c4-ad46-933968ca2ae9", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.896323", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.866859\\", \\"response_time\\": \\"2020-03-06 18:40:38.896279\\", \\"active_work\\": []}", "directive": null, "in_response_to": "44fa80b7-a230-4846-abdf-0d8458877c0f", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,901 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,901 controller router Forwarding frame 273448609190744187218348022606124111332 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,903 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00\xb7\xce\x94\xfb\xaf\xaa\xaaMD\x891B\x8bwQFu{"sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "route_list": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01M\xce\x94\xfb\xaf\xaa\xaaMD\x891B\x8bwQFu{"message_id": "fa7c289f-7656-4c89-9778-60e67373f06e", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.876252", "raw_payload": "2020-03-06T18:40:38.876252", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,904 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\xcd\xb8IV\n\xcd@\x03\xb0r\x9c\xdf\xe5\xddU\xe4{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xcd\xb8IV\n\xcd@\x03\xb0r\x9c\xdf\xe5\xddU\xe4{"message_id": "0dd47e60-320f-44c4-ad46-933968ca2ae9", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.896323", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.866859\\", \\"response_time\\": \\"2020-03-06 18:40:38.896279\\", \\"active_work\\": []}", "directive": null, "in_response_to": "44fa80b7-a230-4846-abdf-0d8458877c0f", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,904 controller receptor message_handler: FramedMessage(msg_id=310606815070276479989234767562195068607, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "6cc25df9-d321-4993-aaaa-f470b50984cf", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.899151", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.869951\\", \\"response_time\\": \\"2020-03-06 18:40:38.899060\\", \\"active_work\\": []}", "directive": null, "in_response_to": "eebd4d92-990f-4ecc-ab65-8a2f744c34e6", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,905 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,905 controller router Forwarding frame 310606815070276479989234767562195068607 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,906 controller receptor message_handler: FramedMessage(msg_id=68720271794661052341201697300804944706, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "38a027f2-539d-465c-8415-fa779a1f8d8b", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.901942", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.872924\\", \\"response_time\\": \\"2020-03-06 18:40:38.901884\\", \\"active_work\\": []}", "directive": null, "in_response_to": "b1471785-2de5-437d-ad9d-e1a9f4591793", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,906 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,906 controller router Forwarding frame 68720271794661052341201697300804944706 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,907 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\xe9\xac\xb2T\xdd\xd0IU\xb8A\x95\xca\x9c\x1f\xe6\xbf{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xe9\xac\xb2T\xdd\xd0IU\xb8A\x95\xca\x9c\x1f\xe6\xbf{"message_id": "6cc25df9-d321-4993-aaaa-f470b50984cf", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.899151", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.869951\\", \\"response_time\\": \\"2020-03-06 18:40:38.899060\\", \\"active_work\\": []}", "directive": null, "in_response_to": "eebd4d92-990f-4ecc-ab65-8a2f744c34e6", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,908 controller receptor message_handler: FramedMessage(msg_id=308627525242029849068545757702676810591, header={'sender': 'node-a', 'recipient': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'route_list': ['node-a', 'node-a']}, payload=bytearray(b'{"message_id": "8fd7e56d-3b7b-4c7a-9f3e-27259536c253", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.904262", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.876252\\", \\"response_time\\": \\"2020-03-06 18:40:38.904224\\", \\"active_work\\": []}", "directive": null, "in_response_to": "fa7c289f-7656-4c89-9778-60e67373f06e", "ttl": null, "serial": 1, "code": 0}'))
DEBUG 2020-03-06 13:40:38,908 controller router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 1 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']
DEBUG 2020-03-06 13:40:38,908 controller router Forwarding frame 308627525242029849068545757702676810591 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,909 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{3\xb3\n\xfd\n\x1eG\x9c\xbbjA\xf1\x94VCB{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc53\xb3\n\xfd\n\x1eG\x9c\xbbjA\xf1\x94VCB{"message_id": "38a027f2-539d-465c-8415-fa779a1f8d8b", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.901942", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.872924\\", \\"response_time\\": \\"2020-03-06 18:40:38.901884\\", \\"active_work\\": []}", "directive": null, "in_response_to": "b1471785-2de5-437d-ad9d-e1a9f4591793", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,910 controller base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00{\xe8/\x7f\xcf\x04KB\xe8\x88\xfcsN\xc5\xac\x0b_{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a", "controller"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xe8/\x7f\xcf\x04KB\xe8\x88\xfcsN\xc5\xac\x0b_{"message_id": "8fd7e56d-3b7b-4c7a-9f3e-27259536c253", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.904262", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.876252\\", \\"response_time\\": \\"2020-03-06 18:40:38.904224\\", \\"active_work\\": []}", "directive": null, "in_response_to": "fa7c289f-7656-4c89-9778-60e67373f06e", "ttl": null, "serial": 1, "code": 0}'
INFO 2020-03-06 13:40:43,911 controller receptor Removing connection <receptor.connection.sock.RawSocket object at 0x7fb56ffdc450> for node ca8ad9ef-0932-441d-b9c6-8b800b1841f8
INFO 2020-03-06 13:40:43,911 controller receptor Expiring connection ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:43,911 controller receptor Emitting Route Advertisements, excluding set()
DEBUG 2020-03-06 13:40:43,912 controller receptor message_handler: cancel request received
DEBUG 2020-03-06 13:40:43,917 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01\x00\xb4\x19q\xdf\xfa5Ot\xb4\x88\xd7\x04\x84\xcfA\xb9{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'
DEBUG 2020-03-06 13:40:43,918 controller base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01\x00\xcb!\x96y\xa8SB\xa3\x94\xd6\xedh\xf3u\xb2\x1a{"cmd": "ROUTE", "id": "controller", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-a"]}'

Node A:

DEBUG 2020-03-06 13:40:38,746 node-a receptor message_handler: FramedMessage(msg_id=201202898140560532513644994891239258247, header={'cmd': 'ROUTE', 'id': 'controller', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['controller', 'node-a', 100], ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1], ['node-a', 'node-b', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,747 node-a receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller'}
DEBUG 2020-03-06 13:40:38,748 node-a receptor message_handler: FramedMessage(msg_id=20680994043013340249325197734646101152, header={'cmd': 'ROUTE', 'id': 'controller', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,748 node-a receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller'}
DEBUG 2020-03-06 13:40:38,751 node-a base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01A\x0c\xb3\x9e\xbc\xa9\x81L\xcb\x93\xc5\x18\xee\x8f\x91\xf9J{"cmd": "ROUTE", "id": "node-a", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-b", "node-a"]}'
DEBUG 2020-03-06 13:40:38,752 node-a base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01\t\xd75\xf6\xdb\x03\xfbB\xea\xbao\xcc\xbd\x10\x9b\x1eV{"cmd": "ROUTE", "id": "node-a", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-b", "node-a"]}'
DEBUG 2020-03-06 13:40:38,761 node-a receptor message_handler: FramedMessage(msg_id=228223973475939175229485654181216976217, header={'cmd': 'ROUTE', 'id': 'controller', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['controller', 'node-a', 100], ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1], ['node-a', 'node-b', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,761 node-a receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller'}
DEBUG 2020-03-06 13:40:38,762 node-a receptor message_handler: FramedMessage(msg_id=100593362855961559937931099027419592880, header={'cmd': 'ROUTE', 'id': 'controller', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,762 node-a receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller'}
DEBUG 2020-03-06 13:40:38,763 node-a base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01A\x19\x8c\xa2kb\xd9M,\x91\xc9\x87\xf4\x7fu\x1bc{"cmd": "ROUTE", "id": "node-a", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-b", "node-a"]}'
DEBUG 2020-03-06 13:40:38,764 node-a base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01\t\x9c\xb7\xd5\xad3\xf3J\x01\xacW\r\x9a\xa3\xc2\x17\xd1{"cmd": "ROUTE", "id": "node-a", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-b", "node-a"]}'
DEBUG 2020-03-06 13:40:38,857 node-a receptor message_handler: FramedMessage(msg_id=31811002701553796399857344553738974372, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "f71adbe2-3c87-47e7-bd74-47b34ea13102", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.840457", "raw_payload": "2020-03-06T18:40:38.840457", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,858 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,858 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,858 node-a router Sending ff298562-3efe-46ad-943c-d61b327e5ffb to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,859 node-a router Forwarding frame 212737024853927306290654191935680824550 to controller
DEBUG 2020-03-06 13:40:38,862 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\xa0\x0b\xa9 \x014C\x14\xba\x85P\x8c6\xb6D\xe6{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xa0\x0b\xa9 \x014C\x14\xba\x85P\x8c6\xb6D\xe6{"message_id": "ff298562-3efe-46ad-943c-d61b327e5ffb", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.858348", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.840457\\", \\"response_time\\": \\"2020-03-06 18:40:38.858219\\", \\"active_work\\": []}", "directive": null, "in_response_to": "f71adbe2-3c87-47e7-bd74-47b34ea13102", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,865 node-a receptor message_handler: FramedMessage(msg_id=199466449140298318971827489544092947282, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "a0c6af36-248b-4654-a403-98a21519178d", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.843720", "raw_payload": "2020-03-06T18:40:38.843720", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,865 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,865 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,865 node-a router Sending e0ac0567-9349-493d-a6b6-0bf0bf46be1d to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,866 node-a router Forwarding frame 37181601294526994548471001456494144918 to controller
DEBUG 2020-03-06 13:40:38,869 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\x1b\xf8\xeazy\xedI>\xb4\'d\xb6\x80Vm\x96{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\x1b\xf8\xeazy\xedI>\xb4\'d\xb6\x80Vm\x96{"message_id": "e0ac0567-9349-493d-a6b6-0bf0bf46be1d", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.865658", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.843720\\", \\"response_time\\": \\"2020-03-06 18:40:38.865587\\", \\"active_work\\": []}", "directive": null, "in_response_to": "a0c6af36-248b-4654-a403-98a21519178d", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,874 node-a receptor message_handler: FramedMessage(msg_id=193161040306420869303950570501631469935, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "08cc2897-b998-44db-ad32-8a1608170a58", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.848420", "raw_payload": "2020-03-06T18:40:38.848420", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,874 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,874 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,875 node-a router Sending 0e5682b6-d3a3-4c16-9d21-f5978917f965 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,875 node-a router Forwarding frame 314197810552239129117826376669342378528 to controller
DEBUG 2020-03-06 13:40:38,877 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\xec`L\x14\x02\xddN/\x92\xf6\xb6\xb2\x91&\xaa {"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xec`L\x14\x02\xddN/\x92\xf6\xb6\xb2\x91&\xaa {"message_id": "0e5682b6-d3a3-4c16-9d21-f5978917f965", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.874882", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.848420\\", \\"response_time\\": \\"2020-03-06 18:40:38.874822\\", \\"active_work\\": []}", "directive": null, "in_response_to": "08cc2897-b998-44db-ad32-8a1608170a58", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,879 node-a receptor message_handler: FramedMessage(msg_id=266147695619547756938544810870869362352, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "92613b89-c421-4168-8ee3-bb18a849ff1f", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.852271", "raw_payload": "2020-03-06T18:40:38.852271", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,879 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,879 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,880 node-a router Sending 0cb84377-d48e-49e1-8f5c-22fa7cfd8357 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,880 node-a router Forwarding frame 287983166690156464311904418861255058446 to controller
DEBUG 2020-03-06 13:40:38,882 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\xd8\xa7\x8aY\x04\x8cL\xb2\xb8"\xc0@a\xc1d\x0e{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xd8\xa7\x8aY\x04\x8cL\xb2\xb8"\xc0@a\xc1d\x0e{"message_id": "0cb84377-d48e-49e1-8f5c-22fa7cfd8357", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.879843", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.852271\\", \\"response_time\\": \\"2020-03-06 18:40:38.879796\\", \\"active_work\\": []}", "directive": null, "in_response_to": "92613b89-c421-4168-8ee3-bb18a849ff1f", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,888 node-a receptor message_handler: FramedMessage(msg_id=19514890540755347965401420351227112731, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "34108e58-48dc-422a-b9ba-415960a0219b", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.857175", "raw_payload": "2020-03-06T18:40:38.857175", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,888 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,889 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,889 node-a router Sending db7e2b15-3d8e-4dda-9738-ae1cbd075cf6 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,889 node-a router Forwarding frame 3767690221847966417705667275117099793 to controller
DEBUG 2020-03-06 13:40:38,891 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\x02\xd5\xa1xM\xd2@\xeb\xa0l\xf8B\x0f\x9c\xfb\x11{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\x02\xd5\xa1xM\xd2@\xeb\xa0l\xf8B\x0f\x9c\xfb\x11{"message_id": "db7e2b15-3d8e-4dda-9738-ae1cbd075cf6", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.888944", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.857175\\", \\"response_time\\": \\"2020-03-06 18:40:38.888861\\", \\"active_work\\": []}", "directive": null, "in_response_to": "34108e58-48dc-422a-b9ba-415960a0219b", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,891 node-a receptor message_handler: FramedMessage(msg_id=304365177226833867948004589269207701424, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "1aad5433-d087-47ab-b840-be2230faf7b6", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.863523", "raw_payload": "2020-03-06T18:40:38.863523", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,891 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,891 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,892 node-a router Sending 7bdf3894-1fec-429f-b40c-453a7f414f21 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,892 node-a router Forwarding frame 95077485895039076120193043945185112266 to controller
DEBUG 2020-03-06 13:40:38,893 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00mG\x87A\xf9m\xc4E\x8e\x89\x13\xc2Fp,p\xca{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5G\x87A\xf9m\xc4E\x8e\x89\x13\xc2Fp,p\xca{"message_id": "7bdf3894-1fec-429f-b40c-453a7f414f21", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.891884", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.863523\\", \\"response_time\\": \\"2020-03-06 18:40:38.891846\\", \\"active_work\\": []}", "directive": null, "in_response_to": "1aad5433-d087-47ab-b840-be2230faf7b6", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,896 node-a receptor message_handler: FramedMessage(msg_id=196158750516082067658122326434648918657, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "44fa80b7-a230-4846-abdf-0d8458877c0f", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.866859", "raw_payload": "2020-03-06T18:40:38.866859", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,896 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,896 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,896 node-a router Sending 0dd47e60-320f-44c4-ad46-933968ca2ae9 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,896 node-a router Forwarding frame 273448609190744187218348022606124111332 to controller
DEBUG 2020-03-06 13:40:38,898 node-a receptor message_handler: FramedMessage(msg_id=26364922314038397895059331456717319774, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "eebd4d92-990f-4ecc-ab65-8a2f744c34e6", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.869951", "raw_payload": "2020-03-06T18:40:38.869951", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,898 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,899 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,899 node-a router Sending 6cc25df9-d321-4993-aaaa-f470b50984cf to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,899 node-a router Forwarding frame 310606815070276479989234767562195068607 to controller
DEBUG 2020-03-06 13:40:38,900 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\xcd\xb8IV\n\xcd@\x03\xb0r\x9c\xdf\xe5\xddU\xe4{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xcd\xb8IV\n\xcd@\x03\xb0r\x9c\xdf\xe5\xddU\xe4{"message_id": "0dd47e60-320f-44c4-ad46-933968ca2ae9", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.896323", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.866859\\", \\"response_time\\": \\"2020-03-06 18:40:38.896279\\", \\"active_work\\": []}", "directive": null, "in_response_to": "44fa80b7-a230-4846-abdf-0d8458877c0f", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,901 node-a receptor message_handler: FramedMessage(msg_id=204767261784784588953178892043641814134, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "b1471785-2de5-437d-ad9d-e1a9f4591793", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.872924", "raw_payload": "2020-03-06T18:40:38.872924", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,901 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,902 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,902 node-a router Sending 38a027f2-539d-465c-8415-fa779a1f8d8b to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,902 node-a router Forwarding frame 68720271794661052341201697300804944706 to controller
DEBUG 2020-03-06 13:40:38,904 node-a receptor message_handler: FramedMessage(msg_id=274594531869313114818188939946408101493, header={'sender': 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'recipient': 'node-a', 'route_list': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller']}, payload=bytearray(b'{"message_id": "fa7c289f-7656-4c89-9778-60e67373f06e", "sender": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "recipient": "node-a", "message_type": "directive", "timestamp": "2020-03-06T18:40:38.876252", "raw_payload": "2020-03-06T18:40:38.876252", "directive": "receptor:ping", "in_response_to": null, "ttl": 15, "serial": 1, "code": 0}'))
INFO 2020-03-06 13:40:38,904 node-a directive Received ping from ca8ad9ef-0932-441d-b9c6-8b800b1841f8
DEBUG 2020-03-06 13:40:38,904 node-a router Shortest path to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 with cost 101 is ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']
DEBUG 2020-03-06 13:40:38,904 node-a router Sending 8fd7e56d-3b7b-4c7a-9f3e-27259536c253 to ca8ad9ef-0932-441d-b9c6-8b800b1841f8 via controller
DEBUG 2020-03-06 13:40:38,904 node-a router Forwarding frame 308627525242029849068545757702676810591 to controller
DEBUG 2020-03-06 13:40:38,904 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\xe9\xac\xb2T\xdd\xd0IU\xb8A\x95\xca\x9c\x1f\xe6\xbf{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xe9\xac\xb2T\xdd\xd0IU\xb8A\x95\xca\x9c\x1f\xe6\xbf{"message_id": "6cc25df9-d321-4993-aaaa-f470b50984cf", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.899151", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.869951\\", \\"response_time\\": \\"2020-03-06 18:40:38.899060\\", \\"active_work\\": []}", "directive": null, "in_response_to": "eebd4d92-990f-4ecc-ab65-8a2f744c34e6", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,906 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m3\xb3\n\xfd\n\x1eG\x9c\xbbjA\xf1\x94VCB{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc53\xb3\n\xfd\n\x1eG\x9c\xbbjA\xf1\x94VCB{"message_id": "38a027f2-539d-465c-8415-fa779a1f8d8b", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.901942", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.872924\\", \\"response_time\\": \\"2020-03-06 18:40:38.901884\\", \\"active_work\\": []}", "directive": null, "in_response_to": "b1471785-2de5-437d-ad9d-e1a9f4591793", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:38,907 node-a base Sending message b'\x00\x01\x00\x00\x00\x01\x00\x00\x00m\xe8/\x7f\xcf\x04KB\xe8\x88\xfcsN\xc5\xac\x0b_{"sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "route_list": ["node-a", "node-a"]}\x01\x01\x00\x00\x00\x01\x00\x00\x01\xc5\xe8/\x7f\xcf\x04KB\xe8\x88\xfcsN\xc5\xac\x0b_{"message_id": "8fd7e56d-3b7b-4c7a-9f3e-27259536c253", "sender": "node-a", "recipient": "ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "message_type": "response", "timestamp": "2020-03-06T18:40:38.904262", "raw_payload": "{\\"initial_time\\": \\"2020-03-06T18:40:38.876252\\", \\"response_time\\": \\"2020-03-06 18:40:38.904224\\", \\"active_work\\": []}", "directive": null, "in_response_to": "fa7c289f-7656-4c89-9778-60e67373f06e", "ttl": null, "serial": 1, "code": 0}'
DEBUG 2020-03-06 13:40:43,919 node-a receptor message_handler: FramedMessage(msg_id=270007680940811920674508940298436325914, header={'cmd': 'ROUTE', 'id': 'controller', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['controller', 'node-a', 100], ['node-a', 'node-b', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:43,920 node-a receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller'}
DEBUG 2020-03-06 13:40:43,925 node-a base Sending message b'\x02\x01\x00\x00\x00\x01\x00\x00\x01\x06I\xe9\r^\xd6\x03As\xa4\xe67\x93\xfb\xa2+\x1d{"cmd": "ROUTE", "id": "node-a", "capabilities": {"worker_versions": {}, "max_work_threads": 12}, "groups": [], "edges": [["controller", "node-a", 100], ["node-a", "node-b", 1]], "seen": ["ca8ad9ef-0932-441d-b9c6-8b800b1841f8", "controller", "node-b", "node-a"]}'

Node B

DEBUG 2020-03-06 13:40:38,752 node-b receptor message_handler: FramedMessage(msg_id=16883376655167935011702387959238097226, header={'cmd': 'ROUTE', 'id': 'node-a', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['controller', 'node-a', 100], ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1], ['node-a', 'node-b', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-b', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,752 node-b receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller', 'node-b'}
DEBUG 2020-03-06 13:40:38,752 node-b receptor message_handler: FramedMessage(msg_id=286064217652221558889792329375177973334, header={'cmd': 'ROUTE', 'id': 'node-a', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-b', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,753 node-b receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller', 'node-b'}
DEBUG 2020-03-06 13:40:38,764 node-b receptor message_handler: FramedMessage(msg_id=33960915713179185597211436518850501475, header={'cmd': 'ROUTE', 'id': 'node-a', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['controller', 'node-a', 100], ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1], ['node-a', 'node-b', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-b', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,764 node-b receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller', 'node-b'}
DEBUG 2020-03-06 13:40:38,765 node-b receptor message_handler: FramedMessage(msg_id=208314091543354296363585525956802123729, header={'cmd': 'ROUTE', 'id': 'node-a', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-b', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:38,765 node-b receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller', 'node-b'}
DEBUG 2020-03-06 13:40:43,926 node-b receptor message_handler: FramedMessage(msg_id=98243720045343325338294655526321138461, header={'cmd': 'ROUTE', 'id': 'node-a', 'capabilities': {'worker_versions': {}, 'max_work_threads': 12}, 'groups': [], 'edges': [['controller', 'node-a', 100], ['node-a', 'node-b', 1]], 'seen': ['ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'controller', 'node-b', 'node-a']}, payload=None)
DEBUG 2020-03-06 13:40:43,927 node-b receptor Emitting Route Advertisements, excluding {'ca8ad9ef-0932-441d-b9c6-8b800b1841f8', 'node-a', 'controller', 'node-b'}
elyezer commented 4 years ago

@matburt I will try that later, thanks for the suggestion

Update: I could not run with the suggested changes because of some issues found. More information here https://github.com/project-receptor/receptor/pull/130#issuecomment-595930688

ghjm commented 4 years ago

I can't reproduce this in current devel.

elyezer commented 4 years ago

@ghjm are you starting both process at the same time? I had the mesh running and had two terminal windows one with ping node-a and the other with ping node-b and used the group functionality of my terminal emulator to press enter at the same time. That is the way I can reliably reproduce it.

ghjm commented 4 years ago

I used the shell to run them in parallel

poetry run receptor -d /tmp/ping-a ping --peer=receptor://127.0.0.1:9999 --delay 0 --count 10 node-a & poetry run receptor -d /tmp/ping-b ping --peer=receptor://127.0.0.1:9999 --delay 0 --count 10 node-b
elyezer commented 4 years ago

receptor-156

elyezer commented 4 years ago

@ghjm I figured what was happening, I had RECEPTOR_NODE_ID env var set to the same value on both terminals. So this raises a different issue, like receptor accepts the same node ID to be set twice on the network and therefore causes routing issues.

What makes more sense, to create a new issue or edit this one to reflect that?

ghjm commented 4 years ago

I think create a new issue - that's not at all the same as the topic of this issue.

elyezer commented 4 years ago

During exploring this issue more I realized that the reason why I was seeing the behavior mentioned here is due to the fact the same node ID was present on two nodes of the mesh. That caused the issues but is it not because receptor wasn't routing properly.

That said and also based on https://github.com/project-receptor/receptor/issues/156#issuecomment-595982387 I will close this issue and open a new one.

Thanks @ghjm for going through it with me.