electrs: Bug: tip_loop thread failed: JSON-RPC error: transport error: Didn't receive response data in time, timed out.

Reproduced on both arm64 RaspberryOS (Debian base) and amd64 Ubuntu 20.04 VM both using RaspiBlitz scripts. The install script is developed and discussed here: https://github.com/rootzoll/raspiblitz/issues/2548 Running 0.9.0-rc1 and same on master.

indexed and compacted successfully, but since then Electrs keeps restarting with the error:

WARN  electrs::thread] tip_loop thread failed: JSON-RPC error: transport error: Didn't receive response data in time, timed out.

Bitcoind is running without errors.

More logs:

systemd[1]: Stopped Electrs.
systemd[1]: Started Electrs.
electrs[1167816]: Config { network: Bitcoin, db_path: "/mnt/hdd/app-storage/electrs/db/bitcoin", daemon_dir: "/home/electrs/.bitcoin", daemon_auth: UserPass("raspibolt", "<sensitive>"), daemon_rpc_addr: 127.0.0.1:8332, daemon_p2p_addr: 127.0.0.1:8333, electrum_rpc_addr: 127.0.0.1:50001, monitoring_addr: 127.0.0.1:4224, wait_duration: 20s, index_batch_size: 10, index_lookup_limit: Some(200), auto_reindex: true, ignore_mempool: false, sync_once: false, server_banner: "Welcome to electrs 3041e89cd2fb377541b929d852ef6298c2d4e60a - the Electrum Rust Server on your RaspiBlitz", args: [] }
electrs[1167816]: [2021-09-21T08:43:40.686Z INFO  electrs::metrics::metrics_impl] serving Prometheus metrics on 127.0.0.1:4224
electrs[1167816]: [2021-09-21T08:43:40.984Z INFO  electrs::db] "/mnt/hdd/app-storage/electrs/db/bitcoin": 129 SST files, 31.649062994 GB, 3.94259865 Grows
electrs[1167816]: [2021-09-21T08:43:43.019Z INFO  electrs::chain] loading 701538 headers, tip=0000000000000000000be09a4d70c768038a3b7e153517276e9d04e1fb615c48
electrs[1167816]: [2021-09-21T08:43:44.904Z INFO  electrs::chain] chain updated: tip=0000000000000000000be09a4d70c768038a3b7e153517276e9d04e1fb615c48, height=701538
electrs[1167816]: [2021-09-21T08:43:47.712Z INFO  electrs::server] serving Electrum RPC on 127.0.0.1:50001
electrs[1167816]: [2021-09-21T08:44:07.716Z WARN  electrs::thread] tip_loop thread failed: JSON-RPC error: transport error: Didn't receive response data in time, timed out.
electrs[1167816]: [2021-09-21T08:44:07.716Z INFO  electrs::server] stopping Electrum RPC server
electrs[1167816]: [2021-09-21T08:44:07.716Z INFO  electrs::db] closing DB at /mnt/hdd/app-storage/electrs/db/bitcoin
systemd[1]: electrs.service: Succeeded.
systemd[1]: electrs.service: Scheduled restart job, restart counter is at 2.
systemd[1]: Stopped Electrs.

Installed with: https://github.com/rootzoll/raspiblitz/blob/dev/home.admin/config.scripts/bonus.electrs.sh Indexed successfully then keeps restarting as above.

Configuration sudo cat /home/electrs/.electrs/config.toml

verbose = 2
timestamp = true
jsonrpc_import = true
index-batch-size = 10
db_dir = "/mnt/hdd/app-storage/electrs/db"
auth = "raspibolt:XXXXX"
# allow BTC-RPC-explorer show tx-s for addresses with a history of more than 100
txid_limit = 1000
# https://github.com/Stadicus/RaspiBolt/issues/646
wait_duration_secs = 20
server_banner = "Welcome to electrs 3041e89cd2fb377541b929d852ef6298c2d4e60a - the Electrum Rust Server on your RaspiBlitz"
$ cat /etc/systemd/system/electrs.service

[Unit]
Description=Electrs
After=bitcoind.service

[Service]
WorkingDirectory=/home/electrs/electrs
ExecStart=/home/electrs/electrs/target/release/electrs --electrum-rpc-addr="0.0.0.0:50001"
User=electrs
Group=electrs
Type=simple
TimeoutSec=60
Restart=always
RestartSec=60

# Hardening measures
PrivateTmp=true
ProtectSystem=full
NoNewPrivileges=true
PrivateDevices=true

[Install]
WantedBy=multi-user.target

