[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against master#cdb45c87e2cd43495379f7e867e3cc15dcee9f93 for pr-145838-1
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-1-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-1-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain cdb45c87e2cd43495379f7e867e3cc15dcee9f93
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "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" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 3e35a62dfd0d7d28f917f382c9350d98b1cdf8cfb0adee888d7cd843e011a8fa
[INFO] running `Command { std: "docker" "start" "-a" "3e35a62dfd0d7d28f917f382c9350d98b1cdf8cfb0adee888d7cd843e011a8fa", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "3e35a62dfd0d7d28f917f382c9350d98b1cdf8cfb0adee888d7cd843e011a8fa", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3e35a62dfd0d7d28f917f382c9350d98b1cdf8cfb0adee888d7cd843e011a8fa", kill_on_drop: false }`
[INFO] [stdout] 3e35a62dfd0d7d28f917f382c9350d98b1cdf8cfb0adee888d7cd843e011a8fa
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-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" "-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] e330fbce65ef760b3c17496d1837c8020706186b59db67e832d875743000c658
[INFO] running `Command { std: "docker" "start" "-a" "e330fbce65ef760b3c17496d1837c8020706186b59db67e832d875743000c658", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling jiff v0.2.10
[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 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 tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 7.70s
[INFO] running `Command { std: "docker" "inspect" "e330fbce65ef760b3c17496d1837c8020706186b59db67e832d875743000c658", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "e330fbce65ef760b3c17496d1837c8020706186b59db67e832d875743000c658", kill_on_drop: false }`
[INFO] [stdout] e330fbce65ef760b3c17496d1837c8020706186b59db67e832d875743000c658
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-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" "-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 333220b9b03efa4e3721689e311db582facbcf24b5d07f9e966caf935cf2204e
[INFO] running `Command { std: "docker" "start" "-a" "333220b9b03efa4e3721689e311db582facbcf24b5d07f9e966caf935cf2204e", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling native-tls v0.2.14
[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 tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[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 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 icu_normalizer v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[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.79s
[INFO] running `Command { std: "docker" "inspect" "333220b9b03efa4e3721689e311db582facbcf24b5d07f9e966caf935cf2204e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "333220b9b03efa4e3721689e311db582facbcf24b5d07f9e966caf935cf2204e", kill_on_drop: false }`
[INFO] [stdout] 333220b9b03efa4e3721689e311db582facbcf24b5d07f9e966caf935cf2204e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-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" "-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 5b1591f3392dfffae4301769a8a7377d3bd5dec8a4536727b8827e328b7cb4b4
[INFO] running `Command { std: "docker" "start" "-a" "5b1591f3392dfffae4301769a8a7377d3bd5dec8a4536727b8827e328b7cb4b4", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.16s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-7957b5c2dc13f12b)
[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::client_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-1c01cc53c6a498a7)
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-09-01T12:31:35.301110Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.301093Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-01T12:31:35.301180Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.301186Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.301096Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.301276Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.301272Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.301290Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.301473Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.301554Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.301614Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.301620Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.301709Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.301479Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.301828Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.301579Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.305543Z TRACE new{response=Response { client: 2025-09-01T12:31:35.303147727Z, server: 2025-09-01T12:31:35.304261547Z } current=2025-09-01T12:31:35.305373097Z}: timesimp::delta: response processing internals latency=1ms 112µs 685ns local_at_midpoint=2025-09-01T12:31:35.304260412Z delta=1µs 135ns
[INFO] [stdout] 2025-09-01T12:31:35.305645Z TRACE timesimp: obtained raw offset from server latency=1.112685ms delta=1µs 135ns
[INFO] [stdout] 2025-09-01T12:31:35.305692Z DEBUG timesimp: no offset stored, storing initial delta offset=1µs 135ns
[INFO] [stdout] 2025-09-01T12:31:35.305711Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-01T12:31:35.305723Z TRACE timesimp: sleeping to spread out requests delay=1.62881537s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.305777Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.313700Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:35.313765Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.317399Z TRACE new{response=Response { client: 2025-09-01T12:31:35.302922907Z, server: 2025-09-01T12:31:40.310093637Z } current=2025-09-01T12:31:35.317234317Z}: timesimp::delta: response processing internals latency=7ms 155µs 705ns local_at_midpoint=2025-09-01T12:31:35.310078612Z delta=5s 15µs 25ns
[INFO] [stdout] 2025-09-01T12:31:35.317474Z TRACE timesimp: obtained raw offset from server latency=7.155705ms delta=5s 15µs 25ns
[INFO] [stdout] 2025-09-01T12:31:35.317511Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 15µs 25ns
[INFO] [stdout] 2025-09-01T12:31:35.317531Z TRACE timesimp: sleeping to spread out requests delay=937.549669ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.319422Z TRACE new{response=Response { client: 2025-09-01T12:31:35.303065417Z, server: 2025-09-01T12:31:40.311192267Z } current=2025-09-01T12:31:35.319316426Z}: timesimp::delta: response processing internals latency=8ms 125µs 504ns local_at_midpoint=2025-09-01T12:31:35.311190921Z delta=5s 1µs 346ns
[INFO] [stdout] 2025-09-01T12:31:35.319501Z TRACE timesimp: obtained raw offset from server latency=8.125504ms delta=5s 1µs 346ns
[INFO] [stdout] 2025-09-01T12:31:35.319530Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 346ns
[INFO] [stdout] 2025-09-01T12:31:35.319541Z TRACE timesimp: sleeping to spread out requests delay=1.245942642s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.322840Z TRACE new{response=Response { client: 2025-09-01T12:31:35.302478017Z, server: 2025-09-01T12:31:40.312605587Z } current=2025-09-01T12:31:35.322725596Z}: timesimp::delta: response processing internals latency=10ms 123µs 789ns local_at_midpoint=2025-09-01T12:31:35.312601806Z delta=5s 3µs 781ns
[INFO] [stdout] 2025-09-01T12:31:35.322928Z TRACE timesimp: obtained raw offset from server latency=10.123789ms delta=5s 3µs 781ns
[INFO] [stdout] 2025-09-01T12:31:35.322960Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 3µs 781ns
[INFO] [stdout] 2025-09-01T12:31:35.322989Z TRACE timesimp: sleeping to spread out requests delay=1.226041855s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.324756Z TRACE new{response=Response { client: 2025-09-01T12:31:35.302408547Z, server: 2025-09-01T12:31:35.313529427Z } current=2025-09-01T12:31:35.324646836Z}: timesimp::delta: response processing internals latency=11ms 119µs 144ns local_at_midpoint=2025-09-01T12:31:35.313527691Z delta=1µs 736ns
[INFO] [stdout] 2025-09-01T12:31:35.324774Z TRACE new{response=Response { client: 2025-09-01T12:31:35.302420157Z, server: 2025-09-01T12:31:30.313536667Z } current=2025-09-01T12:31:35.324660596Z}: timesimp::delta: response processing internals latency=11ms 120µs 219ns local_at_midpoint=2025-09-01T12:31:35.313540376Z delta=5s 3µs 709ns ago
[INFO] [stdout] 2025-09-01T12:31:35.324783Z TRACE new{response=Response { client: 2025-09-01T12:31:35.302470857Z, server: 2025-09-01T12:31:40.313588907Z } current=2025-09-01T12:31:35.324694346Z}: timesimp::delta: response processing internals latency=11ms 111µs 744ns local_at_midpoint=2025-09-01T12:31:35.313582601Z delta=5s 6µs 306ns
[INFO] [stdout] 2025-09-01T12:31:35.326522Z TRACE timesimp: obtained raw offset from server latency=11.119144ms delta=1µs 736ns
[INFO] [stdout] 2025-09-01T12:31:35.326685Z TRACE timesimp: obtained raw offset from server latency=11.111744ms delta=5s 6µs 306ns
[INFO] [stdout] 2025-09-01T12:31:35.326710Z TRACE timesimp: sleeping to spread out requests delay=1.227561159s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.326569Z TRACE timesimp: obtained raw offset from server latency=11.120219ms delta=5s 3µs 709ns ago
[INFO] [stdout] 2025-09-01T12:31:35.326721Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 6µs 306ns
[INFO] [stdout] 2025-09-01T12:31:35.326877Z TRACE timesimp: sleeping to spread out requests delay=701.926664ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.326846Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 3µs 709ns ago
[INFO] [stdout] 2025-09-01T12:31:35.326932Z TRACE timesimp: sleeping to spread out requests delay=1.038412357s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.336716Z TRACE new{response=Response { client: 2025-09-01T12:31:35.312588747Z, server: 2025-09-01T12:31:35.323712086Z } current=2025-09-01T12:31:35.336557025Z}: timesimp::delta: response processing internals latency=11ms 984µs 139ns local_at_midpoint=2025-09-01T12:31:35.324572886Z delta=860µs 800ns ago
[INFO] [stdout] 2025-09-01T12:31:35.336777Z TRACE timesimp: obtained raw offset from server latency=11.984139ms delta=860µs 800ns ago
[INFO] [stdout] 2025-09-01T12:31:35.336792Z TRACE timesimp: sleeping to spread out requests delay=1.969796569s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:35.505632Z TRACE new{response=Response { client: 2025-09-01T12:31:35.302798277Z, server: 2025-09-01T12:31:35.404094382Z } current=2025-09-01T12:31:35.505424096Z}: timesimp::delta: response processing internals latency=101ms 312µs 909ns local_at_midpoint=2025-09-01T12:31:35.404111186Z delta=16µs 804ns ago
[INFO] [stdout] 2025-09-01T12:31:35.505701Z TRACE timesimp: obtained raw offset from server latency=101.312909ms delta=16µs 804ns ago
[INFO] [stdout] 2025-09-01T12:31:35.505715Z DEBUG timesimp: no offset stored, storing initial delta offset=16µs 804ns ago
[INFO] [stdout] 2025-09-01T12:31:35.505725Z TRACE timesimp: sleeping to spread out requests delay=1.76627719s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.052208Z TRACE new{response=Response { client: 2025-09-01T12:31:36.029744569Z, server: 2025-09-01T12:31:41.040899628Z } current=2025-09-01T12:31:36.052052558Z}: timesimp::delta: response processing internals latency=11ms 153µs 994ns local_at_midpoint=2025-09-01T12:31:36.040898563Z delta=5s 1µs 65ns
[INFO] [stdout] 2025-09-01T12:31:36.052344Z TRACE timesimp: obtained raw offset from server latency=11.153994ms delta=5s 1µs 65ns
[INFO] [stdout] 2025-09-01T12:31:36.052391Z TRACE timesimp: sleeping to spread out requests delay=845.459033ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.274643Z TRACE new{response=Response { client: 2025-09-01T12:31:36.257067707Z, server: 2025-09-01T12:31:41.266317276Z } current=2025-09-01T12:31:36.274476296Z}: timesimp::delta: response processing internals latency=8ms 704µs 294ns local_at_midpoint=2025-09-01T12:31:36.265772001Z delta=5s 545µs 275ns
[INFO] [stdout] 2025-09-01T12:31:36.274717Z TRACE timesimp: obtained raw offset from server latency=8.704294ms delta=5s 545µs 275ns
[INFO] [stdout] 2025-09-01T12:31:36.274732Z TRACE timesimp: sleeping to spread out requests delay=860.271495ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.388317Z TRACE new{response=Response { client: 2025-09-01T12:31:36.366767621Z, server: 2025-09-01T12:31:31.37802571Z } current=2025-09-01T12:31:36.388164609Z}: timesimp::delta: response processing internals latency=10ms 698µs 494ns local_at_midpoint=2025-09-01T12:31:36.377466115Z delta=4s 999ms 440µs 405ns ago
[INFO] [stdout] 2025-09-01T12:31:36.388445Z TRACE timesimp: obtained raw offset from server latency=10.698494ms delta=4s 999ms 440µs 405ns ago
[INFO] [stdout] 2025-09-01T12:31:36.388479Z TRACE timesimp: sleeping to spread out requests delay=1.055811235s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.573906Z TRACE new{response=Response { client: 2025-09-01T12:31:36.553514461Z, server: 2025-09-01T12:31:41.56364234Z } current=2025-09-01T12:31:36.57375651Z}: timesimp::delta: response processing internals latency=10ms 121µs 24ns local_at_midpoint=2025-09-01T12:31:36.563635485Z delta=5s 6µs 855ns
[INFO] [stdout] 2025-09-01T12:31:36.574023Z TRACE timesimp: obtained raw offset from server latency=10.121024ms delta=5s 6µs 855ns
[INFO] [stdout] 2025-09-01T12:31:36.574060Z TRACE timesimp: sleeping to spread out requests delay=1.029799963s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.578558Z TRACE new{response=Response { client: 2025-09-01T12:31:36.556228641Z, server: 2025-09-01T12:31:36.56734755Z } current=2025-09-01T12:31:36.578462579Z}: timesimp::delta: response processing internals latency=11ms 116µs 969ns local_at_midpoint=2025-09-01T12:31:36.56734561Z delta=1µs 940ns
[INFO] [stdout] 2025-09-01T12:31:36.578610Z TRACE timesimp: obtained raw offset from server latency=11.116969ms delta=1µs 940ns
[INFO] [stdout] 2025-09-01T12:31:36.578623Z TRACE timesimp: sleeping to spread out requests delay=775.153016ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.582187Z TRACE new{response=Response { client: 2025-09-01T12:31:36.56662564Z, server: 2025-09-01T12:31:41.57475519Z } current=2025-09-01T12:31:36.582113219Z}: timesimp::delta: response processing internals latency=7ms 743µs 789ns local_at_midpoint=2025-09-01T12:31:36.574369429Z delta=5s 385µs 761ns
[INFO] [stdout] 2025-09-01T12:31:36.582282Z TRACE timesimp: obtained raw offset from server latency=7.743789ms delta=5s 385µs 761ns
[INFO] [stdout] 2025-09-01T12:31:36.582297Z TRACE timesimp: sleeping to spread out requests delay=188.756776ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.783228Z TRACE new{response=Response { client: 2025-09-01T12:31:36.772723669Z, server: 2025-09-01T12:31:41.777940039Z } current=2025-09-01T12:31:36.783066688Z}: timesimp::delta: response processing internals latency=5ms 171µs 509ns local_at_midpoint=2025-09-01T12:31:36.777895178Z delta=5s 44µs 861ns
[INFO] [stdout] 2025-09-01T12:31:36.783302Z TRACE timesimp: obtained raw offset from server latency=5.171509ms delta=5s 44µs 861ns
[INFO] [stdout] 2025-09-01T12:31:36.783320Z TRACE timesimp: sleeping to spread out requests delay=1.644097269s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.921373Z TRACE new{response=Response { client: 2025-09-01T12:31:36.898778473Z, server: 2025-09-01T12:31:41.910092222Z } current=2025-09-01T12:31:36.921220871Z}: timesimp::delta: response processing internals latency=11ms 221µs 199ns local_at_midpoint=2025-09-01T12:31:36.909999672Z delta=5s 92µs 550ns
[INFO] [stdout] 2025-09-01T12:31:36.921448Z TRACE timesimp: obtained raw offset from server latency=11.221199ms delta=5s 92µs 550ns
[INFO] [stdout] 2025-09-01T12:31:36.921467Z TRACE timesimp: sleeping to spread out requests delay=582.616678ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:36.938023Z TRACE new{response=Response { client: 2025-09-01T12:31:36.93564746Z, server: 2025-09-01T12:31:36.93677713Z } current=2025-09-01T12:31:36.93790177Z}: timesimp::delta: response processing internals latency=1ms 127µs 155ns local_at_midpoint=2025-09-01T12:31:36.936774615Z delta=2µs 515ns
[INFO] [stdout] 2025-09-01T12:31:36.938101Z TRACE timesimp: obtained raw offset from server latency=1.127155ms delta=2µs 515ns
[INFO] [stdout] 2025-09-01T12:31:36.938119Z TRACE timesimp: sleeping to spread out requests delay=360.937061ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.150899Z TRACE new{response=Response { client: 2025-09-01T12:31:35.314949967Z, server: 2025-09-01T12:31:36.232700218Z } current=2025-09-01T12:31:37.150710189Z}: timesimp::delta: response processing internals latency=917ms 880µs 111ns local_at_midpoint=2025-09-01T12:31:36.232830078Z delta=129µs 860ns ago
[INFO] [stdout] 2025-09-01T12:31:37.150986Z TRACE timesimp: obtained raw offset from server latency=917.880111ms delta=129µs 860ns ago
[INFO] [stdout] 2025-09-01T12:31:37.151005Z DEBUG timesimp: no offset stored, storing initial delta offset=129µs 860ns ago
[INFO] [stdout] 2025-09-01T12:31:37.151025Z TRACE timesimp: sleeping to spread out requests delay=1.874235918s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.152073Z TRACE new{response=Response { client: 2025-09-01T12:31:37.13571599Z, server: 2025-09-01T12:31:42.143857559Z } current=2025-09-01T12:31:37.151986009Z}: timesimp::delta: response processing internals latency=8ms 135µs 9ns local_at_midpoint=2025-09-01T12:31:37.143850999Z delta=5s 6µs 560ns
[INFO] [stdout] 2025-09-01T12:31:37.152128Z TRACE timesimp: obtained raw offset from server latency=8.135009ms delta=5s 6µs 560ns
[INFO] [stdout] 2025-09-01T12:31:37.152147Z TRACE timesimp: sleeping to spread out requests delay=462.943545ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.302094Z TRACE new{response=Response { client: 2025-09-01T12:31:37.299660371Z, server: 2025-09-01T12:31:37.300795181Z } current=2025-09-01T12:31:37.301921551Z}: timesimp::delta: response processing internals latency=1ms 130µs 590ns local_at_midpoint=2025-09-01T12:31:37.300790961Z delta=4µs 220ns
[INFO] [stdout] 2025-09-01T12:31:37.302180Z TRACE timesimp: obtained raw offset from server latency=1.13059ms delta=4µs 220ns
[INFO] [stdout] 2025-09-01T12:31:37.302198Z TRACE timesimp: sleeping to spread out requests delay=44.111047ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.330041Z TRACE new{response=Response { client: 2025-09-01T12:31:37.307639281Z, server: 2025-09-01T12:31:37.31876413Z } current=2025-09-01T12:31:37.329898259Z}: timesimp::delta: response processing internals latency=11ms 129µs 489ns local_at_midpoint=2025-09-01T12:31:37.31876877Z delta=4µs 640ns ago
[INFO] [stdout] 2025-09-01T12:31:37.330118Z TRACE timesimp: obtained raw offset from server latency=11.129489ms delta=4µs 640ns ago
[INFO] [stdout] 2025-09-01T12:31:37.330136Z TRACE timesimp: sleeping to spread out requests delay=474.788175ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.349763Z TRACE new{response=Response { client: 2025-09-01T12:31:37.347362338Z, server: 2025-09-01T12:31:37.348510529Z } current=2025-09-01T12:31:37.349631238Z}: timesimp::delta: response processing internals latency=1ms 134µs 450ns local_at_midpoint=2025-09-01T12:31:37.348496788Z delta=13µs 741ns
[INFO] [stdout] 2025-09-01T12:31:37.349832Z TRACE timesimp: obtained raw offset from server latency=1.13445ms delta=13µs 741ns
[INFO] [stdout] 2025-09-01T12:31:37.349847Z TRACE timesimp: sleeping to spread out requests delay=1.787039954s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.376526Z TRACE new{response=Response { client: 2025-09-01T12:31:37.354170858Z, server: 2025-09-01T12:31:37.365267828Z } current=2025-09-01T12:31:37.376374277Z}: timesimp::delta: response processing internals latency=11ms 101µs 709ns local_at_midpoint=2025-09-01T12:31:37.365272567Z delta=4µs 739ns ago
[INFO] [stdout] 2025-09-01T12:31:37.376672Z TRACE timesimp: obtained raw offset from server latency=11.101709ms delta=4µs 739ns ago
[INFO] [stdout] 2025-09-01T12:31:37.376687Z TRACE timesimp: sleeping to spread out requests delay=528.866531ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.471703Z TRACE new{response=Response { client: 2025-09-01T12:31:37.445680013Z, server: 2025-09-01T12:31:32.456825223Z } current=2025-09-01T12:31:37.471556412Z}: timesimp::delta: response processing internals latency=12ms 938µs 199ns local_at_midpoint=2025-09-01T12:31:37.458618212Z delta=5s 1ms 792µs 989ns ago
[INFO] [stdout] 2025-09-01T12:31:37.471776Z TRACE timesimp: obtained raw offset from server latency=12.938199ms delta=5s 1ms 792µs 989ns ago
[INFO] [stdout] 2025-09-01T12:31:37.471793Z TRACE timesimp: sleeping to spread out requests delay=677.951427ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.475289Z TRACE new{response=Response { client: 2025-09-01T12:31:37.272694602Z, server: 2025-09-01T12:31:37.373942417Z } current=2025-09-01T12:31:37.475200182Z}: timesimp::delta: response processing internals latency=101ms 252µs 790ns local_at_midpoint=2025-09-01T12:31:37.373947392Z delta=4µs 975ns ago
[INFO] [stdout] 2025-09-01T12:31:37.475381Z TRACE timesimp: obtained raw offset from server latency=101.25279ms delta=4µs 975ns ago
[INFO] [stdout] 2025-09-01T12:31:37.475414Z TRACE timesimp: sleeping to spread out requests delay=1.243247698s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.527695Z TRACE new{response=Response { client: 2025-09-01T12:31:37.50527002Z, server: 2025-09-01T12:31:42.51640865Z } current=2025-09-01T12:31:37.527546519Z}: timesimp::delta: response processing internals latency=11ms 138µs 249ns local_at_midpoint=2025-09-01T12:31:37.516408269Z delta=5s 381ns
[INFO] [stdout] 2025-09-01T12:31:37.527779Z TRACE timesimp: obtained raw offset from server latency=11.138249ms delta=5s 381ns
[INFO] [stdout] 2025-09-01T12:31:37.527797Z TRACE timesimp: sleeping to spread out requests delay=1.317821187s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.626968Z TRACE new{response=Response { client: 2025-09-01T12:31:37.605578595Z, server: 2025-09-01T12:31:42.615700374Z } current=2025-09-01T12:31:37.626820354Z}: timesimp::delta: response processing internals latency=10ms 620µs 879ns local_at_midpoint=2025-09-01T12:31:37.616199474Z delta=4s 999ms 500µs 900ns
[INFO] [stdout] 2025-09-01T12:31:37.627050Z TRACE timesimp: obtained raw offset from server latency=10.620879ms delta=4s 999ms 500µs 900ns
[INFO] [stdout] 2025-09-01T12:31:37.627067Z TRACE timesimp: sleeping to spread out requests delay=1.259693252s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.634127Z TRACE new{response=Response { client: 2025-09-01T12:31:37.615677504Z, server: 2025-09-01T12:31:42.624847434Z } current=2025-09-01T12:31:37.634002083Z}: timesimp::delta: response processing internals latency=9ms 162µs 289ns local_at_midpoint=2025-09-01T12:31:37.624839793Z delta=5s 7µs 641ns
[INFO] [stdout] 2025-09-01T12:31:37.634201Z TRACE timesimp: obtained raw offset from server latency=9.162289ms delta=5s 7µs 641ns
[INFO] [stdout] 2025-09-01T12:31:37.634217Z TRACE timesimp: sleeping to spread out requests delay=1.212843812s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.830021Z TRACE new{response=Response { client: 2025-09-01T12:31:37.807557894Z, server: 2025-09-01T12:31:37.818716824Z } current=2025-09-01T12:31:37.829873933Z}: timesimp::delta: response processing internals latency=11ms 158µs 19ns local_at_midpoint=2025-09-01T12:31:37.818715913Z delta=911ns
[INFO] [stdout] 2025-09-01T12:31:37.830094Z TRACE timesimp: obtained raw offset from server latency=11.158019ms delta=911ns
[INFO] [stdout] 2025-09-01T12:31:37.830108Z TRACE timesimp: sleeping to spread out requests delay=429.002607ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:37.929428Z TRACE new{response=Response { client: 2025-09-01T12:31:37.906898169Z, server: 2025-09-01T12:31:37.918064868Z } current=2025-09-01T12:31:37.929276918Z}: timesimp::delta: response processing internals latency=11ms 189µs 374ns local_at_midpoint=2025-09-01T12:31:37.918087543Z delta=22µs 675ns ago
[INFO] [stdout] 2025-09-01T12:31:37.929525Z TRACE timesimp: obtained raw offset from server latency=11.189374ms delta=22µs 675ns ago
[INFO] [stdout] 2025-09-01T12:31:37.929543Z TRACE timesimp: sleeping to spread out requests delay=1.066901519s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:38.173155Z TRACE new{response=Response { client: 2025-09-01T12:31:38.150706836Z, server: 2025-09-01T12:31:33.161858855Z } current=2025-09-01T12:31:38.173007205Z}: timesimp::delta: response processing internals latency=11ms 150µs 184ns local_at_midpoint=2025-09-01T12:31:38.16185702Z delta=4s 999ms 998µs 165ns ago
[INFO] [stdout] 2025-09-01T12:31:38.173231Z TRACE timesimp: obtained raw offset from server latency=11.150184ms delta=4s 999ms 998µs 165ns ago
[INFO] [stdout] 2025-09-01T12:31:38.173248Z TRACE timesimp: sleeping to spread out requests delay=1.123712713s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:38.283127Z TRACE new{response=Response { client: 2025-09-01T12:31:38.26068789Z, server: 2025-09-01T12:31:38.271827289Z } current=2025-09-01T12:31:38.282966809Z}: timesimp::delta: response processing internals latency=11ms 139µs 459ns local_at_midpoint=2025-09-01T12:31:38.271827349Z delta=60ns ago
[INFO] [stdout] 2025-09-01T12:31:38.283195Z TRACE timesimp: obtained raw offset from server latency=11.139459ms delta=60ns ago
[INFO] [stdout] 2025-09-01T12:31:38.283209Z TRACE timesimp: sleeping to spread out requests delay=1.389830911s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:38.446100Z TRACE new{response=Response { client: 2025-09-01T12:31:38.428694911Z, server: 2025-09-01T12:31:43.437827431Z } current=2025-09-01T12:31:38.4459537Z}: timesimp::delta: response processing internals latency=8ms 629µs 394ns local_at_midpoint=2025-09-01T12:31:38.437324305Z delta=5s 503µs 126ns
[INFO] [stdout] 2025-09-01T12:31:38.446163Z TRACE timesimp: obtained raw offset from server latency=8.629394ms delta=5s 503µs 126ns
[INFO] [stdout] 2025-09-01T12:31:38.446177Z TRACE timesimp: sleeping to spread out requests delay=463.271513ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:38.866111Z TRACE new{response=Response { client: 2025-09-01T12:31:38.847705289Z, server: 2025-09-01T12:31:43.856836518Z } current=2025-09-01T12:31:38.865957248Z}: timesimp::delta: response processing internals latency=9ms 125µs 979ns local_at_midpoint=2025-09-01T12:31:38.856831268Z delta=5s 5µs 250ns
[INFO] [stdout] 2025-09-01T12:31:38.866185Z TRACE timesimp: obtained raw offset from server latency=9.125979ms delta=5s 5µs 250ns
[INFO] [stdout] 2025-09-01T12:31:38.866210Z TRACE timesimp: response deltas sorted by latency deltas=[5000.015025, 5000.00656, 5000.545275, 5000.00525, 5000.007641]
[INFO] [stdout] 2025-09-01T12:31:38.866224Z TRACE timesimp: statistics about response deltas median=5000.545275 mean=5000.1159502 variance=0.05761432820779512 stddev=0.24002984857678664
[INFO] [stdout] 2025-09-01T12:31:38.866243Z TRACE timesimp: eliminated outliers inliers=[5000.545275]
[INFO] [stdout] 2025-09-01T12:31:38.866252Z DEBUG timesimp: storing calculated offset offset=5s 545µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-09-01T12:31:38.868966Z TRACE new{response=Response { client: 2025-09-01T12:31:38.846607489Z, server: 2025-09-01T12:31:43.857709588Z } current=2025-09-01T12:31:38.868822348Z}: timesimp::delta: response processing internals latency=11ms 107µs 429ns local_at_midpoint=2025-09-01T12:31:38.857714918Z delta=4s 999ms 994µs 670ns
[INFO] [stdout] 2025-09-01T12:31:38.869035Z TRACE timesimp: obtained raw offset from server latency=11.107429ms delta=4s 999ms 994µs 670ns
[INFO] [stdout] 2025-09-01T12:31:38.869057Z TRACE timesimp: response deltas sorted by latency deltas=[4999.99467, 5000.006306, 5000.000381, 5000.001065, 5000.09255]
[INFO] [stdout] 2025-09-01T12:31:38.869083Z TRACE timesimp: statistics about response deltas median=5000.000381 mean=5000.018994399999 variance=0.001707755066307291 stddev=0.041324993240257055
[INFO] [stdout] 2025-09-01T12:31:38.869105Z TRACE timesimp: eliminated outliers inliers=[4999.99467, 5000.006306, 5000.000381, 5000.001065]
[INFO] [stdout] 2025-09-01T12:31:38.869115Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2025-09-01T12:31:38.910042Z TRACE new{response=Response { client: 2025-09-01T12:31:38.887648567Z, server: 2025-09-01T12:31:43.898772966Z } current=2025-09-01T12:31:38.909894095Z}: timesimp::delta: response processing internals latency=11ms 122µs 764ns local_at_midpoint=2025-09-01T12:31:38.898771331Z delta=5s 1µs 635ns
[INFO] [stdout] 2025-09-01T12:31:38.910109Z TRACE timesimp: obtained raw offset from server latency=11.122764ms delta=5s 1µs 635ns
[INFO] [stdout] 2025-09-01T12:31:38.910123Z TRACE timesimp: sleeping to spread out requests delay=11.753278ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:38.922431Z TRACE new{response=Response { client: 2025-09-01T12:31:38.719692245Z, server: 2025-09-01T12:31:38.82097248Z } current=2025-09-01T12:31:38.922262965Z}: timesimp::delta: response processing internals latency=101ms 285µs 360ns local_at_midpoint=2025-09-01T12:31:38.820977605Z delta=5µs 125ns ago
[INFO] [stdout] 2025-09-01T12:31:38.922584Z TRACE timesimp: obtained raw offset from server latency=101.28536ms delta=5µs 125ns ago
[INFO] [stdout] 2025-09-01T12:31:38.922662Z TRACE timesimp: sleeping to spread out requests delay=1.70356642s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:38.927006Z TRACE new{response=Response { client: 2025-09-01T12:31:38.910634485Z, server: 2025-09-01T12:31:43.918739155Z } current=2025-09-01T12:31:38.926875694Z}: timesimp::delta: response processing internals latency=8ms 120µs 604ns local_at_midpoint=2025-09-01T12:31:38.918755089Z delta=4s 999ms 984µs 66ns
[INFO] [stdout] 2025-09-01T12:31:38.927076Z TRACE timesimp: obtained raw offset from server latency=8.120604ms delta=4s 999ms 984µs 66ns
[INFO] [stdout] 2025-09-01T12:31:38.927095Z TRACE timesimp: response deltas sorted by latency deltas=[5000.044861, 5000.385761, 4999.984066, 5000.001346, 5000.503126]
[INFO] [stdout] 2025-09-01T12:31:38.927114Z TRACE timesimp: statistics about response deltas median=4999.984066 mean=5000.183832000001 variance=0.058811128317371106 stddev=0.24251005817774055
[INFO] [stdout] 2025-09-01T12:31:38.927128Z TRACE timesimp: eliminated outliers inliers=[5000.044861, 4999.984066, 5000.001346]
[INFO] [stdout] 2025-09-01T12:31:38.927144Z DEBUG timesimp: storing calculated offset offset=5s 10µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-09-01T12:31:38.946819Z TRACE new{response=Response { client: 2025-09-01T12:31:38.923252305Z, server: 2025-09-01T12:31:43.935538934Z } current=2025-09-01T12:31:38.946676233Z}: timesimp::delta: response processing internals latency=11ms 711µs 964ns local_at_midpoint=2025-09-01T12:31:38.934964269Z delta=5s 574µs 665ns
[INFO] [stdout] 2025-09-01T12:31:38.946893Z TRACE timesimp: obtained raw offset from server latency=11.711964ms delta=5s 574µs 665ns
[INFO] [stdout] 2025-09-01T12:31:38.946915Z TRACE timesimp: response deltas sorted by latency deltas=[5000.006855, 5000.003781, 4999.5009, 5000.001635, 5000.574665]
[INFO] [stdout] 2025-09-01T12:31:38.946929Z TRACE timesimp: statistics about response deltas median=4999.5009 mean=5000.0175672 variance=0.1444653999642288 stddev=0.3800860428432341
[INFO] [stdout] 2025-09-01T12:31:38.946947Z TRACE timesimp: eliminated outliers inliers=[4999.5009]
[INFO] [stdout] 2025-09-01T12:31:38.946955Z DEBUG timesimp: storing calculated offset offset=4s 999ms 500µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-09-01T12:31:39.022422Z TRACE new{response=Response { client: 2025-09-01T12:31:38.999609071Z, server: 2025-09-01T12:31:39.01087775Z } current=2025-09-01T12:31:39.022267409Z}: timesimp::delta: response processing internals latency=11ms 329µs 169ns local_at_midpoint=2025-09-01T12:31:39.01093824Z delta=60µs 490ns ago
[INFO] [stdout] 2025-09-01T12:31:39.022518Z TRACE timesimp: obtained raw offset from server latency=11.329169ms delta=60µs 490ns ago
[INFO] [stdout] 2025-09-01T12:31:39.022546Z TRACE timesimp: response deltas sorted by latency deltas=[-0.004739, 0.00194, 0.001736, -0.022675, -0.06049]
[INFO] [stdout] 2025-09-01T12:31:39.022566Z TRACE timesimp: statistics about response deltas median=0.001736 mean=-0.0168456 variance=0.0006958899862999999 stddev=0.02637972680487802
[INFO] [stdout] 2025-09-01T12:31:39.022579Z TRACE timesimp: eliminated outliers inliers=[-0.004739, 0.00194, 0.001736, -0.022675]
[INFO] [stdout] 2025-09-01T12:31:39.022594Z DEBUG timesimp: storing calculated offset offset=5µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2025-09-01T12:31:39.140138Z TRACE new{response=Response { client: 2025-09-01T12:31:39.137722593Z, server: 2025-09-01T12:31:39.138859063Z } current=2025-09-01T12:31:39.139978333Z}: timesimp::delta: response processing internals latency=1ms 127µs 870ns local_at_midpoint=2025-09-01T12:31:39.138850463Z delta=8µs 600ns
[INFO] [stdout] 2025-09-01T12:31:39.140225Z TRACE timesimp: obtained raw offset from server latency=1.12787ms delta=8µs 600ns
[INFO] [stdout] 2025-09-01T12:31:39.140249Z TRACE timesimp: response deltas sorted by latency deltas=[0.001135, 0.002515, 0.0086, 0.00422, 0.013741]
[INFO] [stdout] 2025-09-01T12:31:39.140265Z TRACE timesimp: statistics about response deltas median=0.0086 mean=0.006042199999999999 variance=2.64140067e-5 stddev=0.005139455875868573
[INFO] [stdout] 2025-09-01T12:31:39.140285Z TRACE timesimp: eliminated outliers inliers=[0.0086, 0.00422]
[INFO] [stdout] 2025-09-01T12:31:39.140303Z DEBUG timesimp: storing calculated offset offset=6µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-09-01T12:31:39.324240Z TRACE new{response=Response { client: 2025-09-01T12:31:39.301683314Z, server: 2025-09-01T12:31:34.312858784Z } current=2025-09-01T12:31:39.324081663Z}: timesimp::delta: response processing internals latency=11ms 199µs 174ns local_at_midpoint=2025-09-01T12:31:39.312882488Z delta=5s 23µs 704ns ago
[INFO] [stdout] 2025-09-01T12:31:39.324323Z TRACE timesimp: obtained raw offset from server latency=11.199174ms delta=5s 23µs 704ns ago
[INFO] [stdout] 2025-09-01T12:31:39.324347Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.440405, -5000.003709, -4999.998165, -5000.023704, -5001.792989]
[INFO] [stdout] 2025-09-01T12:31:39.324362Z TRACE timesimp: statistics about response deltas median=-4999.998165 mean=-5000.251794399999 variance=0.8028832555773918 stddev=0.8960375302281661
[INFO] [stdout] 2025-09-01T12:31:39.324384Z TRACE timesimp: eliminated outliers inliers=[-4999.440405, -5000.003709, -4999.998165, -5000.023704]
[INFO] [stdout] 2025-09-01T12:31:39.324395Z DEBUG timesimp: storing calculated offset offset=4s 999ms 866µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-09-01T12:31:39.695959Z TRACE new{response=Response { client: 2025-09-01T12:31:39.674130705Z, server: 2025-09-01T12:31:39.685613484Z } current=2025-09-01T12:31:39.695798734Z}: timesimp::delta: response processing internals latency=10ms 834µs 14ns local_at_midpoint=2025-09-01T12:31:39.684964719Z delta=648µs 765ns
[INFO] [stdout] 2025-09-01T12:31:39.696049Z TRACE timesimp: obtained raw offset from server latency=10.834014ms delta=648µs 765ns
[INFO] [stdout] 2025-09-01T12:31:39.696074Z TRACE timesimp: response deltas sorted by latency deltas=[0.648765, -0.00464, -6e-5, 0.000911, -0.8608]
[INFO] [stdout] 2025-09-01T12:31:39.696090Z TRACE timesimp: statistics about response deltas median=-6e-5 mean=-0.04316479999999998 variance=0.28814475713770005 stddev=0.5367911671569309
[INFO] [stdout] 2025-09-01T12:31:39.696110Z TRACE timesimp: eliminated outliers inliers=[-0.00464, -6e-5, 0.000911]
[INFO] [stdout] 2025-09-01T12:31:39.696120Z DEBUG timesimp: storing calculated offset offset=1µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-09-01T12:31:40.459069Z TRACE new{response=Response { client: 2025-09-01T12:31:39.027616299Z, server: 2025-09-01T12:31:39.744596501Z } current=2025-09-01T12:31:40.458915933Z}: timesimp::delta: response processing internals latency=715ms 649µs 817ns local_at_midpoint=2025-09-01T12:31:39.743266116Z delta=1ms 330µs 385ns
[INFO] [stdout] 2025-09-01T12:31:40.459143Z TRACE timesimp: obtained raw offset from server latency=715.649817ms delta=1ms 330µs 385ns
[INFO] [stdout] 2025-09-01T12:31:40.459159Z TRACE timesimp: sleeping to spread out requests delay=296.552642ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:40.829575Z TRACE new{response=Response { client: 2025-09-01T12:31:40.626721344Z, server: 2025-09-01T12:31:40.728049018Z } current=2025-09-01T12:31:40.829396193Z}: timesimp::delta: response processing internals latency=101ms 337µs 424ns local_at_midpoint=2025-09-01T12:31:40.728058768Z delta=9µs 750ns ago
[INFO] [stdout] 2025-09-01T12:31:40.829658Z TRACE timesimp: obtained raw offset from server latency=101.337424ms delta=9µs 750ns ago
[INFO] [stdout] 2025-09-01T12:31:40.829677Z TRACE timesimp: sleeping to spread out requests delay=1.858517494s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:42.485835Z TRACE new{response=Response { client: 2025-09-01T12:31:40.767857976Z, server: 2025-09-01T12:31:41.626706801Z } current=2025-09-01T12:31:42.485680755Z}: timesimp::delta: response processing internals latency=858ms 911µs 389ns local_at_midpoint=2025-09-01T12:31:41.626769365Z delta=62µs 564ns ago
[INFO] [stdout] 2025-09-01T12:31:42.485908Z TRACE timesimp: obtained raw offset from server latency=858.911389ms delta=62µs 564ns ago
[INFO] [stdout] 2025-09-01T12:31:42.485923Z TRACE timesimp: sleeping to spread out requests delay=1.380239851s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:42.892023Z TRACE new{response=Response { client: 2025-09-01T12:31:42.688737924Z, server: 2025-09-01T12:31:42.790508089Z } current=2025-09-01T12:31:42.891853334Z}: timesimp::delta: response processing internals latency=101ms 557µs 705ns local_at_midpoint=2025-09-01T12:31:42.790295629Z delta=212µs 460ns
[INFO] [stdout] 2025-09-01T12:31:42.892114Z TRACE timesimp: obtained raw offset from server latency=101.557705ms delta=212µs 460ns
[INFO] [stdout] 2025-09-01T12:31:42.892139Z TRACE timesimp: response deltas sorted by latency deltas=[-0.004975, -0.005125, -0.016804, -0.00975, 0.21246]
[INFO] [stdout] 2025-09-01T12:31:42.892160Z TRACE timesimp: statistics about response deltas median=-0.016804 mean=0.035161200000000004 variance=0.0098465387097 stddev=0.09922972694560839
[INFO] [stdout] 2025-09-01T12:31:42.892184Z TRACE timesimp: eliminated outliers inliers=[-0.004975, -0.005125, -0.016804, -0.00975]
[INFO] [stdout] 2025-09-01T12:31:42.892194Z DEBUG timesimp: storing calculated offset offset=9µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-09-01T12:31:45.557855Z TRACE new{response=Response { client: 2025-09-01T12:31:43.867120782Z, server: 2025-09-01T12:31:44.715579317Z } current=2025-09-01T12:31:45.557683892Z}: timesimp::delta: response processing internals latency=845ms 281µs 555ns local_at_midpoint=2025-09-01T12:31:44.712402337Z delta=3ms 176µs 980ns
[INFO] [stdout] 2025-09-01T12:31:45.557938Z TRACE timesimp: obtained raw offset from server latency=845.281555ms delta=3ms 176µs 980ns
[INFO] [stdout] 2025-09-01T12:31:45.557958Z TRACE timesimp: sleeping to spread out requests delay=1.301147764s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.460876Z TRACE new{response=Response { client: 2025-09-01T12:31:46.860722812Z, server: 2025-09-01T12:31:47.6607065Z } current=2025-09-01T12:31:48.460714697Z}: timesimp::delta: response processing internals latency=799ms 995µs 942ns local_at_midpoint=2025-09-01T12:31:47.660718754Z delta=12µs 254ns ago
[INFO] [stdout] 2025-09-01T12:31:48.460962Z TRACE timesimp: obtained raw offset from server latency=799.995942ms delta=12µs 254ns ago
[INFO] [stdout] 2025-09-01T12:31:48.460986Z TRACE timesimp: response deltas sorted by latency deltas=[1.330385, -0.012254, 3.17698, -0.062564, -0.12986]
[INFO] [stdout] 2025-09-01T12:31:48.461000Z TRACE timesimp: statistics about response deltas median=3.17698 mean=0.8605373999999999 variance=2.0453577797108 stddev=1.4301600538788657
[INFO] [stdout] 2025-09-01T12:31:48.461015Z TRACE timesimp: eliminated outliers inliers=[3.17698]
[INFO] [stdout] 2025-09-01T12:31:48.461033Z DEBUG timesimp: storing calculated offset offset=3ms 176µs
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 13.16s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-9d1c06fe72bb6515)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-09-01T12:31:48.465390Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:48.465398Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-01T12:31:48.465518Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.465532Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.465668Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:31:48.465731Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.466893Z TRACE new{response=Response { client: 2025-09-01T12:31:48.466743107Z, server: 2025-09-01T12:31:48.466755887Z } current=2025-09-01T12:31:48.466759097Z}: timesimp::delta: response processing internals latency=7µs 995ns local_at_midpoint=2025-09-01T12:31:48.466751102Z delta=4µs 785ns
[INFO] [stdout] 2025-09-01T12:31:48.466918Z TRACE new{response=Response { client: 2025-09-01T12:31:48.466743017Z, server: 2025-09-01T12:31:53.466766727Z } current=2025-09-01T12:31:48.466770407Z}: timesimp::delta: response processing internals latency=13µs 695ns local_at_midpoint=2025-09-01T12:31:48.466756712Z delta=5s 10µs 15ns
[INFO] [stdout] 2025-09-01T12:31:48.466959Z TRACE timesimp: obtained raw offset from server latency=7.995µs delta=4µs 785ns
[INFO] [stdout] 2025-09-01T12:31:48.466977Z TRACE timesimp: sleeping to spread out requests delay=179.451196ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.466989Z TRACE timesimp: obtained raw offset from server latency=13.695µs delta=5s 10µs 15ns
[INFO] [stdout] 2025-09-01T12:31:48.467011Z TRACE timesimp: sleeping to spread out requests delay=1.037673186s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.467086Z TRACE new{response=Response { client: 2025-09-01T12:31:48.466950817Z, server: 2025-09-01T12:31:48.466955227Z } current=2025-09-01T12:31:48.466957417Z}: timesimp::delta: response processing internals latency=3µs 300ns local_at_midpoint=2025-09-01T12:31:48.466954117Z delta=1µs 110ns
[INFO] [stdout] 2025-09-01T12:31:48.467186Z TRACE timesimp: obtained raw offset from server latency=3.3µs delta=1µs 110ns
[INFO] [stdout] 2025-09-01T12:31:48.467274Z DEBUG timesimp: no offset stored, storing initial delta offset=1µs 110ns
[INFO] [stdout] 2025-09-01T12:31:48.467320Z TRACE timesimp: sleeping to spread out requests delay=590.807009ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.467672Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-01T12:31:48.467750Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.469071Z TRACE new{response=Response { client: 2025-09-01T12:31:48.468951687Z, server: 2025-09-01T12:31:43.468954917Z } current=2025-09-01T12:31:48.468956727Z}: timesimp::delta: response processing internals latency=2µs 520ns local_at_midpoint=2025-09-01T12:31:48.468954207Z delta=4s 999ms 999µs 290ns ago
[INFO] [stdout] 2025-09-01T12:31:48.469198Z TRACE timesimp: obtained raw offset from server latency=2.52µs delta=4s 999ms 999µs 290ns ago
[INFO] [stdout] 2025-09-01T12:31:48.469274Z TRACE timesimp: sleeping to spread out requests delay=71.193563ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.544741Z TRACE new{response=Response { client: 2025-09-01T12:31:48.544586193Z, server: 2025-09-01T12:31:43.544595463Z } current=2025-09-01T12:31:48.544599023Z}: timesimp::delta: response processing internals latency=6µs 415ns local_at_midpoint=2025-09-01T12:31:48.544592608Z delta=4s 999ms 997µs 145ns ago
[INFO] [stdout] 2025-09-01T12:31:48.544811Z TRACE timesimp: obtained raw offset from server latency=6.415µs delta=4s 999ms 997µs 145ns ago
[INFO] [stdout] 2025-09-01T12:31:48.544826Z TRACE timesimp: sleeping to spread out requests delay=523.649461ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:48.647570Z TRACE new{response=Response { client: 2025-09-01T12:31:48.647388787Z, server: 2025-09-01T12:31:48.647398187Z } current=2025-09-01T12:31:48.647402517Z}: timesimp::delta: response processing internals latency=6µs 865ns local_at_midpoint=2025-09-01T12:31:48.647395652Z delta=2µs 535ns
[INFO] [stdout] 2025-09-01T12:31:48.647697Z TRACE timesimp: obtained raw offset from server latency=6.865µs delta=2µs 535ns
[INFO] [stdout] 2025-09-01T12:31:48.647741Z TRACE timesimp: sleeping to spread out requests delay=461.143219ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:49.069747Z TRACE new{response=Response { client: 2025-09-01T12:31:49.069571835Z, server: 2025-09-01T12:31:49.069585055Z } current=2025-09-01T12:31:49.069587575Z}: timesimp::delta: response processing internals latency=7µs 870ns local_at_midpoint=2025-09-01T12:31:49.069579705Z delta=5µs 350ns
[INFO] [stdout] 2025-09-01T12:31:49.069747Z TRACE new{response=Response { client: 2025-09-01T12:31:49.069575005Z, server: 2025-09-01T12:31:44.069584005Z } current=2025-09-01T12:31:49.069587625Z}: timesimp::delta: response processing internals latency=6µs 310ns local_at_midpoint=2025-09-01T12:31:49.069581315Z delta=4s 999ms 997µs 310ns ago
[INFO] [stdout] 2025-09-01T12:31:49.069835Z TRACE timesimp: obtained raw offset from server latency=7.87µs delta=5µs 350ns
[INFO] [stdout] 2025-09-01T12:31:49.069845Z TRACE timesimp: obtained raw offset from server latency=6.31µs delta=4s 999ms 997µs 310ns ago
[INFO] [stdout] 2025-09-01T12:31:49.069851Z TRACE timesimp: sleeping to spread out requests delay=1.369607465s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:49.069861Z TRACE timesimp: sleeping to spread out requests delay=1.128434993s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:49.109662Z TRACE new{response=Response { client: 2025-09-01T12:31:49.109503383Z, server: 2025-09-01T12:31:49.109512123Z } current=2025-09-01T12:31:49.109515993Z}: timesimp::delta: response processing internals latency=6µs 305ns local_at_midpoint=2025-09-01T12:31:49.109509688Z delta=2µs 435ns
[INFO] [stdout] 2025-09-01T12:31:49.109828Z TRACE timesimp: obtained raw offset from server latency=6.305µs delta=2µs 435ns
[INFO] [stdout] 2025-09-01T12:31:49.109875Z TRACE timesimp: sleeping to spread out requests delay=418.281161ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:49.506117Z TRACE new{response=Response { client: 2025-09-01T12:31:49.505942402Z, server: 2025-09-01T12:31:54.505951622Z } current=2025-09-01T12:31:49.505955562Z}: timesimp::delta: response processing internals latency=6µs 580ns local_at_midpoint=2025-09-01T12:31:49.505948982Z delta=5s 2µs 640ns
[INFO] [stdout] 2025-09-01T12:31:49.506196Z TRACE timesimp: obtained raw offset from server latency=6.58µs delta=5s 2µs 640ns
[INFO] [stdout] 2025-09-01T12:31:49.506215Z TRACE timesimp: sleeping to spread out requests delay=538.71556ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:49.529926Z TRACE new{response=Response { client: 2025-09-01T12:31:49.52972032Z, server: 2025-09-01T12:31:49.52975337Z } current=2025-09-01T12:31:49.52975796Z}: timesimp::delta: response processing internals latency=18µs 820ns local_at_midpoint=2025-09-01T12:31:49.52973914Z delta=14µs 230ns
[INFO] [stdout] 2025-09-01T12:31:49.530016Z TRACE timesimp: obtained raw offset from server latency=18.82µs delta=14µs 230ns
[INFO] [stdout] 2025-09-01T12:31:49.530035Z TRACE timesimp: sleeping to spread out requests delay=1.081573321s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:50.046046Z TRACE new{response=Response { client: 2025-09-01T12:31:50.045890023Z, server: 2025-09-01T12:31:55.045898523Z } current=2025-09-01T12:31:50.045902213Z}: timesimp::delta: response processing internals latency=6µs 95ns local_at_midpoint=2025-09-01T12:31:50.045896118Z delta=5s 2µs 405ns
[INFO] [stdout] 2025-09-01T12:31:50.046187Z TRACE timesimp: obtained raw offset from server latency=6.095µs delta=5s 2µs 405ns
[INFO] [stdout] 2025-09-01T12:31:50.046201Z TRACE timesimp: sleeping to spread out requests delay=1.300255875s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:50.199833Z TRACE new{response=Response { client: 2025-09-01T12:31:50.199674655Z, server: 2025-09-01T12:31:45.199683245Z } current=2025-09-01T12:31:50.199687065Z}: timesimp::delta: response processing internals latency=6µs 205ns local_at_midpoint=2025-09-01T12:31:50.19968086Z delta=4s 999ms 997µs 615ns ago
[INFO] [stdout] 2025-09-01T12:31:50.199913Z TRACE timesimp: obtained raw offset from server latency=6.205µs delta=4s 999ms 997µs 615ns ago
[INFO] [stdout] 2025-09-01T12:31:50.199930Z TRACE timesimp: sleeping to spread out requests delay=881.813666ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:50.440876Z TRACE new{response=Response { client: 2025-09-01T12:31:50.440715572Z, server: 2025-09-01T12:31:50.440725592Z } current=2025-09-01T12:31:50.440728212Z}: timesimp::delta: response processing internals latency=6µs 320ns local_at_midpoint=2025-09-01T12:31:50.440721892Z delta=3µs 700ns
[INFO] [stdout] 2025-09-01T12:31:50.440949Z TRACE timesimp: obtained raw offset from server latency=6.32µs delta=3µs 700ns
[INFO] [stdout] 2025-09-01T12:31:50.440964Z TRACE timesimp: sleeping to spread out requests delay=198.539169ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:50.612884Z TRACE new{response=Response { client: 2025-09-01T12:31:50.612715363Z, server: 2025-09-01T12:31:50.612724553Z } current=2025-09-01T12:31:50.612728233Z}: timesimp::delta: response processing internals latency=6µs 435ns local_at_midpoint=2025-09-01T12:31:50.612721798Z delta=2µs 755ns
[INFO] [stdout] 2025-09-01T12:31:50.612973Z TRACE timesimp: obtained raw offset from server latency=6.435µs delta=2µs 755ns
[INFO] [stdout] 2025-09-01T12:31:50.613000Z TRACE timesimp: response deltas sorted by latency deltas=[0.002435, 0.002755, 0.002535, 0.004785, 0.01423]
[INFO] [stdout] 2025-09-01T12:31:50.613027Z TRACE timesimp: statistics about response deltas median=0.002535 mean=0.005348 variance=2.558227e-5 stddev=0.005057891853331781
[INFO] [stdout] 2025-09-01T12:31:50.613053Z TRACE timesimp: eliminated outliers inliers=[0.002435, 0.002755, 0.002535, 0.004785]
[INFO] [stdout] 2025-09-01T12:31:50.613066Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2025-09-01T12:31:50.640567Z TRACE new{response=Response { client: 2025-09-01T12:31:50.640387981Z, server: 2025-09-01T12:31:50.640397371Z } current=2025-09-01T12:31:50.640400131Z}: timesimp::delta: response processing internals latency=6µs 75ns local_at_midpoint=2025-09-01T12:31:50.640394056Z delta=3µs 315ns
[INFO] [stdout] 2025-09-01T12:31:50.640724Z TRACE timesimp: obtained raw offset from server latency=6.075µs delta=3µs 315ns
[INFO] [stdout] 2025-09-01T12:31:50.640794Z TRACE timesimp: sleeping to spread out requests delay=1.135532301s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:51.083903Z TRACE new{response=Response { client: 2025-09-01T12:31:51.083733467Z, server: 2025-09-01T12:31:46.083743207Z } current=2025-09-01T12:31:51.083747347Z}: timesimp::delta: response processing internals latency=6µs 940ns local_at_midpoint=2025-09-01T12:31:51.083740407Z delta=4s 999ms 997µs 200ns ago
[INFO] [stdout] 2025-09-01T12:31:51.083983Z TRACE timesimp: obtained raw offset from server latency=6.94µs delta=4s 999ms 997µs 200ns ago
[INFO] [stdout] 2025-09-01T12:31:51.084006Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99929, -4999.997615, -4999.99731, -4999.997145, -4999.9972]
[INFO] [stdout] 2025-09-01T12:31:51.084029Z TRACE timesimp: statistics about response deltas median=-4999.99731 mean=-4999.997711999999 variance=8.111824998159999e-7 stddev=0.0009006567047527042
[INFO] [stdout] 2025-09-01T12:31:51.084045Z TRACE timesimp: eliminated outliers inliers=[-4999.997615, -4999.99731, -4999.997145, -4999.9972]
[INFO] [stdout] 2025-09-01T12:31:51.084054Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2025-09-01T12:31:51.355765Z TRACE new{response=Response { client: 2025-09-01T12:31:51.355591633Z, server: 2025-09-01T12:31:56.355601333Z } current=2025-09-01T12:31:51.355605553Z}: timesimp::delta: response processing internals latency=6µs 960ns local_at_midpoint=2025-09-01T12:31:51.355598593Z delta=5s 2µs 740ns
[INFO] [stdout] 2025-09-01T12:31:51.355852Z TRACE timesimp: obtained raw offset from server latency=6.96µs delta=5s 2µs 740ns
[INFO] [stdout] 2025-09-01T12:31:51.355870Z TRACE timesimp: sleeping to spread out requests delay=66.813112ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:31:51.424382Z TRACE new{response=Response { client: 2025-09-01T12:31:51.424218129Z, server: 2025-09-01T12:31:56.424227589Z } current=2025-09-01T12:31:51.42423178Z}: timesimp::delta: response processing internals latency=6µs 825ns local_at_midpoint=2025-09-01T12:31:51.424224954Z delta=5s 2µs 635ns
[INFO] [stdout] 2025-09-01T12:31:51.424457Z TRACE timesimp: obtained raw offset from server latency=6.825µs delta=5s 2µs 635ns
[INFO] [stdout] 2025-09-01T12:31:51.424479Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002405, 5000.00264, 5000.002635, 5000.00274, 5000.010015]
[INFO] [stdout] 2025-09-01T12:31:51.424520Z TRACE timesimp: statistics about response deltas median=5000.002635 mean=5000.004086999999 variance=1.0996707499778452e-5 stddev=0.0033161283901228028
[INFO] [stdout] 2025-09-01T12:31:51.424535Z TRACE timesimp: eliminated outliers inliers=[5000.002405, 5000.00264, 5000.002635, 5000.00274]
[INFO] [stdout] 2025-09-01T12:31:51.424544Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2025-09-01T12:31:51.777894Z TRACE new{response=Response { client: 2025-09-01T12:31:51.777723141Z, server: 2025-09-01T12:31:51.777733421Z } current=2025-09-01T12:31:51.777736151Z}: timesimp::delta: response processing internals latency=6µs 505ns local_at_midpoint=2025-09-01T12:31:51.777729646Z delta=3µs 775ns
[INFO] [stdout] 2025-09-01T12:31:51.778045Z TRACE timesimp: obtained raw offset from server latency=6.505µs delta=3µs 775ns
[INFO] [stdout] 2025-09-01T12:31:51.778090Z TRACE timesimp: response deltas sorted by latency deltas=[0.00111, 0.003315, 0.0037, 0.003775, 0.00535]
[INFO] [stdout] 2025-09-01T12:31:51.778127Z TRACE timesimp: statistics about response deltas median=0.0037 mean=0.0034500000000000004 variance=2.3179874999999996e-6 stddev=0.0015224938423520798
[INFO] [stdout] 2025-09-01T12:31:51.778156Z TRACE timesimp: eliminated outliers inliers=[0.003315, 0.0037, 0.003775]
[INFO] [stdout] 2025-09-01T12:31:51.778179Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.31s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "5b1591f3392dfffae4301769a8a7377d3bd5dec8a4536727b8827e328b7cb4b4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "5b1591f3392dfffae4301769a8a7377d3bd5dec8a4536727b8827e328b7cb4b4", kill_on_drop: false }`
[INFO] [stdout] 5b1591f3392dfffae4301769a8a7377d3bd5dec8a4536727b8827e328b7cb4b4