Lighthouse: thread 'tokio-runtime-worker-7' panicked at 'elapsed=7481664; when=7481664'

[q9f]

Description

The sync manager shut down and I temporarily lost finality on Schlesi Testnet.

thread 'tokio-runtime-worker-7' panicked at 'elapsed=7481664; when=7481664', /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/wheel/mod.rs:244:5

Version

Using Lighthouse from this branch #1052 @ 310cc4fb504f6b3d6f4b0e9a5f53715a0c848138

Using Schlesi config: https://github.com/goerli/schlesi

Present Behavior

Connected a validator client to a beacon node locally, lost sync manager on the beacon node:

Apr 27 13:18:00.206 INFO Block from local validator              block_slot: 390, block_root: 0x7e2d…96d0, service: http
Apr 27 13:18:06.000 INFO Synced                                  slot: 390, epoch: 12, finalized_epoch: 10, finalized_root: 0xd017…bed4, peers: 6, service: slot_notifier
Apr 27 13:18:16.020 INFO Attestation from local validator        slot: 391, index: 0, source: 11, target: 11, service: http
Apr 27 13:18:18.001 INFO Synced                                  slot: 391, epoch: 12, finalized_epoch: 10, finalized_root: 0xd017…bed4, peers: 6, service: slot_notifier
Apr 27 13:18:20.041 INFO Attestation from local validator        slot: 391, index: 0, source: 11, target: 11, service: http
thread 'tokio-runtime-worker-7' panicked at 'elapsed=7481664; when=7481664', /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/wheel/mod.rs:244:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Apr 27 13:18:21.453 INFO Sync Manager shutdown                   service: sync, service: network
Apr 27 13:18:30.001 INFO Synced                                  slot: 392, epoch: 12, finalized_epoch: 10, finalized_root: 0xd017…bed4, peers: 6, service: slot_notifier
Apr 27 13:18:36.146 ERRO No valid eth1_data votes, `votes_to_consider` empty, outcome: casting `state.eth1_data` as eth1 vote, genesis_time: 1587981600, earliest_block_timestamp: 1587974284, lowest_block_number: 2596126, service: beacon
Apr 27 13:18:36.177 INFO Block from local validator              block_slot: 393, block_root: 0x7d1e…64e9, service: http
Apr 27 13:18:42.001 INFO Synced                                  slot: 393, epoch: 12, finalized_epoch: 10, finalized_root: 0xd017…bed4, peers: 6, service: slot_notifier
Apr 27 13:18:54.001 INFO Synced                                  slot: 394, epoch: 12, finalized_epoch: 10, finalized_root: 0xd017…bed4, peers: 6, service: slot_notifier
Apr 27 13:19:00.170 ERRO No valid eth1_data votes, `votes_to_consider` empty, outcome: casting `state.eth1_data` as eth1 vote, genesis_time: 1587981600, earliest_block_timestamp: 1587974284, lowest_block_number: 2596126, service: beacon
Apr 27 13:19:00.244 INFO Block from local validator              block_slot: 395, block_root: 0xfcac…31d4, service: http
Apr 27 13:19:06.001 INFO Synced                                  slot: 395, epoch: 12, finalized_epoch: 10, finalized_root: 0xd017…bed4, peers: 6, service: slot_notifier
Apr 27 13:19:18.001 INFO Synced                                  slot: 396, epoch: 12, finalized_epoch: 10, finalized_root: 0xd017…bed4, peers: 6, service: slot_notifier

Validator lost ability to submit blocks:

