statime as a service

[MeestorX]

I checked the statime repository to see if there's an example of how the service should look? My guess is that statime is starting to early in the boot sequence?

Here's the error I'm seeing on boot:

journalctl -u statime
Feb 02 23:51:50 rp-satellite-xx statime[1129]: thread 'tokio-runtime-worker' (1134) panicked at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/fixed-1.29.0/src/arith.rs:569:1:
Feb 02 23:51:50 rp-satellite-xx statime[1129]: attempt to subtract with overflow
Feb 02 23:51:50 rp-satellite-xx statime[1129]: note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Here's the statime.service I'm using:

[Unit]
Description=Statime PTP Service
After=network-online.target
Wants=network-online.target

[Service]
Type=simple
WorkingDirectory=/usr/local/bin/statime
ExecStart=/usr/local/bin/statime/statime -c inferno-ptpv1.toml
Restart=on-failure
RestartSec=5

[Install]
WantedBy=multi-user.target

If I restart it manually, it comes right up. Restart=on-failure doesn't kick in it seems.

[MeestorX]

I'll add the RUST_BACKTRACE=1 as suggested to see if it shows an error.

[teodly]

attempt to subtract with overflow

This is internal error of Statime caused by, for example, jumping clock. It may occur when Statime is started before NTP time synchronization. RUST_BACKTRACE=1 will confirm.

Restart=on-failure doesn't kick in it seems.

What does systemctl status statime.service show when it is in the broken state? And please provide uncut logs (from journalctl)

[MeestorX]

Thank you. That was the full journalctl, but without the RUST_BACKTRACE=1. The issue hasn't happened since. Once it does I'll post the logs.

[MeestorX]

Ok, looks like it happened again.

