electrs icon indicating copy to clipboard operation
electrs copied to clipboard
verified publisher icon romanz

Bug: electrs terminates with "Address already in use (os error 98)"

Open florianfink opened this issue 4 years ago • 17 comments

Describe the bug After upgrade to electrs 0.9.0 (from 0.8.6), the database migration is successful. But electrs terminates regularly (around 2 minutes after restart), after utilizing 100% CPU, with error messages: Address already in use (os error 98) or JSON-RPC error: transport error: Couldn't connect to host: Cannot assign requested address (os error 99)

Electrs version 0.9.0

Configuration

# Bitcoin Core settings
network = "bitcoin"
daemon_dir= "/var/lib/bitcoin"
daemon_rpc_addr = "127.0.0.1:8332"

# Electrs settings
electrum_rpc_addr = "127.0.0.1:50001"
db_dir = "/var/lib/electrs/db"
index_lookup_limit = 1000

# Logging
verbose = 2
timestamp = true
rust_backtrace = true

Error log

Oct 07 17:58:33 nuc systemd[1]: Started Electrs daemon.
Oct 07 17:58:33 nuc electrs[7361]: Config { network: Bitcoin, db_path: "/var/lib/electrs/db/bitcoin", daemon_dir: "/var/lib/bitcoin", daemon_auth: UserPass("sensitive", "<sensitive>"), daemon_rpc_addr: V4(127.0.0.1:8332), daemon_p2p_addr: V4(127.0.0.1:8333), electrum_rpc_addr: V4(127.0.0.1:50001), monitoring_addr: V4(127.0.0.1:4224), wait_duration: 10s, jsonrpc_timeout: 15s, index_batch_size: 10, index_lookup_limit: Some(1000), auto_reindex: true, ignore_mempool: false, sync_once: false, server_banner: "Welcome to electrs 0.9.0 (Electrum Rust Server)!", args: [] }
Oct 07 17:58:33 nuc electrs[7361]: [2021-10-07T15:58:33.748Z INFO  electrs::db] "/var/lib/electrs/db/bitcoin": 132 SST files, 31.88136245 GB, 3.971850754 Grows
Oct 07 17:58:37 nuc electrs[7361]: [2021-10-07T15:58:37.183Z INFO  electrs::chain] loading 703965 headers, tip=000000000000000000086d6c9d2a042e8a6a8b0a64aec0aafd2b331428a1c2f7
Oct 07 17:58:40 nuc electrs[7361]: [2021-10-07T15:58:40.738Z INFO  electrs::chain] chain updated: tip=000000000000000000086d6c9d2a042e8a6a8b0a64aec0aafd2b331428a1c2f7, height=703965
Oct 07 17:58:40 nuc electrs[7361]: [2021-10-07T15:58:40.804Z INFO  electrs::index] indexing 6 blocks: [703966..703971]
Oct 07 17:58:41 nuc electrs[7361]: [2021-10-07T15:58:41.172Z INFO  electrs::chain] chain updated: tip=00000000000000000007549cac7664af5f2185862738e08805d1b440a0567181, height=703971
Oct 07 17:59:45 nuc electrs[7361]: [2021-10-07T15:59:45.539Z INFO  electrs::db] closing DB at /var/lib/electrs/db/bitcoin
Oct 07 17:59:45 nuc electrs[7361]: Error: server failed
Oct 07 17:59:45 nuc electrs[7361]: Caused by:
Oct 07 17:59:45 nuc electrs[7361]:     Address already in use (os error 98)
Oct 07 17:59:45 nuc systemd[1]: electrs.service: Main process exited, code=exited, status=1/FAILURE
Oct 07 17:59:45 nuc systemd[1]: electrs.service: Failed with result 'exit-code'.

and sometimes