(same when removing the hardening measures from systemd)

System running electrs

Linux 5.11.0-34-generic #36~20.04.1-Ubuntu x86_64 GNU/Linux

and

Linux 5.10.60-v8+ #1449 SMP PREEMPT aarch64 GNU/Linux

Both systems have 4GB RAM available with 1.4GB and 900MB empty. Swapfile at 1GB usage out of 2 and 4GB.

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 30 (19 by maintainers)

Commits related to this issue

Most upvoted comments

Great! I will leave it debug until tomorrow and grep out any fails/errors if they arise. FYI, that 4gb RPi has nearly every RaspiBlitz service including testnet/signet running simultaneously! My thanks again to all.

Thanks for the debugging! You can also try the latest master (which should log a warning but not fail on HTTP timeouts).

admin@raspberrypi:~ $ sudo systemctl status electrs.service
● electrs.service - Electrs
   Loaded: loaded (/etc/systemd/system/electrs.service; enabled; vendor preset: enabled)
  Drop-In: /etc/systemd/system/electrs.service.d
           └─override.conf
   Active: active (running) since Sun 2021-09-26 09:11:52 BST; 5h 42min ago
 Main PID: 21221 (electrs)
    Tasks: 20 (limit: 4532)
   CGroup: /system.slice/electrs.service
           └─21221 /home/electrs/electrs/target/release/electrs --electrum-rpc-addr=0.0.0.0:50001

Sep 26 14:54:40 raspberrypi electrs[21221]: [2021-09-26T13:54:40.119Z DEBUG electrs::mempool] loading 1412 mempool transactions                                                                                                               
Sep 26 14:54:40 raspberrypi electrs[21221]: [2021-09-26T13:54:40.131Z DEBUG electrs::mempool] 1412 mempool txs: 6 added, 0 removed                                                                                                            
Sep 26 14:54:40 raspberrypi electrs[21221]: [2021-09-26T13:54:40.943Z DEBUG electrs::server] 1267: disconnected
Sep 26 14:54:40 raspberrypi electrs[21221]: [2021-09-26T13:54:40.963Z DEBUG electrs::p2p] got 0 new headers
Sep 26 14:54:40 raspberrypi electrs[21221]: [2021-09-26T13:54:40.993Z DEBUG electrs::mempool] loading 1412 mempool transactions                                                                                                               
Sep 26 14:54:40 raspberrypi electrs[21221]: [2021-09-26T13:54:40.994Z DEBUG electrs::mempool] 1412 mempool txs: 0 added, 0 removed                                                                                                            
Sep 26 14:54:43 raspberrypi electrs[21221]: [2021-09-26T13:54:43.554Z DEBUG electrs::server] 1268: disconnected
Sep 26 14:54:43 raspberrypi electrs[21221]: [2021-09-26T13:54:43.555Z DEBUG electrs::p2p] got 0 new headers
Sep 26 14:54:43 raspberrypi electrs[21221]: [2021-09-26T13:54:43.573Z DEBUG electrs::mempool] loading 1415 mempool transactions                                                                                                               
Sep 26 14:54:43 raspberrypi electrs[21221]: [2021-09-26T13:54:43.584Z DEBUG electrs::mempool] 1415 mempool txs: 3 added, 0 removed 



journalctl -u electrs -xef | cl | grep -in5 "error\|failed\|duration"


