ElectrumX server hang with "INFO:Prefetcher:cancelled; prefetcher stopping", and then crashed on SIGTERM
Nobody has claimed this yet.
- Dominant language
- Python
- Stars
- 568
- Forks
- 447
- PR merge metrics
- No merged PRs in 30d
Description
I observed that my electrumx_server hang completely and it was not responding to any queries, by clients or by RPC. I inspected the log:
(...)
2020-09-11 12:39:16,695:INFO:ElectrumX:[8329980] SSL 85.26.232.243:34434, 236 total
2020-09-11 12:39:16,823:INFO:ElectrumX:[8329981] SSL 123.25.70.15:65462, 236 total
2020-09-11 12:39:16,826:INFO:ElectrumX:[8329982] SSL 168.0.176.3:49000, 237 total
2020-09-11 12:39:17,147:INFO:ElectrumX:[8329983] SSL 103.224.185.201:57543, 232 total
2020-09-11 12:39:18,725:INFO:Prefetcher:cancelled; prefetcher stopping
2020-09-11 12:39:18,733:INFO:ElectrumX:[8329984] SSL 122.176.77.218:49194, 232 total
2020-09-11 12:39:18,805:INFO:BlockProcessor:flushing to DB for a clean shutdown...
2020-09-11 12:39:18,806:INFO:ElectrumX:[8329985] SSL 14.188.159.221:59038, 233 total
2020-09-11 12:39:18,806:INFO:ElectrumX:[8329986] SSL 5.127.4.37:35106, 234 total
2020-09-11 12:39:18,806:INFO:ElectrumX:[8329987] SSL 43.241.145.198:17845, 235 total
2020-09-11 12:39:18,807:INFO:ElectrumX:[8329988] SSL 115.74.225.96:57235, 236 total
2020-09-11 12:39:18,813:INFO:SessionManager:closing down server for ssl://all_interfaces:50002
2020-09-11 12:39:18,813:INFO:SessionManager:closing down server for rpc://localhost:8000
2020-09-11 12:39:18,857:INFO:ElectrumX:[940752] disconnected. Sent 1,694,708 bytes in 29,573 messages
2020-09-11 12:39:18,857:INFO:ElectrumX:[241949] disconnected. Sent 2,020,329 bytes in 35,213 messages
(...dozens disconnected messages and disconnected whilst throttled)
So by the look of it, electrumx_server has stopped operation, shutdown DB on it's own and just sat there. All clients were disconnected and all activity ceased.
Day after I discovered this state. I issued signal 15 SIGTERM from htop to kill hanging process. Then I noticed in the log:
2020-09-12 11:50:13,135:WARNING:Controller:received SIGTERM signal, initiating shutdown
2020-09-12 11:50:13,135:INFO:Controller:shutting down
2020-09-12 11:50:13,135:INFO:Controller:shutdown complete
2020-09-12 11:50:13,160:INFO:ElectrumX:[6417548] disconnected whilst throttled
2020-09-12 11:50:13,160:INFO:ElectrumX:[1721458] disconnected whilst throttled
2020-09-12 11:50:13,160:INFO:ElectrumX:[2920030] disconnected whilst throttled
2020-09-12 11:50:13,160:INFO:ElectrumX:[4422139] disconnected whilst throttled
2020-09-12 11:50:13,160:INFO:ElectrumX:[5994779] disconnected whilst throttled
Last 5 "disconnected whilst throttled" messages. And I thought electrum is completely disconnected, because it's been silent for 24 hours. Straight after these lines we have:
2020-09-12 11:50:13,161:ERROR:electrumx:ElectrumX server terminated abnormally
Traceback (most recent call last):
File "/home/nv01/.local/bin/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 584, in run_until_complete
return future.result()
File "/home/nv01/.local/lib/python3.7/site-packages/electrumx/lib/server_base.py", line 125, in run
await server_task
File "/home/nv01/.local/lib/python3.7/site-packages/electrumx/lib/server_base.py", line 98, in serve
await self.serve(shutdown_event)
File "/home/nv01/.local/lib/python3.7/site-packages/electrumx/server/controller.py", line 134, in serve
await group.spawn(wait_for_catchup())
File "/home/nv01/.local/lib/python3.7/site-packages/aiorpcx/curio.py", line 242, in __aexit__
await self.join()
File "/home/nv01/.local/lib/python3.7/site-packages/aiorpcx/curio.py", line 211, in join
raise task.exception()
File "/home/nv01/.local/lib/python3.7/site-packages/electrumx/server/mempool.py", line 335, in keep_synchronized
await group.spawn(self._logging(synchronized_event))
File "/home/nv01/.local/lib/python3.7/site-packages/aiorpcx/curio.py", line 242, in __aexit__
await self.join()
File "/home/nv01/.local/lib/python3.7/site-packages/aiorpcx/curio.py", line 211, in join
raise task.exception()
File "/home/nv01/.local/lib/python3.7/site-packages/electrumx/server/mempool.py", line 221, in _refresh_hashes
hashes = {hex_str_to_hash(hh) for hh in hex_hashes}
File "/home/nv01/.local/lib/python3.7/site-packages/electrumx/server/mempool.py", line 221, in <setcomp>
hashes = {hex_str_to_hash(hh) for hh in hex_hashes}
File "/home/nv01/.local/lib/python3.7/site-packages/electrumx/lib/hash.py", line 60, in hex_str_to_hash
return bytes(reversed(hex_to_bytes(x)))
ValueError: non-hexadecimal number found in fromhex() arg at position 50
Expected behaviour: electrumx_server should never issue "INFO:Prefetcher:cancelled; prefetcher stopping" and "INFO:BlockProcessor:flushing to DB for a clean shutdown..." unasked.
Also, on SIGTERM is should not crash like it did.
I restarted electrumX server and it's working fine. I issued SIGTERM once again right now to see how it behaves in normal way, this is what happens, as expected:
2020-09-12 20:10:46,137:WARNING:Controller:received SIGTERM signal, initiating shutdown
2020-09-12 20:10:46,137:INFO:Controller:shutting down
2020-09-12 20:10:46,138:INFO:Prefetcher:cancelled; prefetcher stopping
2020-09-12 20:10:46,140:INFO:BlockProcessor:flushing to DB for a clean shutdown...
2020-09-12 20:10:46,141:INFO:SessionManager:closing down server for ssl://all_interfaces:50002
2020-09-12 20:10:46,142:INFO:SessionManager:closing down server for rpc://localhost:8000
2020-09-12 20:10:46,161:INFO:ElectrumX:[110755] disconnected whilst throttled (...dozens of times...)
2020-09-12 20:10:47,156:INFO:Controller:shutdown complete
2020-09-12 20:10:47,157:INFO:electrumx:ElectrumX server terminated normally
Notice that during normal operation message "INFO:Controller:shutdown complete" was not instant like before. Before, electrumx was in "hung" state and there was nothing more to close, so "shutdown complete" message was instant at 0ms. In normal operation, it took 1019ms between "initiating shutdown" and "shutdown complete".
System:
OS: Debian GNU/Linux 10 (buster) x86_64
Kernel: 5.7.0-0.bpo.2-amd64
Electrum straight from git, latest commit:
commit 9ca59facfdb50daf063a5813fc9b08eb6fa1b246 (HEAD -> master, origin/master, origin/HEAD)
Merge: 148df48 23633c2
Author: ghost43 <somber.night@protonmail.com>
Date: Mon Aug 24 17:30:54 2020 +0000
Contributor guide
No contributing guide indexed for this repository
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with server/mempool.py, especially _refresh_hashes and keep_synchronized, then inspect lib/hash.py:60 and server/controller.py:134 using the traceback. Reproduce or isolate the malformed hash that triggers the ValueError and trace how its task affects shutdown. Done means the failure is handled without leaving the server hung, while a normal SIGTERM still completes cleanly.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- backend
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 38/100