Oct 07 17:20:41 nuc electrs[8135]: Error: daemon not available
Oct 07 17:20:41 nuc electrs[8135]: Caused by:
Oct 07 17:20:41 nuc electrs[8135]:     JSON-RPC error: transport error: Couldn't connect to host: Cannot assign requested address (os error 99)
Oct 07 17:20:41 nuc systemd[1]: electrs.service: Main process exited, code=exited, status=1/FAILURE
Oct 07 17:20:41 nuc systemd[1]: electrs.service: Failed with result 'exit-code'.

System running electrs Deployment method: manual Operating System: Ubuntu 18.04.6 LTS Kernel: Linux 4.15.0-159-generic Architecture: x86-64

florianfink avatar Oct 07 '21 16:10 florianfink

Something else has that port open, my guess is you forgot to shutdown the previous instance of electrs.

Kixunil avatar Oct 07 '21 17:10 Kixunil

Definitely no other instance of electrs running. I stopped the service, replaced the binary, restarted it. Then, the database migration took place successfully (size of ./db/bitcoin is around 30G, that should be ok?) Also, I get the same error after reboot. And it worked perfectly using the 0.8.6 binary - haven't changed anything else.

florianfink avatar Oct 07 '21 18:10 florianfink

Many thanks for reporting this issue! Could you please re-run it with higher log verbosity (verbose = 3)?

romanz avatar Oct 07 '21 18:10 romanz

