Node suddenly starved of peers, eventually found idling
cburgdorf opened this issue · 4 comments
cburgdorf commented
What is wrong?
I let my Node run for a while with latest master + #2039 + #2041 and then this happend (Peer 172.33.0.2 is configured as preferred node)
Logs 👇
I think this section around the big peer drop from 9 to 3 peers is most interesting.
DEBUG 2020-09-12 03:46:38,122 BeamDownloader Pending nodes call to ETHPeer (eth, 63) Session(<Node(0x09eebfe60fe0880f9f561d574711af14918243edcf033cc26278f286ab3f69b7f360887563419d42c4fe374584b13309c1557692a4cbf7aebd46f2435e7b3fb7@124.156.180.196:30303)> UUID('933a4371-d08c-42ec-9e48-7374a028d4d4')) future cancelled
�[1m�[33m WARNING 2020-09-12 03:46:38,130 Multiplexer Timed out waiting for command from Multiplexer[p2p:5,eth:63], exiting...�[0m
DEBUG 2020-09-12 03:46:38,130 Multiplexer Timeout <Multiplexer[p2p:5,eth:63]>:
Traceback (most recent call last):
File "/usr/src/app/trinity/p2p/multiplexer.py", line 357, in _do_multiplexing
await self._handle_commands(msg_stream)
File "/usr/src/app/trinity/p2p/multiplexer.py", line 369, in _handle_commands
async for protocol, cmd in msg_stream:
File "/usr/src/app/trinity/p2p/multiplexer.py", line 62, in stream_transport_messages
msg = await transport.recv()
File "/usr/src/app/trinity/p2p/transport.py", line 244, in recv
header_bytes = await self.read(HEADER_LEN + MAC_LEN)
File "/usr/src/app/trinity/p2p/transport.py", line 236, in read
return await asyncio.wait_for(self._reader.readexactly(n), timeout=CONN_IDLE_TIMEOUT)
File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
�[1m�[33m WARNING 2020-09-12 03:46:38,131 Multiplexer Timed out waiting for command from Multiplexer[p2p:5,eth:63], exiting...�[0m
DEBUG 2020-09-12 03:46:38,131 Multiplexer Timeout <Multiplexer[p2p:5,eth:63]>:
Traceback (most recent call last):
File "/usr/src/app/trinity/p2p/multiplexer.py", line 357, in _do_multiplexing
await self._handle_commands(msg_stream)
File "/usr/src/app/trinity/p2p/multiplexer.py", line 369, in _handle_commands
async for protocol, cmd in msg_stream:
File "/usr/src/app/trinity/p2p/multiplexer.py", line 62, in stream_transport_messages
msg = await transport.recv()
File "/usr/src/app/trinity/p2p/transport.py", line 244, in recv
header_bytes = await self.read(HEADER_LEN + MAC_LEN)
File "/usr/src/app/trinity/p2p/transport.py", line 236, in read
return await asyncio.wait_for(self._reader.readexactly(n), timeout=CONN_IDLE_TIMEOUT)
File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
DEBUG 2020-09-12 03:46:38,197 BeamDownloader beam-queen-urgent-rtt: got 1/1 +1 nodes in 0.795s from <Node(0xcbceb7@172.33.0.2)> (0x2b06)
DEBUG 2020-09-12 03:46:38,197 BeamDownloader spread-beam-update: Urgent node latency=0.795s, update factor 3 to 4
DEBUG 2020-09-12 03:46:38,224 QueeningQueue QueenQueuer is skipping active peer ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>
DEBUG 2020-09-12 03:46:38,225 QueeningQueue QueenQueuer is skipping active peer ETHPeer (eth, 63) <Session <Node(0xf2a91c@95.216.0.79)> f03c81f6-3ada-4610-9d0d-48a5c993d572>
�[1m�[33m WARNING 2020-09-12 03:46:38,234 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x816846f582de47c40867833e8b2ef8ae89435a24bf8f227ae7e978ab0ba9baca')] within 600 seconds (took 611.9s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,239 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x82a3f48e053174ab54f89e27c964cf96150cb62e41fcf227e8e88cd8a14678cc')] within 600 seconds (took 687.9s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,240 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x04bee9b999fe8c4ec04e6f252d828676caf76eb1f09f6d0250f36fdb7f5ef51c')] within 600 seconds (took 707.9s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,240 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x648e822dd3cbd3ac6cab44d76eae4b9fad2a10ab308f3e57ab0f938813063976')] within 600 seconds (took 687.0s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,241 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x172b94f36184d736667a629cf19955170eb74720e6b09e76c3cbce77d6f27965')] within 600 seconds (took 625.9s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,242 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0xf018e52cab6883ad01b057936b7978057fd2d04220fb15085824b5695e5c745e')] within 600 seconds (took 686.8s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,244 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x90e32069b7664b4650b27a170a9251437712fedd86d5b11ca3f36c66a2f3d74a')] within 600 seconds (took 643.2s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,244 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0xef9628b0e5e3cea47fa082abe29c2305d0413e880f4613d33894539efbc0990e')] within 600 seconds (took 643.1s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,244 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x0efa54f26a6579dca1b3a9651e8471365e0890355fdef3d884d819eee3086d2e')] within 600 seconds (took 643.2s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:38,245 BeamDownloader Could not collect node data for 1 preview hashes [HexBytes('0x502998dcd6ead1df8d4b11bebdaf6a371784b8c7762d47434d6025d14b36e5e3')] within 600 seconds (took 643.2s)�[0m
DEBUG 2020-09-12 03:46:38,247 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4387e0350>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5c01d4550>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50e8cea90>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50e8cee10>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5c016e6d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,248 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,250 ETHPeerPool Removing ETHPeer (eth, 63) <Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:38,250 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 63) <Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:38,250 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:38,250 BasePeer Tried to disconnect from ETHPeer (eth, 63) <Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14>, but already disconnected
DEBUG 2020-09-12 03:46:38,250 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff466f74310>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff55c6afa50>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,251 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,251 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff466dccf10>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,251 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,251 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff51c5fb9d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,251 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,251 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5c01d4150>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5c01d45d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5c01d4b90>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a3787d90>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ea946510>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,252 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,266 Transport Could not drain writer ([Errno 32] Broken pipe), closing transport writer anyway
DEBUG 2020-09-12 03:46:38,268 Transport Could not drain writer ([Errno 32] Broken pipe), closing transport writer anyway
DEBUG 2020-09-12 03:46:38,270 Connection Removing 'eth' logic from Connection-<Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a>
DEBUG 2020-09-12 03:46:38,275 ExchangeManager Response validation failed for pending NodeDataV65 request from connection Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>: Response contains 1 unexpected nodes
DEBUG 2020-09-12 03:46:38,591 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d0297650>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c0cbd10>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c0cb750>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d015a310>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d009b110>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,591 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,593 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c61a2d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d01abe50>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,593 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,594 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d00a0dd0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,594 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,594 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d00a01d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,594 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,594 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d00a0710>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d00a0c50>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d00c0910>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c341b50>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c3309d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:38,594 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:38,600 ExchangeManager Response validation failed for pending NodeDataV65 request from connection Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>: Response contains 1 unexpected nodes
DEBUG 2020-09-12 03:46:39,484 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50d34d690>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff434c83990>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ebea5fd0>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ebea55d0>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ea8570d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,484 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,485 Connection Removing 'eth' logic from Connection-<Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14>
DEBUG 2020-09-12 03:46:39,485 ETHPeerPool Removing ETHPeer (eth, 65) <Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:39,485 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 65) <Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:39,485 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:39,485 BasePeer Tried to disconnect from ETHPeer (eth, 65) <Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75>, but already disconnected
DEBUG 2020-09-12 03:46:39,486 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50d34d1d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c77f990>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,486 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,486 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff476ad0650>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,486 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,486 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c67b110>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,487 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,487 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4948d6350>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4aa24c610>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a15a8210>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff55c642a50>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c77f450>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4e9c7e9d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,487 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,492 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a8d7f6d0>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50ee83690>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff474c48c90>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff55c5c6b90>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d3a82d90>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,493 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,781 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4aac7cb10>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4aac7c890>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,781 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,781 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50ee83590>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,781 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,781 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff474c48110>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,781 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,781 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff55c5c6dd0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a8d707d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4e82777d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a8d50e50>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a5000c50>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c581d50>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,782 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,782 ExchangeManager Response validation failed for pending NodeDataV65 request from connection Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>: Response contains 1 unexpected nodes
DEBUG 2020-09-12 03:46:39,783 Connection Removing 'eth' logic from Connection-<Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41>
DEBUG 2020-09-12 03:46:39,786 Transport Could not drain writer ([Errno 32] Broken pipe), closing transport writer anyway
DEBUG 2020-09-12 03:46:39,788 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a>
DEBUG 2020-09-12 03:46:39,788 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a>
DEBUG 2020-09-12 03:46:39,788 Connection Removing 'p2p' logic from Connection-<Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a>
DEBUG 2020-09-12 03:46:39,789 ExchangeManager Response validation failed for pending NodeDataV65 request from connection Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>: Response contains 1 unexpected nodes
DEBUG 2020-09-12 03:46:39,790 Connection Removing 'eth' logic from Connection-<Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75>
DEBUG 2020-09-12 03:46:39,792 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a817c050>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c47ab10>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47c573490>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47c573810>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57e0ba6d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,792 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,793 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4885f4490>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a8bc9790>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,793 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,793 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4736179d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,793 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,793 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff491f933d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,793 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,793 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff491f938d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47c573750>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff478807a10>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47880ced0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff55c5809d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47fe90650>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:39,793 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:39,796 ExchangeManager Response validation failed for pending NodeDataV65 request from connection Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>: Response contains 1 unexpected nodes
DEBUG 2020-09-12 03:46:39,804 ExchangeManager Response validation failed for pending NodeDataV65 request from connection Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>: Response contains 1 unexpected nodes
DEBUG 2020-09-12 03:46:39,804 ETHPeerPool Removing ETHPeer (eth, 63) <Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:39,804 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 63) <Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:39,804 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:39,804 BasePeer Tried to disconnect from ETHPeer (eth, 63) <Session <Node(0xd258f1@54.179.45.98)> d47f7d23-a8ab-4922-b81c-54df32180e0a>, but already disconnected
DEBUG 2020-09-12 03:46:39,805 Connection Removing 'eth' logic from Connection-<Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>
DEBUG 2020-09-12 03:46:39,808 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14>
DEBUG 2020-09-12 03:46:39,808 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14>
DEBUG 2020-09-12 03:46:39,808 Connection Removing 'p2p' logic from Connection-<Session <Node(0x20a2a5@18.206.161.247)> 3ad1cee9-1e0a-45e0-805a-838ddfce1f14>
DEBUG 2020-09-12 03:46:39,971 DiscoveryService ============================= Stats =======================
DEBUG 2020-09-12 03:46:39,972 DiscoveryService Routing table has 80 nodes in 256 buckets (4 of which are full), and 828 nodes are in the replacement cache
DEBUG 2020-09-12 03:46:39,972 DiscoveryService ===========================================================
DEBUG 2020-09-12 03:46:40,364 QueeningQueue Peer ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d> is no longer alive, not adding to queue
DEBUG 2020-09-12 03:46:40,365 QueeningQueue Switching queen peer from ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41> to ETHPeer (eth, 63) <Session <Node(0xf2a91c@95.216.0.79)> f03c81f6-3ada-4610-9d0d-48a5c993d572>
DEBUG 2020-09-12 03:46:40,365 QueeningQueue Peer ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41> is no longer alive, not adding to queue
DEBUG 2020-09-12 03:46:40,880 DBManager Server accepted connection: ''
DEBUG 2020-09-12 03:46:40,880 DBManager <trinity.db.manager.DBManager object at 0x7f64b20a0e10>: starting client handler for <socket.socket fd=14, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/trinity/mainnet/ipcs-eth1/db.ipc>
DEBUG 2020-09-12 03:46:40,879 DBClient Opened connection to /trinity/mainnet/ipcs-eth1/db.ipc: <socket.socket fd=22, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0>
DEBUG 2020-09-12 03:46:40,880 DBManager <trinity.db.manager.DBManager object at 0x7f64b20a0e10>: closing client connection: Connection closed
DEBUG 2020-09-12 03:46:40,882 DBClient Opened connection to /trinity/mainnet/ipcs-eth1/db.ipc: <socket.socket fd=22, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0>
DEBUG 2020-09-12 03:46:40,882 DBManager Server accepted connection: ''
DEBUG 2020-09-12 03:46:40,882 DBManager <trinity.db.manager.DBManager object at 0x7f64b20a0e10>: starting client handler for <socket.socket fd=29, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/trinity/mainnet/ipcs-eth1/db.ipc>
DEBUG 2020-09-12 03:46:40,883 DBManager <trinity.db.manager.DBManager object at 0x7f64b20a0e10>: closing client connection: Connection closed
DEBUG 2020-09-12 03:46:40,883 DBClient Opened connection to /trinity/mainnet/ipcs-eth1/db.ipc: <socket.socket fd=22, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0>
DEBUG 2020-09-12 03:46:40,883 DBManager Server accepted connection: ''
DEBUG 2020-09-12 03:46:40,883 DBManager <trinity.db.manager.DBManager object at 0x7f64b20a0e10>: starting client handler for <socket.socket fd=14, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/trinity/mainnet/ipcs-eth1/db.ipc>
DEBUG 2020-09-12 03:46:40,884 DBManager <trinity.db.manager.DBManager object at 0x7f64b20a0e10>: closing client connection: Connection closed
DEBUG 2020-09-12 03:46:40,973 Sync / PeerPool Event loop blocked or overloaded: delay=0.272s, tasks=824
DEBUG 2020-09-12 03:46:40,976 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41>
DEBUG 2020-09-12 03:46:40,977 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41>
DEBUG 2020-09-12 03:46:40,977 Connection Removing 'p2p' logic from Connection-<Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41>
DEBUG 2020-09-12 03:46:40,977 ExchangeManager Response validation failed for pending NodeDataV65 request from connection Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>: Response contains 1 unexpected nodes
DEBUG 2020-09-12 03:46:40,981 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75>
DEBUG 2020-09-12 03:46:40,981 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75>
DEBUG 2020-09-12 03:46:40,981 Connection Removing 'p2p' logic from Connection-<Session <Node(0xf0f660@95.216.70.188)> 03211fbd-8299-4252-82a7-6671dc658b75>
DEBUG 2020-09-12 03:46:41,568 ETHPeerPool Removing ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:41,568 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:41,568 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:41,568 BasePeer Tried to disconnect from ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 578968ce-7545-443e-8e17-5472fdeabd41>, but already disconnected
DEBUG 2020-09-12 03:46:41,581 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>
DEBUG 2020-09-12 03:46:41,581 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>
DEBUG 2020-09-12 03:46:41,582 Connection Removing 'p2p' logic from Connection-<Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>
DEBUG 2020-09-12 03:46:41,593 ETHPeerPool Removing ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:41,593 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:41,593 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:41,593 BasePeer Tried to disconnect from ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d>, but already disconnected
DEBUG 2020-09-12 03:46:41,636 Transport Could not drain writer ([Errno 32] Broken pipe), closing transport writer anyway
DEBUG 2020-09-12 03:46:41,669 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c1dc990>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a207d350>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a207d090>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a207ddd0>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff487383310>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,669 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,670 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ea2df410>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ea08a310>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,670 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,670 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a99e23d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,670 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,671 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a9424cd0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,671 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,671 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a9424190>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff467028210>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff482a96c90>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50cd0d310>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff433ada8d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,671 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,674 Connection Removing 'eth' logic from Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>
DEBUG 2020-09-12 03:46:41,681 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>
DEBUG 2020-09-12 03:46:41,682 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>
DEBUG 2020-09-12 03:46:41,682 Connection Removing 'p2p' logic from Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>
DEBUG 2020-09-12 03:46:41,714 ETHPeerPool Removing ETHPeer (eth, 63) <Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:41,714 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 63) <Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:41,714 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:41,715 BasePeer Tried to disconnect from ETHPeer (eth, 63) <Session <Node(0x09eebf@124.156.180.196)> 933a4371-d08c-42ec-9e48-7374a028d4d4>, but already disconnected
�[1m�[33m WARNING 2020-09-12 03:46:41,754 BeamDownloader Could not collect node data for 21 preview hashes [HexBytes('0xda199c4d270389364c9218a3206db6ed11df999aac2ad3fb8fe8ea09da45da2f'), HexBytes('0x2348654bff1ce330ad0f0646e684bd575714bf17fa86d9c568711c95b5906613')] within 600 seconds (took 710.4s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:41,754 BeamDownloader Could not collect node data for 15 preview hashes [HexBytes('0xe925e10654010297012397cb3136788d8d9d91bf9233f2bf183b990bd3d191ec'), HexBytes('0x15a66e6574736e7fc60484a993c4302649629fbc656c6c6d2ff245d6bb25847c')] within 600 seconds (took 711.1s)�[0m
�[1m�[33m WARNING 2020-09-12 03:46:41,761 BeamDownloader Could not collect node data for 16 preview hashes [HexBytes('0x429579a701f33cf9c0fd859a7f63f837be4f16af8947560c38eeecdbe899a39b'), HexBytes('0xd3005de113521b70bc13d29f21b187b553bb8e19a9690ea3468b6774c8d978ea')] within 600 seconds (took 711.9s)�[0m
INFO 2020-09-12 03:46:41,767 SkeletonSyncer ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d> disconnected while fetching headers
DEBUG 2020-09-12 03:46:41,767 SkeletonSyncer Exiting sync and booting ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d> due to validation error: ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d> gave 0 headers when seeking common meat ancestors from 10844082
DEBUG 2020-09-12 03:46:41,772 SkeletonSyncer Skeleton sync with ETHPeer (eth, 65) <Session <Node(0x325e5e@141.193.159.98)> 18e75e8f-ecad-493a-b222-053dc01a1e4d> ended
DEBUG 2020-09-12 03:46:41,808 BeamDownloader Updating predictive peer count from 4 to 1
DEBUG 2020-09-12 03:46:41,827 Transport Could not drain writer ([Errno 32] Broken pipe), closing transport writer anyway
DEBUG 2020-09-12 03:46:41,828 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff51d3ea610>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff43206ded0>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c2ade10>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff53d71bd50>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c268f90>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,828 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,828 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff51d3eaf10>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4aa8cc7d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,829 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,829 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4aa17cc50>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,829 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,829 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c4797d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,829 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,829 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4866715d0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff51f595110>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a8a5f850>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a8a5fa90>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a9670d90>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ea859290>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:41,829 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:41,832 Connection Removing 'eth' logic from Connection-<Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11>
DEBUG 2020-09-12 03:46:41,841 SkeletonSyncer ETHPeer (eth, 65) <Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180> announced Head TD 17349811489622453697755, which is higher than ours (17349629127190900059469), starting sync
DEBUG 2020-09-12 03:46:41,844 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11>
DEBUG 2020-09-12 03:46:41,844 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11>
DEBUG 2020-09-12 03:46:41,844 Connection Removing 'p2p' logic from Connection-<Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11>
DEBUG 2020-09-12 03:46:41,848 ETHPeerPool Removing ETHPeer (eth, 65) <Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:41,848 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 65) <Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:41,848 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:41,849 BasePeer Tried to disconnect from ETHPeer (eth, 65) <Session <Node(0x42fd07@110.173.59.194)> 026516cf-8dbb-425d-aade-732fc485db11>, but already disconnected
DEBUG 2020-09-12 03:46:41,860 PeerTracker Eth1 Peer Candidate Request: req=24 ret=9 avail=9 total=187
DEBUG 2020-09-12 03:46:41,875 DiscoveryService Found 24 peer candidates, skipped 41
DEBUG 2020-09-12 03:46:41,876 DiscoveryService Broadcasting 24 peer candidates
DEBUG 2020-09-12 03:46:42,631 SkeletonSyncer Requsting chain of headers from ETHPeer (eth, 65) <Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180> starting at #10809137
DEBUG 2020-09-12 03:46:42,633 ETHPeerPool Got 9 peer candidates from backend <trinity.components.builtin.network_db.eth1_peer_db.tracker.EventBusEth1PeerTracker object at 0x7ff5d35f1dd0>
DEBUG 2020-09-12 03:46:42,633 ETHPeerPool Initiating 7 peer connection attempts with 7 open peer slots
DEBUG 2020-09-12 03:46:42,633 ETHPeerPool Got 24 peer candidates from backend <p2p.peer_backend.DiscoveryPeerBackend object at 0x7ff5d35f1e10>
DEBUG 2020-09-12 03:46:42,633 ETHPeerPool Initiating 7 peer connection attempts with 7 open peer slots
DEBUG 2020-09-12 03:46:42,635 ETHPeerPool Connecting to <Node(0x09eebf@124.156.180.196)>...
DEBUG 2020-09-12 03:46:42,636 ETHPeerPool Connecting to <Node(0x20a2a5@18.206.161.247)>...
DEBUG 2020-09-12 03:46:42,636 ETHPeerPool Connecting to <Node(0xd258f1@54.179.45.98)>...
DEBUG 2020-09-12 03:46:42,636 ETHPeerPool Connecting to <Node(0xe85eea@18.189.204.45)>...
DEBUG 2020-09-12 03:46:42,639 ETHPeerPool Connecting to <Node(0xe5b6b7@47.96.84.255)>...
DEBUG 2020-09-12 03:46:42,640 ETHPeerPool Connecting to <Node(0x5c1766@35.246.226.30)>...
DEBUG 2020-09-12 03:46:42,640 ETHPeerPool Connecting to <Node(0x019f6f@222.187.239.223)>...
DEBUG 2020-09-12 03:46:42,641 ETHPeerPool Connecting to <Node(0xcbceb7@172.33.0.2)>...
DEBUG 2020-09-12 03:46:42,641 ETHPeerPool Connecting to <Node(0x0fd93f@23.101.211.229)>...
DEBUG 2020-09-12 03:46:42,642 ETHPeerPool Connecting to <Node(0xd6ac96@104.248.250.108)>...
DEBUG 2020-09-12 03:46:42,645 Transport Could not drain writer ([Errno 32] Broken pipe), closing transport writer anyway
DEBUG 2020-09-12 03:46:42,887 ETHPeerPool Removing ETHPeer (eth, 65) <Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180> from pool: local_reason=None remote_reason=None
DEBUG 2020-09-12 03:46:42,887 PeerTracker Not tracking disconnecting peer ETHPeer (eth, 65) <Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>[outbound] missing disconnect reason
DEBUG 2020-09-12 03:46:42,887 P2PAPI Sending Disconnect to remote peer Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>; reason: CLIENT_QUITTING
DEBUG 2020-09-12 03:46:42,887 BasePeer Tried to disconnect from ETHPeer (eth, 65) <Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>, but already disconnected
DEBUG 2020-09-12 03:46:42,888 wait_first Got CancelledError() waiting for [<Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff59c535310>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff48db8acd0>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff5d0135750>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff494ed4d90>()]>>, <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff57c0d1090>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:42,888 cancel_pending_tasks Cancelled tasks <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:43,360 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50fd86fd0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ea90a250>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:43,360 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:43,360 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff55c7e52d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:43,361 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:43,361 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a4f714d0>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:43,361 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:43,361 wait_first Got CancelledError() waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4736de450>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff50e2c0090>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a5151dd0>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff436f94850>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47cf81e90>()]>>, <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4a9abab50>()]>>], cancelling them all
DEBUG 2020-09-12 03:46:43,361 cancel_pending_tasks Cancelled tasks <Task pending coro=<AsyncioManager.wait_finished() running at /usr/local/lib/python3.7/site-packages/async_service/asyncio.py:280> wait_for=<Future cancelled>>, now waiting for them to return
DEBUG 2020-09-12 03:46:43,383 Sync / PeerPool Event loop blocked or overloaded: delay=0.388s, tasks=721
DEBUG 2020-09-12 03:46:43,383 SkeletonSyncer Header Skeleton Gaps: active=0 queued=0 max=50
DEBUG 2020-09-12 03:46:43,383 BaseBodyChainSyncer (progress, queued, max) of bodies: [(0, 0, 2048)]; Linearizing for import (0 unready, 0 ready); Importing? True
DEBUG 2020-09-12 03:46:43,385 Connection Removing 'eth' logic from Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>
DEBUG 2020-09-12 03:46:43,388 Connection Removing 'eth1-chain-info' logic from Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>
DEBUG 2020-09-12 03:46:43,388 Connection Removing 'eth1-head-info' logic from Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>
DEBUG 2020-09-12 03:46:43,389 Connection Removing 'p2p' logic from Connection-<Session <Node(0xb9d46c@52.40.16.94)> 1b791e57-c3a2-4d87-a494-66decec6d180>
DEBUG 2020-09-12 03:46:43,539 ETHPeerPool Connecting to <Node(0xad612e@104.131.99.64)>...
DEBUG 2020-09-12 03:46:43,550 Connection Adding 'p2p' logic to Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>
DEBUG 2020-09-12 03:46:43,551 Connection Adding 'eth1-head-info' logic to Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>
DEBUG 2020-09-12 03:46:43,551 Connection Adding 'eth1-chain-info' logic to Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>
DEBUG 2020-09-12 03:46:43,552 ResponseCandidateStream Launching <ResponseCandidateStream(Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>, <class 'trinity.protocol.eth.commands.BlockBodiesV65'>)>
DEBUG 2020-09-12 03:46:43,553 ResponseCandidateStream Launching <ResponseCandidateStream(Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>, <class 'trinity.protocol.eth.commands.BlockHeadersV65'>)>
DEBUG 2020-09-12 03:46:43,554 ResponseCandidateStream Launching <ResponseCandidateStream(Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>, <class 'trinity.protocol.eth.commands.NodeDataV65'>)>
DEBUG 2020-09-12 03:46:43,554 ResponseCandidateStream Launching <ResponseCandidateStream(Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>, <class 'trinity.protocol.eth.commands.ReceiptsV65'>)>
DEBUG 2020-09-12 03:46:43,555 Connection Adding 'eth' logic to Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>
DEBUG 2020-09-12 03:46:43,556 ResponseCandidateStream Launching <ResponseCandidateStream(Connection-<Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>, <class 'trinity.protocol.eth.commands.PooledTransactionsV65'>)>
DEBUG 2020-09-12 03:46:43,557 BasePeer Peer ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186> is running but won't start streaming messages until start_protocol_streams() is called
DEBUG 2020-09-12 03:46:43,558 BasePeerBootManager Skipping DAO fork block check as ForkID was validated during handshake of (eth, 65)
INFO 2020-09-12 03:46:43,567 ETHPeerPool Adding ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186> to pool
DEBUG 2020-09-12 03:46:43,567 PeerTracker tracking outbound peer connection: ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>
DEBUG 2020-09-12 03:46:43,568 BasePeer Starting protocol streams for ETHPeer (eth, 65) <Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186>. Subscribers: [<trinity.components.builtin.network_db.eth1_peer_db.tracker.EventBusEth1PeerTracker object at 0x7ff5d35f1dd0>, <trinity.protocol.eth.peer.ETHPeerPoolEventServer object at 0x7ff5d39f2190>, <trinity.protocol.eth.monitors.ETHChainTipMonitor object at 0x7ff55c791710>, <trinity.sync.common.headers.HeaderMeatSyncer object at 0x7ff476c83450>, <trinity.sync.full.chain.RegularChainBodySyncer object at 0x7ff5c3f1f490>, <trinity.sync.beam.state.BeamDownloader object at 0x7ff59c5c1b50>, <trinity.sync.beam.queen.QueeningQueue object at 0x7ff55f8a76d0>]
DEBUG 2020-09-12 03:46:43,577 ETHPeerPool Connecting to <Node(0xcf065a@188.166.0.226)>...
DEBUG 2020-09-12 03:46:43,602 Connection Adding 'p2p' logic to Connection-<Session <Node(0x5c1766@35.246.226.30)> 333ee393-9420-4d9c-b4d2-e3c910764443>
DEBUG 2020-09-12 03:46:43,603 Connection Adding 'eth1-head-info' logic to Connection-<Session <Node(0x5c1766@35.246.226.30)> 333ee393-9420-4d9c-b4d2-e3c910764443>
DEBUG 2020-09-12 03:46:43,603 Connection Adding 'eth1-chain-info' logic to Connection-<Session <Node(0x5c1766@35.246.226.30)> 333ee393-9420-4d9c-b4d2-e3c910764443>
DEBUG 2020-09-12 03:46:43,610 ResponseCandidateStream Launching <ResponseCandidateStream(Connection-<Session <Node(0x5c1766@35.246.226.30)> 333ee393-9420-4d9c-b4d2-e3c910764443>, <class 'trinity.protocol.eth.commands.BlockBodiesV65'>)>
DEBUG 2020-09-12 03:46:43,612 PeerRequestHandler ETHProxyPeer <Session <Node(0xcbceb7@172.33.0.2)> 288cba5d-4d79-4d78-8354-7c479a05f186> requested headers: BlockHeadersQuery(block_number_or_hash=10518527, max_headers=1, skip=0, reverse=False)
How can it be fixed
Needs investigation
gsalgado commented
That TimeoutError was caught, so I don't think it'd have caused the issue we're seeing here. What looks suspicious is the fact that the peer pool last attempted to connect to nodes at 03:47:13. After that it was still periodically reporting the peer count, but never logged anything other than that. Maybe its run() method exited but the service continued running because the reporting (daemon) task was still alive
gsalgado commented
Oh, and I just noticed this in your logs:
DEBUG 2020-09-12 03:46:45,498 BasePeer Peer ETHPeer (eth, 63) <Session <Node(0x019f6f@222.187.239.223)> 4112c953-a4fb-4e2b-9d40-3dcbf9400993> is running but won't start streaming messages until start_protocol_streams() is called
�[1m�[31m ERROR 2020-09-12 03:46:45,501 asyncio Task was destroyed but it is pending!
task: <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4328a2b90>()]>>�[0m
�[1m�[31m ERROR 2020-09-12 03:46:45,501 asyncio Task was destroyed but it is pending!
task: <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47c2d6510>()]> cb=[_wait.<locals>._on_completion() at /usr/local/lib/python3.7/asyncio/tasks.py:466]>�[0m
�[1m�[31m ERROR 2020-09-12 03:46:45,501 wait_first Unexpected error waiting for [<Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4ca8993d0>()]>>], cancelling them all
Traceback (most recent call last):
File "/usr/src/app/trinity/p2p/asyncio_utils.py", line 54, in wait_first
done, pending = await asyncio.wait(tasks, return_when=asyncio.FIRST_COMPLETED)
GeneratorExit�[0m
DEBUG 2020-09-12 03:46:45,515 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled>>, now waiting for them to return
�[1m�[31m ERROR 2020-09-12 03:46:45,519 asyncio Task was destroyed but it is pending!
task: <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future cancelled> cb=[_wait.<locals>._on_completion() at /usr/local/lib/python3.7/asyncio/tasks.py:466]>�[0m
�[1m�[31m ERROR 2020-09-12 03:46:45,519 asyncio Task was destroyed but it is pending!
task: <Task pending coro=<wait_first() running at /usr/src/app/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff4328a2110>()]>>�[0m
�[1m�[31m ERROR 2020-09-12 03:46:45,520 wait_first Unexpected error waiting for [<Task pending coro=<_never_ending_coro() done, defined at /usr/src/app/trinity/p2p/logic.py:125> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47c2d6510>()]>>], cancelling them all
Traceback (most recent call last):
File "/usr/src/app/trinity/p2p/asyncio_utils.py", line 54, in wait_first
done, pending = await asyncio.wait(tasks, return_when=asyncio.FIRST_COMPLETED)
GeneratorExit�[0m
DEBUG 2020-09-12 03:46:45,520 cancel_pending_tasks Cancelled tasks <Task pending coro=<_never_ending_coro() done, defined at /usr/src/app/trinity/p2p/logic.py:125> wait_for=<Future cancelled>>, now waiting for them to return
�[1m�[31m ERROR 2020-09-12 03:46:45,520 asyncio Task was destroyed but it is pending!
task: <Task pending coro=<_never_ending_coro() running at /usr/src/app/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff47c2d6f50>()]>>�[0m
The fact that it happens just a few seconds after the TimeoutError from the multiplexer is probably not a coincidence. Will need to dig further
Also, it might be the same cause as #1895
gsalgado commented
Just saw this on master as well. In #1895 (like here) it was not causing trinity to crash, but the daemon task that's running the crashing code these seems to get stuck, so in #1895 we stop accepting inbound peer connections and here we stop attempting to connect to more peers. That means we end up with a running trinity instance that will eventually end up with no peer connections
INFO 2020-09-14 14:10:33,951 HeaderOnlyPersist Imported 194 headers in 0.39 seconds, new head: <BlockHeader #10848179 54cc5738>
ERROR 2020-09-14 14:10:34,612 asyncio Task was destroyed but it is pending!
task: <Task pending name='Application/eth1-head-info/no-behaviors-fut' coro=<_never_ending_coro() running at /home/salgado/src/snakecharmers/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fd1cc3b3160>()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.8/asyncio/tasks.py:507]>
ERROR 2020-09-14 14:10:34,612 asyncio Task was destroyed but it is pending!
task: <Task pending name='Application/eth1-head-info/apply/<Node(0xaf89b6@111.75.82.242)>' coro=<wait_first() running at /home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fd1d430e640>()]>>
ERROR 2020-09-14 14:10:34,612 asyncio Task was destroyed but it is pending!
task: <Task pending name='Application/eth1-chain-info/no-behaviors-fut' coro=<_never_ending_coro() running at /home/salgado/src/snakecharmers/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fd1cc3b36d0>()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.8/asyncio/tasks.py:507]>
ERROR 2020-09-14 14:10:34,612 asyncio Task was destroyed but it is pending!
task: <Task pending name='Application/eth1-chain-info/apply/<Node(0xaf89b6@111.75.82.242)>' coro=<wait_first() running at /home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py:54> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fd1cc3df670>()]>>
ERROR 2020-09-14 14:10:34,612 asyncio Task was destroyed but it is pending!
task: <Task pending name='CommandHandler/ETHHeadInfoTracker/apply' coro=<_never_ending_coro() running at /home/salgado/src/snakecharmers/trinity/p2p/logic.py:126> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fd1cc1686a0>()]>>
Exception ignored in: <coroutine object wait_first at 0x7fd1dc3bc3c0>
Traceback (most recent call last):
File "/home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py", line 69, in wait_first
ERROR 2020-09-14 14:10:34,612 wait_first Unexpected error waiting for [<Task pending name='Application/eth1-head-info/no-behaviors-fut' coro=<_never_ending_coro() done, defined at /home/salgado/src/snakecharmers/trinity/p2p/logic.py:125> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fd1cc3b3160>()]>>], cancelling them all
Traceback (most recent call last):
File "/home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py", line 54, in wait_first
done, pending = await asyncio.wait(tasks, return_when=asyncio.FIRST_COMPLETED)
GeneratorExit
raise done_task.exception()
File "/usr/lib/python3.8/contextlib.py", line 189, in __aexit__
await self.gen.athrow(typ, value, traceback)
File "/home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py", line 100, in cancel_pending_tasks
done, pending = await asyncio.wait(cancelled, timeout=timeout)
File "/usr/lib/python3.8/asyncio/tasks.py", line 418, in wait
loop = events.get_running_loop()
RuntimeError: no running event loop
Exception ignored in: <coroutine object wait_first at 0x7fd1d40c5bc0>
Traceback (most recent call last):
File "/home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py", line 69, in wait_first
ERROR 2020-09-14 14:10:34,617 wait_first Unexpected error waiting for [<Task pending name='Application/eth1-chain-info/no-behaviors-fut' coro=<_never_ending_coro() done, defined at /home/salgado/src/snakecharmers/trinity/p2p/logic.py:125> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fd1cc3b36d0>()]>>], cancelling them all
Traceback (most recent call last):
File "/home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py", line 54, in wait_first
done, pending = await asyncio.wait(tasks, return_when=asyncio.FIRST_COMPLETED)
GeneratorExit
raise done_task.exception()
File "/usr/lib/python3.8/contextlib.py", line 189, in __aexit__
await self.gen.athrow(typ, value, traceback)
File "/home/salgado/src/snakecharmers/trinity/p2p/asyncio_utils.py", line 100, in cancel_pending_tasks
done, pending = await asyncio.wait(cancelled, timeout=timeout)
File "/usr/lib/python3.8/asyncio/tasks.py", line 418, in wait
loop = events.get_running_loop()
RuntimeError: no running event loop
INFO 2020-09-14 14:10:35,080 HeaderOnlyPersist Imported 194 headers in 0.37 seconds, new head: <BlockHeader #10848373 16d8c47e>
Oh, and in my case I didn't get the TimeoutError on the multiplexer as reported by @cburgdorf, so that's probably unrelated
