RuntimeError: task group is closed, handling 'server.add_peer'

[SomberNight]

On commit 9b22fd3

{"log":"INFO:PeerManager:accepted add_peer request from 81.183.169.117 for bitnode.pw\n","stream":"stdout","time":"2018-08-08T13:58:11.442612629Z"}
{"log":"INFO:PeerManager:accepted new peer bitnode.pw from 81.183.169.117\n","stream":"stdout","time":"2018-08-08T13:58:11.443007644Z"}
{"log":"ERROR:ElectrumX:[21994] exception handling Request('server.add_peer', [{'hosts': {'bitnode.pw': {'tcp_port': None, 'ssl_port': 57081}}, 'pruning': None, 'server_version': 'ElectrumX 1.8', 'protocol_min': '1.1', 'protocol_max': '1.4', 'genesis_hash': '000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f', 'hash_function': 'sha256', 'ssl_port': 57081, 'tcp_port': None}])\n","stream":"stdout","time":"2018-08-08T13:58:11.544418898Z"}
{"log":"Traceback (most recent call last):\n","stream":"stdout","time":"2018-08-08T13:58:11.544466027Z"}
{"log":"  File \"/usr/local/lib/python3.7/site-packages/aiorpcx/session.py\", line 109, in _throttled_request\n","stream":"stdout","time":"2018-08-08T13:58:11.544476061Z"}
{"log":"    result = await self.handle_request(request)\n","stream":"stdout","time":"2018-08-08T13:58:11.544485634Z"}
{"log":"  File \"/usr/local/lib/python3.7/site-packages/electrumx/server/session.py\", line 600, in handle_request\n","stream":"stdout","time":"2018-08-08T13:58:11.544495644Z"}
{"log":"    return await coro\n","stream":"stdout","time":"2018-08-08T13:58:11.544507091Z"}
{"log":"  File \"/usr/local/lib/python3.7/site-packages/electrumx/server/session.py\", line 760, in add_peer\n","stream":"stdout","time":"2018-08-08T13:58:11.54451372Z"}
{"log":"    return await self.peer_mgr.on_add_peer(features, self.peer_address())\n","stream":"stdout","time":"2018-08-08T13:58:11.544520959Z"}
{"log":"  File \"/usr/local/lib/python3.7/site-packages/electrumx/server/peers.py\", line 444, in on_add_peer\n","stream":"stdout","time":"2018-08-08T13:58:11.54452766Z"}
{"log":"    await self._note_peers([peer], check_ports=True)\n","stream":"stdout","time":"2018-08-08T13:58:11.544534598Z"}
{"log":"  File \"/usr/local/lib/python3.7/site-packages/electrumx/server/peers.py\", line 183, in _note_peers\n","stream":"stdout","time":"2018-08-08T13:58:11.544540848Z"}
{"log":"    await self.group.spawn(self._monitor_peer(peer))\n","stream":"stdout","time":"2018-08-08T13:58:11.544547782Z"}
{"log":"  File \"/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py\", line 157, in spawn\n","stream":"stdout","time":"2018-08-08T13:58:11.54455594Z"}
{"log":"    self._add_task(task, report_crash=report_crash)\n","stream":"stdout","time":"2018-08-08T13:58:11.54456266Z"}
{"log":"  File \"/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py\", line 128, in _add_task\n","stream":"stdout","time":"2018-08-08T13:58:11.544570167Z"}
{"log":"    raise RuntimeError('task group is closed')\n","stream":"stdout","time":"2018-08-08T13:58:11.544580886Z"}
{"log":"RuntimeError: task group is closed\n","stream":"stdout","time":"2018-08-08T13:58:11.544588837Z"}

[kyuupichan]

Was this at shutdown and/or at the same time as the other peers-related problem?

[kyuupichan]

If this was in the same run as the other one, it makes sense and is just fall-out from the other failure

[SomberNight]

This was during normal operation. It got printed twice in the logs, and happened strictly before any occurence of #564 (by 1+ hour). I can't see any interesting log lines nearby.

[kyuupichan]

No other failure previously? Hmm, not sure then. I can handle these more robustly, the downside is they then don't get reported and the real bug stays unfixed...

[kyuupichan]

The only way I can see a see this happening @SomberNight is if the taskgroup here:

electrumx/electrumx/server/peers.py

Lines 389 to 395 in 9b22fd3

	async with self.group as group:
	await group.spawn(forever.wait())
	await group.spawn(self._detect_proxy())
	await group.spawn(self._import_peers())
	# Consume tasks as they complete
	async for task in group:
	task.result()

exits. Because of the forever task, it can only exit if the task.result() throws an exception (in which case that's the real bug and I want to fix it) or if the whole thing was cancelled because the server is exiting...

[kyuupichan]

@SomberNight I've caused it to log the exceptions of failed tasks but continue; I think it means this won't happen any more; hopefully instead you'll get the real failure logged