Jormungandr: Invalid block should not unwrap on the chain task and panic

[hodlonaut]

Running latest git master code as of 23 October.

Network of ~10-20 peers was producing new blocks at a rate 1 block every ~5-60 seconds.
I turned off automatic time synchronization in the settings of my Windows laptop while my leader-mode node was running, then adjusted my clock forward by 10 minutes and saved the changes.

Around the next time my leader node produced its next block, sounds like at least a couple of other nodes crashed - also the network seemed to go into the mode where only my node's leader event produced blocks were being propagated throughout... these two events resulted in the gap between next 5-6 blocks going from 5-60 seconds to 1-10 minutes.

Eventually I set my clock back to correct time and restarted my node. Eventually things went back to normal.

[papacarp]

My node was one of the crashed ones. Didn't realize this server didn't have backtrace on.

Oct 24 11:20:31.002 INFO leader event starting, date: 73.126, leader: 1, task: leadership
thread 'block0' panicked at 'called `Result::unwrap()` on an `Err` value: Error(Msg("cannot process leadership block"), State { next_error: Some(Error(CannotApplyBlock, State { next_error: Some(NonMonotonicDate { block_date: BlockDate { epoch: 73, slot_id: 126 }, chain_date: BlockDate { epoch: 73, slot_id: 173 } }), backtrace: InternalBacktrace { backtrace: None } })), backtrace: InternalBacktrace { backtrace: None } })', src/libcore/result.rs:1084:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
called `Result::unwrap()` on an `Err` value: Error(Msg("cannot process leadership block"), State { next_error: Some(Error(CannotApplyBlock, State { next_error: Some(NonMonotonicDate { block_date: BlockDate { epoch: 73, slot_id: 126 }, chain_date: BlockDate { epoch: 73, slot_id: 173 } }), backtrace: InternalBacktrace { backtrace: None } })), backtrace: InternalBacktrace { backtrace: None } })

[NicolasDP]

Thanks, the actual error is @papacarp 's reported error. i.e. it should handle this kind of situation without too much issues: rejecting blocks and creating appropriate one. This will come with 0.7

[dmitrystas]

0.7.0-rc7

