Electrs: Electrs core dump at Result::unwrap()

[reynico]

Hi,
I'm getting random core-dumps on Electrs twice a month or so, running Electrs 0.7.0 on Ubuntu 18.04.3 LTS / Kernel 4.15.0-1045-aws.

Nov 08 14:43:57 ip-10-2-1-96 electrs[6726]: thread 'peer' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', src/libcore
Nov 08 14:43:57 ip-10-2-1-96 electrs[6726]: note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
Nov 08 14:43:58 ip-10-2-1-96 electrs[6726]: thread 'rpc' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', src/libcore/
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: 2019-11-08T14:44:09.354+00:00 - DEBUG - downloading new block headers (602876 already indexed) from 0000000000000000000bdb1f1b42be689f6a89cd0259832b6966d74a186895e7
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: 2019-11-08T14:44:09.354+00:00 - TRACE - downloaded 1 block headers
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: 2019-11-08T14:44:09.354+00:00 - INFO - best=0000000000000000000bdb1f1b42be689f6a89cd0259832b6966d74a186895e7 height=602876 @ 2019-11-08T14:43:56Z (1 left to index)
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', src/libcore
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: 2019-11-08T14:44:09.354+00:00 - TRACE - stop accepting new RPCs
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Any', src/libcore/result.rs:999:5
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: stack backtrace:
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    0:     0x564728a5c3b8 - backtrace::backtrace::libunwind::trace::hfe5db90796807973
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.29/src/backtrace/libunwind.rs:88
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    1:     0x564728a5c3b8 - backtrace::backtrace::trace_unsynchronized::h34b865a835594335
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.29/src/backtrace/mod.rs:66
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    2:     0x564728a5c3b8 - std::sys_common::backtrace::_print::h527254ae44989167
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libstd/sys_common/backtrace.rs:47
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    3:     0x564728a5c3b8 - std::sys_common::backtrace::print::he85dd5ddddf46503
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libstd/sys_common/backtrace.rs:36
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    4:     0x564728a5c3b8 - std::panicking::default_hook::{{closure}}::h847a2eb38b396f14
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libstd/panicking.rs:200
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    5:     0x564728a5bb18 - std::panicking::default_hook::h2ca0f9a30a0e206b
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libstd/panicking.rs:214
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    6:     0x564728a5bb18 - std::panicking::rust_panic_with_hook::hffcefc09751839d1
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libstd/panicking.rs:477
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    7:     0x564728a5b63f - std::panicking::continue_panic_fmt::hc0f142c930c846fc
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libstd/panicking.rs:384
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    8:     0x564728a6b896 - rust_begin_unwind
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libstd/panicking.rs:311
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:    9:     0x564728a7601c - core::panicking::panic_fmt::h2daf88b2616ca2b2
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:                                at src/libcore/panicking.rs:85
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   10:     0x56472884ff96 - core::result::unwrap_failed::h6a9955e775722e2b
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   11:     0x56472883fe7e - core::ptr::real_drop_in_place::hefdd44e51cd88396
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   12:     0x5647288475b6 - electrs::main::hb2f25b763ffd72dc
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   13:     0x564728a8ada3 - std::rt::lang_start::{{closure}}::hccc837831f582d19
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   14:     0x564728847c2e - main
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   15:     0x7fb10474cb97 - __libc_start_main
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   16:     0x56472883e42a - _start
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]:   17:                0x0 - <unknown>
Nov 08 14:44:09 ip-10-2-1-96 electrs[6726]: thread panicked while panicking. aborting.
Nov 08 14:44:09 ip-10-2-1-96 systemd[1]: electrum.service: Main process exited, code=dumped, status=4/ILL
Nov 08 14:44:09 ip-10-2-1-96 systemd[1]: electrum.service: Failed with result 'core-dump'.

Is there anything I can do for this?

[romanz]

Thanks for reporting this issue!
Could you please check if this panic is reproduced on latest electrs version (currently 0.8.0)?

[reynico]

Hi Roman,
We're still getting random crashes on Electrs 0.8.0. Noticed that’s running out of descriptors now:

thread 'acceptor' panicked at 'accept failed: Os { code: 24, kind: Other, message: "Too many open files" }'

And we also got a partial crash where RPC threads crashed but not the entire Electrs process (so our Systemd unit didn’t handle it) and Electrs stopped accepting new RPC calls

• We run a monitoring process that hits the RPC endpoint every second
• rustc 1.39.0 (4560ea788 2019-11-04)
• Ubuntu 18.04 LTS / kernel 4.15.0-1052-aws
• Ram usage grows every second

Here's the last stacktrace we got

