Lighthouse: thread 'tokio-runtime-worker-11' panicked at 'supplied instant is later than self'

[q9f]

Description

Happy to report that latest master is broken :sob:

I can no longer run beacon nodes on Schlesi.

Version

master @ 353e496bcb6aceafb8b6731a6a4972e779a90f6e

Present Behaviour

This happened on all beacon nodes I upgraded:

May 05 18:31:30.001 INFO Synced                                  slot: 59557, block: 0xe1b0…8436, epoch: 1861, finalized_epoch: 1859, finalized_root: 0x9981…7c6b, peers: 2, service: slot_notifier
May 05 18:31:38.606 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2643226, latest_block_age: 256 mins, service: eth1_rpc
May 05 18:31:42.000 INFO Synced                                  slot: 59558, block: 0x4474…3ac9, epoch: 1861, finalized_epoch: 1859, finalized_root: 0x9981…7c6b, peers: 2, service: slot_notifier
May 05 18:31:54.000 INFO Synced                                  slot: 59559, block: 0x15f3…2787, epoch: 1861, finalized_epoch: 1859, finalized_root: 0x9981…7c6b, peers: 2, service: slot_notifier
May 05 18:31:59.686 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2643227, latest_block_age: 256 mins, service: eth1_rpc
thread 'tokio-runtime-worker-11' panicked at 'supplied instant is later than self', src/libstd/time.rs:263:9
stack backtrace:
   0:     0x55c3788552d4 - backtrace::backtrace::libunwind::trace::h5ae3454ebe40b621
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.44/src/backtrace/libunwind.rs:86
   1:     0x55c3788552d4 - backtrace::backtrace::trace_unsynchronized::hbf6f267a483fb2c0
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.44/src/backtrace/mod.rs:66
   2:     0x55c3788552d4 - std::sys_common::backtrace::_print_fmt::h37755015d94b9085
                               at src/libstd/sys_common/backtrace.rs:78
   3:     0x55c3788552d4 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h0561c8cd3569b40d
                               at src/libstd/sys_common/backtrace.rs:59
   4:     0x55c37887adbc - core::fmt::write::h86a597a35d48a212
                               at src/libcore/fmt/mod.rs:1063
   5:     0x55c37884d0e3 - std::io::Write::write_fmt::h73d9dc0f29eefe48
                               at src/libstd/io/mod.rs:1426
   6:     0x55c378858105 - std::sys_common::backtrace::_print::h6c60c5ee09af0233
                               at src/libstd/sys_common/backtrace.rs:62
   7:     0x55c378858105 - std::sys_common::backtrace::print::hf9d1db01634f9b2a
                               at src/libstd/sys_common/backtrace.rs:49
   8:     0x55c378858105 - std::panicking::default_hook::{{closure}}::h1db9298dd213ae95
                               at src/libstd/panicking.rs:204
   9:     0x55c378857e52 - std::panicking::default_hook::h3272faf6cc91fd2e
                               at src/libstd/panicking.rs:224
  10:     0x55c378858762 - std::panicking::rust_panic_with_hook::hb976084785e50594
                               at src/libstd/panicking.rs:470
  11:     0x55c37885834b - rust_begin_unwind
                               at src/libstd/panicking.rs:378
  12:     0x55c378878b61 - core::panicking::panic_fmt::h45f7d6868edb5678
                               at src/libcore/panicking.rs:85
  13:     0x55c3788788f3 - core::option::expect_failed::h9a8bff6ff005b30d
                               at src/libcore/option.rs:1203
  14:     0x55c378854d58 - core::option::Option<T>::expect::h63f0b1f892892a5a
                               at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550/src/libcore/option.rs:347
  15:     0x55c378854d58 - std::time::Instant::duration_since::h6f45165ba2fea7fa
                               at src/libstd/time.rs:263
  16:     0x55c378854d58 - <std::time::Instant as core::ops::arith::Sub>::sub::h490f3bc6e9b2f3f5
                               at src/libstd/time.rs:390
  17:     0x55c3776c891f - eth2_libp2p::peer_manager::PeerManager<TSpec>::update_reputations::h2ebd9401c43b0f7d
  18:     0x55c3776c2809 - eth2_libp2p::peer_manager::PeerManager<TSpec>::connect_peer::h8fd5922b91676c75
  19:     0x55c377f81d86 - <eth2_libp2p::behaviour::Behaviour<TSubstream,TSpec> as libp2p_swarm::behaviour::NetworkBehaviour>::poll::hba8d5013332e63b1
  20:     0x55c377e1aa5e - <libp2p_swarm::ExpandedSwarm<TTransport,TBehaviour,TInEvent,TOutEvent,THandler,THandlerErr,TConnInfo> as futures::stream::Stream>::poll::h2b7789d19d917148
  21:     0x55c377dec124 - <eth2_libp2p::service::Service<TSpec> as futures::stream::Stream>::poll::he80dc605eee4251c
  22:     0x55c377d48b34 - network::service::spawn_service::{{closure}}::h2d9a9aa2689e3adc
  23:     0x55c3784ad842 - futures::task_impl::std::set::h70e771bf1fa6ae94
  24:     0x55c3784adc32 - std::panicking::try::do_call::ha809959104cbaff8
  25:     0x55c37885df17 - __rust_maybe_catch_panic
                               at src/libpanic_unwind/lib.rs:86
  26:     0x55c3784abea5 - tokio_threadpool::task::Task::run::h8a25e0fc0b82aed2
  27:     0x55c3784a497e - tokio_threadpool::worker::Worker::run_task::he366337bba3af524
  28:     0x55c3784a4032 - tokio_threadpool::worker::Worker::run::h4f626ae3de8fdd08
  29:     0x55c3784863de - tokio_timer::clock::clock::with_default::hdce9ba1193c06f7d
  30:     0x55c378488973 - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h9fe6c0b101470e3f
  31:     0x55c3784ab76a - std::thread::local::LocalKey<T>::with::hcc974c4fb796cc4b
  32:     0x55c3784ab899 - std::thread::local::LocalKey<T>::with::hd48affb814e24190
  33:     0x55c3784ac458 - std::sys_common::backtrace::__rust_begin_short_backtrace::h3a88224508a0b894
  34:     0x55c3784adc8c - std::panicking::try::do_call::hdc3d4d4ddaa707e3
  35:     0x55c37885df17 - __rust_maybe_catch_panic
                               at src/libpanic_unwind/lib.rs:86
  36:     0x55c3784ae290 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h23bb8c521ce6a7b9
  37:     0x55c3788446cf - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h553ef812d1929d1b
                               at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550/src/liballoc/boxed.rs:1017
  38:     0x55c37885d00d - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h51b51bce029ae491
                               at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550/src/liballoc/boxed.rs:1017
  39:     0x55c37885d00d - std::sys_common::thread::start_thread::hca943f45f04c8e46
                               at src/libstd/sys_common/thread.rs:13
  40:     0x55c37885d00d - std::sys::unix::thread::Thread::new::thread_start::h352e8a5875b189ee
                               at src/libstd/sys/unix/thread.rs:80
  41:     0x7f1f49e3446f - start_thread
  42:     0x7f1f49d4a3d3 - clone
  43:                0x0 - <unknown>