67261-Sep 26 09:05:16 raspberrypi electrs[12999]: [2021-09-26T08:05:16.424Z DEBUG electrs::server] 26: disconnected 
67262-Sep 26 09:05:16 raspberrypi electrs[12999]: [2021-09-26T08:05:16.425Z DEBUG electrs::p2p] got 0 new headers 
67263-Sep 26 09:05:16 raspberrypi electrs[12999]: [2021-09-26T08:05:16.450Z DEBUG electrs::mempool] loading 2307 mempool transactions                                                                                                         
67264-Sep 26 09:05:16 raspberrypi electrs[12999]: [2021-09-26T08:05:16.452Z DEBUG electrs::mempool] 2307 mempool txs: 0 added, 0 removed                                                                                                      
67265-Sep 26 09:05:41 raspberrypi electrs[12999]: [2021-09-26T08:05:41.647Z INFO  electrs::server] stopping Electrum RPC server                                                                                                               
67266:Sep 26 09:05:41 raspberrypi electrs[12999]: [2021-09-26T08:05:41.646Z WARN  electrs::thread] tip_loop thread failed: JSON-RPC error: transport error: Didn't receive response data in time, timed out.                                  
67267-Sep 26 09:05:41 raspberrypi electrs[12999]: [2021-09-26T08:05:41.656Z INFO  electrs::db] closing DB at /mnt/hdd/app-storage/electrs/db/bitcoin                                                                                          
67268-Sep 26 09:05:41 raspberrypi systemd[1]: electrs.service: Succeeded. 
67269--- Subject: Unit succeeded 
67270--- Defined-By: systemd 
67271--- Support: https://www.debian.org/support 
--
67293--- Support: https://www.debian.org/support 
67294---  
67295--- A start job for unit electrs.service has finished successfully. 
67296---  
67297--- The job identifier is 538693. 
67298:Sep 26 09:06:41 raspberrypi electrs[28160]: Config { network: Bitcoin, db_path: "/mnt/hdd/app-storage/electrs/db/bitcoin", daemon_dir: "/home/electrs/.bitcoin", daemon_auth: UserPass("raspibolt", "<sensitive>"), daemon_rpc_addr: V4(127.0.0.1:8332), daemon_p2p_addr: V4(127.0.0.1:8333), electrum_rpc_addr: V4(0.0.0.0:50001), monitoring_addr: V4(127.0.0.1:4224), wait_duration: 10s, jsonrpc_timeout: 15s, index_batch_size: 10, index_lookup_limit: Some(200), auto_reindex: true, ignore_mempool: false, sync_once: false, server_banner: "Welcome to electrs v0.9.0-rc2 - the Electrum Rust Server on your RaspiBlitz", args: [] }                                                                                         
67299-Sep 26 09:06:41 raspberrypi electrs[28160]: [2021-09-26T08:06:41.966Z INFO  electrs::metrics::metrics_impl] serving Prometheus metrics on 127.0.0.1:4224                                                                                
67300-Sep 26 09:06:48 raspberrypi electrs[28160]: [2021-09-26T08:06:48.750Z INFO  electrs::db] "/mnt/hdd/app-storage/electrs/db/bitcoin": 126 SST files, 31.741806128 GB, 3.950977371 Grows                                                   
67301-Sep 26 09:06:48 raspberrypi electrs[28160]: [2021-09-26T08:06:48.750Z DEBUG electrs::db] DB Some(Config { compacted: true, format: 0 })                                                                                                 
67302-Sep 26 09:06:49 raspberrypi electrs[28160]: [2021-09-26T08:06:49.503Z DEBUG electrs::db] auto-compactions enabled                                                                                                                       
67303-Sep 26 09:07:02 raspberrypi electrs[28160]: [2021-09-26T08:07:02.670Z INFO  electrs::chain] loading 702251 headers, tip=00000000000000000009f5aa4bd1798c4ef678ebd6861ca6511d72621d34af07                                                
--
67547-Sep 26 09:10:25 raspberrypi electrs[28160]: [2021-09-26T08:10:25.127Z DEBUG electrs::server] 13: disconnected 
67548-Sep 26 09:10:25 raspberrypi electrs[28160]: [2021-09-26T08:10:25.129Z DEBUG electrs::p2p] got 0 new headers 
67549-Sep 26 09:10:25 raspberrypi electrs[28160]: [2021-09-26T08:10:25.160Z DEBUG electrs::mempool] loading 2922 mempool transactions                                                                                                         
67550-Sep 26 09:10:25 raspberrypi electrs[28160]: [2021-09-26T08:10:25.171Z DEBUG electrs::mempool] 2922 mempool txs: 3 added, 0 removed                                                                                                      
67551-Sep 26 09:10:52 raspberrypi electrs[28160]: [2021-09-26T08:10:52.359Z INFO  electrs::server] stopping Electrum RPC server                                                                                                               
67552:Sep 26 09:10:52 raspberrypi electrs[28160]: [2021-09-26T08:10:52.359Z WARN  electrs::thread] tip_loop thread failed: JSON-RPC error: transport error: Didn't receive response data in time, timed out.                                  
67553-Sep 26 09:10:52 raspberrypi electrs[28160]: [2021-09-26T08:10:52.359Z INFO  electrs::db] closing DB at /mnt/hdd/app-storage/electrs/db/bitcoin                                                                                          
67554-Sep 26 09:10:52 raspberrypi systemd[1]: electrs.service: Succeeded. 
67555--- Subject: Unit succeeded 
67556--- Defined-By: systemd 
67557--- Support: https://www.debian.org/support 
--
67579--- Support: https://www.debian.org/support 
67580---  
67581--- A start job for unit electrs.service has finished successfully. 
67582---  
67583--- The job identifier is 539671. 
67584:Sep 26 09:11:52 raspberrypi electrs[21221]: Config { network: Bitcoin, db_path: "/mnt/hdd/app-storage/electrs/db/bitcoin", daemon_dir: "/home/electrs/.bitcoin", daemon_auth: UserPass("raspibolt", "<sensitive>"), daemon_rpc_addr: V4(127.0.0.1:8332), daemon_p2p_addr: V4(127.0.0.1:8333), electrum_rpc_addr: V4(0.0.0.0:50001), monitoring_addr: V4(127.0.0.1:4224), wait_duration: 10s, jsonrpc_timeout: 15s, index_batch_size: 10, index_lookup_limit: Some(200), auto_reindex: true, ignore_mempool: false, sync_once: false, server_banner: "Welcome to electrs v0.9.0-rc2 - the Electrum Rust Server on your RaspiBlitz", args: [] }                                                                                         
67585-Sep 26 09:11:52 raspberrypi electrs[21221]: [2021-09-26T08:11:52.683Z INFO  electrs::metrics::metrics_impl] serving Prometheus metrics on 127.0.0.1:4224                                                                                
67586-Sep 26 09:11:53 raspberrypi electrs[21221]: [2021-09-26T08:11:53.088Z INFO  electrs::db] "/mnt/hdd/app-storage/electrs/db/bitcoin": 127 SST files, 31.741806959 GB, 3.950977372 Grows                                                   
67587-Sep 26 09:11:53 raspberrypi electrs[21221]: [2021-09-26T08:11:53.088Z DEBUG electrs::db] DB Some(Config { compacted: true, format: 0 })                                                                                                 
67588-Sep 26 09:11:53 raspberrypi electrs[21221]: [2021-09-26T08:11:53.141Z DEBUG electrs::db] auto-compactions enabled                                                                                                                       
67589-Sep 26 09:11:57 raspberrypi electrs[21221]: [2021-09-26T08:11:57.752Z INFO  electrs::chain] loading 702251 headers, tip=00000000000000000009f5aa4bd1798c4ef678ebd6861ca6511d72621d34af07                                                

