farcaster-node
farcaster-node copied to clipboard
farcaster-project
Bitcoin syncer silent failure using ssl://blockstream.info:993
Issue I described in IRC before already: when using ssl://blockstream.info:993 as the electrum server on testnet, without any other logged failures, start receiving only empty messages from blockstream.info. Thereafter, don't receive any real messages (such as blockheight updates) from the electrum server anymore, so all running swaps stall silently (except for trace logging hints).
extract of logs:
[2022-08-31T11:23:27Z TRACE microservices::peer] Peer message processing complete
[2022-08-31T11:23:27Z TRACE microservices::peer] Awaiting for peer messages...
[2022-08-31T11:23:27Z DEBUG microservices::peer::connection] Awaiting incoming messages from the remote peer
[2022-08-31T11:23:27Z TRACE microservices::esb::controller] Received ESB request from 1 service busses...
[2022-08-31T11:23:27Z DEBUG microservices::esb::controller] loopback -> peerd<020615001ab19d153c15e0c6c91ca3128fb56a91ecdeecd537640c0861464f5532@0.0.0.0:18750>: protocol_message(pong(..))
[2022-08-31T11:23:27Z DEBUG farcaster_node::peerd::runtime] BRIDGE RPC request: protocol_message(pong(..))
[2022-08-31T11:23:27Z TRACE farcaster_node::peerd::runtime] Got pong reply, exiting pong await mode
[2022-08-31T11:23:27Z TRACE microservices::esb::controller] request processing complete
[2022-08-31T11:23:27Z TRACE microservices::esb::controller] Awaiting for ESB request from 3 service buses...
[2022-08-31T11:23:27Z TRACE electrum_client::raw_client] ==> {"jsonrpc":"2.0","id":299,"method":"server.ping","params":[]}
[2022-08-31T11:23:27Z TRACE electrum_client::raw_client] Starting reader thread with `until_message` = Some(299)
[2022-08-31T11:23:27Z TRACE electrum_client::raw_client] <== "{\"id\":299,\"jsonrpc\":\"2.0\",\"result\":null}\n"
[2022-08-31T11:23:27Z TRACE electrum_client::raw_client] Reader thread 299 received a response for its request
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::conn] Conn::read_head
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::io] received 310 bytes
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] parse_headers;
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] -> parse_headers;
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] Response.parse bytes=310
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] Response.parse Complete(160)
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] <- parse_headers;
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] -- parse_headers;
[2022-08-31T11:23:28Z DEBUG hyper::proto::h1::io] parsed 5 headers
[2022-08-31T11:23:28Z DEBUG hyper::proto::h1::conn] incoming body is content-length (150 bytes)
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::decode] decode; state=Length(150)
[2022-08-31T11:23:28Z DEBUG hyper::proto::h1::conn] incoming body completed
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::conn] maybe_notify; read_from_io blocked
[2022-08-31T11:23:28Z TRACE want] signal: Want
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[2022-08-31T11:23:28Z TRACE want] signal: Want
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[2022-08-31T11:23:28Z TRACE hyper::client::pool] put; add idle connection for ("http", localhost:38083)
[2022-08-31T11:23:28Z DEBUG hyper::client::pool] pooling idle connection for ("http", localhost:38083)
[2022-08-31T11:23:28Z DEBUG reqwest::async_impl::client] response '200 OK' for http://localhost:38083/json_rpc
[2022-08-31T11:23:28Z TRACE hyper::client::pool] take? ("http", localhost:38083): expiration = Some(90s)
[2022-08-31T11:23:28Z DEBUG hyper::client::pool] reuse idle connection for ("http", localhost:38083)
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] encode_headers;
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] -> encode_headers;
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] Client::encode method=POST, body=Some(Known(466))
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] <- encode_headers;
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::role] -- encode_headers;
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::encode] sized write, len = 466
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::io] buffer.queue self.len=116 buf.len=466
[2022-08-31T11:23:28Z DEBUG hyper::proto::h1::io] flushed 582 bytes
[2022-08-31T11:23:28Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
[2022-08-31T11:23:28Z TRACE electrum_client::raw_client] <== ""
This failure's distinct from #628 and does not happen with electrs v0.8.9 or v0.9.7, so I'm guessing it's related to blockstream's fork. I will spin up an instance and see if I can reproduce.
Do you still experience this issue or did #735 also fixed it on your side? (On my side it did)
Yup, I haven't seen this issue crop up since #735 at all, so we can safely assume the bump resolved it.