May 05 18:32:04.785 INFO Sync Manager shutdown                   service: sync, service: network
May 05 18:32:06.000 INFO Synced                                  slot: 59560, block: 0x7e5b…0f2b, epoch: 1861, finalized_epoch: 1859, finalized_root: 0x9981…7c6b, peers: 2, service: slot_notifier
May 05 18:32:13.762 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2643228, latest_block_age: 256 mins, service: eth1_rpc
May 05 18:32:18.000 INFO Synced                                  slot: 59561, block:    …  empty, epoch: 1861, finalized_epoch: 1859, finalized_root: 0x9981…7c6b, peers: 2, service: slot_notifier
May 05 18:32:27.832 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2643229, latest_block_age: 256 mins, service: eth1_rpc
May 05 18:32:30.000 INFO Synced                                  slot: 59562, block:    …  empty, epoch: 1861, finalized_epoch: 1859, finalized_root: 0x9981…7c6b, peers: 2, service: slot_notifier
May 05 18:32:41.918 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2643230, latest_block_age: 256 mins, service: eth1_rpc
May 05 18:32:42.001 INFO Synced                                  slot: 59563, block:    …  empty, epoch: 1861, finalized_epoch: 1859, finalized_root: 0x9981…7c6b, peers: 2, service: slot_notifier

Expected Behaviour

The application should behave!

Steps to resolve

N/A

[pawanjay176]

The panic must have occurred at https://github.com/sigp/lighthouse/blob/353e496bcb6aceafb8b6731a6a4972e779a90f6e/beacon_node/eth2-libp2p/src/peer_manager/mod.rs#L396 when self.last_updated < since.

One possible path that could have led to panic is:

1. Peer gets connected
2. Peer gets disconnected
3. notify_disconnect gets called. Call to update_reputations updates self.last_updated to now1.
4. notify_disconnect's call to peerdb.disconnect(peer_id) updates info.connection_status to Disconnect {since: now2} and now2 > now1
5. Peer gets connected again and call to update_reputation panics as self.last_updated < since.

Might have panicked other ways too but the main issue seems to be the unchecked subtraction and the connection status getting updated in multiple places.

[AgeManning]

Thanks @q9f for raising this and @pawanjay176 for isolating the issue.

@divagant-martian I have made a PR which updates this part of the code to protect against underflows here. Will merge once reviewed and you're happy the logic here remains intact.

[paulhauner]

Is the plan to keep this one open until we haven't seen the panic for a few days?

As I understand it we believe the panic is fixed, but were unable to recreate it.

[q9f]

1111 fixed this. let's close this.