Nov 12 03:36:38 ip-10-2-1-246 electrs[4103]: 2019-11-12T03:36:38.115+00:00 - DEBUG - [10.2.1.73:24928] shutting down connection
Nov 12 03:36:38 ip-10-2-1-246 electrs[4103]: 2019-11-12T03:36:38.115+00:00 - INFO - [10.2.1.73:24928] disconnected peer
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: 2019-11-12T03:36:39.015+00:00 - INFO - [10.2.1.73:8425] connected peer
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: thread 'peer' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', src/libcore/result.rs:1165:5
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: stack backtrace:
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    0: backtrace::backtrace::libunwind::trace
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/libunwind.rs:88
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    1: backtrace::backtrace::trace_unsynchronized
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/mod.rs:66
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    2: std::sys_common::backtrace::_print_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:76
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:60
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    4: core::fmt::write
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/fmt/mod.rs:1030
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    5: std::io::Write::write_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/io/mod.rs:1412
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    6: std::sys_common::backtrace::_print
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:64
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    7: std::sys_common::backtrace::print
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:49
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    8: std::panicking::default_hook::{{closure}}
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:196
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    9: std::panicking::default_hook
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:210
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   10: std::panicking::rust_panic_with_hook
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:473
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   11: std::panicking::continue_panic_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:380
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   12: rust_begin_unwind
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:307
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   13: core::panicking::panic_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/panicking.rs:85
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   14: core::result::unwrap_failed
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/result.rs:1165
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: thread 'rpc' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 11, kind: WouldBlock, message: "Resource temporarily unavailable" }', src/libcore/result.rs:1165:5
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: stack backtrace:
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    0: backtrace::backtrace::libunwind::trace
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/libunwind.rs:88
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    1: backtrace::backtrace::trace_unsynchronized
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/mod.rs:66
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    2: std::sys_common::backtrace::_print_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:76
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:60
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    4: core::fmt::write
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/fmt/mod.rs:1030
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    5: std::io::Write::write_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/io/mod.rs:1412
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    6: std::sys_common::backtrace::_print
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:64
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    7: std::sys_common::backtrace::print
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:49
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    8: std::panicking::default_hook::{{closure}}
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:196
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    9: std::panicking::default_hook
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:210
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   10: std::panicking::rust_panic_with_hook
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:473
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   11: std::panicking::continue_panic_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:380
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   12: rust_begin_unwind
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:307
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   13: core::panicking::panic_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/panicking.rs:85
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   14: core::result::unwrap_failed
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/result.rs:1165
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: thread 'acceptor' panicked at 'send failed: "SendError(..)"', src/libcore/result.rs:1165:5
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: stack backtrace:
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    0: backtrace::backtrace::libunwind::trace
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/libunwind.rs:88
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    1: backtrace::backtrace::trace_unsynchronized
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/mod.rs:66
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    2: std::sys_common::backtrace::_print_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:76
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:60
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    4: core::fmt::write
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/fmt/mod.rs:1030
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    5: std::io::Write::write_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/io/mod.rs:1412
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    6: std::sys_common::backtrace::_print
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:64
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    7: std::sys_common::backtrace::print
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/sys_common/backtrace.rs:49
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    8: std::panicking::default_hook::{{closure}}
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:196
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:    9: std::panicking::default_hook
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:210
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   10: std::panicking::rust_panic_with_hook
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:473
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   11: std::panicking::continue_panic_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:380
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   12: rust_begin_unwind
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libstd/panicking.rs:307
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   13: core::panicking::panic_fmt
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/panicking.rs:85
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   14: core::result::unwrap_failed
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:              at src/libcore/result.rs:1165
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]:   15: electrs::rpc::RPC::start_acceptor::{{closure}}
Nov 12 03:36:39 ip-10-2-1-246 electrs[4103]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Nov 12 03:37:05 ip-10-2-1-246 electrs[4103]: 2019-11-12T03:37:05.359+00:00 - DEBUG - downloading new block headers (603391 already indexed) from 0000000000000000000b5a7f01dfe83d53e870983e7a8e29e92f3b7a17efd441
Nov 12 03:37:05 ip-10-2-1-246 electrs[4103]: 2019-11-12T03:37:05.359+00:00 - TRACE - downloaded 1 block headers
Nov 12 03:37:05 ip-10-2-1-246 electrs[4103]: 2019-11-12T03:37:05.359+00:00 - INFO - best=0000000000000000000b5a7f01dfe83d53e870983e7a8e29e92f3b7a17efd441 height=603391 @ 2019-11-12T03:36:46Z (1 left to index)

[Kixunil]

Should this issue be closed thanks to #195?

[reynico]

Yes, thank you.

[shyrwall]

Hi

Sorry for reopening but I'm getting this error on the Blockstream fork (rpc code is same). Just asking here before opening an issue there since i found this issue reported here.

I saw the commit mentioned here was reverted in https://github.com/romanz/electrs/commit/a3bfdda32a1c8cab248d3525786a433d1e415d1e#diff-8776af0b15949a59471d9d5910b92db7

Just want to ask so it wasn't reverted by accident :D

[Kixunil]

rpc code is same

No, it's not

Compare e.g. this electrs blockstream

TBH it kinda sucks when people open issues at different repositories. I've seen it happen in electrs several times already. I'd still like to see good cooperation between the two impls, but this seems like overstepping boundaries to me. Don't get me wrong, I like to help people using electrs, it's just that doing the work twice because they didn't merge bugfixes seems wasteful. How do you see it @romanz?

[shyrwall]

rpc code is same

No, it's not

Compare e.g. this electrs blockstream

TBH it kinda sucks when people open issues at different repositories. I've seen it happen in electrs several times already. I'd still like to see good cooperation between the two impls, but this seems like overstepping boundaries to me. Don't get me wrong, I like to help people using electrs, it's just that doing the work twice because they didn't merge bugfixes seems wasteful. How do you see it @romanz?

Well I agree. I wouldnt open a new issue. I commented on an existed one with the same problem as im facing. Just asked since to me the code in question looked similar in both repos and I hope you can understand that i'd rather ask here then taking days syncing a node against this repo to see if the problem exists here also.

Also issues are disabled on blockstream/electrs.

[Kixunil]

Also issues are disabled on blockstream/electrs.

Ah, true, because it's a fork! That explains a lot. I'd love to see some progress towards merging relevant parts and detaching differences into separate repos or something.

[romanz]

I'd love to see some progress towards merging relevant parts and detaching differences into separate repos or something.

Me too... unfortunately, I don't have enough time to make it happen :(

[Kixunil]

I may be able to look at it in a few weeks, will open a separate issue then.