[INFO] fetching crate timesimp 1.0.0... [INFO] testing timesimp-1.0.0 against try#b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b for pr-145330-1 [INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-2-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-2-tc2/source/Cargo.toml [INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "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" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-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" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] e0d3afb3cce67fe28afa9edd757bd775a6b9bc7d59a8aa991dea3c4237e5b8c3 [INFO] running `Command { std: "docker" "start" "-a" "e0d3afb3cce67fe28afa9edd757bd775a6b9bc7d59a8aa991dea3c4237e5b8c3", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "e0d3afb3cce67fe28afa9edd757bd775a6b9bc7d59a8aa991dea3c4237e5b8c3", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "e0d3afb3cce67fe28afa9edd757bd775a6b9bc7d59a8aa991dea3c4237e5b8c3", kill_on_drop: false }` [INFO] [stdout] e0d3afb3cce67fe28afa9edd757bd775a6b9bc7d59a8aa991dea3c4237e5b8c3 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 116a84f2e87a612bc1b6c26adbd4f1185e8ac0d636d78285779225f4bced66fc [INFO] running `Command { std: "docker" "start" "-a" "116a84f2e87a612bc1b6c26adbd4f1185e8ac0d636d78285779225f4bced66fc", 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 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 tracing v0.1.41 [INFO] [stderr] Compiling thiserror v2.0.12 [INFO] [stderr] Compiling timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 14.72s [INFO] running `Command { std: "docker" "inspect" "116a84f2e87a612bc1b6c26adbd4f1185e8ac0d636d78285779225f4bced66fc", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "116a84f2e87a612bc1b6c26adbd4f1185e8ac0d636d78285779225f4bced66fc", kill_on_drop: false }` [INFO] [stdout] 116a84f2e87a612bc1b6c26adbd4f1185e8ac0d636d78285779225f4bced66fc [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 1b583752edb290ea7769c6c662a5c24ac0b58fa8d2d0d5eefc8627e97ba69419 [INFO] running `Command { std: "docker" "start" "-a" "1b583752edb290ea7769c6c662a5c24ac0b58fa8d2d0d5eefc8627e97ba69419", kill_on_drop: false }` [INFO] [stderr] Compiling libc v0.2.171 [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 hashbrown v0.15.2 [INFO] [stderr] Compiling syn v2.0.100 [INFO] [stderr] Compiling openssl v0.10.72 [INFO] [stderr] Compiling bitflags v2.9.0 [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 thread_local v1.1.8 [INFO] [stderr] Compiling nu-ansi-term v0.46.0 [INFO] [stderr] Compiling tracing-log v0.2.0 [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 parking_lot_core v0.9.10 [INFO] [stderr] Compiling signal-hook-registry v1.4.5 [INFO] [stderr] Compiling socket2 v0.5.9 [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 openssl-sys v0.9.107 [INFO] [stderr] Compiling rand_core v0.9.3 [INFO] [stderr] Compiling rand_chacha v0.9.0 [INFO] [stderr] Compiling native-tls v0.2.14 [INFO] [stderr] Compiling rand v0.9.1 [INFO] [stderr] Compiling synstructure v0.13.1 [INFO] [stderr] Compiling serde_urlencoded v0.7.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 thiserror v2.0.12 [INFO] [stderr] Compiling timesimp v1.0.0 (/opt/rustwide/workdir) [INFO] [stderr] Compiling zerovec v0.10.4 [INFO] [stderr] Compiling tinystr v0.7.6 [INFO] [stderr] Compiling icu_collections v1.5.0 [INFO] [stderr] Compiling icu_locid v1.5.0 [INFO] [stderr] Compiling icu_provider v1.5.0 [INFO] [stderr] Compiling icu_locid_transform v1.5.0 [INFO] [stderr] Compiling icu_properties v1.5.1 [INFO] [stderr] Compiling tokio-util v0.7.15 [INFO] [stderr] Compiling tokio-native-tls v0.3.1 [INFO] [stderr] Compiling tower v0.5.2 [INFO] [stderr] Compiling 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 35.70s [INFO] running `Command { std: "docker" "inspect" "1b583752edb290ea7769c6c662a5c24ac0b58fa8d2d0d5eefc8627e97ba69419", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "1b583752edb290ea7769c6c662a5c24ac0b58fa8d2d0d5eefc8627e97ba69419", kill_on_drop: false }` [INFO] [stdout] 1b583752edb290ea7769c6c662a5c24ac0b58fa8d2d0d5eefc8627e97ba69419 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] f47ab330ebd7c078febc3814d636471aad5b93f4ecc7bc871affb7b02ccb2817 [INFO] running `Command { std: "docker" "start" "-a" "f47ab330ebd7c078febc3814d636471aad5b93f4ecc7bc871affb7b02ccb2817", 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-7957b5c2dc13f12b) [INFO] [stdout] [INFO] [stdout] running 5 tests [INFO] [stdout] test delta::tests::client_behind_server ... ok [INFO] [stdout] test delta::tests::client_ahead_of_server ... ok [INFO] [stdout] test delta::tests::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.10s [INFO] [stdout] [INFO] [stderr] Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-1c01cc53c6a498a7) [INFO] [stdout] [INFO] [stdout] running 10 tests [INFO] [stdout] 2025-10-02T06:17:32.470546Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-10-02T06:17:32.470836Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.470800Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.470918Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.470563Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-10-02T06:17:32.471029Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.470554Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.471115Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.470544Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.471144Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.471267Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.471375Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.471443Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.471486Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.472612Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.472696Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.472652Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.472764Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.489903Z TRACE new{response=Response { client: 2025-10-02T06:17:32.472302039Z, server: 2025-10-02T06:17:37.481483719Z } current=2025-10-02T06:17:32.489669829Z}: timesimp::delta: response processing internals latency=8ms 683µs 895ns local_at_midpoint=2025-10-02T06:17:32.480985934Z delta=5s 497µs 785ns [INFO] [stdout] 2025-10-02T06:17:32.490068Z TRACE timesimp: obtained raw offset from server latency=8.683895ms delta=5s 497µs 785ns [INFO] [stdout] 2025-10-02T06:17:32.490127Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 497µs 785ns [INFO] [stdout] 2025-10-02T06:17:32.490178Z TRACE timesimp: sleeping to spread out requests delay=1.265256457s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.490728Z TRACE new{response=Response { client: 2025-10-02T06:17:32.472346479Z, server: 2025-10-02T06:17:37.481483689Z } current=2025-10-02T06:17:32.490623169Z}: timesimp::delta: response processing internals latency=9ms 138µs 345ns local_at_midpoint=2025-10-02T06:17:32.481484824Z delta=4s 999ms 998µs 865ns [INFO] [stdout] 2025-10-02T06:17:32.490836Z TRACE timesimp: obtained raw offset from server latency=9.138345ms delta=4s 999ms 998µs 865ns [INFO] [stdout] 2025-10-02T06:17:32.490955Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 998µs 865ns [INFO] [stdout] 2025-10-02T06:17:32.490979Z TRACE timesimp: sleeping to spread out requests delay=1.36209307s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.492870Z TRACE new{response=Response { client: 2025-10-02T06:17:32.472479579Z, server: 2025-10-02T06:17:37.482627169Z } current=2025-10-02T06:17:32.492753239Z}: timesimp::delta: response processing internals latency=10ms 136µs 830ns local_at_midpoint=2025-10-02T06:17:32.482616409Z delta=5s 10µs 760ns [INFO] [stdout] 2025-10-02T06:17:32.492983Z TRACE timesimp: obtained raw offset from server latency=10.13683ms delta=5s 10µs 760ns [INFO] [stdout] 2025-10-02T06:17:32.493025Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 10µs 760ns [INFO] [stdout] 2025-10-02T06:17:32.493099Z TRACE timesimp: sleeping to spread out requests delay=556.550411ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.494703Z TRACE new{response=Response { client: 2025-10-02T06:17:32.47225781Z, server: 2025-10-02T06:17:32.483433449Z } current=2025-10-02T06:17:32.494563909Z}: timesimp::delta: response processing internals latency=11ms 153µs 49ns local_at_midpoint=2025-10-02T06:17:32.483410859Z delta=22µs 590ns [INFO] [stdout] 2025-10-02T06:17:32.495037Z TRACE timesimp: obtained raw offset from server latency=11.153049ms delta=22µs 590ns [INFO] [stdout] 2025-10-02T06:17:32.495106Z TRACE timesimp: sleeping to spread out requests delay=281.061264ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.494974Z TRACE new{response=Response { client: 2025-10-02T06:17:32.47243965Z, server: 2025-10-02T06:17:32.483559449Z } current=2025-10-02T06:17:32.494840159Z}: timesimp::delta: response processing internals latency=11ms 200µs 254ns local_at_midpoint=2025-10-02T06:17:32.483639904Z delta=80µs 455ns ago [INFO] [stdout] 2025-10-02T06:17:32.495270Z TRACE timesimp: obtained raw offset from server latency=11.200254ms delta=80µs 455ns ago [INFO] [stdout] 2025-10-02T06:17:32.495359Z TRACE timesimp: sleeping to spread out requests delay=401.805093ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.496994Z TRACE new{response=Response { client: 2025-10-02T06:17:32.474035969Z, server: 2025-10-02T06:17:27.485155989Z } current=2025-10-02T06:17:32.496869409Z}: timesimp::delta: response processing internals latency=11ms 416µs 720ns local_at_midpoint=2025-10-02T06:17:32.485452689Z delta=5s 296µs 700ns ago [INFO] [stdout] 2025-10-02T06:17:32.497062Z TRACE timesimp: obtained raw offset from server latency=11.41672ms delta=5s 296µs 700ns ago [INFO] [stdout] 2025-10-02T06:17:32.497078Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 296µs 700ns ago [INFO] [stdout] 2025-10-02T06:17:32.497093Z TRACE timesimp: sleeping to spread out requests delay=1.929140365s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.497174Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:32.497243Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.501837Z TRACE new{response=Response { client: 2025-10-02T06:17:32.472583219Z, server: 2025-10-02T06:17:37.483704609Z } current=2025-10-02T06:17:32.501662739Z}: timesimp::delta: response processing internals latency=14ms 539µs 760ns local_at_midpoint=2025-10-02T06:17:32.487122979Z delta=4s 996ms 581µs 630ns [INFO] [stdout] 2025-10-02T06:17:32.501910Z TRACE timesimp: obtained raw offset from server latency=14.53976ms delta=4s 996ms 581µs 630ns [INFO] [stdout] 2025-10-02T06:17:32.501925Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 996ms 581µs 630ns [INFO] [stdout] 2025-10-02T06:17:32.501938Z TRACE timesimp: sleeping to spread out requests delay=365.718717ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.508037Z TRACE new{response=Response { client: 2025-10-02T06:17:32.505575778Z, server: 2025-10-02T06:17:32.506719089Z } current=2025-10-02T06:17:32.507841188Z}: timesimp::delta: response processing internals latency=1ms 132µs 705ns local_at_midpoint=2025-10-02T06:17:32.506708483Z delta=10µs 606ns [INFO] [stdout] 2025-10-02T06:17:32.508122Z TRACE timesimp: obtained raw offset from server latency=1.132705ms delta=10µs 606ns [INFO] [stdout] 2025-10-02T06:17:32.508139Z DEBUG timesimp: no offset stored, storing initial delta offset=10µs 606ns [INFO] [stdout] 2025-10-02T06:17:32.508150Z TRACE timesimp: sleeping to spread out requests delay=187.575221ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.699222Z TRACE new{response=Response { client: 2025-10-02T06:17:32.696754452Z, server: 2025-10-02T06:17:32.697894962Z } current=2025-10-02T06:17:32.699024812Z}: timesimp::delta: response processing internals latency=1ms 135µs 180ns local_at_midpoint=2025-10-02T06:17:32.697889632Z delta=5µs 330ns [INFO] [stdout] 2025-10-02T06:17:32.699304Z TRACE timesimp: obtained raw offset from server latency=1.13518ms delta=5µs 330ns [INFO] [stdout] 2025-10-02T06:17:32.699323Z TRACE timesimp: sleeping to spread out requests delay=1.341793693s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.744837Z TRACE new{response=Response { client: 2025-10-02T06:17:32.542023277Z, server: 2025-10-02T06:17:32.643372584Z } current=2025-10-02T06:17:32.744627821Z}: timesimp::delta: response processing internals latency=101ms 302µs 272ns local_at_midpoint=2025-10-02T06:17:32.643325549Z delta=47µs 35ns [INFO] [stdout] 2025-10-02T06:17:32.744916Z TRACE timesimp: obtained raw offset from server latency=101.302272ms delta=47µs 35ns [INFO] [stdout] 2025-10-02T06:17:32.744934Z DEBUG timesimp: no offset stored, storing initial delta offset=47µs 35ns [INFO] [stdout] 2025-10-02T06:17:32.744946Z TRACE timesimp: sleeping to spread out requests delay=732.421689ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.814644Z TRACE new{response=Response { client: 2025-10-02T06:17:32.78370622Z, server: 2025-10-02T06:17:32.796473279Z } current=2025-10-02T06:17:32.814470029Z}: timesimp::delta: response processing internals latency=15ms 381µs 904ns local_at_midpoint=2025-10-02T06:17:32.799088124Z delta=2ms 614µs 845ns ago [INFO] [stdout] 2025-10-02T06:17:32.814729Z TRACE timesimp: obtained raw offset from server latency=15.381904ms delta=2ms 614µs 845ns ago [INFO] [stdout] 2025-10-02T06:17:32.814749Z TRACE timesimp: sleeping to spread out requests delay=1.978674148s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.900718Z TRACE new{response=Response { client: 2025-10-02T06:17:32.868511187Z, server: 2025-10-02T06:17:37.885519106Z } current=2025-10-02T06:17:32.900521886Z}: timesimp::delta: response processing internals latency=16ms 5µs 349ns local_at_midpoint=2025-10-02T06:17:32.884516536Z delta=5s 1ms 2µs 570ns [INFO] [stdout] 2025-10-02T06:17:32.900822Z TRACE timesimp: obtained raw offset from server latency=16.005349ms delta=5s 1ms 2µs 570ns [INFO] [stdout] 2025-10-02T06:17:32.900846Z TRACE timesimp: sleeping to spread out requests delay=212.721226ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:32.921293Z TRACE new{response=Response { client: 2025-10-02T06:17:32.898660936Z, server: 2025-10-02T06:17:32.909857876Z } current=2025-10-02T06:17:32.921117625Z}: timesimp::delta: response processing internals latency=11ms 228µs 344ns local_at_midpoint=2025-10-02T06:17:32.90988928Z delta=31µs 404ns ago [INFO] [stdout] 2025-10-02T06:17:32.921377Z TRACE timesimp: obtained raw offset from server latency=11.228344ms delta=31µs 404ns ago [INFO] [stdout] 2025-10-02T06:17:32.921398Z TRACE timesimp: sleeping to spread out requests delay=903.879362ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.073221Z TRACE new{response=Response { client: 2025-10-02T06:17:33.050627001Z, server: 2025-10-02T06:17:38.061819701Z } current=2025-10-02T06:17:33.07301916Z}: timesimp::delta: response processing internals latency=11ms 196µs 79ns local_at_midpoint=2025-10-02T06:17:33.06182308Z delta=4s 999ms 996µs 621ns [INFO] [stdout] 2025-10-02T06:17:33.073303Z TRACE timesimp: obtained raw offset from server latency=11.196079ms delta=4s 999ms 996µs 621ns [INFO] [stdout] 2025-10-02T06:17:33.073324Z TRACE timesimp: sleeping to spread out requests delay=386.999719ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.136904Z TRACE new{response=Response { client: 2025-10-02T06:17:33.114368579Z, server: 2025-10-02T06:17:38.125519059Z } current=2025-10-02T06:17:33.136721178Z}: timesimp::delta: response processing internals latency=11ms 176µs 299ns local_at_midpoint=2025-10-02T06:17:33.125544878Z delta=4s 999ms 974µs 181ns [INFO] [stdout] 2025-10-02T06:17:33.136988Z TRACE timesimp: obtained raw offset from server latency=11.176299ms delta=4s 999ms 974µs 181ns [INFO] [stdout] 2025-10-02T06:17:33.137013Z TRACE timesimp: sleeping to spread out requests delay=1.900151122s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.483118Z TRACE new{response=Response { client: 2025-10-02T06:17:33.461676059Z, server: 2025-10-02T06:17:38.472759188Z } current=2025-10-02T06:17:33.482925498Z}: timesimp::delta: response processing internals latency=10ms 624µs 719ns local_at_midpoint=2025-10-02T06:17:33.472300778Z delta=5s 458µs 410ns [INFO] [stdout] 2025-10-02T06:17:33.483208Z TRACE timesimp: obtained raw offset from server latency=10.624719ms delta=5s 458µs 410ns [INFO] [stdout] 2025-10-02T06:17:33.483229Z TRACE timesimp: sleeping to spread out requests delay=1.786854658s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.684192Z TRACE new{response=Response { client: 2025-10-02T06:17:33.481519128Z, server: 2025-10-02T06:17:33.582656735Z } current=2025-10-02T06:17:33.684001381Z}: timesimp::delta: response processing internals latency=101ms 241µs 126ns local_at_midpoint=2025-10-02T06:17:33.582760254Z delta=103µs 519ns ago [INFO] [stdout] 2025-10-02T06:17:33.684274Z TRACE timesimp: obtained raw offset from server latency=101.241126ms delta=103µs 519ns ago [INFO] [stdout] 2025-10-02T06:17:33.684294Z TRACE timesimp: sleeping to spread out requests delay=713.992854ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.773193Z TRACE new{response=Response { client: 2025-10-02T06:17:33.756644749Z, server: 2025-10-02T06:17:38.764830709Z } current=2025-10-02T06:17:33.773018149Z}: timesimp::delta: response processing internals latency=8ms 186µs 700ns local_at_midpoint=2025-10-02T06:17:33.764831449Z delta=4s 999ms 999µs 260ns [INFO] [stdout] 2025-10-02T06:17:33.773264Z TRACE timesimp: obtained raw offset from server latency=8.1867ms delta=4s 999ms 999µs 260ns [INFO] [stdout] 2025-10-02T06:17:33.773281Z TRACE timesimp: sleeping to spread out requests delay=263.057ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.849251Z TRACE new{response=Response { client: 2025-10-02T06:17:33.826667187Z, server: 2025-10-02T06:17:33.837861547Z } current=2025-10-02T06:17:33.849057836Z}: timesimp::delta: response processing internals latency=11ms 195µs 324ns local_at_midpoint=2025-10-02T06:17:33.837862511Z delta=964ns ago [INFO] [stdout] 2025-10-02T06:17:33.849450Z TRACE timesimp: obtained raw offset from server latency=11.195324ms delta=964ns ago [INFO] [stdout] 2025-10-02T06:17:33.849523Z TRACE timesimp: sleeping to spread out requests delay=1.143451455s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.867964Z TRACE new{response=Response { client: 2025-10-02T06:17:33.854681836Z, server: 2025-10-02T06:17:38.860918786Z } current=2025-10-02T06:17:33.867778826Z}: timesimp::delta: response processing internals latency=6ms 548µs 495ns local_at_midpoint=2025-10-02T06:17:33.861230331Z delta=4s 999ms 688µs 455ns [INFO] [stdout] 2025-10-02T06:17:33.868150Z TRACE timesimp: obtained raw offset from server latency=6.548495ms delta=4s 999ms 688µs 455ns [INFO] [stdout] 2025-10-02T06:17:33.868251Z TRACE timesimp: sleeping to spread out requests delay=1.329555857s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:33.912774Z TRACE new{response=Response { client: 2025-10-02T06:17:32.473958989Z, server: 2025-10-02T06:17:33.194513237Z } current=2025-10-02T06:17:33.912526674Z}: timesimp::delta: response processing internals latency=719ms 283µs 842ns local_at_midpoint=2025-10-02T06:17:33.193242831Z delta=1ms 270µs 406ns [INFO] [stdout] 2025-10-02T06:17:33.912872Z TRACE timesimp: obtained raw offset from server latency=719.283842ms delta=1ms 270µs 406ns [INFO] [stdout] 2025-10-02T06:17:33.912903Z DEBUG timesimp: no offset stored, storing initial delta offset=1ms 270µs 406ns [INFO] [stdout] 2025-10-02T06:17:33.912916Z TRACE timesimp: sleeping to spread out requests delay=1.960830198s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:34.045146Z TRACE new{response=Response { client: 2025-10-02T06:17:34.04266668Z, server: 2025-10-02T06:17:34.04381843Z } current=2025-10-02T06:17:34.04495418Z}: timesimp::delta: response processing internals latency=1ms 143µs 750ns local_at_midpoint=2025-10-02T06:17:34.04381043Z delta=8µs [INFO] [stdout] 2025-10-02T06:17:34.045242Z TRACE timesimp: obtained raw offset from server latency=1.14375ms delta=8µs [INFO] [stdout] 2025-10-02T06:17:34.045263Z TRACE timesimp: sleeping to spread out requests delay=154.13307ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:34.052089Z TRACE new{response=Response { client: 2025-10-02T06:17:34.03755122Z, server: 2025-10-02T06:17:39.04473361Z } current=2025-10-02T06:17:34.05191209Z}: timesimp::delta: response processing internals latency=7ms 180µs 435ns local_at_midpoint=2025-10-02T06:17:34.044731655Z delta=5s 1µs 955ns [INFO] [stdout] 2025-10-02T06:17:34.052182Z TRACE timesimp: obtained raw offset from server latency=7.180435ms delta=5s 1µs 955ns [INFO] [stdout] 2025-10-02T06:17:34.052203Z TRACE timesimp: sleeping to spread out requests delay=391.901336ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:34.204120Z TRACE new{response=Response { client: 2025-10-02T06:17:34.201531975Z, server: 2025-10-02T06:17:34.202690145Z } current=2025-10-02T06:17:34.203827605Z}: timesimp::delta: response processing internals latency=1ms 147µs 815ns local_at_midpoint=2025-10-02T06:17:34.20267979Z delta=10µs 355ns [INFO] [stdout] 2025-10-02T06:17:34.204211Z TRACE timesimp: obtained raw offset from server latency=1.147815ms delta=10µs 355ns [INFO] [stdout] 2025-10-02T06:17:34.204233Z TRACE timesimp: sleeping to spread out requests delay=1.593176329s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:34.450261Z TRACE new{response=Response { client: 2025-10-02T06:17:34.427653878Z, server: 2025-10-02T06:17:29.438855198Z } current=2025-10-02T06:17:34.450054017Z}: timesimp::delta: response processing internals latency=11ms 200µs 69ns local_at_midpoint=2025-10-02T06:17:34.438853947Z delta=4s 999ms 998µs 749ns ago [INFO] [stdout] 2025-10-02T06:17:34.450355Z TRACE timesimp: obtained raw offset from server latency=11.200069ms delta=4s 999ms 998µs 749ns ago [INFO] [stdout] 2025-10-02T06:17:34.450376Z TRACE timesimp: sleeping to spread out requests delay=1.653748061s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:34.470679Z TRACE new{response=Response { client: 2025-10-02T06:17:34.452512057Z, server: 2025-10-02T06:17:39.459794547Z } current=2025-10-02T06:17:34.470499917Z}: timesimp::delta: response processing internals latency=8ms 993µs 930ns local_at_midpoint=2025-10-02T06:17:34.461505987Z delta=4s 998ms 288µs 560ns [INFO] [stdout] 2025-10-02T06:17:34.470772Z TRACE timesimp: obtained raw offset from server latency=8.99393ms delta=4s 998ms 288µs 560ns [INFO] [stdout] 2025-10-02T06:17:34.470793Z TRACE timesimp: sleeping to spread out requests delay=1.41613937s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:34.601616Z TRACE new{response=Response { client: 2025-10-02T06:17:34.398645799Z, server: 2025-10-02T06:17:34.500009206Z } current=2025-10-02T06:17:34.601426683Z}: timesimp::delta: response processing internals latency=101ms 390µs 442ns local_at_midpoint=2025-10-02T06:17:34.500036241Z delta=27µs 35ns ago [INFO] [stdout] 2025-10-02T06:17:34.601702Z TRACE timesimp: obtained raw offset from server latency=101.390442ms delta=27µs 35ns ago [INFO] [stdout] 2025-10-02T06:17:34.601721Z TRACE timesimp: sleeping to spread out requests delay=1.74259037s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:34.817292Z TRACE new{response=Response { client: 2025-10-02T06:17:34.794672246Z, server: 2025-10-02T06:17:34.805876616Z } current=2025-10-02T06:17:34.817093796Z}: timesimp::delta: response processing internals latency=11ms 210µs 775ns local_at_midpoint=2025-10-02T06:17:34.805883021Z delta=6µs 405ns ago [INFO] [stdout] 2025-10-02T06:17:34.817500Z TRACE timesimp: obtained raw offset from server latency=11.210775ms delta=6µs 405ns ago [INFO] [stdout] 2025-10-02T06:17:34.817613Z TRACE timesimp: sleeping to spread out requests delay=1.742865361s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:35.018089Z TRACE new{response=Response { client: 2025-10-02T06:17:34.99552677Z, server: 2025-10-02T06:17:35.00672073Z } current=2025-10-02T06:17:35.017913779Z}: timesimp::delta: response processing internals latency=11ms 193µs 504ns local_at_midpoint=2025-10-02T06:17:35.006720274Z delta=456ns [INFO] [stdout] 2025-10-02T06:17:35.018160Z TRACE timesimp: obtained raw offset from server latency=11.193504ms delta=456ns [INFO] [stdout] 2025-10-02T06:17:35.018175Z TRACE timesimp: sleeping to spread out requests delay=324.532294ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:35.083111Z TRACE new{response=Response { client: 2025-10-02T06:17:35.060544038Z, server: 2025-10-02T06:17:40.071747198Z } current=2025-10-02T06:17:35.082935928Z}: timesimp::delta: response processing internals latency=11ms 195µs 945ns local_at_midpoint=2025-10-02T06:17:35.071739983Z delta=5s 7µs 215ns [INFO] [stdout] 2025-10-02T06:17:35.083183Z TRACE timesimp: obtained raw offset from server latency=11.195945ms delta=5s 7µs 215ns [INFO] [stdout] 2025-10-02T06:17:35.083200Z TRACE timesimp: sleeping to spread out requests delay=1.169003205s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:35.220261Z TRACE new{response=Response { client: 2025-10-02T06:17:35.199665324Z, server: 2025-10-02T06:17:40.209860893Z } current=2025-10-02T06:17:35.220067943Z}: timesimp::delta: response processing internals latency=10ms 201µs 309ns local_at_midpoint=2025-10-02T06:17:35.209866633Z delta=4s 999ms 994µs 260ns [INFO] [stdout] 2025-10-02T06:17:35.220355Z TRACE timesimp: obtained raw offset from server latency=10.201309ms delta=4s 999ms 994µs 260ns [INFO] [stdout] 2025-10-02T06:17:35.220385Z TRACE timesimp: sleeping to spread out requests delay=1.201566281s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:35.291459Z TRACE new{response=Response { client: 2025-10-02T06:17:35.270660991Z, server: 2025-10-02T06:17:40.280867041Z } current=2025-10-02T06:17:35.291245631Z}: timesimp::delta: response processing internals latency=10ms 292µs 320ns local_at_midpoint=2025-10-02T06:17:35.280953311Z delta=4s 999ms 913µs 730ns [INFO] [stdout] 2025-10-02T06:17:35.291622Z TRACE timesimp: obtained raw offset from server latency=10.29232ms delta=4s 999ms 913µs 730ns [INFO] [stdout] 2025-10-02T06:17:35.291701Z TRACE timesimp: sleeping to spread out requests delay=112.282193ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:35.366564Z TRACE new{response=Response { client: 2025-10-02T06:17:35.343661589Z, server: 2025-10-02T06:17:35.355079819Z } current=2025-10-02T06:17:35.366331028Z}: timesimp::delta: response processing internals latency=11ms 334µs 719ns local_at_midpoint=2025-10-02T06:17:35.354996308Z delta=83µs 511ns [INFO] [stdout] 2025-10-02T06:17:35.366658Z TRACE timesimp: obtained raw offset from server latency=11.334719ms delta=83µs 511ns [INFO] [stdout] 2025-10-02T06:17:35.366693Z TRACE timesimp: response deltas sorted by latency deltas=[0.000456, -0.000964, -0.080455, -0.031404, 0.083511] [INFO] [stdout] 2025-10-02T06:17:35.366711Z TRACE timesimp: statistics about response deltas median=-0.080455 mean=-0.005771199999999999 variance=0.0035669772117000002 stddev=0.0597241761073353 [INFO] [stdout] 2025-10-02T06:17:35.366732Z TRACE timesimp: eliminated outliers inliers=[-0.080455, -0.031404] [INFO] [stdout] 2025-10-02T06:17:35.366743Z DEBUG timesimp: storing calculated offset offset=55µs ago [INFO] [stdout] test client_offset_negative ... ok [INFO] [stdout] 2025-10-02T06:17:35.426421Z TRACE new{response=Response { client: 2025-10-02T06:17:35.405083877Z, server: 2025-10-02T06:17:40.415397487Z } current=2025-10-02T06:17:35.426215707Z}: timesimp::delta: response processing internals latency=10ms 565µs 915ns local_at_midpoint=2025-10-02T06:17:35.415649792Z delta=4s 999ms 747µs 695ns [INFO] [stdout] 2025-10-02T06:17:35.426567Z TRACE timesimp: obtained raw offset from server latency=10.565915ms delta=4s 999ms 747µs 695ns [INFO] [stdout] 2025-10-02T06:17:35.426650Z TRACE timesimp: response deltas sorted by latency deltas=[5000.01076, 4999.91373, 4999.747695, 5000.45841, 4999.996621] [INFO] [stdout] 2025-10-02T06:17:35.426726Z TRACE timesimp: statistics about response deltas median=4999.747695 mean=5000.0254432 variance=0.06953261678372095 stddev=0.26369038052936433 [INFO] [stdout] 2025-10-02T06:17:35.426785Z TRACE timesimp: eliminated outliers inliers=[5000.01076, 4999.91373, 4999.747695, 4999.996621] [INFO] [stdout] 2025-10-02T06:17:35.426823Z DEBUG timesimp: storing calculated offset offset=4s 999ms 917µs [INFO] [stdout] test low_jitter ... ok [INFO] [stdout] 2025-10-02T06:17:35.801111Z TRACE new{response=Response { client: 2025-10-02T06:17:35.798657745Z, server: 2025-10-02T06:17:35.799790765Z } current=2025-10-02T06:17:35.800938685Z}: timesimp::delta: response processing internals latency=1ms 140µs 470ns local_at_midpoint=2025-10-02T06:17:35.799798215Z delta=7µs 450ns ago [INFO] [stdout] 2025-10-02T06:17:35.801198Z TRACE timesimp: obtained raw offset from server latency=1.14047ms delta=7µs 450ns ago [INFO] [stdout] 2025-10-02T06:17:35.801220Z TRACE timesimp: response deltas sorted by latency deltas=[0.010606, 0.00533, -0.00745, 0.008, 0.010355] [INFO] [stdout] 2025-10-02T06:17:35.801235Z TRACE timesimp: statistics about response deltas median=-0.00745 mean=0.0053682 variance=5.58842012e-5 stddev=0.007475573636852225 [INFO] [stdout] 2025-10-02T06:17:35.801250Z TRACE timesimp: eliminated outliers inliers=[-0.00745] [INFO] [stdout] 2025-10-02T06:17:35.801268Z DEBUG timesimp: storing calculated offset offset=7µs ago [INFO] [stdout] test no_delay ... ok [INFO] [stdout] 2025-10-02T06:17:35.905279Z TRACE new{response=Response { client: 2025-10-02T06:17:35.887666892Z, server: 2025-10-02T06:17:40.895869402Z } current=2025-10-02T06:17:35.905081531Z}: timesimp::delta: response processing internals latency=8ms 707µs 319ns local_at_midpoint=2025-10-02T06:17:35.896374211Z delta=4s 999ms 495µs 191ns [INFO] [stdout] 2025-10-02T06:17:35.905372Z TRACE timesimp: obtained raw offset from server latency=8.707319ms delta=4s 999ms 495µs 191ns [INFO] [stdout] 2025-10-02T06:17:35.905401Z TRACE timesimp: response deltas sorted by latency deltas=[5000.001955, 4999.9992600000005, 5000.497785, 4999.495191, 4998.28856] [INFO] [stdout] 2025-10-02T06:17:35.905440Z TRACE timesimp: statistics about response deltas median=5000.497785 mean=4999.656550199999 variance=0.7104661125825851 stddev=0.8428915188697683 [INFO] [stdout] 2025-10-02T06:17:35.905460Z TRACE timesimp: eliminated outliers inliers=[5000.001955, 4999.9992600000005, 5000.497785] [INFO] [stdout] 2025-10-02T06:17:35.905472Z DEBUG timesimp: storing calculated offset offset=5s 166µs [INFO] [stdout] test mid_jitter ... ok [INFO] [stdout] 2025-10-02T06:17:36.128363Z TRACE new{response=Response { client: 2025-10-02T06:17:36.105657925Z, server: 2025-10-02T06:17:31.116852095Z } current=2025-10-02T06:17:36.128185055Z}: timesimp::delta: response processing internals latency=11ms 263µs 565ns local_at_midpoint=2025-10-02T06:17:36.11692149Z delta=5s 69µs 395ns ago [INFO] [stdout] 2025-10-02T06:17:36.128467Z TRACE timesimp: obtained raw offset from server latency=11.263565ms delta=5s 69µs 395ns ago [INFO] [stdout] 2025-10-02T06:17:36.128485Z TRACE timesimp: sleeping to spread out requests delay=465.656119ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:36.276230Z TRACE new{response=Response { client: 2025-10-02T06:17:36.253650681Z, server: 2025-10-02T06:17:41.26484471Z } current=2025-10-02T06:17:36.27604896Z}: timesimp::delta: response processing internals latency=11ms 199µs 139ns local_at_midpoint=2025-10-02T06:17:36.26484982Z delta=4s 999ms 994µs 890ns [INFO] [stdout] 2025-10-02T06:17:36.276403Z TRACE timesimp: obtained raw offset from server latency=11.199139ms delta=4s 999ms 994µs 890ns [INFO] [stdout] 2025-10-02T06:17:36.276505Z TRACE timesimp: response deltas sorted by latency deltas=[4999.974181, 5000.007215, 4999.99489, 4996.58163, 5001.00257] [INFO] [stdout] 2025-10-02T06:17:36.276543Z TRACE timesimp: statistics about response deltas median=4999.99489 mean=4999.5120971999995 variance=2.8752247849117127 stddev=1.6956487799399123 [INFO] [stdout] 2025-10-02T06:17:36.276618Z TRACE timesimp: eliminated outliers inliers=[4999.974181, 5000.007215, 4999.99489, 5001.00257] [INFO] [stdout] 2025-10-02T06:17:36.276650Z DEBUG timesimp: storing calculated offset offset=5s 244µs [INFO] [stdout] test server_offset_positive ... ok [INFO] [stdout] 2025-10-02T06:17:36.444802Z TRACE new{response=Response { client: 2025-10-02T06:17:36.423650215Z, server: 2025-10-02T06:17:41.433833795Z } current=2025-10-02T06:17:36.444625555Z}: timesimp::delta: response processing internals latency=10ms 487µs 670ns local_at_midpoint=2025-10-02T06:17:36.434137885Z delta=4s 999ms 695µs 910ns [INFO] [stdout] 2025-10-02T06:17:36.444886Z TRACE timesimp: obtained raw offset from server latency=10.48767ms delta=4s 999ms 695µs 910ns [INFO] [stdout] 2025-10-02T06:17:36.444906Z TRACE timesimp: sleeping to spread out requests delay=1.944714444s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:36.547607Z TRACE new{response=Response { client: 2025-10-02T06:17:36.344665928Z, server: 2025-10-02T06:17:36.446034794Z } current=2025-10-02T06:17:36.547402551Z}: timesimp::delta: response processing internals latency=101ms 368µs 311ns local_at_midpoint=2025-10-02T06:17:36.446034239Z delta=555ns [INFO] [stdout] 2025-10-02T06:17:36.547684Z TRACE timesimp: obtained raw offset from server latency=101.368311ms delta=555ns [INFO] [stdout] 2025-10-02T06:17:36.547701Z TRACE timesimp: sleeping to spread out requests delay=1.024327068s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:36.584390Z TRACE new{response=Response { client: 2025-10-02T06:17:36.561685211Z, server: 2025-10-02T06:17:36.573012391Z } current=2025-10-02T06:17:36.58420847Z}: timesimp::delta: response processing internals latency=11ms 261µs 629ns local_at_midpoint=2025-10-02T06:17:36.57294684Z delta=65µs 551ns [INFO] [stdout] 2025-10-02T06:17:36.584492Z TRACE timesimp: obtained raw offset from server latency=11.261629ms delta=65µs 551ns [INFO] [stdout] 2025-10-02T06:17:36.584511Z TRACE timesimp: sleeping to spread out requests delay=1.415645701s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:36.617686Z TRACE new{response=Response { client: 2025-10-02T06:17:36.59519867Z, server: 2025-10-02T06:17:31.60634964Z } current=2025-10-02T06:17:36.617507859Z}: timesimp::delta: response processing internals latency=11ms 154µs 594ns local_at_midpoint=2025-10-02T06:17:36.606353264Z delta=5s 3µs 624ns ago [INFO] [stdout] 2025-10-02T06:17:36.617781Z TRACE timesimp: obtained raw offset from server latency=11.154594ms delta=5s 3µs 624ns ago [INFO] [stdout] 2025-10-02T06:17:36.617803Z TRACE timesimp: sleeping to spread out requests delay=1.895469241s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:37.335702Z TRACE new{response=Response { client: 2025-10-02T06:17:35.875633092Z, server: 2025-10-02T06:17:36.605584Z } current=2025-10-02T06:17:37.335517197Z}: timesimp::delta: response processing internals latency=729ms 942µs 52ns local_at_midpoint=2025-10-02T06:17:36.605575144Z delta=8µs 856ns [INFO] [stdout] 2025-10-02T06:17:37.335790Z TRACE timesimp: obtained raw offset from server latency=729.942052ms delta=8µs 856ns [INFO] [stdout] 2025-10-02T06:17:37.335812Z TRACE timesimp: sleeping to spread out requests delay=509.389474ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:37.776246Z TRACE new{response=Response { client: 2025-10-02T06:17:37.572663729Z, server: 2025-10-02T06:17:37.674704746Z } current=2025-10-02T06:17:37.776057303Z}: timesimp::delta: response processing internals latency=101ms 696µs 787ns local_at_midpoint=2025-10-02T06:17:37.674360516Z delta=344µs 230ns [INFO] [stdout] 2025-10-02T06:17:37.776327Z TRACE timesimp: obtained raw offset from server latency=101.696787ms delta=344µs 230ns [INFO] [stdout] 2025-10-02T06:17:37.776348Z TRACE timesimp: response deltas sorted by latency deltas=[-0.103519, 0.047035, 0.000555, -0.027035, 0.34423] [INFO] [stdout] 2025-10-02T06:17:37.776363Z TRACE timesimp: statistics about response deltas median=0.000555 mean=0.0522532 variance=0.029625495546199997 stddev=0.17212058431866886 [INFO] [stdout] 2025-10-02T06:17:37.776385Z TRACE timesimp: eliminated outliers inliers=[-0.103519, 0.047035, 0.000555, -0.027035] [INFO] [stdout] 2025-10-02T06:17:37.776396Z DEBUG timesimp: storing calculated offset offset=20µs ago [INFO] [stdout] test some_delay ... ok [INFO] [stdout] 2025-10-02T06:17:38.025076Z TRACE new{response=Response { client: 2025-10-02T06:17:38.002510846Z, server: 2025-10-02T06:17:38.013699875Z } current=2025-10-02T06:17:38.024895175Z}: timesimp::delta: response processing internals latency=11ms 192µs 164ns local_at_midpoint=2025-10-02T06:17:38.01370301Z delta=3µs 135ns ago [INFO] [stdout] 2025-10-02T06:17:38.025173Z TRACE timesimp: obtained raw offset from server latency=11.192164ms delta=3µs 135ns ago [INFO] [stdout] 2025-10-02T06:17:38.025199Z TRACE timesimp: response deltas sorted by latency deltas=[0.02259, -0.003135, -0.006405, 0.065551, -2.614845] [INFO] [stdout] 2025-10-02T06:17:38.025217Z TRACE timesimp: statistics about response deltas median=-0.006405 mean=-0.5072487999999999 variance=1.3889414356171996 stddev=1.178533595455471 [INFO] [stdout] 2025-10-02T06:17:38.025233Z TRACE timesimp: eliminated outliers inliers=[0.02259, -0.003135, -0.006405, 0.065551] [INFO] [stdout] 2025-10-02T06:17:38.025300Z DEBUG timesimp: storing calculated offset offset=19µs [INFO] [stdout] test client_offset_positive ... ok [INFO] [stdout] 2025-10-02T06:17:38.409266Z TRACE new{response=Response { client: 2025-10-02T06:17:38.390662984Z, server: 2025-10-02T06:17:43.399863423Z } current=2025-10-02T06:17:38.409072603Z}: timesimp::delta: response processing internals latency=9ms 204µs 809ns local_at_midpoint=2025-10-02T06:17:38.399867793Z delta=4s 999ms 995µs 630ns [INFO] [stdout] 2025-10-02T06:17:38.409355Z TRACE timesimp: obtained raw offset from server latency=9.204809ms delta=4s 999ms 995µs 630ns [INFO] [stdout] 2025-10-02T06:17:38.409383Z TRACE timesimp: response deltas sorted by latency deltas=[4999.6884549999995, 4999.998865, 4999.99563, 4999.99426, 4999.69591] [INFO] [stdout] 2025-10-02T06:17:38.409399Z TRACE timesimp: statistics about response deltas median=4999.99563 mean=4999.874623999999 variance=0.02774716024252952 stddev=0.1665747887362596 [INFO] [stdout] 2025-10-02T06:17:38.409437Z TRACE timesimp: eliminated outliers inliers=[4999.998865, 4999.99563, 4999.99426] [INFO] [stdout] 2025-10-02T06:17:38.409455Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs [INFO] [stdout] test high_jitter ... ok [INFO] [stdout] 2025-10-02T06:17:38.537228Z TRACE new{response=Response { client: 2025-10-02T06:17:38.51465338Z, server: 2025-10-02T06:17:33.525843759Z } current=2025-10-02T06:17:38.537038259Z}: timesimp::delta: response processing internals latency=11ms 192µs 439ns local_at_midpoint=2025-10-02T06:17:38.525845819Z delta=5s 2µs 60ns ago [INFO] [stdout] 2025-10-02T06:17:38.537316Z TRACE timesimp: obtained raw offset from server latency=11.192439ms delta=5s 2µs 60ns ago [INFO] [stdout] 2025-10-02T06:17:38.537342Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.003624, -5000.00206, -4999.998749, -5000.069395, -5000.2967] [INFO] [stdout] 2025-10-02T06:17:38.537368Z TRACE timesimp: statistics about response deltas median=-4999.998749 mean=-5000.0741056 variance=0.016351824561282043 stddev=0.12787425292560672 [INFO] [stdout] 2025-10-02T06:17:38.537393Z TRACE timesimp: eliminated outliers inliers=[-5000.003624, -5000.00206, -4999.998749, -5000.069395] [INFO] [stdout] 2025-10-02T06:17:38.537421Z DEBUG timesimp: storing calculated offset offset=5s 18µs ago [INFO] [stdout] test server_offset_negative ... ok [INFO] [stdout] 2025-10-02T06:17:39.593684Z TRACE new{response=Response { client: 2025-10-02T06:17:37.84658505Z, server: 2025-10-02T06:17:38.718653983Z } current=2025-10-02T06:17:39.593500906Z}: timesimp::delta: response processing internals latency=873ms 457µs 928ns local_at_midpoint=2025-10-02T06:17:38.720042978Z delta=1ms 388µs 995ns ago [INFO] [stdout] 2025-10-02T06:17:39.593772Z TRACE timesimp: obtained raw offset from server latency=873.457928ms delta=1ms 388µs 995ns ago [INFO] [stdout] 2025-10-02T06:17:39.593792Z TRACE timesimp: sleeping to spread out requests delay=1.095651249s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:42.423950Z TRACE new{response=Response { client: 2025-10-02T06:17:40.690718851Z, server: 2025-10-02T06:17:41.557678744Z } current=2025-10-02T06:17:42.423757857Z}: timesimp::delta: response processing internals latency=866ms 519µs 503ns local_at_midpoint=2025-10-02T06:17:41.557238354Z delta=440µs 390ns [INFO] [stdout] 2025-10-02T06:17:42.424038Z TRACE timesimp: obtained raw offset from server latency=866.519503ms delta=440µs 390ns [INFO] [stdout] 2025-10-02T06:17:42.424058Z TRACE timesimp: sleeping to spread out requests delay=172.964193ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.424285Z TRACE new{response=Response { client: 2025-10-02T06:17:42.597723281Z, server: 2025-10-02T06:17:43.512501623Z } current=2025-10-02T06:17:44.424102894Z}: timesimp::delta: response processing internals latency=913ms 189µs 806ns local_at_midpoint=2025-10-02T06:17:43.510913087Z delta=1ms 588µs 536ns [INFO] [stdout] 2025-10-02T06:17:44.424384Z TRACE timesimp: obtained raw offset from server latency=913.189806ms delta=1ms 588µs 536ns [INFO] [stdout] 2025-10-02T06:17:44.424433Z TRACE timesimp: response deltas sorted by latency deltas=[1.270406, 0.008856, 0.44039, -1.388995, 1.588536] [INFO] [stdout] 2025-10-02T06:17:44.424451Z TRACE timesimp: statistics about response deltas median=0.44039 mean=0.3838386 variance=1.3810116411858 stddev=1.1751645166468396 [INFO] [stdout] 2025-10-02T06:17:44.424468Z TRACE timesimp: eliminated outliers inliers=[1.270406, 0.008856, 0.44039, 1.588536] [INFO] [stdout] 2025-10-02T06:17:44.424479Z DEBUG timesimp: storing calculated offset offset=827µ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.96s [INFO] [stdout] [INFO] [stderr] Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-9d1c06fe72bb6515) [INFO] [stdout] [INFO] [stdout] running 4 tests [INFO] [stdout] 2025-10-02T06:17:44.564445Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:44.564545Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.564555Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago [INFO] [stdout] 2025-10-02T06:17:44.564612Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.564625Z TRACE timesimp: starting delta collection samples=5 current_offset=0s [INFO] [stdout] 2025-10-02T06:17:44.564648Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.566001Z TRACE new{response=Response { client: 2025-10-02T06:17:44.565815879Z, server: 2025-10-02T06:17:44.56582957Z } current=2025-10-02T06:17:44.565832539Z}: timesimp::delta: response processing internals latency=8µs 330ns local_at_midpoint=2025-10-02T06:17:44.565824209Z delta=5µs 361ns [INFO] [stdout] 2025-10-02T06:17:44.566015Z TRACE new{response=Response { client: 2025-10-02T06:17:44.565826019Z, server: 2025-10-02T06:17:39.56583423Z } current=2025-10-02T06:17:44.56583827Z}: timesimp::delta: response processing internals latency=6µs 125ns local_at_midpoint=2025-10-02T06:17:44.565832144Z delta=4s 999ms 997µs 914ns ago [INFO] [stdout] 2025-10-02T06:17:44.566069Z TRACE timesimp: obtained raw offset from server latency=8.33µs delta=5µs 361ns [INFO] [stdout] 2025-10-02T06:17:44.566081Z TRACE timesimp: obtained raw offset from server latency=6.125µs delta=4s 999ms 997µs 914ns ago [INFO] [stdout] 2025-10-02T06:17:44.566086Z TRACE timesimp: sleeping to spread out requests delay=1.616810381s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.566100Z TRACE timesimp: sleeping to spread out requests delay=1.053487175s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.566281Z TRACE new{response=Response { client: 2025-10-02T06:17:44.566188039Z, server: 2025-10-02T06:17:44.56619049Z } current=2025-10-02T06:17:44.566192059Z}: timesimp::delta: response processing internals latency=2µs 10ns local_at_midpoint=2025-10-02T06:17:44.566190049Z delta=441ns [INFO] [stdout] 2025-10-02T06:17:44.566325Z TRACE timesimp: obtained raw offset from server latency=2.01µs delta=441ns [INFO] [stdout] 2025-10-02T06:17:44.566351Z DEBUG timesimp: no offset stored, storing initial delta offset=441ns [INFO] [stdout] 2025-10-02T06:17:44.566375Z TRACE timesimp: sleeping to spread out requests delay=258.870616ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.566633Z TRACE timesimp: starting delta collection samples=5 current_offset=5s [INFO] [stdout] 2025-10-02T06:17:44.566664Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.568070Z TRACE new{response=Response { client: 2025-10-02T06:17:44.56796255Z, server: 2025-10-02T06:17:49.567965839Z } current=2025-10-02T06:17:44.567967759Z}: timesimp::delta: response processing internals latency=2µs 604ns local_at_midpoint=2025-10-02T06:17:44.567965154Z delta=5s 685ns [INFO] [stdout] 2025-10-02T06:17:44.568130Z TRACE timesimp: obtained raw offset from server latency=2.604µs delta=5s 685ns [INFO] [stdout] 2025-10-02T06:17:44.568145Z TRACE timesimp: sleeping to spread out requests delay=276.789474ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.826804Z TRACE new{response=Response { client: 2025-10-02T06:17:44.826623541Z, server: 2025-10-02T06:17:44.826634152Z } current=2025-10-02T06:17:44.826637651Z}: timesimp::delta: response processing internals latency=7µs 55ns local_at_midpoint=2025-10-02T06:17:44.826630596Z delta=3µs 556ns [INFO] [stdout] 2025-10-02T06:17:44.826884Z TRACE timesimp: obtained raw offset from server latency=7.055µs delta=3µs 556ns [INFO] [stdout] 2025-10-02T06:17:44.826901Z TRACE timesimp: sleeping to spread out requests delay=1.184023676s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:44.848434Z TRACE new{response=Response { client: 2025-10-02T06:17:44.848207191Z, server: 2025-10-02T06:17:49.848217851Z } current=2025-10-02T06:17:44.848222281Z}: timesimp::delta: response processing internals latency=7µs 545ns local_at_midpoint=2025-10-02T06:17:44.848214736Z delta=5s 3µs 115ns [INFO] [stdout] 2025-10-02T06:17:44.848533Z TRACE timesimp: obtained raw offset from server latency=7.545µs delta=5s 3µs 115ns [INFO] [stdout] 2025-10-02T06:17:44.848554Z TRACE timesimp: sleeping to spread out requests delay=673.076616ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:45.530691Z TRACE new{response=Response { client: 2025-10-02T06:17:45.530505309Z, server: 2025-10-02T06:17:50.530514739Z } current=2025-10-02T06:17:45.530518619Z}: timesimp::delta: response processing internals latency=6µs 655ns local_at_midpoint=2025-10-02T06:17:45.530511964Z delta=5s 2µs 775ns [INFO] [stdout] 2025-10-02T06:17:45.530764Z TRACE timesimp: obtained raw offset from server latency=6.655µs delta=5s 2µs 775ns [INFO] [stdout] 2025-10-02T06:17:45.530781Z TRACE timesimp: sleeping to spread out requests delay=1.513267816s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:45.622721Z TRACE new{response=Response { client: 2025-10-02T06:17:45.622517746Z, server: 2025-10-02T06:17:40.622528556Z } current=2025-10-02T06:17:45.622532996Z}: timesimp::delta: response processing internals latency=7µs 625ns local_at_midpoint=2025-10-02T06:17:45.622525371Z delta=4s 999ms 996µs 815ns ago [INFO] [stdout] 2025-10-02T06:17:45.622818Z TRACE timesimp: obtained raw offset from server latency=7.625µs delta=4s 999ms 996µs 815ns ago [INFO] [stdout] 2025-10-02T06:17:45.622841Z TRACE timesimp: sleeping to spread out requests delay=1.704177319s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:46.011817Z TRACE new{response=Response { client: 2025-10-02T06:17:46.011642294Z, server: 2025-10-02T06:17:46.011652195Z } current=2025-10-02T06:17:46.011655334Z}: timesimp::delta: response processing internals latency=6µs 520ns local_at_midpoint=2025-10-02T06:17:46.011648814Z delta=3µs 381ns [INFO] [stdout] 2025-10-02T06:17:46.011975Z TRACE timesimp: obtained raw offset from server latency=6.52µs delta=3µs 381ns [INFO] [stdout] 2025-10-02T06:17:46.012017Z TRACE timesimp: sleeping to spread out requests delay=1.119928616s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:46.186291Z TRACE new{response=Response { client: 2025-10-02T06:17:46.186114468Z, server: 2025-10-02T06:17:46.186125199Z } current=2025-10-02T06:17:46.186128719Z}: timesimp::delta: response processing internals latency=7µs 125ns local_at_midpoint=2025-10-02T06:17:46.186121593Z delta=3µs 606ns [INFO] [stdout] 2025-10-02T06:17:46.186379Z TRACE timesimp: obtained raw offset from server latency=7.125µs delta=3µs 606ns [INFO] [stdout] 2025-10-02T06:17:46.186396Z TRACE timesimp: sleeping to spread out requests delay=1.79789866s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:47.045834Z TRACE new{response=Response { client: 2025-10-02T06:17:47.045651892Z, server: 2025-10-02T06:17:52.045661332Z } current=2025-10-02T06:17:47.045665252Z}: timesimp::delta: response processing internals latency=6µs 680ns local_at_midpoint=2025-10-02T06:17:47.045658572Z delta=5s 2µs 760ns [INFO] [stdout] 2025-10-02T06:17:47.045922Z TRACE timesimp: obtained raw offset from server latency=6.68µs delta=5s 2µs 760ns [INFO] [stdout] 2025-10-02T06:17:47.045941Z TRACE timesimp: sleeping to spread out requests delay=1.822523115s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:47.134225Z TRACE new{response=Response { client: 2025-10-02T06:17:47.134023579Z, server: 2025-10-02T06:17:47.13403505Z } current=2025-10-02T06:17:47.134038569Z}: timesimp::delta: response processing internals latency=7µs 495ns local_at_midpoint=2025-10-02T06:17:47.134031074Z delta=3µs 976ns [INFO] [stdout] 2025-10-02T06:17:47.134307Z TRACE timesimp: obtained raw offset from server latency=7.495µs delta=3µs 976ns [INFO] [stdout] 2025-10-02T06:17:47.134325Z TRACE timesimp: sleeping to spread out requests delay=1.279348328s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:47.327837Z TRACE new{response=Response { client: 2025-10-02T06:17:47.327656403Z, server: 2025-10-02T06:17:42.327666483Z } current=2025-10-02T06:17:47.327670403Z}: timesimp::delta: response processing internals latency=7µs local_at_midpoint=2025-10-02T06:17:47.327663403Z delta=4s 999ms 996µs 920ns ago [INFO] [stdout] 2025-10-02T06:17:47.327924Z TRACE timesimp: obtained raw offset from server latency=7µs delta=4s 999ms 996µs 920ns ago [INFO] [stdout] 2025-10-02T06:17:47.327942Z TRACE timesimp: sleeping to spread out requests delay=644.395725ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:47.973835Z TRACE new{response=Response { client: 2025-10-02T06:17:47.973651502Z, server: 2025-10-02T06:17:42.973661702Z } current=2025-10-02T06:17:47.973665972Z}: timesimp::delta: response processing internals latency=7µs 235ns local_at_midpoint=2025-10-02T06:17:47.973658737Z delta=4s 999ms 997µs 35ns ago [INFO] [stdout] 2025-10-02T06:17:47.973922Z TRACE timesimp: obtained raw offset from server latency=7.235µs delta=4s 999ms 997µs 35ns ago [INFO] [stdout] 2025-10-02T06:17:47.973943Z TRACE timesimp: sleeping to spread out requests delay=1.588287842s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:47.993696Z TRACE new{response=Response { client: 2025-10-02T06:17:47.993513972Z, server: 2025-10-02T06:17:47.993525462Z } current=2025-10-02T06:17:47.993529382Z}: timesimp::delta: response processing internals latency=7µs 705ns local_at_midpoint=2025-10-02T06:17:47.993521677Z delta=3µs 785ns [INFO] [stdout] 2025-10-02T06:17:47.993782Z TRACE timesimp: obtained raw offset from server latency=7.705µs delta=3µs 785ns [INFO] [stdout] 2025-10-02T06:17:47.993801Z TRACE timesimp: sleeping to spread out requests delay=1.595168426s max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:48.414832Z TRACE new{response=Response { client: 2025-10-02T06:17:48.414651669Z, server: 2025-10-02T06:17:48.41466307Z } current=2025-10-02T06:17:48.414666449Z}: timesimp::delta: response processing internals latency=7µs 390ns local_at_midpoint=2025-10-02T06:17:48.414659059Z delta=4µs 11ns [INFO] [stdout] 2025-10-02T06:17:48.414911Z TRACE timesimp: obtained raw offset from server latency=7.39µs delta=4µs 11ns [INFO] [stdout] 2025-10-02T06:17:48.414940Z TRACE timesimp: response deltas sorted by latency deltas=[0.000441, 0.003381, 0.003556, 0.004011, 0.003976] [INFO] [stdout] 2025-10-02T06:17:48.414957Z TRACE timesimp: statistics about response deltas median=0.003556 mean=0.003073 variance=2.2377075000000003e-6 stddev=0.0014958968881577366 [INFO] [stdout] 2025-10-02T06:17:48.414973Z TRACE timesimp: eliminated outliers inliers=[0.003381, 0.003556, 0.004011, 0.003976] [INFO] [stdout] 2025-10-02T06:17:48.414983Z DEBUG timesimp: storing calculated offset offset=3µs [INFO] [stdout] test null_offset ... ok [INFO] [stdout] 2025-10-02T06:17:48.869169Z TRACE new{response=Response { client: 2025-10-02T06:17:48.868962824Z, server: 2025-10-02T06:17:53.868974714Z } current=2025-10-02T06:17:48.868978574Z}: timesimp::delta: response processing internals latency=7µs 875ns local_at_midpoint=2025-10-02T06:17:48.868970699Z delta=5s 4µs 15ns [INFO] [stdout] 2025-10-02T06:17:48.869258Z TRACE timesimp: obtained raw offset from server latency=7.875µs delta=5s 4µs 15ns [INFO] [stdout] 2025-10-02T06:17:48.869286Z TRACE timesimp: response deltas sorted by latency deltas=[5000.000685, 5000.002775, 5000.00276, 5000.003115, 5000.004015] [INFO] [stdout] 2025-10-02T06:17:48.869305Z TRACE timesimp: statistics about response deltas median=5000.00276 mean=5000.00267 variance=1.491600000423949e-6 stddev=0.001221310771435325 [INFO] [stdout] 2025-10-02T06:17:48.869321Z TRACE timesimp: eliminated outliers inliers=[5000.002775, 5000.00276, 5000.003115] [INFO] [stdout] 2025-10-02T06:17:48.869332Z DEBUG timesimp: storing calculated offset offset=5s 2µs [INFO] [stdout] test positive_starting_offset ... ok [INFO] [stdout] 2025-10-02T06:17:49.563813Z TRACE new{response=Response { client: 2025-10-02T06:17:49.563627332Z, server: 2025-10-02T06:17:44.563637482Z } current=2025-10-02T06:17:49.563641092Z}: timesimp::delta: response processing internals latency=6µs 880ns local_at_midpoint=2025-10-02T06:17:49.563634212Z delta=4s 999ms 996µs 730ns ago [INFO] [stdout] 2025-10-02T06:17:49.563906Z TRACE timesimp: obtained raw offset from server latency=6.88µs delta=4s 999ms 996µs 730ns ago [INFO] [stdout] 2025-10-02T06:17:49.563931Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.997914, -4999.99673, -4999.99692, -4999.997035, -4999.996815] [INFO] [stdout] 2025-10-02T06:17:49.563946Z TRACE timesimp: statistics about response deltas median=-4999.99692 mean=-4999.997082799999 variance=2.2896669982283217e-7 stddev=0.0004785046497400335 [INFO] [stdout] 2025-10-02T06:17:49.563969Z TRACE timesimp: eliminated outliers inliers=[-4999.99673, -4999.99692, -4999.997035, -4999.996815] [INFO] [stdout] 2025-10-02T06:17:49.563980Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs ago [INFO] [stdout] test negative_starting_offset ... ok [INFO] [stdout] 2025-10-02T06:17:49.590691Z TRACE new{response=Response { client: 2025-10-02T06:17:49.590512872Z, server: 2025-10-02T06:17:49.590523492Z } current=2025-10-02T06:17:49.590527692Z}: timesimp::delta: response processing internals latency=7µs 410ns local_at_midpoint=2025-10-02T06:17:49.590520282Z delta=3µs 210ns [INFO] [stdout] 2025-10-02T06:17:49.590765Z TRACE timesimp: obtained raw offset from server latency=7.41µs delta=3µs 210ns [INFO] [stdout] 2025-10-02T06:17:49.590781Z TRACE timesimp: sleeping to spread out requests delay=617.471382ms max_jitter=2s [INFO] [stdout] 2025-10-02T06:17:50.215707Z TRACE new{response=Response { client: 2025-10-02T06:17:50.215520312Z, server: 2025-10-02T06:17:50.215530262Z } current=2025-10-02T06:17:50.215534502Z}: timesimp::delta: response processing internals latency=7µs 95ns local_at_midpoint=2025-10-02T06:17:50.215527407Z delta=2µs 855ns [INFO] [stderr] Doc-tests timesimp [INFO] [stdout] 2025-10-02T06:17:50.215794Z TRACE timesimp: obtained raw offset from server latency=7.095µs delta=2µs 855ns [INFO] [stdout] 2025-10-02T06:17:50.215822Z TRACE timesimp: response deltas sorted by latency deltas=[0.002855, 0.003606, 0.00321, 0.003785, 0.005361] [INFO] [stdout] 2025-10-02T06:17:50.215839Z TRACE timesimp: statistics about response deltas median=0.00321 mean=0.0037634 variance=9.272523000000003e-7 stddev=0.0009629394061933494 [INFO] [stdout] 2025-10-02T06:17:50.215854Z TRACE timesimp: eliminated outliers inliers=[0.002855, 0.003606, 0.00321, 0.003785] [INFO] [stdout] 2025-10-02T06:17:50.215863Z DEBUG timesimp: storing calculated offset offset=3µs [INFO] [stdout] test zero_offset ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.65s [INFO] [stdout] [INFO] [stdout] [INFO] [stdout] running 2 tests [INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored [INFO] [stdout] test src/lib.rs - (line 24) - compile ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s [INFO] [stdout] [INFO] running `Command { std: "docker" "inspect" "f47ab330ebd7c078febc3814d636471aad5b93f4ecc7bc871affb7b02ccb2817", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "f47ab330ebd7c078febc3814d636471aad5b93f4ecc7bc871affb7b02ccb2817", kill_on_drop: false }` [INFO] [stdout] f47ab330ebd7c078febc3814d636471aad5b93f4ecc7bc871affb7b02ccb2817