Random crash every ~30 minutes (BitcoinSV)

[angelix]

I am experience a very weird situation where electrumX is shutting down every ~30 minutes of operation with the following log/trace.

Coin: BitcoinSV
ElectrumX: latest
Services: RPC, WebSockets
OS: Ubuntu 19.04 (in Docker)

2020-02-23 16:59:57,961:INFO:MemPool:9,722 txs 4.95 MB touching 16,060 addresses
2020-02-23 17:00:14,817:INFO:SessionManager:closing stale session ids 1188, 1189, 1191
2020-02-23 17:00:58,422:INFO:MemPool:10,057 txs 5.13 MB touching 16,714 addresses
2020-02-23 17:00:58,427:INFO:MemPool:compact fee histogram: [(1, 296155), (0, 4830318)]
2020-02-23 17:01:08,984:INFO:ElectrumX:[1355] WSS XXX.XXX.XXX.XXX:64322, 62 total
2020-02-23 17:01:14,818:INFO:SessionManager:closing stale session ids 1205, 1207, 1208
2020-02-23 17:01:17,312:INFO:ElectrumX:[1356] WSS XXX.XXX.XXX.XXX:58360, 56 total
2020-02-23 17:01:18,479:INFO:Prefetcher:new block height 623,338 hash 000000000000000001d98fc86bc30b4e213868b4ccbac220c22a72c99953d038
2020-02-23 17:01:19,646:INFO:DB:flush #981 took 0.1s.  Height 623,338 txs: 360,376,515 (+3,083)
2020-02-23 17:01:19,646:INFO:BlockProcessor:processed 1 block size 2.66 MB in 1.0s
2020-02-23 17:01:20,507:INFO:ElectrumX:[1359] WSS XXX.XXX.XXX.XXX:59456, 59 total
2020-02-23 17:01:24,603:INFO:ElectrumX:[1283] notified of 1 address
2020-02-23 17:01:24,603:INFO:ElectrumX:[1308] notified of 1 address
2020-02-23 17:01:24,604:INFO:ElectrumX:[1314] notified of 1 address
2020-02-23 17:01:24,604:INFO:ElectrumX:[1336] notified of 1 address
2020-02-23 17:01:24,604:INFO:ElectrumX:[1340] notified of 1 address
2020-02-23 17:01:25,481:INFO:SessionManager:closing down server for ws://0.0.0.0:5104
2020-02-23 17:01:25,481:INFO:SessionManager:closing down server for rpc://0.0.0.0:2104
2020-02-23 17:01:25,481:INFO:SessionManager:closing down server for wss://0.0.0.0:6104
2020-02-23 17:01:29,907:INFO:Prefetcher:cancelled; prefetcher stopping
2020-02-23 17:01:29,908:INFO:BlockProcessor:flushing to DB for a clean shutdown...
2020-02-23 17:01:29,908:INFO:Controller:shutting down
2020-02-23 17:01:29,909:INFO:Controller:shutdown complete
Task exception was never retrieved
future: <Task finished coro=<WebSocketCommonProtocol.close() done, defined at /usr/local/lib/python3.7/dist-packages/websockets/protocol.py:653> exception=AttributeError("'WebSocketServerProtocol' object has no attribute 'transfer_data_task'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 698, in close
    self.transfer_data_task,
AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'
Task exception was never retrieved
future: <Task finished coro=<WebSocketCommonProtocol.close() done, defined at /usr/local/lib/python3.7/dist-packages/websockets/protocol.py:653> exception=AttributeError("'WebSocketServerProtocol' object has no attribute 'transfer_data_task'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 698, in close
    self.transfer_data_task,
AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'
Task exception was never retrieved
future: <Task finished coro=<WebSocketCommonProtocol.close() done, defined at /usr/local/lib/python3.7/dist-packages/websockets/protocol.py:653> exception=AttributeError("'WebSocketServerProtocol' object has no attribute 'transfer_data_task'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 698, in close
    self.transfer_data_task,
AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'
Task exception was never retrieved
future: <Task finished coro=<WebSocketCommonProtocol.close() done, defined at /usr/local/lib/python3.7/dist-packages/websockets/protocol.py:653> exception=AttributeError("'WebSocketServerProtocol' object has no attribute 'transfer_data_task'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 698, in close
    self.transfer_data_task,
AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'
Task exception was never retrieved
future: <Task finished coro=<WebSocketCommonProtocol.close() done, defined at /usr/local/lib/python3.7/dist-packages/websockets/protocol.py:653> exception=AttributeError("'WebSocketServerProtocol' object has no attribute 'transfer_data_task'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 698, in close
    self.transfer_data_task,
AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'
Task exception was never retrieved
future: <Task finished coro=<WebSocketCommonProtocol.close() done, defined at /usr/local/lib/python3.7/dist-packages/websockets/protocol.py:653> exception=AttributeError("'WebSocketServerProtocol' object has no attribute 'transfer_data_task'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 698, in close
    self.transfer_data_task,
AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'
Task exception was never retrieved
future: <Task finished coro=<WebSocketCommonProtocol.close() done, defined at /usr/local/lib/python3.7/dist-packages/websockets/protocol.py:653> exception=AttributeError("'WebSocketServerProtocol' object has no attribute 'transfer_data_task'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 698, in close
    self.transfer_data_task,
AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'
Error in connection handler
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 335, in keep_synchronized
    await group.spawn(self._logging(synchronized_event))
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 232, in _refresh_hashes
    await self.api.on_mempool(touched, height)
  File "/electrumx/server/controller.py", line 67, in on_mempool
    await self._maybe_notify()
  File "/electrumx/server/controller.py", line 55, in _maybe_notify
    await self.notify(height, touched)
  File "/electrumx/server/session.py", line 766, in _notify_sessions
    await self._task_group.spawn(session.notify, touched, height_changed)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 148, in spawn
    self._add_task(task)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 123, in _add_task
    raise RuntimeError('task group is closed')
RuntimeError: task group is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/server.py", line 191, in handler
    await self.ws_handler(self, path)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 54, in ws_server
    await transport.process_messages()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 72, in process_messages
    await self.session.process_messages(self.recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/session.py", line 217, in process_messages
    await self._group.spawn(self._process_messages, recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 195, in join
    task = await self.next_done()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 161, in next_done
    await self._done_event.wait()
  File "/usr/lib/python3.7/asyncio/locks.py", line 293, in wait
    await fut
concurrent.futures._base.CancelledError
Error in connection handler
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 335, in keep_synchronized
    await group.spawn(self._logging(synchronized_event))
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 232, in _refresh_hashes
    await self.api.on_mempool(touched, height)
  File "/electrumx/server/controller.py", line 67, in on_mempool
    await self._maybe_notify()
  File "/electrumx/server/controller.py", line 55, in _maybe_notify
    await self.notify(height, touched)
  File "/electrumx/server/session.py", line 766, in _notify_sessions
    await self._task_group.spawn(session.notify, touched, height_changed)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 148, in spawn
    self._add_task(task)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 123, in _add_task
    raise RuntimeError('task group is closed')
RuntimeError: task group is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/server.py", line 191, in handler
    await self.ws_handler(self, path)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 54, in ws_server
    await transport.process_messages()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 72, in process_messages
    await self.session.process_messages(self.recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/session.py", line 217, in process_messages
    await self._group.spawn(self._process_messages, recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 195, in join
    task = await self.next_done()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 161, in next_done
    await self._done_event.wait()
  File "/usr/lib/python3.7/asyncio/locks.py", line 293, in wait
    await fut
concurrent.futures._base.CancelledError
Error in connection handler
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 335, in keep_synchronized
    await group.spawn(self._logging(synchronized_event))
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 232, in _refresh_hashes
    await self.api.on_mempool(touched, height)
  File "/electrumx/server/controller.py", line 67, in on_mempool
    await self._maybe_notify()
  File "/electrumx/server/controller.py", line 55, in _maybe_notify
    await self.notify(height, touched)
  File "/electrumx/server/session.py", line 766, in _notify_sessions
    await self._task_group.spawn(session.notify, touched, height_changed)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 148, in spawn
    self._add_task(task)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 123, in _add_task
    raise RuntimeError('task group is closed')
RuntimeError: task group is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/server.py", line 191, in handler
    await self.ws_handler(self, path)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 54, in ws_server
    await transport.process_messages()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 72, in process_messages
    await self.session.process_messages(self.recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/session.py", line 217, in process_messages
    await self._group.spawn(self._process_messages, recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 195, in join
    task = await self.next_done()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 161, in next_done
    await self._done_event.wait()
  File "/usr/lib/python3.7/asyncio/locks.py", line 293, in wait
    await fut
concurrent.futures._base.CancelledError
2020-02-23 17:01:40,036:ERROR:electrumx:ElectrumX server terminated abnormally
Traceback (most recent call last):
  File "electrumx_server", line 35, in main
    asyncio.run(controller.run())
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 335, in keep_synchronized
    await group.spawn(self._logging(synchronized_event))
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 232, in _refresh_hashes
    await self.api.on_mempool(touched, height)
  File "/electrumx/server/controller.py", line 67, in on_mempool
    await self._maybe_notify()
  File "/electrumx/server/controller.py", line 55, in _maybe_notify
    await self.notify(height, touched)
  File "/electrumx/server/session.py", line 766, in _notify_sessions
    await self._task_group.spawn(session.notify, touched, height_changed)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 148, in spawn
    self._add_task(task)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 123, in _add_task
    raise RuntimeError('task group is closed')
RuntimeError: task group is closed

Also getting randomly the following exceptions, don't know if related.

2020-02-23 16:56:23,241:INFO:ElectrumX:[1296] WSS XXX.XXX.XXX.XXX:52886, 76 total
Task exception was never retrieved
future: <Task finished coro=<RPCSession._process_messages() done, defined at /usr/local/lib/python3.7/dist-packages/aiorpcx/session.py:432> exception=ConnectionClosedOK('code = 1000 (OK), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/session.py", line 435, in _process_messages
    message = await recv_message()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 63, in recv_message
    message = await self.websocket.recv()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 509, in recv
    await self.ensure_open()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 812, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedOK: code = 1000 (OK), no reason
2020-02-23 16:56:25,560:INFO:ElectrumX:[1259] notified of 1 address

I'll continue investigating the issue. Any insights are welcome.

[kyuupichan]

What is the version of your websockets? I'm using 7.0; not sure if newer or older, but yours seems incompatible

[angelix]

Was using websockets 8.1, went back to 7.0
Unfortunately crashed again.

$ pip3 show websockets
Name: websockets
Version: 7.0

Including the logs, maybe you see something interesting.

2020-02-23 23:10:20,552:INFO:Prefetcher:new block height 623,382 hash 00000000000000000192d405cab6e08401aaeef581dc8c0ca1ef3b64e0f625a6
2020-02-23 23:10:21,508:INFO:DB:flush #773 took 0.0s.  Height 623,382 txs: 360,474,515 (+2,889)
2020-02-23 23:10:21,509:INFO:BlockProcessor:processed 1 block size 2.97 MB in 0.8s
2020-02-23 23:10:32,370:INFO:SessionManager:closing down server for rpc://0.0.0.0:2104
2020-02-23 23:10:32,370:INFO:SessionManager:closing down server for ws://0.0.0.0:5104
2020-02-23 23:10:32,370:INFO:SessionManager:closing down server for wss://0.0.0.0:6104
2020-02-23 23:10:33,540:INFO:Prefetcher:cancelled; prefetcher stopping
2020-02-23 23:10:33,540:INFO:BlockProcessor:flushing to DB for a clean shutdown...
2020-02-23 23:10:33,541:INFO:Controller:shutting down
2020-02-23 23:10:33,541:INFO:Controller:shutdown complete
Error in closing handshake
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 335, in keep_synchronized
    await group.spawn(self._logging(synchronized_event))
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 232, in _refresh_hashes
    await self.api.on_mempool(touched, height)
  File "/electrumx/server/controller.py", line 67, in on_mempool
    await self._maybe_notify()
  File "/electrumx/server/controller.py", line 55, in _maybe_notify
    await self.notify(height, touched)
  File "/electrumx/server/session.py", line 766, in _notify_sessions
    await self._task_group.spawn(session.notify, touched, height_changed)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 148, in spawn
    self._add_task(task)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 123, in _add_task
    raise RuntimeError('task group is closed')
RuntimeError: task group is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/server.py", line 177, in handler
    yield from self.close()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 561, in close
    yield from asyncio.shield(self.close_connection_task)
concurrent.futures._base.CancelledError
Error in connection handler
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 335, in keep_synchronized
    await group.spawn(self._logging(synchronized_event))
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 232, in _refresh_hashes
    await self.api.on_mempool(touched, height)
  File "/electrumx/server/controller.py", line 67, in on_mempool
    await self._maybe_notify()
  File "/electrumx/server/controller.py", line 55, in _maybe_notify
    await self.notify(height, touched)
  File "/electrumx/server/session.py", line 766, in _notify_sessions
    await self._task_group.spawn(session.notify, touched, height_changed)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 148, in spawn
    self._add_task(task)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 123, in _add_task
    raise RuntimeError('task group is closed')
RuntimeError: task group is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/server.py", line 169, in handler
    yield from self.ws_handler(self, path)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 54, in ws_server
    await transport.process_messages()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 72, in process_messages
    await self.session.process_messages(self.recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/session.py", line 217, in process_messages
    await self._group.spawn(self._process_messages, recv_message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 195, in join
    task = await self.next_done()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 161, in next_done
    await self._done_event.wait()
  File "/usr/lib/python3.7/asyncio/locks.py", line 293, in wait
    await fut
concurrent.futures._base.CancelledError
2020-02-23 23:10:33,568:ERROR:electrumx:ElectrumX server terminated abnormally
Traceback (most recent call last):
  File "electrumx_server", line 35, in main
    asyncio.run(controller.run())
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 335, in keep_synchronized
    await group.spawn(self._logging(synchronized_event))
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/mempool.py", line 232, in _refresh_hashes
    await self.api.on_mempool(touched, height)
  File "/electrumx/server/controller.py", line 67, in on_mempool
    await self._maybe_notify()
  File "/electrumx/server/controller.py", line 55, in _maybe_notify
    await self.notify(height, touched)
  File "/electrumx/server/session.py", line 766, in _notify_sessions
    await self._task_group.spawn(session.notify, touched, height_changed)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 148, in spawn
    self._add_task(task)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 123, in _add_task
    raise RuntimeError('task group is closed')
RuntimeError: task group is closed
Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason

Thanks

[randydu]

BSV always crashes recently, stops at block 622559, it runs in a docker container:

INFO:Controller:Python version: 3.7.2 (default, Mar  7 2019, 22:40:59) 
[GCC 8.2.0]

INFO:Controller:software version: ElectrumX 1.9.5
INFO:Controller:aiorpcX version: 0.10.5
INFO:Controller:supported protocol versions: 1.2-1.4.1
INFO:Controller:event loop policy: None
INFO:Controller:reorg limit is 200 blocks
INFO:Daemon:daemon #1 at bsv:8332/ (current)
INFO:DB:switching current directory to /data

INFO:DB:using leveldb for DB backend

INFO:DB:opened UTXO DB (for sync: True)

INFO:DB:DB version: 6
INFO:DB:coin: BitcoinSV
INFO:DB:network: mainnet
INFO:DB:height: 622,559
INFO:DB:tip: 00000000000000000215d64ff5398461b2214daab9005edc246a4ab5782ac755
INFO:DB:tx count: 356,748,088
INFO:DB:flushing DB cache at 1,200 MB

INFO:History:history DB version: 0

INFO:History:flush count: 706

INFO:SessionManager:RPC server listening on 127.0.0.1:8088

INFO:Prefetcher:catching up to daemon height 623,677 (1,118 blocks behind)

INFO:BlockProcessor:flushing to DB for a clean shutdown...

INFO:SessionManager:closing down RPC listening servers

ERROR:root:task crashed: <Task finished coro=<Controller.serve() done, defined at /electrumx/electrumx/server/controller.py:81> exception=AssertionError()>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/util.py", line 119, in check_task

    task.result()
  File "/electrumx/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 240, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 207, in join
    raise task.exception()
  File "/electrumx/electrumx/server/block_processor.py", line 662, in fetch_and_process_blocks
    await self.flush(True)
  File "/electrumx/electrumx/server/block_processor.py", line 335, in flush
    await self.run_in_thread_with_lock(flush)
  File "/electrumx/electrumx/server/block_processor.py", line 191, in run_in_thread_with_lock
    return await asyncio.shield(run_in_thread_locked())
  File "/electrumx/electrumx/server/block_processor.py", line 190, in run_in_thread_locked
    return await run_in_thread(func, *args)
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 68, in run_in_thread
    return await get_event_loop().run_in_executor(None, func, *args)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/electrumx/electrumx/server/block_processor.py", line 334, in flush
    self.estimate_txs_remaining)
  File "/electrumx/electrumx/server/db.py", line 189, in flush_dbs
    self.assert_flushed(flush_data)
  File "/electrumx/electrumx/server/db.py", line 179, in assert_flushed
    assert not flush_data.block_tx_hashes
AssertionError

[randydu]

Here is error message from another docker instance:

ERROR:MemPool:1 txs dropped
INFO:MemPool:100,694 txs touching 75,443 addresses
INFO:ElectrumX:[151600] TCP 172.21.0.1:55340, 1 total
ERROR:MemPool:1 txs dropped

INFO:ElectrumX:[151601] TCP 172.21.0.1:55538, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151602] TCP 172.21.0.1:55736, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151603] TCP 172.21.0.1:55930, 1 total
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151604] TCP 172.21.0.1:56130, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151605] TCP 172.21.0.1:56318, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151606] TCP 172.21.0.1:56512, 1 total
ERROR:MemPool:1 txs dropped
INFO:MemPool:101,378 txs touching 75,916 addresses
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151607] TCP 172.21.0.1:56710, 1 total
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151608] TCP 172.21.0.1:56902, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151609] TCP 172.21.0.1:57098, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151610] TCP 172.21.0.1:57298, 1 total
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151611] TCP 172.21.0.1:57492, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151612] TCP 172.21.0.1:57690, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:MemPool:102,042 txs touching 76,375 addresses
INFO:ElectrumX:[151613] TCP 172.21.0.1:57888, 1 total
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151614] TCP 172.21.0.1:58080, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151615] TCP 172.21.0.1:58268, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151616] TCP 172.21.0.1:58470, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151617] TCP 172.21.0.1:58664, 1 total
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151618] TCP 172.21.0.1:58858, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151619] TCP 172.21.0.1:59058, 1 total
ERROR:MemPool:1 txs dropped
INFO:MemPool:102,667 txs touching 76,771 addresses
INFO:ElectrumX:[151620] TCP 172.21.0.1:59246, 1 total
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151621] TCP 172.21.0.1:59436, 1 total
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151622] TCP 172.21.0.1:59636, 1 total
ERROR:MemPool:1 txs dropped
ERROR:MemPool:1 txs dropped
INFO:ElectrumX:[151623] TCP 172.21.0.1:59822, 1 total
ERROR:MemPool:1 txs dropped
INFO:Prefetcher:new block height 622,560 hash 0000000000000000017b858f02e0c873083b623562ba48f42cbefd61e4d7498c
INFO:ElectrumX:[151624] TCP 172.21.0.1:60016, 1 total
INFO:BlockProcessor:flushing to DB for a clean shutdown...
INFO:SessionManager:closing down RPC, TCP, SSL listening servers