Apr 27 13:18:04.002 INFO Successfully subscribed validators      failed_validators: 2, validators: 2, service: attestation
Apr 27 13:18:06.001 INFO Some validators active                  slot: 390, epoch: 12, total_validators: 3, active_validators: 2, proposers: 2, service: notifier
Apr 27 13:18:16.002 INFO Successfully subscribed validators      failed_validators: 2, validators: 2, service: attestation
Apr 27 13:18:16.020 INFO Successfully published attestations     slot: 391, committee_index: 0, head_block: 0x0f3fbc341d18706b67578838e9bdda5314d0a7eb87b9e48d26825dd9fd84ca0d, count: 1, service: attestation
Apr 27 13:18:18.001 INFO Some validators active                  slot: 391, epoch: 12, total_validators: 3, active_validators: 2, proposers: 2, service: notifier
Apr 27 13:18:20.042 INFO Successfully published aggregate attestations, slot: 391, committee_index: 0, head_block: 0x0f3f…ca0d, signatures: 1, service: attestation
Apr 27 13:18:28.002 CRIT Error during attestation production     error: Failed to subscribe validators: ReqwestError(Error(Status(500), "http://localhost:5052/validator/subscribe")), service: attestation
Apr 27 13:18:30.001 INFO Some validators active                  slot: 392, epoch: 12, total_validators: 3, active_validators: 2, proposers: 2, service: notifier
Apr 27 13:18:36.177 CRIT Error whilst producing block            message: Error from beacon node when publishing block: ReqwestError(Error(Status(500), "http://localhost:5052/validator/block")), service: block
Apr 27 13:18:40.002 CRIT Error during attestation production     error: Failed to subscribe validators: ReqwestError(Error(Status(500), "http://localhost:5052/validator/subscribe")), service: attestation
Apr 27 13:18:42.001 INFO Some validators active                  slot: 393, epoch: 12, total_validators: 3, active_validators: 2, proposers: 2, service: notifier
Apr 27 13:18:52.001 CRIT Error during attestation production     error: Failed to subscribe validators: ReqwestError(Error(Status(500), "http://localhost:5052/validator/subscribe")), service: attestation
Apr 27 13:18:54.001 INFO Some validators active                  slot: 394, epoch: 12, total_validators: 3, active_validators: 2, proposers: 2, service: notifier
Apr 27 13:19:00.244 CRIT Error whilst producing block            message: Error from beacon node when publishing block: ReqwestError(Error(Status(500), "http://localhost:5052/validator/block")), service: block
Apr 27 13:19:04.002 CRIT Error during attestation production     error: Failed to subscribe validators: ReqwestError(Error(Status(500), "http://localhost:5052/validator/subscribe")), service: attestation
Apr 27 13:19:06.001 INFO Some validators active                  slot: 395, epoch: 12, total_validators: 3, active_validators: 2, proposers: 2, service: notifier
Apr 27 13:19:16.002 CRIT Error during attestation production     error: Failed to subscribe validators: ReqwestError(Error(Status(500), "http://localhost:5052/validator/subscribe")), service: attestation
Apr 27 13:19:18.001 INFO Some validators active                  slot: 396, epoch: 12, total_validators: 3, active_validators: 2, proposers: 2, service: notifier

Expected Behavior

Should not panic :)

Steps to resolve

A restart was able to resolve this.

[paulhauner]

I couldn't find the tag for tokio-timer-0.2.13 github.com/tokio-rs, but by looking at the crates.io code, it seems that tokio-timer-0.2.12 is equivalent for this purpose.

Digging into that code, it seems that the panic is here:

fn level_for(elapsed: u64, when: u64) -> usize {
    let masked = elapsed ^ when;

    assert!(masked != 0, "elapsed={}; when={}", elapsed, when);

    let leading_zeros = masked.leading_zeros() as usize;
    let significant = 63 - leading_zeros;
    significant / 6
}

So I think this panic means elapsed == when.

We can follow a call-chain to end up at HashSetDelay::update_timeout, where @AgeManning previously indicated the panic was:

wheel::level_for <- Wheel::insert <- DelayQueue::insert_idx <- DelayQueue::reset_at <- DelayQueue::reset <- HashSetDelay::update_timeout.

Considering the call chain, it seems like the panic is caused by DelayQueue::insert_idx being called with a when that is equal to the current time of it's underlying Wheel. I think this happens if we call HashSetDelay::update_timeout with timeout == 0.

Having a poke around it seems to explicity happen here:

https://github.com/sigp/lighthouse/blob/500f6b53d17c5bc7f3cffb1855800cf1ac8bb159/beacon_node/network/src/attestation_service/mod.rs#L312

Or perhaps here:

https://github.com/sigp/lighthouse/blob/500f6b53d17c5bc7f3cffb1855800cf1ac8bb159/beacon_node/network/src/attestation_service/mod.rs#L260-L278

[paulhauner]

Trying to test this now. Not having any luck though, perhaps I'm not on the right path.

[paulhauner]

Hmm Wheel::insert already ensures that when > self.elapsed before calling level_for:

        if when <= self.elapsed {
            return Err((item, InsertError::Elapsed));
        } else if when - self.elapsed > MAX_DURATION {
            return Err((item, InsertError::Invalid));
        }

        // Get the level at which the entry should be stored
        let level = self.level_for(when);

Shifting focus to Wheel::remove.

[paulhauner]

So Wheel::reset_at calls Wheel::remove!

    pub fn reset_at(&mut self, key: &Key, when: Instant) {
        self.wheel.remove(&key.index, &mut self.slab);

        // Normalize the deadline. Values cannot be set to expire in the past.
        let when = self.normalize_deadline(when);

        self.slab[key.index].when = when;
        self.insert_idx(when, key.index);

        let next_deadline = self.next_deadline();
        if let (Some(ref mut delay), Some(deadline)) = (&mut self.delay, next_deadline) {
            delay.reset(deadline);
        }
    }

Going deeper...

[paulhauner]