Nov 09 10:50:35.643 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 70a5097fe89bc10624b1ed144efa1c86dfd987fba4b43c62, peer_addr: 82.209.54.76:3103, task: network
Nov 09 10:50:43.008 INFO leader event starting, date: 74.23, leader: 1, task: leadership
thread 'block0' panicked at 'called `Result::unwrap()` on an `Err` value: Error(Msg("cannot process leadership block"), State { next_error: Some(Error(CannotApplyBlock, State { next_error: Some(NonMonotonicDate { block_date: BlockDate { epoch: 74, slot_id: 23 }, chain_date: BlockDate { epoch: 74, slot_id: 135 } }), backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
   0: error_chain::backtrace::imp::InternalBacktrace::new
   1: error_chain::State::new
   2: jormungandr::blockchain::chain::Blockchain::apply_block
   3: <futures::future::map::Map<A,F> as futures::future::Future>::poll
   4: futures::task_impl::Spawn<T>::poll_future_notify
   5: jormungandr::blockchain::process::run_handle_input
   6: <futures::future::map_err::MapErr<A,F> as futures::future::Future>::poll
   7: futures::task_impl::std::set
   8: tokio_threadpool::worker::Worker::run_task
   9: tokio_threadpool::worker::Worker::run
  10: std::thread::local::LocalKey<T>::with
  11: tokio::runtime::threadpool::builder::Builder::build::{{closure}}
  12: std::sys_common::backtrace::__rust_begin_short_backtrace
  13: core::ops::function::FnOnce::call_once{{vtable.shim}}
  14: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922
  15: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922
      std::sys_common::thread::start_thread
             at src/libstd/sys_common/thread.rs:13
      std::sys::unix::thread::Thread::new::thread_start
             at src/libstd/sys/unix/thread.rs:79
  16: start_thread
  17: clone
) } })), backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
   0: error_chain::backtrace::imp::InternalBacktrace::new
   1: error_chain::State::new
   2: jormungandr::blockchain::chain::Blockchain::apply_block
   3: <futures::future::map::Map<A,F> as futures::future::Future>::poll
   4: futures::task_impl::Spawn<T>::poll_future_notify
   5: jormungandr::blockchain::process::run_handle_input
   6: <futures::future::map_err::MapErr<A,F> as futures::future::Future>::poll
   7: futures::task_impl::std::set
   8: tokio_threadpool::worker::Worker::run_task
   9: tokio_threadpool::worker::Worker::run
  10: std::thread::local::LocalKey<T>::with
  11: tokio::runtime::threadpool::builder::Builder::build::{{closure}}
  12: std::sys_common::backtrace::__rust_begin_short_backtrace
  13: core::ops::function::FnOnce::call_once{{vtable.shim}}
  14: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922
  15: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922
      std::sys_common::thread::start_thread
             at src/libstd/sys_common/thread.rs:13
      std::sys::unix::thread::Thread::new::thread_start
             at src/libstd/sys/unix/thread.rs:79
  16: start_thread
  17: clone
) } })', src/libcore/result.rs:1165:5
stack backtrace:
   0:     0x5570a4d13d0c - backtrace::backtrace::libunwind::trace::hda41dbcdfba36aa0
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/libunwind.rs:88
   1:     0x5570a4d13d0c - backtrace::backtrace::trace_unsynchronized::h1a8d6e1f8cb3f5d4
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/mod.rs:66
   2:     0x5570a4d13d0c - std::sys_common::backtrace::_print_fmt::h610c4127487e10da
                               at src/libstd/sys_common/backtrace.rs:76
   3:     0x5570a4d13d0c - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h0722dc552e01bd1d
                               at src/libstd/sys_common/backtrace.rs:60
   4:     0x5570a470d6bc - core::fmt::write::h01edf6dd68a42c9c
                               at src/libcore/fmt/mod.rs:1030
   5:     0x5570a4d13526 - std::io::Write::write_fmt::hf15985f193f03c04
                               at src/libstd/io/mod.rs:1412
   6:     0x5570a4d131a0 - std::sys_common::backtrace::_print::hd8d5d08a1795e743
                               at src/libstd/sys_common/backtrace.rs:64
   7:     0x5570a4d131a0 - std::sys_common::backtrace::print::hf89a79e3921a2366
                               at src/libstd/sys_common/backtrace.rs:49
   8:     0x5570a4d131a0 - std::panicking::default_hook::{{closure}}::h3a8f42beb3bb8ae3
                               at src/libstd/panicking.rs:196
   9:     0x5570a4d128ef - std::panicking::default_hook::h8f803b0bc31a5c37
                               at src/libstd/panicking.rs:210
  10:     0x5570a4d128ef - std::panicking::rust_panic_with_hook::h825f041245da8739
                               at src/libstd/panicking.rs:473
  11:     0x5570a4d1241f - std::panicking::continue_panic_fmt::hbe0378e33481e81b
                               at src/libstd/panicking.rs:380
  12:     0x5570a4d20ec6 - rust_begin_unwind
                               at src/libstd/panicking.rs:307
  13:     0x5570a4707939 - core::panicking::panic_fmt::h527855ce0bc891f6
                               at src/libcore/panicking.rs:85
  14:     0x5570a470dd26 - core::result::unwrap_failed::ha8b77e6004f0ba38
                               at src/libcore/result.rs:1165
  15:     0x5570a4882e67 - jormungandr::blockchain::process::run_handle_input::ha49dbbedcaa49336
  16:     0x5570a4804525 - <futures::future::map_err::MapErr<A,F> as futures::future::Future>::poll::h39a25f5b79bd4b76
  17:     0x5570a4d66000 - futures::task_impl::std::set::h85cd6d577f63ac1a
  18:     0x5570a4d61dfc - tokio_threadpool::worker::Worker::run_task::h63ebf3f2b2c9c06d
  19:     0x5570a4d60080 - tokio_threadpool::worker::Worker::run::hf4c7ef5a6eee7453
  20:     0x5570a4d44560 - std::thread::local::LocalKey<T>::with::h5d2e8df7c537e6f0
  21:     0x5570a4d45abc - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h89ce5b4bd9e42aaa
  22:     0x5570a4d5e29b - std::sys_common::backtrace::__rust_begin_short_backtrace::he976dcc67a40945d
  23:     0x5570a4d5f7b8 - core::ops::function::FnOnce::call_once{{vtable.shim}}::he2d293759f141fc7
  24:     0x5570a4d207bf - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h483711add4ba2330
                               at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922
  25:     0x5570a4d21f6c - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h7605b45eb29ed0be
                               at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922
  26:     0x5570a4d21f6c - std::sys_common::thread::start_thread::h557b0c2dc4449562
                               at src/libstd/sys_common/thread.rs:13
  27:     0x5570a4d21f6c - std::sys::unix::thread::Thread::new::thread_start::h7c2a7f9b68fe4bba
                               at src/libstd/sys/unix/thread.rs:79
  28:     0x7fdfd7129fa3 - start_thread
  29:     0x7fdfd70404cf - clone
  30:                0x0 - <unknown>
thread 'leadership0' panicked at 'Expect the event to not close', src/libcore/option.rs:1190:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
Expect the event to not close