search

farcaster-project / farcaster-node

Farcaster cross-chain atomic swap node.
https://crates.io/crates/farcaster_node
MIT License
103 stars 19 forks source link

Bitcoin Syncer failures not logged in production build #628

Closed Lederstrumpf closed 2 years ago

Lederstrumpf commented 2 years ago

Bitcoin syncer is failing on me regularly (using [ssl://blockstream.info:993]()). I've had 100 swaps running overnight where the takers disconnected for well over the cancel threshold, and the maker didn't cancel since it wasn't receiving block height updates from the syncer, but also no errors logged for the production build. Monero syncer was still working, so would maker would also broadcast buy txs, but these would be ignored silently. Maybe we're getting filtered by blockstream.info?

Anyway: I'll switch to debug logging to identify what went wrong, but whatever the issue is - we should have users be notified in production builds of such issues.

h4sh3d commented 2 years ago

Maybe we're getting filtered by blockstream.info?

I don't think so. Probably the same errors we have with latest version in CI

Lederstrumpf commented 2 years ago

Here's (one such) failure scenario where the bitcoin synclet run routine terminates after receiving block 2315082 at 2022-08-05T22:45:32Z:

[2022-08-05T22:32:25Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: c1fc83b9255b0d10cac0f25d48d91d8fb5884b276e05e3d545cea37fce158763
[2022-08-05T22:32:25Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: 269c4906318e133dcc5aa5439f84218d3134102b01b70e0b6aa762e54d3a5faa
[2022-08-05T22:32:27Z DEBUG farcaster_node::syncerd::bitcoin_syncer] trying to broadcast tx: "020000000001019a148aab72a022e2e14655f0e7b4883eb1000bbb6866430bc88625cef4aa15d900000000001e00000001980c000000000000220020d7380880ec86abc9bd8b09933747abcc1c5770ad159b0421782341ac5f3f75760347304402204a62a23640268900121f93a2d0fb4a0a89da31f79f7381108545fa7d01ec913c02204ce0439513990490305461de26605934ba0fd66fe6b5e57909f2315dd0ff07440147304402203692d3090ad15f8f28cc350519929d442655ee321f5606a1e6b3b950ee7ea9c702202cfdbabf56bd28bc535fd12d26405e06c35cb6ee971893bfc563575b139f464e014621037bf78fce94641726fe96a6b9d8db19f609f0cf5d5a1d02ae51e0768e56999790ad210355347bde45d1cb80c6dd67daeb319ec333278770c668cb9b3f687d4c7b14b53fac00000000"
[2022-08-05T22:32:27Z INFO  farcaster_node::syncerd::bitcoin_syncer] Successfully broadcasted: 1267bab35dbdc88dee16a566540c302fed4a94dcfe07d05b84eaf1ce85e5dd0e
[2022-08-05T22:45:33Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: 1267bab35dbdc88dee16a566540c302fed4a94dcfe07d05b84eaf1ce85e5dd0e
[2022-08-05T22:45:34Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: 40df2a9c1ff080f9a2efde5c7f2dfcb4a8e164670ae1caf7aa24a524cab6da24
[2022-08-05T22:45:36Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: e23f11dd6941eee343b0b9539e695d991f529b87a2777501457f86ace7166fce
thread 'tokio-runtime-worker' panicked at 'Should be found in the history if we successfully queried `transaction_get`', src/syncerd/bitcoin_syncer.rs:288:24
[2022-08-05T22:45:36Z DEBUG farcaster_node::syncerd::bitcoin_syncer] exiting bitcoin synclet run routine with: Err(JoinError::Panic(Id(6), ...))
[2022-08-05T22:45:36Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: edd50a47b92ebe4c3a82045be35753b4c399066c7aa6af073df40fd302669c0b

in the handling of this block, later also get this panic:

[2022-08-05T22:45:44Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: 2aeab0c76180eea60cff81b564177504f6b4d24d11c1a2bd293b998d24bd41ef
[2022-08-05T22:45:44Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: 1c8ad1a3b7ecd788da3d9559b6df51de50f135ff9f67e4486e3c759f0282d50a
[2022-08-05T22:45:44Z DEBUG farcaster_node::syncerd::bitcoin_syncer] Updated tx: 7fa9694da65c6985dedbbf165b3dce4a5716e85491b321b07304877f32206862
thread 'tokio-runtime-worker' panicked at 'error sending event from the syncer state: SendError(SyncerdBridgeEvent { event: TransactionConfirmations(TransactionConfirmations { id: TaskId(6), block: [0], confirmations: Some(0), tx: [2, 0, 0, 0, 0, 1, 1, 74, 239, 220, 152, 88, 193, 220, 100, 166, 132, 102, 16, 19, 151, 65, 248, 47, 68, 103, 208, 107, 205, 11, 39, 130, 135, 220, 215, 244, 23, 130, 61, 0, 0, 0, 0, 0, 30, 0, 0, 0, 1, 188, 6, 0, 0, 0, 0, 0, 0, 34, 0, 32, 173, 81, 164, 35, 140, 147, 42, 151, 84, 34, 113, 228, 217, 62, 241, 99, 231, 223, 97, 167, 200, 235, 99, 233, 131, 47, 236, 241, 70, 207, 240, 96, 3, 72, 48, 69, 2, 33, 0, 156, 125, 221, 65, 161, 141, 179, 253, 165, 74, 120, 230, 55, 87, 54, 42, 224, 62, 5, 165, 165, 11, 47, 189, 81, 99, 194, 29, 170, 38, 99, 241, 2, 32, 57, 191, 70, 88, 105, 204, 83, 250, 165, 207, 51, 21, 245, 44, 237, 93, 30, 165, 31, 46, 131, 136, 249, 69, 168, 252, 187, 80, 76, 158, 74, 85, 1, 71, 48, 68, 2, 32, 54, 81, 128, 199, 23, 185, 74, 101, 190, 237, 29, 39, 198, 189, 32, 4, 55, 45, 173, 192, 7, 233, 11, 190, 13, 178, 130, 85, 215, 139, 62, 46, 2, 32, 68, 147, 200, 133, 4, 61, 236, 31, 230, 155, 177, 162, 171, 243, 20, 42, 172, 4, 245, 241, 118, 225, 0, 141, 185, 155, 29, 169, 150, 153, 12, 200, 1, 70, 33, 3, 211, 27, 39, 25, 9, 59, 178, 11, 7, 171, 138, 47, 6, 185, 51, 94, 173, 183, 25, 217, 117, 189, 136, 130, 2, 236, 218, 186, 230, 249, 232, 139, 173, 33, 3, 248, 2, 88, 18, 98, 103, 153, 204, 236, 152, 230, 88, 105, 195, 52, 174, 92, 133, 33, 155, 164, 64, 7, 90, 88, 199, 243, 119, 185, 109, 244, 237, 172, 0, 0, 0, 0] }), source: Swap(0x3d22b018c1019f1fef1536545c065962682794e71b35439325bcf43ff3bf7952) })', src/syncerd/syncer_state.rs:781:14

thereafter, no more events from the bitcoin syncer. full logs can be found on the respective servers (farcasterd & electrs) under ..critical_logs/fn_issue_628_.. - electrs indexes block 2315082 at 2022-08-05T22:55:22.937Z.

Lederstrumpf commented 2 years ago

Been hitting this again, and iirc @h4sh3d too. This time with own electrs, so I also have electrs logs now. I believe that TCP shutdown is related to the panicking synclet.

electrs:

[2022-08-24T02:57:31.203Z INFO  electrs::electrum] your wallet uses less efficient method of querying electrs, consider contacting the developer of your wallet. Reason: blockchain.scripthash.get_history called for unsubscribed scripthash: 8bc98d962d2a4fae9d88cbaa1c1bd1c35d7a228dcc13d7216727ceddf5dead72
[2022-08-24T02:57:33.217Z WARN  electrs::electrum] RPC blockchain.transaction.get failed: failed to get transaction: JSON-RPC error: RPC error response: RpcError { code: -5, message: "No such mempool or blockchain transaction. Use gettransaction for wallet transactions.", data: None }
[2022-08-24T02:57:33.221Z WARN  electrs::electrum] RPC blockchain.transaction.get failed: failed to get transaction: JSON-RPC error: RPC error response: RpcError { code: -5, message: "No such mempool or blockchain transaction. Use gettransaction for wallet transactions.", data: None }
[2022-08-24T02:57:33.225Z WARN  electrs::electrum] RPC blockchain.transaction.get failed: failed to get transaction: JSON-RPC error: RPC error response: RpcError { code: -5, message: "No such mempool or blockchain transaction. Use gettransaction for wallet transactions.", data: None }
[2022-08-24T02:57:33.229Z WARN  electrs::electrum] RPC blockchain.transaction.get failed: failed to get transaction: JSON-RPC error: RPC error response: RpcError { code: -5, message: "No such mempool or blockchain transaction. Use gettransaction for wallet transactions.", data: None }
[2022-08-24T02:57:33.230Z INFO  electrs::electrum] your wallet uses less efficient method of querying electrs, consider contacting the developer of your wallet. Reason: blockchain.scripthash.get_history called for unsubscribed scripthash: 2de6ebe1b32c0380bae8edc287bf68640816a286630c74da88f0f70a7221c71c
[2022-08-24T02:57:33.235Z WARN  electrs::electrum] RPC blockchain.transaction.get failed: failed to get transaction: JSON-RPC error: RPC error response: RpcError { code: -5, message: "No such mempool or blockchain transaction. Use gettransaction for wallet transactions.", data: None }
[2022-08-24T02:57:33.242Z WARN  electrs::electrum] RPC blockchain.transaction.get failed: failed to get transaction: JSON-RPC error: RPC error response: RpcError { code: -5, message: "No such mempool or blockchain transaction. Use gettransaction for wallet transactions.", data: None }
[2022-08-24T02:57:33.247Z INFO  electrs::electrum] your wallet uses less efficient method of querying electrs, consider contacting the developer of your wallet. Reason: blockchain.scripthash.get_history called for unsubscribed scripthash: e5ccd26774c1dd63bb978c72e5229bd0ed27ecc722babdb973681c14fb27b4af
[2022-08-24T02:57:33.256Z WARN  electrs::server] 597: failed to shutdown TCP receiving Transport endpoint is not connected (os error 107)
[2022-08-24T02:57:33.256Z WARN  electrs::thread] recv_loop thread failed: 597: recv failed
[2022-08-24T02:57:33.256Z WARN  electrs::thread] because: Connection reset by peer (os error 104)
[2022-08-24T02:57:33.263Z INFO  electrs::electrum] your wallet uses less efficient method of querying electrs, consider contacting the developer of your wallet. Reason: blockchain.scripthash.get_history called for unsubscribed scripthash: 1aa99b89d6ceb918bfae85b842601f1af36cb76fdfd86b686f55e52eacbc262a

farcasterd:

[2022-08-24T02:57:33Z TRACE farcaster_node::peerd::runtime] Sending ping to the remote peer
[2022-08-24T02:57:33Z DEBUG microservices::peer::connection] Sending LN message to the remote peer: ping(4)
[2022-08-24T02:57:33Z TRACE microservices::peer::connection] Encoded message representation: [29, 0, 4, 0]
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] request processing complete
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Awaiting for ESB request from 3 service buses...
[2022-08-24T02:57:33Z TRACE microservices::peer::connection] Incoming data from the remote peer: [31, 0, 4, 0, 103, 148, 42, 129]
[2022-08-24T02:57:33Z DEBUG microservices::peer::connection] Message from the remote peer: pong(...)
[2022-08-24T02:57:33Z DEBUG microservices::peer] Processing message pong(...)
[2022-08-24T02:57:33Z TRACE microservices::peer] Message details: Pong([103, 148, 42, 129])
[2022-08-24T02:57:33Z TRACE farcaster_node::peerd::runtime] FWP message details: Pong([103, 148, 42, 129])
[2022-08-24T02:57:33Z DEBUG farcaster_node::peerd::runtime] Forwarding FWP message over BRIDGE interface to the runtime
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Sending send_message(pong(...)) from loopback to peerd<0301c5c9ad0d79c03b84aef40399a205a9c3255ec837c0c399ac2ef4e56ec18b02@0.0.0.0:18750> directly
[2022-08-24T02:57:33Z TRACE microservices::peer] Peer message processing complete
[2022-08-24T02:57:33Z TRACE microservices::peer] Awaiting for peer messages...
[2022-08-24T02:57:33Z DEBUG microservices::peer::connection] Awaiting incoming messages from the remote peer
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Received ESB request from 1 service busses...
[2022-08-24T02:57:33Z DEBUG microservices::esb::controller] loopback -> peerd<0301c5c9ad0d79c03b84aef40399a205a9c3255ec837c0c399ac2ef4e56ec18b02@0.0.0.0:18750>: send_message(pong(...))
[2022-08-24T02:57:33Z DEBUG farcaster_node::peerd::runtime] BRIDGE RPC request: send_message(pong(...))
[2022-08-24T02:57:33Z TRACE farcaster_node::peerd::runtime] Got pong reply, exiting pong await mode
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] request processing complete
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Awaiting for ESB request from 3 service buses...
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Received ESB request from 1 service busses...
[2022-08-24T02:57:33Z DEBUG microservices::esb::controller] client<11933005682547197862> -> farcasterd: list_swaps()
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Sending ---
    - "0x539ddf26b302805cd1b9db904f4577c3d8884efdc177a4d570f434d3eabef0da"
    - "0x3f8e365dc80996b1e3699ad4f81acf1e5e2dbb54aad5df4d4b69fb2c49d5cf3d"
    - "0xd2718a88520c2731f04f510c5960d8eba528f64e4593738e819dff62d3d0c0bd"
    - "0xed332d0975f98935bd2d7dfaa8b6ec4a3b07545f12f85364ba5ed978811f9c65"
    - "0x53fadd68c910b42c6f70da1783624444c3d34bd9686a258597b44b74b167bcaf"
    - "0xdee56f812ba9d838b25476a415ede1f594e0b7dcd887d38c367ed33cea3d90b2"
    - "0xc285d7e972df0a272dc40f112534a1d220d880245c687b955ec06baa83fae5cb"
    - "0x62c8a73cbdd2cac6c81b68368d09a162bf01e4afd3a1b9e88180beaa61fba09d"
    - "0x55beca92f94870bef7f6454e1fb943d5b288af4fe8f4c29fe5c2189add2c448a"
    - "0xe7f44dc5bd1c538f8eedb83a3ef470a07fdd0848c26784e303299b72be1da431"
     from farcasterd to client<11933005682547197862> directly
[2022-08-24T02:57:33Z TRACE farcaster_node::farcasterd::runtime] Processed all cli notifications
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] request processing complete
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Awaiting for ESB request from 2 service buses...
[2022-08-24T02:57:33Z TRACE electrum_client::raw_client] <== "{\"id\":15543,\"jsonrpc\":\"2.0\",\"result\":[]}\n"
[2022-08-24T02:57:33Z TRACE electrum_client::raw_client] Reader thread 15543 received a response for its request
thread 'tokio-runtime-worker' panicked at 'Should be found in the history if we successfully queried `transaction_get`', src/syncerd/bitcoin_syncer.rs:257:24
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[2022-08-24T02:57:33Z DEBUG farcaster_node::syncerd::bitcoin_syncer] exiting bitcoin synclet run routine with: Err(JoinError::Panic(Id(6), ...))
[2022-08-24T02:57:33Z DEBUG farcaster_node::syncerd::bitcoin_syncer] shutting down runtime
[2022-08-24T02:57:33Z TRACE farcaster_node::syncerd::bitcoin_syncer] sending request over syncerd bridge: SyncerdBridgeEvent(SyncerdBridgeEvent { event: HeightChanged(HeightChanged { id: TaskId(2), block: [68, 245, 227, 153, 156, 198, 29, 98, 238, 191, 67, 62, 208, 158, 210, 113, 3, 66, 249, 8, 191, 93, 40, 149, 20, 0, 0, 0, 0, 0, 0, 0], height: 2343648 }), source: Swap(0xdee56f812ba9d838b25476a415ede1f594e0b7dcd887d38c367ed33cea3d90b2) })
[2022-08-24T02:57:33Z TRACE microservices::esb::controller] Received ESB request from 1 service busses...
[2022-08-24T02:57:33Z TRACE farcaster_node::syncerd::bitcoin_syncer] sending request over syncerd bridge: SyncerdBridgeEvent(SyncerdBridgeEvent { event: HeightChanged(HeightChanged { id: TaskId(2), block: [68, 245, 227, 153, 156, 198, 29, 98, 238, 191, 67, 62, 208, 158, 210, 113, 3, 66, 249, 8, 191, 93, 40, 149, 20, 0, 0, 0, 0, 0, 0, 0], height: 2343648 }), source: Swap(0x62c8a73cbdd2cac6c81b68368d09a162bf01e4afd3a1b9e88180beaa61fba09d) })

So farcasterd log is same as before, except that it didn't hit the thread 'tokio-runtime-worker' panicked at 'error sending event from the syncer state: SendError(SyncerdBridgeEvent { event:... panick thereafter too.

Farcaster Node's compiled from https://github.com/Lederstrumpf/farcaster-node/commits/cli-readd-public-offers at 4ef05bdd3930f2d8626c9cbae67986a96435ff37, i.e. effectively main at fc42224f7c2067127bdc7209886270b092957fc6 wrt. this issue.