electrs connection failures after nigiri stop/start cycle (bitcoind stuck on IBD)

[kdmukai]

Running latest nigiri with various regtest blocks and wallets created.

Stop nigiri.

Start nigiri.

bitcoind logs show normal startup actions, but then it just sits here without proceeding:

2024-01-27T18:10:08Z [default wallet] AddToWallet 856e26d0b87f0e02033a127ff8e4d331dfcd28f4c7cf9dfec1c8875f179d6309  
2024-01-27T18:10:08Z [default wallet] AddToWallet 54e3201bcfbb25f53dd4b0e705c4cc2c7511c3c45fdc796f4c99cfee88027847  
2024-01-27T18:10:08Z [default wallet] AddToWallet 8a658f7b298d64f6f69de236a8b452341fde481dd853d0bccfc9493303e1d2aa  
2024-01-27T18:10:08Z [default wallet] Scanning current mempool transactions.
2024-01-27T18:10:08Z [default wallet] Rescan completed in             834ms

The electrs logs show it waiting for bitcoind to finish its IBD (but no amount of waiting here will help; again, bitcoind above is not showing any further updates):

electrs  | Config { log: StdErrLog { verbosity: Trace, quiet: false, show_level: true, timestamp: Off, modules: [], writer: "stderr", color_choice: Never }, network_type: Regtest, db_path: "./db/regtest", daemon_dir: "/config/regtest", blocks_dir: "/config/regtest/blocks", daemon_rpc_addr: 172.29.0.2:18443, cookie: Some("admin1:123"), electrum_rpc_addr: 0.0.0.0:50000, http_addr: 0.0.0.0:30000, http_socket_file: None, monitoring_addr: 127.0.0.1:24224, jsonrpc_import: true, light_mode: false, address_search: false, index_unspendables: false, cors: Some("*"), precache_scripts: None, utxos_limit: 500, electrum_txs_limit: 500, electrum_banner: "Welcome to electrs-esplora 0.4.1" }
electrs  | DEBUG - Server listening on 127.0.0.1:24224
electrs  | DEBUG - Running accept thread
electrs  | WARN - failed to connect daemon at 172.29.0.2:18443: Connection refused (os error 111)
electrs  | INFO - NetworkInfo { version: 240001, subversion: "/Satoshi:24.0.1/", relayfee: 1e-5 }
electrs  | INFO - BlockchainInfo { chain: "regtest", blocks: 116, headers: 116, bestblockhash: "59a721bc28ce0600a4214968d06b8bd3e3c564386171334c795b5b99d5923b8c", pruned: false, verificationprogress: 1.0, initialblockdownload: Some(true) }
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
...

