polkadot proces panicked at 'can not convert float seconds to Duration: value is negative'

[stakeworld]

• Server: Linux 00.stakeworld.nl 5.4.0-109-generic Bump libp2p-identify to 0.3.1 polkadot#123-Ubuntu SMP Fri Apr 8 09:10:54 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux , running on 6 core VPS with 16 MB memory,
• polkadot --version: polkadot 0.9.22-17c7b9594ae
• /usr/bin/polkadot --chain kusama --name STAKEWORLD/01 --unsafe-pruning --pruning 1000 --validator --port 30301 --rpc-port 9901 --ws-port 9801 --prometheus-port 9601 --prometheus-external --base-path /home/polkadot/stakeworld-01 --database rocksdb --telemetry-url 'wss://telemetry.polkadot.io/submit/ 1' --telemetry-url 'wss://telemetry-backend.w3f.community/submit 1'

While being in the active validator set the process crashed, it did restart and since is running and validating normal again.

Polkadot LOG
May 29 13:48:14 00.stakeworld.nl polkadot[6173]: Thread 'tokio-runtime-worker' panicked at 'can not convert float seconds to Duration: value is negative', /rustc/7737e0b5c4103216d6fd8cf94>
May 29 13:48:14 00.stakeworld.nl polkadot[6173]: This is a bug. Please report it at:
May 29 13:48:14 00.stakeworld.nl polkadot[6173]: https://github.com/paritytech/polkadot/issues/new

Dmesg output
[May29 13:48] tokio-runtime-w[6345]: segfault at 0 ip 0000000000000000 sp 00007f13ac76eba8 error 14 in polkadot[5621a0f89000+247000]
[ +0.000081] Code: Bad RIP value.

[bkchr]

Can you please show the entire stack trace? Or more logs around the error?

[stakeworld]

I am sorry, i don't have more info for now. I had a lot of problems on that particular node so i've moved to other hardware, since then I didn't see the problem so it could be hardware related. Will report back if it happens again.

[polkalegos]

I've got the same error running Docker images v0.9.26:

====================

Version: 0.9.26-d8785970175

   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
   9: <unknown>
  10: <unknown>
  11: <unknown>
  12: <unknown>
  13: <unknown>
  14: <unknown>
  15: start_thread
  16: clone


Thread 'tokio-runtime-worker' panicked at 'can not convert float seconds to Duration: value is negative', /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/time.rs:782

This is a bug. Please report it at:

	https://github.com/paritytech/polkadot/issues/new

[bkchr]

@polkalegos does this happen multiple times?

[polkalegos]

So far just one @bkchr

[ggwpez]

Very interesting... the std documents this error as only happening in try_from_secs_f* or from_secs_f*.
For what its worth I did a grep -Rni vendor/ -e '.*from_secs_.*' on the Polkadot vendor/ directory after a cargo vendor.
But all these cases are in not-live code 🤔
So no idea where this is being called, not even in a dependency.

vendor/sc-sysinfo/src/lib.rs:70:	pub fn from_secs_f32(secs: f32) -> Self {
vendor/sc-sysinfo/src/lib.rs:71:		Self::MaxDuration(Duration::from_secs_f32(secs))
vendor/frame-benchmarking-cli/src/machine/mod.rs:144:		let verify_limit = ExecutionLimit::from_secs_f32(self.verify_duration);
vendor/frame-benchmarking-cli/src/machine/mod.rs:145:		let disk_limit = ExecutionLimit::from_secs_f32(self.disk_duration);
vendor/frame-benchmarking-cli/src/machine/mod.rs:146:		let hash_limit = ExecutionLimit::from_secs_f32(self.hash_duration);
vendor/frame-benchmarking-cli/src/machine/mod.rs:147:		let memory_limit = ExecutionLimit::from_secs_f32(self.memory_duration);

[koute]

@polkalegos Just for reference, can you tell me which exact Docker image you were running?

[polkalegos]

@koute latest tag version 0.9.26

[polkalegos]

@koute happening again on v0.9.29:

Version: 0.9.29-94078b44fb6

   0: sp_panic_handler::set::{{closure}}
   1: std::panicking::rust_panic_with_hook
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/std/src/panicking.rs:702:17
   2: std::panicking::begin_panic_handler::{{closure}}
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/std/src/panicking.rs:588:13
   3: std::sys_common::backtrace::__rust_end_short_backtrace
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/std/src/sys_common/backtrace.rs:138:18
   4: rust_begin_unwind
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/std/src/panicking.rs:584:5
   5: core::panicking::panic_fmt
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/panicking.rs:142:14
   6: core::panicking::panic_display
   7: <sc_finality_grandpa::communication::gossip::GossipValidator<Block> as sc_network_gossip::validator::Validator<Block>>::message_allowed::{{closure}}
   8: <sc_network_gossip::bridge::GossipEngine<B> as core::future::future::Future>::poll
   9: <sc_finality_grandpa::communication::NetworkBridge<B,N> as core::future::future::Future>::poll
  10: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
  11: tokio::runtime::task::raw::poll
  12: std::sys_common::backtrace::__rust_begin_short_backtrace
  13: core::ops::function::FnOnce::call_once{{vtable.shim}}
  14: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/alloc/src/boxed.rs:1872:9
      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/alloc/src/boxed.rs:1872:9
      std::sys::unix::thread::Thread::new::thread_start
             at rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/std/src/sys/unix/thread.rs:108:17
  15: start_thread
  16: clone


Thread 'tokio-runtime-worker' panicked at 'can not convert float seconds to Duration: value is negative', /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/time.rs:782

This is a bug. Please report it at:

	https://github.com/paritytech/polkadot/issues/new

[koute]

@polkalegos Thank you for the backtrace!

I'll take a look at this.

[arkpar]

I've ran into similar issue once. The problem was that Instance counters are not consistent across threads. I.e creating an instance with Instance::now and then calling elapsed on it in another thread may panic.