[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against master#d98a5da813da67eb189387b8ccfb73cf481275d8+rustflags=-Copt-level=3 for pr-138759-retry
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-7-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-7-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]  Downloading crates ...
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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] bd6eddd4f33e4cdc91c1055a98824556ab47d5279437a2fe8c41b2870e85d117
[INFO] running `Command { std: "docker" "start" "-a" "bd6eddd4f33e4cdc91c1055a98824556ab47d5279437a2fe8c41b2870e85d117", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "bd6eddd4f33e4cdc91c1055a98824556ab47d5279437a2fe8c41b2870e85d117", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "bd6eddd4f33e4cdc91c1055a98824556ab47d5279437a2fe8c41b2870e85d117", kill_on_drop: false }`
[INFO] [stdout] bd6eddd4f33e4cdc91c1055a98824556ab47d5279437a2fe8c41b2870e85d117
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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] c0fc68dd9ff68c489d0cbaee86e8dd527fe1b7bafa69f3b6c26a46191ae0226f
[INFO] running `Command { std: "docker" "start" "-a" "c0fc68dd9ff68c489d0cbaee86e8dd527fe1b7bafa69f3b6c26a46191ae0226f", 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 tracing-core v0.1.33
[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 01s
[INFO] running `Command { std: "docker" "inspect" "c0fc68dd9ff68c489d0cbaee86e8dd527fe1b7bafa69f3b6c26a46191ae0226f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "c0fc68dd9ff68c489d0cbaee86e8dd527fe1b7bafa69f3b6c26a46191ae0226f", kill_on_drop: false }`
[INFO] [stdout] c0fc68dd9ff68c489d0cbaee86e8dd527fe1b7bafa69f3b6c26a46191ae0226f
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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] 55037272bd1589080da46dd56963d3295da19c7990d3a6ecce47a873cec87a3c
[INFO] running `Command { std: "docker" "start" "-a" "55037272bd1589080da46dd56963d3295da19c7990d3a6ecce47a873cec87a3c", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling mime v0.3.17
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling 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 thiserror v2.0.12
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[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 2m 20s
[INFO] running `Command { std: "docker" "inspect" "55037272bd1589080da46dd56963d3295da19c7990d3a6ecce47a873cec87a3c", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "55037272bd1589080da46dd56963d3295da19c7990d3a6ecce47a873cec87a3c", kill_on_drop: false }`
[INFO] [stdout] 55037272bd1589080da46dd56963d3295da19c7990d3a6ecce47a873cec87a3c
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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] 799eab14b274186d0a980dd2c370367aa813959344b76d89b86a5a94ab14646b
[INFO] running `Command { std: "docker" "start" "-a" "799eab14b274186d0a980dd2c370367aa813959344b76d89b86a5a94ab14646b", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.24s
[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_behind_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-cf188712425e7209)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-10-16T10:46:22.343081Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-10-16T10:46:22.343111Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.343186Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.343218Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.343534Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.343739Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.343861Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.343625Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-10-16T10:46:22.343946Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.343614Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.344000Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.343967Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.343666Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.344053Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.345551Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.345570Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.347353Z TRACE new{response=Response { client: 2025-10-16T10:46:22.345153334Z, server: 2025-10-16T10:46:22.346235444Z } current=2025-10-16T10:46:22.347322704Z}: timesimp::delta: response processing internals latency=1ms 84µs 685ns local_at_midpoint=2025-10-16T10:46:22.346238019Z delta=2µs 575ns ago
[INFO] [stdout] 2025-10-16T10:46:22.347376Z TRACE timesimp: obtained raw offset from server latency=1.084685ms delta=2µs 575ns ago
[INFO] [stdout] 2025-10-16T10:46:22.347392Z DEBUG timesimp: no offset stored, storing initial delta offset=2µs 575ns ago
[INFO] [stdout] 2025-10-16T10:46:22.347396Z TRACE timesimp: sleeping to spread out requests delay=1.977413607s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.356588Z TRACE new{response=Response { client: 2025-10-16T10:46:22.344299764Z, server: 2025-10-16T10:46:27.350390644Z } current=2025-10-16T10:46:22.356552034Z}: timesimp::delta: response processing internals latency=6ms 126µs 135ns local_at_midpoint=2025-10-16T10:46:22.350425899Z delta=4s 999ms 964µs 745ns
[INFO] [stdout] 2025-10-16T10:46:22.356619Z TRACE timesimp: obtained raw offset from server latency=6.126135ms delta=4s 999ms 964µs 745ns
[INFO] [stdout] 2025-10-16T10:46:22.356628Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 964µs 745ns
[INFO] [stdout] 2025-10-16T10:46:22.356632Z TRACE timesimp: sleeping to spread out requests delay=103.016347ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.364711Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.364740Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.367385Z TRACE new{response=Response { client: 2025-10-16T10:46:22.345119124Z, server: 2025-10-16T10:46:17.356267384Z } current=2025-10-16T10:46:22.367347834Z}: timesimp::delta: response processing internals latency=11ms 114µs 355ns local_at_midpoint=2025-10-16T10:46:22.356233479Z delta=4s 999ms 966µs 95ns ago
[INFO] [stdout] 2025-10-16T10:46:22.367422Z TRACE timesimp: obtained raw offset from server latency=11.114355ms delta=4s 999ms 966µs 95ns ago
[INFO] [stdout] 2025-10-16T10:46:22.367445Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 966µs 95ns ago
[INFO] [stdout] 2025-10-16T10:46:22.367449Z TRACE timesimp: sleeping to spread out requests delay=519.239073ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.367491Z TRACE new{response=Response { client: 2025-10-16T10:46:22.345135274Z, server: 2025-10-16T10:46:22.356251144Z } current=2025-10-16T10:46:22.367476033Z}: timesimp::delta: response processing internals latency=11ms 170µs 379ns local_at_midpoint=2025-10-16T10:46:22.356305653Z delta=54µs 509ns ago
[INFO] [stdout] 2025-10-16T10:46:22.367499Z TRACE timesimp: obtained raw offset from server latency=11.170379ms delta=54µs 509ns ago
[INFO] [stdout] 2025-10-16T10:46:22.367503Z TRACE timesimp: sleeping to spread out requests delay=314.140476ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.367533Z TRACE new{response=Response { client: 2025-10-16T10:46:22.345150094Z, server: 2025-10-16T10:46:27.356229354Z } current=2025-10-16T10:46:22.367522124Z}: timesimp::delta: response processing internals latency=11ms 186µs 15ns local_at_midpoint=2025-10-16T10:46:22.356336109Z delta=4s 999ms 893µs 245ns
[INFO] [stdout] 2025-10-16T10:46:22.367539Z TRACE timesimp: obtained raw offset from server latency=11.186015ms delta=4s 999ms 893µs 245ns
[INFO] [stdout] 2025-10-16T10:46:22.367543Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 893µs 245ns
[INFO] [stdout] 2025-10-16T10:46:22.367546Z TRACE timesimp: sleeping to spread out requests delay=1.51972319s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.367570Z TRACE new{response=Response { client: 2025-10-16T10:46:22.344219174Z, server: 2025-10-16T10:46:22.356463774Z } current=2025-10-16T10:46:22.367549193Z}: timesimp::delta: response processing internals latency=11ms 665µs 9ns local_at_midpoint=2025-10-16T10:46:22.355884183Z delta=579µs 591ns
[INFO] [stdout] 2025-10-16T10:46:22.367582Z TRACE timesimp: obtained raw offset from server latency=11.665009ms delta=579µs 591ns
[INFO] [stdout] 2025-10-16T10:46:22.367587Z TRACE timesimp: sleeping to spread out requests delay=73.844719ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.380518Z TRACE new{response=Response { client: 2025-10-16T10:46:22.352491934Z, server: 2025-10-16T10:46:27.367467133Z } current=2025-10-16T10:46:22.380479403Z}: timesimp::delta: response processing internals latency=13ms 993µs 734ns local_at_midpoint=2025-10-16T10:46:22.366485668Z delta=5s 981µs 465ns
[INFO] [stdout] 2025-10-16T10:46:22.380552Z TRACE timesimp: obtained raw offset from server latency=13.993734ms delta=5s 981µs 465ns
[INFO] [stdout] 2025-10-16T10:46:22.380561Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 981µs 465ns
[INFO] [stdout] 2025-10-16T10:46:22.380565Z TRACE timesimp: sleeping to spread out requests delay=1.481123009s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.388036Z TRACE new{response=Response { client: 2025-10-16T10:46:22.365852244Z, server: 2025-10-16T10:46:27.376898623Z } current=2025-10-16T10:46:22.387995923Z}: timesimp::delta: response processing internals latency=11ms 71µs 839ns local_at_midpoint=2025-10-16T10:46:22.376924083Z delta=4s 999ms 974µs 540ns
[INFO] [stdout] 2025-10-16T10:46:22.388073Z TRACE timesimp: obtained raw offset from server latency=11.071839ms delta=4s 999ms 974µs 540ns
[INFO] [stdout] 2025-10-16T10:46:22.388083Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 974µs 540ns
[INFO] [stdout] 2025-10-16T10:46:22.388087Z TRACE timesimp: sleeping to spread out requests delay=428.068186ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.397595Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:22.397624Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.466604Z TRACE new{response=Response { client: 2025-10-16T10:46:22.442787712Z, server: 2025-10-16T10:46:22.455479382Z } current=2025-10-16T10:46:22.466582982Z}: timesimp::delta: response processing internals latency=11ms 897µs 635ns local_at_midpoint=2025-10-16T10:46:22.454685347Z delta=794µs 35ns
[INFO] [stdout] 2025-10-16T10:46:22.466640Z TRACE timesimp: obtained raw offset from server latency=11.897635ms delta=794µs 35ns
[INFO] [stdout] 2025-10-16T10:46:22.466650Z TRACE timesimp: sleeping to spread out requests delay=883.983502ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.473181Z TRACE new{response=Response { client: 2025-10-16T10:46:22.460846372Z, server: 2025-10-16T10:46:27.466979302Z } current=2025-10-16T10:46:22.473156042Z}: timesimp::delta: response processing internals latency=6ms 154µs 835ns local_at_midpoint=2025-10-16T10:46:22.467001207Z delta=4s 999ms 978µs 95ns
[INFO] [stdout] 2025-10-16T10:46:22.473213Z TRACE timesimp: obtained raw offset from server latency=6.154835ms delta=4s 999ms 978µs 95ns
[INFO] [stdout] 2025-10-16T10:46:22.473223Z TRACE timesimp: sleeping to spread out requests delay=85.267235ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.574704Z TRACE new{response=Response { client: 2025-10-16T10:46:22.559470931Z, server: 2025-10-16T10:46:27.566572091Z } current=2025-10-16T10:46:22.57467339Z}: timesimp::delta: response processing internals latency=7ms 601µs 229ns local_at_midpoint=2025-10-16T10:46:22.56707216Z delta=4s 999ms 499µs 931ns
[INFO] [stdout] 2025-10-16T10:46:22.574736Z TRACE timesimp: obtained raw offset from server latency=7.601229ms delta=4s 999ms 499µs 931ns
[INFO] [stdout] 2025-10-16T10:46:22.574746Z TRACE timesimp: sleeping to spread out requests delay=75.434595ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.603950Z TRACE new{response=Response { client: 2025-10-16T10:46:22.401469013Z, server: 2025-10-16T10:46:22.502678251Z } current=2025-10-16T10:46:22.60391132Z}: timesimp::delta: response processing internals latency=101ms 221µs 153ns local_at_midpoint=2025-10-16T10:46:22.502690166Z delta=11µs 915ns ago
[INFO] [stdout] 2025-10-16T10:46:22.604048Z TRACE timesimp: obtained raw offset from server latency=101.221153ms delta=11µs 915ns ago
[INFO] [stdout] 2025-10-16T10:46:22.604075Z DEBUG timesimp: no offset stored, storing initial delta offset=11µs 915ns ago
[INFO] [stdout] 2025-10-16T10:46:22.604093Z TRACE timesimp: sleeping to spread out requests delay=1.81986049s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.670274Z TRACE new{response=Response { client: 2025-10-16T10:46:22.651946229Z, server: 2025-10-16T10:46:27.661051859Z } current=2025-10-16T10:46:22.670250719Z}: timesimp::delta: response processing internals latency=9ms 152µs 245ns local_at_midpoint=2025-10-16T10:46:22.661098474Z delta=4s 999ms 953µs 385ns
[INFO] [stdout] 2025-10-16T10:46:22.670310Z TRACE timesimp: obtained raw offset from server latency=9.152245ms delta=4s 999ms 953µs 385ns
[INFO] [stdout] 2025-10-16T10:46:22.670320Z TRACE timesimp: sleeping to spread out requests delay=1.920818367s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.705211Z TRACE new{response=Response { client: 2025-10-16T10:46:22.682957409Z, server: 2025-10-16T10:46:22.694073829Z } current=2025-10-16T10:46:22.705186509Z}: timesimp::delta: response processing internals latency=11ms 114µs 550ns local_at_midpoint=2025-10-16T10:46:22.694071959Z delta=1µs 870ns
[INFO] [stdout] 2025-10-16T10:46:22.705251Z TRACE timesimp: obtained raw offset from server latency=11.11455ms delta=1µs 870ns
[INFO] [stdout] 2025-10-16T10:46:22.705261Z TRACE timesimp: sleeping to spread out requests delay=1.596807744s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.838807Z TRACE new{response=Response { client: 2025-10-16T10:46:22.817564147Z, server: 2025-10-16T10:46:27.828680137Z } current=2025-10-16T10:46:22.838783287Z}: timesimp::delta: response processing internals latency=10ms 609µs 570ns local_at_midpoint=2025-10-16T10:46:22.828173717Z delta=5s 506µs 420ns
[INFO] [stdout] 2025-10-16T10:46:22.838842Z TRACE timesimp: obtained raw offset from server latency=10.60957ms delta=5s 506µs 420ns
[INFO] [stdout] 2025-10-16T10:46:22.838852Z TRACE timesimp: sleeping to spread out requests delay=311.090558ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:22.911511Z TRACE new{response=Response { client: 2025-10-16T10:46:22.887588196Z, server: 2025-10-16T10:46:17.898714456Z } current=2025-10-16T10:46:22.911486256Z}: timesimp::delta: response processing internals latency=11ms 949µs 30ns local_at_midpoint=2025-10-16T10:46:22.899537226Z delta=5s 822µs 770ns ago
[INFO] [stdout] 2025-10-16T10:46:22.911554Z TRACE timesimp: obtained raw offset from server latency=11.94903ms delta=5s 822µs 770ns ago
[INFO] [stdout] 2025-10-16T10:46:22.911564Z TRACE timesimp: sleeping to spread out requests delay=815.430389ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.175505Z TRACE new{response=Response { client: 2025-10-16T10:46:23.151299432Z, server: 2025-10-16T10:46:28.162411712Z } current=2025-10-16T10:46:23.175476172Z}: timesimp::delta: response processing internals latency=12ms 88µs 370ns local_at_midpoint=2025-10-16T10:46:23.163387802Z delta=4s 999ms 23µs 910ns
[INFO] [stdout] 2025-10-16T10:46:23.175552Z TRACE timesimp: obtained raw offset from server latency=12.08837ms delta=4s 999ms 23µs 910ns
[INFO] [stdout] 2025-10-16T10:46:23.175564Z TRACE timesimp: sleeping to spread out requests delay=547.912333ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.373902Z TRACE new{response=Response { client: 2025-10-16T10:46:23.351569439Z, server: 2025-10-16T10:46:23.362683069Z } current=2025-10-16T10:46:23.373878489Z}: timesimp::delta: response processing internals latency=11ms 154µs 525ns local_at_midpoint=2025-10-16T10:46:23.362723964Z delta=40µs 895ns ago
[INFO] [stdout] 2025-10-16T10:46:23.373936Z TRACE timesimp: obtained raw offset from server latency=11.154525ms delta=40µs 895ns ago
[INFO] [stdout] 2025-10-16T10:46:23.373945Z TRACE timesimp: sleeping to spread out requests delay=219.70692ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.616504Z TRACE new{response=Response { client: 2025-10-16T10:46:23.594287256Z, server: 2025-10-16T10:46:23.605401795Z } current=2025-10-16T10:46:23.616477425Z}: timesimp::delta: response processing internals latency=11ms 95µs 84ns local_at_midpoint=2025-10-16T10:46:23.60538234Z delta=19µs 455ns
[INFO] [stdout] 2025-10-16T10:46:23.616539Z TRACE timesimp: obtained raw offset from server latency=11.095084ms delta=19µs 455ns
[INFO] [stdout] 2025-10-16T10:46:23.616549Z TRACE timesimp: sleeping to spread out requests delay=1.300834037s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.746506Z TRACE new{response=Response { client: 2025-10-16T10:46:23.724253774Z, server: 2025-10-16T10:46:28.735365964Z } current=2025-10-16T10:46:23.746475753Z}: timesimp::delta: response processing internals latency=11ms 110µs 989ns local_at_midpoint=2025-10-16T10:46:23.735364763Z delta=5s 1µs 201ns
[INFO] [stdout] 2025-10-16T10:46:23.746546Z TRACE timesimp: obtained raw offset from server latency=11.110989ms delta=5s 1µs 201ns
[INFO] [stdout] 2025-10-16T10:46:23.746556Z TRACE timesimp: sleeping to spread out requests delay=553.668032ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.751500Z TRACE new{response=Response { client: 2025-10-16T10:46:23.728482264Z, server: 2025-10-16T10:46:18.739595333Z } current=2025-10-16T10:46:23.751475944Z}: timesimp::delta: response processing internals latency=11ms 496µs 840ns local_at_midpoint=2025-10-16T10:46:23.739979104Z delta=5s 383µs 771ns ago
[INFO] [stdout] 2025-10-16T10:46:23.751534Z TRACE timesimp: obtained raw offset from server latency=11.49684ms delta=5s 383µs 771ns ago
[INFO] [stdout] 2025-10-16T10:46:23.751544Z TRACE timesimp: sleeping to spread out requests delay=1.534173316s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.824514Z TRACE new{response=Response { client: 2025-10-16T10:46:22.344910564Z, server: 2025-10-16T10:46:23.084573973Z } current=2025-10-16T10:46:23.824468232Z}: timesimp::delta: response processing internals latency=739ms 778µs 834ns local_at_midpoint=2025-10-16T10:46:23.084689398Z delta=115µs 425ns ago
[INFO] [stdout] 2025-10-16T10:46:23.824553Z TRACE timesimp: obtained raw offset from server latency=739.778834ms delta=115µs 425ns ago
[INFO] [stdout] 2025-10-16T10:46:23.824564Z DEBUG timesimp: no offset stored, storing initial delta offset=115µs 425ns ago
[INFO] [stdout] 2025-10-16T10:46:23.824568Z TRACE timesimp: sleeping to spread out requests delay=1.259983285s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.879591Z TRACE new{response=Response { client: 2025-10-16T10:46:23.863581042Z, server: 2025-10-16T10:46:28.872477982Z } current=2025-10-16T10:46:23.879564311Z}: timesimp::delta: response processing internals latency=7ms 991µs 634ns local_at_midpoint=2025-10-16T10:46:23.871572676Z delta=5s 905µs 306ns
[INFO] [stdout] 2025-10-16T10:46:23.879628Z TRACE timesimp: obtained raw offset from server latency=7.991634ms delta=5s 905µs 306ns
[INFO] [stdout] 2025-10-16T10:46:23.879638Z TRACE timesimp: sleeping to spread out requests delay=1.12920948s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:23.909831Z TRACE new{response=Response { client: 2025-10-16T10:46:23.888577891Z, server: 2025-10-16T10:46:28.899689961Z } current=2025-10-16T10:46:23.909803041Z}: timesimp::delta: response processing internals latency=10ms 612µs 575ns local_at_midpoint=2025-10-16T10:46:23.899190466Z delta=5s 499µs 495ns
[INFO] [stdout] 2025-10-16T10:46:23.909871Z TRACE timesimp: obtained raw offset from server latency=10.612575ms delta=5s 499µs 495ns
[INFO] [stdout] 2025-10-16T10:46:23.909880Z TRACE timesimp: sleeping to spread out requests delay=981.186106ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:24.323515Z TRACE new{response=Response { client: 2025-10-16T10:46:24.301255836Z, server: 2025-10-16T10:46:29.312369215Z } current=2025-10-16T10:46:24.323489785Z}: timesimp::delta: response processing internals latency=11ms 116µs 974ns local_at_midpoint=2025-10-16T10:46:24.31237281Z delta=4s 999ms 996µs 405ns
[INFO] [stdout] 2025-10-16T10:46:24.323553Z TRACE timesimp: obtained raw offset from server latency=11.116974ms delta=4s 999ms 996µs 405ns
[INFO] [stdout] 2025-10-16T10:46:24.323563Z TRACE timesimp: response deltas sorted by latency deltas=[5000.50642, 4999.97454, 5000.001201, 4999.996405, 4999.02391]
[INFO] [stdout] 2025-10-16T10:46:24.323570Z TRACE timesimp: statistics about response deltas median=5000.001201 mean=4999.9004952 variance=0.29009236410266226 stddev=0.5386022318025263
[INFO] [stdout] 2025-10-16T10:46:24.323576Z TRACE timesimp: eliminated outliers inliers=[5000.50642, 4999.97454, 5000.001201, 4999.996405]
[INFO] [stdout] 2025-10-16T10:46:24.323581Z DEBUG timesimp: storing calculated offset offset=5s 119µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2025-10-16T10:46:24.325772Z TRACE new{response=Response { client: 2025-10-16T10:46:24.303565405Z, server: 2025-10-16T10:46:24.314670005Z } current=2025-10-16T10:46:24.325757425Z}: timesimp::delta: response processing internals latency=11ms 96µs 10ns local_at_midpoint=2025-10-16T10:46:24.314661415Z delta=8µs 590ns
[INFO] [stdout] 2025-10-16T10:46:24.325792Z TRACE timesimp: obtained raw offset from server latency=11.09601ms delta=8µs 590ns
[INFO] [stdout] 2025-10-16T10:46:24.325799Z TRACE timesimp: sleeping to spread out requests delay=1.597284359s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:24.328765Z TRACE new{response=Response { client: 2025-10-16T10:46:24.326578715Z, server: 2025-10-16T10:46:24.327660965Z } current=2025-10-16T10:46:24.328740395Z}: timesimp::delta: response processing internals latency=1ms 80µs 840ns local_at_midpoint=2025-10-16T10:46:24.327659555Z delta=1µs 410ns
[INFO] [stdout] 2025-10-16T10:46:24.328795Z TRACE timesimp: obtained raw offset from server latency=1.08084ms delta=1µs 410ns
[INFO] [stdout] 2025-10-16T10:46:24.328804Z TRACE timesimp: sleeping to spread out requests delay=906.787242ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:24.611825Z TRACE new{response=Response { client: 2025-10-16T10:46:24.591578471Z, server: 2025-10-16T10:46:29.601689601Z } current=2025-10-16T10:46:24.611799191Z}: timesimp::delta: response processing internals latency=10ms 110µs 360ns local_at_midpoint=2025-10-16T10:46:24.601688831Z delta=5s 770ns
[INFO] [stdout] 2025-10-16T10:46:24.611865Z TRACE timesimp: obtained raw offset from server latency=10.11036ms delta=5s 770ns
[INFO] [stdout] 2025-10-16T10:46:24.611876Z TRACE timesimp: response deltas sorted by latency deltas=[4999.964745, 4999.978095, 4999.499931, 4999.953385, 5000.00077]
[INFO] [stdout] 2025-10-16T10:46:24.611883Z TRACE timesimp: statistics about response deltas median=4999.499931 mean=4999.8793852 variance=0.0453064125101454 stddev=0.21285303030529165
[INFO] [stdout] 2025-10-16T10:46:24.611889Z TRACE timesimp: eliminated outliers inliers=[4999.499931]
[INFO] [stdout] 2025-10-16T10:46:24.611892Z DEBUG timesimp: storing calculated offset offset=4s 999ms 499µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-10-16T10:46:24.628724Z TRACE new{response=Response { client: 2025-10-16T10:46:24.425575963Z, server: 2025-10-16T10:46:24.528481542Z } current=2025-10-16T10:46:24.628696701Z}: timesimp::delta: response processing internals latency=101ms 560µs 369ns local_at_midpoint=2025-10-16T10:46:24.527136332Z delta=1ms 345µs 210ns
[INFO] [stdout] 2025-10-16T10:46:24.628842Z TRACE timesimp: obtained raw offset from server latency=101.560369ms delta=1ms 345µs 210ns
[INFO] [stdout] 2025-10-16T10:46:24.628876Z TRACE timesimp: sleeping to spread out requests delay=1.476244258s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:24.913821Z TRACE new{response=Response { client: 2025-10-16T10:46:24.892570717Z, server: 2025-10-16T10:46:29.903686327Z } current=2025-10-16T10:46:24.913795527Z}: timesimp::delta: response processing internals latency=10ms 612µs 405ns local_at_midpoint=2025-10-16T10:46:24.903183122Z delta=5s 503µs 205ns
[INFO] [stdout] 2025-10-16T10:46:24.913854Z TRACE timesimp: obtained raw offset from server latency=10.612405ms delta=5s 503µs 205ns
[INFO] [stdout] 2025-10-16T10:46:24.913863Z TRACE timesimp: sleeping to spread out requests delay=1.809679269s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:24.941531Z TRACE new{response=Response { client: 2025-10-16T10:46:24.918557476Z, server: 2025-10-16T10:46:24.929660136Z } current=2025-10-16T10:46:24.941505636Z}: timesimp::delta: response processing internals latency=11ms 474µs 80ns local_at_midpoint=2025-10-16T10:46:24.930031556Z delta=371µs 420ns ago
[INFO] [stdout] 2025-10-16T10:46:24.941567Z TRACE timesimp: obtained raw offset from server latency=11.47408ms delta=371µs 420ns ago
[INFO] [stdout] 2025-10-16T10:46:24.941577Z TRACE timesimp: response deltas sorted by latency deltas=[0.019455, -0.040895, -0.37142, 0.579591, 0.794035]
[INFO] [stdout] 2025-10-16T10:46:24.941584Z TRACE timesimp: statistics about response deltas median=-0.37142 mean=0.1961532 variance=0.22851015840119998 stddev=0.4780273615612395
[INFO] [stdout] 2025-10-16T10:46:24.941589Z TRACE timesimp: eliminated outliers inliers=[0.019455, -0.040895, -0.37142]
[INFO] [stdout] 2025-10-16T10:46:24.941593Z DEBUG timesimp: storing calculated offset offset=130µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2025-10-16T10:46:25.030831Z TRACE new{response=Response { client: 2025-10-16T10:46:25.010567075Z, server: 2025-10-16T10:46:30.020668965Z } current=2025-10-16T10:46:25.030805795Z}: timesimp::delta: response processing internals latency=10ms 119µs 360ns local_at_midpoint=2025-10-16T10:46:25.020686435Z delta=4s 999ms 982µs 530ns
[INFO] [stdout] 2025-10-16T10:46:25.030866Z TRACE timesimp: obtained raw offset from server latency=10.11936ms delta=4s 999ms 982µs 530ns
[INFO] [stdout] 2025-10-16T10:46:25.030897Z TRACE timesimp: sleeping to spread out requests delay=1.531323904s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:25.238772Z TRACE new{response=Response { client: 2025-10-16T10:46:25.236563652Z, server: 2025-10-16T10:46:25.237656472Z } current=2025-10-16T10:46:25.238746752Z}: timesimp::delta: response processing internals latency=1ms 91µs 550ns local_at_midpoint=2025-10-16T10:46:25.237655202Z delta=1µs 270ns
[INFO] [stdout] 2025-10-16T10:46:25.238815Z TRACE timesimp: obtained raw offset from server latency=1.09155ms delta=1µs 270ns
[INFO] [stdout] 2025-10-16T10:46:25.238826Z TRACE timesimp: sleeping to spread out requests delay=1.67931976s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:25.308717Z TRACE new{response=Response { client: 2025-10-16T10:46:25.286675401Z, server: 2025-10-16T10:46:20.297568561Z } current=2025-10-16T10:46:25.308689611Z}: timesimp::delta: response processing internals latency=11ms 7µs 105ns local_at_midpoint=2025-10-16T10:46:25.297682506Z delta=5s 113µs 945ns ago
[INFO] [stdout] 2025-10-16T10:46:25.308755Z TRACE timesimp: obtained raw offset from server latency=11.007105ms delta=5s 113µs 945ns ago
[INFO] [stdout] 2025-10-16T10:46:25.308765Z TRACE timesimp: sleeping to spread out requests delay=826.001048ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:25.945921Z TRACE new{response=Response { client: 2025-10-16T10:46:25.924584812Z, server: 2025-10-16T10:46:25.934786181Z } current=2025-10-16T10:46:25.945894532Z}: timesimp::delta: response processing internals latency=10ms 654µs 860ns local_at_midpoint=2025-10-16T10:46:25.935239672Z delta=453µs 491ns ago
[INFO] [stdout] 2025-10-16T10:46:25.945960Z TRACE timesimp: obtained raw offset from server latency=10.65486ms delta=453µs 491ns ago
[INFO] [stdout] 2025-10-16T10:46:25.945971Z TRACE timesimp: sleeping to spread out requests delay=530.089442ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:26.157823Z TRACE new{response=Response { client: 2025-10-16T10:46:26.135576829Z, server: 2025-10-16T10:46:21.146682769Z } current=2025-10-16T10:46:26.157798758Z}: timesimp::delta: response processing internals latency=11ms 110µs 964ns local_at_midpoint=2025-10-16T10:46:26.146687793Z delta=5s 5µs 24ns ago
[INFO] [stdout] 2025-10-16T10:46:26.157860Z TRACE timesimp: obtained raw offset from server latency=11.110964ms delta=5s 5µs 24ns ago
[INFO] [stdout] 2025-10-16T10:46:26.157871Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.113945, -5000.005024, -4999.966095, -5000.383771, -5000.82277]
[INFO] [stdout] 2025-10-16T10:46:26.157878Z TRACE timesimp: statistics about response deltas median=-4999.966095 mean=-5000.258320999999 variance=0.12618505269044417 stddev=0.3552253547967039
[INFO] [stdout] 2025-10-16T10:46:26.157883Z TRACE timesimp: eliminated outliers inliers=[-5000.113945, -5000.005024, -4999.966095]
[INFO] [stdout] 2025-10-16T10:46:26.157887Z DEBUG timesimp: storing calculated offset offset=5s 28µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-10-16T10:46:26.309074Z TRACE new{response=Response { client: 2025-10-16T10:46:26.106582999Z, server: 2025-10-16T10:46:26.207806738Z } current=2025-10-16T10:46:26.309048366Z}: timesimp::delta: response processing internals latency=101ms 232µs 683ns local_at_midpoint=2025-10-16T10:46:26.207815682Z delta=8µs 944ns ago
[INFO] [stdout] 2025-10-16T10:46:26.309112Z TRACE timesimp: obtained raw offset from server latency=101.232683ms delta=8µs 944ns ago
[INFO] [stdout] 2025-10-16T10:46:26.309122Z TRACE timesimp: sleeping to spread out requests delay=835.127288ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:26.499818Z TRACE new{response=Response { client: 2025-10-16T10:46:26.477570554Z, server: 2025-10-16T10:46:26.488686404Z } current=2025-10-16T10:46:26.499790363Z}: timesimp::delta: response processing internals latency=11ms 109µs 904ns local_at_midpoint=2025-10-16T10:46:26.488680458Z delta=5µs 946ns
[INFO] [stdout] 2025-10-16T10:46:26.499923Z TRACE timesimp: obtained raw offset from server latency=11.109904ms delta=5µs 946ns
[INFO] [stdout] 2025-10-16T10:46:26.499957Z TRACE timesimp: response deltas sorted by latency deltas=[-0.453491, 0.00859, 0.005946, 0.00187, -0.054509]
[INFO] [stdout] 2025-10-16T10:46:26.499982Z TRACE timesimp: statistics about response deltas median=0.005946 mean=-0.0983188 variance=0.0401012564777 stddev=0.20025298119553675
[INFO] [stdout] 2025-10-16T10:46:26.500010Z TRACE timesimp: eliminated outliers inliers=[0.00859, 0.005946, 0.00187, -0.054509]
[INFO] [stdout] 2025-10-16T10:46:26.500030Z DEBUG timesimp: storing calculated offset offset=9µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-10-16T10:46:26.582988Z TRACE new{response=Response { client: 2025-10-16T10:46:26.562690863Z, server: 2025-10-16T10:46:31.572851982Z } current=2025-10-16T10:46:26.582960782Z}: timesimp::delta: response processing internals latency=10ms 134µs 959ns local_at_midpoint=2025-10-16T10:46:26.572825822Z delta=5s 26µs 160ns
[INFO] [stdout] 2025-10-16T10:46:26.583026Z TRACE timesimp: obtained raw offset from server latency=10.134959ms delta=5s 26µs 160ns
[INFO] [stdout] 2025-10-16T10:46:26.583036Z TRACE timesimp: sleeping to spread out requests delay=931.658298ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:26.606384Z TRACE new{response=Response { client: 2025-10-16T10:46:25.086586024Z, server: 2025-10-16T10:46:25.846460323Z } current=2025-10-16T10:46:26.606356722Z}: timesimp::delta: response processing internals latency=759ms 885µs 349ns local_at_midpoint=2025-10-16T10:46:25.846471373Z delta=11µs 50ns ago
[INFO] [stdout] 2025-10-16T10:46:26.606421Z TRACE timesimp: obtained raw offset from server latency=759.885349ms delta=11µs 50ns ago
[INFO] [stdout] 2025-10-16T10:46:26.606453Z TRACE timesimp: sleeping to spread out requests delay=35.799278ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:26.744110Z TRACE new{response=Response { client: 2025-10-16T10:46:26.72387401Z, server: 2025-10-16T10:46:31.73397704Z } current=2025-10-16T10:46:26.7440843Z}: timesimp::delta: response processing internals latency=10ms 105µs 145ns local_at_midpoint=2025-10-16T10:46:26.733979155Z delta=4s 999ms 997µs 885ns
[INFO] [stdout] 2025-10-16T10:46:26.744141Z TRACE timesimp: obtained raw offset from server latency=10.105145ms delta=4s 999ms 997µs 885ns
[INFO] [stdout] 2025-10-16T10:46:26.744150Z TRACE timesimp: sleeping to spread out requests delay=1.924500439s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:26.921270Z TRACE new{response=Response { client: 2025-10-16T10:46:26.919062627Z, server: 2025-10-16T10:46:26.920150937Z } current=2025-10-16T10:46:26.921238367Z}: timesimp::delta: response processing internals latency=1ms 87µs 870ns local_at_midpoint=2025-10-16T10:46:26.920150497Z delta=440ns
[INFO] [stdout] 2025-10-16T10:46:26.921309Z TRACE timesimp: obtained raw offset from server latency=1.08787ms delta=440ns
[INFO] [stdout] 2025-10-16T10:46:26.921319Z TRACE timesimp: sleeping to spread out requests delay=1.495315699s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:27.348031Z TRACE new{response=Response { client: 2025-10-16T10:46:27.145578904Z, server: 2025-10-16T10:46:27.246777022Z } current=2025-10-16T10:46:27.348004411Z}: timesimp::delta: response processing internals latency=101ms 212µs 753ns local_at_midpoint=2025-10-16T10:46:27.246791657Z delta=14µs 635ns ago
[INFO] [stdout] 2025-10-16T10:46:27.348069Z TRACE timesimp: obtained raw offset from server latency=101.212753ms delta=14µs 635ns ago
[INFO] [stdout] 2025-10-16T10:46:27.348080Z TRACE timesimp: sleeping to spread out requests delay=1.700574481s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:27.536912Z TRACE new{response=Response { client: 2025-10-16T10:46:27.516578569Z, server: 2025-10-16T10:46:32.526692149Z } current=2025-10-16T10:46:27.536881768Z}: timesimp::delta: response processing internals latency=10ms 151µs 599ns local_at_midpoint=2025-10-16T10:46:27.526730168Z delta=4s 999ms 961µs 981ns
[INFO] [stdout] 2025-10-16T10:46:27.536949Z TRACE timesimp: obtained raw offset from server latency=10.151599ms delta=4s 999ms 961µs 981ns
[INFO] [stdout] 2025-10-16T10:46:27.536959Z TRACE timesimp: response deltas sorted by latency deltas=[5000.905306, 4999.98253, 5000.02616, 4999.961981, 5000.981465]
[INFO] [stdout] 2025-10-16T10:46:27.536966Z TRACE timesimp: statistics about response deltas median=5000.02616 mean=5000.3714884 variance=0.2738173335119795 stddev=0.5232755808481603
[INFO] [stdout] 2025-10-16T10:46:27.536971Z TRACE timesimp: eliminated outliers inliers=[4999.98253, 5000.02616, 4999.961981]
[INFO] [stdout] 2025-10-16T10:46:27.536975Z DEBUG timesimp: storing calculated offset offset=4s 999ms 990µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-10-16T10:46:28.419797Z TRACE new{response=Response { client: 2025-10-16T10:46:28.417586295Z, server: 2025-10-16T10:46:28.418687255Z } current=2025-10-16T10:46:28.419774156Z}: timesimp::delta: response processing internals latency=1ms 93µs 930ns local_at_midpoint=2025-10-16T10:46:28.418680225Z delta=7µs 30ns
[INFO] [stdout] 2025-10-16T10:46:28.419830Z TRACE timesimp: obtained raw offset from server latency=1.09393ms delta=7µs 30ns
[INFO] [stdout] 2025-10-16T10:46:28.419841Z TRACE timesimp: response deltas sorted by latency deltas=[0.00141, -0.002575, 0.00044, 0.00127, 0.00703]
[INFO] [stdout] 2025-10-16T10:46:28.419847Z TRACE timesimp: statistics about response deltas median=0.00044 mean=0.001515 variance=1.20925e-5 stddev=0.0034774272098780155
[INFO] [stdout] 2025-10-16T10:46:28.419853Z TRACE timesimp: eliminated outliers inliers=[0.00141, -0.002575, 0.00044, 0.00127]
[INFO] [stdout] 2025-10-16T10:46:28.419857Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-10-16T10:46:28.618600Z TRACE new{response=Response { client: 2025-10-16T10:46:26.642653401Z, server: 2025-10-16T10:46:27.630571037Z } current=2025-10-16T10:46:28.618574242Z}: timesimp::delta: response processing internals latency=987ms 960µs 420ns local_at_midpoint=2025-10-16T10:46:27.630613821Z delta=42µs 784ns ago
[INFO] [stdout] 2025-10-16T10:46:28.618645Z TRACE timesimp: obtained raw offset from server latency=987.96042ms delta=42µs 784ns ago
[INFO] [stdout] 2025-10-16T10:46:28.618655Z TRACE timesimp: sleeping to spread out requests delay=627.927834ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:28.690814Z TRACE new{response=Response { client: 2025-10-16T10:46:28.670572892Z, server: 2025-10-16T10:46:33.680684722Z } current=2025-10-16T10:46:28.690787141Z}: timesimp::delta: response processing internals latency=10ms 107µs 124ns local_at_midpoint=2025-10-16T10:46:28.680680016Z delta=5s 4µs 706ns
[INFO] [stdout] 2025-10-16T10:46:28.690850Z TRACE timesimp: obtained raw offset from server latency=10.107124ms delta=5s 4µs 706ns
[INFO] [stdout] 2025-10-16T10:46:28.690860Z TRACE timesimp: response deltas sorted by latency deltas=[4999.997885, 5000.004706, 5000.503205, 5000.499495, 4999.893245]
[INFO] [stdout] 2025-10-16T10:46:28.690867Z TRACE timesimp: statistics about response deltas median=5000.503205 mean=5000.1797072 variance=0.08816509701921706 stddev=0.29692608005902255
[INFO] [stdout] 2025-10-16T10:46:28.690873Z TRACE timesimp: eliminated outliers inliers=[5000.503205, 5000.499495]
[INFO] [stdout] 2025-10-16T10:46:28.690876Z DEBUG timesimp: storing calculated offset offset=5s 501µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-10-16T10:46:29.252068Z TRACE new{response=Response { client: 2025-10-16T10:46:29.050573976Z, server: 2025-10-16T10:46:29.150799425Z } current=2025-10-16T10:46:29.252040083Z}: timesimp::delta: response processing internals latency=100ms 733µs 53ns local_at_midpoint=2025-10-16T10:46:29.151307029Z delta=507µs 604ns ago
[INFO] [stdout] 2025-10-16T10:46:29.252103Z TRACE timesimp: obtained raw offset from server latency=100.733053ms delta=507µs 604ns ago
[INFO] [stdout] 2025-10-16T10:46:29.252113Z TRACE timesimp: response deltas sorted by latency deltas=[-0.507604, -0.014635, -0.011915, -0.008944, 1.34521]
[INFO] [stdout] 2025-10-16T10:46:29.252121Z TRACE timesimp: statistics about response deltas median=-0.011915 mean=0.16042240000000002 variance=0.4847527945983 stddev=0.6962419081025646
[INFO] [stdout] 2025-10-16T10:46:29.252126Z TRACE timesimp: eliminated outliers inliers=[-0.507604, -0.014635, -0.011915, -0.008944]
[INFO] [stdout] 2025-10-16T10:46:29.252130Z DEBUG timesimp: storing calculated offset offset=135µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-10-16T10:46:31.198601Z TRACE new{response=Response { client: 2025-10-16T10:46:29.248399663Z, server: 2025-10-16T10:46:30.223572439Z } current=2025-10-16T10:46:31.198574505Z}: timesimp::delta: response processing internals latency=975ms 87µs 421ns local_at_midpoint=2025-10-16T10:46:30.223487084Z delta=85µs 355ns
[INFO] [stdout] 2025-10-16T10:46:31.198636Z TRACE timesimp: obtained raw offset from server latency=975.087421ms delta=85µs 355ns
[INFO] [stdout] 2025-10-16T10:46:31.198646Z TRACE timesimp: sleeping to spread out requests delay=1.176856579s max_jitter=2s
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-0c65a2e6eb3445c6)
[INFO] [stdout] 2025-10-16T10:46:34.099601Z TRACE new{response=Response { client: 2025-10-16T10:46:32.377573298Z, server: 2025-10-16T10:46:33.238569515Z } current=2025-10-16T10:46:34.099570942Z}: timesimp::delta: response processing internals latency=860ms 998µs 822ns local_at_midpoint=2025-10-16T10:46:33.23857212Z delta=2µs 605ns ago
[INFO] [stdout] 2025-10-16T10:46:34.099656Z TRACE timesimp: obtained raw offset from server latency=860.998822ms delta=2µs 605ns ago
[INFO] [stdout] 2025-10-16T10:46:34.099668Z TRACE timesimp: response deltas sorted by latency deltas=[-0.115425, -0.01105, -0.002605, 0.085355, -0.042784]
[INFO] [stdout] 2025-10-16T10:46:34.099675Z TRACE timesimp: statistics about response deltas median=-0.002605 mean=-0.0173018 variance=0.005267751103699999 stddev=0.0725792746154162
[INFO] [stdout] 2025-10-16T10:46:34.099680Z TRACE timesimp: eliminated outliers inliers=[-0.01105, -0.002605, -0.042784]
[INFO] [stdout] 2025-10-16T10:46:34.099684Z DEBUG timesimp: storing calculated offset offset=18µ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.76s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-10-16T10:46:34.103633Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:34.103751Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.104150Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-16T10:46:34.104385Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.104514Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-10-16T10:46:34.104571Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.104910Z TRACE new{response=Response { client: 2025-10-16T10:46:34.104877833Z, server: 2025-10-16T10:46:34.104877953Z } current=2025-10-16T10:46:34.104878133Z}: timesimp::delta: response processing internals latency=150ns local_at_midpoint=2025-10-16T10:46:34.104877983Z delta=30ns ago
[INFO] [stdout] 2025-10-16T10:46:34.104966Z TRACE timesimp: obtained raw offset from server latency=150ns delta=30ns ago
[INFO] [stdout] 2025-10-16T10:46:34.104996Z DEBUG timesimp: no offset stored, storing initial delta offset=30ns ago
[INFO] [stdout] 2025-10-16T10:46:34.105017Z TRACE timesimp: sleeping to spread out requests delay=1.753142347s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.105611Z TRACE new{response=Response { client: 2025-10-16T10:46:34.105587573Z, server: 2025-10-16T10:46:34.105587793Z } current=2025-10-16T10:46:34.105587962Z}: timesimp::delta: response processing internals latency=194ns local_at_midpoint=2025-10-16T10:46:34.105587767Z delta=26ns
[INFO] [stdout] 2025-10-16T10:46:34.105633Z TRACE timesimp: obtained raw offset from server latency=194ns delta=26ns
[INFO] [stdout] 2025-10-16T10:46:34.105651Z TRACE timesimp: sleeping to spread out requests delay=306.891185ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.103639Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-10-16T10:46:34.107125Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.107500Z TRACE new{response=Response { client: 2025-10-16T10:46:34.107476433Z, server: 2025-10-16T10:46:29.107476553Z } current=2025-10-16T10:46:34.107477102Z}: timesimp::delta: response processing internals latency=334ns local_at_midpoint=2025-10-16T10:46:34.107476767Z delta=5s 214ns ago
[INFO] [stdout] 2025-10-16T10:46:34.107549Z TRACE timesimp: obtained raw offset from server latency=334ns delta=5s 214ns ago
[INFO] [stdout] 2025-10-16T10:46:34.107576Z TRACE timesimp: sleeping to spread out requests delay=254.582544ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.108337Z TRACE new{response=Response { client: 2025-10-16T10:46:34.108320212Z, server: 2025-10-16T10:46:39.108320432Z } current=2025-10-16T10:46:34.108320532Z}: timesimp::delta: response processing internals latency=160ns local_at_midpoint=2025-10-16T10:46:34.108320372Z delta=5s 60ns
[INFO] [stdout] 2025-10-16T10:46:34.108355Z TRACE timesimp: obtained raw offset from server latency=160ns delta=5s 60ns
[INFO] [stdout] 2025-10-16T10:46:34.108361Z TRACE timesimp: sleeping to spread out requests delay=1.428406521s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.363021Z TRACE new{response=Response { client: 2025-10-16T10:46:34.362994979Z, server: 2025-10-16T10:46:29.362995209Z } current=2025-10-16T10:46:34.362995399Z}: timesimp::delta: response processing internals latency=210ns local_at_midpoint=2025-10-16T10:46:34.362995189Z delta=4s 999ms 999µs 980ns ago
[INFO] [stdout] 2025-10-16T10:46:34.363061Z TRACE timesimp: obtained raw offset from server latency=210ns delta=4s 999ms 999µs 980ns ago
[INFO] [stdout] 2025-10-16T10:46:34.363070Z TRACE timesimp: sleeping to spread out requests delay=1.74729391s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:34.413902Z TRACE new{response=Response { client: 2025-10-16T10:46:34.413871678Z, server: 2025-10-16T10:46:34.413872078Z } current=2025-10-16T10:46:34.413872278Z}: timesimp::delta: response processing internals latency=300ns local_at_midpoint=2025-10-16T10:46:34.413871978Z delta=100ns
[INFO] [stdout] 2025-10-16T10:46:34.413944Z TRACE timesimp: obtained raw offset from server latency=300ns delta=100ns
[INFO] [stdout] 2025-10-16T10:46:34.413952Z TRACE timesimp: sleeping to spread out requests delay=1.19069951s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:35.538600Z TRACE new{response=Response { client: 2025-10-16T10:46:35.538575841Z, server: 2025-10-16T10:46:40.538576041Z } current=2025-10-16T10:46:35.538576232Z}: timesimp::delta: response processing internals latency=195ns local_at_midpoint=2025-10-16T10:46:35.538576036Z delta=5s 5ns
[INFO] [stdout] 2025-10-16T10:46:35.538846Z TRACE timesimp: obtained raw offset from server latency=195ns delta=5s 5ns
[INFO] [stdout] 2025-10-16T10:46:35.538891Z TRACE timesimp: sleeping to spread out requests delay=1.203715495s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:35.605612Z TRACE new{response=Response { client: 2025-10-16T10:46:35.605586651Z, server: 2025-10-16T10:46:35.60558686Z } current=2025-10-16T10:46:35.60558732Z}: timesimp::delta: response processing internals latency=334ns local_at_midpoint=2025-10-16T10:46:35.605586985Z delta=125ns ago
[INFO] [stdout] 2025-10-16T10:46:35.605657Z TRACE timesimp: obtained raw offset from server latency=334ns delta=125ns ago
[INFO] [stdout] 2025-10-16T10:46:35.605666Z TRACE timesimp: sleeping to spread out requests delay=1.870711676s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:35.861505Z TRACE new{response=Response { client: 2025-10-16T10:46:35.861480537Z, server: 2025-10-16T10:46:35.861480787Z } current=2025-10-16T10:46:35.861480977Z}: timesimp::delta: response processing internals latency=220ns local_at_midpoint=2025-10-16T10:46:35.861480757Z delta=30ns
[INFO] [stdout] 2025-10-16T10:46:35.861541Z TRACE timesimp: obtained raw offset from server latency=220ns delta=30ns
[INFO] [stdout] 2025-10-16T10:46:35.861550Z TRACE timesimp: sleeping to spread out requests delay=116.025995ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:35.978826Z TRACE new{response=Response { client: 2025-10-16T10:46:35.978803165Z, server: 2025-10-16T10:46:35.978803335Z } current=2025-10-16T10:46:35.978803525Z}: timesimp::delta: response processing internals latency=180ns local_at_midpoint=2025-10-16T10:46:35.978803345Z delta=10ns ago
[INFO] [stdout] 2025-10-16T10:46:35.978864Z TRACE timesimp: obtained raw offset from server latency=180ns delta=10ns ago
[INFO] [stdout] 2025-10-16T10:46:35.978872Z TRACE timesimp: sleeping to spread out requests delay=560.001154ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:36.111889Z TRACE new{response=Response { client: 2025-10-16T10:46:36.111865363Z, server: 2025-10-16T10:46:31.111865723Z } current=2025-10-16T10:46:36.111865883Z}: timesimp::delta: response processing internals latency=260ns local_at_midpoint=2025-10-16T10:46:36.111865623Z delta=4s 999ms 999µs 900ns ago
[INFO] [stdout] 2025-10-16T10:46:36.111923Z TRACE timesimp: obtained raw offset from server latency=260ns delta=4s 999ms 999µs 900ns ago
[INFO] [stdout] 2025-10-16T10:46:36.111933Z TRACE timesimp: sleeping to spread out requests delay=274.789399ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:36.388338Z TRACE new{response=Response { client: 2025-10-16T10:46:36.388314199Z, server: 2025-10-16T10:46:31.388314679Z } current=2025-10-16T10:46:36.388314829Z}: timesimp::delta: response processing internals latency=315ns local_at_midpoint=2025-10-16T10:46:36.388314514Z delta=4s 999ms 999µs 835ns ago
[INFO] [stdout] 2025-10-16T10:46:36.388374Z TRACE timesimp: obtained raw offset from server latency=315ns delta=4s 999ms 999µs 835ns ago
[INFO] [stdout] 2025-10-16T10:46:36.388383Z TRACE timesimp: sleeping to spread out requests delay=1.737806605s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:36.540623Z TRACE new{response=Response { client: 2025-10-16T10:46:36.540598837Z, server: 2025-10-16T10:46:36.540599037Z } current=2025-10-16T10:46:36.540599237Z}: timesimp::delta: response processing internals latency=200ns local_at_midpoint=2025-10-16T10:46:36.540599037Z delta=0s
[INFO] [stdout] 2025-10-16T10:46:36.540660Z TRACE timesimp: obtained raw offset from server latency=200ns delta=0s
[INFO] [stdout] 2025-10-16T10:46:36.540678Z TRACE timesimp: sleeping to spread out requests delay=808.823689ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:36.744604Z TRACE new{response=Response { client: 2025-10-16T10:46:36.744572354Z, server: 2025-10-16T10:46:41.744572724Z } current=2025-10-16T10:46:36.744572884Z}: timesimp::delta: response processing internals latency=265ns local_at_midpoint=2025-10-16T10:46:36.744572619Z delta=5s 105ns
[INFO] [stdout] 2025-10-16T10:46:36.744726Z TRACE timesimp: obtained raw offset from server latency=265ns delta=5s 105ns
[INFO] [stdout] 2025-10-16T10:46:36.744755Z TRACE timesimp: sleeping to spread out requests delay=936.76998ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:37.350602Z TRACE new{response=Response { client: 2025-10-16T10:46:37.350575775Z, server: 2025-10-16T10:46:37.350576085Z } current=2025-10-16T10:46:37.350576295Z}: timesimp::delta: response processing internals latency=260ns local_at_midpoint=2025-10-16T10:46:37.350576035Z delta=50ns
[INFO] [stdout] 2025-10-16T10:46:37.350641Z TRACE timesimp: obtained raw offset from server latency=260ns delta=50ns
[INFO] [stdout] 2025-10-16T10:46:37.350653Z TRACE timesimp: response deltas sorted by latency deltas=[-3e-5, -1e-5, 0.0, 3e-5, 5e-5]
[INFO] [stdout] 2025-10-16T10:46:37.350669Z TRACE timesimp: statistics about response deltas median=0.0 mean=8e-6 variance=1.02e-9 stddev=3.193743884534262e-5
[INFO] [stdout] 2025-10-16T10:46:37.350676Z TRACE timesimp: eliminated outliers inliers=[-3e-5, -1e-5, 0.0, 3e-5]
[INFO] [stdout] 2025-10-16T10:46:37.350680Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2025-10-16T10:46:37.477603Z TRACE new{response=Response { client: 2025-10-16T10:46:37.477575453Z, server: 2025-10-16T10:46:37.477575873Z } current=2025-10-16T10:46:37.477576033Z}: timesimp::delta: response processing internals latency=290ns local_at_midpoint=2025-10-16T10:46:37.477575743Z delta=130ns
[INFO] [stdout] 2025-10-16T10:46:37.477644Z TRACE timesimp: obtained raw offset from server latency=290ns delta=130ns
[INFO] [stdout] 2025-10-16T10:46:37.477660Z TRACE timesimp: sleeping to spread out requests delay=1.361213948s max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:37.682619Z TRACE new{response=Response { client: 2025-10-16T10:46:37.68259184Z, server: 2025-10-16T10:46:42.68259228Z } current=2025-10-16T10:46:37.68259244Z}: timesimp::delta: response processing internals latency=300ns local_at_midpoint=2025-10-16T10:46:37.68259214Z delta=5s 140ns
[INFO] [stdout] 2025-10-16T10:46:37.682750Z TRACE timesimp: obtained raw offset from server latency=300ns delta=5s 140ns
[INFO] [stdout] 2025-10-16T10:46:37.682784Z TRACE timesimp: sleeping to spread out requests delay=488.360111ms max_jitter=2s
[INFO] [stdout] 2025-10-16T10:46:38.127603Z TRACE new{response=Response { client: 2025-10-16T10:46:38.127576854Z, server: 2025-10-16T10:46:33.127577174Z } current=2025-10-16T10:46:38.127577344Z}: timesimp::delta: response processing internals latency=245ns local_at_midpoint=2025-10-16T10:46:38.127577099Z delta=4s 999ms 999µs 925ns ago
[INFO] [stdout] 2025-10-16T10:46:38.127642Z TRACE timesimp: obtained raw offset from server latency=245ns delta=4s 999ms 999µs 925ns ago
[INFO] [stdout] 2025-10-16T10:46:38.127652Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.9999800000005, -4999.999925, -4999.9999, -4999.999835, -5000.000214]
[INFO] [stdout] 2025-10-16T10:46:38.127660Z TRACE timesimp: statistics about response deltas median=-4999.9999 mean=-4999.9999708 variance=2.119569999544932e-8 stddev=0.00014558743076052038
[INFO] [stdout] 2025-10-16T10:46:38.127666Z TRACE timesimp: eliminated outliers inliers=[-4999.9999800000005, -4999.999925, -4999.9999, -4999.999835]
[INFO] [stdout] 2025-10-16T10:46:38.127680Z DEBUG timesimp: storing calculated offset offset=4s 999ms 999µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2025-10-16T10:46:38.172496Z TRACE new{response=Response { client: 2025-10-16T10:46:38.172463463Z, server: 2025-10-16T10:46:43.172463833Z } current=2025-10-16T10:46:38.172464053Z}: timesimp::delta: response processing internals latency=295ns local_at_midpoint=2025-10-16T10:46:38.172463758Z delta=5s 75ns
[INFO] [stdout] 2025-10-16T10:46:38.172614Z TRACE timesimp: obtained raw offset from server latency=295ns delta=5s 75ns
[INFO] [stdout] 2025-10-16T10:46:38.172641Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00006, 5000.000005, 5000.000105, 5000.000075, 5000.00014]
[INFO] [stdout] 2025-10-16T10:46:38.172663Z TRACE timesimp: statistics about response deltas median=5000.000105 mean=5000.000077 variance=2.5575000062989422e-9 stddev=5.057173129623844e-5
[INFO] [stdout] 2025-10-16T10:46:38.172734Z TRACE timesimp: eliminated outliers inliers=[5000.00006, 5000.000105, 5000.000075, 5000.00014]
[INFO] [stdout] 2025-10-16T10:46:38.172753Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2025-10-16T10:46:38.840215Z TRACE new{response=Response { client: 2025-10-16T10:46:38.840190413Z, server: 2025-10-16T10:46:38.840190653Z } current=2025-10-16T10:46:38.840190844Z}: timesimp::delta: response processing internals latency=215ns local_at_midpoint=2025-10-16T10:46:38.840190628Z delta=25ns
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 2025-10-16T10:46:38.840250Z TRACE timesimp: obtained raw offset from server latency=215ns delta=25ns
[INFO] [stdout] 2025-10-16T10:46:38.840258Z TRACE timesimp: response deltas sorted by latency deltas=[2.6e-5, 2.5e-5, 0.00013, 0.0001, -0.000125]
[INFO] [stdout] 2025-10-16T10:46:38.840265Z TRACE timesimp: statistics about response deltas median=0.00013 mean=3.12e-5 variance=9.7397e-9 stddev=9.868991843141831e-5
[INFO] [stdout] 2025-10-16T10:46:38.840271Z TRACE timesimp: eliminated outliers inliers=[0.00013, 0.0001]
[INFO] [stdout] 2025-10-16T10:46:38.840274Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.74s
[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.01s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "799eab14b274186d0a980dd2c370367aa813959344b76d89b86a5a94ab14646b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "799eab14b274186d0a980dd2c370367aa813959344b76d89b86a5a94ab14646b", kill_on_drop: false }`
[INFO] [stdout] 799eab14b274186d0a980dd2c370367aa813959344b76d89b86a5a94ab14646b