[INFO] fetching crate timesimp 1.0.0... [INFO] testing timesimp-1.0.0 against beta-2025-09-21 for beta-1.91-3 [INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-5-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-5-tc2/source/Cargo.toml [INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain beta-2025-09-21 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-09-21" "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" "+beta-2025-09-21" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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" "+beta-2025-09-21" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 2d5a22f17f64a41c50404e05af7240b0c673be9a15cd38433551eb8d13c83b3c [INFO] running `Command { std: "docker" "start" "-a" "2d5a22f17f64a41c50404e05af7240b0c673be9a15cd38433551eb8d13c83b3c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "2d5a22f17f64a41c50404e05af7240b0c673be9a15cd38433551eb8d13c83b3c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "2d5a22f17f64a41c50404e05af7240b0c673be9a15cd38433551eb8d13c83b3c", kill_on_drop: false }` [INFO] [stdout] 2d5a22f17f64a41c50404e05af7240b0c673be9a15cd38433551eb8d13c83b3c [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=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" "+beta-2025-09-21" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] bf0b6b4a8ebb1e257f8ffce514f948fafb7999685f3221fdeeb40cacca777f4e [INFO] running `Command { std: "docker" "start" "-a" "bf0b6b4a8ebb1e257f8ffce514f948fafb7999685f3221fdeeb40cacca777f4e", 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 thiserror v2.0.12 [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 timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 8.49s [INFO] running `Command { std: "docker" "inspect" "bf0b6b4a8ebb1e257f8ffce514f948fafb7999685f3221fdeeb40cacca777f4e", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "bf0b6b4a8ebb1e257f8ffce514f948fafb7999685f3221fdeeb40cacca777f4e", kill_on_drop: false }` [INFO] [stdout] bf0b6b4a8ebb1e257f8ffce514f948fafb7999685f3221fdeeb40cacca777f4e [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=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" "+beta-2025-09-21" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] db07250f0b5bad41ada812790c96d4717456ee8463b4013623bb2e99592e4e78 [INFO] running `Command { std: "docker" "start" "-a" "db07250f0b5bad41ada812790c96d4717456ee8463b4013623bb2e99592e4e78", 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 icu_locid_transform_data v1.5.1 [INFO] [stderr] Compiling litemap v0.7.5 [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 signal-hook-registry v1.4.5 [INFO] [stderr] Compiling socket2 v0.5.9 [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 rand_core v0.9.3 [INFO] [stderr] Compiling parking_lot_core v0.9.10 [INFO] [stderr] Compiling serde_urlencoded v0.7.1 [INFO] [stderr] Compiling thread_local v1.1.8 [INFO] [stderr] Compiling rand_chacha v0.9.0 [INFO] [stderr] Compiling parking_lot v0.12.3 [INFO] [stderr] Compiling rustls-pemfile v2.2.0 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling rand v0.9.1 [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 tracing v0.1.41 [INFO] [stderr] Compiling zerofrom v0.1.6 [INFO] [stderr] Compiling yoke v0.7.5 [INFO] [stderr] Compiling zerovec v0.10.4 [INFO] [stderr] Compiling thiserror v2.0.12 [INFO] [stderr] Compiling timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Compiling tinystr v0.7.6 [INFO] [stderr] Compiling icu_collections v1.5.0 [INFO] [stderr] Compiling icu_locid v1.5.0 [INFO] [stderr] Compiling icu_provider v1.5.0 [INFO] [stderr] Compiling icu_locid_transform v1.5.0 [INFO] [stderr] Compiling icu_properties v1.5.1 [INFO] [stderr] Compiling tokio-util v0.7.15 [INFO] [stderr] Compiling tokio-native-tls v0.3.1 [INFO] [stderr] Compiling tower v0.5.2 [INFO] [stderr] Compiling h2 v0.4.9 [INFO] [stderr] Compiling icu_normalizer v1.5.0 [INFO] [stderr] Compiling idna_adapter v1.2.0 [INFO] [stderr] Compiling idna v1.0.3 [INFO] [stderr] Compiling url v2.5.4 [INFO] [stderr] Compiling hyper v1.6.0 [INFO] [stderr] Compiling hyper-util v0.1.11 [INFO] [stderr] Compiling hyper-tls v0.6.0 [INFO] [stderr] Compiling reqwest v0.12.15 [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 37.55s [INFO] running `Command { std: "docker" "inspect" "db07250f0b5bad41ada812790c96d4717456ee8463b4013623bb2e99592e4e78", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "db07250f0b5bad41ada812790c96d4717456ee8463b4013623bb2e99592e4e78", kill_on_drop: false }` [INFO] [stdout] db07250f0b5bad41ada812790c96d4717456ee8463b4013623bb2e99592e4e78 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=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" "+beta-2025-09-21" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 53cd0f5c84f77436660a7b8c67cf5357709bfbfff2dabd0289c93f3b07492321 [INFO] running `Command { std: "docker" "start" "-a" "53cd0f5c84f77436660a7b8c67cf5357709bfbfff2dabd0289c93f3b07492321", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.25s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-f5a7014f299f61aa) [INFO] [stdout] [INFO] [stdout] running 5 tests [INFO] [stdout] test delta::tests::client_ahead_of_server ... ok [INFO] [stdout] test delta::tests::client_behind_server ... ok [INFO] [stdout] test delta::tests::clock_went_backwards ... ok [INFO] [stdout] test delta::tests::client_equal_server ... ok [INFO] [stdout] test delta::tests::with_sleep ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s [INFO] [stdout] [INFO] [stderr] Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-97779c68f75e8a0a) [INFO] [stdout] [INFO] [stdout] running 10 tests [INFO] [stdout] 2025-10-01T14:17:30.665852Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-10-01T14:17:30.665922Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.665941Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.665950Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.666147Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.666222Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.666243Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-10-01T14:17:30.666349Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.666535Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.666664Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.666802Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.666860Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.667387Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.667982Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.668051Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.668074Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.668372Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.668407Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.668366Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:30.669204Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.685517Z TRACE new{response=Response { client: 2025-10-01T14:17:30.667972211Z, server: 2025-10-01T14:17:35.67714758Z } current=2025-10-01T14:17:30.685311319Z}: timesimp::delta: response processing internals latency=8ms 669µs 554ns local_at_midpoint=2025-10-01T14:17:30.676641765Z delta=5s 505µs 815ns [INFO] [stdout] 2025-10-01T14:17:30.685723Z TRACE timesimp: obtained raw offset from server latency=8.669554ms delta=5s 505µs 815ns [INFO] [stdout] 2025-10-01T14:17:30.685800Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 505µs 815ns [INFO] [stdout] 2025-10-01T14:17:30.685835Z TRACE timesimp: sleeping to spread out requests delay=1.191213279s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.689580Z TRACE new{response=Response { client: 2025-10-01T14:17:30.667132631Z, server: 2025-10-01T14:17:30.67826502Z } current=2025-10-01T14:17:30.689416098Z}: timesimp::delta: response processing internals latency=11ms 141µs 733ns local_at_midpoint=2025-10-01T14:17:30.678274364Z delta=9µs 344ns ago [INFO] [stdout] 2025-10-01T14:17:30.689673Z TRACE timesimp: obtained raw offset from server latency=11.141733ms delta=9µs 344ns ago [INFO] [stdout] 2025-10-01T14:17:30.689691Z TRACE timesimp: sleeping to spread out requests delay=1.191173581s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.689790Z TRACE new{response=Response { client: 2025-10-01T14:17:30.667168761Z, server: 2025-10-01T14:17:35.67844468Z } current=2025-10-01T14:17:30.689570028Z}: timesimp::delta: response processing internals latency=11ms 200µs 633ns local_at_midpoint=2025-10-01T14:17:30.678369394Z delta=5s 75µs 286ns [INFO] [stdout] 2025-10-01T14:17:30.689959Z TRACE timesimp: obtained raw offset from server latency=11.200633ms delta=5s 75µs 286ns [INFO] [stdout] 2025-10-01T14:17:30.690119Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 75µs 286ns [INFO] [stdout] 2025-10-01T14:17:30.690238Z TRACE timesimp: sleeping to spread out requests delay=1.053946742s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.690455Z TRACE new{response=Response { client: 2025-10-01T14:17:30.667684991Z, server: 2025-10-01T14:17:30.67880161Z } current=2025-10-01T14:17:30.690057568Z}: timesimp::delta: response processing internals latency=11ms 186µs 288ns local_at_midpoint=2025-10-01T14:17:30.678871279Z delta=69µs 669ns ago [INFO] [stdout] 2025-10-01T14:17:30.690585Z TRACE timesimp: obtained raw offset from server latency=11.186288ms delta=69µs 669ns ago [INFO] [stdout] 2025-10-01T14:17:30.690687Z TRACE timesimp: sleeping to spread out requests delay=1.510299079s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.691783Z TRACE new{response=Response { client: 2025-10-01T14:17:30.669304241Z, server: 2025-10-01T14:17:25.680430249Z } current=2025-10-01T14:17:30.691668248Z}: timesimp::delta: response processing internals latency=11ms 182µs 3ns local_at_midpoint=2025-10-01T14:17:30.680486244Z delta=5s 55µs 995ns ago [INFO] [stdout] 2025-10-01T14:17:30.692904Z TRACE new{response=Response { client: 2025-10-01T14:17:30.6703829Z, server: 2025-10-01T14:17:35.681509099Z } current=2025-10-01T14:17:30.692805698Z}: timesimp::delta: response processing internals latency=11ms 211µs 399ns local_at_midpoint=2025-10-01T14:17:30.681594299Z delta=4s 999ms 914µs 800ns [INFO] [stdout] 2025-10-01T14:17:30.693662Z TRACE timesimp: obtained raw offset from server latency=11.182003ms delta=5s 55µs 995ns ago [INFO] [stdout] 2025-10-01T14:17:30.693781Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 55µs 995ns ago [INFO] [stdout] 2025-10-01T14:17:30.693819Z TRACE timesimp: sleeping to spread out requests delay=782.292055ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.693755Z TRACE timesimp: obtained raw offset from server latency=11.211399ms delta=4s 999ms 914µs 800ns [INFO] [stdout] 2025-10-01T14:17:30.693930Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 914µs 800ns [INFO] [stdout] 2025-10-01T14:17:30.693972Z TRACE timesimp: sleeping to spread out requests delay=1.042553088s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.695099Z TRACE new{response=Response { client: 2025-10-01T14:17:30.692728688Z, server: 2025-10-01T14:17:30.693857618Z } current=2025-10-01T14:17:30.694978758Z}: timesimp::delta: response processing internals latency=1ms 125µs 35ns local_at_midpoint=2025-10-01T14:17:30.693853723Z delta=3µs 895ns [INFO] [stdout] 2025-10-01T14:17:30.695201Z TRACE timesimp: obtained raw offset from server latency=1.125035ms delta=3µs 895ns [INFO] [stdout] 2025-10-01T14:17:30.695246Z DEBUG timesimp: no offset stored, storing initial delta offset=3µs 895ns [INFO] [stdout] 2025-10-01T14:17:30.695280Z TRACE timesimp: sleeping to spread out requests delay=257.804141ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.701584Z TRACE new{response=Response { client: 2025-10-01T14:17:30.669176751Z, server: 2025-10-01T14:17:35.682674379Z } current=2025-10-01T14:17:30.701374807Z}: timesimp::delta: response processing internals latency=16ms 99µs 28ns local_at_midpoint=2025-10-01T14:17:30.685275779Z delta=4s 997ms 398µs 600ns [INFO] [stdout] 2025-10-01T14:17:30.701802Z TRACE timesimp: obtained raw offset from server latency=16.099028ms delta=4s 997ms 398µs 600ns [INFO] [stdout] 2025-10-01T14:17:30.701832Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 997ms 398µs 600ns [INFO] [stdout] 2025-10-01T14:17:30.701844Z TRACE timesimp: sleeping to spread out requests delay=229.556836ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.872521Z TRACE new{response=Response { client: 2025-10-01T14:17:30.669559161Z, server: 2025-10-01T14:17:30.770906439Z } current=2025-10-01T14:17:30.872299457Z}: timesimp::delta: response processing internals latency=101ms 370µs 148ns local_at_midpoint=2025-10-01T14:17:30.770929309Z delta=22µs 870ns ago [INFO] [stdout] 2025-10-01T14:17:30.872612Z TRACE timesimp: obtained raw offset from server latency=101.370148ms delta=22µs 870ns ago [INFO] [stdout] 2025-10-01T14:17:30.872658Z DEBUG timesimp: no offset stored, storing initial delta offset=22µs 870ns ago [INFO] [stdout] 2025-10-01T14:17:30.872671Z TRACE timesimp: sleeping to spread out requests delay=1.977256537s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.952018Z TRACE new{response=Response { client: 2025-10-01T14:17:30.93338367Z, server: 2025-10-01T14:17:35.942595529Z } current=2025-10-01T14:17:30.951828568Z}: timesimp::delta: response processing internals latency=9ms 222µs 449ns local_at_midpoint=2025-10-01T14:17:30.942606119Z delta=4s 999ms 989µs 410ns [INFO] [stdout] 2025-10-01T14:17:30.952185Z TRACE timesimp: obtained raw offset from server latency=9.222449ms delta=4s 999ms 989µs 410ns [INFO] [stdout] 2025-10-01T14:17:30.952279Z TRACE timesimp: sleeping to spread out requests delay=1.387187865s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:30.957608Z TRACE new{response=Response { client: 2025-10-01T14:17:30.955155188Z, server: 2025-10-01T14:17:30.956304518Z } current=2025-10-01T14:17:30.957434418Z}: timesimp::delta: response processing internals latency=1ms 139µs 615ns local_at_midpoint=2025-10-01T14:17:30.956294803Z delta=9µs 715ns [INFO] [stdout] 2025-10-01T14:17:30.957799Z TRACE timesimp: obtained raw offset from server latency=1.139615ms delta=9µs 715ns [INFO] [stdout] 2025-10-01T14:17:30.957850Z TRACE timesimp: sleeping to spread out requests delay=1.593177941s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:31.504216Z TRACE new{response=Response { client: 2025-10-01T14:17:31.479739957Z, server: 2025-10-01T14:17:26.492739685Z } current=2025-10-01T14:17:31.504056304Z}: timesimp::delta: response processing internals latency=12ms 158µs 173ns local_at_midpoint=2025-10-01T14:17:31.49189813Z delta=4s 999ms 158µs 445ns ago [INFO] [stdout] 2025-10-01T14:17:31.504294Z TRACE timesimp: obtained raw offset from server latency=12.158173ms delta=4s 999ms 158µs 445ns ago [INFO] [stdout] 2025-10-01T14:17:31.504311Z TRACE timesimp: sleeping to spread out requests delay=1.552734359s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:31.769276Z TRACE new{response=Response { client: 2025-10-01T14:17:31.747675286Z, server: 2025-10-01T14:17:36.758940515Z } current=2025-10-01T14:17:31.769116793Z}: timesimp::delta: response processing internals latency=10ms 720µs 753ns local_at_midpoint=2025-10-01T14:17:31.758396039Z delta=5s 544µs 476ns [INFO] [stdout] 2025-10-01T14:17:31.769276Z TRACE new{response=Response { client: 2025-10-01T14:17:31.746750846Z, server: 2025-10-01T14:17:36.758026335Z } current=2025-10-01T14:17:31.769170973Z}: timesimp::delta: response processing internals latency=11ms 210µs 63ns local_at_midpoint=2025-10-01T14:17:31.757960909Z delta=5s 65µs 426ns [INFO] [stdout] 2025-10-01T14:17:31.769360Z TRACE timesimp: obtained raw offset from server latency=10.720753ms delta=5s 544µs 476ns [INFO] [stdout] 2025-10-01T14:17:31.769379Z TRACE timesimp: sleeping to spread out requests delay=22.404869ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:31.769381Z TRACE timesimp: obtained raw offset from server latency=11.210063ms delta=5s 65µs 426ns [INFO] [stdout] 2025-10-01T14:17:31.769398Z TRACE timesimp: sleeping to spread out requests delay=277.485866ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:31.815074Z TRACE new{response=Response { client: 2025-10-01T14:17:31.792578151Z, server: 2025-10-01T14:17:36.80372578Z } current=2025-10-01T14:17:31.814912858Z}: timesimp::delta: response processing internals latency=11ms 167µs 353ns local_at_midpoint=2025-10-01T14:17:31.803745504Z delta=4s 999ms 980µs 276ns [INFO] [stdout] 2025-10-01T14:17:31.815150Z TRACE timesimp: obtained raw offset from server latency=11.167353ms delta=4s 999ms 980µs 276ns [INFO] [stdout] 2025-10-01T14:17:31.815198Z TRACE timesimp: sleeping to spread out requests delay=296.095873ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:31.905249Z TRACE new{response=Response { client: 2025-10-01T14:17:31.882730151Z, server: 2025-10-01T14:17:31.893879869Z } current=2025-10-01T14:17:31.905072368Z}: timesimp::delta: response processing internals latency=11ms 171µs 108ns local_at_midpoint=2025-10-01T14:17:31.893901259Z delta=21µs 390ns ago [INFO] [stdout] 2025-10-01T14:17:31.905345Z TRACE timesimp: obtained raw offset from server latency=11.171108ms delta=21µs 390ns ago [INFO] [stdout] 2025-10-01T14:17:31.905376Z TRACE timesimp: sleeping to spread out requests delay=598.404955ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:31.918896Z TRACE new{response=Response { client: 2025-10-01T14:17:31.892724209Z, server: 2025-10-01T14:17:36.907693557Z } current=2025-10-01T14:17:31.918720376Z}: timesimp::delta: response processing internals latency=12ms 998µs 83ns local_at_midpoint=2025-10-01T14:17:31.905722292Z delta=5s 1ms 971µs 265ns [INFO] [stdout] 2025-10-01T14:17:31.918981Z TRACE timesimp: obtained raw offset from server latency=12.998083ms delta=5s 1ms 971µs 265ns [INFO] [stdout] 2025-10-01T14:17:31.919000Z TRACE timesimp: sleeping to spread out requests delay=1.793035857s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.070440Z TRACE new{response=Response { client: 2025-10-01T14:17:32.047874791Z, server: 2025-10-01T14:17:37.05906975Z } current=2025-10-01T14:17:32.070261899Z}: timesimp::delta: response processing internals latency=11ms 193µs 554ns local_at_midpoint=2025-10-01T14:17:32.059068345Z delta=5s 1µs 405ns [INFO] [stdout] 2025-10-01T14:17:32.070527Z TRACE timesimp: obtained raw offset from server latency=11.193554ms delta=5s 1µs 405ns [INFO] [stdout] 2025-10-01T14:17:32.070547Z TRACE timesimp: sleeping to spread out requests delay=1.31806506s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.134315Z TRACE new{response=Response { client: 2025-10-01T14:17:32.112735164Z, server: 2025-10-01T14:17:37.123946852Z } current=2025-10-01T14:17:32.134143931Z}: timesimp::delta: response processing internals latency=10ms 704µs 383ns local_at_midpoint=2025-10-01T14:17:32.123439547Z delta=5s 507µs 305ns [INFO] [stdout] 2025-10-01T14:17:32.134416Z TRACE timesimp: obtained raw offset from server latency=10.704383ms delta=5s 507µs 305ns [INFO] [stdout] 2025-10-01T14:17:32.134436Z TRACE timesimp: sleeping to spread out requests delay=632.142164ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.225301Z TRACE new{response=Response { client: 2025-10-01T14:17:32.202732663Z, server: 2025-10-01T14:17:32.213928452Z } current=2025-10-01T14:17:32.225125231Z}: timesimp::delta: response processing internals latency=11ms 196µs 284ns local_at_midpoint=2025-10-01T14:17:32.213928947Z delta=495ns ago [INFO] [stdout] 2025-10-01T14:17:32.225393Z TRACE timesimp: obtained raw offset from server latency=11.196284ms delta=495ns ago [INFO] [stdout] 2025-10-01T14:17:32.225413Z TRACE timesimp: sleeping to spread out requests delay=761.490552ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.357346Z TRACE new{response=Response { client: 2025-10-01T14:17:32.342748907Z, server: 2025-10-01T14:17:37.349969176Z } current=2025-10-01T14:17:32.357175696Z}: timesimp::delta: response processing internals latency=7ms 213µs 394ns local_at_midpoint=2025-10-01T14:17:32.349962301Z delta=5s 6µs 875ns [INFO] [stdout] 2025-10-01T14:17:32.357445Z TRACE timesimp: obtained raw offset from server latency=7.213394ms delta=5s 6µs 875ns [INFO] [stdout] 2025-10-01T14:17:32.357463Z TRACE timesimp: sleeping to spread out requests delay=1.838692227s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.506894Z TRACE new{response=Response { client: 2025-10-01T14:17:30.666990901Z, server: 2025-10-01T14:17:31.584867205Z } current=2025-10-01T14:17:32.506697858Z}: timesimp::delta: response processing internals latency=919ms 853µs 478ns local_at_midpoint=2025-10-01T14:17:31.586844379Z delta=1ms 977µs 174ns ago [INFO] [stdout] 2025-10-01T14:17:32.506977Z TRACE timesimp: obtained raw offset from server latency=919.853478ms delta=1ms 977µs 174ns ago [INFO] [stdout] 2025-10-01T14:17:32.506994Z DEBUG timesimp: no offset stored, storing initial delta offset=1ms 977µs 174ns ago [INFO] [stdout] 2025-10-01T14:17:32.507004Z TRACE timesimp: sleeping to spread out requests delay=859.976651ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.527660Z TRACE new{response=Response { client: 2025-10-01T14:17:32.504882859Z, server: 2025-10-01T14:17:32.516099097Z } current=2025-10-01T14:17:32.527453256Z}: timesimp::delta: response processing internals latency=11ms 285µs 198ns local_at_midpoint=2025-10-01T14:17:32.516168057Z delta=68µs 960ns ago [INFO] [stdout] 2025-10-01T14:17:32.527761Z TRACE timesimp: obtained raw offset from server latency=11.285198ms delta=68µs 960ns ago [INFO] [stdout] 2025-10-01T14:17:32.527784Z TRACE timesimp: sleeping to spread out requests delay=1.600550132s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.555290Z TRACE new{response=Response { client: 2025-10-01T14:17:32.552851163Z, server: 2025-10-01T14:17:32.554003963Z } current=2025-10-01T14:17:32.555135293Z}: timesimp::delta: response processing internals latency=1ms 142µs 65ns local_at_midpoint=2025-10-01T14:17:32.553993228Z delta=10µs 735ns [INFO] [stdout] 2025-10-01T14:17:32.555453Z TRACE timesimp: obtained raw offset from server latency=1.142065ms delta=10µs 735ns [INFO] [stdout] 2025-10-01T14:17:32.555519Z TRACE timesimp: sleeping to spread out requests delay=1.466575238s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:32.789573Z TRACE new{response=Response { client: 2025-10-01T14:17:32.767931448Z, server: 2025-10-01T14:17:37.778155627Z } current=2025-10-01T14:17:32.789380395Z}: timesimp::delta: response processing internals latency=10ms 724µs 473ns local_at_midpoint=2025-10-01T14:17:32.778655921Z delta=4s 999ms 499µs 706ns [INFO] [stdout] 2025-10-01T14:17:32.789683Z TRACE timesimp: obtained raw offset from server latency=10.724473ms delta=4s 999ms 499µs 706ns [INFO] [stdout] 2025-10-01T14:17:32.789715Z TRACE timesimp: response deltas sorted by latency deltas=[5000.507305, 5000.544476, 4999.499706, 4999.980276, 5000.075286] [INFO] [stdout] 2025-10-01T14:17:32.789729Z TRACE timesimp: statistics about response deltas median=4999.499706 mean=5000.1214098 variance=0.18411547108232454 stddev=0.42908678735463823 [INFO] [stdout] 2025-10-01T14:17:32.789747Z TRACE timesimp: eliminated outliers inliers=[4999.499706] [INFO] [stdout] 2025-10-01T14:17:32.789757Z DEBUG timesimp: storing calculated offset offset=4s 999ms 499µs [INFO] [stdout] test low_jitter ... ok [INFO] [stdout] 2025-10-01T14:17:33.019892Z TRACE new{response=Response { client: 2025-10-01T14:17:32.990729072Z, server: 2025-10-01T14:17:33.00573141Z } current=2025-10-01T14:17:33.019721989Z}: timesimp::delta: response processing internals latency=14ms 496µs 458ns local_at_midpoint=2025-10-01T14:17:33.00522553Z delta=505µs 880ns [INFO] [stdout] 2025-10-01T14:17:33.019980Z TRACE timesimp: obtained raw offset from server latency=14.496458ms delta=505µs 880ns [INFO] [stdout] 2025-10-01T14:17:33.019997Z TRACE timesimp: sleeping to spread out requests delay=154.988239ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:33.052851Z TRACE new{response=Response { client: 2025-10-01T14:17:32.850882859Z, server: 2025-10-01T14:17:32.952246937Z } current=2025-10-01T14:17:33.052661085Z}: timesimp::delta: response processing internals latency=100ms 889µs 113ns local_at_midpoint=2025-10-01T14:17:32.951771972Z delta=474µs 965ns [INFO] [stdout] 2025-10-01T14:17:33.052952Z TRACE timesimp: obtained raw offset from server latency=100.889113ms delta=474µs 965ns [INFO] [stdout] 2025-10-01T14:17:33.052976Z TRACE timesimp: sleeping to spread out requests delay=1.035990738s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:33.081418Z TRACE new{response=Response { client: 2025-10-01T14:17:33.058837344Z, server: 2025-10-01T14:17:28.070037453Z } current=2025-10-01T14:17:33.081244882Z}: timesimp::delta: response processing internals latency=11ms 203µs 769ns local_at_midpoint=2025-10-01T14:17:33.070041113Z delta=5s 3µs 660ns ago [INFO] [stdout] 2025-10-01T14:17:33.081511Z TRACE timesimp: obtained raw offset from server latency=11.203769ms delta=5s 3µs 660ns ago [INFO] [stdout] 2025-10-01T14:17:33.081533Z TRACE timesimp: sleeping to spread out requests delay=734.881951ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:33.216902Z TRACE new{response=Response { client: 2025-10-01T14:17:33.18272774Z, server: 2025-10-01T14:17:33.199721488Z } current=2025-10-01T14:17:33.216726166Z}: timesimp::delta: response processing internals latency=16ms 999µs 213ns local_at_midpoint=2025-10-01T14:17:33.199726953Z delta=5µs 465ns ago [INFO] [stdout] 2025-10-01T14:17:33.216996Z TRACE timesimp: obtained raw offset from server latency=16.999213ms delta=5µs 465ns ago [INFO] [stdout] 2025-10-01T14:17:33.217014Z TRACE timesimp: sleeping to spread out requests delay=614.872592ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:33.412430Z TRACE new{response=Response { client: 2025-10-01T14:17:33.389849096Z, server: 2025-10-01T14:17:38.401044475Z } current=2025-10-01T14:17:33.412242834Z}: timesimp::delta: response processing internals latency=11ms 196µs 869ns local_at_midpoint=2025-10-01T14:17:33.401045965Z delta=4s 999ms 998µs 510ns [INFO] [stdout] 2025-10-01T14:17:33.412523Z TRACE timesimp: obtained raw offset from server latency=11.196869ms delta=4s 999ms 998µs 510ns [INFO] [stdout] 2025-10-01T14:17:33.412545Z TRACE timesimp: sleeping to spread out requests delay=1.635747238s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:33.734448Z TRACE new{response=Response { client: 2025-10-01T14:17:33.712861199Z, server: 2025-10-01T14:17:38.724054318Z } current=2025-10-01T14:17:33.734258076Z}: timesimp::delta: response processing internals latency=10ms 698µs 438ns local_at_midpoint=2025-10-01T14:17:33.723559637Z delta=5s 494µs 681ns [INFO] [stdout] 2025-10-01T14:17:33.734548Z TRACE timesimp: obtained raw offset from server latency=10.698438ms delta=5s 494µs 681ns [INFO] [stdout] 2025-10-01T14:17:33.734572Z TRACE timesimp: sleeping to spread out requests delay=252.390264ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:33.840404Z TRACE new{response=Response { client: 2025-10-01T14:17:33.817850527Z, server: 2025-10-01T14:17:28.829040455Z } current=2025-10-01T14:17:33.840238904Z}: timesimp::delta: response processing internals latency=11ms 194µs 188ns local_at_midpoint=2025-10-01T14:17:33.829044715Z delta=5s 4µs 260ns ago [INFO] [stdout] 2025-10-01T14:17:33.840496Z TRACE timesimp: obtained raw offset from server latency=11.194188ms delta=5s 4µs 260ns ago [INFO] [stdout] 2025-10-01T14:17:33.840516Z TRACE timesimp: sleeping to spread out requests delay=814.930841ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:33.855420Z TRACE new{response=Response { client: 2025-10-01T14:17:33.832863605Z, server: 2025-10-01T14:17:33.844046404Z } current=2025-10-01T14:17:33.855240352Z}: timesimp::delta: response processing internals latency=11ms 188µs 373ns local_at_midpoint=2025-10-01T14:17:33.844051978Z delta=5µs 574ns ago [INFO] [stdout] 2025-10-01T14:17:33.855509Z TRACE timesimp: obtained raw offset from server latency=11.188373ms delta=5µs 574ns ago [INFO] [stdout] 2025-10-01T14:17:33.855535Z TRACE timesimp: response deltas sorted by latency deltas=[-0.069669, -0.005574, -0.000495, 0.50588, -0.005465] [INFO] [stdout] 2025-10-01T14:17:33.855551Z TRACE timesimp: statistics about response deltas median=-0.000495 mean=0.08493540000000001 variance=0.056189853455300004 stddev=0.23704399054880088 [INFO] [stdout] 2025-10-01T14:17:33.855566Z TRACE timesimp: eliminated outliers inliers=[-0.069669, -0.005574, -0.000495, -0.005465] [INFO] [stdout] 2025-10-01T14:17:33.855577Z DEBUG timesimp: storing calculated offset offset=20µs ago [INFO] [stdout] test client_offset_negative ... ok [INFO] [stdout] 2025-10-01T14:17:34.000705Z TRACE new{response=Response { client: 2025-10-01T14:17:33.988118437Z, server: 2025-10-01T14:17:38.994317256Z } current=2025-10-01T14:17:34.000511026Z}: timesimp::delta: response processing internals latency=6ms 196µs 294ns local_at_midpoint=2025-10-01T14:17:33.994314731Z delta=5s 2µs 525ns [INFO] [stdout] 2025-10-01T14:17:34.000790Z TRACE timesimp: obtained raw offset from server latency=6.196294ms delta=5s 2µs 525ns [INFO] [stdout] 2025-10-01T14:17:34.000810Z TRACE timesimp: sleeping to spread out requests delay=467.007362ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:34.026323Z TRACE new{response=Response { client: 2025-10-01T14:17:34.023857783Z, server: 2025-10-01T14:17:34.025015763Z } current=2025-10-01T14:17:34.026159052Z}: timesimp::delta: response processing internals latency=1ms 150µs 634ns local_at_midpoint=2025-10-01T14:17:34.025008417Z delta=7µs 346ns [INFO] [stdout] 2025-10-01T14:17:34.026479Z TRACE timesimp: obtained raw offset from server latency=1.150634ms delta=7µs 346ns [INFO] [stdout] 2025-10-01T14:17:34.026527Z TRACE timesimp: sleeping to spread out requests delay=340.876237ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:34.151465Z TRACE new{response=Response { client: 2025-10-01T14:17:34.128889331Z, server: 2025-10-01T14:17:34.140090379Z } current=2025-10-01T14:17:34.151290128Z}: timesimp::delta: response processing internals latency=11ms 200µs 398ns local_at_midpoint=2025-10-01T14:17:34.140089729Z delta=650ns [INFO] [stdout] 2025-10-01T14:17:34.151553Z TRACE timesimp: obtained raw offset from server latency=11.200398ms delta=650ns [INFO] [stdout] 2025-10-01T14:17:34.151572Z TRACE timesimp: sleeping to spread out requests delay=1.771141549s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:34.220327Z TRACE new{response=Response { client: 2025-10-01T14:17:34.198708063Z, server: 2025-10-01T14:17:39.208921071Z } current=2025-10-01T14:17:34.22013679Z}: timesimp::delta: response processing internals latency=10ms 714µs 363ns local_at_midpoint=2025-10-01T14:17:34.209422426Z delta=4s 999ms 498µs 645ns [INFO] [stdout] 2025-10-01T14:17:34.220444Z TRACE timesimp: obtained raw offset from server latency=10.714363ms delta=4s 999ms 498µs 645ns [INFO] [stdout] 2025-10-01T14:17:34.220471Z TRACE timesimp: sleeping to spread out requests delay=1.034054015s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:34.291798Z TRACE new{response=Response { client: 2025-10-01T14:17:34.089870005Z, server: 2025-10-01T14:17:34.191210893Z } current=2025-10-01T14:17:34.291592282Z}: timesimp::delta: response processing internals latency=100ms 861µs 138ns local_at_midpoint=2025-10-01T14:17:34.190731143Z delta=479µs 750ns [INFO] [stdout] 2025-10-01T14:17:34.291894Z TRACE timesimp: obtained raw offset from server latency=100.861138ms delta=479µs 750ns [INFO] [stdout] 2025-10-01T14:17:34.291917Z TRACE timesimp: sleeping to spread out requests delay=16.1789ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:34.370404Z TRACE new{response=Response { client: 2025-10-01T14:17:34.367918903Z, server: 2025-10-01T14:17:34.369078673Z } current=2025-10-01T14:17:34.370219233Z}: timesimp::delta: response processing internals latency=1ms 150µs 165ns local_at_midpoint=2025-10-01T14:17:34.369069068Z delta=9µs 605ns [INFO] [stdout] 2025-10-01T14:17:34.370492Z TRACE timesimp: obtained raw offset from server latency=1.150165ms delta=9µs 605ns [INFO] [stdout] 2025-10-01T14:17:34.370516Z TRACE timesimp: response deltas sorted by latency deltas=[0.003895, 0.009715, 0.010735, 0.009605, 0.007346] [INFO] [stdout] 2025-10-01T14:17:34.370529Z TRACE timesimp: statistics about response deltas median=0.010735 mean=0.0082592 variance=7.485073199999999e-6 stddev=0.002735886181843097 [INFO] [stdout] 2025-10-01T14:17:34.370543Z TRACE timesimp: eliminated outliers inliers=[0.009715, 0.010735, 0.009605] [INFO] [stdout] 2025-10-01T14:17:34.370552Z DEBUG timesimp: storing calculated offset offset=10µs [INFO] [stdout] test no_delay ... ok [INFO] [stdout] 2025-10-01T14:17:34.487197Z TRACE new{response=Response { client: 2025-10-01T14:17:34.468581811Z, server: 2025-10-01T14:17:39.47781144Z } current=2025-10-01T14:17:34.487020169Z}: timesimp::delta: response processing internals latency=9ms 219µs 179ns local_at_midpoint=2025-10-01T14:17:34.47780099Z delta=5s 10µs 450ns [INFO] [stdout] 2025-10-01T14:17:34.487288Z TRACE timesimp: obtained raw offset from server latency=9.219179ms delta=5s 10µs 450ns [INFO] [stdout] 2025-10-01T14:17:34.487315Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002525, 5000.505815, 5000.01045, 5000.494681, 5001.971265] [INFO] [stdout] 2025-10-01T14:17:34.487329Z TRACE timesimp: statistics about response deltas median=5000.01045 mean=5000.5969472 variance=0.6512073965993685 stddev=0.806974223008002 [INFO] [stdout] 2025-10-01T14:17:34.487343Z TRACE timesimp: eliminated outliers inliers=[5000.002525, 5000.505815, 5000.01045, 5000.494681] [INFO] [stdout] 2025-10-01T14:17:34.487352Z DEBUG timesimp: storing calculated offset offset=5s 253µs [INFO] [stdout] test mid_jitter ... ok [INFO] [stdout] 2025-10-01T14:17:34.512889Z TRACE new{response=Response { client: 2025-10-01T14:17:34.3099488Z, server: 2025-10-01T14:17:34.411297688Z } current=2025-10-01T14:17:34.512707616Z}: timesimp::delta: response processing internals latency=101ms 379µs 408ns local_at_midpoint=2025-10-01T14:17:34.411328208Z delta=30µs 520ns ago [INFO] [stdout] 2025-10-01T14:17:34.512979Z TRACE timesimp: obtained raw offset from server latency=101.379408ms delta=30µs 520ns ago [INFO] [stdout] 2025-10-01T14:17:34.512998Z TRACE timesimp: sleeping to spread out requests delay=672.095408ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:34.681118Z TRACE new{response=Response { client: 2025-10-01T14:17:34.656893399Z, server: 2025-10-01T14:17:29.669741258Z } current=2025-10-01T14:17:34.680942887Z}: timesimp::delta: response processing internals latency=12ms 24µs 744ns local_at_midpoint=2025-10-01T14:17:34.668918143Z delta=4s 999ms 176µs 885ns ago [INFO] [stdout] 2025-10-01T14:17:34.681215Z TRACE timesimp: obtained raw offset from server latency=12.024744ms delta=4s 999ms 176µs 885ns ago [INFO] [stdout] 2025-10-01T14:17:34.681245Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.055995, -5000.00426, -5000.00366, -4999.176885, -4999.158445] [INFO] [stdout] 2025-10-01T14:17:34.681268Z TRACE timesimp: statistics about response deltas median=-5000.00366 mean=-4999.679849 variance=0.2191041976174763 stddev=0.4680856733734502 [INFO] [stdout] 2025-10-01T14:17:34.681299Z TRACE timesimp: eliminated outliers inliers=[-5000.055995, -5000.00426, -5000.00366] [INFO] [stdout] 2025-10-01T14:17:34.681312Z DEBUG timesimp: storing calculated offset offset=5s 21µs ago [INFO] [stdout] test server_offset_negative ... ok [INFO] [stdout] 2025-10-01T14:17:35.072827Z TRACE new{response=Response { client: 2025-10-01T14:17:35.050212094Z, server: 2025-10-01T14:17:40.061427463Z } current=2025-10-01T14:17:35.072655162Z}: timesimp::delta: response processing internals latency=11ms 221µs 534ns local_at_midpoint=2025-10-01T14:17:35.061433628Z delta=4s 999ms 993µs 835ns [INFO] [stdout] 2025-10-01T14:17:35.072922Z TRACE timesimp: obtained raw offset from server latency=11.221534ms delta=4s 999ms 993µs 835ns [INFO] [stdout] 2025-10-01T14:17:35.072951Z TRACE timesimp: response deltas sorted by latency deltas=[5000.001405, 4999.99851, 5000.065426, 4999.9148000000005, 4999.993835] [INFO] [stdout] 2025-10-01T14:17:35.072965Z TRACE timesimp: statistics about response deltas median=5000.065426 mean=4999.9947952 variance=0.002861588277685823 stddev=0.05349381532182784 [INFO] [stdout] 2025-10-01T14:17:35.072984Z TRACE timesimp: eliminated outliers inliers=[5000.065426] [INFO] [stdout] 2025-10-01T14:17:35.072993Z DEBUG timesimp: storing calculated offset offset=5s 65µs [INFO] [stdout] test server_offset_positive ... ok [INFO] [stdout] 2025-10-01T14:17:35.111981Z TRACE new{response=Response { client: 2025-10-01T14:17:33.369735168Z, server: 2025-10-01T14:17:34.240863368Z } current=2025-10-01T14:17:35.111815537Z}: timesimp::delta: response processing internals latency=871ms 40µs 184ns local_at_midpoint=2025-10-01T14:17:34.240775352Z delta=88µs 16ns [INFO] [stdout] 2025-10-01T14:17:35.112065Z TRACE timesimp: obtained raw offset from server latency=871.040184ms delta=88µs 16ns [INFO] [stdout] 2025-10-01T14:17:35.112083Z TRACE timesimp: sleeping to spread out requests delay=1.836280046s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:35.276299Z TRACE new{response=Response { client: 2025-10-01T14:17:35.261722169Z, server: 2025-10-01T14:17:40.268911889Z } current=2025-10-01T14:17:35.276111178Z}: timesimp::delta: response processing internals latency=7ms 194µs 504ns local_at_midpoint=2025-10-01T14:17:35.268916673Z delta=4s 999ms 995µs 216ns [INFO] [stdout] 2025-10-01T14:17:35.276390Z TRACE timesimp: obtained raw offset from server latency=7.194504ms delta=4s 999ms 995µs 216ns [INFO] [stdout] 2025-10-01T14:17:35.276416Z TRACE timesimp: response deltas sorted by latency deltas=[4999.995216, 5000.006875, 4999.98941, 4999.498645, 4997.3986] [INFO] [stdout] 2025-10-01T14:17:35.276431Z TRACE timesimp: statistics about response deltas median=4999.98941 mean=4999.3777492 variance=1.2707102014753735 stddev=1.1272578238696653 [INFO] [stdout] 2025-10-01T14:17:35.276446Z TRACE timesimp: eliminated outliers inliers=[4999.995216, 5000.006875, 4999.98941, 4999.498645] [INFO] [stdout] 2025-10-01T14:17:35.276456Z DEBUG timesimp: storing calculated offset offset=4s 999ms 872µs [INFO] [stdout] test high_jitter ... ok [INFO] [stdout] 2025-10-01T14:17:35.401705Z TRACE new{response=Response { client: 2025-10-01T14:17:35.185935108Z, server: 2025-10-01T14:17:35.300732645Z } current=2025-10-01T14:17:35.401515373Z}: timesimp::delta: response processing internals latency=107ms 790µs 132ns local_at_midpoint=2025-10-01T14:17:35.29372524Z delta=7ms 7µs 405ns [INFO] [stdout] 2025-10-01T14:17:35.401801Z TRACE timesimp: obtained raw offset from server latency=107.790132ms delta=7ms 7µs 405ns [INFO] [stdout] 2025-10-01T14:17:35.401828Z TRACE timesimp: response deltas sorted by latency deltas=[0.47975, 0.474965, -0.02287, -0.03052, 7.007405] [INFO] [stdout] 2025-10-01T14:17:35.401842Z TRACE timesimp: statistics about response deltas median=-0.02287 mean=1.581746 variance=9.262832278117502 stddev=3.043490147530874 [INFO] [stdout] 2025-10-01T14:17:35.401856Z TRACE timesimp: eliminated outliers inliers=[0.47975, 0.474965, -0.02287, -0.03052] [INFO] [stdout] 2025-10-01T14:17:35.401867Z DEBUG timesimp: storing calculated offset offset=225µs [INFO] [stdout] test some_delay ... ok [INFO] [stdout] 2025-10-01T14:17:35.946643Z TRACE new{response=Response { client: 2025-10-01T14:17:35.923903073Z, server: 2025-10-01T14:17:35.935133742Z } current=2025-10-01T14:17:35.946399981Z}: timesimp::delta: response processing internals latency=11ms 248µs 454ns local_at_midpoint=2025-10-01T14:17:35.935151527Z delta=17µs 785ns ago [INFO] [stdout] 2025-10-01T14:17:35.946748Z TRACE timesimp: obtained raw offset from server latency=11.248454ms delta=17µs 785ns ago [INFO] [stdout] 2025-10-01T14:17:35.946777Z TRACE timesimp: response deltas sorted by latency deltas=[-0.009344, -0.02139, 0.00065, -0.017785, -0.06896] [INFO] [stdout] 2025-10-01T14:17:35.946794Z TRACE timesimp: statistics about response deltas median=0.00065 mean=-0.0233658 variance=0.0007218124281999999 stddev=0.026866567108583112 [INFO] [stdout] 2025-10-01T14:17:35.946810Z TRACE timesimp: eliminated outliers inliers=[-0.009344, -0.02139, 0.00065, -0.017785] [INFO] [stdout] 2025-10-01T14:17:35.946821Z DEBUG timesimp: storing calculated offset offset=11µs ago [INFO] [stdout] test client_offset_positive ... ok [INFO] [stdout] 2025-10-01T14:17:38.618043Z TRACE new{response=Response { client: 2025-10-01T14:17:36.949862014Z, server: 2025-10-01T14:17:37.783876548Z } current=2025-10-01T14:17:38.617873001Z}: timesimp::delta: response processing internals latency=834ms 5µs 493ns local_at_midpoint=2025-10-01T14:17:37.783867507Z delta=9µs 41ns [INFO] [stdout] 2025-10-01T14:17:38.618132Z TRACE timesimp: obtained raw offset from server latency=834.005493ms delta=9µs 41ns [INFO] [stdout] 2025-10-01T14:17:38.618153Z TRACE timesimp: sleeping to spread out requests delay=43.749786ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:40.591992Z TRACE new{response=Response { client: 2025-10-01T14:17:38.663354926Z, server: 2025-10-01T14:17:39.627575095Z } current=2025-10-01T14:17:40.591830763Z}: timesimp::delta: response processing internals latency=964ms 237µs 918ns local_at_midpoint=2025-10-01T14:17:39.627592844Z delta=17µs 749ns ago [INFO] [stdout] 2025-10-01T14:17:40.592069Z TRACE timesimp: obtained raw offset from server latency=964.237918ms delta=17µs 749ns ago [INFO] [stdout] 2025-10-01T14:17:40.592087Z TRACE timesimp: sleeping to spread out requests delay=683.045428ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:42.927030Z TRACE new{response=Response { client: 2025-10-01T14:17:41.276856464Z, server: 2025-10-01T14:17:42.101848299Z } current=2025-10-01T14:17:42.926858053Z}: timesimp::delta: response processing internals latency=825ms 794ns local_at_midpoint=2025-10-01T14:17:42.101857258Z delta=8µs 959ns ago [INFO] [stdout] 2025-10-01T14:17:42.927123Z TRACE timesimp: obtained raw offset from server latency=825.000794ms delta=8µs 959ns ago [INFO] [stdout] 2025-10-01T14:17:42.927152Z TRACE timesimp: response deltas sorted by latency deltas=[-0.008959, 0.009041, 0.088016, -1.977174, -0.017749] [INFO] [stdout] 2025-10-01T14:17:42.927175Z TRACE timesimp: statistics about response deltas median=0.088016 mean=-0.381365 variance=0.7975611391925 stddev=0.8930627856945446 [INFO] [stdout] 2025-10-01T14:17:42.927192Z TRACE timesimp: eliminated outliers inliers=[-0.008959, 0.009041, 0.088016, -0.017749] [INFO] [stdout] 2025-10-01T14:17:42.927211Z DEBUG timesimp: storing calculated offset offset=17µ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 12.27s [INFO] [stdout] [INFO] [stderr] Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-f298847650626d21) [INFO] [stdout] [INFO] [stdout] running 4 tests [INFO] [stdout] 2025-10-01T14:17:42.941471Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-10-01T14:17:42.941475Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:42.941650Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:42.941632Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:42.943005Z TRACE new{response=Response { client: 2025-10-01T14:17:42.942859261Z, server: 2025-10-01T14:17:42.942871481Z } current=2025-10-01T14:17:42.942875101Z}: timesimp::delta: response processing internals latency=7µs 920ns local_at_midpoint=2025-10-01T14:17:42.942867181Z delta=4µs 300ns [INFO] [stdout] 2025-10-01T14:17:42.943073Z TRACE timesimp: obtained raw offset from server latency=7.92µs delta=4µs 300ns [INFO] [stdout] 2025-10-01T14:17:42.943090Z DEBUG timesimp: no offset stored, storing initial delta offset=4µs 300ns [INFO] [stdout] 2025-10-01T14:17:42.943112Z TRACE timesimp: sleeping to spread out requests delay=1.485699074s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:42.943006Z TRACE new{response=Response { client: 2025-10-01T14:17:42.942861021Z, server: 2025-10-01T14:17:37.942872241Z } current=2025-10-01T14:17:42.942875152Z}: timesimp::delta: response processing internals latency=7µs 65ns local_at_midpoint=2025-10-01T14:17:42.942868086Z delta=4s 999ms 995µs 845ns ago [INFO] [stdout] 2025-10-01T14:17:42.943180Z TRACE timesimp: obtained raw offset from server latency=7.065µs delta=4s 999ms 995µs 845ns ago [INFO] [stdout] 2025-10-01T14:17:42.943229Z TRACE timesimp: sleeping to spread out requests delay=771.417179ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:42.944835Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-01T14:17:42.944877Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:42.947913Z TRACE new{response=Response { client: 2025-10-01T14:17:42.947741661Z, server: 2025-10-01T14:17:42.947749141Z } current=2025-10-01T14:17:42.947752571Z}: timesimp::delta: response processing internals latency=5µs 455ns local_at_midpoint=2025-10-01T14:17:42.947747116Z delta=2µs 25ns [INFO] [stdout] 2025-10-01T14:17:42.947988Z TRACE timesimp: obtained raw offset from server latency=5.455µs delta=2µs 25ns [INFO] [stdout] 2025-10-01T14:17:42.948006Z TRACE timesimp: sleeping to spread out requests delay=1.588417128s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:42.957897Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-10-01T14:17:42.957962Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:43.018992Z TRACE new{response=Response { client: 2025-10-01T14:17:43.018793783Z, server: 2025-10-01T14:17:48.018804343Z } current=2025-10-01T14:17:43.018807953Z}: timesimp::delta: response processing internals latency=7µs 85ns local_at_midpoint=2025-10-01T14:17:43.018800868Z delta=5s 3µs 475ns [INFO] [stdout] 2025-10-01T14:17:43.019144Z TRACE timesimp: obtained raw offset from server latency=7.085µs delta=5s 3µs 475ns [INFO] [stdout] 2025-10-01T14:17:43.019191Z TRACE timesimp: sleeping to spread out requests delay=1.733489438s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:43.716020Z TRACE new{response=Response { client: 2025-10-01T14:17:43.715851242Z, server: 2025-10-01T14:17:38.715862222Z } current=2025-10-01T14:17:43.715866152Z}: timesimp::delta: response processing internals latency=7µs 455ns local_at_midpoint=2025-10-01T14:17:43.715858697Z delta=4s 999ms 996µs 475ns ago [INFO] [stdout] 2025-10-01T14:17:43.716107Z TRACE timesimp: obtained raw offset from server latency=7.455µs delta=4s 999ms 996µs 475ns ago [INFO] [stdout] 2025-10-01T14:17:43.716128Z TRACE timesimp: sleeping to spread out requests delay=1.396548709s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:44.430039Z TRACE new{response=Response { client: 2025-10-01T14:17:44.429860529Z, server: 2025-10-01T14:17:44.42987554Z } current=2025-10-01T14:17:44.429875009Z}: timesimp::delta: response processing internals latency=7µs 240ns local_at_midpoint=2025-10-01T14:17:44.429867769Z delta=7µs 771ns [INFO] [stdout] 2025-10-01T14:17:44.430116Z TRACE timesimp: obtained raw offset from server latency=7.24µs delta=7µs 771ns [INFO] [stdout] 2025-10-01T14:17:44.430131Z TRACE timesimp: sleeping to spread out requests delay=69.920096ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:44.500681Z TRACE new{response=Response { client: 2025-10-01T14:17:44.500477341Z, server: 2025-10-01T14:17:44.500491571Z } current=2025-10-01T14:17:44.500490921Z}: timesimp::delta: response processing internals latency=6µs 790ns local_at_midpoint=2025-10-01T14:17:44.500484131Z delta=7µs 440ns [INFO] [stdout] 2025-10-01T14:17:44.500759Z TRACE timesimp: obtained raw offset from server latency=6.79µs delta=7µs 440ns [INFO] [stdout] 2025-10-01T14:17:44.500774Z TRACE timesimp: sleeping to spread out requests delay=1.821845735s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:44.538041Z TRACE new{response=Response { client: 2025-10-01T14:17:44.537867957Z, server: 2025-10-01T14:17:44.537878937Z } current=2025-10-01T14:17:44.537883457Z}: timesimp::delta: response processing internals latency=7µs 750ns local_at_midpoint=2025-10-01T14:17:44.537875707Z delta=3µs 230ns [INFO] [stdout] 2025-10-01T14:17:44.538124Z TRACE timesimp: obtained raw offset from server latency=7.75µs delta=3µs 230ns [INFO] [stdout] 2025-10-01T14:17:44.538141Z TRACE timesimp: sleeping to spread out requests delay=60.616755ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:44.600798Z TRACE new{response=Response { client: 2025-10-01T14:17:44.60057119Z, server: 2025-10-01T14:17:44.60058146Z } current=2025-10-01T14:17:44.60058527Z}: timesimp::delta: response processing internals latency=7µs 40ns local_at_midpoint=2025-10-01T14:17:44.60057823Z delta=3µs 230ns [INFO] [stdout] 2025-10-01T14:17:44.600894Z TRACE timesimp: obtained raw offset from server latency=7.04µs delta=3µs 230ns [INFO] [stdout] 2025-10-01T14:17:44.600916Z TRACE timesimp: sleeping to spread out requests delay=876.02795ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:44.756899Z TRACE new{response=Response { client: 2025-10-01T14:17:44.756727672Z, server: 2025-10-01T14:17:49.756736962Z } current=2025-10-01T14:17:44.756740572Z}: timesimp::delta: response processing internals latency=6µs 450ns local_at_midpoint=2025-10-01T14:17:44.756734122Z delta=5s 2µs 840ns [INFO] [stdout] 2025-10-01T14:17:44.757168Z TRACE timesimp: obtained raw offset from server latency=6.45µs delta=5s 2µs 840ns [INFO] [stdout] 2025-10-01T14:17:44.757236Z TRACE timesimp: sleeping to spread out requests delay=661.187973ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:45.114049Z TRACE new{response=Response { client: 2025-10-01T14:17:45.11387816Z, server: 2025-10-01T14:17:40.11388883Z } current=2025-10-01T14:17:45.11389273Z}: timesimp::delta: response processing internals latency=7µs 285ns local_at_midpoint=2025-10-01T14:17:45.113885445Z delta=4s 999ms 996µs 615ns ago [INFO] [stdout] 2025-10-01T14:17:45.114135Z TRACE timesimp: obtained raw offset from server latency=7.285µs delta=4s 999ms 996µs 615ns ago [INFO] [stdout] 2025-10-01T14:17:45.114153Z TRACE timesimp: sleeping to spread out requests delay=21.457953ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:45.136663Z TRACE new{response=Response { client: 2025-10-01T14:17:45.136471718Z, server: 2025-10-01T14:17:40.136481888Z } current=2025-10-01T14:17:45.136486238Z}: timesimp::delta: response processing internals latency=7µs 260ns local_at_midpoint=2025-10-01T14:17:45.136478978Z delta=4s 999ms 997µs 90ns ago [INFO] [stdout] 2025-10-01T14:17:45.136747Z TRACE timesimp: obtained raw offset from server latency=7.26µs delta=4s 999ms 997µs 90ns ago [INFO] [stdout] 2025-10-01T14:17:45.136766Z TRACE timesimp: sleeping to spread out requests delay=1.857560172s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:45.420145Z TRACE new{response=Response { client: 2025-10-01T14:17:45.419970105Z, server: 2025-10-01T14:17:50.419980695Z } current=2025-10-01T14:17:45.419984635Z}: timesimp::delta: response processing internals latency=7µs 265ns local_at_midpoint=2025-10-01T14:17:45.41997737Z delta=5s 3µs 325ns [INFO] [stdout] 2025-10-01T14:17:45.420226Z TRACE timesimp: obtained raw offset from server latency=7.265µs delta=5s 3µs 325ns [INFO] [stdout] 2025-10-01T14:17:45.420245Z TRACE timesimp: sleeping to spread out requests delay=1.030028111s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:45.479034Z TRACE new{response=Response { client: 2025-10-01T14:17:45.478864048Z, server: 2025-10-01T14:17:45.478873518Z } current=2025-10-01T14:17:45.478877478Z}: timesimp::delta: response processing internals latency=6µs 715ns local_at_midpoint=2025-10-01T14:17:45.478870763Z delta=2µs 755ns [INFO] [stdout] 2025-10-01T14:17:45.479119Z TRACE timesimp: obtained raw offset from server latency=6.715µs delta=2µs 755ns [INFO] [stdout] 2025-10-01T14:17:45.479138Z TRACE timesimp: sleeping to spread out requests delay=715.72255ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:46.197078Z TRACE new{response=Response { client: 2025-10-01T14:17:46.196879885Z, server: 2025-10-01T14:17:46.196892985Z } current=2025-10-01T14:17:46.196897625Z}: timesimp::delta: response processing internals latency=8µs 870ns local_at_midpoint=2025-10-01T14:17:46.196888755Z delta=4µs 230ns [INFO] [stdout] 2025-10-01T14:17:46.197172Z TRACE timesimp: obtained raw offset from server latency=8.87µs delta=4µs 230ns [INFO] [stdout] 2025-10-01T14:17:46.197201Z TRACE timesimp: response deltas sorted by latency deltas=[0.002025, 0.002755, 0.00323, 0.00323, 0.00423] [INFO] [stdout] 2025-10-01T14:17:46.197217Z TRACE timesimp: statistics about response deltas median=0.00323 mean=0.0030940000000000004 variance=6.462925000000002e-7 stddev=0.0008039231928486702 [INFO] [stdout] 2025-10-01T14:17:46.197237Z TRACE timesimp: eliminated outliers inliers=[0.002755, 0.00323, 0.00323] [INFO] [stdout] 2025-10-01T14:17:46.197247Z DEBUG timesimp: storing calculated offset offset=3µs [INFO] [stdout] test zero_offset ... ok [INFO] [stdout] 2025-10-01T14:17:46.324019Z TRACE new{response=Response { client: 2025-10-01T14:17:46.32385731Z, server: 2025-10-01T14:17:46.32387107Z } current=2025-10-01T14:17:46.32387031Z}: timesimp::delta: response processing internals latency=6µs 500ns local_at_midpoint=2025-10-01T14:17:46.32386381Z delta=7µs 260ns [INFO] [stdout] 2025-10-01T14:17:46.324087Z TRACE timesimp: obtained raw offset from server latency=6.5µs delta=7µs 260ns [INFO] [stdout] 2025-10-01T14:17:46.324101Z TRACE timesimp: sleeping to spread out requests delay=1.721510384s max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:46.452078Z TRACE new{response=Response { client: 2025-10-01T14:17:46.451891846Z, server: 2025-10-01T14:17:51.451903206Z } current=2025-10-01T14:17:46.451907036Z}: timesimp::delta: response processing internals latency=7µs 595ns local_at_midpoint=2025-10-01T14:17:46.451899441Z delta=5s 3µs 765ns [INFO] [stdout] 2025-10-01T14:17:46.452161Z TRACE timesimp: obtained raw offset from server latency=7.595µs delta=5s 3µs 765ns [INFO] [stdout] 2025-10-01T14:17:46.452181Z TRACE timesimp: sleeping to spread out requests delay=821.14472ms max_jitter=2s [INFO] [stdout] 2025-10-01T14:17:46.996039Z TRACE new{response=Response { client: 2025-10-01T14:17:46.995865343Z, server: 2025-10-01T14:17:41.995875093Z } current=2025-10-01T14:17:46.995879083Z}: timesimp::delta: response processing internals latency=6µs 870ns local_at_midpoint=2025-10-01T14:17:46.995872213Z delta=4s 999ms 997µs 120ns ago [INFO] [stdout] 2025-10-01T14:17:46.996124Z TRACE timesimp: obtained raw offset from server latency=6.87µs delta=4s 999ms 997µs 120ns ago [INFO] [stdout] 2025-10-01T14:17:46.996149Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99712, -4999.995845, -4999.99709, -4999.996615, -4999.996475] [INFO] [stdout] 2025-10-01T14:17:46.996163Z TRACE timesimp: statistics about response deltas median=-4999.99709 mean=-4999.996629 variance=2.7304249982305146e-7 stddev=0.0005225346876744657 [INFO] [stdout] 2025-10-01T14:17:46.996185Z TRACE timesimp: eliminated outliers inliers=[-4999.99712, -4999.99709, -4999.996615] [INFO] [stdout] 2025-10-01T14:17:46.996195Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs ago [INFO] [stdout] test negative_starting_offset ... ok [INFO] [stdout] 2025-10-01T14:17:47.284193Z TRACE new{response=Response { client: 2025-10-01T14:17:47.28401183Z, server: 2025-10-01T14:17:52.284023139Z } current=2025-10-01T14:17:47.28402699Z}: timesimp::delta: response processing internals latency=7µs 580ns local_at_midpoint=2025-10-01T14:17:47.28401941Z delta=5s 3µs 729ns [INFO] [stdout] 2025-10-01T14:17:47.284270Z TRACE timesimp: obtained raw offset from server latency=7.58µs delta=5s 3µs 729ns [INFO] [stdout] 2025-10-01T14:17:47.284294Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00284, 5000.003475, 5000.003325, 5000.003729, 5000.003765] [INFO] [stdout] 2025-10-01T14:17:47.284309Z TRACE timesimp: statistics about response deltas median=5000.003325 mean=5000.0034268 variance=1.4068120006424488e-7 stddev=0.0003750749259337991 [INFO] [stdout] 2025-10-01T14:17:47.284325Z TRACE timesimp: eliminated outliers inliers=[5000.003475, 5000.003325] [INFO] [stdout] 2025-10-01T14:17:47.284336Z DEBUG timesimp: storing calculated offset offset=5s 3µs [INFO] [stdout] test positive_starting_offset ... ok [INFO] [stderr] Doc-tests timesimp [INFO] [stdout] 2025-10-01T14:17:48.047047Z TRACE new{response=Response { client: 2025-10-01T14:17:48.046876791Z, server: 2025-10-01T14:17:48.046891341Z } current=2025-10-01T14:17:48.046890701Z}: timesimp::delta: response processing internals latency=6µs 955ns local_at_midpoint=2025-10-01T14:17:48.046883746Z delta=7µs 595ns [INFO] [stdout] 2025-10-01T14:17:48.047128Z TRACE timesimp: obtained raw offset from server latency=6.955µs delta=7µs 595ns [INFO] [stdout] 2025-10-01T14:17:48.047151Z TRACE timesimp: response deltas sorted by latency deltas=[0.00726, 0.00744, 0.007595, 0.007771, 0.0043] [INFO] [stdout] 2025-10-01T14:17:48.047167Z TRACE timesimp: statistics about response deltas median=0.007595 mean=0.0068732 variance=2.1048187000000002e-6 stddev=0.0014507993314032096 [INFO] [stdout] 2025-10-01T14:17:48.047180Z TRACE timesimp: eliminated outliers inliers=[0.00726, 0.00744, 0.007595, 0.007771] [INFO] [stdout] 2025-10-01T14:17:48.047190Z DEBUG timesimp: storing calculated offset offset=7µs [INFO] [stdout] test null_offset ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.11s [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" "53cd0f5c84f77436660a7b8c67cf5357709bfbfff2dabd0289c93f3b07492321", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "53cd0f5c84f77436660a7b8c67cf5357709bfbfff2dabd0289c93f3b07492321", kill_on_drop: false }` [INFO] [stdout] 53cd0f5c84f77436660a7b8c67cf5357709bfbfff2dabd0289c93f3b07492321