BTW, it’s cool to see that it takes <1 second to index a new block on a Raspberry Pi 😃

Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.106Z DEBUG electrs::p2p] got 1 new headers
Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.106Z INFO  electrs::index] indexing 1 blocks: [701996..701996]
Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.106Z DEBUG electrs::p2p] loading 1 blocks
Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.207Z DEBUG electrs::index] writing 5844 funding and 6480 spending rows from 1947 transactions, 1 blocks
Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.249Z INFO  electrs::chain] chain updated: tip=0000000000000000000d7fcc6c10c77ac028989211a8e5c4087911138814e201, height=701996
Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.251Z DEBUG electrs::p2p] got 0 new headers
Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.464Z DEBUG electrs::mempool] loading 1296 mempool transactions
Sep 24 15:08:12 raspberrypi electrs[4156]: [2021-09-24T14:08:12.647Z DEBUG electrs::mempool] 1296 mempool txs: 29 added, 1946 removed

RPi 4gb / kernel 5.10.60-v8+ / Core 22.0

I updated electrs with openoms dev script and after 6 mins the same bug in this thread appeared with the default wait_duration_secs = 10

On following auto restart it stopped after 12 mins with “notified via SIG15”

I altered wait_duration_secs = 14 and restarted electrs manually. So far out of a total 60 mins and 7 blocks, I have only gotten the following errors, at the 18th minute: ERROR 67: disconnecting due to failed to send response electrs-check/null ERROR 68: disconnecting due to failed to send response electrs-check/null

SparrowWallet is connecting and “Finding transactions…” no problem within the above 60 mins.

I would copy/paste but it is a bit awkward at the moment!

Ah, I see now. I think apart from warning about error it’d be great to modify jsonrpc to support larger timeout for specific request (and add a buffer of few seconds to it).

on the RPi4 4GB there was not a perceivable difference between using: wait_duration_secs = 1 or just commenting out the line falling back to the default 10. Synced a larger wallet with 400 addresses in less than a minute with both settings over Tor.

I prefer leaving this at the default value especially if it wouldn’t fail later on.

From my point of view the issue is solved, thank you for the quick help!

I have created https://github.com/romanz/electrs/compare/wait-timeout, which should warn in case of RPC timeouts (when waiting for new blocks) instead of failing.

@romanz great news, lowering the wait_duration_secs to 1 results in not having these restarts any more. Now the question is what would be the best value to use? A too low value would cause failures too I presume. The default 10 sounds to be a good middle-ground, testing it next.