Thanks for responding so fast! That's a very long log, but I'll break it down. First a whole lot of this:

Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.186Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["1ba8cb5f2703efceea50cfa1afd24820866cdbc719e8272de5cb99b68d8a3ed4"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.187Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["ca3583c1a4ce1234e436c4cd986b7145412970ccea788570cd34233033168c9e"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.189Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["7a2bff1398054e7da388fd6aad816d3a6820088d5bef8c8f15d07c91af0b349d"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.190Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["f61085f5bc5d4d3a382a44bd60865d586cbb9912ed3bbec3ac5f1af782dd3146"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.194Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["d94ed837cf0eb4e9e854661b46df64af654052464c2767e3160ab4ca70804a94",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.196Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["686d3d1ff17b610bf112ff46e0b4f338a0be308b890ce6a6758cda78f1e03ea3",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.196Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["ffce1d6188c1ebbab7d9acff692d4e590393d53f5ddf380028511e82dccc6206",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.200Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["905fa25df1d76e31b8dfbc4c7562a77430bb030f6ae9b0a4f64f0d62d927b4ae",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.201Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["d94ed837cf0eb4e9e854661b46df64af654052464c2767e3160ab4ca70804a94"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.203Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["686d3d1ff17b610bf112ff46e0b4f338a0be308b890ce6a6758cda78f1e03ea3"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.207Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["905fa25df1d76e31b8dfbc4c7562a77430bb030f6ae9b0a4f64f0d62d927b4ae"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.208Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["ffce1d6188c1ebbab7d9acff692d4e590393d53f5ddf380028511e82dccc6206"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.211Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["551263f171860ccf136d0fa8af62b5904fabc232a5947f7d69af587f264e7304",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.214Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["28812c751286e0bf0af67597a8735f7df22d5c14aa9d8a4e15d0a563ca08e96e",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.216Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["7266e71d70ce3de4f055a869f708d4e55157ea359db1096c19eb6002cfea3db6",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.216Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["5d79d4c0f40410141eca2e7e63a5d504367d14d0ef324afd12bb70b5afa6370d",false]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.218Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["551263f171860ccf136d0fa8af62b5904fabc232a5947f7d69af587f264e7304"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.221Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["28812c751286e0bf0af67597a8735f7df22d5c14aa9d8a4e15d0a563ca08e96e"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.224Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["7266e71d70ce3de4f055a869f708d4e55157ea359db1096c19eb6002cfea3db6"]
Oct 07 20:42:28 nuc electrs[9103]: [2021-10-07T18:42:28.225Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["5d79d4c0f40410141eca2e7e63a5d504367d14d0ef324afd12bb70b5afa6370d"]
Oct 07 20:42:56 nuc systemd-journald[443]: Suppressed 17605 messages from electrs.service

Then a whole lot of that:

Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.139Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getrawtransaction: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.140Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["5802d02cfeac620ca58b14d44521707b9584a7d370fc1fe84e9769b7eeb6a59a"]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.143Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getrawtransaction: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.143Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["dbf2a8556d98fc60ba85e3a77d8fab541b45790d2490b2f1a4c253459f863cb3"]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.143Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["513251e6c7f6d70119e78bb6412f43d924619e92085251f591f765737d3fca5f"]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.145Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getrawtransaction: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.145Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["7c654492a8339a777ef8cd7f494e9ad5176fc5d5bfa28810dd02dddbd821b929"]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.151Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getmempoolentry: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.151Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["3b560a34d49adad1d716ca4ff0b0c274988b001bdc572d817a2af1404d414d1e",false]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.155Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getmempoolentry: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.155Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["31b9ecc9b39ee62bccb24c2bc74b1d695582e4e2cb5c7b021ae83d16ec4ffc55",false]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.155Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["1fbdca7fb477a99227504206d938a7e7645516febcaad896662b01dfafdaedf2",false]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.158Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getmempoolentry: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.159Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getrawtransaction ["826ce4f9c5e1d13e74ba89cdca2d6c47a6ffe4c8c319d9c4c11d87878683d7be",false]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.162Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getrawtransaction: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.162Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["3b560a34d49adad1d716ca4ff0b0c274988b001bdc572d817a2af1404d414d1e"]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.166Z DEBUG bitcoincore_rpc::client] JSON-RPC failed parsing reply of getrawtransaction: JsonRpc(Transport(SocketError(Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" })))
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.166Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["1fbdca7fb477a99227504206d938a7e7645516febcaad896662b01dfafdaedf2"]
Oct 07 20:42:56 nuc electrs[9103]: [2021-10-07T18:42:56.166Z DEBUG bitcoincore_rpc::client] JSON-RPC request: getmempoolentry ["31b9ecc9b39ee62bccb24c2bc74b1d695582e4e2cb5c7b021ae83d16ec4ffc55"]

florianfink avatar Oct 07 '21 18:10 florianfink

It seems to come from here: https://github.com/rust-bitcoin/rust-bitcoincore-rpc/blob/27d354338e8da01b2f79e7e34eb42732859ebe7b/client/src/client.rs#L1151

Could you please see if electrs works with --ignore-mempool? It should result in much less RPCs to bitcoind.

romanz avatar Oct 07 '21 18:10 romanz

Could you run lsof -i :50001 under root to check if it's actually electrs trying to bind multiple times?

Kixunil avatar Oct 07 '21 19:10 Kixunil

Could you run lsof -i :50001 under root to check if it's actually electrs trying to bind multiple times?

COMMAND    PID      USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
electrs   1326   user1   17u  IPv4  32750      0t0  TCP localhost.localdomain:50001 (LISTEN)
electrs   1326   user1   23u  IPv4  32754      0t0  TCP localhost.localdomain:50001->localhost.localdomain:54482 (ESTABLISHED)
electrs   1326   user1   25u  IPv4  32754      0t0  TCP localhost.localdomain:50001->localhost.localdomain:54482 (ESTABLISHED)
btc-rpc-e 1648 user2   21u  IPv4  57509      0t0  TCP localhost.localdomain:54482->localhost.localdomain:50001 (ESTABLISHED)

Could you please see if electrs works with --ignore-mempool? It should result in much less RPCs to bitcoind.

After starting up the service again this morning (without --ignore-mempool), it works flawlessly. I haven't changed any configuration. Could it be that it was because the mempool was kind of loaded yesterday with around 25k transactions (vs. around 5k now)?

florianfink avatar Oct 08 '21 09:10 florianfink

Yep, sounds reasonable...

romanz avatar Oct 08 '21 09:10 romanz

I lowered index_lookup_limit to 100 for now (not sure if that could help?) and will keep an eye on it the next time the mempool fills up.

florianfink avatar Oct 08 '21 09:10 florianfink

Hmm, why would mempoll filling have any effect on electrs trying to bind multiple times? That sounds super-weird to me!

Kixunil avatar Oct 08 '21 09:10 Kixunil

I lowered index_lookup_limit to 100 for now (not sure if that could help?)

It is used to prevent loading "too popular addresses" (having more than index_lookup_limit funding transactions), e.g. https://blockstream.info/address/1CK6KHY6MHgYvmRQ4PAafKYDrg1ejbH1cE.

romanz avatar Oct 08 '21 12:10 romanz

IIUC, the AddrNotAvailable error happens here: https://github.com/apoelstra/rust-jsonrpc/blob/64005f2896b98934e58c3a22f7d1430b110cb01a/src/simple_http.rs#L59 Note that we open a separate TCP connection for each RPC :/

       EADDRNOTAVAIL
              (Internet domain sockets) The socket referred to by sockfd had not previously been 
              bound to an address and, upon attempting to bind it to an ephemeral port, it was 
              determined that all port numbers in the ephemeral port range are currently in use.  
              See the discussion of /proc/sys/net/ipv4/ip_local_port_range in ip(7).

romanz avatar Oct 08 '21 12:10 romanz

Maybe we should batch mempool retrieval (getmempoolentry and getrawtransaction) RPCs... :thinking:

romanz avatar Oct 08 '21 12:10 romanz

all port numbers in the ephemeral port range are currently in use

This must be the case because connect binds ephemeral ports only.

On my machine:

$ cat /proc/sys/net/ipv4/ip_local_port_range 
32768	60999

So either the system is configured to much narrower range, is overloaded with bunch of ephemeral connections or electrs is opening > 28000 connections per ~minute.

Since RPC opens a new connection each time and does no pooling or other optimization techniques I think it should be improved regardless of whether this is a bug in electrs.

Kixunil avatar Oct 08 '21 13:10 Kixunil

Same on my machine:

$ cat /proc/sys/net/ipv4/ip_local_port_range 
32768	60999

There is also lnd and btc-rpc-explorer running on that machine, which might be responsible for additional connections.

or electrs is opening > 28000 connections per ~minute.

Could that happen when there are >28000 transactions in mempool and electrs is restarted?

florianfink avatar Oct 08 '21 14:10 florianfink

Yes, that'd make sense. Transactions are requested from mempool one-by-one

So I guess as a lighter-weight optimization we should just reuse the connection in mempool sync. Sadly this is not currently possible with jsonrpc, so we need to modify that one first.

Kixunil avatar Oct 08 '21 15:10 Kixunil

Could you run lsof -i :50001 under root to check if it's actually electrs trying to bind multiple times?

COMMAND    PID      USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
electrs   1326   user1   17u  IPv4  32750      0t0  TCP localhost.localdomain:50001 (LISTEN)
electrs   1326   user1   23u  IPv4  32754      0t0  TCP localhost.localdomain:50001->localhost.localdomain:54482 (ESTABLISHED)
electrs   1326   user1   25u  IPv4  32754      0t0  TCP localhost.localdomain:50001->localhost.localdomain:54482 (ESTABLISHED)
btc-rpc-e 1648 user2   21u  IPv4  57509      0t0  TCP localhost.localdomain:54482->localhost.localdomain:50001 (ESTABLISHED)

Could you please see if electrs works with --ignore-mempool? It should result in much less RPCs to bitcoind.

After starting up the service again this morning (without --ignore-mempool), it works flawlessly. I haven't changed any configuration. Could it be that it was because the mempool was kind of loaded yesterday with around 25k transactions (vs. around 5k now)?

I'm having the same error/issue. How do you start up the service without --ignore-mempool?

heredia21 avatar Dec 10 '21 16:12 heredia21