search

romanz / electrs

An efficient re-implementation of Electrum Server in Rust
MIT License
1.02k stars 373 forks source link

Bug: elecrts fails with "failed to shutdown p2p connection: Transport endpoint is not connected (os error 107)" #769

Open jirigrill opened 1 year ago

jirigrill commented 1 year ago

Describe the bug I am trying to setup Electrum server, but when I run "electrs --conf .electrs/electrs.conf" I get this error: WARN electrs::p2p] failed to shutdown p2p connection: Transport endpoint is not connected (os error 107)

Electrs version I am using current master (v0.9.9)

To Reproduce Steps to reproduce the behavior:

  1. Configure and start electrs
  2. Error

Expected behavior Electrs will get synced

Configuration

#Bitcoin Core settings
network = "bitcoin"
daemon_dir= "/home/admin/.bitcoin"
daemon_rpc_addr = "127.0.0.1:8332"
daemon_p2p_addr = "127.0.0.1:8333"

#Electrs settings
electrum_rpc_addr = "127.0.0.1:50001"
db_dir = "/home/admin/.electrs/db"

#Logging
log_filters = "DEBUG"
timestamp = true

Error message

WARN  electrs::p2p] failed to shutdown p2p connection: Transport endpoint is not connected (os error 107)
Error: electrs failed

Caused by:
    receiving on an empty and disconnected channel

System running electrs

primeroz commented 1 year ago

I had a similar issue when i just upgraded from 0.8 to 0.9.9

for me i had to make sure that bitcoin.conf had bind=0.0.0.0 set since in my TRACE logs of electrs it was failing when trying to send to the P2P endpoint

antonilol commented 1 year ago

i get this error when using the netcat example

i get the right response, but netcat doesn't return the command prompt after receiving the data, so i kill it with ^C (SIGTERM) after killing netcat, electrs logs a warning [2022-11-03T16:23:55.531Z WARN electrs::server] 39: failed to shutdown TCP receiving Transport endpoint is not connected (os error 107)

$ echo '{"jsonrpc": "2.0", "method": "blockchain.scripthash.listunspent", "params": ["37d930a0d474560e16eb7e40bcd02ec16c3dad3317c10b272e743a024eb37bea"], "id": 9}' | netcat 127.0.0.1 60401
{"id":9,"jsonrpc":"2.0","result":[{"height":525,"tx_hash":"ff864f18956f4abcf550328ca37d5bd74598e9d2ac75e65fd3d3a13048c0abec","tx_pos":0,"value":400000000},{"height":525,"tx_hash":"b4930f0ca5a6f2b1cd4353f3c01ae6d0555b5430ca854a993e36f6c2ff1c1f4b","tx_pos":0,"value":250000000}]}
^C
IanMichaelHarper commented 1 year ago

I also get this bug on my node. More details can be found at the raspiblitz issue I opened

Rav3nPL commented 5 months ago

Seems like it it caused when bitcoind p2p connections pool are full.

trieska commented 5 months ago

it was bit tricky to start electrs 3 days ago, but adding whitelist parameter to bitcoin.conf help so electrs did sync.

I need to restart server and after that electrs is not able to connect to bitcoind and I am getting same error.

my server has local ip 192.168.75.10 bitcoind is binding 0.0.0.0 by default and I did forward 8333 on router so I can see that other nodes are connected.

here is part of my bitcoin.conf

maxuploadtarget=512M
maxconnections=14
whitelist=download@127.0.0.1
whitelist=download@192.168.75.10

and here electrs.toml

auth="euser:asfdasfasfasfasfasdf"

network = "bitcoin"

daemon_rpc_addr = "127.0.0.1:8332"
daemon_p2p_addr = "192.168.75.10:8333"
daemon-dir = "/mnt/node_1/blockchain"

electrum_rpc_addr = "192.168.75.10:50001"
db_dir = "/mnt/node_1/electrs"

log_filters = "TRACE"
timestamp = true

yes, bitcoin p2p pool is full but whitelist should take care of that, also if bitcoind did save that peer 192.168.75.10 (local electrs) did download more then maxuploadtarget that should be solved by whitelist too.

what I dont understand why it was working two days ago

where is log from electrs

