[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against 1.90.0 for beta-1.91-3
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-5-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-5-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain 1.90.0
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.90.0" "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" "+1.90.0" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+1.90.0" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] f5e366715cdea7826fbb2429a064f532be5008ee4bb00bdc40a49649335c07e4
[INFO] running `Command { std: "docker" "start" "-a" "f5e366715cdea7826fbb2429a064f532be5008ee4bb00bdc40a49649335c07e4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "f5e366715cdea7826fbb2429a064f532be5008ee4bb00bdc40a49649335c07e4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "f5e366715cdea7826fbb2429a064f532be5008ee4bb00bdc40a49649335c07e4", kill_on_drop: false }`
[INFO] [stdout] f5e366715cdea7826fbb2429a064f532be5008ee4bb00bdc40a49649335c07e4
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+1.90.0" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] ce677aa2799693943ede363e00baee5d91b3d68af65a5394283a504fd11cab54
[INFO] running `Command { std: "docker" "start" "-a" "ce677aa2799693943ede363e00baee5d91b3d68af65a5394283a504fd11cab54", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 8.52s
[INFO] running `Command { std: "docker" "inspect" "ce677aa2799693943ede363e00baee5d91b3d68af65a5394283a504fd11cab54", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "ce677aa2799693943ede363e00baee5d91b3d68af65a5394283a504fd11cab54", kill_on_drop: false }`
[INFO] [stdout] ce677aa2799693943ede363e00baee5d91b3d68af65a5394283a504fd11cab54
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+1.90.0" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] bebba9a2e498d08155d921f22b336e84b4c8b6f8b140e8e171969a6c901025ce
[INFO] running `Command { std: "docker" "start" "-a" "bebba9a2e498d08155d921f22b336e84b4c8b6f8b140e8e171969a6c901025ce", 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 litemap v0.7.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling rustls-pemfile v2.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 synstructure v0.13.1
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[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 35.53s
[INFO] running `Command { std: "docker" "inspect" "bebba9a2e498d08155d921f22b336e84b4c8b6f8b140e8e171969a6c901025ce", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "bebba9a2e498d08155d921f22b336e84b4c8b6f8b140e8e171969a6c901025ce", kill_on_drop: false }`
[INFO] [stdout] bebba9a2e498d08155d921f22b336e84b4c8b6f8b140e8e171969a6c901025ce
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+1.90.0" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 0aa948e3c264f8a52ea536d1591f4b88e8aa5213e28f8aa498a6ac9573302ce7
[INFO] running `Command { std: "docker" "start" "-a" "0aa948e3c264f8a52ea536d1591f4b88e8aa5213e28f8aa498a6ac9573302ce7", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.24s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-3b4f137662fc7cca)
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-048c4171ae76d44f)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-10-01T14:16:24.165783Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-10-01T14:16:24.165788Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.165899Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.165910Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.166335Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-10-01T14:16:24.166350Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.166371Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.166384Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.166423Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.166453Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.166718Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.166790Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.168839Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.166814Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.167000Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.169035Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.168799Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.169147Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.167151Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:24.169217Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.172606Z TRACE new{response=Response { client: 2025-10-01T14:16:24.17018374Z, server: 2025-10-01T14:16:24.17130275Z } current=2025-10-01T14:16:24.17242146Z}: timesimp::delta: response processing internals latency=1ms 118µs 860ns local_at_midpoint=2025-10-01T14:16:24.1713026Z delta=150ns
[INFO] [stdout] 2025-10-01T14:16:24.172751Z TRACE timesimp: obtained raw offset from server latency=1.11886ms delta=150ns
[INFO] [stdout] 2025-10-01T14:16:24.172798Z DEBUG timesimp: no offset stored, storing initial delta offset=150ns
[INFO] [stdout] 2025-10-01T14:16:24.172841Z TRACE timesimp: sleeping to spread out requests delay=300.549944ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.179993Z TRACE new{response=Response { client: 2025-10-01T14:16:24.16756583Z, server: 2025-10-01T14:16:29.17367005Z } current=2025-10-01T14:16:24.179802479Z}: timesimp::delta: response processing internals latency=6ms 118µs 324ns local_at_midpoint=2025-10-01T14:16:24.173684154Z delta=4s 999ms 985µs 896ns
[INFO] [stdout] 2025-10-01T14:16:24.181675Z TRACE timesimp: obtained raw offset from server latency=6.118324ms delta=4s 999ms 985µs 896ns
[INFO] [stdout] 2025-10-01T14:16:24.181757Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 985µs 896ns
[INFO] [stdout] 2025-10-01T14:16:24.181797Z TRACE timesimp: sleeping to spread out requests delay=1.206061775s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.182005Z TRACE new{response=Response { client: 2025-10-01T14:16:24.167632721Z, server: 2025-10-01T14:16:29.1747665Z } current=2025-10-01T14:16:24.181893919Z}: timesimp::delta: response processing internals latency=7ms 130µs 599ns local_at_midpoint=2025-10-01T14:16:24.17476332Z delta=5s 3µs 180ns
[INFO] [stdout] 2025-10-01T14:16:24.182068Z TRACE timesimp: obtained raw offset from server latency=7.130599ms delta=5s 3µs 180ns
[INFO] [stdout] 2025-10-01T14:16:24.182089Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 3µs 180ns
[INFO] [stdout] 2025-10-01T14:16:24.182099Z TRACE timesimp: sleeping to spread out requests delay=1.890073438s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.189718Z TRACE new{response=Response { client: 2025-10-01T14:16:24.167121751Z, server: 2025-10-01T14:16:29.178302989Z } current=2025-10-01T14:16:24.189481068Z}: timesimp::delta: response processing internals latency=11ms 179µs 658ns local_at_midpoint=2025-10-01T14:16:24.178301409Z delta=5s 1µs 580ns
[INFO] [stdout] 2025-10-01T14:16:24.189810Z TRACE timesimp: obtained raw offset from server latency=11.179658ms delta=5s 1µs 580ns
[INFO] [stdout] 2025-10-01T14:16:24.189829Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 580ns
[INFO] [stdout] 2025-10-01T14:16:24.189840Z TRACE timesimp: sleeping to spread out requests delay=1.225519735s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.189919Z TRACE new{response=Response { client: 2025-10-01T14:16:24.16755513Z, server: 2025-10-01T14:16:24.178679959Z } current=2025-10-01T14:16:24.189812798Z}: timesimp::delta: response processing internals latency=11ms 128µs 834ns local_at_midpoint=2025-10-01T14:16:24.178683964Z delta=4µs 5ns ago
[INFO] [stdout] 2025-10-01T14:16:24.191674Z TRACE timesimp: obtained raw offset from server latency=11.128834ms delta=4µs 5ns ago
[INFO] [stdout] 2025-10-01T14:16:24.191749Z TRACE timesimp: sleeping to spread out requests delay=959.38743ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.192697Z TRACE new{response=Response { client: 2025-10-01T14:16:24.1702628Z, server: 2025-10-01T14:16:29.181393299Z } current=2025-10-01T14:16:24.192528648Z}: timesimp::delta: response processing internals latency=11ms 132µs 924ns local_at_midpoint=2025-10-01T14:16:24.181395724Z delta=4s 999ms 997µs 575ns
[INFO] [stdout] 2025-10-01T14:16:24.192766Z TRACE timesimp: obtained raw offset from server latency=11.132924ms delta=4s 999ms 997µs 575ns
[INFO] [stdout] 2025-10-01T14:16:24.192782Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 997µs 575ns
[INFO] [stdout] 2025-10-01T14:16:24.192793Z TRACE timesimp: sleeping to spread out requests delay=1.759585611s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.192969Z TRACE new{response=Response { client: 2025-10-01T14:16:24.17040797Z, server: 2025-10-01T14:16:19.181518869Z } current=2025-10-01T14:16:24.192871698Z}: timesimp::delta: response processing internals latency=11ms 231µs 864ns local_at_midpoint=2025-10-01T14:16:24.181639834Z delta=5s 120µs 965ns ago
[INFO] [stdout] 2025-10-01T14:16:24.193028Z TRACE timesimp: obtained raw offset from server latency=11.231864ms delta=5s 120µs 965ns ago
[INFO] [stdout] 2025-10-01T14:16:24.193044Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 120µs 965ns ago
[INFO] [stdout] 2025-10-01T14:16:24.193054Z TRACE timesimp: sleeping to spread out requests delay=885.550682ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.197911Z TRACE new{response=Response { client: 2025-10-01T14:16:24.17184431Z, server: 2025-10-01T14:16:24.185703968Z } current=2025-10-01T14:16:24.197735097Z}: timesimp::delta: response processing internals latency=12ms 945µs 393ns local_at_midpoint=2025-10-01T14:16:24.184789703Z delta=914µs 265ns
[INFO] [stdout] 2025-10-01T14:16:24.197987Z TRACE timesimp: obtained raw offset from server latency=12.945393ms delta=914µs 265ns
[INFO] [stdout] 2025-10-01T14:16:24.198005Z TRACE timesimp: sleeping to spread out requests delay=1.814992616s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.373043Z TRACE new{response=Response { client: 2025-10-01T14:16:24.17007879Z, server: 2025-10-01T14:16:24.271421619Z } current=2025-10-01T14:16:24.372829037Z}: timesimp::delta: response processing internals latency=101ms 375µs 123ns local_at_midpoint=2025-10-01T14:16:24.271453913Z delta=32µs 294ns ago
[INFO] [stdout] 2025-10-01T14:16:24.373134Z TRACE timesimp: obtained raw offset from server latency=101.375123ms delta=32µs 294ns ago
[INFO] [stdout] 2025-10-01T14:16:24.373155Z DEBUG timesimp: no offset stored, storing initial delta offset=32µs 294ns ago
[INFO] [stdout] 2025-10-01T14:16:24.373166Z TRACE timesimp: sleeping to spread out requests delay=1.519975291s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:24.478000Z TRACE new{response=Response { client: 2025-10-01T14:16:24.474407705Z, server: 2025-10-01T14:16:24.476700695Z } current=2025-10-01T14:16:24.477839355Z}: timesimp::delta: response processing internals latency=1ms 715µs 825ns local_at_midpoint=2025-10-01T14:16:24.47612353Z delta=577µs 165ns
[INFO] [stdout] 2025-10-01T14:16:24.478083Z TRACE timesimp: obtained raw offset from server latency=1.715825ms delta=577µs 165ns
[INFO] [stdout] 2025-10-01T14:16:24.478101Z TRACE timesimp: sleeping to spread out requests delay=1.001244263s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.104274Z TRACE new{response=Response { client: 2025-10-01T14:16:25.081727755Z, server: 2025-10-01T14:16:20.092917843Z } current=2025-10-01T14:16:25.104110202Z}: timesimp::delta: response processing internals latency=11ms 191µs 223ns local_at_midpoint=2025-10-01T14:16:25.092918978Z delta=5s 1µs 135ns ago
[INFO] [stdout] 2025-10-01T14:16:25.104357Z TRACE timesimp: obtained raw offset from server latency=11.191223ms delta=5s 1µs 135ns ago
[INFO] [stdout] 2025-10-01T14:16:25.104380Z TRACE timesimp: sleeping to spread out requests delay=1.335743337s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.174442Z TRACE new{response=Response { client: 2025-10-01T14:16:25.151870607Z, server: 2025-10-01T14:16:25.163067175Z } current=2025-10-01T14:16:25.174266834Z}: timesimp::delta: response processing internals latency=11ms 198µs 113ns local_at_midpoint=2025-10-01T14:16:25.16306872Z delta=1µs 545ns ago
[INFO] [stdout] 2025-10-01T14:16:25.174668Z TRACE timesimp: obtained raw offset from server latency=11.198113ms delta=1µs 545ns ago
[INFO] [stdout] 2025-10-01T14:16:25.174739Z TRACE timesimp: sleeping to spread out requests delay=536.073001ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.404051Z TRACE new{response=Response { client: 2025-10-01T14:16:25.388833489Z, server: 2025-10-01T14:16:30.397717438Z } current=2025-10-01T14:16:25.403899708Z}: timesimp::delta: response processing internals latency=7ms 533µs 109ns local_at_midpoint=2025-10-01T14:16:25.396366598Z delta=5s 1ms 350µs 840ns
[INFO] [stdout] 2025-10-01T14:16:25.404128Z TRACE timesimp: obtained raw offset from server latency=7.533109ms delta=5s 1ms 350µs 840ns
[INFO] [stdout] 2025-10-01T14:16:25.404144Z TRACE timesimp: sleeping to spread out requests delay=1.387622108s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.437115Z TRACE new{response=Response { client: 2025-10-01T14:16:25.415883686Z, server: 2025-10-01T14:16:30.426732175Z } current=2025-10-01T14:16:25.436934874Z}: timesimp::delta: response processing internals latency=10ms 525µs 594ns local_at_midpoint=2025-10-01T14:16:25.42640928Z delta=5s 322µs 895ns
[INFO] [stdout] 2025-10-01T14:16:25.437211Z TRACE timesimp: obtained raw offset from server latency=10.525594ms delta=5s 322µs 895ns
[INFO] [stdout] 2025-10-01T14:16:25.437232Z TRACE timesimp: sleeping to spread out requests delay=1.14419385s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.482330Z TRACE new{response=Response { client: 2025-10-01T14:16:25.479881749Z, server: 2025-10-01T14:16:25.481030569Z } current=2025-10-01T14:16:25.482165219Z}: timesimp::delta: response processing internals latency=1ms 141µs 735ns local_at_midpoint=2025-10-01T14:16:25.481023484Z delta=7µs 85ns
[INFO] [stdout] 2025-10-01T14:16:25.482425Z TRACE timesimp: obtained raw offset from server latency=1.141735ms delta=7µs 85ns
[INFO] [stdout] 2025-10-01T14:16:25.482445Z TRACE timesimp: sleeping to spread out requests delay=386.07256ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.665062Z TRACE new{response=Response { client: 2025-10-01T14:16:24.17049275Z, server: 2025-10-01T14:16:24.917869334Z } current=2025-10-01T14:16:25.664854148Z}: timesimp::delta: response processing internals latency=747ms 180µs 699ns local_at_midpoint=2025-10-01T14:16:24.917673449Z delta=195µs 885ns
[INFO] [stdout] 2025-10-01T14:16:25.665146Z TRACE timesimp: obtained raw offset from server latency=747.180699ms delta=195µs 885ns
[INFO] [stdout] 2025-10-01T14:16:25.665164Z DEBUG timesimp: no offset stored, storing initial delta offset=195µs 885ns
[INFO] [stdout] 2025-10-01T14:16:25.665175Z TRACE timesimp: sleeping to spread out requests delay=1.654739135s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.734267Z TRACE new{response=Response { client: 2025-10-01T14:16:25.711674142Z, server: 2025-10-01T14:16:25.722887531Z } current=2025-10-01T14:16:25.73408506Z}: timesimp::delta: response processing internals latency=11ms 205µs 459ns local_at_midpoint=2025-10-01T14:16:25.722879601Z delta=7µs 930ns
[INFO] [stdout] 2025-10-01T14:16:25.734444Z TRACE timesimp: obtained raw offset from server latency=11.205459ms delta=7µs 930ns
[INFO] [stdout] 2025-10-01T14:16:25.734514Z TRACE timesimp: sleeping to spread out requests delay=1.418224771s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.871350Z TRACE new{response=Response { client: 2025-10-01T14:16:25.868871254Z, server: 2025-10-01T14:16:25.870032044Z } current=2025-10-01T14:16:25.871182624Z}: timesimp::delta: response processing internals latency=1ms 155µs 685ns local_at_midpoint=2025-10-01T14:16:25.870026939Z delta=5µs 105ns
[INFO] [stdout] 2025-10-01T14:16:25.871443Z TRACE timesimp: obtained raw offset from server latency=1.155685ms delta=5µs 105ns
[INFO] [stdout] 2025-10-01T14:16:25.871462Z TRACE timesimp: sleeping to spread out requests delay=157.734648ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:25.979078Z TRACE new{response=Response { client: 2025-10-01T14:16:25.953845714Z, server: 2025-10-01T14:16:30.967718242Z } current=2025-10-01T14:16:25.978909661Z}: timesimp::delta: response processing internals latency=12ms 531µs 973ns local_at_midpoint=2025-10-01T14:16:25.966377687Z delta=5s 1ms 340µs 555ns
[INFO] [stdout] 2025-10-01T14:16:25.979170Z TRACE timesimp: obtained raw offset from server latency=12.531973ms delta=5s 1ms 340µs 555ns
[INFO] [stdout] 2025-10-01T14:16:25.979191Z TRACE timesimp: sleeping to spread out requests delay=1.018849746s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.032545Z TRACE new{response=Response { client: 2025-10-01T14:16:26.029834165Z, server: 2025-10-01T14:16:26.030970785Z } current=2025-10-01T14:16:26.032378465Z}: timesimp::delta: response processing internals latency=1ms 272µs 150ns local_at_midpoint=2025-10-01T14:16:26.031106315Z delta=135µs 530ns ago
[INFO] [stdout] 2025-10-01T14:16:26.032657Z TRACE timesimp: obtained raw offset from server latency=1.27215ms delta=135µs 530ns ago
[INFO] [stdout] 2025-10-01T14:16:26.032687Z TRACE timesimp: response deltas sorted by latency deltas=[0.00015, 0.007085, 0.005105, -0.13553, 0.577165]
[INFO] [stdout] 2025-10-01T14:16:26.032705Z TRACE timesimp: statistics about response deltas median=0.005105 mean=0.090795 variance=0.0775863596875 stddev=0.2785432815335886
[INFO] [stdout] 2025-10-01T14:16:26.032724Z TRACE timesimp: eliminated outliers inliers=[0.00015, 0.007085, 0.005105, -0.13553]
[INFO] [stdout] 2025-10-01T14:16:26.032736Z DEBUG timesimp: storing calculated offset offset=30µs ago
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-10-01T14:16:26.036873Z TRACE new{response=Response { client: 2025-10-01T14:16:26.013856157Z, server: 2025-10-01T14:16:26.025150176Z } current=2025-10-01T14:16:26.036714814Z}: timesimp::delta: response processing internals latency=11ms 429µs 328ns local_at_midpoint=2025-10-01T14:16:26.025285485Z delta=135µs 309ns ago
[INFO] [stdout] 2025-10-01T14:16:26.036957Z TRACE timesimp: obtained raw offset from server latency=11.429328ms delta=135µs 309ns ago
[INFO] [stdout] 2025-10-01T14:16:26.036976Z TRACE timesimp: sleeping to spread out requests delay=1.095091626s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.085390Z TRACE new{response=Response { client: 2025-10-01T14:16:26.0729616Z, server: 2025-10-01T14:16:31.07910614Z } current=2025-10-01T14:16:26.085236019Z}: timesimp::delta: response processing internals latency=6ms 137µs 209ns local_at_midpoint=2025-10-01T14:16:26.079098809Z delta=5s 7µs 331ns
[INFO] [stdout] 2025-10-01T14:16:26.085481Z TRACE timesimp: obtained raw offset from server latency=6.137209ms delta=5s 7µs 331ns
[INFO] [stdout] 2025-10-01T14:16:26.085500Z TRACE timesimp: sleeping to spread out requests delay=22.149384ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.097385Z TRACE new{response=Response { client: 2025-10-01T14:16:25.894839801Z, server: 2025-10-01T14:16:25.996293689Z } current=2025-10-01T14:16:26.097218578Z}: timesimp::delta: response processing internals latency=101ms 189µs 388ns local_at_midpoint=2025-10-01T14:16:25.996029189Z delta=264µs 500ns
[INFO] [stdout] 2025-10-01T14:16:26.097476Z TRACE timesimp: obtained raw offset from server latency=101.189388ms delta=264µs 500ns
[INFO] [stdout] 2025-10-01T14:16:26.097495Z TRACE timesimp: sleeping to spread out requests delay=824.428153ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.126244Z TRACE new{response=Response { client: 2025-10-01T14:16:26.108795806Z, server: 2025-10-01T14:16:31.116938865Z } current=2025-10-01T14:16:26.126088304Z}: timesimp::delta: response processing internals latency=8ms 646µs 249ns local_at_midpoint=2025-10-01T14:16:26.117442055Z delta=4s 999ms 496µs 810ns
[INFO] [stdout] 2025-10-01T14:16:26.126334Z TRACE timesimp: obtained raw offset from server latency=8.646249ms delta=4s 999ms 496µs 810ns
[INFO] [stdout] 2025-10-01T14:16:26.126355Z TRACE timesimp: sleeping to spread out requests delay=610.389223ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.464443Z TRACE new{response=Response { client: 2025-10-01T14:16:26.441873108Z, server: 2025-10-01T14:16:21.453061396Z } current=2025-10-01T14:16:26.464260135Z}: timesimp::delta: response processing internals latency=11ms 193µs 513ns local_at_midpoint=2025-10-01T14:16:26.453066621Z delta=5s 5µs 225ns ago
[INFO] [stdout] 2025-10-01T14:16:26.464536Z TRACE timesimp: obtained raw offset from server latency=11.193513ms delta=5s 5µs 225ns ago
[INFO] [stdout] 2025-10-01T14:16:26.464555Z TRACE timesimp: sleeping to spread out requests delay=869.738161ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.604037Z TRACE new{response=Response { client: 2025-10-01T14:16:26.582885181Z, server: 2025-10-01T14:16:31.59309115Z } current=2025-10-01T14:16:26.603865889Z}: timesimp::delta: response processing internals latency=10ms 490µs 354ns local_at_midpoint=2025-10-01T14:16:26.593375535Z delta=4s 999ms 715µs 615ns
[INFO] [stdout] 2025-10-01T14:16:26.604133Z TRACE timesimp: obtained raw offset from server latency=10.490354ms delta=4s 999ms 715µs 615ns
[INFO] [stdout] 2025-10-01T14:16:26.604156Z TRACE timesimp: sleeping to spread out requests delay=1.266516086s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.760447Z TRACE new{response=Response { client: 2025-10-01T14:16:26.737882103Z, server: 2025-10-01T14:16:31.749075402Z } current=2025-10-01T14:16:26.760272261Z}: timesimp::delta: response processing internals latency=11ms 195µs 79ns local_at_midpoint=2025-10-01T14:16:26.749077182Z delta=4s 999ms 998µs 220ns
[INFO] [stdout] 2025-10-01T14:16:26.760543Z TRACE timesimp: obtained raw offset from server latency=11.195079ms delta=4s 999ms 998µs 220ns
[INFO] [stdout] 2025-10-01T14:16:26.760566Z TRACE timesimp: sleeping to spread out requests delay=684.597967ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:26.801435Z TRACE new{response=Response { client: 2025-10-01T14:16:26.792867627Z, server: 2025-10-01T14:16:31.797059546Z } current=2025-10-01T14:16:26.801267156Z}: timesimp::delta: response processing internals latency=4ms 199µs 764ns local_at_midpoint=2025-10-01T14:16:26.797067391Z delta=4s 999ms 992µs 155ns
[INFO] [stdout] 2025-10-01T14:16:26.801526Z TRACE timesimp: obtained raw offset from server latency=4.199764ms delta=4s 999ms 992µs 155ns
[INFO] [stdout] 2025-10-01T14:16:26.801548Z TRACE timesimp: sleeping to spread out requests delay=840.848531ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.028027Z TRACE new{response=Response { client: 2025-10-01T14:16:27.001722443Z, server: 2025-10-01T14:16:32.016721741Z } current=2025-10-01T14:16:27.02787237Z}: timesimp::delta: response processing internals latency=13ms 74µs 963ns local_at_midpoint=2025-10-01T14:16:27.014797406Z delta=5s 1ms 924µs 335ns
[INFO] [stdout] 2025-10-01T14:16:27.028114Z TRACE timesimp: obtained raw offset from server latency=13.074963ms delta=5s 1ms 924µs 335ns
[INFO] [stdout] 2025-10-01T14:16:27.028134Z TRACE timesimp: sleeping to spread out requests delay=207.45308ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.130948Z TRACE new{response=Response { client: 2025-10-01T14:16:26.923867732Z, server: 2025-10-01T14:16:27.02671877Z } current=2025-10-01T14:16:27.130775848Z}: timesimp::delta: response processing internals latency=103ms 454µs 58ns local_at_midpoint=2025-10-01T14:16:27.02732179Z delta=603µs 20ns ago
[INFO] [stdout] 2025-10-01T14:16:27.131046Z TRACE timesimp: obtained raw offset from server latency=103.454058ms delta=603µs 20ns ago
[INFO] [stdout] 2025-10-01T14:16:27.131067Z TRACE timesimp: sleeping to spread out requests delay=268.665296ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.165845Z TRACE new{response=Response { client: 2025-10-01T14:16:27.132816438Z, server: 2025-10-01T14:16:27.147726266Z } current=2025-10-01T14:16:27.165683034Z}: timesimp::delta: response processing internals latency=16ms 433µs 298ns local_at_midpoint=2025-10-01T14:16:27.149249736Z delta=1ms 523µs 470ns ago
[INFO] [stdout] 2025-10-01T14:16:27.165936Z TRACE timesimp: obtained raw offset from server latency=16.433298ms delta=1ms 523µs 470ns ago
[INFO] [stdout] 2025-10-01T14:16:27.165956Z TRACE timesimp: sleeping to spread out requests delay=649.199551ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.175645Z TRACE new{response=Response { client: 2025-10-01T14:16:27.153858475Z, server: 2025-10-01T14:16:27.165059534Z } current=2025-10-01T14:16:27.175337533Z}: timesimp::delta: response processing internals latency=10ms 739µs 529ns local_at_midpoint=2025-10-01T14:16:27.164598004Z delta=461µs 530ns
[INFO] [stdout] 2025-10-01T14:16:27.178705Z TRACE timesimp: obtained raw offset from server latency=10.739529ms delta=461µs 530ns
[INFO] [stdout] 2025-10-01T14:16:27.178825Z TRACE timesimp: sleeping to spread out requests delay=1.181451206s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.258279Z TRACE new{response=Response { client: 2025-10-01T14:16:27.236573996Z, server: 2025-10-01T14:16:32.247914274Z } current=2025-10-01T14:16:27.258105543Z}: timesimp::delta: response processing internals latency=10ms 765µs 773ns local_at_midpoint=2025-10-01T14:16:27.247339769Z delta=5s 574µs 505ns
[INFO] [stdout] 2025-10-01T14:16:27.258376Z TRACE timesimp: obtained raw offset from server latency=10.765773ms delta=5s 574µs 505ns
[INFO] [stdout] 2025-10-01T14:16:27.258397Z TRACE timesimp: sleeping to spread out requests delay=1.100539055s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.358471Z TRACE new{response=Response { client: 2025-10-01T14:16:27.335890654Z, server: 2025-10-01T14:16:22.347085593Z } current=2025-10-01T14:16:27.358280662Z}: timesimp::delta: response processing internals latency=11ms 195µs 4ns local_at_midpoint=2025-10-01T14:16:27.347085658Z delta=5s 65ns ago
[INFO] [stdout] 2025-10-01T14:16:27.358565Z TRACE timesimp: obtained raw offset from server latency=11.195004ms delta=5s 65ns ago
[INFO] [stdout] 2025-10-01T14:16:27.358586Z TRACE timesimp: sleeping to spread out requests delay=1.298682599s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.459464Z TRACE new{response=Response { client: 2025-10-01T14:16:27.445875122Z, server: 2025-10-01T14:16:32.452112661Z } current=2025-10-01T14:16:27.45930256Z}: timesimp::delta: response processing internals latency=6ms 713µs 719ns local_at_midpoint=2025-10-01T14:16:27.452588841Z delta=4s 999ms 523µs 820ns
[INFO] [stdout] 2025-10-01T14:16:27.459550Z TRACE timesimp: obtained raw offset from server latency=6.713719ms delta=4s 999ms 523µs 820ns
[INFO] [stdout] 2025-10-01T14:16:27.459576Z TRACE timesimp: response deltas sorted by latency deltas=[5000.007331, 4999.52382, 5000.00318, 4999.49681, 4999.9982199999995]
[INFO] [stdout] 2025-10-01T14:16:27.459590Z TRACE timesimp: statistics about response deltas median=5000.00318 mean=4999.8058722000005 variance=0.0728966447991083 stddev=0.269993786593522
[INFO] [stdout] 2025-10-01T14:16:27.459610Z TRACE timesimp: eliminated outliers inliers=[5000.007331, 5000.00318, 4999.9982199999995]
[INFO] [stdout] 2025-10-01T14:16:27.459649Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-10-01T14:16:27.613271Z TRACE new{response=Response { client: 2025-10-01T14:16:27.405725916Z, server: 2025-10-01T14:16:27.511759094Z } current=2025-10-01T14:16:27.613098372Z}: timesimp::delta: response processing internals latency=103ms 686µs 228ns local_at_midpoint=2025-10-01T14:16:27.509412144Z delta=2ms 346µs 950ns
[INFO] [stdout] 2025-10-01T14:16:27.613367Z TRACE timesimp: obtained raw offset from server latency=103.686228ms delta=2ms 346µs 950ns
[INFO] [stdout] 2025-10-01T14:16:27.613391Z TRACE timesimp: sleeping to spread out requests delay=1.415633922s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.658424Z TRACE new{response=Response { client: 2025-10-01T14:16:27.643866249Z, server: 2025-10-01T14:16:32.651060668Z } current=2025-10-01T14:16:27.658252397Z}: timesimp::delta: response processing internals latency=7ms 193µs 74ns local_at_midpoint=2025-10-01T14:16:27.651059323Z delta=5s 1µs 345ns
[INFO] [stdout] 2025-10-01T14:16:27.658521Z TRACE timesimp: obtained raw offset from server latency=7.193074ms delta=5s 1µs 345ns
[INFO] [stdout] 2025-10-01T14:16:27.658541Z TRACE timesimp: sleeping to spread out requests delay=1.096639465s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.838385Z TRACE new{response=Response { client: 2025-10-01T14:16:27.815823329Z, server: 2025-10-01T14:16:27.827012247Z } current=2025-10-01T14:16:27.838209036Z}: timesimp::delta: response processing internals latency=11ms 192µs 853ns local_at_midpoint=2025-10-01T14:16:27.827016182Z delta=3µs 935ns ago
[INFO] [stdout] 2025-10-01T14:16:27.838480Z TRACE timesimp: obtained raw offset from server latency=11.192853ms delta=3µs 935ns ago
[INFO] [stdout] 2025-10-01T14:16:27.838503Z TRACE timesimp: sleeping to spread out requests delay=1.50698393s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:27.901875Z TRACE new{response=Response { client: 2025-10-01T14:16:27.876757542Z, server: 2025-10-01T14:16:32.88804706Z } current=2025-10-01T14:16:27.901716019Z}: timesimp::delta: response processing internals latency=12ms 479µs 238ns local_at_midpoint=2025-10-01T14:16:27.88923678Z delta=4s 998ms 810µs 280ns
[INFO] [stdout] 2025-10-01T14:16:27.901954Z TRACE timesimp: obtained raw offset from server latency=12.479238ms delta=4s 998ms 810µs 280ns
[INFO] [stdout] 2025-10-01T14:16:27.901970Z TRACE timesimp: sleeping to spread out requests delay=807.514086ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:28.384664Z TRACE new{response=Response { client: 2025-10-01T14:16:28.361983756Z, server: 2025-10-01T14:16:28.373181364Z } current=2025-10-01T14:16:28.384458423Z}: timesimp::delta: response processing internals latency=11ms 237µs 333ns local_at_midpoint=2025-10-01T14:16:28.373221089Z delta=39µs 725ns ago
[INFO] [stdout] 2025-10-01T14:16:28.384839Z TRACE timesimp: obtained raw offset from server latency=11.237333ms delta=39µs 725ns ago
[INFO] [stdout] 2025-10-01T14:16:28.384934Z TRACE timesimp: response deltas sorted by latency deltas=[0.46153, -0.004005, -0.001545, 0.00793, -0.039725]
[INFO] [stdout] 2025-10-01T14:16:28.385004Z TRACE timesimp: statistics about response deltas median=-0.001545 mean=0.084837 variance=0.0446706864075 stddev=0.21135440948203565
[INFO] [stdout] 2025-10-01T14:16:28.385075Z TRACE timesimp: eliminated outliers inliers=[-0.004005, -0.001545, 0.00793, -0.039725]
[INFO] [stdout] 2025-10-01T14:16:28.385132Z DEBUG timesimp: storing calculated offset offset=9µs ago
[INFO] [stdout] 2025-10-01T14:16:28.386952Z TRACE new{response=Response { client: 2025-10-01T14:16:28.362715516Z, server: 2025-10-01T14:16:33.375700184Z } current=2025-10-01T14:16:28.386845553Z}: timesimp::delta: response processing internals latency=12ms 65µs 18ns local_at_midpoint=2025-10-01T14:16:28.374780534Z delta=5s 919µs 650ns
[INFO] [stdout] 2025-10-01T14:16:28.387016Z TRACE timesimp: obtained raw offset from server latency=12.065018ms delta=5s 919µs 650ns
[INFO] [stdout] 2025-10-01T14:16:28.387036Z TRACE timesimp: response deltas sorted by latency deltas=[5000.574505, 4999.997575, 5000.91965, 5001.340555, 5001.924335]
[INFO] [stdout] 2025-10-01T14:16:28.387049Z TRACE timesimp: statistics about response deltas median=5000.91965 mean=5000.951324 variance=0.5377210333797345 stddev=0.7332946429503863
[INFO] [stdout] 2025-10-01T14:16:28.387066Z TRACE timesimp: eliminated outliers inliers=[5000.574505, 5000.91965, 5001.340555]
[INFO] [stdout] 2025-10-01T14:16:28.387076Z DEBUG timesimp: storing calculated offset offset=5s 944µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2025-10-01T14:16:28.680911Z TRACE new{response=Response { client: 2025-10-01T14:16:28.658285011Z, server: 2025-10-01T14:16:23.66949472Z } current=2025-10-01T14:16:28.680721739Z}: timesimp::delta: response processing internals latency=11ms 218µs 364ns local_at_midpoint=2025-10-01T14:16:28.669503375Z delta=5s 8µs 655ns ago
[INFO] [stdout] 2025-10-01T14:16:28.681002Z TRACE timesimp: obtained raw offset from server latency=11.218364ms delta=5s 8µs 655ns ago
[INFO] [stdout] 2025-10-01T14:16:28.681029Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.001135, -5000.005225, -5000.000065, -5000.008655, -5000.120965]
[INFO] [stdout] 2025-10-01T14:16:28.681046Z TRACE timesimp: statistics about response deltas median=-5000.000065 mean=-5000.027209 variance=0.002758596229999904 stddev=0.05252234029439191
[INFO] [stdout] 2025-10-01T14:16:28.681060Z TRACE timesimp: eliminated outliers inliers=[-5000.001135, -5000.005225, -5000.000065, -5000.008655]
[INFO] [stdout] 2025-10-01T14:16:28.681071Z DEBUG timesimp: storing calculated offset offset=5s 3µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-10-01T14:16:28.731288Z TRACE new{response=Response { client: 2025-10-01T14:16:28.710731845Z, server: 2025-10-01T14:16:33.720916504Z } current=2025-10-01T14:16:28.731109303Z}: timesimp::delta: response processing internals latency=10ms 188µs 729ns local_at_midpoint=2025-10-01T14:16:28.720920574Z delta=4s 999ms 995µs 930ns
[INFO] [stdout] 2025-10-01T14:16:28.731384Z TRACE timesimp: obtained raw offset from server latency=10.188729ms delta=4s 999ms 995µs 930ns
[INFO] [stdout] 2025-10-01T14:16:28.731414Z TRACE timesimp: response deltas sorted by latency deltas=[4999.99593, 4999.715615, 5000.322895, 5000.00158, 4998.81028]
[INFO] [stdout] 2025-10-01T14:16:28.731436Z TRACE timesimp: statistics about response deltas median=5000.322895 mean=4999.769259999999 variance=0.33359600273772977 stddev=0.5775777027705707
[INFO] [stdout] 2025-10-01T14:16:28.731451Z TRACE timesimp: eliminated outliers inliers=[4999.99593, 5000.322895, 5000.00158]
[INFO] [stdout] 2025-10-01T14:16:28.731460Z DEBUG timesimp: storing calculated offset offset=5s 106µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-10-01T14:16:28.772438Z TRACE new{response=Response { client: 2025-10-01T14:16:28.75585907Z, server: 2025-10-01T14:16:33.764046579Z } current=2025-10-01T14:16:28.772253788Z}: timesimp::delta: response processing internals latency=8ms 197µs 359ns local_at_midpoint=2025-10-01T14:16:28.764056429Z delta=4s 999ms 990µs 150ns
[INFO] [stdout] 2025-10-01T14:16:28.772537Z TRACE timesimp: obtained raw offset from server latency=8.197359ms delta=4s 999ms 990µs 150ns
[INFO] [stdout] 2025-10-01T14:16:28.772567Z TRACE timesimp: response deltas sorted by latency deltas=[4999.992155, 4999.985896, 5000.001345, 5001.35084, 4999.99015]
[INFO] [stdout] 2025-10-01T14:16:28.772584Z TRACE timesimp: statistics about response deltas median=5000.001345 mean=5000.2640771999995 variance=0.3691110415418199 stddev=0.6075450942455382
[INFO] [stdout] 2025-10-01T14:16:28.772613Z TRACE timesimp: eliminated outliers inliers=[4999.992155, 4999.985896, 5000.001345, 4999.99015]
[INFO] [stdout] 2025-10-01T14:16:28.772663Z DEBUG timesimp: storing calculated offset offset=4s 999ms 992µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-10-01T14:16:28.931031Z TRACE new{response=Response { client: 2025-10-01T14:16:27.320869086Z, server: 2025-10-01T14:16:28.125865853Z } current=2025-10-01T14:16:28.9308586Z}: timesimp::delta: response processing internals latency=804ms 994µs 757ns local_at_midpoint=2025-10-01T14:16:28.125863843Z delta=2µs 10ns
[INFO] [stdout] 2025-10-01T14:16:28.931114Z TRACE timesimp: obtained raw offset from server latency=804.994757ms delta=2µs 10ns
[INFO] [stdout] 2025-10-01T14:16:28.931133Z TRACE timesimp: sleeping to spread out requests delay=49.539565ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:29.232535Z TRACE new{response=Response { client: 2025-10-01T14:16:29.030636018Z, server: 2025-10-01T14:16:29.130991737Z } current=2025-10-01T14:16:29.232370605Z}: timesimp::delta: response processing internals latency=100ms 867µs 293ns local_at_midpoint=2025-10-01T14:16:29.131503311Z delta=511µs 574ns ago
[INFO] [stdout] 2025-10-01T14:16:29.232648Z TRACE timesimp: obtained raw offset from server latency=100.867293ms delta=511µs 574ns ago
[INFO] [stdout] 2025-10-01T14:16:29.232675Z TRACE timesimp: response deltas sorted by latency deltas=[-0.511574, 0.2645, -0.032294, -0.60302, 2.34695]
[INFO] [stdout] 2025-10-01T14:16:29.232701Z TRACE timesimp: statistics about response deltas median=-0.032294 mean=0.2929124 variance=1.4438825406108 stddev=1.201616636290793
[INFO] [stdout] 2025-10-01T14:16:29.232715Z TRACE timesimp: eliminated outliers inliers=[-0.511574, 0.2645, -0.032294, -0.60302]
[INFO] [stdout] 2025-10-01T14:16:29.232725Z DEBUG timesimp: storing calculated offset offset=220µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-10-01T14:16:29.369517Z TRACE new{response=Response { client: 2025-10-01T14:16:29.346869132Z, server: 2025-10-01T14:16:29.35816806Z } current=2025-10-01T14:16:29.369355359Z}: timesimp::delta: response processing internals latency=11ms 243µs 113ns local_at_midpoint=2025-10-01T14:16:29.358112245Z delta=55µs 815ns
[INFO] [stdout] 2025-10-01T14:16:29.369594Z TRACE timesimp: obtained raw offset from server latency=11.243113ms delta=55µs 815ns
[INFO] [stdout] 2025-10-01T14:16:29.369645Z TRACE timesimp: response deltas sorted by latency deltas=[-0.003935, 0.055815, -0.135309, 0.914265, -1.52347]
[INFO] [stdout] 2025-10-01T14:16:29.369662Z TRACE timesimp: statistics about response deltas median=-0.135309 mean=-0.1385268 variance=0.7705830708662001 stddev=0.8778286113280884
[INFO] [stdout] 2025-10-01T14:16:29.369676Z TRACE timesimp: eliminated outliers inliers=[-0.003935, 0.055815, -0.135309]
[INFO] [stdout] 2025-10-01T14:16:29.369685Z DEBUG timesimp: storing calculated offset offset=27µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-10-01T14:16:30.786027Z TRACE new{response=Response { client: 2025-10-01T14:16:28.981493374Z, server: 2025-10-01T14:16:29.88386071Z } current=2025-10-01T14:16:30.785861725Z}: timesimp::delta: response processing internals latency=902ms 184µs 175ns local_at_midpoint=2025-10-01T14:16:29.883677549Z delta=183µs 161ns
[INFO] [stdout] 2025-10-01T14:16:30.786117Z TRACE timesimp: obtained raw offset from server latency=902.184175ms delta=183µs 161ns
[INFO] [stdout] 2025-10-01T14:16:30.786137Z TRACE timesimp: sleeping to spread out requests delay=1.373737964s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:34.104997Z TRACE new{response=Response { client: 2025-10-01T14:16:32.160953166Z, server: 2025-10-01T14:16:33.131931144Z } current=2025-10-01T14:16:34.104725772Z}: timesimp::delta: response processing internals latency=971ms 886µs 303ns local_at_midpoint=2025-10-01T14:16:33.132839469Z delta=908µs 325ns ago
[INFO] [stdout] 2025-10-01T14:16:34.105094Z TRACE timesimp: obtained raw offset from server latency=971.886303ms delta=908µs 325ns ago
[INFO] [stdout] 2025-10-01T14:16:34.105115Z TRACE timesimp: sleeping to spread out requests delay=66.344158ms max_jitter=2s
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-df61f2f1a63ac7e1)
[INFO] [stdout] 2025-10-01T14:16:35.826040Z TRACE new{response=Response { client: 2025-10-01T14:16:34.172459954Z, server: 2025-10-01T14:16:34.998874388Z } current=2025-10-01T14:16:35.825869133Z}: timesimp::delta: response processing internals latency=826ms 704µs 589ns local_at_midpoint=2025-10-01T14:16:34.999164543Z delta=290µs 155ns ago
[INFO] [stdout] 2025-10-01T14:16:35.826126Z TRACE timesimp: obtained raw offset from server latency=826.704589ms delta=290µs 155ns ago
[INFO] [stdout] 2025-10-01T14:16:35.826153Z TRACE timesimp: response deltas sorted by latency deltas=[0.195885, 0.00201, -0.290155, 0.183161, -0.908325]
[INFO] [stdout] 2025-10-01T14:16:35.826169Z TRACE timesimp: statistics about response deltas median=-0.290155 mean=-0.1634848 variance=0.21188268893520001 stddev=0.4603071680250048
[INFO] [stdout] 2025-10-01T14:16:35.826183Z TRACE timesimp: eliminated outliers inliers=[0.00201, -0.290155]
[INFO] [stdout] 2025-10-01T14:16:35.826193Z DEBUG timesimp: storing calculated offset offset=144µs ago
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 11.66s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-10-01T14:16:35.834534Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:35.834539Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-10-01T14:16:35.834670Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.834678Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.836083Z TRACE new{response=Response { client: 2025-10-01T14:16:35.835903761Z, server: 2025-10-01T14:16:35.835918092Z } current=2025-10-01T14:16:35.835921472Z}: timesimp::delta: response processing internals latency=8µs 855ns local_at_midpoint=2025-10-01T14:16:35.835912616Z delta=5µs 476ns
[INFO] [stdout] 2025-10-01T14:16:35.836083Z TRACE new{response=Response { client: 2025-10-01T14:16:35.835921601Z, server: 2025-10-01T14:16:40.835925281Z } current=2025-10-01T14:16:35.835927152Z}: timesimp::delta: response processing internals latency=2µs 775ns local_at_midpoint=2025-10-01T14:16:35.835924376Z delta=5s 905ns
[INFO] [stdout] 2025-10-01T14:16:35.836161Z TRACE timesimp: obtained raw offset from server latency=8.855µs delta=5µs 476ns
[INFO] [stdout] 2025-10-01T14:16:35.836170Z TRACE timesimp: obtained raw offset from server latency=2.775µs delta=5s 905ns
[INFO] [stdout] 2025-10-01T14:16:35.836181Z TRACE timesimp: sleeping to spread out requests delay=1.367866227s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.836187Z TRACE timesimp: sleeping to spread out requests delay=433.051535ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.847899Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-10-01T14:16:35.847964Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.851961Z TRACE new{response=Response { client: 2025-10-01T14:16:35.85176867Z, server: 2025-10-01T14:16:30.851777639Z } current=2025-10-01T14:16:35.851781019Z}: timesimp::delta: response processing internals latency=6µs 174ns local_at_midpoint=2025-10-01T14:16:35.851774844Z delta=4s 999ms 997µs 205ns ago
[INFO] [stdout] 2025-10-01T14:16:35.852041Z TRACE timesimp: obtained raw offset from server latency=6.174µs delta=4s 999ms 997µs 205ns ago
[INFO] [stdout] 2025-10-01T14:16:35.852060Z TRACE timesimp: sleeping to spread out requests delay=1.137523964s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.865940Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-10-01T14:16:35.866007Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.869933Z TRACE new{response=Response { client: 2025-10-01T14:16:35.869760688Z, server: 2025-10-01T14:16:35.869770137Z } current=2025-10-01T14:16:35.869773128Z}: timesimp::delta: response processing internals latency=6µs 220ns local_at_midpoint=2025-10-01T14:16:35.869766908Z delta=3µs 229ns
[INFO] [stdout] 2025-10-01T14:16:35.870005Z TRACE timesimp: obtained raw offset from server latency=6.22µs delta=3µs 229ns
[INFO] [stdout] 2025-10-01T14:16:35.870030Z DEBUG timesimp: no offset stored, storing initial delta offset=3µs 229ns
[INFO] [stdout] 2025-10-01T14:16:35.870041Z TRACE timesimp: sleeping to spread out requests delay=66.030658ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:35.937567Z TRACE new{response=Response { client: 2025-10-01T14:16:35.93739683Z, server: 2025-10-01T14:16:35.937409579Z } current=2025-10-01T14:16:35.9374102Z}: timesimp::delta: response processing internals latency=6µs 685ns local_at_midpoint=2025-10-01T14:16:35.937403515Z delta=6µs 64ns
[INFO] [stdout] 2025-10-01T14:16:35.937678Z TRACE timesimp: obtained raw offset from server latency=6.685µs delta=6µs 64ns
[INFO] [stdout] 2025-10-01T14:16:35.937699Z TRACE timesimp: sleeping to spread out requests delay=1.352931124s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:36.275886Z TRACE new{response=Response { client: 2025-10-01T14:16:36.275720201Z, server: 2025-10-01T14:16:41.275730061Z } current=2025-10-01T14:16:36.27573403Z}: timesimp::delta: response processing internals latency=6µs 914ns local_at_midpoint=2025-10-01T14:16:36.275727115Z delta=5s 2µs 946ns
[INFO] [stdout] 2025-10-01T14:16:36.275965Z TRACE timesimp: obtained raw offset from server latency=6.914µs delta=5s 2µs 946ns
[INFO] [stdout] 2025-10-01T14:16:36.275982Z TRACE timesimp: sleeping to spread out requests delay=1.612934726s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:36.991050Z TRACE new{response=Response { client: 2025-10-01T14:16:36.990870108Z, server: 2025-10-01T14:16:31.990879568Z } current=2025-10-01T14:16:36.990883698Z}: timesimp::delta: response processing internals latency=6µs 795ns local_at_midpoint=2025-10-01T14:16:36.990876903Z delta=4s 999ms 997µs 335ns ago
[INFO] [stdout] 2025-10-01T14:16:36.991139Z TRACE timesimp: obtained raw offset from server latency=6.795µs delta=4s 999ms 997µs 335ns ago
[INFO] [stdout] 2025-10-01T14:16:36.991159Z TRACE timesimp: sleeping to spread out requests delay=147.049559ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:37.143920Z TRACE new{response=Response { client: 2025-10-01T14:16:37.14373305Z, server: 2025-10-01T14:16:32.143744Z } current=2025-10-01T14:16:37.14374763Z}: timesimp::delta: response processing internals latency=7µs 290ns local_at_midpoint=2025-10-01T14:16:37.14374034Z delta=4s 999ms 996µs 340ns ago
[INFO] [stdout] 2025-10-01T14:16:37.144005Z TRACE timesimp: obtained raw offset from server latency=7.29µs delta=4s 999ms 996µs 340ns ago
[INFO] [stdout] 2025-10-01T14:16:37.144024Z TRACE timesimp: sleeping to spread out requests delay=1.374409958s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:37.205071Z TRACE new{response=Response { client: 2025-10-01T14:16:37.204880693Z, server: 2025-10-01T14:16:37.204891293Z } current=2025-10-01T14:16:37.204895323Z}: timesimp::delta: response processing internals latency=7µs 315ns local_at_midpoint=2025-10-01T14:16:37.204888008Z delta=3µs 285ns
[INFO] [stdout] 2025-10-01T14:16:37.205163Z TRACE timesimp: obtained raw offset from server latency=7.315µs delta=3µs 285ns
[INFO] [stdout] 2025-10-01T14:16:37.205182Z TRACE timesimp: sleeping to spread out requests delay=83.940125ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:37.290903Z TRACE new{response=Response { client: 2025-10-01T14:16:37.290722753Z, server: 2025-10-01T14:16:37.290732753Z } current=2025-10-01T14:16:37.290736633Z}: timesimp::delta: response processing internals latency=6µs 940ns local_at_midpoint=2025-10-01T14:16:37.290729693Z delta=3µs 60ns
[INFO] [stdout] 2025-10-01T14:16:37.290986Z TRACE timesimp: obtained raw offset from server latency=6.94µs delta=3µs 60ns
[INFO] [stdout] 2025-10-01T14:16:37.291005Z TRACE timesimp: sleeping to spread out requests delay=736.121276ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:37.292010Z TRACE new{response=Response { client: 2025-10-01T14:16:37.291839503Z, server: 2025-10-01T14:16:37.291852472Z } current=2025-10-01T14:16:37.291852693Z}: timesimp::delta: response processing internals latency=6µs 595ns local_at_midpoint=2025-10-01T14:16:37.291846098Z delta=6µs 374ns
[INFO] [stdout] 2025-10-01T14:16:37.292096Z TRACE timesimp: obtained raw offset from server latency=6.595µs delta=6µs 374ns
[INFO] [stdout] 2025-10-01T14:16:37.292112Z TRACE timesimp: sleeping to spread out requests delay=384.506498ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:37.677885Z TRACE new{response=Response { client: 2025-10-01T14:16:37.677722828Z, server: 2025-10-01T14:16:37.677735227Z } current=2025-10-01T14:16:37.677735538Z}: timesimp::delta: response processing internals latency=6µs 355ns local_at_midpoint=2025-10-01T14:16:37.677729183Z delta=6µs 44ns
[INFO] [stdout] 2025-10-01T14:16:37.677962Z TRACE timesimp: obtained raw offset from server latency=6.355µs delta=6µs 44ns
[INFO] [stdout] 2025-10-01T14:16:37.677978Z TRACE timesimp: sleeping to spread out requests delay=381.489669ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:37.890034Z TRACE new{response=Response { client: 2025-10-01T14:16:37.889858274Z, server: 2025-10-01T14:16:42.889867944Z } current=2025-10-01T14:16:37.889871824Z}: timesimp::delta: response processing internals latency=6µs 775ns local_at_midpoint=2025-10-01T14:16:37.889865049Z delta=5s 2µs 895ns
[INFO] [stdout] 2025-10-01T14:16:37.890119Z TRACE timesimp: obtained raw offset from server latency=6.775µs delta=5s 2µs 895ns
[INFO] [stdout] 2025-10-01T14:16:37.890140Z TRACE timesimp: sleeping to spread out requests delay=1.399069124s max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:38.029905Z TRACE new{response=Response { client: 2025-10-01T14:16:38.029728138Z, server: 2025-10-01T14:16:38.029738987Z } current=2025-10-01T14:16:38.029742898Z}: timesimp::delta: response processing internals latency=7µs 380ns local_at_midpoint=2025-10-01T14:16:38.029735518Z delta=3µs 469ns
[INFO] [stdout] 2025-10-01T14:16:38.029982Z TRACE timesimp: obtained raw offset from server latency=7.38µs delta=3µs 469ns
[INFO] [stdout] 2025-10-01T14:16:38.029998Z TRACE timesimp: sleeping to spread out requests delay=263.298697ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:38.060529Z TRACE new{response=Response { client: 2025-10-01T14:16:38.060329104Z, server: 2025-10-01T14:16:38.060343683Z } current=2025-10-01T14:16:38.060345044Z}: timesimp::delta: response processing internals latency=7µs 970ns local_at_midpoint=2025-10-01T14:16:38.060337074Z delta=6µs 609ns
[INFO] [stdout] 2025-10-01T14:16:38.060660Z TRACE timesimp: obtained raw offset from server latency=7.97µs delta=6µs 609ns
[INFO] [stdout] 2025-10-01T14:16:38.060697Z TRACE timesimp: response deltas sorted by latency deltas=[0.003229, 0.006044, 0.006374, 0.006064, 0.006609]
[INFO] [stdout] 2025-10-01T14:16:38.060715Z TRACE timesimp: statistics about response deltas median=0.006374 mean=0.005664000000000001 variance=1.9076875e-6 stddev=0.001381190609582906
[INFO] [stdout] 2025-10-01T14:16:38.060731Z TRACE timesimp: eliminated outliers inliers=[0.006044, 0.006374, 0.006064, 0.006609]
[INFO] [stdout] 2025-10-01T14:16:38.060741Z DEBUG timesimp: storing calculated offset offset=6µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2025-10-01T14:16:38.294740Z TRACE new{response=Response { client: 2025-10-01T14:16:38.294539127Z, server: 2025-10-01T14:16:38.294548837Z } current=2025-10-01T14:16:38.294553057Z}: timesimp::delta: response processing internals latency=6µs 965ns local_at_midpoint=2025-10-01T14:16:38.294546092Z delta=2µs 745ns
[INFO] [stdout] 2025-10-01T14:16:38.294828Z TRACE timesimp: obtained raw offset from server latency=6.965µs delta=2µs 745ns
[INFO] [stdout] 2025-10-01T14:16:38.294851Z TRACE timesimp: response deltas sorted by latency deltas=[0.00306, 0.002745, 0.003285, 0.003469, 0.005476]
[INFO] [stdout] 2025-10-01T14:16:38.294866Z TRACE timesimp: statistics about response deltas median=0.003285 mean=0.003607 variance=1.1645355e-6 stddev=0.0010791364603237165
[INFO] [stdout] 2025-10-01T14:16:38.294891Z TRACE timesimp: eliminated outliers inliers=[0.00306, 0.002745, 0.003285, 0.003469]
[INFO] [stdout] 2025-10-01T14:16:38.294901Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2025-10-01T14:16:38.520107Z TRACE new{response=Response { client: 2025-10-01T14:16:38.519928731Z, server: 2025-10-01T14:16:33.519938181Z } current=2025-10-01T14:16:38.519941941Z}: timesimp::delta: response processing internals latency=6µs 605ns local_at_midpoint=2025-10-01T14:16:38.519935336Z delta=4s 999ms 997µs 155ns ago
[INFO] [stdout] 2025-10-01T14:16:38.520197Z TRACE timesimp: obtained raw offset from server latency=6.605µs delta=4s 999ms 997µs 155ns ago
[INFO] [stdout] 2025-10-01T14:16:38.520216Z TRACE timesimp: sleeping to spread out requests delay=28.038368ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:38.549773Z TRACE new{response=Response { client: 2025-10-01T14:16:38.549562678Z, server: 2025-10-01T14:16:33.549572527Z } current=2025-10-01T14:16:38.549576098Z}: timesimp::delta: response processing internals latency=6µs 710ns local_at_midpoint=2025-10-01T14:16:38.549569388Z delta=4s 999ms 996µs 861ns ago
[INFO] [stdout] 2025-10-01T14:16:38.549864Z TRACE timesimp: obtained raw offset from server latency=6.71µs delta=4s 999ms 996µs 861ns ago
[INFO] [stdout] 2025-10-01T14:16:38.549890Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.997205, -4999.997155, -4999.996861, -4999.997335, -4999.99634]
[INFO] [stdout] 2025-10-01T14:16:38.549905Z TRACE timesimp: statistics about response deltas median=-4999.996861 mean=-4999.9969792 variance=1.5775820008883622e-7 stddev=0.00039718786498184485
[INFO] [stdout] 2025-10-01T14:16:38.549920Z TRACE timesimp: eliminated outliers inliers=[-4999.997205, -4999.997155, -4999.996861]
[INFO] [stdout] 2025-10-01T14:16:38.549929Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2025-10-01T14:16:39.290041Z TRACE new{response=Response { client: 2025-10-01T14:16:39.289871892Z, server: 2025-10-01T14:16:44.289881072Z } current=2025-10-01T14:16:39.289885022Z}: timesimp::delta: response processing internals latency=6µs 565ns local_at_midpoint=2025-10-01T14:16:39.289878457Z delta=5s 2µs 615ns
[INFO] [stdout] 2025-10-01T14:16:39.290122Z TRACE timesimp: obtained raw offset from server latency=6.565µs delta=5s 2µs 615ns
[INFO] [stdout] 2025-10-01T14:16:39.290139Z TRACE timesimp: sleeping to spread out requests delay=184.025635ms max_jitter=2s
[INFO] [stdout] 2025-10-01T14:16:39.475203Z TRACE new{response=Response { client: 2025-10-01T14:16:39.4750275Z, server: 2025-10-01T14:16:44.47503784Z } current=2025-10-01T14:16:39.47504124Z}: timesimp::delta: response processing internals latency=6µs 870ns local_at_midpoint=2025-10-01T14:16:39.47503437Z delta=5s 3µs 470ns
[INFO] [stdout] 2025-10-01T14:16:39.475300Z TRACE timesimp: obtained raw offset from server latency=6.87µs delta=5s 3µs 470ns
[INFO] [stdout] 2025-10-01T14:16:39.475327Z TRACE timesimp: response deltas sorted by latency deltas=[5000.000905, 5000.002615, 5000.002895, 5000.00347, 5000.002946]
[INFO] [stdout] 2025-10-01T14:16:39.475343Z TRACE timesimp: statistics about response deltas median=5000.002895 mean=5000.0025662 variance=9.57794699819055e-7 stddev=0.0009786698625272236
[INFO] [stdout] 2025-10-01T14:16:39.475370Z TRACE timesimp: eliminated outliers inliers=[5000.002615, 5000.002895, 5000.00347, 5000.002946]
[INFO] [stdout] 2025-10-01T14:16:39.475382Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.65s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "0aa948e3c264f8a52ea536d1591f4b88e8aa5213e28f8aa498a6ac9573302ce7", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "0aa948e3c264f8a52ea536d1591f4b88e8aa5213e28f8aa498a6ac9573302ce7", kill_on_drop: false }`
[INFO] [stdout] 0aa948e3c264f8a52ea536d1591f4b88e8aa5213e28f8aa498a6ac9573302ce7