Alright, I manged to trigger the panic by adding this test to the end of hashmap_delay.rs:

    #[test]
    #[should_panic]
    fn panic() {
        let key = 2;
        let value = 2;

        let mut map = HashMapDelay::default();

        std::thread::sleep(Duration::from_secs(1));

        for _ in 0..10000 {
            for _ in 0..100 {
                let _ = map.poll();
            }
            map.insert(key, value);
            map.update_timeout(&key, Duration::from_secs(0));
        }
    }

Now I need to refine this and figure out if tokio is being naughty and how we can avoid it.

[paulhauner]

For clarity, here's the panic message:

**thread 'hashmap_delay::tests::panic' panicked at 'elapsed=98304; when=98304', /home/paul/development/tokio/tokio-timer/src/wheel/mod.rs:244:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.**

[paulhauner]

Alright, so I've been looking into this some more and I'll document where I'm up to for history sake.

So the panic we're looking for comes from elapsed == when in wheel::level_for which is a private fn and only called in two places:

• Wheel::insert: this call is guarded against elapsed == when.
• Wheel::remove: not guarded from this condition.

Given this, Wheel::remove must be the culprit.

So how can elapsed == when? Let's look at how these variables are set:

• elapsed: always set to Wheel::elapsed. But where is the private self.elapsed var set?
  
  
  
  • Via Wheel::set_elapsed which is only called via Wheel::poll.
  
  
• when: set here in Wheel::insert to a value that must be higher than self.elapsed (so previously mentioned guard condition).

Given this, when can never be set to equal elapsed. But, self.elapsed can be set to equal when via Wheel:poll.

Poll pops the next expired task off the wheel and maybe sets self.elapsed. So, what I can figure is that we have multiple processes that are set to expire at the same time and we've popped one of them (and updated self.elapsed) but failed to pop the rest of them off via poll. Then, before calling poll again we've tried to Wheel::remove one of those expired-but-not-popped entries.

So, why would we pop one entry but not the rest? We call poll in this in two places:

• AttestationService
• PeerManager

Both of these we poll till we get None, unless we hit an error. So, we must be hitting an error. We can hit an error via:

• In HashSetDelay a value exists in self.expirations but not in self.entries: I can't for the life of me figure out how this is possible.
• Via an upstream tokio_timer::Error: the only error that seems reachable here is Shutdown, which means the timer is shutdown and we can never recover. This certainly doesn't seem like the case to me.

So, I'm at a bit of a loss here. My solution now is to patch Wheel::remove with:

        let level = if when == self.elapsed {
            0
        } else {
            self.level_for(when)
        };

I'm not convinced that this is the right solution, but it seems to be my only solution available at the moment so I'm going to take a shot.

[q9f]

thread 'tokio-runtime-worker-6' panicked at 'elapsed=5186752; when=5186752', /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/wheel/mod.rs:244:5
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.44/src/backtrace/libunwind.rs:86
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.44/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:78
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1063
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1426
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:204
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:224
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:470
  11: rust_begin_unwind
             at src/libstd/panicking.rs:378
  12: std::panicking::begin_panic_fmt
             at src/libstd/panicking.rs:332
  13: tokio_timer::wheel::level_for
  14: tokio_timer::wheel::Wheel<T>::remove
  15: tokio_timer::delay_queue::DelayQueue<T>::reset
  16: hashmap_delay::hashset_delay::HashSetDelay<K>::insert
  17: eth2_libp2p::peer_manager::PeerManager<TSpec>::ping_request
  18: <eth2_libp2p::behaviour::Behaviour<TSubstream,TSpec> as libp2p_swarm::behaviour::NetworkBehaviour>::poll
  19: <libp2p_swarm::ExpandedSwarm<TTransport,TBehaviour,TInEvent,TOutEvent,THandler,THandlerErr,TConnInfo> as futures::stream::Stream>::poll
  20: <eth2_libp2p::service::Service<TSpec> as futures::stream::Stream>::poll
  21: <futures::future::poll_fn::PollFn<F> as futures::future::Future>::poll
  22: futures::task_impl::std::set
  23: std::panicking::try::do_call
  24: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:86
  25: tokio_threadpool::task::Task::run
  26: tokio_threadpool::worker::Worker::run_task
  27: tokio_threadpool::worker::Worker::run
  28: tokio_timer::clock::clock::with_default
  29: tokio::runtime::threadpool::builder::Builder::build::{{closure}}
  30: std::thread::local::LocalKey<T>::with
  31: std::thread::local::LocalKey<T>::with
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

[paulhauner]

Alright, new progress. I still think it's possible to make tokio_timer panic if you do a Wheel::remove between calls to Wheel::poll, however I don't think that's what we're doing here. The fact that we're taking mutable references to HashSetDelay means that we can statically analyze the struct on it's own and determine that it's impossible for this to happen with the current code. Ofc, I haven't formally proved it but that's what I get from detailed reading of it.

