[INFO] fetching crate timesimp 1.0.0... [INFO] testing timesimp-1.0.0 against master#733b47ea4b1b86216f14ef56e49440c33933f230+rustflags=-Copt-level=3 for pr-138759-retry [INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-7-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-7-tc2/source/Cargo.toml [INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain 733b47ea4b1b86216f14ef56e49440c33933f230 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+733b47ea4b1b86216f14ef56e49440c33933f230" "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" "+733b47ea4b1b86216f14ef56e49440c33933f230" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+733b47ea4b1b86216f14ef56e49440c33933f230" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 349a162bfcb0bee790cb25b3e2cc257dbc19cf113a2fcce78126b37007bbc62c [INFO] running `Command { std: "docker" "start" "-a" "349a162bfcb0bee790cb25b3e2cc257dbc19cf113a2fcce78126b37007bbc62c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "349a162bfcb0bee790cb25b3e2cc257dbc19cf113a2fcce78126b37007bbc62c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "349a162bfcb0bee790cb25b3e2cc257dbc19cf113a2fcce78126b37007bbc62c", kill_on_drop: false }` [INFO] [stdout] 349a162bfcb0bee790cb25b3e2cc257dbc19cf113a2fcce78126b37007bbc62c [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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 -Copt-level=3" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+733b47ea4b1b86216f14ef56e49440c33933f230" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 82dc1b7301f132471a8d0d977b52370f94c4168bbbef79de9d7dd0c162a9160a [INFO] running `Command { std: "docker" "start" "-a" "82dc1b7301f132471a8d0d977b52370f94c4168bbbef79de9d7dd0c162a9160a", kill_on_drop: false }` [INFO] [stderr] Compiling proc-macro2 v1.0.94 [INFO] [stderr] Compiling libc v0.2.171 [INFO] [stderr] Compiling zerocopy v0.8.24 [INFO] [stderr] Compiling tracing-core v0.1.33 [INFO] [stderr] Compiling jiff v0.2.10 [INFO] [stderr] Compiling quote v1.0.40 [INFO] [stderr] Compiling syn v2.0.100 [INFO] [stderr] Compiling getrandom v0.3.2 [INFO] [stderr] Compiling rand_core v0.9.3 [INFO] [stderr] Compiling ppv-lite86 v0.2.21 [INFO] [stderr] Compiling rand_chacha v0.9.0 [INFO] [stderr] Compiling rand v0.9.1 [INFO] [stderr] Compiling thiserror-impl v2.0.12 [INFO] [stderr] Compiling tracing-attributes v0.1.28 [INFO] [stderr] Compiling thiserror v2.0.12 [INFO] [stderr] Compiling tracing v0.1.41 [INFO] [stderr] Compiling timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 38.60s [INFO] running `Command { std: "docker" "inspect" "82dc1b7301f132471a8d0d977b52370f94c4168bbbef79de9d7dd0c162a9160a", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "82dc1b7301f132471a8d0d977b52370f94c4168bbbef79de9d7dd0c162a9160a", kill_on_drop: false }` [INFO] [stdout] 82dc1b7301f132471a8d0d977b52370f94c4168bbbef79de9d7dd0c162a9160a [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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 -Copt-level=3" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+733b47ea4b1b86216f14ef56e49440c33933f230" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 664b8babbe34d6e0d112b94d8da3737948f31c9f8abd21a7605467da60af88a2 [INFO] running `Command { std: "docker" "start" "-a" "664b8babbe34d6e0d112b94d8da3737948f31c9f8abd21a7605467da60af88a2", kill_on_drop: false }` [INFO] [stderr] Compiling libc v0.2.171 [INFO] [stderr] Compiling smallvec v1.14.0 [INFO] [stderr] Compiling openssl-sys v0.9.107 [INFO] [stderr] Compiling openssl v0.10.72 [INFO] [stderr] Compiling futures-task v0.3.31 [INFO] [stderr] Compiling syn v2.0.100 [INFO] [stderr] Compiling hashbrown v0.15.2 [INFO] [stderr] Compiling bitflags v2.9.0 [INFO] [stderr] Compiling futures-channel v0.3.31 [INFO] [stderr] Compiling serde v1.0.219 [INFO] [stderr] Compiling overload v0.1.1 [INFO] [stderr] Compiling rustls-pki-types v1.11.0 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling encoding_rs v0.8.35 [INFO] [stderr] Compiling mime v0.3.17 [INFO] [stderr] Compiling nu-ansi-term v0.46.0 [INFO] [stderr] Compiling futures-util v0.3.31 [INFO] [stderr] Compiling rustls-pemfile v2.2.0 [INFO] [stderr] Compiling tracing-subscriber v0.3.19 [INFO] [stderr] Compiling indexmap v2.9.0 [INFO] [stderr] Compiling native-tls v0.2.14 [INFO] [stderr] Compiling parking_lot_core v0.9.10 [INFO] [stderr] Compiling socket2 v0.5.9 [INFO] [stderr] Compiling signal-hook-registry v1.4.5 [INFO] [stderr] Compiling mio v1.0.3 [INFO] [stderr] Compiling getrandom v0.3.2 [INFO] [stderr] Compiling parking_lot v0.12.3 [INFO] [stderr] Compiling rand_core v0.9.3 [INFO] [stderr] Compiling rand_chacha v0.9.0 [INFO] [stderr] Compiling rand v0.9.1 [INFO] [stderr] Compiling serde_urlencoded v0.7.1 [INFO] [stderr] Compiling synstructure v0.13.1 [INFO] [stderr] Compiling zerofrom-derive v0.1.6 [INFO] [stderr] Compiling yoke-derive v0.7.5 [INFO] [stderr] Compiling zerovec-derive v0.10.3 [INFO] [stderr] Compiling displaydoc v0.2.5 [INFO] [stderr] Compiling tokio-macros v2.5.0 [INFO] [stderr] Compiling icu_provider_macros v1.5.0 [INFO] [stderr] Compiling tracing-attributes v0.1.28 [INFO] [stderr] Compiling openssl-macros v0.1.1 [INFO] [stderr] Compiling thiserror-impl v2.0.12 [INFO] [stderr] Compiling tokio v1.44.2 [INFO] [stderr] Compiling thiserror v2.0.12 [INFO] [stderr] Compiling zerofrom v0.1.6 [INFO] [stderr] Compiling yoke v0.7.5 [INFO] [stderr] Compiling zerovec v0.10.4 [INFO] [stderr] Compiling tinystr v0.7.6 [INFO] [stderr] Compiling icu_collections v1.5.0 [INFO] [stderr] Compiling icu_locid v1.5.0 [INFO] [stderr] Compiling icu_provider v1.5.0 [INFO] [stderr] Compiling icu_locid_transform v1.5.0 [INFO] [stderr] Compiling tokio-util v0.7.15 [INFO] [stderr] Compiling tokio-native-tls v0.3.1 [INFO] [stderr] Compiling tower v0.5.2 [INFO] [stderr] Compiling tracing v0.1.41 [INFO] [stderr] Compiling icu_properties v1.5.1 [INFO] [stderr] Compiling h2 v0.4.9 [INFO] [stderr] Compiling timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Compiling icu_normalizer v1.5.0 [INFO] [stderr] Compiling idna_adapter v1.2.0 [INFO] [stderr] Compiling idna v1.0.3 [INFO] [stderr] Compiling url v2.5.4 [INFO] [stderr] Compiling hyper v1.6.0 [INFO] [stderr] Compiling hyper-util v0.1.11 [INFO] [stderr] Compiling hyper-tls v0.6.0 [INFO] [stderr] Compiling reqwest v0.12.15 [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 08s [INFO] running `Command { std: "docker" "inspect" "664b8babbe34d6e0d112b94d8da3737948f31c9f8abd21a7605467da60af88a2", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "664b8babbe34d6e0d112b94d8da3737948f31c9f8abd21a7605467da60af88a2", kill_on_drop: false }` [INFO] [stdout] 664b8babbe34d6e0d112b94d8da3737948f31c9f8abd21a7605467da60af88a2 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-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 -Copt-level=3" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+733b47ea4b1b86216f14ef56e49440c33933f230" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 7d2cf679efd4e8d43878302d0ffa8fc23a9036e416e05ec5fb61d08d018fadd5 [INFO] running `Command { std: "docker" "start" "-a" "7d2cf679efd4e8d43878302d0ffa8fc23a9036e416e05ec5fb61d08d018fadd5", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.23s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-5f38e1294478f341) [INFO] [stdout] [INFO] [stdout] running 5 tests [INFO] [stdout] test delta::tests::client_ahead_of_server ... ok [INFO] [stdout] test delta::tests::client_equal_server ... ok [INFO] [stdout] test delta::tests::clock_went_backwards ... ok [INFO] [stdout] test delta::tests::client_behind_server ... ok [INFO] [stdout] test delta::tests::with_sleep ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s [INFO] [stdout] [INFO] [stderr] Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-cf188712425e7209) [INFO] [stdout] [INFO] [stdout] running 10 tests [INFO] [stdout] 2025-10-16T10:48:30.267564Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-10-16T10:48:30.267593Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.267938Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.267990Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.268007Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.268025Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.268232Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-10-16T10:48:30.268258Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.268237Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.268312Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.268457Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.268518Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.268671Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.268724Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.268828Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.268846Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.268874Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.268884Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.269363Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:30.269570Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.272872Z TRACE new{response=Response { client: 2025-10-16T10:48:30.27067577Z, server: 2025-10-16T10:48:30.27176076Z } current=2025-10-16T10:48:30.2728441Z}: timesimp::delta: response processing internals latency=1ms 84µs 165ns local_at_midpoint=2025-10-16T10:48:30.271759935Z delta=825ns [INFO] [stdout] 2025-10-16T10:48:30.272944Z TRACE timesimp: obtained raw offset from server latency=1.084165ms delta=825ns [INFO] [stdout] 2025-10-16T10:48:30.272974Z DEBUG timesimp: no offset stored, storing initial delta offset=825ns [INFO] [stdout] 2025-10-16T10:48:30.272995Z TRACE timesimp: sleeping to spread out requests delay=553.533874ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.286678Z TRACE new{response=Response { client: 2025-10-16T10:48:30.2694292Z, server: 2025-10-16T10:48:35.27753512Z } current=2025-10-16T10:48:30.28663295Z}: timesimp::delta: response processing internals latency=8ms 601µs 875ns local_at_midpoint=2025-10-16T10:48:30.278031075Z delta=4s 999ms 504µs 45ns [INFO] [stdout] 2025-10-16T10:48:30.286712Z TRACE timesimp: obtained raw offset from server latency=8.601875ms delta=4s 999ms 504µs 45ns [INFO] [stdout] 2025-10-16T10:48:30.286723Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 504µs 45ns [INFO] [stdout] 2025-10-16T10:48:30.286727Z TRACE timesimp: sleeping to spread out requests delay=944.594175ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.289607Z TRACE new{response=Response { client: 2025-10-16T10:48:30.26939239Z, server: 2025-10-16T10:48:35.27948323Z } current=2025-10-16T10:48:30.28957143Z}: timesimp::delta: response processing internals latency=10ms 89µs 520ns local_at_midpoint=2025-10-16T10:48:30.27948191Z delta=5s 1µs 320ns [INFO] [stdout] 2025-10-16T10:48:30.289642Z TRACE timesimp: obtained raw offset from server latency=10.08952ms delta=5s 1µs 320ns [INFO] [stdout] 2025-10-16T10:48:30.289652Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 320ns [INFO] [stdout] 2025-10-16T10:48:30.289656Z TRACE timesimp: sleeping to spread out requests delay=139.290281ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.289659Z TRACE new{response=Response { client: 2025-10-16T10:48:30.2694748Z, server: 2025-10-16T10:48:35.27955606Z } current=2025-10-16T10:48:30.28964007Z}: timesimp::delta: response processing internals latency=10ms 82µs 635ns local_at_midpoint=2025-10-16T10:48:30.279557435Z delta=4s 999ms 998µs 625ns [INFO] [stdout] 2025-10-16T10:48:30.289707Z TRACE timesimp: obtained raw offset from server latency=10.082635ms delta=4s 999ms 998µs 625ns [INFO] [stdout] 2025-10-16T10:48:30.289750Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 998µs 625ns [INFO] [stdout] 2025-10-16T10:48:30.289787Z TRACE timesimp: sleeping to spread out requests delay=217.089237ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.290966Z TRACE new{response=Response { client: 2025-10-16T10:48:30.26870851Z, server: 2025-10-16T10:48:30.2798335Z } current=2025-10-16T10:48:30.2909321Z}: timesimp::delta: response processing internals latency=11ms 111µs 795ns local_at_midpoint=2025-10-16T10:48:30.279820305Z delta=13µs 195ns [INFO] [stdout] 2025-10-16T10:48:30.290997Z TRACE timesimp: obtained raw offset from server latency=11.111795ms delta=13µs 195ns [INFO] [stdout] 2025-10-16T10:48:30.291006Z TRACE timesimp: sleeping to spread out requests delay=942.402568ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.291760Z TRACE new{response=Response { client: 2025-10-16T10:48:30.26955301Z, server: 2025-10-16T10:48:30.28064362Z } current=2025-10-16T10:48:30.29173548Z}: timesimp::delta: response processing internals latency=11ms 91µs 235ns local_at_midpoint=2025-10-16T10:48:30.280644245Z delta=625ns ago [INFO] [stdout] 2025-10-16T10:48:30.291788Z TRACE timesimp: obtained raw offset from server latency=11.091235ms delta=625ns ago [INFO] [stdout] 2025-10-16T10:48:30.291796Z TRACE timesimp: sleeping to spread out requests delay=1.954756841s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.292105Z TRACE new{response=Response { client: 2025-10-16T10:48:30.26984714Z, server: 2025-10-16T10:48:35.28094093Z } current=2025-10-16T10:48:30.29207648Z}: timesimp::delta: response processing internals latency=11ms 114µs 670ns local_at_midpoint=2025-10-16T10:48:30.28096181Z delta=4s 999ms 979µs 120ns [INFO] [stdout] 2025-10-16T10:48:30.292174Z TRACE timesimp: obtained raw offset from server latency=11.11467ms delta=4s 999ms 979µs 120ns [INFO] [stdout] 2025-10-16T10:48:30.292225Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 979µs 120ns [INFO] [stdout] 2025-10-16T10:48:30.292261Z TRACE timesimp: sleeping to spread out requests delay=1.617029157s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.292172Z TRACE new{response=Response { client: 2025-10-16T10:48:30.26997523Z, server: 2025-10-16T10:48:25.28106181Z } current=2025-10-16T10:48:30.29214788Z}: timesimp::delta: response processing internals latency=11ms 86µs 325ns local_at_midpoint=2025-10-16T10:48:30.281061555Z delta=4s 999ms 999µs 745ns ago [INFO] [stdout] 2025-10-16T10:48:30.292326Z TRACE timesimp: obtained raw offset from server latency=11.086325ms delta=4s 999ms 999µs 745ns ago [INFO] [stdout] 2025-10-16T10:48:30.292332Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 999µs 745ns ago [INFO] [stdout] 2025-10-16T10:48:30.292336Z TRACE timesimp: sleeping to spread out requests delay=1.07395629s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.451210Z TRACE new{response=Response { client: 2025-10-16T10:48:30.429969828Z, server: 2025-10-16T10:48:35.441074407Z } current=2025-10-16T10:48:30.451183438Z}: timesimp::delta: response processing internals latency=10ms 606µs 805ns local_at_midpoint=2025-10-16T10:48:30.440576633Z delta=5s 497µs 774ns [INFO] [stdout] 2025-10-16T10:48:30.451250Z TRACE timesimp: obtained raw offset from server latency=10.606805ms delta=5s 497µs 774ns [INFO] [stdout] 2025-10-16T10:48:30.451260Z TRACE timesimp: sleeping to spread out requests delay=263.344945ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.472389Z TRACE new{response=Response { client: 2025-10-16T10:48:30.26993565Z, server: 2025-10-16T10:48:30.371118308Z } current=2025-10-16T10:48:30.472347717Z}: timesimp::delta: response processing internals latency=101ms 206µs 33ns local_at_midpoint=2025-10-16T10:48:30.371141683Z delta=23µs 375ns ago [INFO] [stdout] 2025-10-16T10:48:30.472425Z TRACE timesimp: obtained raw offset from server latency=101.206033ms delta=23µs 375ns ago [INFO] [stdout] 2025-10-16T10:48:30.472452Z DEBUG timesimp: no offset stored, storing initial delta offset=23µs 375ns ago [INFO] [stdout] 2025-10-16T10:48:30.472456Z TRACE timesimp: sleeping to spread out requests delay=1.376480567s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.518366Z TRACE new{response=Response { client: 2025-10-16T10:48:30.507142677Z, server: 2025-10-16T10:48:35.512242326Z } current=2025-10-16T10:48:30.518340917Z}: timesimp::delta: response processing internals latency=5ms 599µs 120ns local_at_midpoint=2025-10-16T10:48:30.512741797Z delta=4s 999ms 500µs 529ns [INFO] [stdout] 2025-10-16T10:48:30.518404Z TRACE timesimp: obtained raw offset from server latency=5.59912ms delta=4s 999ms 500µs 529ns [INFO] [stdout] 2025-10-16T10:48:30.518415Z TRACE timesimp: sleeping to spread out requests delay=248.823725ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.735992Z TRACE new{response=Response { client: 2025-10-16T10:48:30.715620914Z, server: 2025-10-16T10:48:35.725858903Z } current=2025-10-16T10:48:30.735967893Z}: timesimp::delta: response processing internals latency=10ms 173µs 489ns local_at_midpoint=2025-10-16T10:48:30.725794403Z delta=5s 64µs 500ns [INFO] [stdout] 2025-10-16T10:48:30.736023Z TRACE timesimp: obtained raw offset from server latency=10.173489ms delta=5s 64µs 500ns [INFO] [stdout] 2025-10-16T10:48:30.736033Z TRACE timesimp: sleeping to spread out requests delay=233.960616ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.783532Z TRACE new{response=Response { client: 2025-10-16T10:48:30.768674443Z, server: 2025-10-16T10:48:35.774795143Z } current=2025-10-16T10:48:30.783506513Z}: timesimp::delta: response processing internals latency=7ms 416µs 35ns local_at_midpoint=2025-10-16T10:48:30.776090478Z delta=4s 998ms 704µs 665ns [INFO] [stdout] 2025-10-16T10:48:30.783569Z TRACE timesimp: obtained raw offset from server latency=7.416035ms delta=4s 998ms 704µs 665ns [INFO] [stdout] 2025-10-16T10:48:30.783580Z TRACE timesimp: sleeping to spread out requests delay=1.821461395s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.829820Z TRACE new{response=Response { client: 2025-10-16T10:48:30.827588302Z, server: 2025-10-16T10:48:30.828702302Z } current=2025-10-16T10:48:30.829792542Z}: timesimp::delta: response processing internals latency=1ms 102µs 120ns local_at_midpoint=2025-10-16T10:48:30.828690422Z delta=11µs 880ns [INFO] [stdout] 2025-10-16T10:48:30.829862Z TRACE timesimp: obtained raw offset from server latency=1.10212ms delta=11µs 880ns [INFO] [stdout] 2025-10-16T10:48:30.829872Z TRACE timesimp: sleeping to spread out requests delay=413.036537ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:30.993690Z TRACE new{response=Response { client: 2025-10-16T10:48:30.97138007Z, server: 2025-10-16T10:48:35.98256146Z } current=2025-10-16T10:48:30.993665739Z}: timesimp::delta: response processing internals latency=11ms 142µs 834ns local_at_midpoint=2025-10-16T10:48:30.982522904Z delta=5s 38µs 556ns [INFO] [stdout] 2025-10-16T10:48:30.993725Z TRACE timesimp: obtained raw offset from server latency=11.142834ms delta=5s 38µs 556ns [INFO] [stdout] 2025-10-16T10:48:30.993734Z TRACE timesimp: sleeping to spread out requests delay=1.193882228s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:31.246741Z TRACE new{response=Response { client: 2025-10-16T10:48:31.244458196Z, server: 2025-10-16T10:48:31.245635226Z } current=2025-10-16T10:48:31.246718546Z}: timesimp::delta: response processing internals latency=1ms 130µs 175ns local_at_midpoint=2025-10-16T10:48:31.245588371Z delta=46µs 855ns [INFO] [stdout] 2025-10-16T10:48:31.246768Z TRACE timesimp: obtained raw offset from server latency=1.130175ms delta=46µs 855ns [INFO] [stdout] 2025-10-16T10:48:31.246777Z TRACE timesimp: sleeping to spread out requests delay=1.090893221s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:31.246797Z TRACE new{response=Response { client: 2025-10-16T10:48:31.232573636Z, server: 2025-10-16T10:48:36.239673486Z } current=2025-10-16T10:48:31.246789146Z}: timesimp::delta: response processing internals latency=7ms 107µs 755ns local_at_midpoint=2025-10-16T10:48:31.239681391Z delta=4s 999ms 992µs 95ns [INFO] [stdout] 2025-10-16T10:48:31.246806Z TRACE timesimp: obtained raw offset from server latency=7.107755ms delta=4s 999ms 992µs 95ns [INFO] [stdout] 2025-10-16T10:48:31.246810Z TRACE timesimp: sleeping to spread out requests delay=1.990944227s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:31.256803Z TRACE new{response=Response { client: 2025-10-16T10:48:31.234578076Z, server: 2025-10-16T10:48:31.245672916Z } current=2025-10-16T10:48:31.256782176Z}: timesimp::delta: response processing internals latency=11ms 102µs 50ns local_at_midpoint=2025-10-16T10:48:31.245680126Z delta=7µs 210ns ago [INFO] [stdout] 2025-10-16T10:48:31.256828Z TRACE timesimp: obtained raw offset from server latency=11.10205ms delta=7µs 210ns ago [INFO] [stdout] 2025-10-16T10:48:31.256836Z TRACE timesimp: sleeping to spread out requests delay=1.287141929s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:31.389788Z TRACE new{response=Response { client: 2025-10-16T10:48:31.367568104Z, server: 2025-10-16T10:48:26.378664534Z } current=2025-10-16T10:48:31.389767594Z}: timesimp::delta: response processing internals latency=11ms 99µs 745ns local_at_midpoint=2025-10-16T10:48:31.378667849Z delta=5s 3µs 315ns ago [INFO] [stdout] 2025-10-16T10:48:31.389812Z TRACE timesimp: obtained raw offset from server latency=11.099745ms delta=5s 3µs 315ns ago [INFO] [stdout] 2025-10-16T10:48:31.389821Z TRACE timesimp: sleeping to spread out requests delay=69.320935ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:31.482215Z TRACE new{response=Response { client: 2025-10-16T10:48:31.460011183Z, server: 2025-10-16T10:48:26.471104243Z } current=2025-10-16T10:48:31.482194062Z}: timesimp::delta: response processing internals latency=11ms 91µs 439ns local_at_midpoint=2025-10-16T10:48:31.471102622Z delta=4s 999ms 998µs 379ns ago [INFO] [stdout] 2025-10-16T10:48:31.482240Z TRACE timesimp: obtained raw offset from server latency=11.091439ms delta=4s 999ms 998µs 379ns ago [INFO] [stdout] 2025-10-16T10:48:31.482249Z TRACE timesimp: sleeping to spread out requests delay=1.752742316s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:31.932813Z TRACE new{response=Response { client: 2025-10-16T10:48:31.910586226Z, server: 2025-10-16T10:48:36.921697696Z } current=2025-10-16T10:48:31.932793596Z}: timesimp::delta: response processing internals latency=11ms 103µs 685ns local_at_midpoint=2025-10-16T10:48:31.921689911Z delta=5s 7µs 785ns [INFO] [stdout] 2025-10-16T10:48:31.932838Z TRACE timesimp: obtained raw offset from server latency=11.103685ms delta=5s 7µs 785ns [INFO] [stdout] 2025-10-16T10:48:31.932845Z TRACE timesimp: sleeping to spread out requests delay=1.54647226s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:32.052516Z TRACE new{response=Response { client: 2025-10-16T10:48:31.849936587Z, server: 2025-10-16T10:48:31.951242965Z } current=2025-10-16T10:48:32.052489644Z}: timesimp::delta: response processing internals latency=101ms 276µs 528ns local_at_midpoint=2025-10-16T10:48:31.951213115Z delta=29µs 850ns [INFO] [stdout] 2025-10-16T10:48:32.052552Z TRACE timesimp: obtained raw offset from server latency=101.276528ms delta=29µs 850ns [INFO] [stdout] 2025-10-16T10:48:32.052562Z TRACE timesimp: sleeping to spread out requests delay=1.413013569s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:32.211607Z TRACE new{response=Response { client: 2025-10-16T10:48:30.26965937Z, server: 2025-10-16T10:48:31.240770476Z } current=2025-10-16T10:48:32.211568882Z}: timesimp::delta: response processing internals latency=970ms 954µs 756ns local_at_midpoint=2025-10-16T10:48:31.240614126Z delta=156µs 350ns [INFO] [stdout] 2025-10-16T10:48:32.211716Z TRACE timesimp: obtained raw offset from server latency=970.954756ms delta=156µs 350ns [INFO] [stdout] 2025-10-16T10:48:32.211729Z DEBUG timesimp: no offset stored, storing initial delta offset=156µs 350ns [INFO] [stdout] 2025-10-16T10:48:32.211734Z TRACE timesimp: sleeping to spread out requests delay=760.935058ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:32.212079Z TRACE new{response=Response { client: 2025-10-16T10:48:32.189720792Z, server: 2025-10-16T10:48:37.200967612Z } current=2025-10-16T10:48:32.212068352Z}: timesimp::delta: response processing internals latency=11ms 173µs 780ns local_at_midpoint=2025-10-16T10:48:32.200894572Z delta=5s 73µs 40ns [INFO] [stdout] 2025-10-16T10:48:32.212091Z TRACE timesimp: obtained raw offset from server latency=11.17378ms delta=5s 73µs 40ns [INFO] [stdout] 2025-10-16T10:48:32.212099Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00132, 5000.0645, 5000.497774, 5000.038556, 5000.07304] [INFO] [stdout] 2025-10-16T10:48:32.212106Z TRACE timesimp: statistics about response deltas median=5000.497774 mean=5000.135037999999 variance=0.04189651174800869 stddev=0.20468637411417664 [INFO] [stdout] 2025-10-16T10:48:32.212112Z TRACE timesimp: eliminated outliers inliers=[5000.497774] [INFO] [stdout] 2025-10-16T10:48:32.212117Z DEBUG timesimp: storing calculated offset offset=5s 497µs [INFO] [stdout] test low_jitter ... ok [INFO] [stdout] 2025-10-16T10:48:32.270043Z TRACE new{response=Response { client: 2025-10-16T10:48:32.247615191Z, server: 2025-10-16T10:48:32.258838971Z } current=2025-10-16T10:48:32.269991521Z}: timesimp::delta: response processing internals latency=11ms 188µs 165ns local_at_midpoint=2025-10-16T10:48:32.258803356Z delta=35µs 615ns [INFO] [stdout] 2025-10-16T10:48:32.270072Z TRACE timesimp: obtained raw offset from server latency=11.188165ms delta=35µs 615ns [INFO] [stdout] 2025-10-16T10:48:32.270081Z TRACE timesimp: sleeping to spread out requests delay=1.048213563s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:32.341265Z TRACE new{response=Response { client: 2025-10-16T10:48:32.33903596Z, server: 2025-10-16T10:48:32.34014019Z } current=2025-10-16T10:48:32.34123871Z}: timesimp::delta: response processing internals latency=1ms 101µs 375ns local_at_midpoint=2025-10-16T10:48:32.340137335Z delta=2µs 855ns [INFO] [stdout] 2025-10-16T10:48:32.341296Z TRACE timesimp: obtained raw offset from server latency=1.101375ms delta=2µs 855ns [INFO] [stdout] 2025-10-16T10:48:32.341306Z TRACE timesimp: sleeping to spread out requests delay=1.109248807s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:32.567481Z TRACE new{response=Response { client: 2025-10-16T10:48:32.545284087Z, server: 2025-10-16T10:48:32.556374047Z } current=2025-10-16T10:48:32.567460436Z}: timesimp::delta: response processing internals latency=11ms 88µs 174ns local_at_midpoint=2025-10-16T10:48:32.556372261Z delta=1µs 786ns [INFO] [stdout] 2025-10-16T10:48:32.567502Z TRACE timesimp: obtained raw offset from server latency=11.088174ms delta=1µs 786ns [INFO] [stdout] 2025-10-16T10:48:32.567508Z TRACE timesimp: sleeping to spread out requests delay=1.661556357s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:32.616635Z TRACE new{response=Response { client: 2025-10-16T10:48:32.606497416Z, server: 2025-10-16T10:48:37.612517186Z } current=2025-10-16T10:48:32.616611666Z}: timesimp::delta: response processing internals latency=5ms 57µs 125ns local_at_midpoint=2025-10-16T10:48:32.611554541Z delta=5s 962µs 645ns [INFO] [stdout] 2025-10-16T10:48:32.616665Z TRACE timesimp: obtained raw offset from server latency=5.057125ms delta=5s 962µs 645ns [INFO] [stdout] 2025-10-16T10:48:32.616683Z TRACE timesimp: sleeping to spread out requests delay=842.906231ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:33.252774Z TRACE new{response=Response { client: 2025-10-16T10:48:33.238564017Z, server: 2025-10-16T10:48:38.245660306Z } current=2025-10-16T10:48:33.252750766Z}: timesimp::delta: response processing internals latency=7ms 93µs 374ns local_at_midpoint=2025-10-16T10:48:33.245657391Z delta=5s 2µs 915ns [INFO] [stdout] 2025-10-16T10:48:33.252809Z TRACE timesimp: obtained raw offset from server latency=7.093374ms delta=5s 2µs 915ns [INFO] [stdout] 2025-10-16T10:48:33.252819Z TRACE timesimp: sleeping to spread out requests delay=1.367409163s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:33.258788Z TRACE new{response=Response { client: 2025-10-16T10:48:33.236590947Z, server: 2025-10-16T10:48:28.247684657Z } current=2025-10-16T10:48:33.258775866Z}: timesimp::delta: response processing internals latency=11ms 92µs 459ns local_at_midpoint=2025-10-16T10:48:33.247683406Z delta=4s 999ms 998µs 749ns ago [INFO] [stdout] 2025-10-16T10:48:33.258811Z TRACE timesimp: obtained raw offset from server latency=11.092459ms delta=4s 999ms 998µs 749ns ago [INFO] [stdout] 2025-10-16T10:48:33.258819Z TRACE timesimp: sleeping to spread out requests delay=598.442308ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:33.342077Z TRACE new{response=Response { client: 2025-10-16T10:48:33.319570205Z, server: 2025-10-16T10:48:33.330683605Z } current=2025-10-16T10:48:33.342051875Z}: timesimp::delta: response processing internals latency=11ms 240µs 835ns local_at_midpoint=2025-10-16T10:48:33.33081104Z delta=127µs 435ns ago [INFO] [stdout] 2025-10-16T10:48:33.342114Z TRACE timesimp: obtained raw offset from server latency=11.240835ms delta=127µs 435ns ago [INFO] [stdout] 2025-10-16T10:48:33.342124Z TRACE timesimp: sleeping to spread out requests delay=1.080054258s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:33.453767Z TRACE new{response=Response { client: 2025-10-16T10:48:33.451561824Z, server: 2025-10-16T10:48:33.452657604Z } current=2025-10-16T10:48:33.453741654Z}: timesimp::delta: response processing internals latency=1ms 89µs 915ns local_at_midpoint=2025-10-16T10:48:33.452651739Z delta=5µs 865ns [INFO] [stdout] 2025-10-16T10:48:33.453801Z TRACE timesimp: obtained raw offset from server latency=1.089915ms delta=5µs 865ns [INFO] [stdout] 2025-10-16T10:48:33.453813Z TRACE timesimp: response deltas sorted by latency deltas=[0.000825, 0.005865, 0.002855, 0.01188, 0.046855] [INFO] [stdout] 2025-10-16T10:48:33.453822Z TRACE timesimp: statistics about response deltas median=0.002855 mean=0.013656000000000001 variance=0.000361830905 stddev=0.01902185335344587 [INFO] [stdout] 2025-10-16T10:48:33.453827Z TRACE timesimp: eliminated outliers inliers=[0.000825, 0.005865, 0.002855, 0.01188] [INFO] [stdout] 2025-10-16T10:48:33.453831Z DEBUG timesimp: storing calculated offset offset=5µs [INFO] [stdout] test no_delay ... ok [INFO] [stdout] 2025-10-16T10:48:33.472837Z TRACE new{response=Response { client: 2025-10-16T10:48:33.460565654Z, server: 2025-10-16T10:48:38.466655194Z } current=2025-10-16T10:48:33.472815773Z}: timesimp::delta: response processing internals latency=6ms 125µs 59ns local_at_midpoint=2025-10-16T10:48:33.466690713Z delta=4s 999ms 964µs 481ns [INFO] [stdout] 2025-10-16T10:48:33.472931Z TRACE timesimp: obtained raw offset from server latency=6.125059ms delta=4s 999ms 964µs 481ns [INFO] [stdout] 2025-10-16T10:48:33.472961Z TRACE timesimp: response deltas sorted by latency deltas=[5000.962645, 4999.500529, 4999.964481, 4998.704665, 4999.998625] [INFO] [stdout] 2025-10-16T10:48:33.472987Z TRACE timesimp: statistics about response deltas median=4999.964481 mean=4999.826189 variance=0.6760654023676916 stddev=0.822231963844566 [INFO] [stdout] 2025-10-16T10:48:33.473009Z TRACE timesimp: eliminated outliers inliers=[4999.500529, 4999.964481, 4999.998625] [INFO] [stdout] 2025-10-16T10:48:33.473040Z DEBUG timesimp: storing calculated offset offset=4s 999ms 821µs [INFO] [stdout] test high_jitter ... ok [INFO] [stdout] 2025-10-16T10:48:33.502819Z TRACE new{response=Response { client: 2025-10-16T10:48:33.480578093Z, server: 2025-10-16T10:48:38.491687473Z } current=2025-10-16T10:48:33.502795173Z}: timesimp::delta: response processing internals latency=11ms 108µs 540ns local_at_midpoint=2025-10-16T10:48:33.491686633Z delta=5s 840ns [INFO] [stdout] 2025-10-16T10:48:33.502855Z TRACE timesimp: obtained raw offset from server latency=11.10854ms delta=5s 840ns [INFO] [stdout] 2025-10-16T10:48:33.502864Z TRACE timesimp: sleeping to spread out requests delay=568.94211ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:33.669090Z TRACE new{response=Response { client: 2025-10-16T10:48:33.466569203Z, server: 2025-10-16T10:48:33.567820982Z } current=2025-10-16T10:48:33.669066071Z}: timesimp::delta: response processing internals latency=101ms 248µs 434ns local_at_midpoint=2025-10-16T10:48:33.567817637Z delta=3µs 345ns [INFO] [stdout] 2025-10-16T10:48:33.669121Z TRACE timesimp: obtained raw offset from server latency=101.248434ms delta=3µs 345ns [INFO] [stdout] 2025-10-16T10:48:33.669130Z TRACE timesimp: sleeping to spread out requests delay=1.934038399s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:33.880895Z TRACE new{response=Response { client: 2025-10-16T10:48:33.858614478Z, server: 2025-10-16T10:48:28.869724178Z } current=2025-10-16T10:48:33.880868137Z}: timesimp::delta: response processing internals latency=11ms 126µs 829ns local_at_midpoint=2025-10-16T10:48:33.869741307Z delta=5s 17µs 129ns ago [INFO] [stdout] 2025-10-16T10:48:33.880933Z TRACE timesimp: obtained raw offset from server latency=11.126829ms delta=5s 17µs 129ns ago [INFO] [stdout] 2025-10-16T10:48:33.880945Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.999745, -4999.998379, -4999.998749, -5000.003315, -5000.017129] [INFO] [stdout] 2025-10-16T10:48:33.880952Z TRACE timesimp: statistics about response deltas median=-4999.998749 mean=-5000.003463399999 variance=6.216845879889862e-5 stddev=0.007884697762051416 [INFO] [stdout] 2025-10-16T10:48:33.880958Z TRACE timesimp: eliminated outliers inliers=[-4999.999745, -4999.998379, -4999.998749, -5000.003315] [INFO] [stdout] 2025-10-16T10:48:33.880962Z DEBUG timesimp: storing calculated offset offset=5s ago [INFO] [stdout] test server_offset_negative ... ok [INFO] [stdout] 2025-10-16T10:48:34.095771Z TRACE new{response=Response { client: 2025-10-16T10:48:34.073561705Z, server: 2025-10-16T10:48:39.084656334Z } current=2025-10-16T10:48:34.095750454Z}: timesimp::delta: response processing internals latency=11ms 94µs 374ns local_at_midpoint=2025-10-16T10:48:34.084656079Z delta=5s 255ns [INFO] [stdout] 2025-10-16T10:48:34.095796Z TRACE timesimp: obtained raw offset from server latency=11.094374ms delta=5s 255ns [INFO] [stdout] 2025-10-16T10:48:34.095802Z TRACE timesimp: sleeping to spread out requests delay=1.903167405s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:34.253009Z TRACE new{response=Response { client: 2025-10-16T10:48:34.230656012Z, server: 2025-10-16T10:48:34.241879062Z } current=2025-10-16T10:48:34.252983192Z}: timesimp::delta: response processing internals latency=11ms 163µs 590ns local_at_midpoint=2025-10-16T10:48:34.241819602Z delta=59µs 460ns [INFO] [stdout] 2025-10-16T10:48:34.253039Z TRACE timesimp: obtained raw offset from server latency=11.16359ms delta=59µs 460ns [INFO] [stdout] 2025-10-16T10:48:34.253048Z TRACE timesimp: sleeping to spread out requests delay=784.166702ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:34.445578Z TRACE new{response=Response { client: 2025-10-16T10:48:34.42328256Z, server: 2025-10-16T10:48:34.434458609Z } current=2025-10-16T10:48:34.445558359Z}: timesimp::delta: response processing internals latency=11ms 137µs 899ns local_at_midpoint=2025-10-16T10:48:34.434420459Z delta=38µs 150ns [INFO] [stdout] 2025-10-16T10:48:34.445601Z TRACE timesimp: obtained raw offset from server latency=11.137899ms delta=38µs 150ns [INFO] [stdout] 2025-10-16T10:48:34.445608Z TRACE timesimp: sleeping to spread out requests delay=824.558617ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:34.596977Z TRACE new{response=Response { client: 2025-10-16T10:48:32.973572181Z, server: 2025-10-16T10:48:33.785482039Z } current=2025-10-16T10:48:34.596961627Z}: timesimp::delta: response processing internals latency=811ms 694µs 723ns local_at_midpoint=2025-10-16T10:48:33.785266904Z delta=215µs 135ns [INFO] [stdout] 2025-10-16T10:48:34.596995Z TRACE timesimp: obtained raw offset from server latency=811.694723ms delta=215µs 135ns [INFO] [stdout] 2025-10-16T10:48:34.597002Z TRACE timesimp: sleeping to spread out requests delay=1.498530352s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:34.642507Z TRACE new{response=Response { client: 2025-10-16T10:48:34.622280297Z, server: 2025-10-16T10:48:39.632411977Z } current=2025-10-16T10:48:34.642494146Z}: timesimp::delta: response processing internals latency=10ms 106µs 924ns local_at_midpoint=2025-10-16T10:48:34.632387221Z delta=5s 24µs 756ns [INFO] [stdout] 2025-10-16T10:48:34.642528Z TRACE timesimp: obtained raw offset from server latency=10.106924ms delta=5s 24µs 756ns [INFO] [stdout] 2025-10-16T10:48:34.642534Z TRACE timesimp: sleeping to spread out requests delay=812.24521ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:35.060346Z TRACE new{response=Response { client: 2025-10-16T10:48:35.03803744Z, server: 2025-10-16T10:48:35.04917664Z } current=2025-10-16T10:48:35.06031611Z}: timesimp::delta: response processing internals latency=11ms 139µs 335ns local_at_midpoint=2025-10-16T10:48:35.049176775Z delta=135ns ago [INFO] [stdout] 2025-10-16T10:48:35.060380Z TRACE timesimp: obtained raw offset from server latency=11.139335ms delta=135ns ago [INFO] [stdout] 2025-10-16T10:48:35.060391Z TRACE timesimp: response deltas sorted by latency deltas=[0.001786, -0.00721, 0.013195, -0.000135, 0.05946] [INFO] [stdout] 2025-10-16T10:48:35.060400Z TRACE timesimp: statistics about response deltas median=0.013195 mean=0.013419200000000001 variance=0.0007161042757000001 stddev=0.02676012473251947 [INFO] [stdout] 2025-10-16T10:48:35.060416Z TRACE timesimp: eliminated outliers inliers=[0.001786, -0.00721, 0.013195, -0.000135] [INFO] [stdout] 2025-10-16T10:48:35.060420Z DEBUG timesimp: storing calculated offset offset=1µs [INFO] [stdout] test client_offset_negative ... ok [INFO] [stdout] 2025-10-16T10:48:35.293053Z TRACE new{response=Response { client: 2025-10-16T10:48:35.270604207Z, server: 2025-10-16T10:48:35.281714227Z } current=2025-10-16T10:48:35.293027437Z}: timesimp::delta: response processing internals latency=11ms 211µs 615ns local_at_midpoint=2025-10-16T10:48:35.281815822Z delta=101µs 595ns ago [INFO] [stdout] 2025-10-16T10:48:35.293084Z TRACE timesimp: obtained raw offset from server latency=11.211615ms delta=101µs 595ns ago [INFO] [stdout] 2025-10-16T10:48:35.293094Z TRACE timesimp: response deltas sorted by latency deltas=[-0.000625, 0.03815, 0.035615, -0.101595, -0.127435] [INFO] [stdout] 2025-10-16T10:48:35.293102Z TRACE timesimp: statistics about response deltas median=0.035615 mean=-0.031177999999999994 variance=0.006106281545 stddev=0.07814269988297051 [INFO] [stdout] 2025-10-16T10:48:35.293107Z TRACE timesimp: eliminated outliers inliers=[-0.000625, 0.03815, 0.035615] [INFO] [stdout] 2025-10-16T10:48:35.293111Z DEBUG timesimp: storing calculated offset offset=24µs [INFO] [stdout] test client_offset_positive ... ok [INFO] [stdout] 2025-10-16T10:48:35.470716Z TRACE new{response=Response { client: 2025-10-16T10:48:35.456482414Z, server: 2025-10-16T10:48:40.463579764Z } current=2025-10-16T10:48:35.470691934Z}: timesimp::delta: response processing internals latency=7ms 104µs 760ns local_at_midpoint=2025-10-16T10:48:35.463587174Z delta=4s 999ms 992µs 590ns [INFO] [stdout] 2025-10-16T10:48:35.470748Z TRACE timesimp: obtained raw offset from server latency=7.10476ms delta=4s 999ms 992µs 590ns [INFO] [stdout] 2025-10-16T10:48:35.470758Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002915, 4999.99259, 4999.992095, 4999.504045, 5000.024756] [INFO] [stdout] 2025-10-16T10:48:35.470765Z TRACE timesimp: statistics about response deltas median=4999.992095 mean=4999.903280199999 variance=0.04998412933772876 stddev=0.22357130705376474 [INFO] [stdout] 2025-10-16T10:48:35.470771Z TRACE timesimp: eliminated outliers inliers=[5000.002915, 4999.99259, 4999.992095, 5000.024756] [INFO] [stdout] 2025-10-16T10:48:35.470775Z DEBUG timesimp: storing calculated offset offset=5s 3µs [INFO] [stdout] test mid_jitter ... ok [INFO] [stdout] 2025-10-16T10:48:35.806021Z TRACE new{response=Response { client: 2025-10-16T10:48:35.604575712Z, server: 2025-10-16T10:48:35.705780521Z } current=2025-10-16T10:48:35.805995649Z}: timesimp::delta: response processing internals latency=100ms 709µs 968ns local_at_midpoint=2025-10-16T10:48:35.70528568Z delta=494µs 841ns [INFO] [stdout] 2025-10-16T10:48:35.806057Z TRACE timesimp: obtained raw offset from server latency=100.709968ms delta=494µs 841ns [INFO] [stdout] 2025-10-16T10:48:35.806068Z TRACE timesimp: sleeping to spread out requests delay=369.435088ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:36.022810Z TRACE new{response=Response { client: 2025-10-16T10:48:36.000573377Z, server: 2025-10-16T10:48:41.011680656Z } current=2025-10-16T10:48:36.022785116Z}: timesimp::delta: response processing internals latency=11ms 105µs 869ns local_at_midpoint=2025-10-16T10:48:36.011679246Z delta=5s 1µs 410ns [INFO] [stdout] 2025-10-16T10:48:36.022849Z TRACE timesimp: obtained raw offset from server latency=11.105869ms delta=5s 1µs 410ns [INFO] [stdout] 2025-10-16T10:48:36.022860Z TRACE timesimp: response deltas sorted by latency deltas=[5000.000255, 5000.007785, 5000.00141, 5000.00084, 4999.97912] [INFO] [stdout] 2025-10-16T10:48:36.022868Z TRACE timesimp: statistics about response deltas median=5000.00141 mean=4999.997882000001 variance=0.000119227432498454 stddev=0.01091913149011651 [INFO] [stdout] 2025-10-16T10:48:36.022875Z TRACE timesimp: eliminated outliers inliers=[5000.000255, 5000.007785, 5000.00141, 5000.00084] [INFO] [stdout] 2025-10-16T10:48:36.022879Z DEBUG timesimp: storing calculated offset offset=5s 2µs [INFO] [stdout] test server_offset_positive ... ok [INFO] [stdout] 2025-10-16T10:48:36.378019Z TRACE new{response=Response { client: 2025-10-16T10:48:36.176568354Z, server: 2025-10-16T10:48:36.277766833Z } current=2025-10-16T10:48:36.377994371Z}: timesimp::delta: response processing internals latency=100ms 713µs 8ns local_at_midpoint=2025-10-16T10:48:36.277281362Z delta=485µs 471ns [INFO] [stdout] 2025-10-16T10:48:36.378051Z TRACE timesimp: obtained raw offset from server latency=100.713008ms delta=485µs 471ns [INFO] [stdout] 2025-10-16T10:48:36.378061Z TRACE timesimp: response deltas sorted by latency deltas=[0.494841, 0.485471, -0.023375, 0.003345, 0.02985] [INFO] [stdout] 2025-10-16T10:48:36.378068Z TRACE timesimp: statistics about response deltas median=-0.023375 mean=0.1980264 variance=0.0714815084468 stddev=0.2673602596625011 [INFO] [stdout] 2025-10-16T10:48:36.378073Z TRACE timesimp: eliminated outliers inliers=[-0.023375, 0.003345, 0.02985] [INFO] [stdout] 2025-10-16T10:48:36.378077Z DEBUG timesimp: storing calculated offset offset=3µs [INFO] [stdout] test some_delay ... ok [INFO] [stdout] 2025-10-16T10:48:37.790577Z TRACE new{response=Response { client: 2025-10-16T10:48:36.096567555Z, server: 2025-10-16T10:48:36.943558263Z } current=2025-10-16T10:48:37.79055592Z}: timesimp::delta: response processing internals latency=846ms 994µs 182ns local_at_midpoint=2025-10-16T10:48:36.943561737Z delta=3µs 474ns ago [INFO] [stdout] 2025-10-16T10:48:37.790601Z TRACE timesimp: obtained raw offset from server latency=846.994182ms delta=3µs 474ns ago [INFO] [stdout] 2025-10-16T10:48:37.790608Z TRACE timesimp: sleeping to spread out requests delay=861.704152ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:40.361526Z TRACE new{response=Response { client: 2025-10-16T10:48:38.653502388Z, server: 2025-10-16T10:48:39.507541746Z } current=2025-10-16T10:48:40.361504403Z}: timesimp::delta: response processing internals latency=854ms 1µs 7ns local_at_midpoint=2025-10-16T10:48:39.507503395Z delta=38µs 351ns [INFO] [stdout] 2025-10-16T10:48:40.361549Z TRACE timesimp: obtained raw offset from server latency=854.001007ms delta=38µs 351ns [INFO] [stdout] 2025-10-16T10:48:40.361556Z TRACE timesimp: sleeping to spread out requests delay=110.375051ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.128776Z TRACE new{response=Response { client: 2025-10-16T10:48:40.472812812Z, server: 2025-10-16T10:48:41.300777309Z } current=2025-10-16T10:48:42.128756277Z}: timesimp::delta: response processing internals latency=827ms 971µs 732ns local_at_midpoint=2025-10-16T10:48:41.300784544Z delta=7µs 235ns ago [INFO] [stdout] 2025-10-16T10:48:42.128799Z TRACE timesimp: obtained raw offset from server latency=827.971732ms delta=7µs 235ns ago [INFO] [stdout] 2025-10-16T10:48:42.128806Z TRACE timesimp: response deltas sorted by latency deltas=[0.215135, -0.007235, -0.003474, 0.038351, 0.15635] [INFO] [stdout] 2025-10-16T10:48:42.128812Z TRACE timesimp: statistics about response deltas median=-0.003474 mean=0.0798254 variance=0.010100782850299998 stddev=0.10050265096155424 [INFO] [stdout] 2025-10-16T10:48:42.128816Z TRACE timesimp: eliminated outliers inliers=[-0.007235, -0.003474, 0.038351] [INFO] [stdout] 2025-10-16T10:48:42.128819Z DEBUG timesimp: storing calculated offset offset=9µs [INFO] [stdout] test much_delay ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 11.86s [INFO] [stdout] [INFO] [stderr] Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-0c65a2e6eb3445c6) [INFO] [stdout] [INFO] [stdout] running 4 tests [INFO] [stdout] 2025-10-16T10:48:42.132193Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:42.132207Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-16T10:48:42.132214Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.132214Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-10-16T10:48:42.132219Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.132225Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.132223Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-10-16T10:48:42.132244Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.133338Z TRACE new{response=Response { client: 2025-10-16T10:48:42.133324337Z, server: 2025-10-16T10:48:42.133324507Z } current=2025-10-16T10:48:42.133324597Z}: timesimp::delta: response processing internals latency=130ns local_at_midpoint=2025-10-16T10:48:42.133324467Z delta=40ns [INFO] [stdout] 2025-10-16T10:48:42.133340Z TRACE new{response=Response { client: 2025-10-16T10:48:42.133329197Z, server: 2025-10-16T10:48:47.133329297Z } current=2025-10-16T10:48:42.133329377Z}: timesimp::delta: response processing internals latency=90ns local_at_midpoint=2025-10-16T10:48:42.133329287Z delta=5s 10ns [INFO] [stdout] 2025-10-16T10:48:42.133356Z TRACE timesimp: obtained raw offset from server latency=130ns delta=40ns [INFO] [stdout] 2025-10-16T10:48:42.133363Z TRACE timesimp: sleeping to spread out requests delay=1.332607393s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.133365Z TRACE timesimp: obtained raw offset from server latency=90ns delta=5s 10ns [INFO] [stdout] 2025-10-16T10:48:42.133369Z TRACE timesimp: sleeping to spread out requests delay=1.261070545s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.133364Z TRACE new{response=Response { client: 2025-10-16T10:48:42.133345367Z, server: 2025-10-16T10:48:37.133345477Z } current=2025-10-16T10:48:42.133345637Z}: timesimp::delta: response processing internals latency=135ns local_at_midpoint=2025-10-16T10:48:42.133345502Z delta=5s 25ns ago [INFO] [stdout] 2025-10-16T10:48:42.133338Z TRACE new{response=Response { client: 2025-10-16T10:48:42.133318547Z, server: 2025-10-16T10:48:42.133318657Z } current=2025-10-16T10:48:42.133318787Z}: timesimp::delta: response processing internals latency=120ns local_at_midpoint=2025-10-16T10:48:42.133318667Z delta=10ns ago [INFO] [stdout] 2025-10-16T10:48:42.133377Z TRACE timesimp: obtained raw offset from server latency=135ns delta=5s 25ns ago [INFO] [stdout] 2025-10-16T10:48:42.133383Z TRACE timesimp: sleeping to spread out requests delay=758.084314ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.133385Z TRACE timesimp: obtained raw offset from server latency=120ns delta=10ns ago [INFO] [stdout] 2025-10-16T10:48:42.133393Z DEBUG timesimp: no offset stored, storing initial delta offset=10ns ago [INFO] [stdout] 2025-10-16T10:48:42.133397Z TRACE timesimp: sleeping to spread out requests delay=125.51395ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.259639Z TRACE new{response=Response { client: 2025-10-16T10:48:42.259618865Z, server: 2025-10-16T10:48:42.259619065Z } current=2025-10-16T10:48:42.259619155Z}: timesimp::delta: response processing internals latency=145ns local_at_midpoint=2025-10-16T10:48:42.25961901Z delta=55ns [INFO] [stdout] 2025-10-16T10:48:42.259661Z TRACE timesimp: obtained raw offset from server latency=145ns delta=55ns [INFO] [stdout] 2025-10-16T10:48:42.259675Z TRACE timesimp: sleeping to spread out requests delay=1.810292172s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:42.893250Z TRACE new{response=Response { client: 2025-10-16T10:48:42.893230846Z, server: 2025-10-16T10:48:37.893231156Z } current=2025-10-16T10:48:42.893231236Z}: timesimp::delta: response processing internals latency=195ns local_at_midpoint=2025-10-16T10:48:42.893231041Z delta=4s 999ms 999µs 885ns ago [INFO] [stdout] 2025-10-16T10:48:42.893271Z TRACE timesimp: obtained raw offset from server latency=195ns delta=4s 999ms 999µs 885ns ago [INFO] [stdout] 2025-10-16T10:48:42.893278Z TRACE timesimp: sleeping to spread out requests delay=1.809321986s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:43.395783Z TRACE new{response=Response { client: 2025-10-16T10:48:43.395763099Z, server: 2025-10-16T10:48:48.395763329Z } current=2025-10-16T10:48:43.395763409Z}: timesimp::delta: response processing internals latency=155ns local_at_midpoint=2025-10-16T10:48:43.395763254Z delta=5s 75ns [INFO] [stdout] 2025-10-16T10:48:43.395806Z TRACE timesimp: obtained raw offset from server latency=155ns delta=5s 75ns [INFO] [stdout] 2025-10-16T10:48:43.395813Z TRACE timesimp: sleeping to spread out requests delay=1.71434538s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:43.466860Z TRACE new{response=Response { client: 2025-10-16T10:48:43.466832178Z, server: 2025-10-16T10:48:43.466832438Z } current=2025-10-16T10:48:43.466832728Z}: timesimp::delta: response processing internals latency=275ns local_at_midpoint=2025-10-16T10:48:43.466832453Z delta=15ns ago [INFO] [stdout] 2025-10-16T10:48:43.466896Z TRACE timesimp: obtained raw offset from server latency=275ns delta=15ns ago [INFO] [stdout] 2025-10-16T10:48:43.466904Z TRACE timesimp: sleeping to spread out requests delay=1.691927642s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:44.070692Z TRACE new{response=Response { client: 2025-10-16T10:48:44.070656669Z, server: 2025-10-16T10:48:44.070656909Z } current=2025-10-16T10:48:44.070657089Z}: timesimp::delta: response processing internals latency=210ns local_at_midpoint=2025-10-16T10:48:44.070656879Z delta=30ns [INFO] [stdout] 2025-10-16T10:48:44.070720Z TRACE timesimp: obtained raw offset from server latency=210ns delta=30ns [INFO] [stdout] 2025-10-16T10:48:44.070729Z TRACE timesimp: sleeping to spread out requests delay=791.912131ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:44.703642Z TRACE new{response=Response { client: 2025-10-16T10:48:44.70361769Z, server: 2025-10-16T10:48:39.70361794Z } current=2025-10-16T10:48:44.70361811Z}: timesimp::delta: response processing internals latency=210ns local_at_midpoint=2025-10-16T10:48:44.7036179Z delta=4s 999ms 999µs 960ns ago [INFO] [stdout] 2025-10-16T10:48:44.703678Z TRACE timesimp: obtained raw offset from server latency=210ns delta=4s 999ms 999µs 960ns ago [INFO] [stdout] 2025-10-16T10:48:44.703696Z TRACE timesimp: sleeping to spread out requests delay=775.824449ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:44.863629Z TRACE new{response=Response { client: 2025-10-16T10:48:44.863608607Z, server: 2025-10-16T10:48:44.863608787Z } current=2025-10-16T10:48:44.863608877Z}: timesimp::delta: response processing internals latency=135ns local_at_midpoint=2025-10-16T10:48:44.863608742Z delta=45ns [INFO] [stdout] 2025-10-16T10:48:44.863657Z TRACE timesimp: obtained raw offset from server latency=135ns delta=45ns [INFO] [stdout] 2025-10-16T10:48:44.863663Z TRACE timesimp: sleeping to spread out requests delay=1.947058024s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:45.111651Z TRACE new{response=Response { client: 2025-10-16T10:48:45.111626544Z, server: 2025-10-16T10:48:50.111626744Z } current=2025-10-16T10:48:45.111626904Z}: timesimp::delta: response processing internals latency=180ns local_at_midpoint=2025-10-16T10:48:45.111626724Z delta=5s 20ns [INFO] [stdout] 2025-10-16T10:48:45.111688Z TRACE timesimp: obtained raw offset from server latency=180ns delta=5s 20ns [INFO] [stdout] 2025-10-16T10:48:45.111697Z TRACE timesimp: sleeping to spread out requests delay=671.634691ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:45.159646Z TRACE new{response=Response { client: 2025-10-16T10:48:45.159622063Z, server: 2025-10-16T10:48:45.159622663Z } current=2025-10-16T10:48:45.159622833Z}: timesimp::delta: response processing internals latency=385ns local_at_midpoint=2025-10-16T10:48:45.159622448Z delta=215ns [INFO] [stdout] 2025-10-16T10:48:45.159686Z TRACE timesimp: obtained raw offset from server latency=385ns delta=215ns [INFO] [stdout] 2025-10-16T10:48:45.159695Z TRACE timesimp: sleeping to spread out requests delay=227.963648ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:45.389076Z TRACE new{response=Response { client: 2025-10-16T10:48:45.3890509Z, server: 2025-10-16T10:48:45.38905131Z } current=2025-10-16T10:48:45.38905159Z}: timesimp::delta: response processing internals latency=345ns local_at_midpoint=2025-10-16T10:48:45.389051245Z delta=65ns [INFO] [stdout] 2025-10-16T10:48:45.389107Z TRACE timesimp: obtained raw offset from server latency=345ns delta=65ns [INFO] [stdout] 2025-10-16T10:48:45.389115Z TRACE timesimp: sleeping to spread out requests delay=1.126689237s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:45.480585Z TRACE new{response=Response { client: 2025-10-16T10:48:45.480561528Z, server: 2025-10-16T10:48:40.480561828Z } current=2025-10-16T10:48:45.480561999Z}: timesimp::delta: response processing internals latency=235ns local_at_midpoint=2025-10-16T10:48:45.480561763Z delta=4s 999ms 999µs 935ns ago [INFO] [stdout] 2025-10-16T10:48:45.480617Z TRACE timesimp: obtained raw offset from server latency=235ns delta=4s 999ms 999µs 935ns ago [INFO] [stdout] 2025-10-16T10:48:45.480626Z TRACE timesimp: sleeping to spread out requests delay=1.250125328s max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:45.784601Z TRACE new{response=Response { client: 2025-10-16T10:48:45.784582094Z, server: 2025-10-16T10:48:50.784582434Z } current=2025-10-16T10:48:45.784582504Z}: timesimp::delta: response processing internals latency=205ns local_at_midpoint=2025-10-16T10:48:45.784582299Z delta=5s 135ns [INFO] [stdout] 2025-10-16T10:48:45.784627Z TRACE timesimp: obtained raw offset from server latency=205ns delta=5s 135ns [INFO] [stdout] 2025-10-16T10:48:45.784633Z TRACE timesimp: sleeping to spread out requests delay=829.180972ms max_jitter=2s [INFO] [stdout] 2025-10-16T10:48:46.516872Z TRACE new{response=Response { client: 2025-10-16T10:48:46.516847063Z, server: 2025-10-16T10:48:46.516847383Z } current=2025-10-16T10:48:46.516847543Z}: timesimp::delta: response processing internals latency=240ns local_at_midpoint=2025-10-16T10:48:46.516847303Z delta=80ns [INFO] [stdout] 2025-10-16T10:48:46.516910Z TRACE timesimp: obtained raw offset from server latency=240ns delta=80ns [INFO] [stdout] 2025-10-16T10:48:46.516920Z TRACE timesimp: response deltas sorted by latency deltas=[4e-5, 8e-5, -1.5e-5, 6.5e-5, 0.000215] [INFO] [stdout] 2025-10-16T10:48:46.516927Z TRACE timesimp: statistics about response deltas median=-1.5e-5 mean=7.7e-5 variance=7.257499999999999e-9 stddev=8.519096196193584e-5 [INFO] [stdout] 2025-10-16T10:48:46.516933Z TRACE timesimp: eliminated outliers inliers=[4e-5, -1.5e-5, 6.5e-5] [INFO] [stdout] 2025-10-16T10:48:46.516937Z DEBUG timesimp: storing calculated offset offset=0s [INFO] [stdout] test zero_offset ... ok [INFO] [stdout] 2025-10-16T10:48:46.614587Z TRACE new{response=Response { client: 2025-10-16T10:48:46.614561742Z, server: 2025-10-16T10:48:51.614562032Z } current=2025-10-16T10:48:46.614562262Z}: timesimp::delta: response processing internals latency=260ns local_at_midpoint=2025-10-16T10:48:46.614562002Z delta=5s 30ns [INFO] [stdout] 2025-10-16T10:48:46.614622Z TRACE timesimp: obtained raw offset from server latency=260ns delta=5s 30ns [INFO] [stdout] 2025-10-16T10:48:46.615056Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00001, 5000.000075, 5000.00002, 5000.000135, 5000.00003] [INFO] [stdout] 2025-10-16T10:48:46.615066Z TRACE timesimp: statistics about response deltas median=5000.00002 mean=5000.000054 variance=2.6675000052887477e-9 stddev=5.1647846085667e-5 [INFO] [stdout] 2025-10-16T10:48:46.615073Z TRACE timesimp: eliminated outliers inliers=[5000.00001, 5000.00002, 5000.00003] [INFO] [stdout] 2025-10-16T10:48:46.615078Z DEBUG timesimp: storing calculated offset offset=5s [INFO] [stdout] test positive_starting_offset ... ok [INFO] [stdout] 2025-10-16T10:48:46.732074Z TRACE new{response=Response { client: 2025-10-16T10:48:46.73204981Z, server: 2025-10-16T10:48:41.73205014Z } current=2025-10-16T10:48:46.73205031Z}: timesimp::delta: response processing internals latency=250ns local_at_midpoint=2025-10-16T10:48:46.73205006Z delta=4s 999ms 999µs 920ns ago [INFO] [stdout] 2025-10-16T10:48:46.732114Z TRACE timesimp: obtained raw offset from server latency=250ns delta=4s 999ms 999µs 920ns ago [INFO] [stdout] 2025-10-16T10:48:46.732124Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.000025, -4999.999885, -4999.99996, -4999.999935, -4999.99992] [INFO] [stdout] 2025-10-16T10:48:46.732133Z TRACE timesimp: statistics about response deltas median=-4999.99996 mean=-4999.9999450000005 variance=2.737500004935282e-9 stddev=5.2321123888304254e-5 [INFO] [stdout] 2025-10-16T10:48:46.732139Z TRACE timesimp: eliminated outliers inliers=[-4999.99996, -4999.999935, -4999.99992] [INFO] [stdout] 2025-10-16T10:48:46.732143Z DEBUG timesimp: storing calculated offset offset=4s 999ms 999µs ago [INFO] [stdout] test negative_starting_offset ... ok [INFO] [stdout] 2025-10-16T10:48:46.812288Z TRACE new{response=Response { client: 2025-10-16T10:48:46.812262969Z, server: 2025-10-16T10:48:46.812263279Z } current=2025-10-16T10:48:46.812263489Z}: timesimp::delta: response processing internals latency=260ns local_at_midpoint=2025-10-16T10:48:46.812263229Z delta=50ns [INFO] [stdout] 2025-10-16T10:48:46.812322Z TRACE timesimp: obtained raw offset from server latency=260ns delta=50ns [INFO] [stdout] 2025-10-16T10:48:46.812332Z TRACE timesimp: response deltas sorted by latency deltas=[-1e-5, 4.5e-5, 5.5e-5, 3e-5, 5e-5] [INFO] [stdout] 2025-10-16T10:48:46.812339Z TRACE timesimp: statistics about response deltas median=5.5e-5 mean=3.4e-5 variance=6.924999999999999e-10 stddev=2.631539473388153e-5 [INFO] [stdout] 2025-10-16T10:48:46.812346Z TRACE timesimp: eliminated outliers inliers=[4.5e-5, 5.5e-5, 3e-5, 5e-5] [INFO] [stdout] 2025-10-16T10:48:46.812349Z DEBUG timesimp: storing calculated offset offset=0s [INFO] [stdout] test null_offset ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.68s [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" "7d2cf679efd4e8d43878302d0ffa8fc23a9036e416e05ec5fb61d08d018fadd5", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "7d2cf679efd4e8d43878302d0ffa8fc23a9036e416e05ec5fb61d08d018fadd5", kill_on_drop: false }` [INFO] [stdout] 7d2cf679efd4e8d43878302d0ffa8fc23a9036e416e05ec5fb61d08d018fadd5