ERROR:root:task crashed: <Task finished coro=<Controller.serve() done, defined at /electrumx/electrumx/server/controller.py:81> exception=AssertionError()>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/util.py", line 119, in check_task
    task.result()
  File "/electrumx/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 240, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 207, in join
    raise task.exception()
  File "/electrumx/electrumx/server/block_processor.py", line 662, in fetch_and_process_blocks
    await self.flush(True)
  File "/electrumx/electrumx/server/block_processor.py", line 335, in flush
    await self.run_in_thread_with_lock(flush)
  File "/electrumx/electrumx/server/block_processor.py", line 191, in run_in_thread_with_lock
    return await asyncio.shield(run_in_thread_locked())
  File "/electrumx/electrumx/server/block_processor.py", line 190, in run_in_thread_locked
    return await run_in_thread(func, *args)
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 68, in run_in_thread
    return await get_event_loop().run_in_executor(None, func, *args)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/electrumx/electrumx/server/block_processor.py", line 334, in flush
    self.estimate_txs_remaining)
  File "/electrumx/electrumx/server/db.py", line 189, in flush_dbs
    self.assert_flushed(flush_data)
  File "/electrumx/electrumx/server/db.py", line 179, in assert_flushed
    assert not flush_data.block_tx_hashes
AssertionError

