[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against beta-2026-04-21 for beta-1.96-1
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-6-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-6-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain beta-2026-04-21
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2026-04-21" "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-2026-04-21" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2026-04-21" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] ea383c41c88cb7edf61bcdf7eeb6c8e1cd080ebe6b75dea7b4815407e17388c3
[INFO] running `Command { std: "docker" "start" "-a" "ea383c41c88cb7edf61bcdf7eeb6c8e1cd080ebe6b75dea7b4815407e17388c3", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "ea383c41c88cb7edf61bcdf7eeb6c8e1cd080ebe6b75dea7b4815407e17388c3", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "ea383c41c88cb7edf61bcdf7eeb6c8e1cd080ebe6b75dea7b4815407e17388c3", kill_on_drop: false }`
[INFO] [stdout] ea383c41c88cb7edf61bcdf7eeb6c8e1cd080ebe6b75dea7b4815407e17388c3
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2026-04-21" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] f95dc688cfa316a1599bb21a2860fb08f625a81b7a175589d4237321cd5a73d5
[INFO] running `Command { std: "docker" "start" "-a" "f95dc688cfa316a1599bb21a2860fb08f625a81b7a175589d4237321cd5a73d5", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[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 tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror-impl 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 8.56s
[INFO] running `Command { std: "docker" "inspect" "f95dc688cfa316a1599bb21a2860fb08f625a81b7a175589d4237321cd5a73d5", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "f95dc688cfa316a1599bb21a2860fb08f625a81b7a175589d4237321cd5a73d5", kill_on_drop: false }`
[INFO] [stdout] f95dc688cfa316a1599bb21a2860fb08f625a81b7a175589d4237321cd5a73d5
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2026-04-21" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 4e023f14d2a6b602eb79e545b9b9336e5c8be5ba02ed17449cf6082aa0f25caf
[INFO] running `Command { std: "docker" "start" "-a" "4e023f14d2a6b602eb79e545b9b9336e5c8be5ba02ed17449cf6082aa0f25caf", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling futures-core v0.3.31
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling try-lock v0.2.5
[INFO] [stderr]    Compiling atomic-waker v1.1.2
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling ryu v1.0.20
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling mime v0.3.17
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling synstructure v0.13.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 zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[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 26.10s
[INFO] running `Command { std: "docker" "inspect" "4e023f14d2a6b602eb79e545b9b9336e5c8be5ba02ed17449cf6082aa0f25caf", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "4e023f14d2a6b602eb79e545b9b9336e5c8be5ba02ed17449cf6082aa0f25caf", kill_on_drop: false }`
[INFO] [stdout] 4e023f14d2a6b602eb79e545b9b9336e5c8be5ba02ed17449cf6082aa0f25caf
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2026-04-21" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 645150f539a3fa4c3d8d0bed6ea423f923bfc67e82b4794cb6d155a20b2eb11c
[INFO] running `Command { std: "docker" "start" "-a" "645150f539a3fa4c3d8d0bed6ea423f923bfc67e82b4794cb6d155a20b2eb11c", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.12s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-82f64dda2acb0230)
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[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::client_equal_server ... 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-513d9ee63cc91ba0)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2026-04-24T22:13:25.672497Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672536Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672452Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-04-24T22:13:25.672561Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672566Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672469Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672608Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672472Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-04-24T22:13:25.672685Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672579Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672784Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672801Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672820Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672827Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672878Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672928Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.672467Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672973Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:25.672989Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.673001Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.676404Z TRACE new{response=Response { client: 2026-04-24T22:13:25.673975393Z, server: 2026-04-24T22:13:25.675118562Z } current=2026-04-24T22:13:25.676246862Z}: timesimp::delta: response processing internals latency=1ms 135µs 734ns local_at_midpoint=2026-04-24T22:13:25.675111127Z delta=7µs 435ns
[INFO] [stdout] 2026-04-24T22:13:25.676481Z TRACE timesimp: obtained raw offset from server latency=1.135734ms delta=7µs 435ns
[INFO] [stdout] 2026-04-24T22:13:25.676507Z DEBUG timesimp: no offset stored, storing initial delta offset=7µs 435ns
[INFO] [stdout] 2026-04-24T22:13:25.676525Z TRACE timesimp: sleeping to spread out requests delay=1.334337632s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.688346Z TRACE new{response=Response { client: 2026-04-24T22:13:25.673827973Z, server: 2026-04-24T22:13:30.680979292Z } current=2026-04-24T22:13:25.688137841Z}: timesimp::delta: response processing internals latency=7ms 154µs 934ns local_at_midpoint=2026-04-24T22:13:25.680982907Z delta=4s 999ms 996µs 385ns
[INFO] [stdout] 2026-04-24T22:13:25.688441Z TRACE timesimp: obtained raw offset from server latency=7.154934ms delta=4s 999ms 996µs 385ns
[INFO] [stdout] 2026-04-24T22:13:25.688465Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 996µs 385ns
[INFO] [stdout] 2026-04-24T22:13:25.688481Z TRACE timesimp: sleeping to spread out requests delay=999.33103ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.694290Z TRACE new{response=Response { client: 2026-04-24T22:13:25.673842793Z, server: 2026-04-24T22:13:30.683953592Z } current=2026-04-24T22:13:25.694131611Z}: timesimp::delta: response processing internals latency=10ms 144µs 409ns local_at_midpoint=2026-04-24T22:13:25.683987202Z delta=4s 999ms 966µs 390ns
[INFO] [stdout] 2026-04-24T22:13:25.694368Z TRACE timesimp: obtained raw offset from server latency=10.144409ms delta=4s 999ms 966µs 390ns
[INFO] [stdout] 2026-04-24T22:13:25.694391Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 966µs 390ns
[INFO] [stdout] 2026-04-24T22:13:25.694407Z TRACE timesimp: sleeping to spread out requests delay=1.978943238s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.694659Z TRACE new{response=Response { client: 2026-04-24T22:13:25.674113153Z, server: 2026-04-24T22:13:30.684364592Z } current=2026-04-24T22:13:25.694543281Z}: timesimp::delta: response processing internals latency=10ms 215µs 64ns local_at_midpoint=2026-04-24T22:13:25.684328217Z delta=5s 36µs 375ns
[INFO] [stdout] 2026-04-24T22:13:25.694731Z TRACE timesimp: obtained raw offset from server latency=10.215064ms delta=5s 36µs 375ns
[INFO] [stdout] 2026-04-24T22:13:25.694751Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 36µs 375ns
[INFO] [stdout] 2026-04-24T22:13:25.694772Z TRACE timesimp: sleeping to spread out requests delay=1.235329997s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.696513Z TRACE new{response=Response { client: 2026-04-24T22:13:25.673851913Z, server: 2026-04-24T22:13:25.685048332Z } current=2026-04-24T22:13:25.696322101Z}: timesimp::delta: response processing internals latency=11ms 235µs 94ns local_at_midpoint=2026-04-24T22:13:25.685087007Z delta=38µs 675ns ago
[INFO] [stdout] 2026-04-24T22:13:25.696586Z TRACE timesimp: obtained raw offset from server latency=11.235094ms delta=38µs 675ns ago
[INFO] [stdout] 2026-04-24T22:13:25.696612Z TRACE timesimp: sleeping to spread out requests delay=32.285761ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.696870Z TRACE new{response=Response { client: 2026-04-24T22:13:25.674111882Z, server: 2026-04-24T22:13:30.685237452Z } current=2026-04-24T22:13:25.696741471Z}: timesimp::delta: response processing internals latency=11ms 314µs 794ns local_at_midpoint=2026-04-24T22:13:25.685426676Z delta=4s 999ms 810µs 776ns
[INFO] [stdout] 2026-04-24T22:13:25.697055Z TRACE timesimp: obtained raw offset from server latency=11.314794ms delta=4s 999ms 810µs 776ns
[INFO] [stdout] 2026-04-24T22:13:25.697106Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 810µs 776ns
[INFO] [stdout] 2026-04-24T22:13:25.697147Z TRACE timesimp: sleeping to spread out requests delay=806.172374ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.697150Z TRACE new{response=Response { client: 2026-04-24T22:13:25.673968182Z, server: 2026-04-24T22:13:25.685110242Z } current=2026-04-24T22:13:25.696806151Z}: timesimp::delta: response processing internals latency=11ms 418µs 984ns local_at_midpoint=2026-04-24T22:13:25.685387166Z delta=276µs 924ns ago
[INFO] [stdout] 2026-04-24T22:13:25.697150Z TRACE new{response=Response { client: 2026-04-24T22:13:25.674176882Z, server: 2026-04-24T22:13:20.685275122Z } current=2026-04-24T22:13:25.696942461Z}: timesimp::delta: response processing internals latency=11ms 382µs 789ns local_at_midpoint=2026-04-24T22:13:25.685559671Z delta=5s 284µs 549ns ago
[INFO] [stdout] 2026-04-24T22:13:25.697286Z TRACE timesimp: obtained raw offset from server latency=11.418984ms delta=276µs 924ns ago
[INFO] [stdout] 2026-04-24T22:13:25.697301Z TRACE timesimp: obtained raw offset from server latency=11.382789ms delta=5s 284µs 549ns ago
[INFO] [stdout] 2026-04-24T22:13:25.697311Z TRACE timesimp: sleeping to spread out requests delay=11.805683ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.697322Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 284µs 549ns ago
[INFO] [stdout] 2026-04-24T22:13:25.697482Z TRACE timesimp: sleeping to spread out requests delay=243.207139ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.732267Z TRACE new{response=Response { client: 2026-04-24T22:13:25.70966227Z, server: 2026-04-24T22:13:25.720957289Z } current=2026-04-24T22:13:25.732095688Z}: timesimp::delta: response processing internals latency=11ms 216µs 709ns local_at_midpoint=2026-04-24T22:13:25.720878979Z delta=78µs 310ns
[INFO] [stdout] 2026-04-24T22:13:25.732351Z TRACE timesimp: obtained raw offset from server latency=11.216709ms delta=78µs 310ns
[INFO] [stdout] 2026-04-24T22:13:25.732371Z TRACE timesimp: sleeping to spread out requests delay=1.515155156s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.752477Z TRACE new{response=Response { client: 2026-04-24T22:13:25.729806958Z, server: 2026-04-24T22:13:25.741085687Z } current=2026-04-24T22:13:25.752306486Z}: timesimp::delta: response processing internals latency=11ms 249µs 764ns local_at_midpoint=2026-04-24T22:13:25.741056722Z delta=28µs 965ns
[INFO] [stdout] 2026-04-24T22:13:25.752563Z TRACE timesimp: obtained raw offset from server latency=11.249764ms delta=28µs 965ns
[INFO] [stdout] 2026-04-24T22:13:25.752585Z TRACE timesimp: sleeping to spread out requests delay=20.912071ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.797379Z TRACE new{response=Response { client: 2026-04-24T22:13:25.774818184Z, server: 2026-04-24T22:13:25.786026784Z } current=2026-04-24T22:13:25.797215083Z}: timesimp::delta: response processing internals latency=11ms 198µs 449ns local_at_midpoint=2026-04-24T22:13:25.786016633Z delta=10µs 151ns
[INFO] [stdout] 2026-04-24T22:13:25.797467Z TRACE timesimp: obtained raw offset from server latency=11.198449ms delta=10µs 151ns
[INFO] [stdout] 2026-04-24T22:13:25.797489Z TRACE timesimp: sleeping to spread out requests delay=468.262106ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.877062Z TRACE new{response=Response { client: 2026-04-24T22:13:25.674104762Z, server: 2026-04-24T22:13:25.775408714Z } current=2026-04-24T22:13:25.876815466Z}: timesimp::delta: response processing internals latency=101ms 355µs 352ns local_at_midpoint=2026-04-24T22:13:25.775460114Z delta=51µs 400ns ago
[INFO] [stdout] 2026-04-24T22:13:25.877152Z TRACE timesimp: obtained raw offset from server latency=101.355352ms delta=51µs 400ns ago
[INFO] [stdout] 2026-04-24T22:13:25.877175Z DEBUG timesimp: no offset stored, storing initial delta offset=51µs 400ns ago
[INFO] [stdout] 2026-04-24T22:13:25.877189Z TRACE timesimp: sleeping to spread out requests delay=1.196244108s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:25.963710Z TRACE new{response=Response { client: 2026-04-24T22:13:25.941156941Z, server: 2026-04-24T22:13:20.95235938Z } current=2026-04-24T22:13:25.963533039Z}: timesimp::delta: response processing internals latency=11ms 188µs 49ns local_at_midpoint=2026-04-24T22:13:25.95234499Z delta=4s 999ms 985µs 610ns ago
[INFO] [stdout] 2026-04-24T22:13:25.963813Z TRACE timesimp: obtained raw offset from server latency=11.188049ms delta=4s 999ms 985µs 610ns ago
[INFO] [stdout] 2026-04-24T22:13:25.963852Z TRACE timesimp: sleeping to spread out requests delay=1.353440587s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:26.293697Z TRACE new{response=Response { client: 2026-04-24T22:13:26.271159544Z, server: 2026-04-24T22:13:26.282349803Z } current=2026-04-24T22:13:26.293535012Z}: timesimp::delta: response processing internals latency=11ms 187µs 734ns local_at_midpoint=2026-04-24T22:13:26.282347278Z delta=2µs 525ns
[INFO] [stdout] 2026-04-24T22:13:26.293785Z TRACE timesimp: obtained raw offset from server latency=11.187734ms delta=2µs 525ns
[INFO] [stdout] 2026-04-24T22:13:26.293805Z TRACE timesimp: sleeping to spread out requests delay=1.889179047s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:26.526666Z TRACE new{response=Response { client: 2026-04-24T22:13:26.504143885Z, server: 2026-04-24T22:13:31.515390124Z } current=2026-04-24T22:13:26.526530793Z}: timesimp::delta: response processing internals latency=11ms 193µs 454ns local_at_midpoint=2026-04-24T22:13:26.515337339Z delta=5s 52µs 785ns
[INFO] [stdout] 2026-04-24T22:13:26.526725Z TRACE timesimp: obtained raw offset from server latency=11.193454ms delta=5s 52µs 785ns
[INFO] [stdout] 2026-04-24T22:13:26.526739Z TRACE timesimp: sleeping to spread out requests delay=1.372488331s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:26.705282Z TRACE new{response=Response { client: 2026-04-24T22:13:26.688762729Z, server: 2026-04-24T22:13:31.696952718Z } current=2026-04-24T22:13:26.705114248Z}: timesimp::delta: response processing internals latency=8ms 175µs 759ns local_at_midpoint=2026-04-24T22:13:26.696938488Z delta=5s 14µs 230ns
[INFO] [stdout] 2026-04-24T22:13:26.705373Z TRACE timesimp: obtained raw offset from server latency=8.175759ms delta=5s 14µs 230ns
[INFO] [stdout] 2026-04-24T22:13:26.705395Z TRACE timesimp: sleeping to spread out requests delay=1.489670372s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:26.951730Z TRACE new{response=Response { client: 2026-04-24T22:13:26.931190699Z, server: 2026-04-24T22:13:31.941371569Z } current=2026-04-24T22:13:26.951554988Z}: timesimp::delta: response processing internals latency=10ms 182µs 144ns local_at_midpoint=2026-04-24T22:13:26.941372843Z delta=4s 999ms 998µs 726ns
[INFO] [stdout] 2026-04-24T22:13:26.951832Z TRACE timesimp: obtained raw offset from server latency=10.182144ms delta=4s 999ms 998µs 726ns
[INFO] [stdout] 2026-04-24T22:13:26.951874Z TRACE timesimp: sleeping to spread out requests delay=1.898786984s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.014640Z TRACE new{response=Response { client: 2026-04-24T22:13:27.012172273Z, server: 2026-04-24T22:13:27.013329493Z } current=2026-04-24T22:13:27.014470403Z}: timesimp::delta: response processing internals latency=1ms 149µs 65ns local_at_midpoint=2026-04-24T22:13:27.013321338Z delta=8µs 155ns
[INFO] [stdout] 2026-04-24T22:13:27.014736Z TRACE timesimp: obtained raw offset from server latency=1.149065ms delta=8µs 155ns
[INFO] [stdout] 2026-04-24T22:13:27.014761Z TRACE timesimp: sleeping to spread out requests delay=731.605703ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.271709Z TRACE new{response=Response { client: 2026-04-24T22:13:27.249168803Z, server: 2026-04-24T22:13:27.260343162Z } current=2026-04-24T22:13:27.271517442Z}: timesimp::delta: response processing internals latency=11ms 174µs 319ns local_at_midpoint=2026-04-24T22:13:27.260343122Z delta=40ns
[INFO] [stdout] 2026-04-24T22:13:27.271803Z TRACE timesimp: obtained raw offset from server latency=11.174319ms delta=40ns
[INFO] [stdout] 2026-04-24T22:13:27.271830Z TRACE timesimp: sleeping to spread out requests delay=369.788558ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.276749Z TRACE new{response=Response { client: 2026-04-24T22:13:27.074724558Z, server: 2026-04-24T22:13:27.175153159Z } current=2026-04-24T22:13:27.276550441Z}: timesimp::delta: response processing internals latency=100ms 912µs 941ns local_at_midpoint=2026-04-24T22:13:27.175637499Z delta=484µs 340ns ago
[INFO] [stdout] 2026-04-24T22:13:27.276853Z TRACE timesimp: obtained raw offset from server latency=100.912941ms delta=484µs 340ns ago
[INFO] [stdout] 2026-04-24T22:13:27.276886Z TRACE timesimp: sleeping to spread out requests delay=1.403753079s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.341135Z TRACE new{response=Response { client: 2026-04-24T22:13:27.318488087Z, server: 2026-04-24T22:13:22.329692757Z } current=2026-04-24T22:13:27.340965256Z}: timesimp::delta: response processing internals latency=11ms 238µs 584ns local_at_midpoint=2026-04-24T22:13:27.329726671Z delta=5s 33µs 914ns ago
[INFO] [stdout] 2026-04-24T22:13:27.341222Z TRACE timesimp: obtained raw offset from server latency=11.238584ms delta=5s 33µs 914ns ago
[INFO] [stdout] 2026-04-24T22:13:27.341246Z TRACE timesimp: sleeping to spread out requests delay=317.680731ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.600509Z TRACE new{response=Response { client: 2026-04-24T22:13:25.673827982Z, server: 2026-04-24T22:13:26.637095574Z } current=2026-04-24T22:13:27.600301274Z}: timesimp::delta: response processing internals latency=963ms 236µs 646ns local_at_midpoint=2026-04-24T22:13:26.637064628Z delta=30µs 946ns
[INFO] [stdout] 2026-04-24T22:13:27.600602Z TRACE timesimp: obtained raw offset from server latency=963.236646ms delta=30µs 946ns
[INFO] [stdout] 2026-04-24T22:13:27.600637Z DEBUG timesimp: no offset stored, storing initial delta offset=30µs 946ns
[INFO] [stdout] 2026-04-24T22:13:27.600653Z TRACE timesimp: sleeping to spread out requests delay=525.255302ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.665345Z TRACE new{response=Response { client: 2026-04-24T22:13:27.642579011Z, server: 2026-04-24T22:13:27.65376725Z } current=2026-04-24T22:13:27.665158789Z}: timesimp::delta: response processing internals latency=11ms 289µs 889ns local_at_midpoint=2026-04-24T22:13:27.6538689Z delta=101µs 650ns ago
[INFO] [stdout] 2026-04-24T22:13:27.665451Z TRACE timesimp: obtained raw offset from server latency=11.289889ms delta=101µs 650ns ago
[INFO] [stdout] 2026-04-24T22:13:27.665480Z TRACE timesimp: sleeping to spread out requests delay=515.314927ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.683379Z TRACE new{response=Response { client: 2026-04-24T22:13:27.660807879Z, server: 2026-04-24T22:13:22.672003918Z } current=2026-04-24T22:13:27.683215638Z}: timesimp::delta: response processing internals latency=11ms 203µs 879ns local_at_midpoint=2026-04-24T22:13:27.672011758Z delta=5s 7µs 840ns ago
[INFO] [stdout] 2026-04-24T22:13:27.683464Z TRACE timesimp: obtained raw offset from server latency=11.203879ms delta=5s 7µs 840ns ago
[INFO] [stdout] 2026-04-24T22:13:27.683485Z TRACE timesimp: sleeping to spread out requests delay=1.091955784s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.696217Z TRACE new{response=Response { client: 2026-04-24T22:13:27.674744808Z, server: 2026-04-24T22:13:32.684914597Z } current=2026-04-24T22:13:27.696053407Z}: timesimp::delta: response processing internals latency=10ms 654µs 299ns local_at_midpoint=2026-04-24T22:13:27.685399107Z delta=4s 999ms 515µs 490ns
[INFO] [stdout] 2026-04-24T22:13:27.696302Z TRACE timesimp: obtained raw offset from server latency=10.654299ms delta=4s 999ms 515µs 490ns
[INFO] [stdout] 2026-04-24T22:13:27.696321Z TRACE timesimp: sleeping to spread out requests delay=627.876502ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.750471Z TRACE new{response=Response { client: 2026-04-24T22:13:27.747874932Z, server: 2026-04-24T22:13:27.749092002Z } current=2026-04-24T22:13:27.750268152Z}: timesimp::delta: response processing internals latency=1ms 196µs 610ns local_at_midpoint=2026-04-24T22:13:27.749071542Z delta=20µs 460ns
[INFO] [stdout] 2026-04-24T22:13:27.750570Z TRACE timesimp: obtained raw offset from server latency=1.19661ms delta=20µs 460ns
[INFO] [stdout] 2026-04-24T22:13:27.750611Z TRACE timesimp: sleeping to spread out requests delay=194.214485ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.922821Z TRACE new{response=Response { client: 2026-04-24T22:13:27.90018116Z, server: 2026-04-24T22:13:32.911336799Z } current=2026-04-24T22:13:27.922650508Z}: timesimp::delta: response processing internals latency=11ms 234µs 674ns local_at_midpoint=2026-04-24T22:13:27.911415834Z delta=4s 999ms 920µs 965ns
[INFO] [stdout] 2026-04-24T22:13:27.922936Z TRACE timesimp: obtained raw offset from server latency=11.234674ms delta=4s 999ms 920µs 965ns
[INFO] [stdout] 2026-04-24T22:13:27.922960Z TRACE timesimp: sleeping to spread out requests delay=119.036824ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:27.948491Z TRACE new{response=Response { client: 2026-04-24T22:13:27.946027536Z, server: 2026-04-24T22:13:27.947186956Z } current=2026-04-24T22:13:27.948329886Z}: timesimp::delta: response processing internals latency=1ms 151µs 175ns local_at_midpoint=2026-04-24T22:13:27.947178711Z delta=8µs 245ns
[INFO] [stdout] 2026-04-24T22:13:27.948579Z TRACE timesimp: obtained raw offset from server latency=1.151175ms delta=8µs 245ns
[INFO] [stdout] 2026-04-24T22:13:27.948626Z TRACE timesimp: sleeping to spread out requests delay=1.561890417s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:28.066002Z TRACE new{response=Response { client: 2026-04-24T22:13:28.043517658Z, server: 2026-04-24T22:13:33.054669077Z } current=2026-04-24T22:13:28.065813416Z}: timesimp::delta: response processing internals latency=11ms 147µs 879ns local_at_midpoint=2026-04-24T22:13:28.054665537Z delta=5s 3µs 540ns
[INFO] [stdout] 2026-04-24T22:13:28.066099Z TRACE timesimp: obtained raw offset from server latency=11.147879ms delta=5s 3µs 540ns
[INFO] [stdout] 2026-04-24T22:13:28.066121Z TRACE timesimp: sleeping to spread out requests delay=266.980999ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:28.204651Z TRACE new{response=Response { client: 2026-04-24T22:13:28.182165267Z, server: 2026-04-24T22:13:28.193325386Z } current=2026-04-24T22:13:28.204480955Z}: timesimp::delta: response processing internals latency=11ms 157µs 844ns local_at_midpoint=2026-04-24T22:13:28.193323111Z delta=2µs 275ns
[INFO] [stdout] 2026-04-24T22:13:28.204733Z TRACE timesimp: obtained raw offset from server latency=11.157844ms delta=2µs 275ns
[INFO] [stdout] 2026-04-24T22:13:28.204763Z TRACE timesimp: response deltas sorted by latency deltas=[0.002275, 4e-5, 0.07831, -0.10165, -0.276924]
[INFO] [stdout] 2026-04-24T22:13:28.204782Z TRACE timesimp: statistics about response deltas median=0.07831 mean=-0.059589800000000005 variance=0.018850634070200004 stddev=0.137297611305514
[INFO] [stdout] 2026-04-24T22:13:28.204807Z TRACE timesimp: eliminated outliers inliers=[0.002275, 4e-5, 0.07831]
[INFO] [stdout] 2026-04-24T22:13:28.204820Z DEBUG timesimp: storing calculated offset offset=26µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2026-04-24T22:13:28.205575Z TRACE new{response=Response { client: 2026-04-24T22:13:28.184125236Z, server: 2026-04-24T22:13:28.195279186Z } current=2026-04-24T22:13:28.205422535Z}: timesimp::delta: response processing internals latency=10ms 648µs 649ns local_at_midpoint=2026-04-24T22:13:28.194773885Z delta=505µs 301ns
[INFO] [stdout] 2026-04-24T22:13:28.205661Z TRACE timesimp: obtained raw offset from server latency=10.648649ms delta=505µs 301ns
[INFO] [stdout] 2026-04-24T22:13:28.205693Z TRACE timesimp: response deltas sorted by latency deltas=[0.505301, 0.002525, 0.010151, -0.038675, 0.028965]
[INFO] [stdout] 2026-04-24T22:13:28.205711Z TRACE timesimp: statistics about response deltas median=0.010151 mean=0.1016534 variance=0.0515265443048 stddev=0.2269945909152903
[INFO] [stdout] 2026-04-24T22:13:28.205734Z TRACE timesimp: eliminated outliers inliers=[0.002525, 0.010151, -0.038675, 0.028965]
[INFO] [stdout] 2026-04-24T22:13:28.205747Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2026-04-24T22:13:28.213577Z TRACE new{response=Response { client: 2026-04-24T22:13:28.196086475Z, server: 2026-04-24T22:13:33.204262895Z } current=2026-04-24T22:13:28.213445044Z}: timesimp::delta: response processing internals latency=8ms 679µs 284ns local_at_midpoint=2026-04-24T22:13:28.204765759Z delta=4s 999ms 497µs 136ns
[INFO] [stdout] 2026-04-24T22:13:28.213665Z TRACE timesimp: obtained raw offset from server latency=8.679284ms delta=4s 999ms 497µs 136ns
[INFO] [stdout] 2026-04-24T22:13:28.213688Z TRACE timesimp: sleeping to spread out requests delay=1.476873081s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:28.346700Z TRACE new{response=Response { client: 2026-04-24T22:13:28.325150795Z, server: 2026-04-24T22:13:33.336352084Z } current=2026-04-24T22:13:28.346490703Z}: timesimp::delta: response processing internals latency=10ms 669µs 954ns local_at_midpoint=2026-04-24T22:13:28.335820749Z delta=5s 531µs 335ns
[INFO] [stdout] 2026-04-24T22:13:28.346787Z TRACE timesimp: obtained raw offset from server latency=10.669954ms delta=5s 531µs 335ns
[INFO] [stdout] 2026-04-24T22:13:28.346810Z TRACE timesimp: sleeping to spread out requests delay=1.927335895s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:28.356780Z TRACE new{response=Response { client: 2026-04-24T22:13:28.334399314Z, server: 2026-04-24T22:13:33.345521933Z } current=2026-04-24T22:13:28.356672922Z}: timesimp::delta: response processing internals latency=11ms 136µs 804ns local_at_midpoint=2026-04-24T22:13:28.345536118Z delta=4s 999ms 985µs 815ns
[INFO] [stdout] 2026-04-24T22:13:28.356846Z TRACE timesimp: obtained raw offset from server latency=11.136804ms delta=4s 999ms 985µs 815ns
[INFO] [stdout] 2026-04-24T22:13:28.356875Z TRACE timesimp: response deltas sorted by latency deltas=[4999.985815, 5000.00354, 5000.052785, 4999.920965, 4999.810776]
[INFO] [stdout] 2026-04-24T22:13:28.356910Z TRACE timesimp: statistics about response deltas median=5000.052785 mean=4999.9547762 variance=0.00870657375466286 stddev=0.09330902290059016
[INFO] [stdout] 2026-04-24T22:13:28.356935Z TRACE timesimp: eliminated outliers inliers=[4999.985815, 5000.00354, 5000.052785]
[INFO] [stdout] 2026-04-24T22:13:28.356947Z DEBUG timesimp: storing calculated offset offset=5s 14µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2026-04-24T22:13:28.798700Z TRACE new{response=Response { client: 2026-04-24T22:13:28.776185698Z, server: 2026-04-24T22:13:23.787359497Z } current=2026-04-24T22:13:28.798519936Z}: timesimp::delta: response processing internals latency=11ms 167µs 119ns local_at_midpoint=2026-04-24T22:13:28.787352817Z delta=4s 999ms 993µs 320ns ago
[INFO] [stdout] 2026-04-24T22:13:28.798863Z TRACE timesimp: obtained raw offset from server latency=11.167119ms delta=4s 999ms 993µs 320ns ago
[INFO] [stdout] 2026-04-24T22:13:28.798921Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99332, -4999.98561, -5000.00784, -5000.033914, -5000.284549]
[INFO] [stdout] 2026-04-24T22:13:28.798943Z TRACE timesimp: statistics about response deltas median=-5000.00784 mean=-5000.0610466 variance=0.015949504009820266 stddev=0.1262913457439593
[INFO] [stdout] 2026-04-24T22:13:28.798964Z TRACE timesimp: eliminated outliers inliers=[-4999.99332, -4999.98561, -5000.00784, -5000.033914]
[INFO] [stdout] 2026-04-24T22:13:28.798978Z DEBUG timesimp: storing calculated offset offset=5s 5µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2026-04-24T22:13:28.865534Z TRACE new{response=Response { client: 2026-04-24T22:13:28.852123332Z, server: 2026-04-24T22:13:33.859256921Z } current=2026-04-24T22:13:28.86537872Z}: timesimp::delta: response processing internals latency=6ms 627µs 694ns local_at_midpoint=2026-04-24T22:13:28.858751026Z delta=5s 505µs 895ns
[INFO] [stdout] 2026-04-24T22:13:28.865667Z TRACE timesimp: obtained raw offset from server latency=6.627694ms delta=5s 505µs 895ns
[INFO] [stdout] 2026-04-24T22:13:28.865683Z TRACE timesimp: sleeping to spread out requests delay=1.139527814s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:28.884918Z TRACE new{response=Response { client: 2026-04-24T22:13:28.681995596Z, server: 2026-04-24T22:13:28.783340507Z } current=2026-04-24T22:13:28.884718159Z}: timesimp::delta: response processing internals latency=101ms 361µs 281ns local_at_midpoint=2026-04-24T22:13:28.783356877Z delta=16µs 370ns ago
[INFO] [stdout] 2026-04-24T22:13:28.885019Z TRACE timesimp: obtained raw offset from server latency=101.361281ms delta=16µs 370ns ago
[INFO] [stdout] 2026-04-24T22:13:28.885050Z TRACE timesimp: sleeping to spread out requests delay=626.672218ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:29.513441Z TRACE new{response=Response { client: 2026-04-24T22:13:29.511000838Z, server: 2026-04-24T22:13:29.512162327Z } current=2026-04-24T22:13:29.513292537Z}: timesimp::delta: response processing internals latency=1ms 145µs 849ns local_at_midpoint=2026-04-24T22:13:29.512146687Z delta=15µs 640ns
[INFO] [stdout] 2026-04-24T22:13:29.513522Z TRACE timesimp: obtained raw offset from server latency=1.145849ms delta=15µs 640ns
[INFO] [stdout] 2026-04-24T22:13:29.513547Z TRACE timesimp: response deltas sorted by latency deltas=[0.007435, 0.01564, 0.008155, 0.008245, 0.02046]
[INFO] [stdout] 2026-04-24T22:13:29.513565Z TRACE timesimp: statistics about response deltas median=0.008155 mean=0.011987000000000001 variance=3.363590749999999e-5 stddev=0.005799647187545117
[INFO] [stdout] 2026-04-24T22:13:29.513584Z TRACE timesimp: eliminated outliers inliers=[0.007435, 0.008155, 0.008245]
[INFO] [stdout] 2026-04-24T22:13:29.513614Z DEBUG timesimp: storing calculated offset offset=7µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2026-04-24T22:13:29.535163Z TRACE new{response=Response { client: 2026-04-24T22:13:28.127138431Z, server: 2026-04-24T22:13:28.831129103Z } current=2026-04-24T22:13:29.535002356Z}: timesimp::delta: response processing internals latency=703ms 931µs 962ns local_at_midpoint=2026-04-24T22:13:28.831070393Z delta=58µs 710ns
[INFO] [stdout] 2026-04-24T22:13:29.535250Z TRACE timesimp: obtained raw offset from server latency=703.931962ms delta=58µs 710ns
[INFO] [stdout] 2026-04-24T22:13:29.535275Z TRACE timesimp: sleeping to spread out requests delay=1.055998798s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:29.711916Z TRACE new{response=Response { client: 2026-04-24T22:13:29.692177143Z, server: 2026-04-24T22:13:34.702389562Z } current=2026-04-24T22:13:29.711697421Z}: timesimp::delta: response processing internals latency=9ms 760µs 139ns local_at_midpoint=2026-04-24T22:13:29.701937282Z delta=5s 452µs 280ns
[INFO] [stdout] 2026-04-24T22:13:29.712011Z TRACE timesimp: obtained raw offset from server latency=9.760139ms delta=5s 452µs 280ns
[INFO] [stdout] 2026-04-24T22:13:29.712035Z TRACE timesimp: sleeping to spread out requests delay=692.83689ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:29.715764Z TRACE new{response=Response { client: 2026-04-24T22:13:29.512936997Z, server: 2026-04-24T22:13:29.614283249Z } current=2026-04-24T22:13:29.715590701Z}: timesimp::delta: response processing internals latency=101ms 326µs 852ns local_at_midpoint=2026-04-24T22:13:29.614263849Z delta=19µs 400ns
[INFO] [stdout] 2026-04-24T22:13:29.715849Z TRACE timesimp: obtained raw offset from server latency=101.326852ms delta=19µs 400ns
[INFO] [stdout] 2026-04-24T22:13:29.715876Z TRACE timesimp: sleeping to spread out requests delay=484.461002ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:30.025013Z TRACE new{response=Response { client: 2026-04-24T22:13:30.006420727Z, server: 2026-04-24T22:13:35.015594296Z } current=2026-04-24T22:13:30.024804715Z}: timesimp::delta: response processing internals latency=9ms 191µs 994ns local_at_midpoint=2026-04-24T22:13:30.015612721Z delta=4s 999ms 981µs 575ns
[INFO] [stdout] 2026-04-24T22:13:30.025106Z TRACE timesimp: obtained raw offset from server latency=9.191994ms delta=4s 999ms 981µs 575ns
[INFO] [stdout] 2026-04-24T22:13:30.025131Z TRACE timesimp: sleeping to spread out requests delay=1.705091721s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:30.295325Z TRACE new{response=Response { client: 2026-04-24T22:13:30.274622735Z, server: 2026-04-24T22:13:35.284963514Z } current=2026-04-24T22:13:30.295153043Z}: timesimp::delta: response processing internals latency=10ms 265µs 154ns local_at_midpoint=2026-04-24T22:13:30.284887889Z delta=5s 75µs 625ns
[INFO] [stdout] 2026-04-24T22:13:30.295417Z TRACE timesimp: obtained raw offset from server latency=10.265154ms delta=5s 75µs 625ns
[INFO] [stdout] 2026-04-24T22:13:30.295440Z TRACE timesimp: sleeping to spread out requests delay=1.288067794s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:30.403592Z TRACE new{response=Response { client: 2026-04-24T22:13:30.201686511Z, server: 2026-04-24T22:13:30.302149143Z } current=2026-04-24T22:13:30.403422024Z}: timesimp::delta: response processing internals latency=100ms 867µs 756ns local_at_midpoint=2026-04-24T22:13:30.302554267Z delta=405µs 124ns ago
[INFO] [stdout] 2026-04-24T22:13:30.403699Z TRACE timesimp: obtained raw offset from server latency=100.867756ms delta=405µs 124ns ago
[INFO] [stdout] 2026-04-24T22:13:30.403731Z TRACE timesimp: response deltas sorted by latency deltas=[-0.405124, -0.48434, 0.0194, -0.0514, -0.01637]
[INFO] [stdout] 2026-04-24T22:13:30.403752Z TRACE timesimp: statistics about response deltas median=0.0194 mean=-0.1875668 variance=0.0565226163912 stddev=0.23774485565664719
[INFO] [stdout] 2026-04-24T22:13:30.403780Z TRACE timesimp: eliminated outliers inliers=[0.0194, -0.0514, -0.01637]
[INFO] [stdout] 2026-04-24T22:13:30.403793Z DEBUG timesimp: storing calculated offset offset=16µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2026-04-24T22:13:30.429566Z TRACE new{response=Response { client: 2026-04-24T22:13:30.405586744Z, server: 2026-04-24T22:13:35.416856843Z } current=2026-04-24T22:13:30.428716072Z}: timesimp::delta: response processing internals latency=11ms 564µs 664ns local_at_midpoint=2026-04-24T22:13:30.417151408Z delta=4s 999ms 705µs 435ns
[INFO] [stdout] 2026-04-24T22:13:30.429803Z TRACE timesimp: obtained raw offset from server latency=11.564664ms delta=4s 999ms 705µs 435ns
[INFO] [stdout] 2026-04-24T22:13:30.429880Z TRACE timesimp: response deltas sorted by latency deltas=[4999.996385, 5000.01423, 4999.497136, 5000.45228, 4999.705435]
[INFO] [stdout] 2026-04-24T22:13:30.429918Z TRACE timesimp: statistics about response deltas median=4999.497136 mean=4999.933093199999 variance=0.13050772545384026 stddev=0.36125852993921165
[INFO] [stdout] 2026-04-24T22:13:30.429946Z TRACE timesimp: eliminated outliers inliers=[4999.497136, 4999.705435]
[INFO] [stdout] 2026-04-24T22:13:30.429962Z DEBUG timesimp: storing calculated offset offset=4s 999ms 601µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2026-04-24T22:13:31.606704Z TRACE new{response=Response { client: 2026-04-24T22:13:31.585142957Z, server: 2026-04-24T22:13:36.596338887Z } current=2026-04-24T22:13:31.606524716Z}: timesimp::delta: response processing internals latency=10ms 690µs 879ns local_at_midpoint=2026-04-24T22:13:31.595833836Z delta=5s 505µs 51ns
[INFO] [stdout] 2026-04-24T22:13:31.606794Z TRACE timesimp: obtained raw offset from server latency=10.690879ms delta=5s 505µs 51ns
[INFO] [stdout] 2026-04-24T22:13:31.606822Z TRACE timesimp: response deltas sorted by latency deltas=[4999.96639, 5000.075625, 4999.51549, 5000.531335, 5000.505051]
[INFO] [stdout] 2026-04-24T22:13:31.606842Z TRACE timesimp: statistics about response deltas median=4999.51549 mean=5000.1187782 variance=0.17711270091874154 stddev=0.4208475982095437
[INFO] [stdout] 2026-04-24T22:13:31.606862Z TRACE timesimp: eliminated outliers inliers=[4999.51549]
[INFO] [stdout] 2026-04-24T22:13:31.606875Z DEBUG timesimp: storing calculated offset offset=4s 999ms 515µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2026-04-24T22:13:31.748746Z TRACE new{response=Response { client: 2026-04-24T22:13:31.732144055Z, server: 2026-04-24T22:13:36.740337955Z } current=2026-04-24T22:13:31.748564994Z}: timesimp::delta: response processing internals latency=8ms 210µs 469ns local_at_midpoint=2026-04-24T22:13:31.740354524Z delta=4s 999ms 983µs 431ns
[INFO] [stdout] 2026-04-24T22:13:31.748831Z TRACE timesimp: obtained raw offset from server latency=8.210469ms delta=4s 999ms 983µs 431ns
[INFO] [stdout] 2026-04-24T22:13:31.748865Z TRACE timesimp: response deltas sorted by latency deltas=[5000.505895, 4999.983431, 4999.981575, 4999.998726, 5000.036375]
[INFO] [stdout] 2026-04-24T22:13:31.748884Z TRACE timesimp: statistics about response deltas median=4999.981575 mean=5000.1012003999995 variance=0.051665230577900935 stddev=0.22729986928703003
[INFO] [stdout] 2026-04-24T22:13:31.748931Z TRACE timesimp: eliminated outliers inliers=[4999.983431, 4999.981575, 4999.998726, 5000.036375]
[INFO] [stdout] 2026-04-24T22:13:31.748945Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2026-04-24T22:13:32.009673Z TRACE new{response=Response { client: 2026-04-24T22:13:30.591743299Z, server: 2026-04-24T22:13:31.301122181Z } current=2026-04-24T22:13:32.009510213Z}: timesimp::delta: response processing internals latency=708ms 883µs 457ns local_at_midpoint=2026-04-24T22:13:31.300626756Z delta=495µs 425ns
[INFO] [stdout] 2026-04-24T22:13:32.009763Z TRACE timesimp: obtained raw offset from server latency=708.883457ms delta=495µs 425ns
[INFO] [stdout] 2026-04-24T22:13:32.009784Z TRACE timesimp: sleeping to spread out requests delay=1.208884007s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:34.864330Z TRACE new{response=Response { client: 2026-04-24T22:13:33.220143463Z, server: 2026-04-24T22:13:34.042300156Z } current=2026-04-24T22:13:34.864145698Z}: timesimp::delta: response processing internals latency=822ms 1µs 117ns local_at_midpoint=2026-04-24T22:13:34.04214458Z delta=155µs 576ns
[INFO] [stdout] 2026-04-24T22:13:34.864442Z TRACE timesimp: obtained raw offset from server latency=822.001117ms delta=155µs 576ns
[INFO] [stdout] 2026-04-24T22:13:34.864469Z TRACE timesimp: sleeping to spread out requests delay=1.998396379s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.481147Z TRACE new{response=Response { client: 2026-04-24T22:13:36.864148174Z, server: 2026-04-24T22:13:37.671182008Z } current=2026-04-24T22:13:38.480972801Z}: timesimp::delta: response processing internals latency=808ms 412µs 313ns local_at_midpoint=2026-04-24T22:13:37.672560487Z delta=1ms 378µs 479ns ago
[INFO] [stdout] 2026-04-24T22:13:38.481244Z TRACE timesimp: obtained raw offset from server latency=808.412313ms delta=1ms 378µs 479ns ago
[INFO] [stdout] 2026-04-24T22:13:38.481276Z TRACE timesimp: response deltas sorted by latency deltas=[0.05871, 0.495425, -1.378479, 0.155576, 0.030946]
[INFO] [stdout] 2026-04-24T22:13:38.481302Z TRACE timesimp: statistics about response deltas median=-1.378479 mean=-0.1275644 variance=0.5232238285303 stddev=0.7233421241226727
[INFO] [stdout] 2026-04-24T22:13:38.481339Z TRACE timesimp: eliminated outliers inliers=[-1.378479]
[INFO] [stdout] 2026-04-24T22:13:38.481353Z DEBUG timesimp: storing calculated offset offset=1ms 378µ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 12.81s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-8ae4f6af8a41ac33)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2026-04-24T22:13:38.485194Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-04-24T22:13:38.485194Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:38.485291Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.485301Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.486716Z TRACE new{response=Response { client: 2026-04-24T22:13:38.486540181Z, server: 2026-04-24T22:13:38.486554631Z } current=2026-04-24T22:13:38.486557691Z}: timesimp::delta: response processing internals latency=8µs 755ns local_at_midpoint=2026-04-24T22:13:38.486548936Z delta=5µs 695ns
[INFO] [stdout] 2026-04-24T22:13:38.486851Z TRACE timesimp: obtained raw offset from server latency=8.755µs delta=5µs 695ns
[INFO] [stdout] 2026-04-24T22:13:38.486882Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-04-24T22:13:38.488120Z TRACE new{response=Response { client: 2026-04-24T22:13:38.488013321Z, server: 2026-04-24T22:13:33.488016491Z } current=2026-04-24T22:13:38.488018201Z}: timesimp::delta: response processing internals latency=2µs 440ns local_at_midpoint=2026-04-24T22:13:38.488015761Z delta=4s 999ms 999µs 270ns ago
[INFO] [stdout] 2026-04-24T22:13:38.489037Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.488933Z TRACE timesimp: sleeping to spread out requests delay=1.5814037s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.489080Z TRACE timesimp: obtained raw offset from server latency=2.44µs delta=4s 999ms 999µs 270ns ago
[INFO] [stdout] 2026-04-24T22:13:38.489106Z TRACE timesimp: sleeping to spread out requests delay=1.816251038s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.489103Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-04-24T22:13:38.489136Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.490724Z TRACE new{response=Response { client: 2026-04-24T22:13:38.490554281Z, server: 2026-04-24T22:13:43.49056211Z } current=2026-04-24T22:13:38.49056573Z}: timesimp::delta: response processing internals latency=5µs 724ns local_at_midpoint=2026-04-24T22:13:38.490560005Z delta=5s 2µs 105ns
[INFO] [stdout] 2026-04-24T22:13:38.490807Z TRACE timesimp: obtained raw offset from server latency=5.724µs delta=5s 2µs 105ns
[INFO] [stdout] 2026-04-24T22:13:38.490826Z TRACE timesimp: sleeping to spread out requests delay=1.083083249s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:38.493093Z TRACE new{response=Response { client: 2026-04-24T22:13:38.49298734Z, server: 2026-04-24T22:13:38.49299096Z } current=2026-04-24T22:13:38.4929928Z}: timesimp::delta: response processing internals latency=2µs 730ns local_at_midpoint=2026-04-24T22:13:38.49299007Z delta=890ns
[INFO] [stdout] 2026-04-24T22:13:38.493164Z TRACE timesimp: obtained raw offset from server latency=2.73µs delta=890ns
[INFO] [stdout] 2026-04-24T22:13:38.493190Z DEBUG timesimp: no offset stored, storing initial delta offset=890ns
[INFO] [stdout] 2026-04-24T22:13:38.493210Z TRACE timesimp: sleeping to spread out requests delay=1.522407852s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:39.575331Z TRACE new{response=Response { client: 2026-04-24T22:13:39.575147841Z, server: 2026-04-24T22:13:44.575158541Z } current=2026-04-24T22:13:39.575162241Z}: timesimp::delta: response processing internals latency=7µs 200ns local_at_midpoint=2026-04-24T22:13:39.575155041Z delta=5s 3µs 500ns
[INFO] [stdout] 2026-04-24T22:13:39.575437Z TRACE timesimp: obtained raw offset from server latency=7.2µs delta=5s 3µs 500ns
[INFO] [stdout] 2026-04-24T22:13:39.575463Z TRACE timesimp: sleeping to spread out requests delay=415.990279ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:39.993304Z TRACE new{response=Response { client: 2026-04-24T22:13:39.993132647Z, server: 2026-04-24T22:13:44.993142717Z } current=2026-04-24T22:13:39.993145857Z}: timesimp::delta: response processing internals latency=6µs 605ns local_at_midpoint=2026-04-24T22:13:39.993139252Z delta=5s 3µs 465ns
[INFO] [stdout] 2026-04-24T22:13:39.993404Z TRACE timesimp: obtained raw offset from server latency=6.605µs delta=5s 3µs 465ns
[INFO] [stdout] 2026-04-24T22:13:39.993428Z TRACE timesimp: sleeping to spread out requests delay=106.379758ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:40.016314Z TRACE new{response=Response { client: 2026-04-24T22:13:40.016138245Z, server: 2026-04-24T22:13:40.016149765Z } current=2026-04-24T22:13:40.016152575Z}: timesimp::delta: response processing internals latency=7µs 165ns local_at_midpoint=2026-04-24T22:13:40.01614541Z delta=4µs 355ns
[INFO] [stdout] 2026-04-24T22:13:40.016403Z TRACE timesimp: obtained raw offset from server latency=7.165µs delta=4µs 355ns
[INFO] [stdout] 2026-04-24T22:13:40.016425Z TRACE timesimp: sleeping to spread out requests delay=914.522688ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:40.071283Z TRACE new{response=Response { client: 2026-04-24T22:13:40.071116101Z, server: 2026-04-24T22:13:40.071125461Z } current=2026-04-24T22:13:40.071128511Z}: timesimp::delta: response processing internals latency=6µs 205ns local_at_midpoint=2026-04-24T22:13:40.071122306Z delta=3µs 155ns
[INFO] [stdout] 2026-04-24T22:13:40.071386Z TRACE timesimp: obtained raw offset from server latency=6.205µs delta=3µs 155ns
[INFO] [stdout] 2026-04-24T22:13:40.071412Z TRACE timesimp: sleeping to spread out requests delay=1.305398422s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:40.101297Z TRACE new{response=Response { client: 2026-04-24T22:13:40.101133728Z, server: 2026-04-24T22:13:45.101142988Z } current=2026-04-24T22:13:40.101146338Z}: timesimp::delta: response processing internals latency=6µs 305ns local_at_midpoint=2026-04-24T22:13:40.101140033Z delta=5s 2µs 955ns
[INFO] [stdout] 2026-04-24T22:13:40.101390Z TRACE timesimp: obtained raw offset from server latency=6.305µs delta=5s 2µs 955ns
[INFO] [stdout] 2026-04-24T22:13:40.101415Z TRACE timesimp: sleeping to spread out requests delay=500.834006ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:40.306320Z TRACE new{response=Response { client: 2026-04-24T22:13:40.306142181Z, server: 2026-04-24T22:13:35.306151751Z } current=2026-04-24T22:13:40.306155811Z}: timesimp::delta: response processing internals latency=6µs 815ns local_at_midpoint=2026-04-24T22:13:40.306148996Z delta=4s 999ms 997µs 245ns ago
[INFO] [stdout] 2026-04-24T22:13:40.306506Z TRACE timesimp: obtained raw offset from server latency=6.815µs delta=4s 999ms 997µs 245ns ago
[INFO] [stdout] 2026-04-24T22:13:40.306809Z TRACE timesimp: sleeping to spread out requests delay=1.087714901s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:40.604283Z TRACE new{response=Response { client: 2026-04-24T22:13:40.604106327Z, server: 2026-04-24T22:13:45.604116927Z } current=2026-04-24T22:13:40.604120417Z}: timesimp::delta: response processing internals latency=7µs 45ns local_at_midpoint=2026-04-24T22:13:40.604113372Z delta=5s 3µs 555ns
[INFO] [stdout] 2026-04-24T22:13:40.604374Z TRACE timesimp: obtained raw offset from server latency=7.045µs delta=5s 3µs 555ns
[INFO] [stdout] 2026-04-24T22:13:40.604405Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002105, 5000.002955, 5000.003465, 5000.003555, 5000.0035]
[INFO] [stdout] 2026-04-24T22:13:40.604424Z TRACE timesimp: statistics about response deltas median=5000.003465 mean=5000.003116 variance=3.775050001958526e-7 stddev=0.0006144143554604276
[INFO] [stdout] 2026-04-24T22:13:40.604444Z TRACE timesimp: eliminated outliers inliers=[5000.002955, 5000.003465, 5000.003555, 5000.0035]
[INFO] [stdout] 2026-04-24T22:13:40.604458Z DEBUG timesimp: storing calculated offset offset=5s 3µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2026-04-24T22:13:40.932343Z TRACE new{response=Response { client: 2026-04-24T22:13:40.93216957Z, server: 2026-04-24T22:13:40.93218008Z } current=2026-04-24T22:13:40.93218288Z}: timesimp::delta: response processing internals latency=6µs 655ns local_at_midpoint=2026-04-24T22:13:40.932176225Z delta=3µs 855ns
[INFO] [stdout] 2026-04-24T22:13:40.932442Z TRACE timesimp: obtained raw offset from server latency=6.655µs delta=3µs 855ns
[INFO] [stdout] 2026-04-24T22:13:40.932467Z TRACE timesimp: sleeping to spread out requests delay=1.431628675s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:41.381166Z TRACE new{response=Response { client: 2026-04-24T22:13:41.380985053Z, server: 2026-04-24T22:13:41.380994443Z } current=2026-04-24T22:13:41.380997833Z}: timesimp::delta: response processing internals latency=6µs 390ns local_at_midpoint=2026-04-24T22:13:41.380991443Z delta=3µs
[INFO] [stdout] 2026-04-24T22:13:41.381256Z TRACE timesimp: obtained raw offset from server latency=6.39µs delta=3µs
[INFO] [stdout] 2026-04-24T22:13:41.381276Z TRACE timesimp: sleeping to spread out requests delay=1.363257396s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:41.396149Z TRACE new{response=Response { client: 2026-04-24T22:13:41.395986712Z, server: 2026-04-24T22:13:36.395996082Z } current=2026-04-24T22:13:41.395999382Z}: timesimp::delta: response processing internals latency=6µs 335ns local_at_midpoint=2026-04-24T22:13:41.395993047Z delta=4s 999ms 996µs 965ns ago
[INFO] [stdout] 2026-04-24T22:13:41.396235Z TRACE timesimp: obtained raw offset from server latency=6.335µs delta=4s 999ms 996µs 965ns ago
[INFO] [stdout] 2026-04-24T22:13:41.396256Z TRACE timesimp: sleeping to spread out requests delay=1.487949627s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:42.365294Z TRACE new{response=Response { client: 2026-04-24T22:13:42.365125652Z, server: 2026-04-24T22:13:42.365136322Z } current=2026-04-24T22:13:42.365138502Z}: timesimp::delta: response processing internals latency=6µs 425ns local_at_midpoint=2026-04-24T22:13:42.365132077Z delta=4µs 245ns
[INFO] [stdout] 2026-04-24T22:13:42.365375Z TRACE timesimp: obtained raw offset from server latency=6.425µs delta=4µs 245ns
[INFO] [stdout] 2026-04-24T22:13:42.365395Z TRACE timesimp: sleeping to spread out requests delay=482.678959ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:42.754173Z TRACE new{response=Response { client: 2026-04-24T22:13:42.75399798Z, server: 2026-04-24T22:13:42.75400806Z } current=2026-04-24T22:13:42.75401206Z}: timesimp::delta: response processing internals latency=7µs 40ns local_at_midpoint=2026-04-24T22:13:42.75400502Z delta=3µs 40ns
[INFO] [stdout] 2026-04-24T22:13:42.754265Z TRACE timesimp: obtained raw offset from server latency=7.04µs delta=3µs 40ns
[INFO] [stdout] 2026-04-24T22:13:42.754288Z TRACE timesimp: sleeping to spread out requests delay=241.428271ms max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:42.849276Z TRACE new{response=Response { client: 2026-04-24T22:13:42.849099832Z, server: 2026-04-24T22:13:42.849110002Z } current=2026-04-24T22:13:42.849112723Z}: timesimp::delta: response processing internals latency=6µs 445ns local_at_midpoint=2026-04-24T22:13:42.849106277Z delta=3µs 725ns
[INFO] [stdout] 2026-04-24T22:13:42.849368Z TRACE timesimp: obtained raw offset from server latency=6.445µs delta=3µs 725ns
[INFO] [stdout] 2026-04-24T22:13:42.849395Z TRACE timesimp: response deltas sorted by latency deltas=[0.00089, 0.004245, 0.003725, 0.003855, 0.004355]
[INFO] [stdout] 2026-04-24T22:13:42.849413Z TRACE timesimp: statistics about response deltas median=0.003725 mean=0.0034140000000000004 variance=2.0594549999999997e-6 stddev=0.0014350801371352054
[INFO] [stdout] 2026-04-24T22:13:42.849433Z TRACE timesimp: eliminated outliers inliers=[0.004245, 0.003725, 0.003855, 0.004355]
[INFO] [stdout] 2026-04-24T22:13:42.849447Z DEBUG timesimp: storing calculated offset offset=4µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2026-04-24T22:13:42.885654Z TRACE new{response=Response { client: 2026-04-24T22:13:42.885467969Z, server: 2026-04-24T22:13:37.88547834Z } current=2026-04-24T22:13:42.885481929Z}: timesimp::delta: response processing internals latency=6µs 980ns local_at_midpoint=2026-04-24T22:13:42.885474949Z delta=4s 999ms 996µs 609ns ago
[INFO] [stdout] 2026-04-24T22:13:42.885747Z TRACE timesimp: obtained raw offset from server latency=6.98µs delta=4s 999ms 996µs 609ns ago
[INFO] [stdout] 2026-04-24T22:13:42.885769Z TRACE timesimp: sleeping to spread out requests delay=1.072363188s max_jitter=2s
[INFO] [stdout] 2026-04-24T22:13:42.997028Z TRACE new{response=Response { client: 2026-04-24T22:13:42.99683498Z, server: 2026-04-24T22:13:42.99684534Z } current=2026-04-24T22:13:42.9968493Z}: timesimp::delta: response processing internals latency=7µs 160ns local_at_midpoint=2026-04-24T22:13:42.99684214Z delta=3µs 200ns
[INFO] [stdout] 2026-04-24T22:13:42.997197Z TRACE timesimp: obtained raw offset from server latency=7.16µs delta=3µs 200ns
[INFO] [stdout] 2026-04-24T22:13:42.997280Z TRACE timesimp: response deltas sorted by latency deltas=[0.003155, 0.003, 0.00304, 0.0032, 0.005695]
[INFO] [stdout] 2026-04-24T22:13:42.997319Z TRACE timesimp: statistics about response deltas median=0.00304 mean=0.0036180000000000006 variance=1.3547575000000006e-6 stddev=0.0011639405053524001
[INFO] [stdout] 2026-04-24T22:13:42.997395Z TRACE timesimp: eliminated outliers inliers=[0.003155, 0.003, 0.00304, 0.0032]
[INFO] [stdout] 2026-04-24T22:13:42.997429Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 2026-04-24T22:13:43.965173Z TRACE new{response=Response { client: 2026-04-24T22:13:43.964996701Z, server: 2026-04-24T22:13:38.965006781Z } current=2026-04-24T22:13:43.965010251Z}: timesimp::delta: response processing internals latency=6µs 775ns local_at_midpoint=2026-04-24T22:13:43.965003476Z delta=4s 999ms 996µs 695ns ago
[INFO] [stdout] 2026-04-24T22:13:43.965269Z TRACE timesimp: obtained raw offset from server latency=6.775µs delta=4s 999ms 996µs 695ns ago
[INFO] [stdout] 2026-04-24T22:13:43.965298Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99927, -4999.996965, -4999.996695, -4999.9972450000005, -4999.996609]
[INFO] [stdout] 2026-04-24T22:13:43.965318Z TRACE timesimp: statistics about response deltas median=-4999.996695 mean=-4999.9973568000005 variance=1.2058812002927187e-6 stddev=0.0010981262223864426
[INFO] [stdout] 2026-04-24T22:13:43.965343Z TRACE timesimp: eliminated outliers inliers=[-4999.996965, -4999.996695, -4999.9972450000005, -4999.996609]
[INFO] [stdout] 2026-04-24T22:13:43.965376Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.48s
[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] [stdout] all doctests ran in 1.62s; merged doctests compilation took 1.59s
[INFO] running `Command { std: "docker" "inspect" "645150f539a3fa4c3d8d0bed6ea423f923bfc67e82b4794cb6d155a20b2eb11c", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "645150f539a3fa4c3d8d0bed6ea423f923bfc67e82b4794cb6d155a20b2eb11c", kill_on_drop: false }`
[INFO] [stdout] 645150f539a3fa4c3d8d0bed6ea423f923bfc67e82b4794cb6d155a20b2eb11c