I've seen this happen a couple of times now and finally was able to grab the console output. I'm not sure why this happens, but basically electrs will continue to run and sync with the chain, but it stops listening on its rpc port entirely.
INFO - [127.0.0.1:55350] connected peer
TRACE - RPC Request("{\"jsonrpc\":\"2.0\",\"method\":\"server.version\",\"params\"
:[\"btc-rpc-explorer-v1.1\",\"1.2\"],\"id\":1563}\n")
TRACE - RPC PeriodicUpdate
TRACE - RPC Request("{\"jsonrpc\":\"2.0\",\"method\":\"server.ping\",\"params\":[]
,\"id\":1564}\n")
ERROR - [127.0.0.1:55350] connection handling failed: Error: unknown method server
.ping []
DEBUG - [127.0.0.1:55350] shutting down connection
INFO - [127.0.0.1:55350] disconnected peer
INFO - [127.0.0.1:55352] connected peer
thread 'peer' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code:
11, kind: WouldBlock, message: "Resource temporarily unavailable" }', libcore/result.rs:945:5
note: Run with `RUST_BACKTRACE=1` for a backtrace.
thread 'rpc' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', libcore/result.rs:945:5
thread 'acceptor' panicked at 'send failed: "SendError(..)"', libcore/result.rs:945:5
This might be fixed with server.ping being implemented, but I thought I'd still share it in case ther's a subtle bug somewhere with how unknown methods are handled. I'll update if this issue goes away after updating to the latest from master.
sangaman
All 14 comments
It may be related to https://github.com/romanz/electrs/issues/80#issuecomment-438023839.
Could you try to reproduce this issue with RUST_BACKTRACE=full?
romanz
on 16 Nov 2018
Sure, before or after I update to the latest from master?
sangaman
on 16 Nov 2018
Probably before, since the fix should resolve the error (so the panic would probably disappear).
romanz
on 16 Nov 2018
馃憤 Attempting to reproduce now with RUST_BACKTRACE=full. It's been happening after some hours of repeated failed pings, so I'll keep an eye on it.
sangaman
on 16 Nov 2018
Actually pardon my ignorance, it seems it's not something I can pass in via command line. What exactly do I need to change for trace logging?
sangaman
on 16 Nov 2018
No problem :)
You can run the following command export RUST_BACKTRACE=full on the same Bash shell where you run cargo run the Electrum server.
romanz
on 16 Nov 2018
Reproduced and got the trace output:
INFO - [127.0.0.1:43032] connected peer
thread 'peer' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code:
11, kind: WouldBlock, message: "Resource temporarily unavailable" }', libcore/res
ult.rs:945:5
stack backtrace:
0: 0x8d07a7 -
1: 0x8c2f57 -
2: 0x8c0de7 -
3: 0x8c0a7f -
4: 0x8c14d3 -
5: 0x8c10d3 -
6: 0x8c0fbb -
7: 0x90dcaf -
8: 0x5a2e1f - ,
9: 0x5d9efb -
10: 0x57a967 -
11: 0x5bb99b -
12: 0x5dfef7 -
13: 0x8d83cb -
14: 0x5e5ca7 - EC2EPKcj
15: 0x8c1b4b -
thread 'rpc' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', libcore/result.rs:945:5
stack backtrace:
0: 0x8d07a7 -
1: 0x8c2f57 -
2: 0x8c0de7 -
3: 0x8c0a7f -
4: 0x8c14d3 -
5: 0x8c10d3 -
6: 0x8c0fbb -
7: 0x90dcaf -
8: 0x5a2e1f - ,
9: 0x5d99e3 -
10: 0x5bc4c3 -
11: 0x5dffcb -
12: 0x8d83cb -
13: 0x5e6913 - se_facetINSt7__cxx119money_getIwSt19istreambuf_iteratorIwSt11char_traitsIwEEEEERKT_RKSt6locale
14: 0x8c1b4b -
thread 'acceptor' panicked at 'send failed: "SendError(..)"', libcore/result.rs:945:5
stack backtrace:
0: 0x8d07a7 -
1: 0x8c2f57 -
2: 0x8c0de7 -
3: 0x8c0a7f -
4: 0x8c14d3 -
5: 0x8c10d3 -
6: 0x8c0fbb -
7: 0x90dcaf -
8: 0x5a21cb -
9: 0x5ccda7 - __cxx119money_getIwSt19istreambuf_iteratorIwSt11char_traitsIwEEEC2Ej
10: 0x5bc1ff - vsq3
11: 0x5e0053 -
12: 0x8d83cb -
13: 0x5e5af3 - ransformEPKwS3_
14: 0x8c1b4b -
Still not sure about the root cause for this problem... couldn't find an unwrap()/except() at electrs code that seems to cause this :(
Could you try to reproduce it in debug (i.e. when running electrs with cargo run without --release flag)?
Also, in case the issue is TCP connection being somehow opened in non-blocking mode - could you try to see if https://github.com/romanz/electrs/commit/04af2448aea267d4dee3da30ccba8cd1e035b479 (from nonblocking branch) helps with the panic?
/cc @devrandom (following #80)
romanz
on 17 Nov 2018
Here's the output without --release.
INFO - [127.0.0.1:46158] connected peer
TRACE - RPC Request("{\"jsonrpc\":\"2.0\",\"method\":\"server.version\",\"params\"
:[\"btc-rpc-explorer-v1.1\",\"1.2\"],\"id\":2121}\n")
TRACE - RPC PeriodicUpdate
TRACE - RPC PeriodicUpdate
TRACE - RPC Request("{\"jsonrpc\":\"2.0\",\"method\":\"server.ping\",\"params\":[]
,\"id\":2122}\n")
ERROR - [127.0.0.1:46158] connection handling failed: Error: unknown method server
.ping []
stack backtrace:
0: 0x6f4f07 - backtrace::backtrace::libunwind::trace::hb297fa2123bee7bb
at /home/bitcoin/.cargo/registry/src/github.com-1ecc6299db9ec823/b
acktrace-0.3.9/src/backtrace/libunwind.rs:53
- backtrace::backtrace::trace::h7a224549728584fd
at /home/bitcoin/.cargo/registry/src/github.com-1ecc6299db9ec823/b
acktrace-0.3.9/src/backtrace/mod.rs:42
1: 0x6f0fa3 - backtrace::capture::Backtrace::new_unresolved::h1acb4e14032c9a9
1
at /home/bitcoin/.cargo/registry/src/github.com-1ecc6299db9ec823/b
acktrace-0.3.9/src/capture.rs:88
2: 0x6f0333 - error_chain::backtrace::imp::InternalBacktrace::new::h73a88916a
09cdaf5
at /home/bitcoin/.cargo/registry/src/github.com-1ecc6299db9ec823/e
rror-chain-0.12.0/src/backtrace.rs:56
3: 0x6edbd7 - <error_chain::State as core::default::Default>::default::h3f7a3
b62a01e9e0b
at /home/bitcoin/.cargo/registry/src/github.com-1ecc6299db9ec823/e
rror-chain-0.12.0/src/lib.rs:666
4: 0x5b150f - electrs::errors::Error::from_kind::h6826048caf51852e
at /home/bitcoin/electrs/<impl_error_chain_processed macros>:53
5: 0x5b1757 - <electrs::errors::Error as core::convert::From<alloc::string::S
tring>>::from::hd6e772942cc6a313
at /home/bitcoin/electrs/<impl_error_chain_processed macros>:108
6: 0x5340fb - <T as core::convert::Into<U>>::into::h946db35210835f86
at /checkout/src/libcore/convert.rs:396
7: 0x5a9403 - electrs::rpc::Connection::handle_command::he6a4fba788ff90b0
at src/rpc.rs:303
8: 0x5ab95f - electrs::rpc::Connection::handle_replies::ha6fc1fe193dffbd7
at src/rpc.rs:382
9: 0x5acd3f - electrs::rpc::Connection::run::h57dd67794664d37b
at src/rpc.rs:430
10: 0x6b70af - electrs::rpc::RPC::start::{{closure}}::{{closure}}::h401c6c0d05
46bfd1
at src/rpc.rs:532
11: 0x63f0eb - std::sys_common::backtrace::__rust_begin_short_backtrace::h68a5
fb2df896ae59
at /checkout/src/libstd/sys_common/backtrace.rs:136
12: 0x4f88c3 - std::thread::Builder::spawn::{{closure}}::{{closure}}::hf396af0
d52fb20ec
at /checkout/src/libstd/thread/mod.rs:409
13: 0x5d53b7 - <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce
<()>>::call_once::hae6055cb72f484c1
at /checkout/src/libstd/panic.rs:313
14: 0x6b9c0b - std::panicking::try::do_call::h4acd4dde868267ad
at /checkout/src/libstd/panicking.rs:310
15: 0xf6557f - __rust_maybe_catch_panic
at libpanic_unwind/lib.rs:105
16: 0x6b95fb - std::panicking::try::h78b3e7a04ea0ff8f
at /checkout/src/libstd/panicking.rs:289
17: 0x5d54f7 - std::panic::catch_unwind::h4953fb6c5ed9088a
at /checkout/src/libstd/panic.rs:392
18: 0x4f84a3 - std::thread::Builder::spawn::{{closure}}::hf9c0637e0470b439
at /checkout/src/libstd/thread/mod.rs:408
19: 0x4f8f03 - <F as alloc::boxed::FnBox<A>>::call_box::h7cd67199f983cf45
at /checkout/src/liballoc/boxed.rs:642
20: 0xf4ecff - <alloc::boxed::Box<(dyn alloc::boxed::FnBox<A, Output=R> + 'a)> as core::ops::function::FnOnce<A>>::call_once::h7d2aab5a18d45822
at /checkout/src/liballoc/boxed.rs:652
- std::sys_common::thread::start_thread::hbe8dd03f6b1fa4a1
at libstd/sys_common/thread.rs:24
- std::sys::unix::thread::Thread::new::thread_start::h67f88174b80ff684
at libstd/sys/unix/thread.rs:90
DEBUG - [127.0.0.1:46158] shutting down connection
INFO - [127.0.0.1:46158] disconnected peer
INFO - [127.0.0.1:46186] connected peer
thread 'peer' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', libcore/result.rs:945:5
stack backtrace:
0: 0xf5d95b - <unknown>
1: 0xf5010b - <unknown>
2: 0xf4df9b - <unknown>
3: 0xf4dc33 - <unknown>
4: 0xf4e687 - <unknown>
5: 0xf4e287 - <unknown>
6: 0xf4e16f - <unknown>
7: 0xf9ae93 - <unknown>
8: 0x81da53 - <unknown>
9: 0x4c0433 - <unknown>
10: 0x64153b - <unknown>
11: 0x5acd27 - <unknown>
12: 0x6b70af - <unknown>
13: 0x63f0eb - <unknown>
14: 0x4f88c3 - <unknown>
15: 0x5d53b7 - <unknown>
16: 0x6b9c0b - <unknown>
17: 0xf6557f - <unknown>
18: 0x6b95fb - <unknown>
19: 0x5d54f7 - <unknown>
20: 0x4f84a3 - <unknown>
21: 0x4f8f03 - <unknown>
22: 0xf4ecff - <unknown>
thread 'rpc' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', libcore/result.rs:945:5
stack backtrace:
0: 0xf5d95b - <unknown>
1: 0xf5010b - <unknown>
2: 0xf4df9b - <unknown>
3: 0xf4dc33 - <unknown>
4: 0xf4e687 - <unknown>
5: 0xf4e287 - <unknown>
6: 0xf4e16f - <unknown>
7: 0xf9ae93 - <unknown>
8: 0xf27287 - <unknown>
9: 0xecf803 - <unknown>
10: 0x641cc7 - <unknown>
11: 0x6b7623 - <unknown>
12: 0x63ef87 - <unknown>
13: 0x4f875f - <unknown>
14: 0x5d5177 - <unknown>
15: 0x6b9f8f - <unknown>
16: 0xf6557f - <unknown>
17: 0x6b925f - <unknown>
18: 0x5d5643 - <unknown>
19: 0x4f6953 - <unknown>
20: 0x4f8fe3 - <unknown>
21: 0xf4ecff - <unknown>
thread 'acceptor' panicked at 'send failed: "SendError(..)"', libcore/result.rs:945:5
stack backtrace:
0: 0xf5d95b - <unknown>
1: 0xf5010b - <unknown>
2: 0xf4df9b - <unknown>
3: 0xf4dc33 - <unknown>
4: 0xf4e687 - <unknown>
5: 0xf4e287 - <unknown>
6: 0xf4e16f - <unknown>
7: 0xf9ae93 - <unknown>
8: 0x4d25db - <unknown>
9: 0x4bd22f - <unknown>
10: 0x6b6d53 - <unknown>
11: 0x63f193 - <unknown>
12: 0x4f8643 - <unknown>
13: 0x5d5337 - <unknown>
14: 0x6b9c7b - <unknown>
15: 0xf6557f - <unknown>
16: 0x6b9383 - <unknown>
17: 0x5d55b3 - <unknown>
18: 0x4f70ab - <unknown>
19: 0x4f8f6f - <unknown>
20: 0xf4ecff - <unknown>
Ah when I use the nonblocking branch, it has the commits that implement server.ping - so I might not get the error again (we'll see I guess). If you want I can always use an older version and cherry pick just the blocking fix.
sangaman
on 18 Nov 2018
Can you please describe what JSONRPC commands are sent to electrs, since I'd like to reproduce this error on my machine?
Please also let me know which OS, Rust version and electrs commit you are using.
romanz
on 18 Nov 2018
It's just server.ping and server.version - but what's probably more noteworthy is that the socket keeps getting destroyed each time server.ping would fail and then a new socket would be created. The calls were coming from btc-rpc-explorer.
I believe I was on c86245751 running Ubuntu 18.04 with rustc 1.29.1 (b801ae664 2018-09-20).
sangaman
on 18 Nov 2018
FYI, this issue seems to be gone using the nonblocking branch.
sangaman
on 20 Nov 2018
Closing (nonblocking branch is merged to master @ 4c5f7f8).
romanz
on 19 Jan 2019
Related issues
duckartes
路
3Comments
mkl-
路
5Comments
lukechilds
路
3Comments
HardCorePawn
路
3Comments
Overtorment
路
3Comments
Most helpful comment
FYI, this issue seems to be gone using the
nonblockingbranch.