[randydu]

Restart the docker instance, the log messages are:

INFO:Controller:Python version: 3.7.2 (default, Mar  7 2019, 22:40:59) 
[GCC 8.2.0]

INFO:Controller:software version: ElectrumX 1.9.5

INFO:Controller:aiorpcX version: 0.10.5
INFO:Controller:supported protocol versions: 1.2-1.4.1
INFO:Controller:event loop policy: None
INFO:Controller:reorg limit is 200 blocks
INFO:Daemon:daemon #1 at bsv:8332/ (current)
INFO:DB:switching current directory to /data

INFO:DB:using leveldb for DB backend

INFO:DB:opened UTXO DB (for sync: True)

INFO:DB:DB version: 6

INFO:DB:coin: BitcoinSV
INFO:DB:network: mainnet
INFO:DB:height: 622,559
INFO:DB:tip: 00000000000000000215d64ff5398461b2214daab9005edc246a4ab5782ac755
INFO:DB:tx count: 356,748,088

INFO:DB:flushing DB cache at 1,200 MB

INFO:History:history DB version: 0
INFO:History:flush count: 9,436

INFO:DB:deleted 2,538 stale undo entries

INFO:SessionManager:RPC server listening on 127.0.0.1:8088

INFO:Prefetcher:catching up to daemon height 623,678 (1,119 blocks behind)

