[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against try#b83b707f97d809763b7861afa7638871f3339a33 for pr-145838-1
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-1-tc2/source
[INFO] started tweaking crates.io crate timesimp 1.0.0
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate timesimp 1.0.0
[INFO] tweaked toml for crates.io crate timesimp 1.0.0 written to /workspace/builds/worker-1-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain b83b707f97d809763b7861afa7638871f3339a33
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+b83b707f97d809763b7861afa7638871f3339a33" "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" "+b83b707f97d809763b7861afa7638871f3339a33" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+b83b707f97d809763b7861afa7638871f3339a33" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 86922b146f90ecb9556523dbba93ef930e1a6b304c7e75703b4afcfdb2c44da1
[INFO] running `Command { std: "docker" "start" "-a" "86922b146f90ecb9556523dbba93ef930e1a6b304c7e75703b4afcfdb2c44da1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "86922b146f90ecb9556523dbba93ef930e1a6b304c7e75703b4afcfdb2c44da1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "86922b146f90ecb9556523dbba93ef930e1a6b304c7e75703b4afcfdb2c44da1", kill_on_drop: false }`
[INFO] [stdout] 86922b146f90ecb9556523dbba93ef930e1a6b304c7e75703b4afcfdb2c44da1
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=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" "+b83b707f97d809763b7861afa7638871f3339a33" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] ea4c6c896373de265427e7e44c8dab08a86f6359829cf7e89c97b61876604050
[INFO] running `Command { std: "docker" "start" "-a" "ea4c6c896373de265427e7e44c8dab08a86f6359829cf7e89c97b61876604050", 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 8.47s
[INFO] running `Command { std: "docker" "inspect" "ea4c6c896373de265427e7e44c8dab08a86f6359829cf7e89c97b61876604050", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "ea4c6c896373de265427e7e44c8dab08a86f6359829cf7e89c97b61876604050", kill_on_drop: false }`
[INFO] [stdout] ea4c6c896373de265427e7e44c8dab08a86f6359829cf7e89c97b61876604050
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=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" "+b83b707f97d809763b7861afa7638871f3339a33" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 6861daedd66d45dd1a39d84ac08d774abd19520cf4b9c375633c749bb97c23cd
[INFO] running `Command { std: "docker" "start" "-a" "6861daedd66d45dd1a39d84ac08d774abd19520cf4b9c375633c749bb97c23cd", kill_on_drop: false }`
[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 syn v2.0.100
[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 openssl-sys v0.9.107
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[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 h2 v0.4.9
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 30.18s
[INFO] running `Command { std: "docker" "inspect" "6861daedd66d45dd1a39d84ac08d774abd19520cf4b9c375633c749bb97c23cd", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "6861daedd66d45dd1a39d84ac08d774abd19520cf4b9c375633c749bb97c23cd", kill_on_drop: false }`
[INFO] [stdout] 6861daedd66d45dd1a39d84ac08d774abd19520cf4b9c375633c749bb97c23cd
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=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" "+b83b707f97d809763b7861afa7638871f3339a33" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] b6f1f71368048125998c50c88bf2239c5c58edee50e36aebaefc2ef16038da09
[INFO] running `Command { std: "docker" "start" "-a" "b6f1f71368048125998c50c88bf2239c5c58edee50e36aebaefc2ef16038da09", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.21s
[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_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.03s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-1c01cc53c6a498a7)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-09-01T12:32:34.987358Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:34.987417Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-01T12:32:34.989631Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.989664Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:34.989699Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.990740Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:34.990841Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.987888Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:34.988033Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:34.991603Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.988576Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:34.989534Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.991738Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.987547Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-01T12:32:34.991818Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.991642Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.988210Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:34.991943Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:34.993370Z TRACE new{response=Response { client: 2025-09-01T12:32:34.990945231Z, server: 2025-09-01T12:32:34.992082001Z } current=2025-09-01T12:32:34.993207481Z}: timesimp::delta: response processing internals latency=1ms 131µs 125ns local_at_midpoint=2025-09-01T12:32:34.992076356Z delta=5µs 645ns
[INFO] [stdout] 2025-09-01T12:32:34.993446Z TRACE timesimp: obtained raw offset from server latency=1.131125ms delta=5µs 645ns
[INFO] [stdout] 2025-09-01T12:32:34.993468Z DEBUG timesimp: no offset stored, storing initial delta offset=5µs 645ns
[INFO] [stdout] 2025-09-01T12:32:34.993498Z TRACE timesimp: sleeping to spread out requests delay=1.450358769s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.007502Z TRACE new{response=Response { client: 2025-09-01T12:32:34.992996051Z, server: 2025-09-01T12:32:40.000152371Z } current=2025-09-01T12:32:35.007281381Z}: timesimp::delta: response processing internals latency=7ms 142µs 665ns local_at_midpoint=2025-09-01T12:32:35.000138716Z delta=5s 13µs 655ns
[INFO] [stdout] 2025-09-01T12:32:35.007604Z TRACE timesimp: obtained raw offset from server latency=7.142665ms delta=5s 13µs 655ns
[INFO] [stdout] 2025-09-01T12:32:35.007623Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 13µs 655ns
[INFO] [stdout] 2025-09-01T12:32:35.007635Z TRACE timesimp: sleeping to spread out requests delay=1.96673562s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.011506Z TRACE new{response=Response { client: 2025-09-01T12:32:34.993057061Z, server: 2025-09-01T12:32:40.002188041Z } current=2025-09-01T12:32:35.01133137Z}: timesimp::delta: response processing internals latency=9ms 137µs 154ns local_at_midpoint=2025-09-01T12:32:35.002194215Z delta=4s 999ms 993µs 826ns
[INFO] [stdout] 2025-09-01T12:32:35.011582Z TRACE timesimp: obtained raw offset from server latency=9.137154ms delta=4s 999ms 993µs 826ns
[INFO] [stdout] 2025-09-01T12:32:35.011598Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 993µs 826ns
[INFO] [stdout] 2025-09-01T12:32:35.011610Z TRACE timesimp: sleeping to spread out requests delay=600.208304ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.013372Z TRACE new{response=Response { client: 2025-09-01T12:32:34.990967802Z, server: 2025-09-01T12:32:35.002098961Z } current=2025-09-01T12:32:35.01321977Z}: timesimp::delta: response processing internals latency=11ms 125µs 984ns local_at_midpoint=2025-09-01T12:32:35.002093786Z delta=5µs 175ns
[INFO] [stdout] 2025-09-01T12:32:35.013448Z TRACE timesimp: obtained raw offset from server latency=11.125984ms delta=5µs 175ns
[INFO] [stdout] 2025-09-01T12:32:35.013466Z TRACE timesimp: sleeping to spread out requests delay=1.500398045s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.015628Z TRACE new{response=Response { client: 2025-09-01T12:32:34.993139751Z, server: 2025-09-01T12:32:35.004273791Z } current=2025-09-01T12:32:35.01542928Z}: timesimp::delta: response processing internals latency=11ms 144µs 764ns local_at_midpoint=2025-09-01T12:32:35.004284515Z delta=10µs 724ns ago
[INFO] [stdout] 2025-09-01T12:32:35.015717Z TRACE timesimp: obtained raw offset from server latency=11.144764ms delta=10µs 724ns ago
[INFO] [stdout] 2025-09-01T12:32:35.015738Z TRACE timesimp: sleeping to spread out requests delay=1.158057s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.018816Z TRACE new{response=Response { client: 2025-09-01T12:32:34.995593251Z, server: 2025-09-01T12:32:40.006745981Z } current=2025-09-01T12:32:35.01866199Z}: timesimp::delta: response processing internals latency=11ms 534µs 369ns local_at_midpoint=2025-09-01T12:32:35.00712762Z delta=4s 999ms 618µs 361ns
[INFO] [stdout] 2025-09-01T12:32:35.018880Z TRACE timesimp: obtained raw offset from server latency=11.534369ms delta=4s 999ms 618µs 361ns
[INFO] [stdout] 2025-09-01T12:32:35.018896Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 618µs 361ns
[INFO] [stdout] 2025-09-01T12:32:35.018907Z TRACE timesimp: sleeping to spread out requests delay=510.643315ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.024792Z TRACE new{response=Response { client: 2025-09-01T12:32:34.996577901Z, server: 2025-09-01T12:32:30.01154168Z } current=2025-09-01T12:32:35.02459837Z}: timesimp::delta: response processing internals latency=14ms 10µs 234ns local_at_midpoint=2025-09-01T12:32:35.010588135Z delta=4s 999ms 46µs 455ns ago
[INFO] [stdout] 2025-09-01T12:32:35.024884Z TRACE timesimp: obtained raw offset from server latency=14.010234ms delta=4s 999ms 46µs 455ns ago
[INFO] [stdout] 2025-09-01T12:32:35.024903Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 46µs 455ns ago
[INFO] [stdout] 2025-09-01T12:32:35.024915Z TRACE timesimp: sleeping to spread out requests delay=1.780335669s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.039203Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:35.039269Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.063050Z TRACE new{response=Response { client: 2025-09-01T12:32:35.040496779Z, server: 2025-09-01T12:32:40.051678978Z } current=2025-09-01T12:32:35.062857878Z}: timesimp::delta: response processing internals latency=11ms 180µs 549ns local_at_midpoint=2025-09-01T12:32:35.051677328Z delta=5s 1µs 650ns
[INFO] [stdout] 2025-09-01T12:32:35.063191Z TRACE timesimp: obtained raw offset from server latency=11.180549ms delta=5s 1µs 650ns
[INFO] [stdout] 2025-09-01T12:32:35.063231Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 650ns
[INFO] [stdout] 2025-09-01T12:32:35.063262Z TRACE timesimp: sleeping to spread out requests delay=1.474457834s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.209843Z TRACE new{response=Response { client: 2025-09-01T12:32:34.995694891Z, server: 2025-09-01T12:32:35.106591555Z } current=2025-09-01T12:32:35.20959208Z}: timesimp::delta: response processing internals latency=106ms 948µs 594ns local_at_midpoint=2025-09-01T12:32:35.102643485Z delta=3ms 948µs 70ns
[INFO] [stdout] 2025-09-01T12:32:35.209938Z TRACE timesimp: obtained raw offset from server latency=106.948594ms delta=3ms 948µs 70ns
[INFO] [stdout] 2025-09-01T12:32:35.209959Z DEBUG timesimp: no offset stored, storing initial delta offset=3ms 948µs 70ns
[INFO] [stdout] 2025-09-01T12:32:35.209971Z TRACE timesimp: sleeping to spread out requests delay=1.168263149s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.568758Z TRACE new{response=Response { client: 2025-09-01T12:32:35.534590833Z, server: 2025-09-01T12:32:40.551582372Z } current=2025-09-01T12:32:35.568581651Z}: timesimp::delta: response processing internals latency=16ms 995µs 409ns local_at_midpoint=2025-09-01T12:32:35.551586242Z delta=4s 999ms 996µs 130ns
[INFO] [stdout] 2025-09-01T12:32:35.568865Z TRACE timesimp: obtained raw offset from server latency=16.995409ms delta=4s 999ms 996µs 130ns
[INFO] [stdout] 2025-09-01T12:32:35.568887Z TRACE timesimp: sleeping to spread out requests delay=67.740448ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.634157Z TRACE new{response=Response { client: 2025-09-01T12:32:35.612446178Z, server: 2025-09-01T12:32:40.622658308Z } current=2025-09-01T12:32:35.633980577Z}: timesimp::delta: response processing internals latency=10ms 767µs 199ns local_at_midpoint=2025-09-01T12:32:35.623213377Z delta=4s 999ms 444µs 931ns
[INFO] [stdout] 2025-09-01T12:32:35.634245Z TRACE timesimp: obtained raw offset from server latency=10.767199ms delta=4s 999ms 444µs 931ns
[INFO] [stdout] 2025-09-01T12:32:35.634263Z TRACE timesimp: sleeping to spread out requests delay=122.078199ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.675826Z TRACE new{response=Response { client: 2025-09-01T12:32:35.641600747Z, server: 2025-09-01T12:32:40.658952636Z } current=2025-09-01T12:32:35.675625705Z}: timesimp::delta: response processing internals latency=17ms 12µs 479ns local_at_midpoint=2025-09-01T12:32:35.658613226Z delta=5s 339µs 410ns
[INFO] [stdout] 2025-09-01T12:32:35.676028Z TRACE timesimp: obtained raw offset from server latency=17.012479ms delta=5s 339µs 410ns
[INFO] [stdout] 2025-09-01T12:32:35.676056Z TRACE timesimp: sleeping to spread out requests delay=1.161196109s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:35.780214Z TRACE new{response=Response { client: 2025-09-01T12:32:35.757653721Z, server: 2025-09-01T12:32:40.76884992Z } current=2025-09-01T12:32:35.780047729Z}: timesimp::delta: response processing internals latency=11ms 197µs 4ns local_at_midpoint=2025-09-01T12:32:35.768850725Z delta=4s 999ms 999µs 195ns
[INFO] [stdout] 2025-09-01T12:32:35.780304Z TRACE timesimp: obtained raw offset from server latency=11.197004ms delta=4s 999ms 999µs 195ns
[INFO] [stdout] 2025-09-01T12:32:35.780326Z TRACE timesimp: sleeping to spread out requests delay=1.160753324s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.197266Z TRACE new{response=Response { client: 2025-09-01T12:32:36.174725839Z, server: 2025-09-01T12:32:36.185910328Z } current=2025-09-01T12:32:36.197101198Z}: timesimp::delta: response processing internals latency=11ms 187µs 679ns local_at_midpoint=2025-09-01T12:32:36.185913518Z delta=3µs 190ns ago
[INFO] [stdout] 2025-09-01T12:32:36.197350Z TRACE timesimp: obtained raw offset from server latency=11.187679ms delta=3µs 190ns ago
[INFO] [stdout] 2025-09-01T12:32:36.197370Z TRACE timesimp: sleeping to spread out requests delay=163.638698ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.384324Z TRACE new{response=Response { client: 2025-09-01T12:32:36.361740899Z, server: 2025-09-01T12:32:36.372955128Z } current=2025-09-01T12:32:36.384152448Z}: timesimp::delta: response processing internals latency=11ms 205µs 774ns local_at_midpoint=2025-09-01T12:32:36.372946673Z delta=8µs 455ns
[INFO] [stdout] 2025-09-01T12:32:36.384408Z TRACE timesimp: obtained raw offset from server latency=11.205774ms delta=8µs 455ns
[INFO] [stdout] 2025-09-01T12:32:36.384427Z TRACE timesimp: sleeping to spread out requests delay=212.144509ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.448148Z TRACE new{response=Response { client: 2025-09-01T12:32:36.445708324Z, server: 2025-09-01T12:32:36.446855554Z } current=2025-09-01T12:32:36.447983254Z}: timesimp::delta: response processing internals latency=1ms 137µs 465ns local_at_midpoint=2025-09-01T12:32:36.446845789Z delta=9µs 765ns
[INFO] [stdout] 2025-09-01T12:32:36.448230Z TRACE timesimp: obtained raw offset from server latency=1.137465ms delta=9µs 765ns
[INFO] [stdout] 2025-09-01T12:32:36.448248Z TRACE timesimp: sleeping to spread out requests delay=1.934747709s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.498339Z TRACE new{response=Response { client: 2025-09-01T12:32:34.995793611Z, server: 2025-09-01T12:32:35.746711881Z } current=2025-09-01T12:32:36.498136762Z}: timesimp::delta: response processing internals latency=751ms 171µs 575ns local_at_midpoint=2025-09-01T12:32:35.746965186Z delta=253µs 305ns ago
[INFO] [stdout] 2025-09-01T12:32:36.498419Z TRACE timesimp: obtained raw offset from server latency=751.171575ms delta=253µs 305ns ago
[INFO] [stdout] 2025-09-01T12:32:36.498437Z DEBUG timesimp: no offset stored, storing initial delta offset=253µs 305ns ago
[INFO] [stdout] 2025-09-01T12:32:36.498448Z TRACE timesimp: sleeping to spread out requests delay=1.506222918s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.544247Z TRACE new{response=Response { client: 2025-09-01T12:32:36.52160782Z, server: 2025-09-01T12:32:36.53289949Z } current=2025-09-01T12:32:36.544079969Z}: timesimp::delta: response processing internals latency=11ms 236µs 74ns local_at_midpoint=2025-09-01T12:32:36.532843894Z delta=55µs 596ns
[INFO] [stdout] 2025-09-01T12:32:36.544338Z TRACE timesimp: obtained raw offset from server latency=11.236074ms delta=55µs 596ns
[INFO] [stdout] 2025-09-01T12:32:36.544358Z TRACE timesimp: sleeping to spread out requests delay=1.33162932s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.563114Z TRACE new{response=Response { client: 2025-09-01T12:32:36.540574639Z, server: 2025-09-01T12:32:41.551758159Z } current=2025-09-01T12:32:36.562951708Z}: timesimp::delta: response processing internals latency=11ms 188µs 534ns local_at_midpoint=2025-09-01T12:32:36.551763173Z delta=4s 999ms 994µs 986ns
[INFO] [stdout] 2025-09-01T12:32:36.563190Z TRACE timesimp: obtained raw offset from server latency=11.188534ms delta=4s 999ms 994µs 986ns
[INFO] [stdout] 2025-09-01T12:32:36.563206Z TRACE timesimp: sleeping to spread out requests delay=1.136543541s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.581613Z TRACE new{response=Response { client: 2025-09-01T12:32:36.378752468Z, server: 2025-09-01T12:32:36.480112343Z } current=2025-09-01T12:32:36.581420647Z}: timesimp::delta: response processing internals latency=101ms 334µs 89ns local_at_midpoint=2025-09-01T12:32:36.480086557Z delta=25µs 786ns
[INFO] [stdout] 2025-09-01T12:32:36.581695Z TRACE timesimp: obtained raw offset from server latency=101.334089ms delta=25µs 786ns
[INFO] [stdout] 2025-09-01T12:32:36.581713Z TRACE timesimp: sleeping to spread out requests delay=1.892518473s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.622979Z TRACE new{response=Response { client: 2025-09-01T12:32:36.598894576Z, server: 2025-09-01T12:32:36.611590556Z } current=2025-09-01T12:32:36.622798565Z}: timesimp::delta: response processing internals latency=11ms 951µs 994ns local_at_midpoint=2025-09-01T12:32:36.61084657Z delta=743µs 986ns
[INFO] [stdout] 2025-09-01T12:32:36.623077Z TRACE timesimp: obtained raw offset from server latency=11.951994ms delta=743µs 986ns
[INFO] [stdout] 2025-09-01T12:32:36.623098Z TRACE timesimp: sleeping to spread out requests delay=1.021114885s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.836161Z TRACE new{response=Response { client: 2025-09-01T12:32:36.813589135Z, server: 2025-09-01T12:32:31.824788664Z } current=2025-09-01T12:32:36.835986684Z}: timesimp::delta: response processing internals latency=11ms 198µs 774ns local_at_midpoint=2025-09-01T12:32:36.824787909Z delta=4s 999ms 999µs 245ns ago
[INFO] [stdout] 2025-09-01T12:32:36.836242Z TRACE timesimp: obtained raw offset from server latency=11.198774ms delta=4s 999ms 999µs 245ns ago
[INFO] [stdout] 2025-09-01T12:32:36.836260Z TRACE timesimp: sleeping to spread out requests delay=1.145318074s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.866028Z TRACE new{response=Response { client: 2025-09-01T12:32:36.840576643Z, server: 2025-09-01T12:32:41.851886193Z } current=2025-09-01T12:32:36.865864302Z}: timesimp::delta: response processing internals latency=12ms 643µs 829ns local_at_midpoint=2025-09-01T12:32:36.853220472Z delta=4s 998ms 665µs 721ns
[INFO] [stdout] 2025-09-01T12:32:36.866109Z TRACE timesimp: obtained raw offset from server latency=12.643829ms delta=4s 998ms 665µs 721ns
[INFO] [stdout] 2025-09-01T12:32:36.866128Z TRACE timesimp: sleeping to spread out requests delay=689.310291ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.954162Z TRACE new{response=Response { client: 2025-09-01T12:32:36.942725418Z, server: 2025-09-01T12:32:41.947868088Z } current=2025-09-01T12:32:36.954001737Z}: timesimp::delta: response processing internals latency=5ms 638µs 159ns local_at_midpoint=2025-09-01T12:32:36.948363577Z delta=4s 999ms 504µs 511ns
[INFO] [stdout] 2025-09-01T12:32:36.954251Z TRACE timesimp: obtained raw offset from server latency=5.638159ms delta=4s 999ms 504µs 511ns
[INFO] [stdout] 2025-09-01T12:32:36.954268Z TRACE timesimp: sleeping to spread out requests delay=1.277661032s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:36.988119Z TRACE new{response=Response { client: 2025-09-01T12:32:36.975685356Z, server: 2025-09-01T12:32:41.981827976Z } current=2025-09-01T12:32:36.987961996Z}: timesimp::delta: response processing internals latency=6ms 138µs 320ns local_at_midpoint=2025-09-01T12:32:36.981823676Z delta=5s 4µs 300ns
[INFO] [stdout] 2025-09-01T12:32:36.988208Z TRACE timesimp: obtained raw offset from server latency=6.13832ms delta=5s 4µs 300ns
[INFO] [stdout] 2025-09-01T12:32:36.988225Z TRACE timesimp: sleeping to spread out requests delay=217.482421ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:37.219239Z TRACE new{response=Response { client: 2025-09-01T12:32:37.206697014Z, server: 2025-09-01T12:32:42.212887433Z } current=2025-09-01T12:32:37.219074423Z}: timesimp::delta: response processing internals latency=6ms 188µs 704ns local_at_midpoint=2025-09-01T12:32:37.212885718Z delta=5s 1µs 715ns
[INFO] [stdout] 2025-09-01T12:32:37.219328Z TRACE timesimp: obtained raw offset from server latency=6.188704ms delta=5s 1µs 715ns
[INFO] [stdout] 2025-09-01T12:32:37.219349Z TRACE timesimp: sleeping to spread out requests delay=1.620306159s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:37.578292Z TRACE new{response=Response { client: 2025-09-01T12:32:37.556725586Z, server: 2025-09-01T12:32:42.566926715Z } current=2025-09-01T12:32:37.578121964Z}: timesimp::delta: response processing internals latency=10ms 698µs 189ns local_at_midpoint=2025-09-01T12:32:37.567423775Z delta=4s 999ms 502µs 940ns
[INFO] [stdout] 2025-09-01T12:32:37.578461Z TRACE timesimp: obtained raw offset from server latency=10.698189ms delta=4s 999ms 502µs 940ns
[INFO] [stdout] 2025-09-01T12:32:37.578711Z TRACE timesimp: response deltas sorted by latency deltas=[4999.50294, 4999.618361, 4998.665721, 4999.9961299999995, 5000.33941]
[INFO] [stdout] 2025-09-01T12:32:37.578877Z TRACE timesimp: statistics about response deltas median=4998.665721 mean=4999.6245124 variance=0.39581921399790376 stddev=0.6291416485958498
[INFO] [stdout] 2025-09-01T12:32:37.578953Z TRACE timesimp: eliminated outliers inliers=[4998.665721]
[INFO] [stdout] 2025-09-01T12:32:37.578976Z DEBUG timesimp: storing calculated offset offset=4s 998ms 665µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-09-01T12:32:37.668247Z TRACE new{response=Response { client: 2025-09-01T12:32:37.645722881Z, server: 2025-09-01T12:32:37.6569101Z } current=2025-09-01T12:32:37.668085029Z}: timesimp::delta: response processing internals latency=11ms 181µs 74ns local_at_midpoint=2025-09-01T12:32:37.656903955Z delta=6µs 145ns
[INFO] [stdout] 2025-09-01T12:32:37.668335Z TRACE timesimp: obtained raw offset from server latency=11.181074ms delta=6µs 145ns
[INFO] [stdout] 2025-09-01T12:32:37.668364Z TRACE timesimp: response deltas sorted by latency deltas=[-0.010724, 0.006145, -0.00319, 0.008455, 0.743986]
[INFO] [stdout] 2025-09-01T12:32:37.668381Z TRACE timesimp: statistics about response deltas median=-0.00319 mean=0.1489344 variance=0.1107105797513 stddev=0.3327319938799093
[INFO] [stdout] 2025-09-01T12:32:37.668403Z TRACE timesimp: eliminated outliers inliers=[-0.010724, 0.006145, -0.00319, 0.008455]
[INFO] [stdout] 2025-09-01T12:32:37.668415Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2025-09-01T12:32:37.723796Z TRACE new{response=Response { client: 2025-09-01T12:32:37.701100228Z, server: 2025-09-01T12:32:42.712289107Z } current=2025-09-01T12:32:37.723626326Z}: timesimp::delta: response processing internals latency=11ms 263µs 49ns local_at_midpoint=2025-09-01T12:32:37.712363277Z delta=4s 999ms 925µs 830ns
[INFO] [stdout] 2025-09-01T12:32:37.723881Z TRACE timesimp: obtained raw offset from server latency=11.263049ms delta=4s 999ms 925µs 830ns
[INFO] [stdout] 2025-09-01T12:32:37.723901Z TRACE timesimp: sleeping to spread out requests delay=499.158473ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:37.899278Z TRACE new{response=Response { client: 2025-09-01T12:32:37.876716969Z, server: 2025-09-01T12:32:37.887908438Z } current=2025-09-01T12:32:37.899105897Z}: timesimp::delta: response processing internals latency=11ms 194µs 464ns local_at_midpoint=2025-09-01T12:32:37.887911433Z delta=2µs 995ns ago
[INFO] [stdout] 2025-09-01T12:32:37.899368Z TRACE timesimp: obtained raw offset from server latency=11.194464ms delta=2µs 995ns ago
[INFO] [stdout] 2025-09-01T12:32:37.899388Z TRACE timesimp: sleeping to spread out requests delay=1.334870995s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:38.005402Z TRACE new{response=Response { client: 2025-09-01T12:32:37.982733993Z, server: 2025-09-01T12:32:32.993931202Z } current=2025-09-01T12:32:38.005236222Z}: timesimp::delta: response processing internals latency=11ms 251µs 114ns local_at_midpoint=2025-09-01T12:32:37.993985107Z delta=5s 53µs 905ns ago
[INFO] [stdout] 2025-09-01T12:32:38.005570Z TRACE timesimp: obtained raw offset from server latency=11.251114ms delta=5s 53µs 905ns ago
[INFO] [stdout] 2025-09-01T12:32:38.005612Z TRACE timesimp: sleeping to spread out requests delay=1.698088584s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:38.246263Z TRACE new{response=Response { client: 2025-09-01T12:32:38.22366Z, server: 2025-09-01T12:32:43.234856419Z } current=2025-09-01T12:32:38.246104819Z}: timesimp::delta: response processing internals latency=11ms 222µs 409ns local_at_midpoint=2025-09-01T12:32:38.234882409Z delta=4s 999ms 974µs 10ns
[INFO] [stdout] 2025-09-01T12:32:38.246347Z TRACE timesimp: obtained raw offset from server latency=11.222409ms delta=4s 999ms 974µs 10ns
[INFO] [stdout] 2025-09-01T12:32:38.246368Z TRACE timesimp: sleeping to spread out requests delay=1.318804589s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:38.248277Z TRACE new{response=Response { client: 2025-09-01T12:32:38.23272517Z, server: 2025-09-01T12:32:43.239900829Z } current=2025-09-01T12:32:38.248109459Z}: timesimp::delta: response processing internals latency=7ms 692µs 144ns local_at_midpoint=2025-09-01T12:32:38.240417314Z delta=4s 999ms 483µs 515ns
[INFO] [stdout] 2025-09-01T12:32:38.248363Z TRACE timesimp: obtained raw offset from server latency=7.692144ms delta=4s 999ms 483µs 515ns
[INFO] [stdout] 2025-09-01T12:32:38.248390Z TRACE timesimp: response deltas sorted by latency deltas=[4999.504511, 4999.483515, 4999.993826, 4999.444931, 4999.999195]
[INFO] [stdout] 2025-09-01T12:32:38.248418Z TRACE timesimp: statistics about response deltas median=4999.993826 mean=4999.6851956 variance=0.08122435352783808 stddev=0.2849988658360557
[INFO] [stdout] 2025-09-01T12:32:38.248435Z TRACE timesimp: eliminated outliers inliers=[4999.993826, 4999.999195]
[INFO] [stdout] 2025-09-01T12:32:38.248455Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-09-01T12:32:38.387104Z TRACE new{response=Response { client: 2025-09-01T12:32:38.384688022Z, server: 2025-09-01T12:32:38.385822942Z } current=2025-09-01T12:32:38.386948651Z}: timesimp::delta: response processing internals latency=1ms 130µs 314ns local_at_midpoint=2025-09-01T12:32:38.385818336Z delta=4µs 606ns
[INFO] [stdout] 2025-09-01T12:32:38.387192Z TRACE timesimp: obtained raw offset from server latency=1.130314ms delta=4µs 606ns
[INFO] [stdout] 2025-09-01T12:32:38.387211Z TRACE timesimp: sleeping to spread out requests delay=1.366885821s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:38.677657Z TRACE new{response=Response { client: 2025-09-01T12:32:38.474742927Z, server: 2025-09-01T12:32:38.576116281Z } current=2025-09-01T12:32:38.677463276Z}: timesimp::delta: response processing internals latency=101ms 360µs 174ns local_at_midpoint=2025-09-01T12:32:38.576103101Z delta=13µs 180ns
[INFO] [stdout] 2025-09-01T12:32:38.677745Z TRACE timesimp: obtained raw offset from server latency=101.360174ms delta=13µs 180ns
[INFO] [stdout] 2025-09-01T12:32:38.677779Z TRACE timesimp: sleeping to spread out requests delay=8.764734ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:38.865882Z TRACE new{response=Response { client: 2025-09-01T12:32:38.844555827Z, server: 2025-09-01T12:32:43.856566097Z } current=2025-09-01T12:32:38.865714066Z}: timesimp::delta: response processing internals latency=10ms 579µs 119ns local_at_midpoint=2025-09-01T12:32:38.855134946Z delta=5s 1ms 431µs 151ns
[INFO] [stdout] 2025-09-01T12:32:38.865974Z TRACE timesimp: obtained raw offset from server latency=10.579119ms delta=5s 1ms 431µs 151ns
[INFO] [stdout] 2025-09-01T12:32:38.865995Z TRACE timesimp: sleeping to spread out requests delay=385.344498ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:38.889907Z TRACE new{response=Response { client: 2025-09-01T12:32:38.687996766Z, server: 2025-09-01T12:32:38.78934392Z } current=2025-09-01T12:32:38.889709885Z}: timesimp::delta: response processing internals latency=100ms 856µs 559ns local_at_midpoint=2025-09-01T12:32:38.788853325Z delta=490µs 595ns
[INFO] [stdout] 2025-09-01T12:32:38.890141Z TRACE timesimp: obtained raw offset from server latency=100.856559ms delta=490µs 595ns
[INFO] [stdout] 2025-09-01T12:32:38.890214Z TRACE timesimp: sleeping to spread out requests delay=1.322105022s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:39.269776Z TRACE new{response=Response { client: 2025-09-01T12:32:39.240605876Z, server: 2025-09-01T12:32:39.255581885Z } current=2025-09-01T12:32:39.269581845Z}: timesimp::delta: response processing internals latency=14ms 487µs 984ns local_at_midpoint=2025-09-01T12:32:39.25509386Z delta=488µs 25ns
[INFO] [stdout] 2025-09-01T12:32:39.269859Z TRACE timesimp: obtained raw offset from server latency=14.487984ms delta=488µs 25ns
[INFO] [stdout] 2025-09-01T12:32:39.269877Z TRACE timesimp: sleeping to spread out requests delay=1.95456953s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:39.272836Z TRACE new{response=Response { client: 2025-09-01T12:32:39.252725836Z, server: 2025-09-01T12:32:44.264548095Z } current=2025-09-01T12:32:39.272684304Z}: timesimp::delta: response processing internals latency=9ms 979µs 234ns local_at_midpoint=2025-09-01T12:32:39.26270507Z delta=5s 1ms 843µs 25ns
[INFO] [stdout] 2025-09-01T12:32:39.272909Z TRACE timesimp: obtained raw offset from server latency=9.979234ms delta=5s 1ms 843µs 25ns
[INFO] [stdout] 2025-09-01T12:32:39.272930Z TRACE timesimp: response deltas sorted by latency deltas=[5000.0043, 5000.001715, 5000.013655, 5001.843025, 5001.431151]
[INFO] [stdout] 2025-09-01T12:32:39.272943Z TRACE timesimp: statistics about response deltas median=5000.013655 mean=5000.658769199999 variance=0.81881448283329 stddev=0.904883684698365
[INFO] [stdout] 2025-09-01T12:32:39.272957Z TRACE timesimp: eliminated outliers inliers=[5000.0043, 5000.001715, 5000.013655]
[INFO] [stdout] 2025-09-01T12:32:39.272965Z DEBUG timesimp: storing calculated offset offset=5s 6µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-09-01T12:32:39.563861Z TRACE new{response=Response { client: 2025-09-01T12:32:38.005640082Z, server: 2025-09-01T12:32:38.78459165Z } current=2025-09-01T12:32:39.563687179Z}: timesimp::delta: response processing internals latency=779ms 23µs 548ns local_at_midpoint=2025-09-01T12:32:38.78466363Z delta=71µs 980ns ago
[INFO] [stdout] 2025-09-01T12:32:39.563938Z TRACE timesimp: obtained raw offset from server latency=779.023548ms delta=71µs 980ns ago
[INFO] [stdout] 2025-09-01T12:32:39.563956Z TRACE timesimp: sleeping to spread out requests delay=1.22975425s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:39.600760Z TRACE new{response=Response { client: 2025-09-01T12:32:39.572584499Z, server: 2025-09-01T12:32:44.586581368Z } current=2025-09-01T12:32:39.600603487Z}: timesimp::delta: response processing internals latency=14ms 9µs 494ns local_at_midpoint=2025-09-01T12:32:39.586593993Z delta=4s 999ms 987µs 375ns
[INFO] [stdout] 2025-09-01T12:32:39.600835Z TRACE timesimp: obtained raw offset from server latency=14.009494ms delta=4s 999ms 987µs 375ns
[INFO] [stdout] 2025-09-01T12:32:39.600857Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00165, 4999.994986, 4999.97401, 4999.92583, 4999.987375]
[INFO] [stdout] 2025-09-01T12:32:39.600870Z TRACE timesimp: statistics about response deltas median=4999.97401 mean=4999.976770200001 variance=0.0009164510701943416 stddev=0.03027294287303997
[INFO] [stdout] 2025-09-01T12:32:39.600884Z TRACE timesimp: eliminated outliers inliers=[5000.00165, 4999.994986, 4999.97401, 4999.987375]
[INFO] [stdout] 2025-09-01T12:32:39.600893Z DEBUG timesimp: storing calculated offset offset=4s 999ms 989µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2025-09-01T12:32:39.727940Z TRACE new{response=Response { client: 2025-09-01T12:32:39.705353692Z, server: 2025-09-01T12:32:34.716566291Z } current=2025-09-01T12:32:39.72776611Z}: timesimp::delta: response processing internals latency=11ms 206µs 209ns local_at_midpoint=2025-09-01T12:32:39.716559901Z delta=4s 999ms 993µs 610ns ago
[INFO] [stdout] 2025-09-01T12:32:39.728044Z TRACE timesimp: obtained raw offset from server latency=11.206209ms delta=4s 999ms 993µs 610ns ago
[INFO] [stdout] 2025-09-01T12:32:39.728833Z TRACE timesimp: sleeping to spread out requests delay=1.407409919s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:39.758132Z TRACE new{response=Response { client: 2025-09-01T12:32:39.755708769Z, server: 2025-09-01T12:32:39.756854239Z } current=2025-09-01T12:32:39.757977629Z}: timesimp::delta: response processing internals latency=1ms 134µs 430ns local_at_midpoint=2025-09-01T12:32:39.756843199Z delta=11µs 40ns
[INFO] [stdout] 2025-09-01T12:32:39.758214Z TRACE timesimp: obtained raw offset from server latency=1.13443ms delta=11µs 40ns
[INFO] [stdout] 2025-09-01T12:32:39.758230Z TRACE timesimp: sleeping to spread out requests delay=111.185403ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:39.873004Z TRACE new{response=Response { client: 2025-09-01T12:32:39.870590753Z, server: 2025-09-01T12:32:39.871728683Z } current=2025-09-01T12:32:39.872850173Z}: timesimp::delta: response processing internals latency=1ms 129µs 710ns local_at_midpoint=2025-09-01T12:32:39.871720463Z delta=8µs 220ns
[INFO] [stdout] 2025-09-01T12:32:39.873081Z TRACE timesimp: obtained raw offset from server latency=1.12971ms delta=8µs 220ns
[INFO] [stdout] 2025-09-01T12:32:39.873100Z TRACE timesimp: response deltas sorted by latency deltas=[0.00822, 0.004606, 0.005645, 0.01104, 0.009765]
[INFO] [stdout] 2025-09-01T12:32:39.873113Z TRACE timesimp: statistics about response deltas median=0.005645 mean=0.007855200000000001 variance=7.3414127e-6 stddev=0.002709504142827613
[INFO] [stdout] 2025-09-01T12:32:39.873126Z TRACE timesimp: eliminated outliers inliers=[0.00822, 0.004606, 0.005645]
[INFO] [stdout] 2025-09-01T12:32:39.873135Z DEBUG timesimp: storing calculated offset offset=6µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-09-01T12:32:40.415594Z TRACE new{response=Response { client: 2025-09-01T12:32:40.212736975Z, server: 2025-09-01T12:32:40.314086149Z } current=2025-09-01T12:32:40.415413814Z}: timesimp::delta: response processing internals latency=101ms 338µs 419ns local_at_midpoint=2025-09-01T12:32:40.314075394Z delta=10µs 755ns
[INFO] [stdout] 2025-09-01T12:32:40.415684Z TRACE timesimp: obtained raw offset from server latency=101.338419ms delta=10µs 755ns
[INFO] [stdout] 2025-09-01T12:32:40.415709Z TRACE timesimp: response deltas sorted by latency deltas=[0.490595, 0.025786, 0.010755, 0.01318, 3.94807]
[INFO] [stdout] 2025-09-01T12:32:40.415725Z TRACE timesimp: statistics about response deltas median=0.010755 mean=0.8976772000000001 variance=2.9499431755367 stddev=1.7175398614112862
[INFO] [stdout] 2025-09-01T12:32:40.415742Z TRACE timesimp: eliminated outliers inliers=[0.490595, 0.025786, 0.010755, 0.01318]
[INFO] [stdout] 2025-09-01T12:32:40.415759Z DEBUG timesimp: storing calculated offset offset=135µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-09-01T12:32:41.191747Z TRACE new{response=Response { client: 2025-09-01T12:32:41.137589126Z, server: 2025-09-01T12:32:36.171589584Z } current=2025-09-01T12:32:41.191578803Z}: timesimp::delta: response processing internals latency=26ms 994µs 838ns local_at_midpoint=2025-09-01T12:32:41.164583964Z delta=4s 992ms 994µs 380ns ago
[INFO] [stdout] 2025-09-01T12:32:41.191827Z TRACE timesimp: obtained raw offset from server latency=26.994838ms delta=4s 992ms 994µs 380ns ago
[INFO] [stdout] 2025-09-01T12:32:41.191850Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.999245, -4999.9936099999995, -5000.053905, -4999.046455, -4992.99438]
[INFO] [stdout] 2025-09-01T12:32:41.191864Z TRACE timesimp: statistics about response deltas median=-5000.053905 mean=-4998.4175190000005 variance=9.36741905644157 stddev=3.060623965213886
[INFO] [stdout] 2025-09-01T12:32:41.191877Z TRACE timesimp: eliminated outliers inliers=[-4999.999245, -4999.9936099999995, -5000.053905, -4999.046455]
[INFO] [stdout] 2025-09-01T12:32:41.191887Z DEBUG timesimp: storing calculated offset offset=4s 999ms 773µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-09-01T12:32:41.248265Z TRACE new{response=Response { client: 2025-09-01T12:32:41.225725161Z, server: 2025-09-01T12:32:41.236913271Z } current=2025-09-01T12:32:41.24810602Z}: timesimp::delta: response processing internals latency=11ms 190µs 429ns local_at_midpoint=2025-09-01T12:32:41.23691559Z delta=2µs 319ns ago
[INFO] [stdout] 2025-09-01T12:32:41.248341Z TRACE timesimp: obtained raw offset from server latency=11.190429ms delta=2µs 319ns ago
[INFO] [stdout] 2025-09-01T12:32:41.248363Z TRACE timesimp: response deltas sorted by latency deltas=[0.005175, -0.002319, -0.002995, 0.055596, 0.488025]
[INFO] [stdout] 2025-09-01T12:32:41.248376Z TRACE timesimp: statistics about response deltas median=-0.002995 mean=0.1086964 variance=0.045556476846800004 stddev=0.21343963279297498
[INFO] [stdout] 2025-09-01T12:32:41.248389Z TRACE timesimp: eliminated outliers inliers=[0.005175, -0.002319, -0.002995, 0.055596]
[INFO] [stdout] 2025-09-01T12:32:41.248398Z DEBUG timesimp: storing calculated offset offset=13µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-09-01T12:32:42.738898Z TRACE new{response=Response { client: 2025-09-01T12:32:40.797661354Z, server: 2025-09-01T12:32:41.770605862Z } current=2025-09-01T12:32:42.738727751Z}: timesimp::delta: response processing internals latency=970ms 533µs 198ns local_at_midpoint=2025-09-01T12:32:41.768194552Z delta=2ms 411µs 310ns
[INFO] [stdout] 2025-09-01T12:32:42.738975Z TRACE timesimp: obtained raw offset from server latency=970.533198ms delta=2ms 411µs 310ns
[INFO] [stdout] 2025-09-01T12:32:42.738992Z TRACE timesimp: sleeping to spread out requests delay=1.701543602s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:46.086747Z TRACE new{response=Response { client: 2025-09-01T12:32:44.441719081Z, server: 2025-09-01T12:32:45.262726057Z } current=2025-09-01T12:32:46.086583863Z}: timesimp::delta: response processing internals latency=822ms 432µs 391ns local_at_midpoint=2025-09-01T12:32:45.264151472Z delta=1ms 425µs 415ns ago
[INFO] [stdout] 2025-09-01T12:32:46.086838Z TRACE timesimp: obtained raw offset from server latency=822.432391ms delta=1ms 425µs 415ns ago
[INFO] [stdout] 2025-09-01T12:32:46.086857Z TRACE timesimp: sleeping to spread out requests delay=1.787572466s max_jitter=2s
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-9d1c06fe72bb6515)
[INFO] [stdout] 2025-09-01T12:32:49.520776Z TRACE new{response=Response { client: 2025-09-01T12:32:47.880586968Z, server: 2025-09-01T12:32:48.699702225Z } current=2025-09-01T12:32:49.520594072Z}: timesimp::delta: response processing internals latency=820ms 3µs 552ns local_at_midpoint=2025-09-01T12:32:48.70059052Z delta=888µs 295ns ago
[INFO] [stdout] 2025-09-01T12:32:49.520878Z TRACE timesimp: obtained raw offset from server latency=820.003552ms delta=888µs 295ns ago
[INFO] [stdout] 2025-09-01T12:32:49.520906Z TRACE timesimp: response deltas sorted by latency deltas=[-0.253305, -0.07198, -0.888295, -1.425415, 2.41131]
[INFO] [stdout] 2025-09-01T12:32:49.520924Z TRACE timesimp: statistics about response deltas median=-0.888295 mean=-0.04553700000000003 variance=2.1735670742324995 stddev=1.4743022330012594
[INFO] [stdout] 2025-09-01T12:32:49.520947Z TRACE timesimp: eliminated outliers inliers=[-0.253305, -0.07198, -0.888295, -1.425415]
[INFO] [stdout] 2025-09-01T12:32:49.520959Z DEBUG timesimp: storing calculated offset offset=659µ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 14.53s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-09-01T12:32:49.525100Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-01T12:32:49.525264Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:49.525693Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:49.525728Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:49.525845Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-01T12:32:49.525906Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:49.526697Z TRACE new{response=Response { client: 2025-09-01T12:32:49.526536431Z, server: 2025-09-01T12:32:44.526550181Z } current=2025-09-01T12:32:49.526552891Z}: timesimp::delta: response processing internals latency=8µs 230ns local_at_midpoint=2025-09-01T12:32:49.526544661Z delta=4s 999ms 994µs 480ns ago
[INFO] [stdout] 2025-09-01T12:32:49.526810Z TRACE timesimp: obtained raw offset from server latency=8.23µs delta=4s 999ms 994µs 480ns ago
[INFO] [stdout] 2025-09-01T12:32:49.526874Z TRACE timesimp: sleeping to spread out requests delay=710.035279ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:49.527072Z TRACE new{response=Response { client: 2025-09-01T12:32:49.526968451Z, server: 2025-09-01T12:32:49.526971651Z } current=2025-09-01T12:32:49.526973531Z}: timesimp::delta: response processing internals latency=2µs 540ns local_at_midpoint=2025-09-01T12:32:49.526970991Z delta=660ns
[INFO] [stdout] 2025-09-01T12:32:49.527136Z TRACE timesimp: obtained raw offset from server latency=2.54µs delta=660ns
[INFO] [stdout] 2025-09-01T12:32:49.527160Z DEBUG timesimp: no offset stored, storing initial delta offset=660ns
[INFO] [stdout] 2025-09-01T12:32:49.527179Z TRACE timesimp: sleeping to spread out requests delay=1.542252743s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:49.527312Z TRACE new{response=Response { client: 2025-09-01T12:32:49.527151611Z, server: 2025-09-01T12:32:54.527159461Z } current=2025-09-01T12:32:49.527162581Z}: timesimp::delta: response processing internals latency=5µs 485ns local_at_midpoint=2025-09-01T12:32:49.527157096Z delta=5s 2µs 365ns
[INFO] [stdout] 2025-09-01T12:32:49.527379Z TRACE timesimp: obtained raw offset from server latency=5.485µs delta=5s 2µs 365ns
[INFO] [stdout] 2025-09-01T12:32:49.527394Z TRACE timesimp: sleeping to spread out requests delay=508.297881ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:49.529689Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T12:32:49.529790Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:49.531707Z TRACE new{response=Response { client: 2025-09-01T12:32:49.531568821Z, server: 2025-09-01T12:32:49.531574951Z } current=2025-09-01T12:32:49.531578311Z}: timesimp::delta: response processing internals latency=4µs 745ns local_at_midpoint=2025-09-01T12:32:49.531573566Z delta=1µs 385ns
[INFO] [stdout] 2025-09-01T12:32:49.531806Z TRACE timesimp: obtained raw offset from server latency=4.745µs delta=1µs 385ns
[INFO] [stdout] 2025-09-01T12:32:49.531844Z TRACE timesimp: sleeping to spread out requests delay=1.73895032s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:50.038544Z TRACE new{response=Response { client: 2025-09-01T12:32:50.038350874Z, server: 2025-09-01T12:32:55.038359824Z } current=2025-09-01T12:32:50.038363284Z}: timesimp::delta: response processing internals latency=6µs 205ns local_at_midpoint=2025-09-01T12:32:50.038357079Z delta=5s 2µs 745ns
[INFO] [stdout] 2025-09-01T12:32:50.038615Z TRACE timesimp: obtained raw offset from server latency=6.205µs delta=5s 2µs 745ns
[INFO] [stdout] 2025-09-01T12:32:50.038630Z TRACE timesimp: sleeping to spread out requests delay=175.788453ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:50.215955Z TRACE new{response=Response { client: 2025-09-01T12:32:50.215747375Z, server: 2025-09-01T12:32:55.215759395Z } current=2025-09-01T12:32:50.215764144Z}: timesimp::delta: response processing internals latency=8µs 384ns local_at_midpoint=2025-09-01T12:32:50.215755759Z delta=5s 3µs 636ns
[INFO] [stdout] 2025-09-01T12:32:50.216054Z TRACE timesimp: obtained raw offset from server latency=8.384µs delta=5s 3µs 636ns
[INFO] [stdout] 2025-09-01T12:32:50.216072Z TRACE timesimp: sleeping to spread out requests delay=161.855327ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:50.238970Z TRACE new{response=Response { client: 2025-09-01T12:32:50.238811703Z, server: 2025-09-01T12:32:45.238821534Z } current=2025-09-01T12:32:50.238824654Z}: timesimp::delta: response processing internals latency=6µs 475ns local_at_midpoint=2025-09-01T12:32:50.238818178Z delta=4s 999ms 996µs 644ns ago
[INFO] [stdout] 2025-09-01T12:32:50.239062Z TRACE timesimp: obtained raw offset from server latency=6.475µs delta=4s 999ms 996µs 644ns ago
[INFO] [stdout] 2025-09-01T12:32:50.239083Z TRACE timesimp: sleeping to spread out requests delay=224.420205ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:50.381757Z TRACE new{response=Response { client: 2025-09-01T12:32:50.381587306Z, server: 2025-09-01T12:32:55.381597536Z } current=2025-09-01T12:32:50.381601096Z}: timesimp::delta: response processing internals latency=6µs 895ns local_at_midpoint=2025-09-01T12:32:50.381594201Z delta=5s 3µs 335ns
[INFO] [stdout] 2025-09-01T12:32:50.381830Z TRACE timesimp: obtained raw offset from server latency=6.895µs delta=5s 3µs 335ns
[INFO] [stdout] 2025-09-01T12:32:50.381845Z TRACE timesimp: sleeping to spread out requests delay=516.398261ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:50.464742Z TRACE new{response=Response { client: 2025-09-01T12:32:50.464568891Z, server: 2025-09-01T12:32:45.464579702Z } current=2025-09-01T12:32:50.464583531Z}: timesimp::delta: response processing internals latency=7µs 320ns local_at_midpoint=2025-09-01T12:32:50.464576211Z delta=4s 999ms 996µs 509ns ago
[INFO] [stdout] 2025-09-01T12:32:50.464811Z TRACE timesimp: obtained raw offset from server latency=7.32µs delta=4s 999ms 996µs 509ns ago
[INFO] [stdout] 2025-09-01T12:32:50.464826Z TRACE timesimp: sleeping to spread out requests delay=399.231938ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:50.867781Z TRACE new{response=Response { client: 2025-09-01T12:32:50.86760938Z, server: 2025-09-01T12:32:45.86761969Z } current=2025-09-01T12:32:50.86762357Z}: timesimp::delta: response processing internals latency=7µs 95ns local_at_midpoint=2025-09-01T12:32:50.867616475Z delta=4s 999ms 996µs 785ns ago
[INFO] [stdout] 2025-09-01T12:32:50.867861Z TRACE timesimp: obtained raw offset from server latency=7.095µs delta=4s 999ms 996µs 785ns ago
[INFO] [stdout] 2025-09-01T12:32:50.867877Z TRACE timesimp: sleeping to spread out requests delay=1.134097522s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:50.899761Z TRACE new{response=Response { client: 2025-09-01T12:32:50.899587519Z, server: 2025-09-01T12:32:55.899597688Z } current=2025-09-01T12:32:50.899601219Z}: timesimp::delta: response processing internals latency=6µs 850ns local_at_midpoint=2025-09-01T12:32:50.899594369Z delta=5s 3µs 319ns
[INFO] [stdout] 2025-09-01T12:32:50.899948Z TRACE timesimp: obtained raw offset from server latency=6.85µs delta=5s 3µs 319ns
[INFO] [stdout] 2025-09-01T12:32:50.900038Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002365, 5000.002745, 5000.003319, 5000.003335, 5000.003636]
[INFO] [stdout] 2025-09-01T12:32:50.900104Z TRACE timesimp: statistics about response deltas median=5000.003319 mean=5000.00308 variance=2.6368300012667623e-7 stddev=0.0005135007304052023
[INFO] [stdout] 2025-09-01T12:32:50.900165Z TRACE timesimp: eliminated outliers inliers=[5000.003319, 5000.003335, 5000.003636]
[INFO] [stdout] 2025-09-01T12:32:50.900198Z DEBUG timesimp: storing calculated offset offset=5s 3µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2025-09-01T12:32:51.071745Z TRACE new{response=Response { client: 2025-09-01T12:32:51.071587079Z, server: 2025-09-01T12:32:51.071597539Z } current=2025-09-01T12:32:51.071600169Z}: timesimp::delta: response processing internals latency=6µs 545ns local_at_midpoint=2025-09-01T12:32:51.071593624Z delta=3µs 915ns
[INFO] [stdout] 2025-09-01T12:32:51.071833Z TRACE timesimp: obtained raw offset from server latency=6.545µs delta=3µs 915ns
[INFO] [stdout] 2025-09-01T12:32:51.071849Z TRACE timesimp: sleeping to spread out requests delay=173.858457ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:51.247465Z TRACE new{response=Response { client: 2025-09-01T12:32:51.24728046Z, server: 2025-09-01T12:32:51.24729095Z } current=2025-09-01T12:32:51.24729401Z}: timesimp::delta: response processing internals latency=6µs 775ns local_at_midpoint=2025-09-01T12:32:51.247287235Z delta=3µs 715ns
[INFO] [stdout] 2025-09-01T12:32:51.247569Z TRACE timesimp: obtained raw offset from server latency=6.775µs delta=3µs 715ns
[INFO] [stdout] 2025-09-01T12:32:51.247586Z TRACE timesimp: sleeping to spread out requests delay=1.15544816s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:51.275719Z TRACE new{response=Response { client: 2025-09-01T12:32:51.275554839Z, server: 2025-09-01T12:32:51.275564488Z } current=2025-09-01T12:32:51.275567739Z}: timesimp::delta: response processing internals latency=6µs 450ns local_at_midpoint=2025-09-01T12:32:51.275561289Z delta=3µs 199ns
[INFO] [stdout] 2025-09-01T12:32:51.275801Z TRACE timesimp: obtained raw offset from server latency=6.45µs delta=3µs 199ns
[INFO] [stdout] 2025-09-01T12:32:51.275818Z TRACE timesimp: sleeping to spread out requests delay=1.273674254s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:52.009794Z TRACE new{response=Response { client: 2025-09-01T12:32:52.00958358Z, server: 2025-09-01T12:32:47.009593509Z } current=2025-09-01T12:32:52.009597029Z}: timesimp::delta: response processing internals latency=6µs 724ns local_at_midpoint=2025-09-01T12:32:52.009590304Z delta=4s 999ms 996µs 795ns ago
[INFO] [stdout] 2025-09-01T12:32:52.009880Z TRACE timesimp: obtained raw offset from server latency=6.724µs delta=4s 999ms 996µs 795ns ago
[INFO] [stdout] 2025-09-01T12:32:52.009905Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.996644, -4999.996795, -4999.996785, -4999.996509, -4999.99448]
[INFO] [stdout] 2025-09-01T12:32:52.009920Z TRACE timesimp: statistics about response deltas median=-4999.996785 mean=-4999.9962426 variance=9.845482997340754e-7 stddev=0.0009922440726626062
[INFO] [stdout] 2025-09-01T12:32:52.009941Z TRACE timesimp: eliminated outliers inliers=[-4999.996644, -4999.996795, -4999.996785, -4999.996509]
[INFO] [stdout] 2025-09-01T12:32:52.009952Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2025-09-01T12:32:52.404935Z TRACE new{response=Response { client: 2025-09-01T12:32:52.404750569Z, server: 2025-09-01T12:32:52.404767979Z } current=2025-09-01T12:32:52.404770439Z}: timesimp::delta: response processing internals latency=9µs 935ns local_at_midpoint=2025-09-01T12:32:52.404760504Z delta=7µs 475ns
[INFO] [stdout] 2025-09-01T12:32:52.405012Z TRACE timesimp: obtained raw offset from server latency=9.935µs delta=7µs 475ns
[INFO] [stdout] 2025-09-01T12:32:52.405028Z TRACE timesimp: sleeping to spread out requests delay=590.17282ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:52.550894Z TRACE new{response=Response { client: 2025-09-01T12:32:52.550706781Z, server: 2025-09-01T12:32:52.550717251Z } current=2025-09-01T12:32:52.550720611Z}: timesimp::delta: response processing internals latency=6µs 915ns local_at_midpoint=2025-09-01T12:32:52.550713696Z delta=3µs 555ns
[INFO] [stdout] 2025-09-01T12:32:52.550983Z TRACE timesimp: obtained raw offset from server latency=6.915µs delta=3µs 555ns
[INFO] [stdout] 2025-09-01T12:32:52.551002Z TRACE timesimp: sleeping to spread out requests delay=905.028519ms max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:52.996940Z TRACE new{response=Response { client: 2025-09-01T12:32:52.996762647Z, server: 2025-09-01T12:32:52.996773517Z } current=2025-09-01T12:32:52.996776357Z}: timesimp::delta: response processing internals latency=6µs 855ns local_at_midpoint=2025-09-01T12:32:52.996769502Z delta=4µs 15ns
[INFO] [stdout] 2025-09-01T12:32:52.997031Z TRACE timesimp: obtained raw offset from server latency=6.855µs delta=4µs 15ns
[INFO] [stdout] 2025-09-01T12:32:52.997056Z TRACE timesimp: response deltas sorted by latency deltas=[0.00066, 0.003915, 0.003715, 0.004015, 0.007475]
[INFO] [stdout] 2025-09-01T12:32:52.997070Z TRACE timesimp: statistics about response deltas median=0.003715 mean=0.0039559999999999994 variance=5.827555e-6 stddev=0.0024140329326668266
[INFO] [stdout] 2025-09-01T12:32:52.997096Z TRACE timesimp: eliminated outliers inliers=[0.003915, 0.003715, 0.004015]
[INFO] [stdout] 2025-09-01T12:32:52.997106Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2025-09-01T12:32:53.457895Z TRACE new{response=Response { client: 2025-09-01T12:32:53.457721313Z, server: 2025-09-01T12:32:53.457731303Z } current=2025-09-01T12:32:53.457734853Z}: timesimp::delta: response processing internals latency=6µs 770ns local_at_midpoint=2025-09-01T12:32:53.457728083Z delta=3µs 220ns
[INFO] [stdout] 2025-09-01T12:32:53.457983Z TRACE timesimp: obtained raw offset from server latency=6.77µs delta=3µs 220ns
[INFO] [stdout] 2025-09-01T12:32:53.458003Z TRACE timesimp: sleeping to spread out requests delay=1.549720183s max_jitter=2s
[INFO] [stdout] 2025-09-01T12:32:55.009934Z TRACE new{response=Response { client: 2025-09-01T12:32:55.009766531Z, server: 2025-09-01T12:32:55.009777011Z } current=2025-09-01T12:32:55.009780351Z}: timesimp::delta: response processing internals latency=6µs 910ns local_at_midpoint=2025-09-01T12:32:55.009773441Z delta=3µs 570ns
[INFO] [stdout] 2025-09-01T12:32:55.010027Z TRACE timesimp: obtained raw offset from server latency=6.91µs delta=3µs 570ns
[INFO] [stdout] 2025-09-01T12:32:55.010052Z TRACE timesimp: response deltas sorted by latency deltas=[0.001385, 0.003199, 0.00322, 0.00357, 0.003555]
[INFO] [stdout] 2025-09-01T12:32:55.010067Z TRACE timesimp: statistics about response deltas median=0.00322 mean=0.0029858000000000003 variance=8.320357e-7 stddev=0.000912159909226447
[INFO] [stdout] 2025-09-01T12:32:55.010093Z TRACE timesimp: eliminated outliers inliers=[0.003199, 0.00322, 0.00357, 0.003555]
[INFO] [stdout] 2025-09-01T12:32:55.010104Z DEBUG timesimp: storing calculated offset offset=3µs
[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 5.49s
[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" "b6f1f71368048125998c50c88bf2239c5c58edee50e36aebaefc2ef16038da09", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "b6f1f71368048125998c50c88bf2239c5c58edee50e36aebaefc2ef16038da09", kill_on_drop: false }`
[INFO] [stdout] b6f1f71368048125998c50c88bf2239c5c58edee50e36aebaefc2ef16038da09