Jan 23 22:27:59 skriatok electrs[456022]: Starting electrs 0.10.0 on x86_64 linux with Config { network: Bitcoin, db_path: "/mnt/node_1/electrs/bitcoin", daemon_dir: "/mnt/btc_node/.bitcoin", daemon_auth: UserPass("euser", "<sensitive>"), daemon_rpc_addr: 127.0.0.1:8332, daemon_p2p_addr: 192.168.75.10:8333, electrum_rpc_addr: 192.168.75.10:50001, monitoring_addr: 127.0.0.1:4224, wait_duration: 10s, jsonrpc_timeout: 15s, index_batch_size: 10, index_lookup_limit: None, reindex_last_blocks: 0, auto_reindex: true, ignore_mempool: false, sync_once: false, skip_block_download_wait: false, disable_electrum_rpc: false, server_banner: "Welcome to electrs 0.10.0 (Electrum Rust Server)!", signet_magic: f9beb4d9, args: [] }
    Jan 23 22:27:59 skriatok electrs[456022]: [2024-01-23T21:27:59.787Z DEBUG tiny_http] Server listening on 127.0.0.1:4224
    Jan 23 22:27:59 skriatok electrs[456022]: [2024-01-23T21:27:59.787Z INFO  electrs::metrics::metrics_impl] serving Prometheus metrics on 127.0.0.1:4224
    Jan 23 22:27:59 skriatok electrs[456022]: [2024-01-23T21:27:59.788Z INFO  electrs::server] serving Electrum RPC on 192.168.75.10:50001
    Jan 23 22:27:59 skriatok electrs[456022]: [2024-01-23T21:27:59.789Z DEBUG tiny_http] Running accept thread
    Jan 23 22:27:59 skriatok electrs[456022]: [2024-01-23T21:27:59.912Z INFO  electrs::db] "/mnt/node_1/electrs/bitcoin": 175 SST files, 45.258448579 GB, 5.678357143 Grows
    Jan 23 22:27:59 skriatok electrs[456022]: [2024-01-23T21:27:59.913Z DEBUG electrs::db] DB Some(Config { compacted: true, format: 0 })
    Jan 23 22:27:59 skriatok electrs[456022]: [2024-01-23T21:27:59.988Z DEBUG electrs::db] auto-compactions enabled
    Jan 23 22:28:06 skriatok electrs[456022]: [2024-01-23T21:28:06.646Z INFO  electrs::chain] loading 826999 headers, tip=0000000000000000000130df2873283f409788609c674637080b13a7f2719906
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.268Z INFO  electrs::chain] chain updated: tip=0000000000000000000130df2873283f409788609c674637080b13a7f2719906, height=826999
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.348Z DEBUG bitcoincore_rpc] JSON-RPC request: getblockchaininfo []
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.350Z TRACE bitcoincore_rpc] JSON-RPC response for getblockchaininfo: {"chain":"main","blocks":827048,"headers":827048,"bestblockhash":"00000000000000000001b7302799c43f9191738aadc160fa87eb04866c11f0a7","difficulty":70343519904866.8,"time":1706044246,"mediantime":1706041347,"verificationprogress":0.9999939506341941,"initialblockdownload":false,"chainwork":"000000000000000000000000000000000000000066d64f3307db0e4fb5b208d4","size_on_disk":616981805120,"pruned":false,"warnings":""}
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.350Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.352Z TRACE bitcoincore_rpc] JSON-RPC response for getnetworkinfo: {"version":260000,"subversion":"/Satoshi:26.0.0/","protocolversion":70016,"localservices":"0000000000000409","localservicesnames":["NETWORK","WITNESS","NETWORK_LIMITED"],"localrelay":true,"timeoffset":0,"networkactive":true,"connections":14,"connections_in":3,"connections_out":11,"networks":[{"name":"ipv4","limited":false,"reachable":true,"proxy":"","proxy_randomize_credentials":false},{"name":"ipv6","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false},{"name":"onion","limited":false,"reachable":true,"proxy":"127.0.0.1:9050","proxy_randomize_credentials":true},{"name":"i2p","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false},{"name":"cjdns","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false}],"relayfee":0.00001000,"incrementalfee":0.00001000,"localaddresses":[{"address":"blablabla.onion","port":8333,"score":4}],"warnings":""}
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.352Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.354Z TRACE bitcoincore_rpc] JSON-RPC response for getnetworkinfo: {"version":260000,"subversion":"/Satoshi:26.0.0/","protocolversion":70016,"localservices":"0000000000000409","localservicesnames":["NETWORK","WITNESS","NETWORK_LIMITED"],"localrelay":true,"timeoffset":0,"networkactive":true,"connections":14,"connections_in":3,"connections_out":11,"networks":[{"name":"ipv4","limited":false,"reachable":true,"proxy":"","proxy_randomize_credentials":false},{"name":"ipv6","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false},{"name":"onion","limited":false,"reachable":true,"proxy":"127.0.0.1:9050","proxy_randomize_credentials":true},{"name":"i2p","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false},{"name":"cjdns","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false}],"relayfee":0.00001000,"incrementalfee":0.00001000,"localaddresses":[{"address":"blabla.onion","port":8333,"score":4}],"warnings":""}
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.354Z DEBUG bitcoincore_rpc] JSON-RPC request: getblockchaininfo []
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.355Z TRACE bitcoincore_rpc] JSON-RPC response for getblockchaininfo: {"chain":"main","blocks":827048,"headers":827048,"bestblockhash":"00000000000000000001b7302799c43f9191738aadc160fa87eb04866c11f0a7","difficulty":70343519904866.8,"time":1706044246,"mediantime":1706041347,"verificationprogress":0.9999939506341941,"initialblockdownload":false,"chainwork":"000000000000000000000000000000000000000066d64f3307db0e4fb5b208d4","size_on_disk":616981805120,"pruned":false,"warnings":""}
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.355Z DEBUG bitcoincore_rpc] JSON-RPC request: getnetworkinfo []
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.356Z TRACE bitcoincore_rpc] JSON-RPC response for getnetworkinfo: {"version":260000,"subversion":"/Satoshi:26.0.0/","protocolversion":70016,"localservices":"0000000000000409","localservicesnames":["NETWORK","WITNESS","NETWORK_LIMITED"],"localrelay":true,"timeoffset":0,"networkactive":true,"connections":14,"connections_in":3,"connections_out":11,"networks":[{"name":"ipv4","limited":false,"reachable":true,"proxy":"","proxy_randomize_credentials":false},{"name":"ipv6","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false},{"name":"onion","limited":false,"reachable":true,"proxy":"127.0.0.1:9050","proxy_randomize_credentials":true},{"name":"i2p","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false},{"name":"cjdns","limited":true,"reachable":false,"proxy":"","proxy_randomize_credentials":false}],"relayfee":0.00001000,"incrementalfee":0.00001000,"localaddresses":[{"address":"blabla.onion","port":8333,"score":4}],"warnings":""}
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.357Z TRACE electrs::p2p] send: Version(VersionMessage { version: 70001, services: ServiceFlags(0), timestamp: 1706045294, receiver: Address {services: ServiceFlags(NONE), address: 0.0.0.0, port: 0}, sender: Address {services: ServiceFlags(NONE), address: 0.0.0.0, port: 0}, nonce: 2823239126432311126, user_agent: "/electrs:0.10.0/", start_height: 0, relay: false })
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.358Z DEBUG electrs::p2p] closing p2p_recv thread: connection closed
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.358Z DEBUG electrs::p2p] closing p2p_loop thread: peer has disconnected
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.359Z DEBUG electrs::p2p] closing p2p_send thread: no more messages to send
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.359Z WARN  electrs::p2p] failed to shutdown p2p connection: Transport endpoint is not connected (os error 107)
    Jan 23 22:28:14 skriatok electrs[456022]: [2024-01-23T21:28:14.359Z INFO  electrs::db] closing DB at /mnt/node_1/electrs/bitcoin
    Jan 23 22:28:14 skriatok electrs[456022]: Error: electrs failed
    Jan 23 22:28:14 skriatok electrs[456022]: Caused by:
    Jan 23 22:28:14 skriatok electrs[456022]:     receiving on an empty and disconnected channel
    Jan 23 22:28:14 skriatok systemd[1]: electrs.service: Main process exited, code=exited, status=1/FAILURE
    Jan 23 22:28:14 skriatok systemd[1]: electrs.service: Failed with result 'exit-code'.

I've been struggling with this all day and can't figure out why bitcoin refuses connection from local electrs, at least that's how I see it. Thanks for help

trieska commented 5 months ago

I did find this discusion helpful.

well, it is quite strange to me. So I decided to increase maxconnections=20 then stop bitcoind and remove peers.dat. I did start bitcoind and wait for few minutes then start electrs.

electrs was able to connect, maybe there was not to many inbound connection.

but I did whitelist local electrs which should not be count. Or is it ?

EDIT:

after while I did see that connection is ok and electrs is communicating with bitcoind so I decided to reduce logging, I did restart electrs and now it is not able to connect. in btc-rpc-explorer I see following counts for peers:

inbound 9
outbound-full-relay 8
block-relay-only    2