INFO:BlockProcessor:flushing to DB for a clean shutdown...
INFO:SessionManager:closing down RPC listening servers

ERROR:root:task crashed: <Task finished coro=<Controller.serve() done, defined at /electrumx/electrumx/server/controller.py:81> exception=AssertionError()>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/util.py", line 119, in check_task
    task.result()
  File "/electrumx/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 240, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 207, in join
    raise task.exception()
  File "/electrumx/electrumx/server/block_processor.py", line 662, in fetch_and_process_blocks
    await self.flush(True)
  File "/electrumx/electrumx/server/block_processor.py", line 335, in flush
    await self.run_in_thread_with_lock(flush)
  File "/electrumx/electrumx/server/block_processor.py", line 191, in run_in_thread_with_lock
    return await asyncio.shield(run_in_thread_locked())
  File "/electrumx/electrumx/server/block_processor.py", line 190, in run_in_thread_locked
    return await run_in_thread(func, *args)
  File "/usr/local/lib/python3.7/site-packages/aiorpcx/curio.py", line 68, in run_in_thread
    return await get_event_loop().run_in_executor(None, func, *args)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/electrumx/electrumx/server/block_processor.py", line 334, in flush
    self.estimate_txs_remaining)
  File "/electrumx/electrumx/server/db.py", line 189, in flush_dbs
    self.assert_flushed(flush_data)
  File "/electrumx/electrumx/server/db.py", line 179, in assert_flushed
    assert not flush_data.block_tx_hashes