Feb 04 12:24:15 rp-satellite-xx systemd[1]: Started statime.service - Statime PTP Service.
Feb 04 13:53:29 rp-satellite-xx statime[1211]: thread 'tokio-runtime-worker' (1223) panicked at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/fixed-1.29.0/src/arith.rs:569:1:
Feb 04 13:53:29 rp-satellite-xx statime[1211]: attempt to subtract with overflow
Feb 04 13:53:29 rp-satellite-xx statime[1211]: stack backtrace:
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    0: __rustc::rust_begin_unwind
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/panicking.rs:698:5
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    1: core::panicking::panic_fmt
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/core/src/panicking.rs:80:14
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    2: core::panicking::panic_const::panic_const_sub_overflow
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/core/src/panicking.rs:180:17
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    3: <u128 as core::ops::arith::Sub>::sub
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/core/src/ops/arith.rs:218:45
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    4: fixed::arith::<impl core::ops::arith::Sub for fixed::FixedU128<Frac>>::sub
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/fixed-1.29.0/src/arith.rs:110:48
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    5: <statime::time::instant::Time as core::ops::arith::Add<statime::time::duration::Duration>>::add
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime/src/time/instant.rs:112:24
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    6: <statime::time::instant::Time as core::ops::arith::AddAssign<statime::time::duration::Duration>>::add_assign
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime/src/time/instant.rs:124:17
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    7: statime::filters::kalman::InnerFilter::absorb_offset_steer
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime/src/filters/kalman.rs:343:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    8: statime::filters::kalman::BaseFilter::absorb_offset_steer
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime/src/filters/kalman.rs:435:19
Feb 04 13:53:31 rp-satellite-xx statime[1211]:    9: statime::filters::kalman::KalmanFilter::step
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime/src/filters/kalman.rs:674:32
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   10: statime::filters::kalman::KalmanFilter::steer
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime/src/filters/kalman.rs:707:18
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   11: <statime::filters::kalman::KalmanFilter as statime::filters::Filter>::measurement
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime/src/filters/kalman.rs:610:14
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   12: statime::intermediate_clock_task::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /usr/local/src/statime/statime-linux/src/main.rs:312:41
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   13: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/core.rs:331:24
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   14: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/loom/std/unsafe_cell.rs:16:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   15: tokio::runtime::task::core::Core<T,S>::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/core.rs:320:30
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   16: tokio::runtime::task::harness::poll_future::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:532:30
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   17: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/core/src/panic/unwind_safe.rs:274:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   18: std::panicking::catch_unwind::do_call
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/panicking.rs:590:40
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   19: __rust_try
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   20: std::panicking::catch_unwind
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/panicking.rs:553:19
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   21: std::panic::catch_unwind
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/panic.rs:359:14
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   22: tokio::runtime::task::harness::poll_future
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:520:18
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   23: tokio::runtime::task::harness::Harness<T,S>::poll_inner
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:209:27
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   24: tokio::runtime::task::harness::Harness<T,S>::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:154:20
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   25: tokio::runtime::task::raw::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/raw.rs:271:13
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   26: tokio::runtime::task::raw::RawTask::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/raw.rs:201:18
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   27: tokio::runtime::task::LocalNotified<S>::run
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/mod.rs:463:13
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   28: tokio::runtime::scheduler::multi_thread::worker::Context::run_task::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/scheduler/multi_thread/worker.rs:600:18
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   29: tokio::task::coop::with_budget
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/task/coop/mod.rs:167:5
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   30: tokio::task::coop::budget
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/task/coop/mod.rs:133:5
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   31: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/scheduler/multi_thread/worker.rs:594:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   32: tokio::runtime::scheduler::multi_thread::worker::Context::run
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/scheduler/multi_thread/worker.rs:542:29
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   33: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/scheduler/multi_thread/worker.rs:507:24
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   34: tokio::runtime::context::scoped::Scoped<T>::set
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/context/scoped.rs:40:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   35: tokio::runtime::context::set_scheduler::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/context.rs:180:38
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   36: std::thread::local::LocalKey<T>::try_with
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/thread/local.rs:508:12
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   37: std::thread::local::LocalKey<T>::with
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/thread/local.rs:472:20
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   38: tokio::runtime::context::set_scheduler
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/context.rs:180:17
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   39: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/scheduler/multi_thread/worker.rs:502:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   40: tokio::runtime::context::runtime::enter_runtime
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/context/runtime.rs:65:16
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   41: tokio::runtime::scheduler::multi_thread::worker::run
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/scheduler/multi_thread/worker.rs:494:5
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   42: tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/scheduler/multi_thread/worker.rs:460:45
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   43: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/blocking/task.rs:42:21
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   44: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/core.rs:331:24
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   45: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/loom/std/unsafe_cell.rs:16:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   46: tokio::runtime::task::core::Core<T,S>::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/core.rs:320:30
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   47: tokio::runtime::task::harness::poll_future::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:532:30
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   48: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/core/src/panic/unwind_safe.rs:274:9
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   49: std::panicking::catch_unwind::do_call
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/panicking.rs:590:40
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   50: __rust_try
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   51: std::panicking::catch_unwind
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/panicking.rs:553:19
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   52: std::panic::catch_unwind
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /rustc/ded5c06cf21d2b93bffd5d884aa6e96934ee4234/library/std/src/panic.rs:359:14
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   53: tokio::runtime::task::harness::poll_future
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:520:18
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   54: tokio::runtime::task::harness::Harness<T,S>::poll_inner
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:209:27
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   55: tokio::runtime::task::harness::Harness<T,S>::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/harness.rs:154:20
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   56: tokio::runtime::task::raw::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/raw.rs:271:13
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   57: tokio::runtime::task::raw::RawTask::poll
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/raw.rs:201:18
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   58: tokio::runtime::task::UnownedTask<S>::run
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/task/mod.rs:500:13
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   59: tokio::runtime::blocking::pool::Task::run
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/blocking/pool.rs:161:19
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   60: tokio::runtime::blocking::pool::Inner::run
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/blocking/pool.rs:511:22
Feb 04 13:53:31 rp-satellite-xx statime[1211]:   61: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}
Feb 04 13:53:31 rp-satellite-xx statime[1211]:              at /root/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.1/src/runtime/blocking/pool.rs:469:47
Feb 04 13:53:31 rp-satellite-xx statime[1211]: note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

[teodly]

It may happen if system clock jumps (we are abusing Statime a bit here - originally it wasn't designed for virtual clocks). However it should be harmless as systemd should restart the service. What was systemctl status statime.service showing right after it broke?

[MeestorX]

I don't recall exactly, except it didn't restart.

[teodly]

Maybe the process doesn't exit because error happens in non-main thread?

sudo systemctl status statime.service just after it broke would confirm this

[MeestorX]

Doesn't journalctl -u statime show everything that systemctl status statime shows (and more?)

[teodly]

No. It doesn't show current state of the service.

[maze42d]

you could try setting the service to run after ntpd (or whatever debian uses for ntp) and/or a dirty cheap trick ExecStart=sleep 2; /usr/local/bin/statime/statime -c inferno-ptpv1.toml

[MeestorX]

Thank you. I now just wait a bit before starting pipewire - trying to get pipewire to wait for statime to settle was too big a PITA.
The problem still remains though that when statime fails, the service doesn't sense that and restart. So the restart part of the service doesn't work.
I would love to get that part to work somehow.