[INFO] fetching crate timesimp 1.0.0... [INFO] testing timesimp-1.0.0 against beta-2025-10-28 for beta-1.92-2 [INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-0-tc2/source [INFO] started tweaking crates.io crate timesimp 1.0.0 [INFO] removed 0 missing tests [INFO] finished tweaking crates.io crate timesimp 1.0.0 [INFO] tweaked toml for crates.io crate timesimp 1.0.0 written to /workspace/builds/worker-0-tc2/source/Cargo.toml [INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain beta-2025-10-28 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-10-28" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }` [INFO] crate crates.io crate timesimp 1.0.0 already has a lockfile, it will not be regenerated [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-10-28" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] c2cda0a536f0f59ad30377e70e9268c369750522b92cb99882f6b688c3d691d3 [INFO] running `Command { std: "docker" "start" "-a" "c2cda0a536f0f59ad30377e70e9268c369750522b92cb99882f6b688c3d691d3", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "c2cda0a536f0f59ad30377e70e9268c369750522b92cb99882f6b688c3d691d3", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "c2cda0a536f0f59ad30377e70e9268c369750522b92cb99882f6b688c3d691d3", kill_on_drop: false }` [INFO] [stdout] c2cda0a536f0f59ad30377e70e9268c369750522b92cb99882f6b688c3d691d3 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] ddaf0e1ba8cc67954b60427991bd0c1e49347448e103607ca78fb7cb564d5fca [INFO] running `Command { std: "docker" "start" "-a" "ddaf0e1ba8cc67954b60427991bd0c1e49347448e103607ca78fb7cb564d5fca", kill_on_drop: false }` [INFO] [stderr] Compiling libc v0.2.171 [INFO] [stderr] Compiling thiserror v2.0.12 [INFO] [stderr] Compiling tracing-core v0.1.33 [INFO] [stderr] Compiling jiff v0.2.10 [INFO] [stderr] Compiling thiserror-impl v2.0.12 [INFO] [stderr] Compiling tracing v0.1.41 [INFO] [stderr] Compiling getrandom v0.3.2 [INFO] [stderr] Compiling rand_core v0.9.3 [INFO] [stderr] Compiling rand_chacha v0.9.0 [INFO] [stderr] Compiling rand v0.9.1 [INFO] [stderr] Compiling timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 12.32s [INFO] running `Command { std: "docker" "inspect" "ddaf0e1ba8cc67954b60427991bd0c1e49347448e103607ca78fb7cb564d5fca", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "ddaf0e1ba8cc67954b60427991bd0c1e49347448e103607ca78fb7cb564d5fca", kill_on_drop: false }` [INFO] [stdout] ddaf0e1ba8cc67954b60427991bd0c1e49347448e103607ca78fb7cb564d5fca [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 487361f3ce1dcfbacef9d886b925a88045c51d6720d2117ef047b757f8b84674 [INFO] running `Command { std: "docker" "start" "-a" "487361f3ce1dcfbacef9d886b925a88045c51d6720d2117ef047b757f8b84674", kill_on_drop: false }` [INFO] [stderr] Compiling smallvec v1.14.0 [INFO] [stderr] Compiling shlex v1.3.0 [INFO] [stderr] Compiling vcpkg v0.2.15 [INFO] [stderr] Compiling syn v2.0.100 [INFO] [stderr] Compiling pkg-config v0.3.32 [INFO] [stderr] Compiling signal-hook-registry v1.4.5 [INFO] [stderr] Compiling openssl v0.10.72 [INFO] [stderr] Compiling foreign-types-shared v0.1.1 [INFO] [stderr] Compiling futures-task v0.3.31 [INFO] [stderr] Compiling cc v1.2.20 [INFO] [stderr] Compiling foreign-types v0.3.2 [INFO] [stderr] Compiling futures-util v0.3.31 [INFO] [stderr] Compiling bitflags v2.9.0 [INFO] [stderr] Compiling parking_lot_core v0.9.10 [INFO] [stderr] Compiling native-tls v0.2.14 [INFO] [stderr] Compiling futures-channel v0.3.31 [INFO] [stderr] Compiling parking_lot v0.12.3 [INFO] [stderr] Compiling serde v1.0.219 [INFO] [stderr] Compiling openssl-probe v0.1.6 [INFO] [stderr] Compiling http-body-util v0.1.3 [INFO] [stderr] Compiling sync_wrapper v1.0.2 [INFO] [stderr] Compiling tower-layer v0.3.3 [INFO] [stderr] Compiling rustls-pemfile v2.2.0 [INFO] [stderr] Compiling rand v0.9.1 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling encoding_rs v0.8.35 [INFO] [stderr] Compiling thread_local v1.1.8 [INFO] [stderr] Compiling mime v0.3.17 [INFO] [stderr] Compiling ipnet v2.11.0 [INFO] [stderr] Compiling tracing-subscriber v0.3.19 [INFO] [stderr] Compiling openssl-sys v0.9.107 [INFO] [stderr] Compiling synstructure v0.13.1 [INFO] [stderr] Compiling serde_urlencoded v0.7.1 [INFO] [stderr] Compiling zerofrom-derive v0.1.6 [INFO] [stderr] Compiling yoke-derive v0.7.5 [INFO] [stderr] Compiling zerovec-derive v0.10.3 [INFO] [stderr] Compiling displaydoc v0.2.5 [INFO] [stderr] Compiling tokio-macros v2.5.0 [INFO] [stderr] Compiling icu_provider_macros v1.5.0 [INFO] [stderr] Compiling tracing-attributes v0.1.28 [INFO] [stderr] Compiling openssl-macros v0.1.1 [INFO] [stderr] Compiling thiserror-impl v2.0.12 [INFO] [stderr] Compiling tokio v1.44.2 [INFO] [stderr] Compiling tracing v0.1.41 [INFO] [stderr] Compiling zerofrom v0.1.6 [INFO] [stderr] Compiling thiserror v2.0.12 [INFO] [stderr] Compiling yoke v0.7.5 [INFO] [stderr] Compiling timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Compiling zerovec v0.10.4 [INFO] [stderr] Compiling tinystr v0.7.6 [INFO] [stderr] Compiling icu_collections v1.5.0 [INFO] [stderr] Compiling icu_locid v1.5.0 [INFO] [stderr] Compiling icu_provider v1.5.0 [INFO] [stderr] Compiling icu_locid_transform v1.5.0 [INFO] [stderr] Compiling icu_properties v1.5.1 [INFO] [stderr] Compiling tokio-util v0.7.15 [INFO] [stderr] Compiling tokio-native-tls v0.3.1 [INFO] [stderr] Compiling tower v0.5.2 [INFO] [stderr] Compiling h2 v0.4.9 [INFO] [stderr] Compiling icu_normalizer v1.5.0 [INFO] [stderr] Compiling idna_adapter v1.2.0 [INFO] [stderr] Compiling idna v1.0.3 [INFO] [stderr] Compiling url v2.5.4 [INFO] [stderr] Compiling hyper v1.6.0 [INFO] [stderr] Compiling hyper-util v0.1.11 [INFO] [stderr] Compiling hyper-tls v0.6.0 [INFO] [stderr] Compiling reqwest v0.12.15 [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 08s [INFO] running `Command { std: "docker" "inspect" "487361f3ce1dcfbacef9d886b925a88045c51d6720d2117ef047b757f8b84674", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "487361f3ce1dcfbacef9d886b925a88045c51d6720d2117ef047b757f8b84674", kill_on_drop: false }` [INFO] [stdout] 487361f3ce1dcfbacef9d886b925a88045c51d6720d2117ef047b757f8b84674 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 465420a2020bb969c1d7760eb941065dc188235b6c9d9779175d30990efb8300 [INFO] running `Command { std: "docker" "start" "-a" "465420a2020bb969c1d7760eb941065dc188235b6c9d9779175d30990efb8300", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.27s [INFO] [stdout] [INFO] [stdout] running 5 tests [INFO] [stdout] test delta::tests::client_equal_server ... ok [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-f5a7014f299f61aa) [INFO] [stdout] test delta::tests::client_behind_server ... ok [INFO] [stdout] test delta::tests::client_ahead_of_server ... ok [INFO] [stdout] test delta::tests::clock_went_backwards ... ok [INFO] [stdout] test delta::tests::with_sleep ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s [INFO] [stdout] [INFO] [stderr] Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-97779c68f75e8a0a) [INFO] [stdout] [INFO] [stdout] running 10 tests [INFO] [stdout] 2025-11-05T06:48:28.260823Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:28.260887Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:28.260893Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.260900Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.260847Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:28.260950Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.261081Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:28.261102Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.261425Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:28.261460Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.261758Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-11-05T06:48:28.261813Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.263683Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:28.263715Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.264428Z TRACE new{response=Response { client: 2025-11-05T06:48:28.262064878Z, server: 2025-11-05T06:48:28.263179708Z } current=2025-11-05T06:48:28.264294208Z}: timesimp::delta: response processing internals latency=1ms 114µs 665ns local_at_midpoint=2025-11-05T06:48:28.263179543Z delta=165ns [INFO] [stdout] 2025-11-05T06:48:28.264486Z TRACE timesimp: obtained raw offset from server latency=1.114665ms delta=165ns [INFO] [stdout] 2025-11-05T06:48:28.264505Z DEBUG timesimp: no offset stored, storing initial delta offset=165ns [INFO] [stdout] 2025-11-05T06:48:28.264531Z TRACE timesimp: sleeping to spread out requests delay=594.421902ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.268262Z TRACE new{response=Response { client: 2025-11-05T06:48:28.261601598Z, server: 2025-11-05T06:48:33.265039658Z } current=2025-11-05T06:48:28.268157648Z}: timesimp::delta: response processing internals latency=3ms 278µs 25ns local_at_midpoint=2025-11-05T06:48:28.264879623Z delta=5s 160µs 35ns [INFO] [stdout] 2025-11-05T06:48:28.268312Z TRACE timesimp: obtained raw offset from server latency=3.278025ms delta=5s 160µs 35ns [INFO] [stdout] 2025-11-05T06:48:28.268324Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 160µs 35ns [INFO] [stdout] 2025-11-05T06:48:28.268332Z TRACE timesimp: sleeping to spread out requests delay=1.192904154s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.268774Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-11-05T06:48:28.268833Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.276553Z TRACE new{response=Response { client: 2025-11-05T06:48:28.262134328Z, server: 2025-11-05T06:48:33.269264048Z } current=2025-11-05T06:48:28.276385288Z}: timesimp::delta: response processing internals latency=7ms 125µs 480ns local_at_midpoint=2025-11-05T06:48:28.269259808Z delta=5s 4µs 240ns [INFO] [stdout] 2025-11-05T06:48:28.276626Z TRACE timesimp: obtained raw offset from server latency=7.12548ms delta=5s 4µs 240ns [INFO] [stdout] 2025-11-05T06:48:28.276642Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 4µs 240ns [INFO] [stdout] 2025-11-05T06:48:28.276652Z TRACE timesimp: sleeping to spread out requests delay=413.437184ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.284690Z TRACE new{response=Response { client: 2025-11-05T06:48:28.262269668Z, server: 2025-11-05T06:48:23.273396268Z } current=2025-11-05T06:48:28.284538568Z}: timesimp::delta: response processing internals latency=11ms 134µs 450ns local_at_midpoint=2025-11-05T06:48:28.273404118Z delta=5s 7µs 850ns ago [INFO] [stdout] 2025-11-05T06:48:28.284759Z TRACE timesimp: obtained raw offset from server latency=11.13445ms delta=5s 7µs 850ns ago [INFO] [stdout] 2025-11-05T06:48:28.284775Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 7µs 850ns ago [INFO] [stdout] 2025-11-05T06:48:28.284786Z TRACE timesimp: sleeping to spread out requests delay=1.293057034s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.298807Z TRACE new{response=Response { client: 2025-11-05T06:48:28.269599268Z, server: 2025-11-05T06:48:28.279805818Z } current=2025-11-05T06:48:28.298635367Z}: timesimp::delta: response processing internals latency=14ms 518µs 49ns local_at_midpoint=2025-11-05T06:48:28.284117317Z delta=4ms 311µs 499ns ago [INFO] [stdout] 2025-11-05T06:48:28.298881Z TRACE timesimp: obtained raw offset from server latency=14.518049ms delta=4ms 311µs 499ns ago [INFO] [stdout] 2025-11-05T06:48:28.298899Z TRACE timesimp: sleeping to spread out requests delay=762.448587ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.304766Z TRACE new{response=Response { client: 2025-11-05T06:48:28.273602088Z, server: 2025-11-05T06:48:28.284726457Z } current=2025-11-05T06:48:28.304587787Z}: timesimp::delta: response processing internals latency=15ms 492µs 849ns local_at_midpoint=2025-11-05T06:48:28.289094937Z delta=4ms 368µs 480ns ago [INFO] [stdout] 2025-11-05T06:48:28.304843Z TRACE timesimp: obtained raw offset from server latency=15.492849ms delta=4ms 368µs 480ns ago [INFO] [stdout] 2025-11-05T06:48:28.304861Z TRACE timesimp: sleeping to spread out requests delay=672.855246ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.305912Z TRACE new{response=Response { client: 2025-11-05T06:48:28.264880438Z, server: 2025-11-05T06:48:33.295628887Z } current=2025-11-05T06:48:28.305775117Z}: timesimp::delta: response processing internals latency=20ms 447µs 339ns local_at_midpoint=2025-11-05T06:48:28.285327777Z delta=5s 10ms 301µs 110ns [INFO] [stdout] 2025-11-05T06:48:28.305974Z TRACE timesimp: obtained raw offset from server latency=20.447339ms delta=5s 10ms 301µs 110ns [INFO] [stdout] 2025-11-05T06:48:28.305987Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 10ms 301µs 110ns [INFO] [stdout] 2025-11-05T06:48:28.305997Z TRACE timesimp: sleeping to spread out requests delay=1.969019767s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.706734Z TRACE new{response=Response { client: 2025-11-05T06:48:28.691278177Z, server: 2025-11-05T06:48:33.698431037Z } current=2025-11-05T06:48:28.706589686Z}: timesimp::delta: response processing internals latency=7ms 655µs 754ns local_at_midpoint=2025-11-05T06:48:28.698933931Z delta=4s 999ms 497µs 106ns [INFO] [stdout] 2025-11-05T06:48:28.706867Z TRACE timesimp: obtained raw offset from server latency=7.655754ms delta=4s 999ms 497µs 106ns [INFO] [stdout] 2025-11-05T06:48:28.706903Z TRACE timesimp: sleeping to spread out requests delay=1.455835004s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:28.862698Z TRACE new{response=Response { client: 2025-11-05T06:48:28.860360262Z, server: 2025-11-05T06:48:28.861482772Z } current=2025-11-05T06:48:28.862553032Z}: timesimp::delta: response processing internals latency=1ms 96µs 385ns local_at_midpoint=2025-11-05T06:48:28.861456647Z delta=26µs 125ns [INFO] [stdout] 2025-11-05T06:48:28.862775Z TRACE timesimp: obtained raw offset from server latency=1.096385ms delta=26µs 125ns [INFO] [stdout] 2025-11-05T06:48:28.862792Z TRACE timesimp: sleeping to spread out requests delay=1.442823984s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:29.002112Z TRACE new{response=Response { client: 2025-11-05T06:48:28.979709149Z, server: 2025-11-05T06:48:28.990841829Z } current=2025-11-05T06:48:29.001964418Z}: timesimp::delta: response processing internals latency=11ms 127µs 634ns local_at_midpoint=2025-11-05T06:48:28.990836783Z delta=5µs 46ns [INFO] [stdout] 2025-11-05T06:48:29.002185Z TRACE timesimp: obtained raw offset from server latency=11.127634ms delta=5µs 46ns [INFO] [stdout] 2025-11-05T06:48:29.002201Z TRACE timesimp: sleeping to spread out requests delay=1.465661428s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:29.085236Z TRACE new{response=Response { client: 2025-11-05T06:48:29.062739837Z, server: 2025-11-05T06:48:29.073909846Z } current=2025-11-05T06:48:29.085081456Z}: timesimp::delta: response processing internals latency=11ms 170µs 809ns local_at_midpoint=2025-11-05T06:48:29.073910646Z delta=800ns ago [INFO] [stdout] 2025-11-05T06:48:29.085329Z TRACE timesimp: obtained raw offset from server latency=11.170809ms delta=800ns ago [INFO] [stdout] 2025-11-05T06:48:29.085347Z TRACE timesimp: sleeping to spread out requests delay=785.731777ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:29.484753Z TRACE new{response=Response { client: 2025-11-05T06:48:29.469602216Z, server: 2025-11-05T06:48:34.476772005Z } current=2025-11-05T06:48:29.484596715Z}: timesimp::delta: response processing internals latency=7ms 497µs 249ns local_at_midpoint=2025-11-05T06:48:29.477099465Z delta=4s 999ms 672µs 540ns [INFO] [stdout] 2025-11-05T06:48:29.484836Z TRACE timesimp: obtained raw offset from server latency=7.497249ms delta=4s 999ms 672µs 540ns [INFO] [stdout] 2025-11-05T06:48:29.484854Z TRACE timesimp: sleeping to spread out requests delay=1.803274012s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:29.605092Z TRACE new{response=Response { client: 2025-11-05T06:48:29.582603513Z, server: 2025-11-05T06:48:24.593776412Z } current=2025-11-05T06:48:29.604946112Z}: timesimp::delta: response processing internals latency=11ms 171µs 299ns local_at_midpoint=2025-11-05T06:48:29.593774812Z delta=4s 999ms 998µs 400ns ago [INFO] [stdout] 2025-11-05T06:48:29.605168Z TRACE timesimp: obtained raw offset from server latency=11.171299ms delta=4s 999ms 998µs 400ns ago [INFO] [stdout] 2025-11-05T06:48:29.605187Z TRACE timesimp: sleeping to spread out requests delay=1.419963206s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:29.896936Z TRACE new{response=Response { client: 2025-11-05T06:48:29.872606315Z, server: 2025-11-05T06:48:29.885595264Z } current=2025-11-05T06:48:29.896782874Z}: timesimp::delta: response processing internals latency=12ms 88µs 279ns local_at_midpoint=2025-11-05T06:48:29.884694594Z delta=900µs 670ns [INFO] [stdout] 2025-11-05T06:48:29.897023Z TRACE timesimp: obtained raw offset from server latency=12.088279ms delta=900µs 670ns [INFO] [stdout] 2025-11-05T06:48:29.897041Z TRACE timesimp: sleeping to spread out requests delay=39.998356ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:29.962029Z TRACE new{response=Response { client: 2025-11-05T06:48:29.938374273Z, server: 2025-11-05T06:48:29.950597663Z } current=2025-11-05T06:48:29.961881072Z}: timesimp::delta: response processing internals latency=11ms 753µs 399ns local_at_midpoint=2025-11-05T06:48:29.950127672Z delta=469µs 991ns [INFO] [stdout] 2025-11-05T06:48:29.962112Z TRACE timesimp: obtained raw offset from server latency=11.753399ms delta=469µs 991ns [INFO] [stdout] 2025-11-05T06:48:29.962131Z TRACE timesimp: sleeping to spread out requests delay=129.899545ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.088891Z TRACE new{response=Response { client: 2025-11-05T06:48:28.262068388Z, server: 2025-11-05T06:48:29.175724334Z } current=2025-11-05T06:48:30.088724149Z}: timesimp::delta: response processing internals latency=913ms 327µs 880ns local_at_midpoint=2025-11-05T06:48:29.175396268Z delta=328µs 66ns [INFO] [stdout] 2025-11-05T06:48:30.089129Z TRACE timesimp: obtained raw offset from server latency=913.32788ms delta=328µs 66ns [INFO] [stdout] 2025-11-05T06:48:30.089221Z DEBUG timesimp: no offset stored, storing initial delta offset=328µs 66ns [INFO] [stdout] 2025-11-05T06:48:30.089264Z TRACE timesimp: sleeping to spread out requests delay=770.885093ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.119124Z TRACE new{response=Response { client: 2025-11-05T06:48:30.097588679Z, server: 2025-11-05T06:48:30.107752499Z } current=2025-11-05T06:48:30.118980488Z}: timesimp::delta: response processing internals latency=10ms 695µs 904ns local_at_midpoint=2025-11-05T06:48:30.108284583Z delta=532µs 84ns ago [INFO] [stdout] 2025-11-05T06:48:30.119201Z TRACE timesimp: obtained raw offset from server latency=10.695904ms delta=532µs 84ns ago [INFO] [stdout] 2025-11-05T06:48:30.119227Z TRACE timesimp: response deltas sorted by latency deltas=[-0.532084, -0.0008, 0.469991, 0.90067, -4.311499] [INFO] [stdout] 2025-11-05T06:48:30.119241Z TRACE timesimp: statistics about response deltas median=0.469991 mean=-0.6947444 variance=4.3727216830953 stddev=2.0911053735035208 [INFO] [stdout] 2025-11-05T06:48:30.119266Z TRACE timesimp: eliminated outliers inliers=[-0.532084, -0.0008, 0.469991, 0.90067] [INFO] [stdout] 2025-11-05T06:48:30.119276Z DEBUG timesimp: storing calculated offset offset=209µs [INFO] [stdout] test client_offset_negative ... ok [INFO] [stdout] 2025-11-05T06:48:30.120376Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:30.120407Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.144926Z TRACE new{response=Response { client: 2025-11-05T06:48:30.121594498Z, server: 2025-11-05T06:48:35.133592448Z } current=2025-11-05T06:48:30.144757318Z}: timesimp::delta: response processing internals latency=11ms 581µs 410ns local_at_midpoint=2025-11-05T06:48:30.133175908Z delta=5s 416µs 540ns [INFO] [stdout] 2025-11-05T06:48:30.145006Z TRACE timesimp: obtained raw offset from server latency=11.58141ms delta=5s 416µs 540ns [INFO] [stdout] 2025-11-05T06:48:30.145023Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 416µs 540ns [INFO] [stdout] 2025-11-05T06:48:30.145033Z TRACE timesimp: sleeping to spread out requests delay=1.47584s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.199858Z TRACE new{response=Response { client: 2025-11-05T06:48:30.169649577Z, server: 2025-11-05T06:48:35.184595946Z } current=2025-11-05T06:48:30.199712256Z}: timesimp::delta: response processing internals latency=15ms 31µs 339ns local_at_midpoint=2025-11-05T06:48:30.184680916Z delta=4s 999ms 915µs 30ns [INFO] [stdout] 2025-11-05T06:48:30.199924Z TRACE timesimp: obtained raw offset from server latency=15.031339ms delta=4s 999ms 915µs 30ns [INFO] [stdout] 2025-11-05T06:48:30.199939Z TRACE timesimp: sleeping to spread out requests delay=251.676027ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.297205Z TRACE new{response=Response { client: 2025-11-05T06:48:30.276719784Z, server: 2025-11-05T06:48:35.286893384Z } current=2025-11-05T06:48:30.297062283Z}: timesimp::delta: response processing internals latency=10ms 171µs 249ns local_at_midpoint=2025-11-05T06:48:30.286891033Z delta=5s 2µs 351ns [INFO] [stdout] 2025-11-05T06:48:30.297283Z TRACE timesimp: obtained raw offset from server latency=10.171249ms delta=5s 2µs 351ns [INFO] [stdout] 2025-11-05T06:48:30.297300Z TRACE timesimp: sleeping to spread out requests delay=63.49468ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.321240Z TRACE new{response=Response { client: 2025-11-05T06:48:30.318871763Z, server: 2025-11-05T06:48:30.319992173Z } current=2025-11-05T06:48:30.321100323Z}: timesimp::delta: response processing internals latency=1ms 114µs 280ns local_at_midpoint=2025-11-05T06:48:30.319986043Z delta=6µs 130ns [INFO] [stdout] 2025-11-05T06:48:30.321311Z TRACE timesimp: obtained raw offset from server latency=1.11428ms delta=6µs 130ns [INFO] [stdout] 2025-11-05T06:48:30.321324Z TRACE timesimp: sleeping to spread out requests delay=1.774747725s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.393274Z TRACE new{response=Response { client: 2025-11-05T06:48:30.371397351Z, server: 2025-11-05T06:48:35.382965281Z } current=2025-11-05T06:48:30.393125771Z}: timesimp::delta: response processing internals latency=10ms 864µs 210ns local_at_midpoint=2025-11-05T06:48:30.382261561Z delta=5s 703µs 720ns [INFO] [stdout] 2025-11-05T06:48:30.393394Z TRACE timesimp: obtained raw offset from server latency=10.86421ms delta=5s 703µs 720ns [INFO] [stdout] 2025-11-05T06:48:30.393431Z TRACE timesimp: sleeping to spread out requests delay=98.164468ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.470662Z TRACE new{response=Response { client: 2025-11-05T06:48:30.454141189Z, server: 2025-11-05T06:48:35.462315789Z } current=2025-11-05T06:48:30.470488779Z}: timesimp::delta: response processing internals latency=8ms 173µs 795ns local_at_midpoint=2025-11-05T06:48:30.462314984Z delta=5s 805ns [INFO] [stdout] 2025-11-05T06:48:30.470733Z TRACE timesimp: obtained raw offset from server latency=8.173795ms delta=5s 805ns [INFO] [stdout] 2025-11-05T06:48:30.470750Z TRACE timesimp: sleeping to spread out requests delay=664.796136ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.495846Z TRACE new{response=Response { client: 2025-11-05T06:48:30.469730689Z, server: 2025-11-05T06:48:30.484577169Z } current=2025-11-05T06:48:30.495706088Z}: timesimp::delta: response processing internals latency=12ms 987µs 699ns local_at_midpoint=2025-11-05T06:48:30.482718388Z delta=1ms 858µs 781ns [INFO] [stdout] 2025-11-05T06:48:30.495909Z TRACE timesimp: obtained raw offset from server latency=12.987699ms delta=1ms 858µs 781ns [INFO] [stdout] 2025-11-05T06:48:30.495925Z TRACE timesimp: sleeping to spread out requests delay=1.630162247s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:30.515737Z TRACE new{response=Response { client: 2025-11-05T06:48:30.492783228Z, server: 2025-11-05T06:48:35.503784318Z } current=2025-11-05T06:48:30.515596317Z}: timesimp::delta: response processing internals latency=11ms 406µs 544ns local_at_midpoint=2025-11-05T06:48:30.504189772Z delta=4s 999ms 594µs 546ns [INFO] [stdout] 2025-11-05T06:48:30.515881Z TRACE timesimp: obtained raw offset from server latency=11.406544ms delta=4s 999ms 594µs 546ns [INFO] [stdout] 2025-11-05T06:48:30.515918Z TRACE timesimp: sleeping to spread out requests delay=1.679982646s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:31.048923Z TRACE new{response=Response { client: 2025-11-05T06:48:31.026450594Z, server: 2025-11-05T06:48:26.037598974Z } current=2025-11-05T06:48:31.048772253Z}: timesimp::delta: response processing internals latency=11ms 160µs 829ns local_at_midpoint=2025-11-05T06:48:31.037611423Z delta=5s 12µs 449ns ago [INFO] [stdout] 2025-11-05T06:48:31.049003Z TRACE timesimp: obtained raw offset from server latency=11.160829ms delta=5s 12µs 449ns ago [INFO] [stdout] 2025-11-05T06:48:31.049021Z TRACE timesimp: sleeping to spread out requests delay=934.628332ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:31.155150Z TRACE new{response=Response { client: 2025-11-05T06:48:31.136606771Z, server: 2025-11-05T06:48:36.145850711Z } current=2025-11-05T06:48:31.15500794Z}: timesimp::delta: response processing internals latency=9ms 200µs 584ns local_at_midpoint=2025-11-05T06:48:31.145807355Z delta=5s 43µs 356ns [INFO] [stdout] 2025-11-05T06:48:31.155214Z TRACE timesimp: obtained raw offset from server latency=9.200584ms delta=5s 43µs 356ns [INFO] [stdout] 2025-11-05T06:48:31.155233Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00424, 4999.497106, 5000.000805, 5000.043356, 4999.91503] [INFO] [stdout] 2025-11-05T06:48:31.155245Z TRACE timesimp: statistics about response deltas median=5000.000805 mean=4999.892107400001 variance=0.050954144705843994 stddev=0.22573024765379582 [INFO] [stdout] 2025-11-05T06:48:31.155266Z TRACE timesimp: eliminated outliers inliers=[5000.00424, 5000.000805, 5000.043356, 4999.91503] [INFO] [stdout] 2025-11-05T06:48:31.155275Z DEBUG timesimp: storing calculated offset offset=4s 999ms 990µs [INFO] [stdout] test mid_jitter ... ok [INFO] [stdout] 2025-11-05T06:48:31.155768Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:31.155837Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:31.307738Z TRACE new{response=Response { client: 2025-11-05T06:48:31.288730467Z, server: 2025-11-05T06:48:36.297890276Z } current=2025-11-05T06:48:31.307587996Z}: timesimp::delta: response processing internals latency=9ms 428µs 764ns local_at_midpoint=2025-11-05T06:48:31.298159231Z delta=4s 999ms 731µs 45ns [INFO] [stdout] 2025-11-05T06:48:31.307821Z TRACE timesimp: obtained raw offset from server latency=9.428764ms delta=4s 999ms 731µs 45ns [INFO] [stdout] 2025-11-05T06:48:31.307838Z TRACE timesimp: sleeping to spread out requests delay=308.423423ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:31.359832Z TRACE new{response=Response { client: 2025-11-05T06:48:31.15703896Z, server: 2025-11-05T06:48:31.258351677Z } current=2025-11-05T06:48:31.359684155Z}: timesimp::delta: response processing internals latency=101ms 322µs 597ns local_at_midpoint=2025-11-05T06:48:31.258361557Z delta=9µs 880ns ago [INFO] [stdout] 2025-11-05T06:48:31.359904Z TRACE timesimp: obtained raw offset from server latency=101.322597ms delta=9µs 880ns ago [INFO] [stdout] 2025-11-05T06:48:31.359918Z DEBUG timesimp: no offset stored, storing initial delta offset=9µs 880ns ago [INFO] [stdout] 2025-11-05T06:48:31.359927Z TRACE timesimp: sleeping to spread out requests delay=1.427192094s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:31.634253Z TRACE new{response=Response { client: 2025-11-05T06:48:31.623602008Z, server: 2025-11-05T06:48:36.628977278Z } current=2025-11-05T06:48:31.634112627Z}: timesimp::delta: response processing internals latency=5ms 255µs 309ns local_at_midpoint=2025-11-05T06:48:31.628857317Z delta=5s 119µs 961ns [INFO] [stdout] 2025-11-05T06:48:31.634323Z TRACE timesimp: obtained raw offset from server latency=5.255309ms delta=5s 119µs 961ns [INFO] [stdout] 2025-11-05T06:48:31.634340Z TRACE timesimp: sleeping to spread out requests delay=857.34025ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:31.646379Z TRACE new{response=Response { client: 2025-11-05T06:48:31.623656768Z, server: 2025-11-05T06:48:36.635085527Z } current=2025-11-05T06:48:31.646239717Z}: timesimp::delta: response processing internals latency=11ms 291µs 474ns local_at_midpoint=2025-11-05T06:48:31.634948242Z delta=5s 137µs 285ns [INFO] [stdout] 2025-11-05T06:48:31.646508Z TRACE timesimp: obtained raw offset from server latency=11.291474ms delta=5s 137µs 285ns [INFO] [stdout] 2025-11-05T06:48:31.646596Z TRACE timesimp: sleeping to spread out requests delay=212.460131ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:31.881653Z TRACE new{response=Response { client: 2025-11-05T06:48:31.860101951Z, server: 2025-11-05T06:48:36.871277141Z } current=2025-11-05T06:48:31.881438091Z}: timesimp::delta: response processing internals latency=10ms 668µs 70ns local_at_midpoint=2025-11-05T06:48:31.870770021Z delta=5s 507µs 120ns [INFO] [stdout] 2025-11-05T06:48:31.881808Z TRACE timesimp: obtained raw offset from server latency=10.66807ms delta=5s 507µs 120ns [INFO] [stdout] 2025-11-05T06:48:31.881884Z TRACE timesimp: sleeping to spread out requests delay=1.949010174s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:32.007221Z TRACE new{response=Response { client: 2025-11-05T06:48:31.984731158Z, server: 2025-11-05T06:48:26.995901928Z } current=2025-11-05T06:48:32.007068607Z}: timesimp::delta: response processing internals latency=11ms 168µs 724ns local_at_midpoint=2025-11-05T06:48:31.995899882Z delta=4s 999ms 997µs 954ns ago [INFO] [stdout] 2025-11-05T06:48:32.007308Z TRACE timesimp: obtained raw offset from server latency=11.168724ms delta=4s 999ms 997µs 954ns ago [INFO] [stdout] 2025-11-05T06:48:32.007327Z TRACE timesimp: sleeping to spread out requests delay=327.452888ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:32.100189Z TRACE new{response=Response { client: 2025-11-05T06:48:32.097747315Z, server: 2025-11-05T06:48:32.098877785Z } current=2025-11-05T06:48:32.100043625Z}: timesimp::delta: response processing internals latency=1ms 148µs 155ns local_at_midpoint=2025-11-05T06:48:32.09889547Z delta=17µs 685ns ago [INFO] [stdout] 2025-11-05T06:48:32.100315Z TRACE timesimp: obtained raw offset from server latency=1.148155ms delta=17µs 685ns ago [INFO] [stdout] 2025-11-05T06:48:32.100360Z TRACE timesimp: sleeping to spread out requests delay=1.585587182s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:32.150114Z TRACE new{response=Response { client: 2025-11-05T06:48:32.127708414Z, server: 2025-11-05T06:48:32.138838394Z } current=2025-11-05T06:48:32.149964113Z}: timesimp::delta: response processing internals latency=11ms 127µs 849ns local_at_midpoint=2025-11-05T06:48:32.138836263Z delta=2µs 131ns [INFO] [stdout] 2025-11-05T06:48:32.150194Z TRACE timesimp: obtained raw offset from server latency=11.127849ms delta=2µs 131ns [INFO] [stdout] 2025-11-05T06:48:32.150211Z TRACE timesimp: sleeping to spread out requests delay=1.828777538s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:32.219910Z TRACE new{response=Response { client: 2025-11-05T06:48:32.197737572Z, server: 2025-11-05T06:48:37.209598502Z } current=2025-11-05T06:48:32.219767611Z}: timesimp::delta: response processing internals latency=11ms 15µs 19ns local_at_midpoint=2025-11-05T06:48:32.208752591Z delta=5s 845µs 911ns [INFO] [stdout] 2025-11-05T06:48:32.219980Z TRACE timesimp: obtained raw offset from server latency=11.015019ms delta=5s 845µs 911ns [INFO] [stdout] 2025-11-05T06:48:32.220000Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002351, 5000.70372, 5000.845911, 4999.594546, 5010.30111] [INFO] [stdout] 2025-11-05T06:48:32.220012Z TRACE timesimp: statistics about response deltas median=5000.845911 mean=5002.2895276 variance=20.319592451982597 stddev=4.5077258625589245 [INFO] [stdout] 2025-11-05T06:48:32.220024Z TRACE timesimp: eliminated outliers inliers=[5000.002351, 5000.70372, 5000.845911, 4999.594546] [INFO] [stdout] 2025-11-05T06:48:32.220037Z DEBUG timesimp: storing calculated offset offset=5s 286µs [INFO] [stdout] test low_jitter ... ok [INFO] [stdout] 2025-11-05T06:48:32.358201Z TRACE new{response=Response { client: 2025-11-05T06:48:32.335731048Z, server: 2025-11-05T06:48:27.346905578Z } current=2025-11-05T06:48:32.358054858Z}: timesimp::delta: response processing internals latency=11ms 161µs 905ns local_at_midpoint=2025-11-05T06:48:32.346892953Z delta=4s 999ms 987µs 375ns ago [INFO] [stdout] 2025-11-05T06:48:32.358280Z TRACE timesimp: obtained raw offset from server latency=11.161905ms delta=4s 999ms 987µs 375ns ago [INFO] [stdout] 2025-11-05T06:48:32.358302Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.00785, -5000.012449, -4999.987375, -4999.997954, -4999.9984] [INFO] [stdout] 2025-11-05T06:48:32.358315Z TRACE timesimp: statistics about response deltas median=-4999.987375 mean=-5000.0008056 variance=9.48729712998585e-5 stddev=0.009740275730176148 [INFO] [stdout] 2025-11-05T06:48:32.358328Z TRACE timesimp: eliminated outliers inliers=[-4999.987375] [INFO] [stdout] 2025-11-05T06:48:32.358337Z DEBUG timesimp: storing calculated offset offset=4s 999ms 987µs ago [INFO] [stdout] test server_offset_negative ... ok [INFO] [stdout] 2025-11-05T06:48:32.505049Z TRACE new{response=Response { client: 2025-11-05T06:48:30.913603597Z, server: 2025-11-05T06:48:31.709582745Z } current=2025-11-05T06:48:32.504911014Z}: timesimp::delta: response processing internals latency=795ms 653µs 708ns local_at_midpoint=2025-11-05T06:48:31.709257305Z delta=325µs 440ns [INFO] [stdout] 2025-11-05T06:48:32.505118Z TRACE timesimp: obtained raw offset from server latency=795.653708ms delta=325µs 440ns [INFO] [stdout] 2025-11-05T06:48:32.505132Z TRACE timesimp: sleeping to spread out requests delay=1.580122863s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:32.511067Z TRACE new{response=Response { client: 2025-11-05T06:48:32.492685304Z, server: 2025-11-05T06:48:37.501826274Z } current=2025-11-05T06:48:32.510974024Z}: timesimp::delta: response processing internals latency=9ms 144µs 360ns local_at_midpoint=2025-11-05T06:48:32.501829664Z delta=4s 999ms 996µs 610ns [INFO] [stdout] 2025-11-05T06:48:32.511122Z TRACE timesimp: obtained raw offset from server latency=9.14436ms delta=4s 999ms 996µs 610ns [INFO] [stdout] 2025-11-05T06:48:32.511394Z TRACE timesimp: response deltas sorted by latency deltas=[5000.160035, 5000.119961, 4999.67254, 4999.99661, 4999.731045] [INFO] [stdout] 2025-11-05T06:48:32.511871Z TRACE timesimp: statistics about response deltas median=4999.67254 mean=4999.9360381999995 variance=0.04978115479373173 stddev=0.22311690835463754 [INFO] [stdout] 2025-11-05T06:48:32.512259Z TRACE timesimp: eliminated outliers inliers=[4999.67254, 4999.731045] [INFO] [stdout] 2025-11-05T06:48:32.512406Z DEBUG timesimp: storing calculated offset offset=4s 999ms 701µs [INFO] [stdout] test high_jitter ... ok [INFO] [stdout] 2025-11-05T06:48:32.991040Z TRACE new{response=Response { client: 2025-11-05T06:48:32.788725646Z, server: 2025-11-05T06:48:32.890576904Z } current=2025-11-05T06:48:32.990884651Z}: timesimp::delta: response processing internals latency=101ms 79µs 502ns local_at_midpoint=2025-11-05T06:48:32.889805148Z delta=771µs 756ns [INFO] [stdout] 2025-11-05T06:48:32.991121Z TRACE timesimp: obtained raw offset from server latency=101.079502ms delta=771µs 756ns [INFO] [stdout] 2025-11-05T06:48:32.991141Z TRACE timesimp: sleeping to spread out requests delay=1.604325415s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:33.694839Z TRACE new{response=Response { client: 2025-11-05T06:48:33.690602552Z, server: 2025-11-05T06:48:33.693578362Z } current=2025-11-05T06:48:33.694700182Z}: timesimp::delta: response processing internals latency=2ms 48µs 815ns local_at_midpoint=2025-11-05T06:48:33.692651367Z delta=926µs 995ns [INFO] [stdout] 2025-11-05T06:48:33.694913Z TRACE timesimp: obtained raw offset from server latency=2.048815ms delta=926µs 995ns [INFO] [stdout] 2025-11-05T06:48:33.694934Z TRACE timesimp: response deltas sorted by latency deltas=[0.026125, 0.00613, 0.000165, -0.017685, 0.926995] [INFO] [stdout] 2025-11-05T06:48:33.694948Z TRACE timesimp: statistics about response deltas median=0.000165 mean=0.18834599999999999 variance=0.170745382605 stddev=0.41321348308713257 [INFO] [stdout] 2025-11-05T06:48:33.694965Z TRACE timesimp: eliminated outliers inliers=[0.026125, 0.00613, 0.000165, -0.017685] [INFO] [stdout] 2025-11-05T06:48:33.694982Z DEBUG timesimp: storing calculated offset offset=3µs [INFO] [stdout] test no_delay ... ok [INFO] [stdout] 2025-11-05T06:48:33.856735Z TRACE new{response=Response { client: 2025-11-05T06:48:33.832620288Z, server: 2025-11-05T06:48:38.843788808Z } current=2025-11-05T06:48:33.856592358Z}: timesimp::delta: response processing internals latency=11ms 986µs 35ns local_at_midpoint=2025-11-05T06:48:33.844606323Z delta=4s 999ms 182µs 485ns [INFO] [stdout] 2025-11-05T06:48:33.856811Z TRACE timesimp: obtained raw offset from server latency=11.986035ms delta=4s 999ms 182µs 485ns [INFO] [stdout] 2025-11-05T06:48:33.856827Z TRACE timesimp: sleeping to spread out requests delay=520.808082ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:34.025721Z TRACE new{response=Response { client: 2025-11-05T06:48:33.981881434Z, server: 2025-11-05T06:48:34.007585674Z } current=2025-11-05T06:48:34.025575223Z}: timesimp::delta: response processing internals latency=21ms 846µs 894ns local_at_midpoint=2025-11-05T06:48:34.003728328Z delta=3ms 857µs 346ns [INFO] [stdout] 2025-11-05T06:48:34.025794Z TRACE timesimp: obtained raw offset from server latency=21.846894ms delta=3ms 857µs 346ns [INFO] [stdout] 2025-11-05T06:48:34.025816Z TRACE timesimp: response deltas sorted by latency deltas=[0.005046, 0.002131, 1.858781, -4.36848, 3.857346] [INFO] [stdout] 2025-11-05T06:48:34.025830Z TRACE timesimp: statistics about response deltas median=1.858781 mean=0.27096480000000006 variance=9.2626807172897 stddev=3.043465248247415 [INFO] [stdout] 2025-11-05T06:48:34.025844Z TRACE timesimp: eliminated outliers inliers=[0.005046, 0.002131, 1.858781, 3.857346] [INFO] [stdout] 2025-11-05T06:48:34.025853Z DEBUG timesimp: storing calculated offset offset=1ms 430µs [INFO] [stdout] test client_offset_positive ... ok [INFO] [stdout] 2025-11-05T06:48:34.402910Z TRACE new{response=Response { client: 2025-11-05T06:48:34.378928964Z, server: 2025-11-05T06:48:39.391604293Z } current=2025-11-05T06:48:34.402759973Z}: timesimp::delta: response processing internals latency=11ms 915µs 504ns local_at_midpoint=2025-11-05T06:48:34.390844468Z delta=5s 759µs 825ns [INFO] [stdout] 2025-11-05T06:48:34.402993Z TRACE timesimp: obtained raw offset from server latency=11.915504ms delta=5s 759µs 825ns [INFO] [stdout] 2025-11-05T06:48:34.403015Z TRACE timesimp: response deltas sorted by latency deltas=[5000.50712, 5000.137285, 5000.41654, 5000.759825, 4999.182485] [INFO] [stdout] 2025-11-05T06:48:34.403041Z TRACE timesimp: statistics about response deltas median=5000.41654 mean=5000.200651 variance=0.3734710310174458 stddev=0.6111227626405727 [INFO] [stdout] 2025-11-05T06:48:34.403057Z TRACE timesimp: eliminated outliers inliers=[5000.50712, 5000.137285, 5000.41654, 5000.759825] [INFO] [stdout] 2025-11-05T06:48:34.403077Z DEBUG timesimp: storing calculated offset offset=5s 455µs [INFO] [stdout] test server_offset_positive ... ok [INFO] [stdout] 2025-11-05T06:48:34.799573Z TRACE new{response=Response { client: 2025-11-05T06:48:34.596769398Z, server: 2025-11-05T06:48:34.698091865Z } current=2025-11-05T06:48:34.799405762Z}: timesimp::delta: response processing internals latency=101ms 318µs 182ns local_at_midpoint=2025-11-05T06:48:34.69808758Z delta=4µs 285ns [INFO] [stdout] 2025-11-05T06:48:34.799649Z TRACE timesimp: obtained raw offset from server latency=101.318182ms delta=4µs 285ns [INFO] [stdout] 2025-11-05T06:48:34.799666Z TRACE timesimp: sleeping to spread out requests delay=1.02922059s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:35.618736Z TRACE new{response=Response { client: 2025-11-05T06:48:34.086603931Z, server: 2025-11-05T06:48:34.851576981Z } current=2025-11-05T06:48:35.61859417Z}: timesimp::delta: response processing internals latency=765ms 995µs 119ns local_at_midpoint=2025-11-05T06:48:34.85259905Z delta=1ms 22µs 69ns ago [INFO] [stdout] 2025-11-05T06:48:35.618804Z TRACE timesimp: obtained raw offset from server latency=765.995119ms delta=1ms 22µs 69ns ago [INFO] [stdout] 2025-11-05T06:48:35.618819Z TRACE timesimp: sleeping to spread out requests delay=684.004455ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:36.037750Z TRACE new{response=Response { client: 2025-11-05T06:48:35.834578844Z, server: 2025-11-05T06:48:35.936596591Z } current=2025-11-05T06:48:36.037599409Z}: timesimp::delta: response processing internals latency=101ms 510µs 282ns local_at_midpoint=2025-11-05T06:48:35.936089126Z delta=507µs 465ns [INFO] [stdout] 2025-11-05T06:48:36.037821Z TRACE timesimp: obtained raw offset from server latency=101.510282ms delta=507µs 465ns [INFO] [stdout] 2025-11-05T06:48:36.037837Z TRACE timesimp: sleeping to spread out requests delay=638.007576ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:36.883745Z TRACE new{response=Response { client: 2025-11-05T06:48:36.677742412Z, server: 2025-11-05T06:48:36.779743729Z } current=2025-11-05T06:48:36.883599746Z}: timesimp::delta: response processing internals latency=102ms 928µs 667ns local_at_midpoint=2025-11-05T06:48:36.780671079Z delta=927µs 350ns ago [INFO] [stdout] 2025-11-05T06:48:36.883876Z TRACE timesimp: obtained raw offset from server latency=102.928667ms delta=927µs 350ns ago [INFO] [stdout] 2025-11-05T06:48:36.883918Z TRACE timesimp: response deltas sorted by latency deltas=[0.771756, 0.004285, -0.00988, 0.507465, -0.92735] [INFO] [stdout] 2025-11-05T06:48:36.883951Z TRACE timesimp: statistics about response deltas median=-0.00988 mean=0.06925520000000003 variance=0.42231015856270004 stddev=0.649853951717384 [INFO] [stdout] 2025-11-05T06:48:36.883983Z TRACE timesimp: eliminated outliers inliers=[0.004285, -0.00988, 0.507465] [INFO] [stdout] 2025-11-05T06:48:36.884014Z DEBUG timesimp: storing calculated offset offset=167µs [INFO] [stdout] test some_delay ... ok [INFO] [stdout] 2025-11-05T06:48:37.722752Z TRACE new{response=Response { client: 2025-11-05T06:48:36.303718002Z, server: 2025-11-05T06:48:37.012708953Z } current=2025-11-05T06:48:37.722602643Z}: timesimp::delta: response processing internals latency=709ms 442µs 320ns local_at_midpoint=2025-11-05T06:48:37.013160322Z delta=451µs 369ns ago [INFO] [stdout] 2025-11-05T06:48:37.722835Z TRACE timesimp: obtained raw offset from server latency=709.44232ms delta=451µs 369ns ago [INFO] [stdout] 2025-11-05T06:48:37.722854Z TRACE timesimp: sleeping to spread out requests delay=299.966227ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.814858Z TRACE new{response=Response { client: 2025-11-05T06:48:38.024398945Z, server: 2025-11-05T06:48:38.919721801Z } current=2025-11-05T06:48:39.814716867Z}: timesimp::delta: response processing internals latency=895ms 158µs 961ns local_at_midpoint=2025-11-05T06:48:38.919557906Z delta=163µs 895ns [INFO] [stdout] 2025-11-05T06:48:39.814934Z TRACE timesimp: obtained raw offset from server latency=895.158961ms delta=163µs 895ns [INFO] [stderr] Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-f298847650626d21) [INFO] [stdout] 2025-11-05T06:48:39.814956Z TRACE timesimp: response deltas sorted by latency deltas=[-0.451369, -1.022069, 0.32544, 0.163895, 0.328066] [INFO] [stdout] 2025-11-05T06:48:39.814968Z TRACE timesimp: statistics about response deltas median=0.32544 mean=-0.13120739999999995 variance=0.3506705427072999 stddev=0.5921744191598451 [INFO] [stdout] 2025-11-05T06:48:39.814982Z TRACE timesimp: eliminated outliers inliers=[0.32544, 0.163895, 0.328066] [INFO] [stdout] 2025-11-05T06:48:39.814990Z DEBUG timesimp: storing calculated offset offset=272µs [INFO] [stdout] test much_delay ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 11.56s [INFO] [stdout] [INFO] [stdout] [INFO] [stdout] running 4 tests [INFO] [stdout] 2025-11-05T06:48:39.819107Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-11-05T06:48:39.819174Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.820597Z TRACE new{response=Response { client: 2025-11-05T06:48:39.820414647Z, server: 2025-11-05T06:48:34.820426727Z } current=2025-11-05T06:48:39.820429837Z}: timesimp::delta: response processing internals latency=7µs 595ns local_at_midpoint=2025-11-05T06:48:39.820422242Z delta=4s 999ms 995µs 515ns ago [INFO] [stdout] 2025-11-05T06:48:39.820656Z TRACE timesimp: obtained raw offset from server latency=7.595µs delta=4s 999ms 995µs 515ns ago [INFO] [stdout] 2025-11-05T06:48:39.820671Z TRACE timesimp: sleeping to spread out requests delay=459.400512ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.821701Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:39.821724Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.821753Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-11-05T06:48:39.821743Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-11-05T06:48:39.821775Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.821789Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.822986Z TRACE new{response=Response { client: 2025-11-05T06:48:39.822892027Z, server: 2025-11-05T06:48:39.822894777Z } current=2025-11-05T06:48:39.822896287Z}: timesimp::delta: response processing internals latency=2µs 130ns local_at_midpoint=2025-11-05T06:48:39.822894157Z delta=620ns [INFO] [stdout] 2025-11-05T06:48:39.823043Z TRACE timesimp: obtained raw offset from server latency=2.13µs delta=620ns [INFO] [stdout] 2025-11-05T06:48:39.823026Z TRACE new{response=Response { client: 2025-11-05T06:48:39.822938027Z, server: 2025-11-05T06:48:39.822940447Z } current=2025-11-05T06:48:39.822941907Z}: timesimp::delta: response processing internals latency=1µs 940ns local_at_midpoint=2025-11-05T06:48:39.822939967Z delta=480ns [INFO] [stdout] 2025-11-05T06:48:39.823063Z DEBUG timesimp: no offset stored, storing initial delta offset=620ns [INFO] [stdout] 2025-11-05T06:48:39.823070Z TRACE timesimp: obtained raw offset from server latency=1.94µs delta=480ns [INFO] [stdout] 2025-11-05T06:48:39.823082Z TRACE timesimp: sleeping to spread out requests delay=1.708035187s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.823091Z TRACE timesimp: sleeping to spread out requests delay=1.623669083s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:39.823204Z TRACE new{response=Response { client: 2025-11-05T06:48:39.823049587Z, server: 2025-11-05T06:48:44.823056237Z } current=2025-11-05T06:48:39.823058907Z}: timesimp::delta: response processing internals latency=4µs 660ns local_at_midpoint=2025-11-05T06:48:39.823054247Z delta=5s 1µs 990ns [INFO] [stdout] 2025-11-05T06:48:39.823271Z TRACE timesimp: obtained raw offset from server latency=4.66µs delta=5s 1µs 990ns [INFO] [stdout] 2025-11-05T06:48:39.823295Z TRACE timesimp: sleeping to spread out requests delay=1.756092068s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:40.283746Z TRACE new{response=Response { client: 2025-11-05T06:48:40.283595664Z, server: 2025-11-05T06:48:35.283603874Z } current=2025-11-05T06:48:40.283606824Z}: timesimp::delta: response processing internals latency=5µs 580ns local_at_midpoint=2025-11-05T06:48:40.283601244Z delta=4s 999ms 997µs 370ns ago [INFO] [stdout] 2025-11-05T06:48:40.283827Z TRACE timesimp: obtained raw offset from server latency=5.58µs delta=4s 999ms 997µs 370ns ago [INFO] [stdout] 2025-11-05T06:48:40.283846Z TRACE timesimp: sleeping to spread out requests delay=215.581204ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:40.500784Z TRACE new{response=Response { client: 2025-11-05T06:48:40.500622248Z, server: 2025-11-05T06:48:35.500631848Z } current=2025-11-05T06:48:40.500635019Z}: timesimp::delta: response processing internals latency=6µs 385ns local_at_midpoint=2025-11-05T06:48:40.500628633Z delta=4s 999ms 996µs 785ns ago [INFO] [stdout] 2025-11-05T06:48:40.500870Z TRACE timesimp: obtained raw offset from server latency=6.385µs delta=4s 999ms 996µs 785ns ago [INFO] [stdout] 2025-11-05T06:48:40.500889Z TRACE timesimp: sleeping to spread out requests delay=1.476013726s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:41.452775Z TRACE new{response=Response { client: 2025-11-05T06:48:41.452621983Z, server: 2025-11-05T06:48:41.452630163Z } current=2025-11-05T06:48:41.452633473Z}: timesimp::delta: response processing internals latency=5µs 745ns local_at_midpoint=2025-11-05T06:48:41.452627728Z delta=2µs 435ns [INFO] [stdout] 2025-11-05T06:48:41.452858Z TRACE timesimp: obtained raw offset from server latency=5.745µs delta=2µs 435ns [INFO] [stdout] 2025-11-05T06:48:41.452877Z TRACE timesimp: sleeping to spread out requests delay=1.048307031s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:41.532868Z TRACE new{response=Response { client: 2025-11-05T06:48:41.532726921Z, server: 2025-11-05T06:48:41.532736111Z } current=2025-11-05T06:48:41.532738781Z}: timesimp::delta: response processing internals latency=5µs 930ns local_at_midpoint=2025-11-05T06:48:41.532732851Z delta=3µs 260ns [INFO] [stdout] 2025-11-05T06:48:41.532933Z TRACE timesimp: obtained raw offset from server latency=5.93µs delta=3µs 260ns [INFO] [stdout] 2025-11-05T06:48:41.532947Z TRACE timesimp: sleeping to spread out requests delay=852.382008ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:41.580905Z TRACE new{response=Response { client: 2025-11-05T06:48:41.580743539Z, server: 2025-11-05T06:48:46.580752559Z } current=2025-11-05T06:48:41.580755639Z}: timesimp::delta: response processing internals latency=6µs 50ns local_at_midpoint=2025-11-05T06:48:41.580749589Z delta=5s 2µs 970ns [INFO] [stdout] 2025-11-05T06:48:41.581069Z TRACE timesimp: obtained raw offset from server latency=6.05µs delta=5s 2µs 970ns [INFO] [stdout] 2025-11-05T06:48:41.581144Z TRACE timesimp: sleeping to spread out requests delay=1.825680313s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:41.978888Z TRACE new{response=Response { client: 2025-11-05T06:48:41.978732889Z, server: 2025-11-05T06:48:36.978741399Z } current=2025-11-05T06:48:41.978744659Z}: timesimp::delta: response processing internals latency=5µs 885ns local_at_midpoint=2025-11-05T06:48:41.978738774Z delta=4s 999ms 997µs 375ns ago [INFO] [stdout] 2025-11-05T06:48:41.978968Z TRACE timesimp: obtained raw offset from server latency=5.885µs delta=4s 999ms 997µs 375ns ago [INFO] [stdout] 2025-11-05T06:48:41.978986Z TRACE timesimp: sleeping to spread out requests delay=919.425555ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:42.386859Z TRACE new{response=Response { client: 2025-11-05T06:48:42.386710878Z, server: 2025-11-05T06:48:42.386720078Z } current=2025-11-05T06:48:42.386722348Z}: timesimp::delta: response processing internals latency=5µs 735ns local_at_midpoint=2025-11-05T06:48:42.386716613Z delta=3µs 465ns [INFO] [stdout] 2025-11-05T06:48:42.386938Z TRACE timesimp: obtained raw offset from server latency=5.735µs delta=3µs 465ns [INFO] [stdout] 2025-11-05T06:48:42.386955Z TRACE timesimp: sleeping to spread out requests delay=1.084921159s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:42.502898Z TRACE new{response=Response { client: 2025-11-05T06:48:42.502743015Z, server: 2025-11-05T06:48:42.502751625Z } current=2025-11-05T06:48:42.502755485Z}: timesimp::delta: response processing internals latency=6µs 235ns local_at_midpoint=2025-11-05T06:48:42.50274925Z delta=2µs 375ns [INFO] [stdout] 2025-11-05T06:48:42.502979Z TRACE timesimp: obtained raw offset from server latency=6.235µs delta=2µs 375ns [INFO] [stdout] 2025-11-05T06:48:42.502998Z TRACE timesimp: sleeping to spread out requests delay=217.921749ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:42.722642Z TRACE new{response=Response { client: 2025-11-05T06:48:42.722470329Z, server: 2025-11-05T06:48:42.722479169Z } current=2025-11-05T06:48:42.722482419Z}: timesimp::delta: response processing internals latency=6µs 45ns local_at_midpoint=2025-11-05T06:48:42.722476374Z delta=2µs 795ns [INFO] [stdout] 2025-11-05T06:48:42.722725Z TRACE timesimp: obtained raw offset from server latency=6.045µs delta=2µs 795ns [INFO] [stdout] 2025-11-05T06:48:42.722745Z TRACE timesimp: sleeping to spread out requests delay=749.296949ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:42.899879Z TRACE new{response=Response { client: 2025-11-05T06:48:42.899723424Z, server: 2025-11-05T06:48:37.899732394Z } current=2025-11-05T06:48:42.899735644Z}: timesimp::delta: response processing internals latency=6µs 110ns local_at_midpoint=2025-11-05T06:48:42.899729534Z delta=4s 999ms 997µs 140ns ago [INFO] [stdout] 2025-11-05T06:48:42.899961Z TRACE timesimp: obtained raw offset from server latency=6.11µs delta=4s 999ms 997µs 140ns ago [INFO] [stdout] 2025-11-05T06:48:42.899988Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99737, -4999.997375, -4999.9971399999995, -4999.996785, -4999.995515] [INFO] [stdout] 2025-11-05T06:48:42.900003Z TRACE timesimp: statistics about response deltas median=-4999.9971399999995 mean=-4999.996837 variance=6.039325001617461e-7 stddev=0.0007771309414517904 [INFO] [stdout] 2025-11-05T06:48:42.900018Z TRACE timesimp: eliminated outliers inliers=[-4999.99737, -4999.997375, -4999.9971399999995, -4999.996785] [INFO] [stdout] 2025-11-05T06:48:42.900033Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago [INFO] [stdout] test negative_starting_offset ... ok [INFO] [stdout] 2025-11-05T06:48:43.408851Z TRACE new{response=Response { client: 2025-11-05T06:48:43.40870664Z, server: 2025-11-05T06:48:48.40871504Z } current=2025-11-05T06:48:43.40871837Z}: timesimp::delta: response processing internals latency=5µs 865ns local_at_midpoint=2025-11-05T06:48:43.408712505Z delta=5s 2µs 535ns [INFO] [stdout] 2025-11-05T06:48:43.408998Z TRACE timesimp: obtained raw offset from server latency=5.865µs delta=5s 2µs 535ns [INFO] [stdout] 2025-11-05T06:48:43.409063Z TRACE timesimp: sleeping to spread out requests delay=175.366171ms max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:43.473800Z TRACE new{response=Response { client: 2025-11-05T06:48:43.473662419Z, server: 2025-11-05T06:48:43.473671768Z } current=2025-11-05T06:48:43.473674359Z}: timesimp::delta: response processing internals latency=5µs 970ns local_at_midpoint=2025-11-05T06:48:43.473668389Z delta=3µs 379ns [INFO] [stdout] 2025-11-05T06:48:43.473800Z TRACE new{response=Response { client: 2025-11-05T06:48:43.473688228Z, server: 2025-11-05T06:48:43.473691739Z } current=2025-11-05T06:48:43.473693499Z}: timesimp::delta: response processing internals latency=2µs 635ns local_at_midpoint=2025-11-05T06:48:43.473690863Z delta=876ns [INFO] [stdout] 2025-11-05T06:48:43.473880Z TRACE timesimp: obtained raw offset from server latency=5.97µs delta=3µs 379ns [INFO] [stdout] 2025-11-05T06:48:43.473891Z TRACE timesimp: obtained raw offset from server latency=2.635µs delta=876ns [INFO] [stdout] 2025-11-05T06:48:43.473896Z TRACE timesimp: sleeping to spread out requests delay=1.806229626s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:43.473910Z TRACE timesimp: response deltas sorted by latency deltas=[0.00048, 0.000876, 0.002435, 0.002795, 0.002375] [INFO] [stdout] 2025-11-05T06:48:43.473922Z TRACE timesimp: statistics about response deltas median=0.002435 mean=0.0017922 variance=1.0799367000000002e-6 stddev=0.00103920002886836 [INFO] [stdout] 2025-11-05T06:48:43.473943Z TRACE timesimp: eliminated outliers inliers=[0.002435, 0.002795, 0.002375] [INFO] [stdout] 2025-11-05T06:48:43.473952Z DEBUG timesimp: storing calculated offset offset=2µs [INFO] [stdout] test zero_offset ... ok [INFO] [stdout] 2025-11-05T06:48:43.585662Z TRACE new{response=Response { client: 2025-11-05T06:48:43.585488625Z, server: 2025-11-05T06:48:48.585497675Z } current=2025-11-05T06:48:43.585500935Z}: timesimp::delta: response processing internals latency=6µs 155ns local_at_midpoint=2025-11-05T06:48:43.58549478Z delta=5s 2µs 895ns [INFO] [stdout] 2025-11-05T06:48:43.585818Z TRACE timesimp: obtained raw offset from server latency=6.155µs delta=5s 2µs 895ns [INFO] [stdout] 2025-11-05T06:48:43.585885Z TRACE timesimp: sleeping to spread out requests delay=1.497702321s max_jitter=2s [INFO] [stdout] 2025-11-05T06:48:45.085866Z TRACE new{response=Response { client: 2025-11-05T06:48:45.085714815Z, server: 2025-11-05T06:48:50.085723375Z } current=2025-11-05T06:48:45.085726835Z}: timesimp::delta: response processing internals latency=6µs 10ns local_at_midpoint=2025-11-05T06:48:45.085720825Z delta=5s 2µs 550ns [INFO] [stdout] 2025-11-05T06:48:45.085948Z TRACE timesimp: obtained raw offset from server latency=6.01µs delta=5s 2µs 550ns [INFO] [stdout] 2025-11-05T06:48:45.085971Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00199, 5000.002535, 5000.00255, 5000.00297, 5000.002895] [INFO] [stdout] 2025-11-05T06:48:45.085985Z TRACE timesimp: statistics about response deltas median=5000.00255 mean=5000.002588 variance=1.5050749993816104e-7 stddev=0.0003879529609864591 [INFO] [stdout] 2025-11-05T06:48:45.086002Z TRACE timesimp: eliminated outliers inliers=[5000.002535, 5000.00255, 5000.002895] [INFO] [stdout] 2025-11-05T06:48:45.086012Z DEBUG timesimp: storing calculated offset offset=5s 2µs [INFO] [stdout] test positive_starting_offset ... ok [INFO] [stdout] 2025-11-05T06:48:45.287743Z TRACE new{response=Response { client: 2025-11-05T06:48:45.28760036Z, server: 2025-11-05T06:48:45.28760978Z } current=2025-11-05T06:48:45.287612Z}: timesimp::delta: response processing internals latency=5µs 820ns local_at_midpoint=2025-11-05T06:48:45.28760618Z delta=3µs 600ns [INFO] [stdout] 2025-11-05T06:48:45.287815Z TRACE timesimp: obtained raw offset from server latency=5.82µs delta=3µs 600ns [INFO] [stdout] 2025-11-05T06:48:45.287834Z TRACE timesimp: response deltas sorted by latency deltas=[0.00062, 0.003465, 0.0036, 0.00326, 0.003379] [INFO] [stdout] 2025-11-05T06:48:45.287847Z TRACE timesimp: statistics about response deltas median=0.0036 mean=0.0028648 variance=1.5901177e-6 stddev=0.001260998691513992 [INFO] [stdout] 2025-11-05T06:48:45.287866Z TRACE timesimp: eliminated outliers inliers=[0.003465, 0.0036, 0.00326, 0.003379] [INFO] [stdout] 2025-11-05T06:48:45.287875Z DEBUG timesimp: storing calculated offset offset=3µs [INFO] [stdout] test null_offset ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.47s [INFO] [stdout] [INFO] [stderr] Doc-tests timesimp [INFO] [stdout] [INFO] [stdout] running 2 tests [INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored [INFO] [stdout] test src/lib.rs - (line 24) - compile ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s [INFO] [stdout] [INFO] [stdout] all doctests ran in 1.76s; merged doctests compilation took 1.73s [INFO] running `Command { std: "docker" "inspect" "465420a2020bb969c1d7760eb941065dc188235b6c9d9779175d30990efb8300", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "465420a2020bb969c1d7760eb941065dc188235b6c9d9779175d30990efb8300", kill_on_drop: false }` [INFO] [stdout] 465420a2020bb969c1d7760eb941065dc188235b6c9d9779175d30990efb8300