esplora front end just shows an error, as expected (if electrs hasn't successfully connected to bitcoind, esplora will be out of luck).

But bitcoind never moves on. RPC responds to getblockchaininfo and getconnectioncount etc so it is still running.

chopsticks logs:

chopsticks  | 2024/01/27 16:15:09 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | 2024/01/27 16:15:09 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | time="2024-01-27T16:15:09Z" level=info msg="New request from remote address: 192.168.65.1:28850" duration=1.705125ms hostname="electrs:30000" method=GET path=/mempool/recent response= start_time="2024-01-27T16:15:09Z" status=502
chopsticks  | time="2024-01-27T16:15:09Z" level=info msg="New request from remote address: 192.168.65.1:28849" duration=2.311334ms hostname="electrs:30000" method=GET path=/blocks response= start_time="2024-01-27T16:15:09Z" status=502
chopsticks  | 2024/01/27 16:15:09 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | time="2024-01-27T16:15:09Z" level=info msg="New request from remote address: 192.168.65.1:28850" duration="639.084µs" hostname="electrs:30000" method=GET path=/blocks/tip/height response= start_time="2024-01-27T16:15:09Z" status=502
chopsticks  | 2024/01/27 16:15:13 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | 2024/01/27 16:15:13 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | time="2024-01-27T16:15:13Z" level=info msg="New request from remote address: 192.168.65.1:28850" duration=1.497708ms hostname="electrs:30000" method=GET path=/blocks response= start_time="2024-01-27T16:15:13Z" status=502
chopsticks  | time="2024-01-27T16:15:13Z" level=info msg="New request from remote address: 192.168.65.1:28849" duration=1.420333ms hostname="electrs:30000" method=GET path=/mempool/recent response= start_time="2024-01-27T16:15:13Z" status=502
chopsticks  | 2024/01/27 16:15:14 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | time="2024-01-27T16:15:14Z" level=info msg="New request from remote address: 192.168.65.1:28849" duration=3.126709ms hostname="electrs:30000" method=GET path=/blocks/ response= start_time="2024-01-27T16:15:14Z" status=502
chopsticks  | 2024/01/27 16:15:15 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | time="2024-01-27T16:15:15Z" level=info msg="New request from remote address: 192.168.65.1:28849" duration=3.115083ms hostname="electrs:30000" method=GET path=/mempool/recent response= start_time="2024-01-27T16:15:15Z" status=502
chopsticks  | 2024/01/27 16:18:15 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | 2024/01/27 16:18:15 http: proxy error: dial tcp 172.31.0.3:30000: connect: connection refused
chopsticks  | time="2024-01-27T16:18:15Z" level=info msg="New request from remote address: 192.168.65.1:28865" duration=2.2985ms hostname="electrs:30000" method=GET path=/mempool/recent response= start_time="2024-01-27T16:18:15Z" status=502
chopsticks  | time="2024-01-27T16:18:15Z" level=info msg="New request from remote address: 192.168.65.1:28864" duration=2.336167ms hostname="electrs:30000" method=GET path=/blocks response= start_time="2024-01-27T16:18:15Z" status=502
chopsticks  | time="2024-01-27T16:21:37Z" level=info msg="Starting server with configuration:" chain=bitcoin electrs_url="http://electrs:30000" faucet_enabled=true listen_url="0.0.0.0:3000" logger_enabled=true mining_enabled=true rpc_server_url="http://admin1:123@bitcoin:18443" tls_enabled=false
chopsticks  | time="2024-01-27T16:21:37Z" level=fatal msg="creating wallet" error="could not list wallets: Method listwallets failed with error: Loading wallet…"
chopsticks  | time="2024-01-27T16:21:37Z" level=info msg="Starting server with configuration:" chain=bitcoin electrs_url="http://electrs:30000" faucet_enabled=true listen_url="0.0.0.0:3000" logger_enabled=true mining_enabled=true rpc_server_url="http://admin1:123@bitcoin:18443" tls_enabled=false
chopsticks  | time="2024-01-27T16:21:37Z" level=fatal msg="creating wallet" error="could not list wallets: Method listwallets failed with error: Loading wallet…"
chopsticks  | time="2024-01-27T16:21:38Z" level=info msg="Starting server with configuration:" chain=bitcoin electrs_url="http://electrs:30000" faucet_enabled=true listen_url="0.0.0.0:3000" logger_enabled=true mining_enabled=true rpc_server_url="http://admin1:123@bitcoin:18443" tls_enabled=false

The workaround

Finally I poke it by calling nigiri rpc -generate 1. Now suddenly things start moving:

2024-01-27T18:17:04Z CreateNewBlock(): block weight: 888 txs: 0 fees: 0 sigops 400
2024-01-27T18:17:04Z Leaving InitialBlockDownload (latching to false)
2024-01-27T18:17:04Z UpdateTip: new best=148a310f9b7441b3dcdd67360d7563b2d9c43a0ad5d677b85f71370997ff06e7 height=117 version=0x20000000 log2_work=7.882643 tx=134 date='2024-01-27T18:17:04Z' progress=1.000000 cache=0.0MiB(1txo)
2024-01-27T18:17:04Z [default wallet] AddToWallet 44930e5bea687d6164c4f51fc07a0af8ec3b44e74dfdf1aedefddc1d5d928b76  new

This seems to be the key: "Leaving InitialBlockDownload"

Now electrs can do its thing:

...
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | WARN - waiting for bitcoind sync to finish: 116/116 blocks, verification progress: 100.000%
electrs  | DEBUG - opening DB at "./db/regtest/newindex/txstore"
electrs  | DEBUG - 0 blocks were added
electrs  | DEBUG - opening DB at "./db/regtest/newindex/history"
electrs  | DEBUG - 0 blocks were indexed
electrs  | DEBUG - opening DB at "./db/regtest/newindex/cache"
electrs  | DEBUG - downloading all block headers up to 148a310f9b7441b3dcdd67360d7563b2d9c43a0ad5d677b85f71370997ff06e7
electrs  | TRACE - downloading 118 block headers
electrs  | INFO - hash=148a310f9b7441b3dcdd67360d7563b2d9c43a0ad5d677b85f71370997ff06e7 height=117 @ 2024-01-27T18:17:04Z (118 left to index)
electrs  | DEBUG - adding transactions from 118 blocks using Bitcoind
electrs  | DEBUG - hash=148a310f9b7441b3dcdd67360d7563b2d9c43a0ad5d677b85f71370997ff06e7 height=117 @ 2024-01-27T18:17:04Z (118 left to index)
electrs  | DEBUG - writing 700 rows to RocksDB { path: "./db/regtest/newindex/txstore" }, flush=Disable

And now everything is fine again.

It's not every time I start/stop nigiri. I did upgrade Docker just before this so perhaps the container and/or one of these processes went through an ugly shutdown?

Just leaving this here in case anyone else runs into a similar problem.