AssertionError

Both docker instances stop at the same block height with the same error. They have been running for months until this crash last week.

I've compacted the fist docker instance and run it, still crashes.

It seems the BSV block #622559/622560 has some weird txs that could crash the electrumX.

[randydu]

I will try the latest electrumX version to see if it makes any difference.

[kyuupichan]

Yes that is the problem, you need to be on 1.14 for Genesis. I'm not sure what the txs are but you may have to rebuild the DB from scratch.

[angelix]

Sorry kyuupichan, but what randydu is refering to has nothing to do with the issue i posted in the first place.
I am still experience the same behaviour, crashing every now and then, with websocket 8.1 & websocket 7.

[kyuupichan]

@angelix the error shown: "AttributeError: 'WebSocketServerProtocol' object has no attribute 'transfer_data_task'" originates in the websocket package and refers to a problem within its data structures. I suspect your installation of the package is somehow corrupted.

[kyuupichan]

https://github.com/aaugustin/websockets/blob/master/src/websockets/protocol.py#L278 is where it is defined, apparently

[angelix]

Downgraded to websockets v7, different exceptions are occurring.
Don't know if a client message is doing this, but even that shouldn't bring down the server.

Latest log:

2020-02-26 14:05:23,423:INFO:ElectrumX:[47] WSS XXX.XXX.XXX.XXX:47172, 23 total
Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
2020-02-26 14:05:29,238:INFO:MemPool:6,570 txs 3.07 MB touching 10,596 addresses
2020-02-26 14:06:05,313:INFO:Prefetcher:new block height 623,751 hash 00000000000000000250f4222ec97f93cadc2a2a1bde84cda5bd5ebb6789af53
2020-02-26 14:06:06,014:INFO:DB:flush #1,087 took 0.0s.  Height 623,751 txs: 362,052,517 (+1,874)
2020-02-26 14:06:06,014:INFO:BlockProcessor:processed 1 block size 1.00 MB in 0.6s
2020-02-26 14:06:21,002:INFO:ElectrumX:[59] WSS XXX.XXX.XXX.XXX:3844, 22 total
2020-02-26 14:06:21,140:INFO:SessionManager:closing down server for ws://0.0.0.0:5104
2020-02-26 14:06:21,140:INFO:SessionManager:closing down server for rpc://0.0.0.0:2104
2020-02-26 14:06:21,140:INFO:SessionManager:closing down server for wss://0.0.0.0:6104
2020-02-26 14:06:21,999:INFO:Prefetcher:cancelled; prefetcher stopping
2020-02-26 14:06:21,999:INFO:BlockProcessor:flushing to DB for a clean shutdown...
2020-02-26 14:06:22,000:INFO:Controller:shutting down
2020-02-26 14:06:22,000:INFO:Controller:shutdown complete
2020-02-26 14:06:22,001:ERROR:electrumx:ElectrumX server terminated abnormally
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "electrumx_server", line 35, in main
    asyncio.run(controller.run())
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 579, in run_until_complete
    return future.result()
  File "/electrumx/lib/server_base.py", line 125, in run
    await server_task
  File "/electrumx/lib/server_base.py", line 98, in serve
    await self.serve(shutdown_event)
  File "/electrumx/server/controller.py", line 134, in serve
    await group.spawn(wait_for_catchup())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/session.py", line 611, in serve
    await group.spawn(self._manage_servers())
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 242, in __aexit__
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/curio.py", line 211, in join
    raise task.exception()
  File "/electrumx/server/session.py", line 963, in notify
    await self.send_notification('blockchain.headers.subscribe', args)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/session.py", line 534, in send_notification
    await self._send_message(message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/session.py", line 153, in _send_message
    await self.transport.write(message)
  File "/usr/local/lib/python3.7/dist-packages/aiorpcx/websocket.py", line 85, in write
    await self.websocket.send(framed_message)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 462, in send
    yield from self.ensure_open()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 658, in ensure_open
    ) from self.transfer_data_exc
websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/usr/local/lib/python3.7/dist-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/usr/local/lib/python3.7/dist-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason

[angelix]

@kyuupichan i was able to reproduce it with artillery.io
I will share the sample config of the stress test.

[onnateldome]

@kyuupichan here is the artillery.io script that we used for the stress test:

config:
  target: "wss://XXXX:XXX"
  plugins:
    fuzzer: {}
  phases:
    - duration: 60
      arrivalRate: 20
subprotocols:
    - json
scenarios:
  - engine: "ws"
    flow:
      - send: '{"id":0,"method":"server.version","params":["1.18.8-dev_289_android","1.4"]}'
      - send: '{"id":1,"method":"blockchain.headers.subscribe"}'
      - send: '{"id":2,"method":"blockchain.scripthash.subscribe","params":["963c7985bf4123e2d650c707458d6f731b2a0de6ffebbbcb3198f973aecb52c5"]}'
      - send: '{"id":3,"method":"blockchain.scripthash.subscribe","params":["578b41ac4333609a6216b0595d88df72070e734fcbd6ec58c3f2b6900d1f14cf"]}'
      - send: '{"id":4,"method":"blockchain.scripthash.subscribe","params":["6be90d7a1835ad86fa647e429e7e4f849c8da575abbcbf77178b4e80008217ba"]}'
      - send: '{"id":5,"method":"blockchain.scripthash.subscribe","params":["fc9794b06359653b29a2425f16401dba7e18e2f59ba63275d8146f2e420b8f59"]}'
      - send: '{"id":6,"method":"blockchain.scripthash.subscribe","params":["0f4137ef81c6ce2f533c65a79349faaa6a7a8f3602475bf2b0f4a5fc8a1ab592"]}'
      - send: '{"id":7,"method":"blockchain.scripthash.subscribe","params":["46cfe715fdd8a2be46bf7cab5787f4900754b9d6f250aae16034e7a9259b66a6"]}'
      - send: '{"id":8,"method":"blockchain.scripthash.subscribe","params":["acc65567fc97e2befcc52e072cce9e0806c78183b1cf1e6084cb3553337bbc63"]}'
      - send: '{"id":9,"method":"blockchain.scripthash.subscribe","params":["3ba6d0060218fedafa08c3e18ae5bf563058a60f36d3215928cc1839156faf8b"]}'
      - send: '{"id":10,"method":"blockchain.scripthash.subscribe","params":["8c6f50c964a993d07aec5873929ba9d77dae2daa7cc9318276f18d056dfbd302"]}'
      - send: '{"id":11,"method":"blockchain.scripthash.subscribe","params":["ce8684902c923d671b4bcde5aeebe62b4017bf2e2680937874eebe8cfc9233e8"]}'
      - send: '{"id":12,"method":"blockchain.scripthash.subscribe","params":["53c8835bba229b2d479e03d200e3ab188698c7ec232de3a1b78e2a0dd1118384"]}'
      - send: '{"id":13,"method":"blockchain.scripthash.subscribe","params":["1327368ad941a4581871353259e24df70c7d96413b28071633a4607284684e7b"]}'
      - send: '{"id":14,"method":"blockchain.scripthash.subscribe","params":["1173365fe38eb7c446952524491f0e3c05cf750b800d7e635189078cea1024c0"]}'
      - send: '{"id":15,"method":"blockchain.scripthash.subscribe","params":["793528e69efd213c6acbc615fbd4ab4a1e3618550e8e23638cca1fb597a16d01"]}'
      - send: '{"id":16,"method":"blockchain.scripthash.subscribe","params":["86247c9adaa4887b8ced359fbf5c401f7ef65eb53cc163c6bde38fe875ccb859"]}'
      - send: '{"id":17,"method":"blockchain.scripthash.subscribe","params":["ebaec7981099a799a778a32e5e25605a4bc2d3a6a0e1681238320c4deb9d17b8"]}'
      - send: '{"id":18,"method":"blockchain.scripthash.subscribe","params":["a685f4ff12d16351874b18802fa2151a2704672dc0ab469a0a60f99768f06c80"]}'
      - send: '{"id":19,"method":"blockchain.scripthash.subscribe","params":["d7cf745dc807467a8578ca13dabac5546a1741b8f314bb0fe30c19d9db6187a8"]}'
      - send: '{"id":20,"method":"blockchain.scripthash.subscribe","params":["1185fd57087cc0819b21d9f796a9d5c187b20b809ef5032338a4fa049f5fa19e"]}'
      - send: '{"id":21,"method":"blockchain.scripthash.subscribe","params":["9a020bb0ce6401a199dc370b971e8de8792548f3bb1f47bb42912afbc0249ab5"]}'
      - send: '{"id":22,"method":"blockchain.scripthash.subscribe","params":["08e5848ab80da860b2fc5dbe35d90ea6fdfcef157ed91932f5341aaaa84c4cc8"]}'
      - send: '{"id":23,"method":"blockchain.scripthash.subscribe","params":["7b3fc453b63f226ac3a4e3a0fa985e3b9fd74fbde086ca8ff43d254da18def1c"]}'
      - send: '{"id":24,"method":"blockchain.scripthash.subscribe","params":["cb9119431a300c5fd25cefc61e37ea935b1fc3f4bedcbeea90b745fe3ed05153"]}'
      - send: '{"id":25,"method":"blockchain.scripthash.subscribe","params":["68260af453478e4442c159f4d95464ed8bc1a6f1daf7480892836d71d1bc9895"]}'
      - send: '{"id":26,"method":"blockchain.scripthash.subscribe","params":["889b9cd69ef886a2006471c5c52a42a1bde6a3f14ab56d472cab4dd4df8e832f"]}'
      - send: '{"id":27,"method":"blockchain.scripthash.subscribe","params":["4b79c94172c3997b4ddbee74b0863b4934b63d9657544f62db5e72b09b03cb71"]}'
      - send: '{"id":28,"method":"blockchain.scripthash.subscribe","params":["b56ac7686fcdfb5588b265adc0e8f865b7caca73be383831b6c9ffa2a33f99d7"]}'
      - send: '{"id":29,"method":"blockchain.scripthash.subscribe","params":["943fd31ccf312ac112855eb7dd6fd2154cff05a1bc624a031efacca82dc37bcc"]}'
      - send: '{"id":30,"method":"blockchain.scripthash.subscribe","params":["da7915feb04dba1d249dad666c17678e865d897b2e11cd5bd2c9d46c3d060cf3"]}'
      - send: '{"id":31,"method":"blockchain.scripthash.subscribe","params":["21ca93adc6f9ef1db034bc4ffcdecb262b3f703208576e48d7f42ecb996fb8ca"]}'
      - send: '{"id":32,"method":"blockchain.scripthash.subscribe","params":["00e44d04c89e3b0619688058973d1f8e217b0869f403e61778e9078d3be185e6"]}'
      - send: '{"id":33,"method":"blockchain.scripthash.subscribe","params":["2824474eb29f97279c271c70eadda42ebebc060b3d32e2c1183ca9c78c8d4a6f"]}'
      - send: '{"id":34,"method":"blockchain.scripthash.subscribe","params":["1dcd606b7940cae0cf2f173288c0fa711d7d344901072a8b1e175a17f6d66755"]}'
      - send: '{"id":35,"method":"blockchain.scripthash.subscribe","params":["d59e38c1240a78bd6f888d4a2ad83b4f981f37a17ce31b25fbfc1ab97486d3fb"]}'
      - send: '{"id":36,"method":"blockchain.scripthash.subscribe","params":["5c2a06106d5dcc7b288fee1a8e78640ac111cd4469e2e6531be9307e7838b614"]}'
      - send: '{"id":37,"method":"blockchain.scripthash.subscribe","params":["5ad8ca20949b168ec74f22875611313b940f4941ce2327e225b9aad55d09d40f"]}'
      - send: '{"id":38,"method":"blockchain.scripthash.subscribe","params":["7ae9787644fefdb648835a20ecee085c2abd66952c4a58cbe7aee0fa066a072c"]}'
      - send: '{"id":39,"method":"blockchain.scripthash.subscribe","params":["4ff3ae05a8285ec26aa7bd86e6346d668f31a345de099f4ad818740546c6754e"]}'
      - send: '{"id":40,"method":"blockchain.scripthash.subscribe","params":["30648bcf72cfcf40af3b7a03e7a854e76035ef8e996e0210b0716bd5637373c5"]}'
      - send: '{"id":41,"method":"blockchain.scripthash.subscribe","params":["86540f71b958421bb78f849b7fcdb9cf6b72ee06ec8188daa851263a2bfec7ae"]}'
      - send: '{"id":42,"method":"blockchain.scripthash.subscribe","params":["f6559eee06eff11a371e40e2c0b5649dfd56df305ae9d9ad27f42b00b749eff3"]}'
      - send: '{"id":43,"method":"blockchain.scripthash.subscribe","params":["ed030785921e1c9530c38e26c68afdc460a3cec1ccdee867f56663877401351d"]}'
      - send: '{"id":44,"method":"blockchain.scripthash.subscribe","params":["d090a0d5f0efc77c3ab2eb3853359c583fc845d0f2d58ad575bd960e6231c4c4"]}'
      - send: '{"id":45,"method":"blockchain.scripthash.subscribe","params":["48ad171d9ae4f0b96b13b1aa799c83da61dbee8e8b113a011d864572d593d027"]}'
      - send: '{"id":46,"method":"blockchain.scripthash.subscribe","params":["287b85ba24fbf0a46d3be22c32cbea01d9906823e0569b6b8e71370b294d6473"]}'
      - send: '{"id":47,"method":"blockchain.scripthash.subscribe","params":["53b16b8b88feb9175ee1e57af09a0431d8ecdc78835c302cc0cebb5576fbe0ac"]}'
      - send: '{"id":48,"method":"blockchain.scripthash.subscribe","params":["c7b9ca59c52c278a5a6291da03bb5708d3e3ffefb2165b240542ec11b8ea1e68"]}'
      - send: '{"id":49,"method":"blockchain.scripthash.subscribe","params":["79680920fd2dac3442f1c44e414a5707fda744d4271eb8294469f361b557246f"]}'
      - send: '{"id":50,"method":"blockchain.scripthash.subscribe","params":["1bdbc4027c6f2eeadceed2943fd1323298e7dd71ef1652bce734916a3d27edf5"]}'
      - send: '{"id":51,"method":"blockchain.scripthash.subscribe","params":["a29c9601952695a8f431e8ca1b84135a855eaceaf2ae28f805ff66da77089cb2"]}'
      - send: '{"id":52,"method":"blockchain.scripthash.subscribe","params":["e28641a853e7616d1cf8e53d0e7ea8d6c876217deaca9598a8fd03bea3c8050b"]}'
      - send: '{"id":53,"method":"blockchain.scripthash.subscribe","params":["2fb9881e8818110760e793ff266855423f2c61bf103ca5a3ad249ea4ccd86543"]}'
      - send: '{"id":54,"method":"blockchain.scripthash.subscribe","params":["f57aa7784011b8079dd689d68687778999be6b4051b97e5e3809aa54a56de38d"]}'
      - send: '{"id":55,"method":"blockchain.scripthash.subscribe","params":["0ba5f5cd04f5a664b58b7c7652c39a0f872758a34997aae10715017f87d72f1e"]}'