The new thing is that we're using PeerId in a HashMap. PeerId has the following caveat on it's AsRef<[u8]> impl (notably, not on it's Hash or Eq impls):

/// **NOTE:** This byte representation is not necessarily consistent with
/// equality of peer IDs. That is, two peer IDs may be considered equal
/// while having a different byte representation as per `AsRef<[u8]>`.
impl AsRef<[u8]> for PeerId {
    fn as_ref(&self) -> &[u8] {
        self.as_bytes()
    }

This breaks an assumption by std::collections::HashMap:

... if two keys are equal, their hashes must be equal.

This gives us reason to assume that HashSetDelay::expirations and HashSetDelay::items can become disjoint. This is certainly a path worth exploring.

[AgeManning]

Seems tokio::DelayQueue is all kinds of broken in the version we are using.

We've added a patch, which corrects its behaviour is some initial testing. Was not able to reproduce the panic in a testing environment but hopefully the corrected behaviour addresses this in the wild.

[paulhauner]

We discovered that if you call DelayQueue::insert during a series of DelayQueue::poll calls it will cause the next DelayQueue:poll to return Async::NotReady. I believe this can cause the issue I mentioned in https://github.com/sigp/lighthouse/issues/1067#issuecomment-621058472. We were not able to recreate, though.

We tested against the latest version of tokio and did not observe this weird behavior. We're upgrading to this version via #879, so I think the best course is to patch for now. This saves us getting deep into a older version of tokio that we're going to replace in a week or so anyway.

I think we should leave this issue open until @q9f and myself don't observe this panic for a couple of days.

[q9f]

I can no longer observe this.

[AgeManning]

Closing as this is either resolved currently, or will soon be resolved with upgrades to tokio

[q9f]

Happened again this morning on master @ b6c027b9ecc77182d64f99594e6d4418764d01b8

May 03 11:33:42.000 INFO Synced                                  slot: 43068, block:    …  empty, epoch: 1345, finalized_epoch: 1343, finalized_root: 0x2926…c66c, peers: 5, service: slot_notifier
May 03 11:33:51.244 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2630036, latest_block_age: 256 mins, service: eth1_rpc
May 03 11:33:54.001 INFO Synced                                  slot: 43069, block: 0xe208…7e86, epoch: 1345, finalized_epoch: 1343, finalized_root: 0x2926…c66c, peers: 5, service: slot_notifier
May 03 11:34:00.188 INFO Block from local validator              block_slot: 43070, block_root: 0xafd8…aea0, service: http
May 03 11:34:04.023 INFO Attestation from local validator        slot: 43070, index: 0, source: 1344, target: 1344, service: http
thread 'tokio-runtime-worker-3' panicked at 'elapsed=87109568; when=87109568', /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/wheel/mod.rs:244:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
May 03 11:34:04.066 INFO Sync Manager shutdown                   service: sync, service: network
May 03 11:34:05.330 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2630037, latest_block_age: 256 mins, service: eth1_rpc
May 03 11:34:06.001 INFO Synced                                  slot: 43070, block: 0xafd8…aea0, epoch: 1345, finalized_epoch: 1343, finalized_root: 0x2926…c66c, peers: 5, service: slot_notifier
May 03 11:34:08.046 INFO Attestation from local validator        slot: 43070, index: 0, source: 1344, target: 1344, service: http
May 03 11:34:18.000 INFO Synced                                  slot: 43071, block:    …  empty, epoch: 1345, finalized_epoch: 1343, finalized_root: 0x2926…c66c, peers: 5, service: slot_notifier
May 03 11:34:19.406 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2630038, latest_block_age: 256 mins, service: eth1_rpc
May 03 11:34:30.001 INFO Synced                                  slot: 43072, block:    …  empty, epoch: 1346, finalized_epoch: 1343, finalized_root: 0x2926…c66c, peers: 5, service: slot_notifier
May 03 11:34:33.478 INFO Imported eth1 block(s)                  new: 1, total_cached_blocks: 4096, latest_block: 2630039, latest_block_age: 256 mins, service: eth1_rpc

[paulhauner]

Nooooo! That commit should indeed have the #1087 fix in it...

I might just re-open this until we haven't seen it for a while and/or our upstream issue is resolved.

[AgeManning]

Tokio upgrades are inbound (this week) which should hopefully address this

[AgeManning]

Ok, I'm hoping the stable-futures branch resolves this. If anyone sees this on the stable-futures branch we are in trouble. Will be doing extensive testing. If we don't see it in a few days, will re-close this issue

[AgeManning]

I have not witnessed this in the stable futures upgrade. I'm going to consider this resolved again.

[q9f]

Didn't see this either. :+1:

[AgeManning]

I saw a notification for this thread and my heart sank a little.

Turns out it's all good!! Wooh :tada: :taco: