Jormungandr: thread 'network1' panicked at 'called `Result::unwrap()` on Shutdown

[hemants1]

Describe the bug
A clear and concise description of what the bug is.

Mandatory Information

1. jcli --full-version output;

jcli 0.8.5 (HEAD-3db0680, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

1. jormungandr --full-version output;

jormungandr 0.8.5 (HEAD-3db0680, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

To Reproduce
Steps to reproduce the behavior:

1. Start node as leader:

jormungandr --config node-config.N.yaml --genesis-block-hash 8e4d2a343f3dcf9330ad9035b3e8d168e6728904262f2c434a4f8f934ec7b676 --secret node_secret.yaml

Expected behavior

Expected to have a stable running node..! But node crashed because of panic.

Additional context
Dec 25 07:10:02.263 ERRO failed to enqueue request for processing, reason: send failed because receiver is gone, request: PushHeaders, sub_task: server, task: network
thread 'network1' panicked at 'called Result::unwrap() on an Err value: SpawnError { is_shutdown: true }', src/libcore/result.rs:1165:5
stack backtrace:
0: backtrace::backtrace::libunwind::trace
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
1: backtrace::backtrace::trace_unsynchronized
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
2: std::sys_common::backtrace::_print_fmt
at src/libstd/sys_common/backtrace.rs:77
3: ::fmt
at src/libstd/sys_common/backtrace.rs:61
4: core::fmt::write
at src/libcore/fmt/mod.rs:1028
5: std::io::Write::write_fmt
at src/libstd/io/mod.rs:1412
6: std::sys_common::backtrace::_print
at src/libstd/sys_common/backtrace.rs:65
7: std::sys_common::backtrace::print
at src/libstd/sys_common/backtrace.rs:50
8: std::panicking::default_hook::{{closure}}
at src/libstd/panicking.rs:188
9: std::panicking::default_hook
at src/libstd/panicking.rs:205
10: std::panicking::rust_panic_with_hook
at src/libstd/panicking.rs:464
11: std::panicking::continue_panic_fmt
at src/libstd/panicking.rs:373
12: rust_begin_unwind
at src/libstd/panicking.rs:302
13: core::panicking::panic_fmt
at src/libcore/panicking.rs:139
14: core::result::unwrap_failed
at src/libcore/result.rs:1165
15: as futures::future::Future>::poll
16: as futures::future::Future>::poll
17: futures::task_impl::std::set
18: tokio_threadpool::worker::Worker::run_task
19: tokio_threadpool::worker::Worker::run
20: tokio_reactor::with_default
21: tokio::runtime::threadpool::builder::Builder::build::{{closure}}
note: Some details are omitted, run with RUST_BACKTRACE=full for a verbose backtrace.
Dec 25 07:10:04.153 CRIT Task panicked, task: network

[eugene-babichenko]

Can you provide logs before this error occurred? There could have been other errors that actually caused send failed because receiver is gone.

[hemants1]

Pls find attached complete log. Log level was set to WARN.

node.zip

[hemants1]

There are many panic critical showed recently. 8.5 looks to be unstable. Attaching logs with RUST_BACKTRACE=full

node.zip

[Linicks]

I happened to notice this issue in my logs as well, with the exception that it was a different network # . I have the same versions of JCLI and Jormungandr mentioned above. Here is the log entry that I caught:
`` Dec 30 22:32:11.763 INFO connecting to peer, node_id: b1b788149b51b804f5c0fa30fca8084597d8f0298430dd2d, peer_addr: 72.217.38.176:3100, task: network thread 'network2' panicked at 'calledResult::unwrap()on anErr` value: SpawnError { is_shutdown: true }', src/libcore/result.rs:1165:5

[Linicks]

Ok, It just happened again. Interestingly, this node had been stable for quite some time and has suddenly started acting up.

`` Dec 30 22:55:46.251 INFO connecting to peer, node_id: b19a13499ef3176c16dc3f3abb5b0ac956382592563171b2, peer_addr: 173.249.37.161:3100, task: network Dec 30 22:55:46.416 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: b19a13499ef3176c16dc3f3abb5b0ac956382592563171b2, peer_addr: 173.249.37.161:3100, task: network Dec 30 22:55:46.554 INFO peer node ID differs from the expected 488e59de45ab10ad88f7ec8c4280344db4b96301b7598097, node_id: b816ab0dd45ac607659e286c2255e36cb5b74090e4685da1, peer_addr: 3.133.59.147:9000, task: network Dec 30 22:55:47.078 INFO disconnecting client, node_id: c14285292f5ff74536f496edc8adfbda854fca887ef9e900, peer_addr: 24.37.174.13:3826, task: network Dec 30 22:55:47.108 INFO connecting to peer, node_id: bd74c22df99805fe2e64a9ed90906349b6c4a77b991e7abb, peer_addr: 78.47.31.87:3000, task: network Dec 30 22:55:47.157 INFO service finished successfully, task: rest Dec 30 22:55:47.158 INFO Shutting down node Dec 30 22:55:47.266 INFO connecting to peer, node_id: bf3168a3dad9907eaff64820f0b9c30835695399889c77f5, peer_addr: 116.233.80.165:3200, task: network Dec 30 22:55:47.429 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: bf3168a3dad9907eaff64820f0b9c30835695399889c77f5, peer_addr: 116.233.80.165:3200, task: network Dec 30 22:55:47.475 INFO connecting to peer, node_id: 18f5b29b7c95364fdcf3a7a395df86ea7ac7b732da1394aa, peer_addr: 46.36.37.117:3000, task: network Dec 30 22:55:47.513 INFO disconnecting client, node_id: 222200000000000000000000000000000000000000002222, peer_addr: 82.217.191.196:3011, task: network Dec 30 22:55:49.083 INFO disconnecting client, node_id: 1881de7f7a2bc316132bd8ce02a71466aab4d47e797f0f1d, peer_addr: 52.208.100.78:3000, task: network Dec 30 22:55:49.129 INFO connecting to peer, node_id: 36341d37a12574f42ddd0f3c1f632ebdbeec2ec82190aeb5, peer_addr: 91.167.243.137:3000, task: network Dec 30 22:55:49.356 INFO connecting to peer, node_id: c1a89738d68fa4ef554da4cbcb8a5ee91231af050c73c49a, peer_addr: 3.133.7.237:9000, task: network thread 'network2' panicked at 'calledResult::unwrap()on anErrvalue: SpawnError { is_shutdown: true }', src/libcore/result.rs:1165:5 note: run withRUST_BACKTRACE=1` environment variable to display a backtrace.
Dec 30 22:55:49.402 CRIT Task panicked, task: network

[bobdobs]

I got the same error. My Jormungandr has been running pretty smooth on ITN lately. It ran for 2x4 days before requiring a restart! I then switched to the latest trusted peers that were announced in Telegram (they are not in the official config yet AFAIK). Apart from the trusted peers I have not changed anything in my setup, and the error is most likely unrelated.

Stack trace:

jormungandr 0.8.5
thread 'network1' panicked at 'called `Result::unwrap()` on an `Err` value: SpawnError { is_shutdown: true }', src/libcore/result.rs:1165:5
stack backtrace:
   0:     0x560e7b27712c - backtrace::backtrace::libunwind::trace::h65597d255cb1398b
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
   1:     0x560e7b27712c - backtrace::backtrace::trace_unsynchronized::hd4f479d7150ec4a0
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
   2:     0x560e7b27712c - std::sys_common::backtrace::_print_fmt::h015072984a2b172c
                               at src/libstd/sys_common/backtrace.rs:77
   3:     0x560e7b27712c - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h6df05d3335f32194
                               at src/libstd/sys_common/backtrace.rs:61
   4:     0x560e7abf525c - core::fmt::write::h1f444f4312eb6c27
                               at src/libcore/fmt/mod.rs:1028
   5:     0x560e7b2769b6 - std::io::Write::write_fmt::h8d147888220078ef
                               at src/libstd/io/mod.rs:1412
   6:     0x560e7b27662e - std::sys_common::backtrace::_print::h8a6df0fa81d6af62
                               at src/libstd/sys_common/backtrace.rs:65
   7:     0x560e7b27662e - std::sys_common::backtrace::print::h6f05b4733407e509
                               at src/libstd/sys_common/backtrace.rs:50
   8:     0x560e7b27662e - std::panicking::default_hook::{{closure}}::h0d0a23bd02315dd8
                               at src/libstd/panicking.rs:188
   9:     0x560e7b275dd3 - std::panicking::default_hook::h8d15a9aecb4efac6
                               at src/libstd/panicking.rs:205
  10:     0x560e7b275dd3 - std::panicking::rust_panic_with_hook::hbe174577402a475d
                               at src/libstd/panicking.rs:464
  11:     0x560e7b27594e - std::panicking::continue_panic_fmt::h4d855dad868accf3
                               at src/libstd/panicking.rs:373
  12:     0x560e7b284da6 - rust_begin_unwind
                               at src/libstd/panicking.rs:302
  13:     0x560e7abef53d - core::panicking::panic_fmt::hdeb7979ab6591473
                               at src/libcore/panicking.rs:139
  14:     0x560e7abf58d6 - core::result::unwrap_failed::h054dd680e6fcd38b
                               at src/libcore/result.rs:1165
  15:     0x560e7b15efed - <futures::future::join::Join3<A,B,C> as futures::future::Future>::poll::h5cd85c2adfaecbe7
  16:     0x560e7ad02bdf - <futures::future::then::Then<A,B,F> as futures::future::Future>::poll::h35193bd86ef65137
  17:     0x560e7b2c9360 - futures::task_impl::std::set::h3219199b205065b2
  18:     0x560e7b2c55d2 - tokio_threadpool::worker::Worker::run_task::h0cc32dbb6e87704c
  19:     0x560e7b2c3840 - tokio_threadpool::worker::Worker::run::h4e299990638426d6
  20:     0x560e7b2a72cc - tokio_reactor::with_default::h28f5cad7bf275e58
  21:     0x560e7b2a9105 - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h69048e1306e1a393
  22:     0x560e7b2c1a5b - std::sys_common::backtrace::__rust_begin_short_backtrace::h4b760d2a71152644
  23:     0x560e7b2c2658 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h63d23a27bb1aa29b
  24:     0x560e7b28407f - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h3534c64212330b0c
                               at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
  25:     0x560e7b285f6c - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h338c10574a337ece
                               at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
  26:     0x560e7b285f6c - std::sys_common::thread::start_thread::h761ac6d57710d65d
                               at src/libstd/sys_common/thread.rs:13
  27:     0x560e7b285f6c - std::sys::unix::thread::Thread::new::thread_start::h61c012ef60f933c0
                               at src/libstd/sys/unix/thread.rs:79
  28:     0x7f0865b986ba - start_thread
  29:     0x7f08656b641d - clone
  30:                0x0 - <unknown>

Logs attached (log level is actually warn even though the filename indicates info):
logs_info_level.zip

[CodeSandwich]

These panics are caused by another panic, described in https://github.com/input-output-hk/jormungandr/issues/1422, point 3. It shows up dozens of times in logs before the final one. When the root cause is fixed, this issue should disappear.

[rinor]

@hemants1 the panic related to 'internal error: entered unreachable code', jormungandr/src/blockchain/storage.rs should be now fixed in master since https://github.com/input-output-hk/jormungandr/pull/1441 was merged. If feasible please update and check if issue still present.

[stanfieldr]

I'm running on the latest commit hash of master, same error.
jormungandr 0.8.5 (master-35a60a3c, release, linux [x86_64]) - [rustc 1.39.0 (4560ea788 2019-11-04)]
[stderr.txt](https://github.com/input-output-hk/jormungandr/files/4032186/stderr.txt)
stdout.txt

[jalora8]

Yup I'm also having the same problem.

jormungandr --full-version
jormungandr 0.8.5 (HEAD-35a60a3c, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

thread 'network0' panicked at 'calledResult::unwrap()on anErrvalue: SpawnError { is_shutdown: true }', src/libcore/result.rs:1165:5 Jan 07 23:51:04.039 CRIT Task panicked, task: network

[NicolasDP]

That there is a panic at shutdown time is not necessarily a problem. I will make the issue as low for now and won't close it as it would be better to have the node do a nice and clean shutdown.

[khkwon01]

Currently, we used to version 0.8.6 but the error happened repeatedly.

The error like to the below

thread 'tokio-runtime-worker-1' panicked at 'called Result::unwrap() on an Err value: SpawnError { is_shutdown: true }', src/libcore/result.rs:1165:5

[ssainball]

The systems we run are experiencing the same error.

$ RUST_BACKTRACE=full /root/jormungandr --genesis-block-hash $(cat /root/genesis-hash.txt) --config /root/node- config.yaml --secret /root/node-secret.yaml
thread 'tokio-runtime-worker-1' panicked at 'called Result::unwrap() on an Err value: SpawnError { is_shutdown: true }', src/libcore/result.rs:1165:5
stack backtrace:
0: 0x562ebecddbcc - backtrace::backtrace::libunwind::trace::h65597d255cb1398b
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
1: 0x562ebecddbcc - backtrace::backtrace::trace_unsynchronized::hd4f479d7150ec4a0
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
2: 0x562ebecddbcc - std::sys_common::backtrace::_print_fmt::h015072984a2b172c
at src/libstd/sys_common/backtrace.rs:77
3: 0x562ebecddbcc - ::fmt::h6df05d3335f32194
at src/libstd/sys_common/backtrace.rs:61
4: 0x562ebe669b3c - core::fmt::write::h1f444f4312eb6c27
at src/libcore/fmt/mod.rs:1028
5: 0x562ebecdd436 - std::io::Write::write_fmt::h8d147888220078ef
at src/libstd/io/mod.rs:1412
6: 0x562ebecdd0ae - std::sys_common::backtrace::_print::h8a6df0fa81d6af62
at src/libstd/sys_common/backtrace.rs:65
7: 0x562ebecdd0ae - std::sys_common::backtrace::print::h6f05b4733407e509
at src/libstd/sys_common/backtrace.rs:50
8: 0x562ebecdd0ae - std::panicking::default_hook::{{closure}}::h0d0a23bd02315dd8
at src/libstd/panicking.rs:188
9: 0x562ebecdc853 - std::panicking::default_hook::h8d15a9aecb4efac6
at src/libstd/panicking.rs:205
10: 0x562ebecdc853 - std::panicking::rust_panic_with_hook::hbe174577402a475d
at src/libstd/panicking.rs:464
11: 0x562ebecdc3ce - std::panicking::continue_panic_fmt::h4d855dad868accf3
at src/libstd/panicking.rs:373
12: 0x562ebeceb806 - rust_begin_unwind
at src/libstd/panicking.rs:302
13: 0x562ebe663e1d - core::panicking::panic_fmt::hdeb7979ab6591473
at src/libcore/panicking.rs:139
14: 0x562ebe66a1b6 - core::result::unwrap_failed::h054dd680e6fcd38b
at src/libcore/result.rs:1165
15: 0x562ebebc27c5 - as futures::future::Future>::poll::h6278d9801d3b1928
16: 0x562ebe7772af - as futures::future::Future>::poll::hfd0967b84d01bf48
17: 0x562ebed2f2ae - futures::task_impl::std::set::h3219199b205065b2
18: 0x562ebed2b492 - tokio_threadpool::worker::Worker::run_task::h0cc32dbb6e87704c
19: 0x562ebed2a966 - tokio_threadpool::worker::Worker::run::h4e299990638426d6
20: 0x562ebed0c16c - tokio_reactor::with_default::hb6d4413126074571
21: 0x562ebed0df35 - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h666c3911afe216eb
22: 0x562ebed2633b - std::sys_common::backtrace::__rust_begin_short_backtrace::h4b760d2a71152644
23: 0x562ebed26f38 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h63d23a27bb1aa29b
24: 0x562ebeceaadf - as core::ops::function::FnOnce>::call_once::h3534c64212330b0c
at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
25: 0x562ebecec9ac - as core::ops::function::FnOnce>::call_once::h338c10574a337ece
at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
26: 0x562ebecec9ac - std::sys_common::thread::start_thread::h761ac6d57710d65d
at src/libstd/sys_common/thread.rs:13
27: 0x562ebecec9ac - std::sys::unix::thread::Thread::new::thread_start::h61c012ef60f933c0
at src/libstd/sys/unix/thread.rs:79
28: 0x7faf8a5b96db - start_thread
29: 0x7faf8a0ca88f - __clone
30: 0x0 -
root@k03:~#