[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against master#d98a5da813da67eb189387b8ccfb73cf481275d8+rustflags=-Copt-level=3 for pr-138759
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-2-tc1/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-2-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain d98a5da813da67eb189387b8ccfb73cf481275d8
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+d98a5da813da67eb189387b8ccfb73cf481275d8" "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" "+d98a5da813da67eb189387b8ccfb73cf481275d8" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/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:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+d98a5da813da67eb189387b8ccfb73cf481275d8" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 91689f8661136552bc537039fbda55bca8c77860144ea82128a4b722b3550d91
[INFO] running `Command { std: "docker" "start" "-a" "91689f8661136552bc537039fbda55bca8c77860144ea82128a4b722b3550d91", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "91689f8661136552bc537039fbda55bca8c77860144ea82128a4b722b3550d91", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "91689f8661136552bc537039fbda55bca8c77860144ea82128a4b722b3550d91", kill_on_drop: false }`
[INFO] [stdout] 91689f8661136552bc537039fbda55bca8c77860144ea82128a4b722b3550d91
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/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=forbid -Copt-level=3" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+d98a5da813da67eb189387b8ccfb73cf481275d8" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 1004ccf64345f1d3ec8a9de42ba9ac58f61c21d08630a7ec2cb948b804070790
[INFO] running `Command { std: "docker" "start" "-a" "1004ccf64345f1d3ec8a9de42ba9ac58f61c21d08630a7ec2cb948b804070790", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 44s
[INFO] running `Command { std: "docker" "inspect" "1004ccf64345f1d3ec8a9de42ba9ac58f61c21d08630a7ec2cb948b804070790", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "1004ccf64345f1d3ec8a9de42ba9ac58f61c21d08630a7ec2cb948b804070790", kill_on_drop: false }`
[INFO] [stdout] 1004ccf64345f1d3ec8a9de42ba9ac58f61c21d08630a7ec2cb948b804070790
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/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=forbid -Copt-level=3" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+d98a5da813da67eb189387b8ccfb73cf481275d8" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] d940eb81438e63fdad1b1f58c0464e08008c9f53cf752d541111b6b2cbe5f694
[INFO] running `Command { std: "docker" "start" "-a" "d940eb81438e63fdad1b1f58c0464e08008c9f53cf752d541111b6b2cbe5f694", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling native-tls v0.2.14
[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 zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[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 thiserror v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[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 hyper v1.6.0
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[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-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 5m 22s
[INFO] running `Command { std: "docker" "inspect" "d940eb81438e63fdad1b1f58c0464e08008c9f53cf752d541111b6b2cbe5f694", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "d940eb81438e63fdad1b1f58c0464e08008c9f53cf752d541111b6b2cbe5f694", kill_on_drop: false }`
[INFO] [stdout] d940eb81438e63fdad1b1f58c0464e08008c9f53cf752d541111b6b2cbe5f694
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/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=forbid -Copt-level=3" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+d98a5da813da67eb189387b8ccfb73cf481275d8" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 93387e16b84b09dd2fb1b8a219abec1d6d04ae74808d1c81c4f651dd0312481b
[INFO] running `Command { std: "docker" "start" "-a" "93387e16b84b09dd2fb1b8a219abec1d6d04ae74808d1c81c4f651dd0312481b", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.26s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-5f38e1294478f341)
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-cf188712425e7209)
[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] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-10-14T23:00:57.719237Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:00:57.719259Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.719373Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-10-14T23:00:57.719463Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.719479Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:00:57.719517Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.719234Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-10-14T23:00:57.719530Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.719574Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:00:57.719587Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.719702Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:00:57.719743Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.719846Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:00:57.719883Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.720062Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:00:57.720079Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.723365Z TRACE new{response=Response { client: 2025-10-14T23:00:57.721170637Z, server: 2025-10-14T23:00:57.722249547Z } current=2025-10-14T23:00:57.723327027Z}: timesimp::delta: response processing internals latency=1ms 78µs 195ns local_at_midpoint=2025-10-14T23:00:57.722248832Z delta=715ns
[INFO] [stdout] 2025-10-14T23:00:57.723390Z TRACE timesimp: obtained raw offset from server latency=1.078195ms delta=715ns
[INFO] [stdout] 2025-10-14T23:00:57.723399Z DEBUG timesimp: no offset stored, storing initial delta offset=715ns
[INFO] [stdout] 2025-10-14T23:00:57.723402Z TRACE timesimp: sleeping to spread out requests delay=1.399937743s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.730539Z TRACE new{response=Response { client: 2025-10-14T23:00:57.720332307Z, server: 2025-10-14T23:01:02.725418417Z } current=2025-10-14T23:00:57.730509027Z}: timesimp::delta: response processing internals latency=5ms 88µs 360ns local_at_midpoint=2025-10-14T23:00:57.725420667Z delta=4s 999ms 997µs 750ns
[INFO] [stdout] 2025-10-14T23:00:57.730565Z TRACE timesimp: obtained raw offset from server latency=5.08836ms delta=4s 999ms 997µs 750ns
[INFO] [stdout] 2025-10-14T23:00:57.730574Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 997µs 750ns
[INFO] [stdout] 2025-10-14T23:00:57.730577Z TRACE timesimp: sleeping to spread out requests delay=1.675915316s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.732801Z TRACE new{response=Response { client: 2025-10-14T23:00:57.720610677Z, server: 2025-10-14T23:01:02.726696717Z } current=2025-10-14T23:00:57.732782996Z}: timesimp::delta: response processing internals latency=6ms 86µs 159ns local_at_midpoint=2025-10-14T23:00:57.726696836Z delta=4s 999ms 999µs 881ns
[INFO] [stdout] 2025-10-14T23:00:57.732819Z TRACE timesimp: obtained raw offset from server latency=6.086159ms delta=4s 999ms 999µs 881ns
[INFO] [stdout] 2025-10-14T23:00:57.732825Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 999µs 881ns
[INFO] [stdout] 2025-10-14T23:00:57.732829Z TRACE timesimp: sleeping to spread out requests delay=1.731800781s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.740901Z TRACE new{response=Response { client: 2025-10-14T23:00:57.720681417Z, server: 2025-10-14T23:01:02.730771907Z } current=2025-10-14T23:00:57.740870376Z}: timesimp::delta: response processing internals latency=10ms 94µs 479ns local_at_midpoint=2025-10-14T23:00:57.730775896Z delta=4s 999ms 996µs 11ns
[INFO] [stdout] 2025-10-14T23:00:57.740930Z TRACE timesimp: obtained raw offset from server latency=10.094479ms delta=4s 999ms 996µs 11ns
[INFO] [stdout] 2025-10-14T23:00:57.740938Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 996µs 11ns
[INFO] [stdout] 2025-10-14T23:00:57.740942Z TRACE timesimp: sleeping to spread out requests delay=1.056382549s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.742819Z TRACE new{response=Response { client: 2025-10-14T23:00:57.720605987Z, server: 2025-10-14T23:00:57.731716016Z } current=2025-10-14T23:00:57.742796616Z}: timesimp::delta: response processing internals latency=11ms 95µs 314ns local_at_midpoint=2025-10-14T23:00:57.731701301Z delta=14µs 715ns
[INFO] [stdout] 2025-10-14T23:00:57.742843Z TRACE timesimp: obtained raw offset from server latency=11.095314ms delta=14µs 715ns
[INFO] [stdout] 2025-10-14T23:00:57.742851Z TRACE timesimp: sleeping to spread out requests delay=1.69389885s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.742884Z TRACE new{response=Response { client: 2025-10-14T23:00:57.720617297Z, server: 2025-10-14T23:00:57.731700356Z } current=2025-10-14T23:00:57.742871866Z}: timesimp::delta: response processing internals latency=11ms 127µs 284ns local_at_midpoint=2025-10-14T23:00:57.731744581Z delta=44µs 225ns ago
[INFO] [stdout] 2025-10-14T23:00:57.742895Z TRACE timesimp: obtained raw offset from server latency=11.127284ms delta=44µs 225ns ago
[INFO] [stdout] 2025-10-14T23:00:57.742899Z TRACE timesimp: sleeping to spread out requests delay=156.3631ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.743154Z TRACE new{response=Response { client: 2025-10-14T23:00:57.720983697Z, server: 2025-10-14T23:00:52.732062396Z } current=2025-10-14T23:00:57.743139216Z}: timesimp::delta: response processing internals latency=11ms 77µs 759ns local_at_midpoint=2025-10-14T23:00:57.732061456Z delta=4s 999ms 999µs 60ns ago
[INFO] [stdout] 2025-10-14T23:00:57.743169Z TRACE timesimp: obtained raw offset from server latency=11.077759ms delta=4s 999ms 999µs 60ns ago
[INFO] [stdout] 2025-10-14T23:00:57.743174Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 999µs 60ns ago
[INFO] [stdout] 2025-10-14T23:00:57.743178Z TRACE timesimp: sleeping to spread out requests delay=1.257435174s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:57.927036Z TRACE new{response=Response { client: 2025-10-14T23:00:57.901090463Z, server: 2025-10-14T23:00:57.912188592Z } current=2025-10-14T23:00:57.927008172Z}: timesimp::delta: response processing internals latency=12ms 958µs 854ns local_at_midpoint=2025-10-14T23:00:57.914049317Z delta=1ms 860µs 725ns ago
[INFO] [stdout] 2025-10-14T23:00:57.927069Z TRACE timesimp: obtained raw offset from server latency=12.958854ms delta=1ms 860µs 725ns ago
[INFO] [stdout] 2025-10-14T23:00:57.927077Z TRACE timesimp: sleeping to spread out requests delay=1.589299913s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:58.820583Z TRACE new{response=Response { client: 2025-10-14T23:00:58.798117592Z, server: 2025-10-14T23:01:03.809458842Z } current=2025-10-14T23:00:58.820561322Z}: timesimp::delta: response processing internals latency=11ms 221µs 865ns local_at_midpoint=2025-10-14T23:00:58.809339457Z delta=5s 119µs 385ns
[INFO] [stdout] 2025-10-14T23:00:58.820611Z TRACE timesimp: obtained raw offset from server latency=11.221865ms delta=5s 119µs 385ns
[INFO] [stdout] 2025-10-14T23:00:58.820619Z TRACE timesimp: sleeping to spread out requests delay=1.549679847s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.023242Z TRACE new{response=Response { client: 2025-10-14T23:00:59.001020268Z, server: 2025-10-14T23:00:54.012118727Z } current=2025-10-14T23:00:59.023218997Z}: timesimp::delta: response processing internals latency=11ms 99µs 364ns local_at_midpoint=2025-10-14T23:00:59.012119632Z delta=5s 905ns ago
[INFO] [stdout] 2025-10-14T23:00:59.023276Z TRACE timesimp: obtained raw offset from server latency=11.099364ms delta=5s 905ns ago
[INFO] [stdout] 2025-10-14T23:00:59.023285Z TRACE timesimp: sleeping to spread out requests delay=682.303984ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.126354Z TRACE new{response=Response { client: 2025-10-14T23:00:59.124162845Z, server: 2025-10-14T23:00:59.125246775Z } current=2025-10-14T23:00:59.126333635Z}: timesimp::delta: response processing internals latency=1ms 85µs 395ns local_at_midpoint=2025-10-14T23:00:59.12524824Z delta=1µs 465ns ago
[INFO] [stdout] 2025-10-14T23:00:59.126383Z TRACE timesimp: obtained raw offset from server latency=1.085395ms delta=1µs 465ns ago
[INFO] [stdout] 2025-10-14T23:00:59.126392Z TRACE timesimp: sleeping to spread out requests delay=1.323952721s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.205021Z TRACE new{response=Response { client: 2025-10-14T23:00:57.720847897Z, server: 2025-10-14T23:00:58.46310638Z } current=2025-10-14T23:00:59.204985073Z}: timesimp::delta: response processing internals latency=742ms 68µs 588ns local_at_midpoint=2025-10-14T23:00:58.462916485Z delta=189µs 895ns
[INFO] [stdout] 2025-10-14T23:00:59.205051Z TRACE timesimp: obtained raw offset from server latency=742.068588ms delta=189µs 895ns
[INFO] [stdout] 2025-10-14T23:00:59.205060Z DEBUG timesimp: no offset stored, storing initial delta offset=189µs 895ns
[INFO] [stdout] 2025-10-14T23:00:59.205064Z TRACE timesimp: sleeping to spread out requests delay=1.730090585s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.422309Z TRACE new{response=Response { client: 2025-10-14T23:00:59.408093178Z, server: 2025-10-14T23:01:04.415188128Z } current=2025-10-14T23:00:59.422287028Z}: timesimp::delta: response processing internals latency=7ms 96µs 925ns local_at_midpoint=2025-10-14T23:00:59.415190103Z delta=4s 999ms 998µs 25ns
[INFO] [stdout] 2025-10-14T23:00:59.422342Z TRACE timesimp: obtained raw offset from server latency=7.096925ms delta=4s 999ms 998µs 25ns
[INFO] [stdout] 2025-10-14T23:00:59.422351Z TRACE timesimp: sleeping to spread out requests delay=1.0585373s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.460388Z TRACE new{response=Response { client: 2025-10-14T23:00:59.438096458Z, server: 2025-10-14T23:00:59.449273397Z } current=2025-10-14T23:00:59.460368397Z}: timesimp::delta: response processing internals latency=11ms 135µs 969ns local_at_midpoint=2025-10-14T23:00:59.449232427Z delta=40µs 970ns
[INFO] [stdout] 2025-10-14T23:00:59.460416Z TRACE timesimp: obtained raw offset from server latency=11.135969ms delta=40µs 970ns
[INFO] [stdout] 2025-10-14T23:00:59.460425Z TRACE timesimp: sleeping to spread out requests delay=1.544716707s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.482310Z TRACE new{response=Response { client: 2025-10-14T23:00:59.466095747Z, server: 2025-10-14T23:01:04.474190817Z } current=2025-10-14T23:00:59.482288697Z}: timesimp::delta: response processing internals latency=8ms 96µs 475ns local_at_midpoint=2025-10-14T23:00:59.474192222Z delta=4s 999ms 998µs 595ns
[INFO] [stdout] 2025-10-14T23:00:59.482341Z TRACE timesimp: obtained raw offset from server latency=8.096475ms delta=4s 999ms 998µs 595ns
[INFO] [stdout] 2025-10-14T23:00:59.482349Z TRACE timesimp: sleeping to spread out requests delay=764.210521ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.539299Z TRACE new{response=Response { client: 2025-10-14T23:00:59.518084636Z, server: 2025-10-14T23:00:59.529179946Z } current=2025-10-14T23:00:59.539278165Z}: timesimp::delta: response processing internals latency=10ms 596µs 764ns local_at_midpoint=2025-10-14T23:00:59.5286814Z delta=498µs 546ns
[INFO] [stdout] 2025-10-14T23:00:59.539330Z TRACE timesimp: obtained raw offset from server latency=10.596764ms delta=498µs 546ns
[INFO] [stdout] 2025-10-14T23:00:59.539339Z TRACE timesimp: sleeping to spread out requests delay=1.190445593s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:00:59.728308Z TRACE new{response=Response { client: 2025-10-14T23:00:59.706088392Z, server: 2025-10-14T23:00:54.717184321Z } current=2025-10-14T23:00:59.728286761Z}: timesimp::delta: response processing internals latency=11ms 99µs 184ns local_at_midpoint=2025-10-14T23:00:59.717187576Z delta=5s 3µs 255ns ago
[INFO] [stdout] 2025-10-14T23:00:59.728343Z TRACE timesimp: obtained raw offset from server latency=11.099184ms delta=5s 3µs 255ns ago
[INFO] [stdout] 2025-10-14T23:00:59.728353Z TRACE timesimp: sleeping to spread out requests delay=1.876239964s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:00.284033Z TRACE new{response=Response { client: 2025-10-14T23:01:00.258014009Z, server: 2025-10-14T23:01:05.273009389Z } current=2025-10-14T23:01:00.284012478Z}: timesimp::delta: response processing internals latency=12ms 999µs 234ns local_at_midpoint=2025-10-14T23:01:00.271013243Z delta=5s 1ms 996µs 146ns
[INFO] [stdout] 2025-10-14T23:01:00.284059Z TRACE timesimp: obtained raw offset from server latency=12.999234ms delta=5s 1ms 996µs 146ns
[INFO] [stdout] 2025-10-14T23:01:00.284067Z TRACE timesimp: sleeping to spread out requests delay=1.969780882s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:00.393299Z TRACE new{response=Response { client: 2025-10-14T23:01:00.371088996Z, server: 2025-10-14T23:01:05.382184506Z } current=2025-10-14T23:01:00.393277606Z}: timesimp::delta: response processing internals latency=11ms 94µs 305ns local_at_midpoint=2025-10-14T23:01:00.382183301Z delta=5s 1µs 205ns
[INFO] [stdout] 2025-10-14T23:01:00.393326Z TRACE timesimp: obtained raw offset from server latency=11.094305ms delta=5s 1µs 205ns
[INFO] [stdout] 2025-10-14T23:01:00.393334Z TRACE timesimp: sleeping to spread out requests delay=1.456720566s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:00.464354Z TRACE new{response=Response { client: 2025-10-14T23:01:00.462171964Z, server: 2025-10-14T23:01:00.463254674Z } current=2025-10-14T23:01:00.464334214Z}: timesimp::delta: response processing internals latency=1ms 81µs 125ns local_at_midpoint=2025-10-14T23:01:00.463253089Z delta=1µs 585ns
[INFO] [stdout] 2025-10-14T23:01:00.464380Z TRACE timesimp: obtained raw offset from server latency=1.081125ms delta=1µs 585ns
[INFO] [stdout] 2025-10-14T23:01:00.464388Z TRACE timesimp: sleeping to spread out requests delay=550.145207ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:00.496118Z TRACE new{response=Response { client: 2025-10-14T23:01:00.482092124Z, server: 2025-10-14T23:01:05.491006024Z } current=2025-10-14T23:01:00.496097814Z}: timesimp::delta: response processing internals latency=7ms 2µs 845ns local_at_midpoint=2025-10-14T23:01:00.489094969Z delta=5s 1ms 911µs 55ns
[INFO] [stdout] 2025-10-14T23:01:00.496146Z TRACE timesimp: obtained raw offset from server latency=7.002845ms delta=5s 1ms 911µs 55ns
[INFO] [stdout] 2025-10-14T23:01:00.496153Z TRACE timesimp: sleeping to spread out requests delay=483.983491ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:00.753316Z TRACE new{response=Response { client: 2025-10-14T23:01:00.731105048Z, server: 2025-10-14T23:01:00.742198638Z } current=2025-10-14T23:01:00.753294698Z}: timesimp::delta: response processing internals latency=11ms 94µs 825ns local_at_midpoint=2025-10-14T23:01:00.742199873Z delta=1µs 235ns ago
[INFO] [stdout] 2025-10-14T23:01:00.753343Z TRACE timesimp: obtained raw offset from server latency=11.094825ms delta=1µs 235ns ago
[INFO] [stdout] 2025-10-14T23:01:00.753353Z TRACE timesimp: sleeping to spread out requests delay=1.503076837s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:00.993015Z TRACE new{response=Response { client: 2025-10-14T23:01:00.980723033Z, server: 2025-10-14T23:01:05.986894502Z } current=2025-10-14T23:01:00.992993822Z}: timesimp::delta: response processing internals latency=6ms 135µs 394ns local_at_midpoint=2025-10-14T23:01:00.986858427Z delta=5s 36µs 75ns
[INFO] [stdout] 2025-10-14T23:01:00.993045Z TRACE timesimp: obtained raw offset from server latency=6.135394ms delta=5s 36µs 75ns
[INFO] [stdout] 2025-10-14T23:01:00.993053Z TRACE timesimp: sleeping to spread out requests delay=937.450194ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:01.018202Z TRACE new{response=Response { client: 2025-10-14T23:01:01.016017992Z, server: 2025-10-14T23:01:01.017099732Z } current=2025-10-14T23:01:01.018179912Z}: timesimp::delta: response processing internals latency=1ms 80µs 960ns local_at_midpoint=2025-10-14T23:01:01.017098952Z delta=780ns
[INFO] [stdout] 2025-10-14T23:01:01.018231Z TRACE timesimp: obtained raw offset from server latency=1.08096ms delta=780ns
[INFO] [stdout] 2025-10-14T23:01:01.018239Z TRACE timesimp: sleeping to spread out requests delay=1.748361482s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:01.028303Z TRACE new{response=Response { client: 2025-10-14T23:01:01.006090132Z, server: 2025-10-14T23:01:01.017180582Z } current=2025-10-14T23:01:01.028279561Z}: timesimp::delta: response processing internals latency=11ms 94µs 714ns local_at_midpoint=2025-10-14T23:01:01.017184846Z delta=4µs 264ns ago
[INFO] [stdout] 2025-10-14T23:01:01.028336Z TRACE timesimp: obtained raw offset from server latency=11.094714ms delta=4µs 264ns ago
[INFO] [stdout] 2025-10-14T23:01:01.028345Z TRACE timesimp: sleeping to spread out requests delay=343.24207ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:01.396229Z TRACE new{response=Response { client: 2025-10-14T23:01:01.374004264Z, server: 2025-10-14T23:01:01.385107343Z } current=2025-10-14T23:01:01.396207053Z}: timesimp::delta: response processing internals latency=11ms 101µs 394ns local_at_midpoint=2025-10-14T23:01:01.385105658Z delta=1µs 685ns
[INFO] [stdout] 2025-10-14T23:01:01.396261Z TRACE timesimp: obtained raw offset from server latency=11.101394ms delta=1µs 685ns
[INFO] [stdout] 2025-10-14T23:01:01.396271Z TRACE timesimp: sleeping to spread out requests delay=1.529006066s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:01.661236Z TRACE new{response=Response { client: 2025-10-14T23:01:01.639041488Z, server: 2025-10-14T23:00:56.650116447Z } current=2025-10-14T23:01:01.661214447Z}: timesimp::delta: response processing internals latency=11ms 86µs 479ns local_at_midpoint=2025-10-14T23:01:01.650127967Z delta=5s 11µs 520ns ago
[INFO] [stdout] 2025-10-14T23:01:01.661267Z TRACE timesimp: obtained raw offset from server latency=11.086479ms delta=5s 11µs 520ns ago
[INFO] [stdout] 2025-10-14T23:01:01.661275Z TRACE timesimp: sleeping to spread out requests delay=1.468592214s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:01.874336Z TRACE new{response=Response { client: 2025-10-14T23:01:01.854112293Z, server: 2025-10-14T23:01:06.864209682Z } current=2025-10-14T23:01:01.874313512Z}: timesimp::delta: response processing internals latency=10ms 100µs 609ns local_at_midpoint=2025-10-14T23:01:01.864212902Z delta=4s 999ms 996µs 780ns
[INFO] [stdout] 2025-10-14T23:01:01.874364Z TRACE timesimp: obtained raw offset from server latency=10.100609ms delta=4s 999ms 996µs 780ns
[INFO] [stdout] 2025-10-14T23:01:01.874374Z TRACE timesimp: sleeping to spread out requests delay=1.25645194s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:01.940024Z TRACE new{response=Response { client: 2025-10-14T23:01:01.931544171Z, server: 2025-10-14T23:01:06.934637771Z } current=2025-10-14T23:01:01.940002001Z}: timesimp::delta: response processing internals latency=4ms 228µs 915ns local_at_midpoint=2025-10-14T23:01:01.935773086Z delta=4s 998ms 864µs 685ns
[INFO] [stdout] 2025-10-14T23:01:01.940059Z TRACE timesimp: obtained raw offset from server latency=4.228915ms delta=4s 998ms 864µs 685ns
[INFO] [stdout] 2025-10-14T23:01:01.940070Z TRACE timesimp: response deltas sorted by latency deltas=[4998.8646850000005, 4999.99775, 5000.036075, 5001.911055, 4999.998025]
[INFO] [stdout] 2025-10-14T23:01:01.940076Z TRACE timesimp: statistics about response deltas median=5000.036075 mean=5000.161518 variance=1.2029853523443053 stddev=1.0968068892673428
[INFO] [stdout] 2025-10-14T23:01:01.940081Z TRACE timesimp: eliminated outliers inliers=[4999.99775, 5000.036075, 4999.998025]
[INFO] [stdout] 2025-10-14T23:01:01.940086Z DEBUG timesimp: storing calculated offset offset=5s 10µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-10-14T23:01:01.940367Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:01:01.940385Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:01.963715Z TRACE new{response=Response { client: 2025-10-14T23:01:01.941477591Z, server: 2025-10-14T23:01:06.952579051Z } current=2025-10-14T23:01:01.9636805Z}: timesimp::delta: response processing internals latency=11ms 101µs 454ns local_at_midpoint=2025-10-14T23:01:01.952579045Z delta=5s 6ns
[INFO] [stdout] 2025-10-14T23:01:01.963745Z TRACE timesimp: obtained raw offset from server latency=11.101454ms delta=5s 6ns
[INFO] [stdout] 2025-10-14T23:01:01.963754Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 6ns
[INFO] [stdout] 2025-10-14T23:01:01.963757Z TRACE timesimp: sleeping to spread out requests delay=1.67686094s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:02.277045Z TRACE new{response=Response { client: 2025-10-14T23:01:02.255116973Z, server: 2025-10-14T23:01:07.265287983Z } current=2025-10-14T23:01:02.277025293Z}: timesimp::delta: response processing internals latency=10ms 954µs 160ns local_at_midpoint=2025-10-14T23:01:02.266071133Z delta=4s 999ms 216µs 850ns
[INFO] [stdout] 2025-10-14T23:01:02.277075Z TRACE timesimp: obtained raw offset from server latency=10.95416ms delta=4s 999ms 216µs 850ns
[INFO] [stdout] 2025-10-14T23:01:02.277084Z TRACE timesimp: sleeping to spread out requests delay=546.433591ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:02.284032Z TRACE new{response=Response { client: 2025-10-14T23:01:02.257524673Z, server: 2025-10-14T23:01:02.271005063Z } current=2025-10-14T23:01:02.284007233Z}: timesimp::delta: response processing internals latency=13ms 241µs 280ns local_at_midpoint=2025-10-14T23:01:02.270765953Z delta=239µs 110ns
[INFO] [stdout] 2025-10-14T23:01:02.284061Z TRACE timesimp: obtained raw offset from server latency=13.24128ms delta=239µs 110ns
[INFO] [stdout] 2025-10-14T23:01:02.284070Z TRACE timesimp: response deltas sorted by latency deltas=[0.498546, -0.001235, -0.044225, -1.860725, 0.23911]
[INFO] [stdout] 2025-10-14T23:01:02.284077Z TRACE timesimp: statistics about response deltas median=-0.044225 mean=-0.23370580000000002 variance=0.8742211507307 stddev=0.9349979415649534
[INFO] [stdout] 2025-10-14T23:01:02.284082Z TRACE timesimp: eliminated outliers inliers=[0.498546, -0.001235, -0.044225, 0.23911]
[INFO] [stdout] 2025-10-14T23:01:02.284085Z DEBUG timesimp: storing calculated offset offset=173µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2025-10-14T23:01:02.284313Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:01:02.284329Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:02.364009Z TRACE new{response=Response { client: 2025-10-14T23:01:00.936088364Z, server: 2025-10-14T23:01:01.650134967Z } current=2025-10-14T23:01:02.363988901Z}: timesimp::delta: response processing internals latency=713ms 950µs 268ns local_at_midpoint=2025-10-14T23:01:01.650038632Z delta=96µs 335ns
[INFO] [stdout] 2025-10-14T23:01:02.364035Z TRACE timesimp: obtained raw offset from server latency=713.950268ms delta=96µs 335ns
[INFO] [stdout] 2025-10-14T23:01:02.364044Z TRACE timesimp: sleeping to spread out requests delay=468.857624ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:02.487886Z TRACE new{response=Response { client: 2025-10-14T23:01:02.285421063Z, server: 2025-10-14T23:01:02.38662483Z } current=2025-10-14T23:01:02.487860778Z}: timesimp::delta: response processing internals latency=101ms 219µs 857ns local_at_midpoint=2025-10-14T23:01:02.38664092Z delta=16µs 90ns ago
[INFO] [stdout] 2025-10-14T23:01:02.487926Z TRACE timesimp: obtained raw offset from server latency=101.219857ms delta=16µs 90ns ago
[INFO] [stdout] 2025-10-14T23:01:02.487935Z DEBUG timesimp: no offset stored, storing initial delta offset=16µs 90ns ago
[INFO] [stdout] 2025-10-14T23:01:02.487939Z TRACE timesimp: sleeping to spread out requests delay=1.396642367s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:02.771219Z TRACE new{response=Response { client: 2025-10-14T23:01:02.769040822Z, server: 2025-10-14T23:01:02.770122542Z } current=2025-10-14T23:01:02.771199572Z}: timesimp::delta: response processing internals latency=1ms 79µs 375ns local_at_midpoint=2025-10-14T23:01:02.770120197Z delta=2µs 345ns
[INFO] [stdout] 2025-10-14T23:01:02.771245Z TRACE timesimp: obtained raw offset from server latency=1.079375ms delta=2µs 345ns
[INFO] [stdout] 2025-10-14T23:01:02.771254Z TRACE timesimp: response deltas sorted by latency deltas=[0.000715, 0.002345, 0.00078, 0.001585, -0.001465]
[INFO] [stdout] 2025-10-14T23:01:02.771260Z TRACE timesimp: statistics about response deltas median=0.00078 mean=0.0007919999999999998 variance=2.035195e-6 stddev=0.001426602607596103
[INFO] [stdout] 2025-10-14T23:01:02.771266Z TRACE timesimp: eliminated outliers inliers=[0.000715, 0.00078, 0.001585]
[INFO] [stdout] 2025-10-14T23:01:02.771269Z DEBUG timesimp: storing calculated offset offset=1µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-10-14T23:01:02.838934Z TRACE new{response=Response { client: 2025-10-14T23:01:02.824716531Z, server: 2025-10-14T23:01:07.831821671Z } current=2025-10-14T23:01:02.83891436Z}: timesimp::delta: response processing internals latency=7ms 98µs 914ns local_at_midpoint=2025-10-14T23:01:02.831815445Z delta=5s 6µs 226ns
[INFO] [stdout] 2025-10-14T23:01:02.838976Z TRACE timesimp: obtained raw offset from server latency=7.098914ms delta=5s 6µs 226ns
[INFO] [stdout] 2025-10-14T23:01:02.838986Z TRACE timesimp: response deltas sorted by latency deltas=[4999.999881, 5000.006226, 4999.998595, 4999.21685, 5001.996146]
[INFO] [stdout] 2025-10-14T23:01:02.838993Z TRACE timesimp: statistics about response deltas median=4999.998595 mean=5000.243539600001 variance=1.0753514608097423 stddev=1.03699154326819
[INFO] [stdout] 2025-10-14T23:01:02.838998Z TRACE timesimp: eliminated outliers inliers=[4999.999881, 5000.006226, 4999.998595, 4999.21685]
[INFO] [stdout] 2025-10-14T23:01:02.839001Z DEBUG timesimp: storing calculated offset offset=4s 999ms 805µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-10-14T23:01:02.948313Z TRACE new{response=Response { client: 2025-10-14T23:01:02.926092708Z, server: 2025-10-14T23:01:02.937193398Z } current=2025-10-14T23:01:02.948293248Z}: timesimp::delta: response processing internals latency=11ms 100µs 270ns local_at_midpoint=2025-10-14T23:01:02.937192978Z delta=420ns
[INFO] [stdout] 2025-10-14T23:01:02.948344Z TRACE timesimp: obtained raw offset from server latency=11.10027ms delta=420ns
[INFO] [stdout] 2025-10-14T23:01:02.948352Z TRACE timesimp: response deltas sorted by latency deltas=[-0.004264, 0.014715, 0.00042, 0.001685, 0.04097]
[INFO] [stdout] 2025-10-14T23:01:02.948358Z TRACE timesimp: statistics about response deltas median=0.00042 mean=0.010705200000000002 variance=0.0003358157277 stddev=0.01832527565140563
[INFO] [stdout] 2025-10-14T23:01:02.948363Z TRACE timesimp: eliminated outliers inliers=[-0.004264, 0.014715, 0.00042, 0.001685]
[INFO] [stdout] 2025-10-14T23:01:02.948366Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-10-14T23:01:03.153312Z TRACE new{response=Response { client: 2025-10-14T23:01:03.131095244Z, server: 2025-10-14T23:00:58.142193684Z } current=2025-10-14T23:01:03.153291973Z}: timesimp::delta: response processing internals latency=11ms 98µs 364ns local_at_midpoint=2025-10-14T23:01:03.142193608Z delta=4s 999ms 999µs 924ns ago
[INFO] [stdout] 2025-10-14T23:01:03.153341Z TRACE timesimp: obtained raw offset from server latency=11.098364ms delta=4s 999ms 999µs 924ns ago
[INFO] [stdout] 2025-10-14T23:01:03.153350Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99906, -5000.01152, -4999.999924, -5000.003255, -5000.000905]
[INFO] [stdout] 2025-10-14T23:01:03.153356Z TRACE timesimp: statistics about response deltas median=-4999.999924 mean=-5000.0029328 variance=2.5501811700349078e-5 stddev=0.005049931851059881
[INFO] [stdout] 2025-10-14T23:01:03.153360Z TRACE timesimp: eliminated outliers inliers=[-4999.99906, -4999.999924, -5000.003255, -5000.000905]
[INFO] [stdout] 2025-10-14T23:01:03.153364Z DEBUG timesimp: storing calculated offset offset=5s ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-10-14T23:01:03.154280Z TRACE new{response=Response { client: 2025-10-14T23:01:03.132097934Z, server: 2025-10-14T23:01:08.143185653Z } current=2025-10-14T23:01:03.154268913Z}: timesimp::delta: response processing internals latency=11ms 85µs 489ns local_at_midpoint=2025-10-14T23:01:03.143183423Z delta=5s 2µs 230ns
[INFO] [stdout] 2025-10-14T23:01:03.154298Z TRACE timesimp: obtained raw offset from server latency=11.085489ms delta=5s 2µs 230ns
[INFO] [stdout] 2025-10-14T23:01:03.154305Z TRACE timesimp: response deltas sorted by latency deltas=[4999.996011, 4999.9967799999995, 5000.00223, 5000.001205, 5000.119385]
[INFO] [stdout] 2025-10-14T23:01:03.154310Z TRACE timesimp: statistics about response deltas median=5000.00223 mean=5000.0231222 variance=0.0029030757517067435 stddev=0.05388019814093804
[INFO] [stdout] 2025-10-14T23:01:03.154315Z TRACE timesimp: eliminated outliers inliers=[4999.996011, 4999.9967799999995, 5000.00223, 5000.001205]
[INFO] [stdout] 2025-10-14T23:01:03.154318Z DEBUG timesimp: storing calculated offset offset=4s 999ms 999µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-10-14T23:01:03.664327Z TRACE new{response=Response { client: 2025-10-14T23:01:03.642100782Z, server: 2025-10-14T23:01:08.653202732Z } current=2025-10-14T23:01:03.664303272Z}: timesimp::delta: response processing internals latency=11ms 101µs 245ns local_at_midpoint=2025-10-14T23:01:03.653202027Z delta=5s 705ns
[INFO] [stdout] 2025-10-14T23:01:03.664355Z TRACE timesimp: obtained raw offset from server latency=11.101245ms delta=5s 705ns
[INFO] [stdout] 2025-10-14T23:01:03.664363Z TRACE timesimp: sleeping to spread out requests delay=1.340338816s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:04.087463Z TRACE new{response=Response { client: 2025-10-14T23:01:03.886015076Z, server: 2025-10-14T23:01:03.987214444Z } current=2025-10-14T23:01:04.087441802Z}: timesimp::delta: response processing internals latency=100ms 713µs 363ns local_at_midpoint=2025-10-14T23:01:03.986728439Z delta=486µs 5ns
[INFO] [stdout] 2025-10-14T23:01:04.087489Z TRACE timesimp: obtained raw offset from server latency=100.713363ms delta=486µs 5ns
[INFO] [stdout] 2025-10-14T23:01:04.087498Z TRACE timesimp: sleeping to spread out requests delay=1.643757115s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:04.620057Z TRACE new{response=Response { client: 2025-10-14T23:01:02.83459664Z, server: 2025-10-14T23:01:03.704094071Z } current=2025-10-14T23:01:04.62003563Z}: timesimp::delta: response processing internals latency=892ms 719µs 495ns local_at_midpoint=2025-10-14T23:01:03.727316135Z delta=23ms 222µs 64ns ago
[INFO] [stdout] 2025-10-14T23:01:04.620088Z TRACE timesimp: obtained raw offset from server latency=892.719495ms delta=23ms 222µs 64ns ago
[INFO] [stdout] 2025-10-14T23:01:04.620096Z TRACE timesimp: sleeping to spread out requests delay=73.840332ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:05.028199Z TRACE new{response=Response { client: 2025-10-14T23:01:05.006103491Z, server: 2025-10-14T23:01:10.017080551Z } current=2025-10-14T23:01:05.028177461Z}: timesimp::delta: response processing internals latency=11ms 36µs 985ns local_at_midpoint=2025-10-14T23:01:05.017140476Z delta=4s 999ms 940µs 75ns
[INFO] [stdout] 2025-10-14T23:01:05.028230Z TRACE timesimp: obtained raw offset from server latency=11.036985ms delta=4s 999ms 940µs 75ns
[INFO] [stdout] 2025-10-14T23:01:05.028238Z TRACE timesimp: sleeping to spread out requests delay=1.572547553s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:05.938257Z TRACE new{response=Response { client: 2025-10-14T23:01:05.732099105Z, server: 2025-10-14T23:01:05.837010992Z } current=2025-10-14T23:01:05.93823558Z}: timesimp::delta: response processing internals latency=103ms 68µs 237ns local_at_midpoint=2025-10-14T23:01:05.835167342Z delta=1ms 843µs 650ns
[INFO] [stdout] 2025-10-14T23:01:05.938285Z TRACE timesimp: obtained raw offset from server latency=103.068237ms delta=1ms 843µs 650ns
[INFO] [stdout] 2025-10-14T23:01:05.938293Z TRACE timesimp: sleeping to spread out requests delay=160.807201ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:06.302001Z TRACE new{response=Response { client: 2025-10-14T23:01:06.099553016Z, server: 2025-10-14T23:01:06.200781354Z } current=2025-10-14T23:01:06.301978292Z}: timesimp::delta: response processing internals latency=101ms 212µs 638ns local_at_midpoint=2025-10-14T23:01:06.200765654Z delta=15µs 700ns
[INFO] [stdout] 2025-10-14T23:01:06.302030Z TRACE timesimp: obtained raw offset from server latency=101.212638ms delta=15µs 700ns
[INFO] [stdout] 2025-10-14T23:01:06.302039Z TRACE timesimp: sleeping to spread out requests delay=1.559268486s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:06.429026Z TRACE new{response=Response { client: 2025-10-14T23:01:04.695305298Z, server: 2025-10-14T23:01:05.561096138Z } current=2025-10-14T23:01:06.429002009Z}: timesimp::delta: response processing internals latency=866ms 848µs 355ns local_at_midpoint=2025-10-14T23:01:05.562153653Z delta=1ms 57µs 515ns ago
[INFO] [stdout] 2025-10-14T23:01:06.429057Z TRACE timesimp: obtained raw offset from server latency=866.848355ms delta=1ms 57µs 515ns ago
[INFO] [stdout] 2025-10-14T23:01:06.429065Z TRACE timesimp: sleeping to spread out requests delay=959.769287ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:06.624324Z TRACE new{response=Response { client: 2025-10-14T23:01:06.602108805Z, server: 2025-10-14T23:01:11.613208925Z } current=2025-10-14T23:01:06.624301834Z}: timesimp::delta: response processing internals latency=11ms 96µs 514ns local_at_midpoint=2025-10-14T23:01:06.613205319Z delta=5s 3µs 606ns
[INFO] [stdout] 2025-10-14T23:01:06.624351Z TRACE timesimp: obtained raw offset from server latency=11.096514ms delta=5s 3µs 606ns
[INFO] [stdout] 2025-10-14T23:01:06.624360Z TRACE timesimp: sleeping to spread out requests delay=1.551045934s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.066035Z TRACE new{response=Response { client: 2025-10-14T23:01:07.863091536Z, server: 2025-10-14T23:01:07.964800444Z } current=2025-10-14T23:01:08.066014792Z}: timesimp::delta: response processing internals latency=101ms 461µs 628ns local_at_midpoint=2025-10-14T23:01:07.964553164Z delta=247µs 280ns
[INFO] [stdout] 2025-10-14T23:01:08.066058Z TRACE timesimp: obtained raw offset from server latency=101.461628ms delta=247µs 280ns
[INFO] [stdout] 2025-10-14T23:01:08.066067Z TRACE timesimp: response deltas sorted by latency deltas=[0.486005, 0.0157, -0.01609, 0.24728, 1.84365]
[INFO] [stdout] 2025-10-14T23:01:08.066073Z TRACE timesimp: statistics about response deltas median=-0.01609 mean=0.515309 variance=0.592295532905 stddev=0.7696073888061367
[INFO] [stdout] 2025-10-14T23:01:08.066078Z TRACE timesimp: eliminated outliers inliers=[0.486005, 0.0157, -0.01609, 0.24728]
[INFO] [stdout] 2025-10-14T23:01:08.066081Z DEBUG timesimp: storing calculated offset offset=183µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-10-14T23:01:08.199300Z TRACE new{response=Response { client: 2025-10-14T23:01:08.177092549Z, server: 2025-10-14T23:01:13.188184509Z } current=2025-10-14T23:01:08.199279368Z}: timesimp::delta: response processing internals latency=11ms 93µs 409ns local_at_midpoint=2025-10-14T23:01:08.188185958Z delta=4s 999ms 998µs 551ns
[INFO] [stdout] 2025-10-14T23:01:08.199384Z TRACE timesimp: obtained raw offset from server latency=11.093409ms delta=4s 999ms 998µs 551ns
[INFO] [stdout] 2025-10-14T23:01:08.199416Z TRACE timesimp: response deltas sorted by latency deltas=[4999.940075, 4999.998551, 5000.003606, 5000.000705, 5000.000006]
[INFO] [stdout] 2025-10-14T23:01:08.199438Z TRACE timesimp: statistics about response deltas median=5000.003606 mean=4999.9885886 variance=0.0007388763182930353 stddev=0.0271822794903782
[INFO] [stdout] 2025-10-14T23:01:08.199495Z TRACE timesimp: eliminated outliers inliers=[4999.998551, 5000.003606, 5000.000705, 5000.000006]
[INFO] [stdout] 2025-10-14T23:01:08.199516Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-0c65a2e6eb3445c6)
[INFO] [stdout] 2025-10-14T23:01:08.968034Z TRACE new{response=Response { client: 2025-10-14T23:01:07.390093937Z, server: 2025-10-14T23:01:08.177960179Z } current=2025-10-14T23:01:08.968007341Z}: timesimp::delta: response processing internals latency=788ms 956µs 702ns local_at_midpoint=2025-10-14T23:01:08.179050639Z delta=1ms 90µs 460ns ago
[INFO] [stdout] 2025-10-14T23:01:08.968063Z TRACE timesimp: obtained raw offset from server latency=788.956702ms delta=1ms 90µs 460ns ago
[INFO] [stdout] 2025-10-14T23:01:08.968071Z TRACE timesimp: response deltas sorted by latency deltas=[0.096335, 0.189895, -1.09046, -1.057515, -23.222064]
[INFO] [stdout] 2025-10-14T23:01:08.968077Z TRACE timesimp: statistics about response deltas median=-1.09046 mean=-5.016761799999999 variance=103.94438579011867 stddev=10.19531195158435
[INFO] [stdout] 2025-10-14T23:01:08.968082Z TRACE timesimp: eliminated outliers inliers=[0.096335, 0.189895, -1.09046, -1.057515]
[INFO] [stdout] 2025-10-14T23:01:08.968086Z DEBUG timesimp: storing calculated offset offset=465µs ago
[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.25s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-10-14T23:01:08.970867Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-10-14T23:01:08.970872Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-10-14T23:01:08.970889Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.970891Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.970915Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:01:08.970924Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.970943Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-14T23:01:08.970948Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.972025Z TRACE new{response=Response { client: 2025-10-14T23:01:08.972009591Z, server: 2025-10-14T23:01:13.972009751Z } current=2025-10-14T23:01:08.972009841Z}: timesimp::delta: response processing internals latency=125ns local_at_midpoint=2025-10-14T23:01:08.972009716Z delta=5s 35ns
[INFO] [stdout] 2025-10-14T23:01:08.972027Z TRACE new{response=Response { client: 2025-10-14T23:01:08.972014801Z, server: 2025-10-14T23:01:08.972014911Z } current=2025-10-14T23:01:08.972015001Z}: timesimp::delta: response processing internals latency=100ns local_at_midpoint=2025-10-14T23:01:08.972014901Z delta=10ns
[INFO] [stdout] 2025-10-14T23:01:08.972039Z TRACE timesimp: obtained raw offset from server latency=125ns delta=5s 35ns
[INFO] [stdout] 2025-10-14T23:01:08.972043Z TRACE timesimp: sleeping to spread out requests delay=237.864865ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.972049Z TRACE timesimp: obtained raw offset from server latency=100ns delta=10ns
[INFO] [stdout] 2025-10-14T23:01:08.972055Z DEBUG timesimp: no offset stored, storing initial delta offset=10ns
[INFO] [stdout] 2025-10-14T23:01:08.972058Z TRACE timesimp: sleeping to spread out requests delay=1.821903682s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.972088Z TRACE new{response=Response { client: 2025-10-14T23:01:08.972079671Z, server: 2025-10-14T23:01:08.972079751Z } current=2025-10-14T23:01:08.972079821Z}: timesimp::delta: response processing internals latency=75ns local_at_midpoint=2025-10-14T23:01:08.972079746Z delta=5ns
[INFO] [stdout] 2025-10-14T23:01:08.972094Z TRACE timesimp: obtained raw offset from server latency=75ns delta=5ns
[INFO] [stdout] 2025-10-14T23:01:08.972098Z TRACE timesimp: sleeping to spread out requests delay=107.026883ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:08.972026Z TRACE new{response=Response { client: 2025-10-14T23:01:08.972007941Z, server: 2025-10-14T23:01:03.972008101Z } current=2025-10-14T23:01:08.972008271Z}: timesimp::delta: response processing internals latency=165ns local_at_midpoint=2025-10-14T23:01:08.972008106Z delta=5s 5ns ago
[INFO] [stdout] 2025-10-14T23:01:08.972935Z TRACE timesimp: obtained raw offset from server latency=165ns delta=5s 5ns ago
[INFO] [stdout] 2025-10-14T23:01:08.972943Z TRACE timesimp: sleeping to spread out requests delay=1.22555898s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:09.080320Z TRACE new{response=Response { client: 2025-10-14T23:01:09.080298268Z, server: 2025-10-14T23:01:09.080298458Z } current=2025-10-14T23:01:09.080298618Z}: timesimp::delta: response processing internals latency=175ns local_at_midpoint=2025-10-14T23:01:09.080298443Z delta=15ns
[INFO] [stdout] 2025-10-14T23:01:09.080351Z TRACE timesimp: obtained raw offset from server latency=175ns delta=15ns
[INFO] [stdout] 2025-10-14T23:01:09.080358Z TRACE timesimp: sleeping to spread out requests delay=567.978891ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:09.211394Z TRACE new{response=Response { client: 2025-10-14T23:01:09.211372025Z, server: 2025-10-14T23:01:14.211372295Z } current=2025-10-14T23:01:09.211372465Z}: timesimp::delta: response processing internals latency=220ns local_at_midpoint=2025-10-14T23:01:09.211372245Z delta=5s 50ns
[INFO] [stdout] 2025-10-14T23:01:09.211425Z TRACE timesimp: obtained raw offset from server latency=220ns delta=5s 50ns
[INFO] [stdout] 2025-10-14T23:01:09.211433Z TRACE timesimp: sleeping to spread out requests delay=1.223748293s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:09.649034Z TRACE new{response=Response { client: 2025-10-14T23:01:09.649012765Z, server: 2025-10-14T23:01:09.649013005Z } current=2025-10-14T23:01:09.649013165Z}: timesimp::delta: response processing internals latency=200ns local_at_midpoint=2025-10-14T23:01:09.649012965Z delta=40ns
[INFO] [stdout] 2025-10-14T23:01:09.649066Z TRACE timesimp: obtained raw offset from server latency=200ns delta=40ns
[INFO] [stdout] 2025-10-14T23:01:09.649073Z TRACE timesimp: sleeping to spread out requests delay=611.955014ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:10.201034Z TRACE new{response=Response { client: 2025-10-14T23:01:10.201012983Z, server: 2025-10-14T23:01:05.201013303Z } current=2025-10-14T23:01:10.201013463Z}: timesimp::delta: response processing internals latency=240ns local_at_midpoint=2025-10-14T23:01:10.201013223Z delta=4s 999ms 999µs 920ns ago
[INFO] [stdout] 2025-10-14T23:01:10.201064Z TRACE timesimp: obtained raw offset from server latency=240ns delta=4s 999ms 999µs 920ns ago
[INFO] [stdout] 2025-10-14T23:01:10.201071Z TRACE timesimp: sleeping to spread out requests delay=539.810201ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:10.262838Z TRACE new{response=Response { client: 2025-10-14T23:01:10.262814661Z, server: 2025-10-14T23:01:10.262814951Z } current=2025-10-14T23:01:10.262815131Z}: timesimp::delta: response processing internals latency=235ns local_at_midpoint=2025-10-14T23:01:10.262814896Z delta=55ns
[INFO] [stdout] 2025-10-14T23:01:10.262869Z TRACE timesimp: obtained raw offset from server latency=235ns delta=55ns
[INFO] [stdout] 2025-10-14T23:01:10.262876Z TRACE timesimp: sleeping to spread out requests delay=407.962616ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:10.436125Z TRACE new{response=Response { client: 2025-10-14T23:01:10.436103978Z, server: 2025-10-14T23:01:15.436104198Z } current=2025-10-14T23:01:10.436104427Z}: timesimp::delta: response processing internals latency=224ns local_at_midpoint=2025-10-14T23:01:10.436104202Z delta=4s 999ms 999µs 996ns
[INFO] [stdout] 2025-10-14T23:01:10.436155Z TRACE timesimp: obtained raw offset from server latency=224ns delta=4s 999ms 999µs 996ns
[INFO] [stdout] 2025-10-14T23:01:10.436162Z TRACE timesimp: sleeping to spread out requests delay=447.827847ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:10.671127Z TRACE new{response=Response { client: 2025-10-14T23:01:10.671106432Z, server: 2025-10-14T23:01:10.671106692Z } current=2025-10-14T23:01:10.671106782Z}: timesimp::delta: response processing internals latency=175ns local_at_midpoint=2025-10-14T23:01:10.671106607Z delta=85ns
[INFO] [stdout] 2025-10-14T23:01:10.671158Z TRACE timesimp: obtained raw offset from server latency=175ns delta=85ns
[INFO] [stdout] 2025-10-14T23:01:10.671167Z TRACE timesimp: response deltas sorted by latency deltas=[5e-6, 1.5e-5, 8.5e-5, 4e-5, 5.5e-5]
[INFO] [stdout] 2025-10-14T23:01:10.671173Z TRACE timesimp: statistics about response deltas median=8.5e-5 mean=4e-5 variance=1.0250000000000003e-9 stddev=3.2015621187164245e-5
[INFO] [stdout] 2025-10-14T23:01:10.671179Z TRACE timesimp: eliminated outliers inliers=[8.5e-5, 5.5e-5]
[INFO] [stdout] 2025-10-14T23:01:10.671182Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2025-10-14T23:01:10.742286Z TRACE new{response=Response { client: 2025-10-14T23:01:10.74226502Z, server: 2025-10-14T23:01:05.742265351Z } current=2025-10-14T23:01:10.742265511Z}: timesimp::delta: response processing internals latency=245ns local_at_midpoint=2025-10-14T23:01:10.742265265Z delta=4s 999ms 999µs 914ns ago
[INFO] [stdout] 2025-10-14T23:01:10.742312Z TRACE timesimp: obtained raw offset from server latency=245ns delta=4s 999ms 999µs 914ns ago
[INFO] [stdout] 2025-10-14T23:01:10.742319Z TRACE timesimp: sleeping to spread out requests delay=882.993798ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:10.795107Z TRACE new{response=Response { client: 2025-10-14T23:01:10.795085049Z, server: 2025-10-14T23:01:10.795085359Z } current=2025-10-14T23:01:10.795085519Z}: timesimp::delta: response processing internals latency=235ns local_at_midpoint=2025-10-14T23:01:10.795085284Z delta=75ns
[INFO] [stdout] 2025-10-14T23:01:10.795137Z TRACE timesimp: obtained raw offset from server latency=235ns delta=75ns
[INFO] [stdout] 2025-10-14T23:01:10.795145Z TRACE timesimp: sleeping to spread out requests delay=1.100622238s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:10.885110Z TRACE new{response=Response { client: 2025-10-14T23:01:10.885089957Z, server: 2025-10-14T23:01:15.885090217Z } current=2025-10-14T23:01:10.885090367Z}: timesimp::delta: response processing internals latency=205ns local_at_midpoint=2025-10-14T23:01:10.885090162Z delta=5s 55ns
[INFO] [stdout] 2025-10-14T23:01:10.885140Z TRACE timesimp: obtained raw offset from server latency=205ns delta=5s 55ns
[INFO] [stdout] 2025-10-14T23:01:10.885148Z TRACE timesimp: sleeping to spread out requests delay=570.294304ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:11.456831Z TRACE new{response=Response { client: 2025-10-14T23:01:11.456809744Z, server: 2025-10-14T23:01:16.456809964Z } current=2025-10-14T23:01:11.456810114Z}: timesimp::delta: response processing internals latency=185ns local_at_midpoint=2025-10-14T23:01:11.456809929Z delta=5s 35ns
[INFO] [stdout] 2025-10-14T23:01:11.456862Z TRACE timesimp: obtained raw offset from server latency=185ns delta=5s 35ns
[INFO] [stdout] 2025-10-14T23:01:11.456871Z TRACE timesimp: response deltas sorted by latency deltas=[5000.000035, 5000.000035, 5000.000055, 5000.00005, 4999.9999960000005]
[INFO] [stdout] 2025-10-14T23:01:11.456878Z TRACE timesimp: statistics about response deltas median=5000.000055 mean=5000.0000342 variance=5.356999928157138e-10 stddev=2.3145193730356067e-5
[INFO] [stdout] 2025-10-14T23:01:11.456883Z TRACE timesimp: eliminated outliers inliers=[5000.000035, 5000.000035, 5000.000055, 5000.00005]
[INFO] [stdout] 2025-10-14T23:01:11.456887Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2025-10-14T23:01:11.626495Z TRACE new{response=Response { client: 2025-10-14T23:01:11.62647478Z, server: 2025-10-14T23:01:06.6264751Z } current=2025-10-14T23:01:11.62647525Z}: timesimp::delta: response processing internals latency=235ns local_at_midpoint=2025-10-14T23:01:11.626475015Z delta=4s 999ms 999µs 915ns ago
[INFO] [stdout] 2025-10-14T23:01:11.626523Z TRACE timesimp: obtained raw offset from server latency=235ns delta=4s 999ms 999µs 915ns ago
[INFO] [stdout] 2025-10-14T23:01:11.626531Z TRACE timesimp: sleeping to spread out requests delay=214.129979ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:11.841859Z TRACE new{response=Response { client: 2025-10-14T23:01:11.841837695Z, server: 2025-10-14T23:01:06.841837975Z } current=2025-10-14T23:01:11.841838166Z}: timesimp::delta: response processing internals latency=235ns local_at_midpoint=2025-10-14T23:01:11.84183793Z delta=4s 999ms 999µs 955ns ago
[INFO] [stdout] 2025-10-14T23:01:11.841887Z TRACE timesimp: obtained raw offset from server latency=235ns delta=4s 999ms 999µs 955ns ago
[INFO] [stdout] 2025-10-14T23:01:11.841896Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.000005, -4999.999915, -4999.999955, -4999.99992, -4999.999914]
[INFO] [stdout] 2025-10-14T23:01:11.841903Z TRACE timesimp: statistics about response deltas median=-4999.999955 mean=-4999.999941800001 variance=1.5336999910504794e-9 stddev=3.9162481931696816e-5
[INFO] [stdout] 2025-10-14T23:01:11.841909Z TRACE timesimp: eliminated outliers inliers=[-4999.999955, -4999.99992]
[INFO] [stdout] 2025-10-14T23:01:11.841913Z DEBUG timesimp: storing calculated offset offset=4s 999ms 999µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2025-10-14T23:01:11.897028Z TRACE new{response=Response { client: 2025-10-14T23:01:11.897007394Z, server: 2025-10-14T23:01:11.897007614Z } current=2025-10-14T23:01:11.897007764Z}: timesimp::delta: response processing internals latency=185ns local_at_midpoint=2025-10-14T23:01:11.897007579Z delta=35ns
[INFO] [stdout] 2025-10-14T23:01:11.897125Z TRACE timesimp: obtained raw offset from server latency=185ns delta=35ns
[INFO] [stdout] 2025-10-14T23:01:11.897150Z TRACE timesimp: sleeping to spread out requests delay=1.888077348s max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:13.786855Z TRACE new{response=Response { client: 2025-10-14T23:01:13.786834061Z, server: 2025-10-14T23:01:13.786834261Z } current=2025-10-14T23:01:13.786834411Z}: timesimp::delta: response processing internals latency=175ns local_at_midpoint=2025-10-14T23:01:13.786834236Z delta=25ns
[INFO] [stdout] 2025-10-14T23:01:13.786947Z TRACE timesimp: obtained raw offset from server latency=175ns delta=25ns
[INFO] [stdout] 2025-10-14T23:01:13.786992Z TRACE timesimp: sleeping to spread out requests delay=627.976582ms max_jitter=2s
[INFO] [stdout] 2025-10-14T23:01:14.416413Z TRACE new{response=Response { client: 2025-10-14T23:01:14.416390757Z, server: 2025-10-14T23:01:14.416391167Z } current=2025-10-14T23:01:14.416391367Z}: timesimp::delta: response processing internals latency=305ns local_at_midpoint=2025-10-14T23:01:14.416391062Z delta=105ns
[INFO] [stdout] 2025-10-14T23:01:14.416437Z TRACE timesimp: obtained raw offset from server latency=305ns delta=105ns
[INFO] [stdout] 2025-10-14T23:01:14.416446Z TRACE timesimp: response deltas sorted by latency deltas=[1e-5, 2.5e-5, 3.5e-5, 7.5e-5, 0.000105]
[INFO] [stdout] 2025-10-14T23:01:14.416453Z TRACE timesimp: statistics about response deltas median=3.5e-5 mean=5e-5 variance=1.525e-9 stddev=3.905124837953327e-5
[INFO] [stdout] 2025-10-14T23:01:14.416458Z TRACE timesimp: eliminated outliers inliers=[1e-5, 2.5e-5, 3.5e-5]
[INFO] [stdout] 2025-10-14T23:01:14.416462Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stderr]    Doc-tests timesimp
[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.45s
[INFO] [stdout] 
[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] running `Command { std: "docker" "inspect" "93387e16b84b09dd2fb1b8a219abec1d6d04ae74808d1c81c4f651dd0312481b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "93387e16b84b09dd2fb1b8a219abec1d6d04ae74808d1c81c4f651dd0312481b", kill_on_drop: false }`
[INFO] [stdout] 93387e16b84b09dd2fb1b8a219abec1d6d04ae74808d1c81c4f651dd0312481b