[INFO] cloning repository https://github.com/passcod/timesimp
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/passcod/timesimp" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 92be20531742c87fc283ec0ed2fc2aa3b1f638ae
[INFO] testing passcod/timesimp against master#ec6f9a5b4413f74386267ef8efc93712c2ce6db6 for pr-155739-1
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-4-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-4-tc1/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-4-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain ec6f9a5b4413f74386267ef8efc93712c2ce6db6
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate git repo https://github.com/passcod/timesimp 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" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded ctor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded napi-sys v3.0.0-alpha.1
[INFO] [stderr]   Downloaded ctor v0.4.2
[INFO] [stderr]   Downloaded dtor v0.0.6
[INFO] [stderr]   Downloaded dtor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded napi-build v2.1.6
[INFO] [stderr]   Downloaded napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]   Downloaded convert_case v0.8.0
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded napi-derive v3.0.0-alpha.29
[INFO] [stderr]   Downloaded napi v3.0.0-alpha.33
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb
[INFO] running `Command { std: "docker" "start" "-a" "cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb", kill_on_drop: false }`
[INFO] [stdout] cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f
[INFO] running `Command { std: "docker" "start" "-a" "2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[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 napi-derive-backend v2.0.0-alpha.28
[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 timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 27.81s
[INFO] running `Command { std: "docker" "inspect" "2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f", kill_on_drop: false }`
[INFO] [stdout] 2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7
[INFO] running `Command { std: "docker" "start" "-a" "6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[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 zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[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 icu_normalizer v1.5.0
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[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 h2 v0.4.9
[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]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 47.70s
[INFO] running `Command { std: "docker" "inspect" "6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7", kill_on_drop: false }`
[INFO] [stdout] 6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6
[INFO] running `Command { std: "docker" "start" "-a" "fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.31s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-7875ddb3df0d84b6)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.14s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-f04346ec9fba397a)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2026-05-15T02:52:13.221668Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.221733Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.221666Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.221758Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.221872Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.221903Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.221662Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-05-15T02:52:13.221958Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.222392Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.222430Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.222523Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.222598Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.226202Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.226338Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.233442Z TRACE new{response=Response { client: 2026-05-15T02:52:13.227809347Z, server: 2026-05-15T02:52:13.230211947Z } current=2026-05-15T02:52:13.233225797Z}: timesimp::delta: response processing internals latency=2ms 708µs 225ns local_at_midpoint=2026-05-15T02:52:13.230517572Z delta=305µs 625ns ago
[INFO] [stdout] 2026-05-15T02:52:13.233538Z TRACE timesimp: obtained raw offset from server latency=2.708225ms delta=305µs 625ns ago
[INFO] [stdout] 2026-05-15T02:52:13.233567Z DEBUG timesimp: no offset stored, storing initial delta offset=305µs 625ns ago
[INFO] [stdout] 2026-05-15T02:52:13.233581Z TRACE timesimp: sleeping to spread out requests delay=100.274858ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.241509Z TRACE new{response=Response { client: 2026-05-15T02:52:13.223840647Z, server: 2026-05-15T02:52:18.229000787Z } current=2026-05-15T02:52:13.241281937Z}: timesimp::delta: response processing internals latency=8ms 720µs 645ns local_at_midpoint=2026-05-15T02:52:13.232561292Z delta=4s 996ms 439µs 495ns
[INFO] [stdout] 2026-05-15T02:52:13.241611Z TRACE timesimp: obtained raw offset from server latency=8.720645ms delta=4s 996ms 439µs 495ns
[INFO] [stdout] 2026-05-15T02:52:13.241635Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 996ms 439µs 495ns
[INFO] [stdout] 2026-05-15T02:52:13.241650Z TRACE timesimp: sleeping to spread out requests delay=1.947499777s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.245201Z TRACE new{response=Response { client: 2026-05-15T02:52:13.223626567Z, server: 2026-05-15T02:52:18.233763377Z } current=2026-05-15T02:52:13.244947207Z}: timesimp::delta: response processing internals latency=10ms 660µs 320ns local_at_midpoint=2026-05-15T02:52:13.234286887Z delta=4s 999ms 476µs 490ns
[INFO] [stdout] 2026-05-15T02:52:13.245297Z TRACE timesimp: obtained raw offset from server latency=10.66032ms delta=4s 999ms 476µs 490ns
[INFO] [stdout] 2026-05-15T02:52:13.245322Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 476µs 490ns
[INFO] [stdout] 2026-05-15T02:52:13.245340Z TRACE timesimp: sleeping to spread out requests delay=1.445663882s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.250225Z TRACE new{response=Response { client: 2026-05-15T02:52:13.227623967Z, server: 2026-05-15T02:52:08.238809827Z } current=2026-05-15T02:52:13.250000377Z}: timesimp::delta: response processing internals latency=11ms 188µs 205ns local_at_midpoint=2026-05-15T02:52:13.238812172Z delta=5s 2µs 345ns ago
[INFO] [stdout] 2026-05-15T02:52:13.250388Z TRACE timesimp: obtained raw offset from server latency=11.188205ms delta=5s 2µs 345ns ago
[INFO] [stdout] 2026-05-15T02:52:13.250614Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 2µs 345ns ago
[INFO] [stdout] 2026-05-15T02:52:13.250914Z TRACE timesimp: sleeping to spread out requests delay=942.412887ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.252005Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.252319Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-05-15T02:52:13.256211Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.256322Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.252526Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:13.256383Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.276256Z TRACE new{response=Response { client: 2026-05-15T02:52:13.257655257Z, server: 2026-05-15T02:52:18.266821726Z } current=2026-05-15T02:52:13.276005906Z}: timesimp::delta: response processing internals latency=9ms 175µs 324ns local_at_midpoint=2026-05-15T02:52:13.266830581Z delta=4s 999ms 991µs 145ns
[INFO] [stdout] 2026-05-15T02:52:13.276356Z TRACE timesimp: obtained raw offset from server latency=9.175324ms delta=4s 999ms 991µs 145ns
[INFO] [stdout] 2026-05-15T02:52:13.276382Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 991µs 145ns
[INFO] [stdout] 2026-05-15T02:52:13.276398Z TRACE timesimp: sleeping to spread out requests delay=1.778543963s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.279980Z TRACE new{response=Response { client: 2026-05-15T02:52:13.257575837Z, server: 2026-05-15T02:52:13.268705217Z } current=2026-05-15T02:52:13.279848466Z}: timesimp::delta: response processing internals latency=11ms 136µs 314ns local_at_midpoint=2026-05-15T02:52:13.268712151Z delta=6µs 934ns ago
[INFO] [stdout] 2026-05-15T02:52:13.280128Z TRACE timesimp: obtained raw offset from server latency=11.136314ms delta=6µs 934ns ago
[INFO] [stdout] 2026-05-15T02:52:13.280206Z TRACE timesimp: sleeping to spread out requests delay=520.484414ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.292189Z TRACE new{response=Response { client: 2026-05-15T02:52:13.223090927Z, server: 2026-05-15T02:52:18.234220927Z } current=2026-05-15T02:52:13.291960266Z}: timesimp::delta: response processing internals latency=34ms 434µs 669ns local_at_midpoint=2026-05-15T02:52:13.257525596Z delta=4s 976ms 695µs 331ns
[INFO] [stdout] 2026-05-15T02:52:13.292389Z TRACE new{response=Response { client: 2026-05-15T02:52:13.223183247Z, server: 2026-05-15T02:52:13.234290227Z } current=2026-05-15T02:52:13.292294076Z}: timesimp::delta: response processing internals latency=34ms 555µs 414ns local_at_midpoint=2026-05-15T02:52:13.257738661Z delta=23ms 448µs 434ns ago
[INFO] [stdout] 2026-05-15T02:52:13.292469Z TRACE timesimp: obtained raw offset from server latency=34.555414ms delta=23ms 448µs 434ns ago
[INFO] [stdout] 2026-05-15T02:52:13.292493Z TRACE timesimp: sleeping to spread out requests delay=451.041085ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.292562Z TRACE timesimp: obtained raw offset from server latency=34.434669ms delta=4s 976ms 695µs 331ns
[INFO] [stdout] 2026-05-15T02:52:13.292582Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 976ms 695µs 331ns
[INFO] [stdout] 2026-05-15T02:52:13.292595Z TRACE timesimp: sleeping to spread out requests delay=718.939152ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.337435Z TRACE new{response=Response { client: 2026-05-15T02:52:13.334985946Z, server: 2026-05-15T02:52:13.336131666Z } current=2026-05-15T02:52:13.337271476Z}: timesimp::delta: response processing internals latency=1ms 142µs 765ns local_at_midpoint=2026-05-15T02:52:13.336128711Z delta=2µs 955ns
[INFO] [stdout] 2026-05-15T02:52:13.337532Z TRACE timesimp: obtained raw offset from server latency=1.142765ms delta=2µs 955ns
[INFO] [stdout] 2026-05-15T02:52:13.337554Z TRACE timesimp: sleeping to spread out requests delay=1.960373369s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.427462Z TRACE new{response=Response { client: 2026-05-15T02:52:13.222964437Z, server: 2026-05-15T02:52:13.325247876Z } current=2026-05-15T02:52:13.427250345Z}: timesimp::delta: response processing internals latency=102ms 142µs 954ns local_at_midpoint=2026-05-15T02:52:13.325107391Z delta=140µs 485ns
[INFO] [stdout] 2026-05-15T02:52:13.427558Z TRACE timesimp: obtained raw offset from server latency=102.142954ms delta=140µs 485ns
[INFO] [stdout] 2026-05-15T02:52:13.427583Z DEBUG timesimp: no offset stored, storing initial delta offset=140µs 485ns
[INFO] [stdout] 2026-05-15T02:52:13.427598Z TRACE timesimp: sleeping to spread out requests delay=771.011869ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.774001Z TRACE new{response=Response { client: 2026-05-15T02:52:13.745250091Z, server: 2026-05-15T02:52:13.762603411Z } current=2026-05-15T02:52:13.773812511Z}: timesimp::delta: response processing internals latency=14ms 281µs 210ns local_at_midpoint=2026-05-15T02:52:13.759531301Z delta=3ms 72µs 110ns
[INFO] [stdout] 2026-05-15T02:52:13.774098Z TRACE timesimp: obtained raw offset from server latency=14.28121ms delta=3ms 72µs 110ns
[INFO] [stdout] 2026-05-15T02:52:13.774124Z TRACE timesimp: sleeping to spread out requests delay=194.810775ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.824622Z TRACE new{response=Response { client: 2026-05-15T02:52:13.80204716Z, server: 2026-05-15T02:52:13.8132375Z } current=2026-05-15T02:52:13.82442843Z}: timesimp::delta: response processing internals latency=11ms 190µs 635ns local_at_midpoint=2026-05-15T02:52:13.813237795Z delta=295ns ago
[INFO] [stdout] 2026-05-15T02:52:13.824720Z TRACE timesimp: obtained raw offset from server latency=11.190635ms delta=295ns ago
[INFO] [stdout] 2026-05-15T02:52:13.824744Z TRACE timesimp: sleeping to spread out requests delay=862.687717ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:13.993569Z TRACE new{response=Response { client: 2026-05-15T02:52:13.969643708Z, server: 2026-05-15T02:52:13.982253458Z } current=2026-05-15T02:52:13.993396148Z}: timesimp::delta: response processing internals latency=11ms 876µs 220ns local_at_midpoint=2026-05-15T02:52:13.981519928Z delta=733µs 530ns
[INFO] [stdout] 2026-05-15T02:52:13.993744Z TRACE timesimp: obtained raw offset from server latency=11.87622ms delta=733µs 530ns
[INFO] [stdout] 2026-05-15T02:52:13.993822Z TRACE timesimp: sleeping to spread out requests delay=1.199666158s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:14.035040Z TRACE new{response=Response { client: 2026-05-15T02:52:14.012446768Z, server: 2026-05-15T02:52:19.023652308Z } current=2026-05-15T02:52:14.034857817Z}: timesimp::delta: response processing internals latency=11ms 205µs 524ns local_at_midpoint=2026-05-15T02:52:14.023652292Z delta=5s 16ns
[INFO] [stdout] 2026-05-15T02:52:14.035256Z TRACE timesimp: obtained raw offset from server latency=11.205524ms delta=5s 16ns
[INFO] [stdout] 2026-05-15T02:52:14.035336Z TRACE timesimp: sleeping to spread out requests delay=1.19202038s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:14.219420Z TRACE new{response=Response { client: 2026-05-15T02:52:14.196393506Z, server: 2026-05-15T02:52:09.207599915Z } current=2026-05-15T02:52:14.219247305Z}: timesimp::delta: response processing internals latency=11ms 426µs 899ns local_at_midpoint=2026-05-15T02:52:14.207820405Z delta=5s 220µs 490ns ago
[INFO] [stdout] 2026-05-15T02:52:14.219514Z TRACE timesimp: obtained raw offset from server latency=11.426899ms delta=5s 220µs 490ns ago
[INFO] [stdout] 2026-05-15T02:52:14.219537Z TRACE timesimp: sleeping to spread out requests delay=1.198438158s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:14.403287Z TRACE new{response=Response { client: 2026-05-15T02:52:14.200378815Z, server: 2026-05-15T02:52:14.301718034Z } current=2026-05-15T02:52:14.403076263Z}: timesimp::delta: response processing internals latency=101ms 348µs 724ns local_at_midpoint=2026-05-15T02:52:14.301727539Z delta=9µs 505ns ago
[INFO] [stdout] 2026-05-15T02:52:14.403377Z TRACE timesimp: obtained raw offset from server latency=101.348724ms delta=9µs 505ns ago
[INFO] [stdout] 2026-05-15T02:52:14.403401Z TRACE timesimp: sleeping to spread out requests delay=1.171020175s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:14.712439Z TRACE new{response=Response { client: 2026-05-15T02:52:14.68940636Z, server: 2026-05-15T02:52:14.70061045Z } current=2026-05-15T02:52:14.712249129Z}: timesimp::delta: response processing internals latency=11ms 421µs 384ns local_at_midpoint=2026-05-15T02:52:14.700827744Z delta=217µs 294ns ago
[INFO] [stdout] 2026-05-15T02:52:14.712555Z TRACE timesimp: obtained raw offset from server latency=11.421384ms delta=217µs 294ns ago
[INFO] [stdout] 2026-05-15T02:52:14.712582Z TRACE timesimp: sleeping to spread out requests delay=1.029600699s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:14.715913Z TRACE new{response=Response { client: 2026-05-15T02:52:14.69424317Z, server: 2026-05-15T02:52:19.704537529Z } current=2026-05-15T02:52:14.715737409Z}: timesimp::delta: response processing internals latency=10ms 747µs 119ns local_at_midpoint=2026-05-15T02:52:14.704990289Z delta=4s 999ms 547µs 240ns
[INFO] [stdout] 2026-05-15T02:52:14.716008Z TRACE timesimp: obtained raw offset from server latency=10.747119ms delta=4s 999ms 547µs 240ns
[INFO] [stdout] 2026-05-15T02:52:14.716032Z TRACE timesimp: sleeping to spread out requests delay=114.821889ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:14.852988Z TRACE new{response=Response { client: 2026-05-15T02:52:14.832386848Z, server: 2026-05-15T02:52:19.842590688Z } current=2026-05-15T02:52:14.852799968Z}: timesimp::delta: response processing internals latency=10ms 206µs 560ns local_at_midpoint=2026-05-15T02:52:14.842593408Z delta=4s 999ms 997µs 280ns
[INFO] [stdout] 2026-05-15T02:52:14.853078Z TRACE timesimp: obtained raw offset from server latency=10.20656ms delta=4s 999ms 997µs 280ns
[INFO] [stdout] 2026-05-15T02:52:14.853101Z TRACE timesimp: sleeping to spread out requests delay=1.034192331s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.076430Z TRACE new{response=Response { client: 2026-05-15T02:52:15.058251996Z, server: 2026-05-15T02:52:20.067239635Z } current=2026-05-15T02:52:15.076245015Z}: timesimp::delta: response processing internals latency=8ms 996µs 509ns local_at_midpoint=2026-05-15T02:52:15.067248505Z delta=4s 999ms 991µs 130ns
[INFO] [stdout] 2026-05-15T02:52:15.076537Z TRACE timesimp: obtained raw offset from server latency=8.996509ms delta=4s 999ms 991µs 130ns
[INFO] [stdout] 2026-05-15T02:52:15.076562Z TRACE timesimp: sleeping to spread out requests delay=1.902537872s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.155464Z TRACE new{response=Response { client: 2026-05-15T02:52:13.257496937Z, server: 2026-05-15T02:52:14.205419255Z } current=2026-05-15T02:52:15.155254264Z}: timesimp::delta: response processing internals latency=948ms 878µs 663ns local_at_midpoint=2026-05-15T02:52:14.2063756Z delta=956µs 345ns ago
[INFO] [stdout] 2026-05-15T02:52:15.155562Z TRACE timesimp: obtained raw offset from server latency=948.878663ms delta=956µs 345ns ago
[INFO] [stdout] 2026-05-15T02:52:15.155586Z DEBUG timesimp: no offset stored, storing initial delta offset=956µs 345ns ago
[INFO] [stdout] 2026-05-15T02:52:15.155599Z TRACE timesimp: sleeping to spread out requests delay=328.330672ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.206966Z TRACE new{response=Response { client: 2026-05-15T02:52:15.190400244Z, server: 2026-05-15T02:52:20.198591614Z } current=2026-05-15T02:52:15.206781014Z}: timesimp::delta: response processing internals latency=8ms 190µs 385ns local_at_midpoint=2026-05-15T02:52:15.198590629Z delta=5s 985ns
[INFO] [stdout] 2026-05-15T02:52:15.207073Z TRACE timesimp: obtained raw offset from server latency=8.190385ms delta=5s 985ns
[INFO] [stdout] 2026-05-15T02:52:15.207103Z TRACE timesimp: sleeping to spread out requests delay=37.323695ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.218095Z TRACE new{response=Response { client: 2026-05-15T02:52:15.195402264Z, server: 2026-05-15T02:52:15.206726834Z } current=2026-05-15T02:52:15.217919634Z}: timesimp::delta: response processing internals latency=11ms 258µs 685ns local_at_midpoint=2026-05-15T02:52:15.206660949Z delta=65µs 885ns
[INFO] [stdout] 2026-05-15T02:52:15.218217Z TRACE timesimp: obtained raw offset from server latency=11.258685ms delta=65µs 885ns
[INFO] [stdout] 2026-05-15T02:52:15.218241Z TRACE timesimp: sleeping to spread out requests delay=620.587142ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.251110Z TRACE new{response=Response { client: 2026-05-15T02:52:15.228525423Z, server: 2026-05-15T02:52:20.239721693Z } current=2026-05-15T02:52:15.250925873Z}: timesimp::delta: response processing internals latency=11ms 200µs 225ns local_at_midpoint=2026-05-15T02:52:15.239725648Z delta=4s 999ms 996µs 45ns
[INFO] [stdout] 2026-05-15T02:52:15.251254Z TRACE timesimp: obtained raw offset from server latency=11.200225ms delta=4s 999ms 996µs 45ns
[INFO] [stdout] 2026-05-15T02:52:15.251278Z TRACE timesimp: sleeping to spread out requests delay=633.904248ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.258845Z TRACE new{response=Response { client: 2026-05-15T02:52:15.246355333Z, server: 2026-05-15T02:52:20.252526673Z } current=2026-05-15T02:52:15.258678583Z}: timesimp::delta: response processing internals latency=6ms 161µs 625ns local_at_midpoint=2026-05-15T02:52:15.252516958Z delta=5s 9µs 715ns
[INFO] [stdout] 2026-05-15T02:52:15.258930Z TRACE timesimp: obtained raw offset from server latency=6.161625ms delta=5s 9µs 715ns
[INFO] [stdout] 2026-05-15T02:52:15.258950Z TRACE timesimp: sleeping to spread out requests delay=1.79484218s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.302018Z TRACE new{response=Response { client: 2026-05-15T02:52:15.299533433Z, server: 2026-05-15T02:52:15.300692473Z } current=2026-05-15T02:52:15.301828823Z}: timesimp::delta: response processing internals latency=1ms 147µs 695ns local_at_midpoint=2026-05-15T02:52:15.300681128Z delta=11µs 345ns
[INFO] [stdout] 2026-05-15T02:52:15.302244Z TRACE timesimp: obtained raw offset from server latency=1.147695ms delta=11µs 345ns
[INFO] [stdout] 2026-05-15T02:52:15.302285Z TRACE timesimp: sleeping to spread out requests delay=1.446394315s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.442649Z TRACE new{response=Response { client: 2026-05-15T02:52:15.419398091Z, server: 2026-05-15T02:52:10.431275231Z } current=2026-05-15T02:52:15.442474581Z}: timesimp::delta: response processing internals latency=11ms 538µs 245ns local_at_midpoint=2026-05-15T02:52:15.430936336Z delta=4s 999ms 661µs 105ns ago
[INFO] [stdout] 2026-05-15T02:52:15.442745Z TRACE timesimp: obtained raw offset from server latency=11.538245ms delta=4s 999ms 661µs 105ns ago
[INFO] [stdout] 2026-05-15T02:52:15.442771Z TRACE timesimp: sleeping to spread out requests delay=1.976376098s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.778427Z TRACE new{response=Response { client: 2026-05-15T02:52:15.748253317Z, server: 2026-05-15T02:52:15.763247817Z } current=2026-05-15T02:52:15.778250437Z}: timesimp::delta: response processing internals latency=14ms 998µs 560ns local_at_midpoint=2026-05-15T02:52:15.763251877Z delta=4µs 60ns ago
[INFO] [stdout] 2026-05-15T02:52:15.778522Z TRACE timesimp: obtained raw offset from server latency=14.99856ms delta=4µs 60ns ago
[INFO] [stdout] 2026-05-15T02:52:15.778542Z TRACE timesimp: sleeping to spread out requests delay=259.869755ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.789425Z TRACE new{response=Response { client: 2026-05-15T02:52:15.581253539Z, server: 2026-05-15T02:52:15.687246998Z } current=2026-05-15T02:52:15.789237957Z}: timesimp::delta: response processing internals latency=103ms 992µs 209ns local_at_midpoint=2026-05-15T02:52:15.685245748Z delta=2ms 1µs 250ns
[INFO] [stdout] 2026-05-15T02:52:15.789534Z TRACE timesimp: obtained raw offset from server latency=103.992209ms delta=2ms 1µs 250ns
[INFO] [stdout] 2026-05-15T02:52:15.789557Z TRACE timesimp: sleeping to spread out requests delay=1.634780818s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.863079Z TRACE new{response=Response { client: 2026-05-15T02:52:15.840398826Z, server: 2026-05-15T02:52:15.851715566Z } current=2026-05-15T02:52:15.862908256Z}: timesimp::delta: response processing internals latency=11ms 254µs 715ns local_at_midpoint=2026-05-15T02:52:15.851653541Z delta=62µs 25ns
[INFO] [stdout] 2026-05-15T02:52:15.863189Z TRACE timesimp: obtained raw offset from server latency=11.254715ms delta=62µs 25ns
[INFO] [stdout] 2026-05-15T02:52:15.863268Z TRACE timesimp: response deltas sorted by latency deltas=[0.062025, 0.065885, 0.73353, 3.07211, -23.448434]
[INFO] [stdout] 2026-05-15T02:52:15.863319Z TRACE timesimp: statistics about response deltas median=0.73353 mean=-3.9029768 variance=120.91175789812868 stddev=10.995988263822797
[INFO] [stdout] 2026-05-15T02:52:15.863347Z TRACE timesimp: eliminated outliers inliers=[0.062025, 0.065885, 0.73353, 3.07211]
[INFO] [stdout] 2026-05-15T02:52:15.863362Z DEBUG timesimp: storing calculated offset offset=983µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2026-05-15T02:52:15.908741Z TRACE new{response=Response { client: 2026-05-15T02:52:15.886168566Z, server: 2026-05-15T02:52:20.897367626Z } current=2026-05-15T02:52:15.908567655Z}: timesimp::delta: response processing internals latency=11ms 199µs 544ns local_at_midpoint=2026-05-15T02:52:15.89736811Z delta=4s 999ms 999µs 516ns
[INFO] [stdout] 2026-05-15T02:52:15.908829Z TRACE timesimp: obtained raw offset from server latency=11.199544ms delta=4s 999ms 999µs 516ns
[INFO] [stdout] 2026-05-15T02:52:15.908853Z TRACE timesimp: sleeping to spread out requests delay=907.571486ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:15.911032Z TRACE new{response=Response { client: 2026-05-15T02:52:15.888402256Z, server: 2026-05-15T02:52:20.899619726Z } current=2026-05-15T02:52:15.910836226Z}: timesimp::delta: response processing internals latency=11ms 216µs 985ns local_at_midpoint=2026-05-15T02:52:15.899619241Z delta=5s 485ns
[INFO] [stdout] 2026-05-15T02:52:15.911188Z TRACE timesimp: obtained raw offset from server latency=11.216985ms delta=5s 485ns
[INFO] [stdout] 2026-05-15T02:52:15.911215Z TRACE timesimp: sleeping to spread out requests delay=1.015196645s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:16.062674Z TRACE new{response=Response { client: 2026-05-15T02:52:16.040089144Z, server: 2026-05-15T02:52:16.051282664Z } current=2026-05-15T02:52:16.062491204Z}: timesimp::delta: response processing internals latency=11ms 201µs 30ns local_at_midpoint=2026-05-15T02:52:16.051290174Z delta=7µs 510ns ago
[INFO] [stdout] 2026-05-15T02:52:16.062845Z TRACE timesimp: obtained raw offset from server latency=11.20103ms delta=7µs 510ns ago
[INFO] [stdout] 2026-05-15T02:52:16.062942Z TRACE timesimp: response deltas sorted by latency deltas=[-0.006934, -0.000295, -0.00751, -0.217294, -0.00406]
[INFO] [stdout] 2026-05-15T02:52:16.063020Z TRACE timesimp: statistics about response deltas median=-0.00751 mean=-0.0472186 variance=0.009047438146799999 stddev=0.0951180221976887
[INFO] [stdout] 2026-05-15T02:52:16.063100Z TRACE timesimp: eliminated outliers inliers=[-0.006934, -0.000295, -0.00751, -0.00406]
[INFO] [stdout] 2026-05-15T02:52:16.063186Z DEBUG timesimp: storing calculated offset offset=4µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2026-05-15T02:52:16.752861Z TRACE new{response=Response { client: 2026-05-15T02:52:16.750413706Z, server: 2026-05-15T02:52:16.751566386Z } current=2026-05-15T02:52:16.752683585Z}: timesimp::delta: response processing internals latency=1ms 134µs 939ns local_at_midpoint=2026-05-15T02:52:16.751548645Z delta=17µs 741ns
[INFO] [stdout] 2026-05-15T02:52:16.752956Z TRACE timesimp: obtained raw offset from server latency=1.134939ms delta=17µs 741ns
[INFO] [stdout] 2026-05-15T02:52:16.752978Z TRACE timesimp: sleeping to spread out requests delay=154.821715ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:16.842844Z TRACE new{response=Response { client: 2026-05-15T02:52:16.820256475Z, server: 2026-05-15T02:52:21.831470225Z } current=2026-05-15T02:52:16.842673795Z}: timesimp::delta: response processing internals latency=11ms 208µs 660ns local_at_midpoint=2026-05-15T02:52:16.831465135Z delta=5s 5µs 90ns
[INFO] [stdout] 2026-05-15T02:52:16.842930Z TRACE timesimp: obtained raw offset from server latency=11.20866ms delta=5s 5µs 90ns
[INFO] [stdout] 2026-05-15T02:52:16.842957Z TRACE timesimp: response deltas sorted by latency deltas=[4999.999516, 4999.996045, 5000.000016, 5000.00509, 4976.695331]
[INFO] [stdout] 2026-05-15T02:52:16.842974Z TRACE timesimp: statistics about response deltas median=5000.000016 mean=4995.3391996 variance=108.62308428524872 stddev=10.422239888107006
[INFO] [stdout] 2026-05-15T02:52:16.842991Z TRACE timesimp: eliminated outliers inliers=[4999.999516, 4999.996045, 5000.000016, 5000.00509]
[INFO] [stdout] 2026-05-15T02:52:16.843007Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2026-05-15T02:52:16.913737Z TRACE new{response=Response { client: 2026-05-15T02:52:16.911294444Z, server: 2026-05-15T02:52:16.912444674Z } current=2026-05-15T02:52:16.913571554Z}: timesimp::delta: response processing internals latency=1ms 138µs 555ns local_at_midpoint=2026-05-15T02:52:16.912432999Z delta=11µs 675ns
[INFO] [stdout] 2026-05-15T02:52:16.913836Z TRACE timesimp: obtained raw offset from server latency=1.138555ms delta=11µs 675ns
[INFO] [stdout] 2026-05-15T02:52:16.913865Z TRACE timesimp: response deltas sorted by latency deltas=[0.017741, 0.011675, 0.002955, 0.011345, -0.305625]
[INFO] [stdout] 2026-05-15T02:52:16.913884Z TRACE timesimp: statistics about response deltas median=0.002955 mean=-0.0523818 variance=0.0200689663812 stddev=0.14166497937457936
[INFO] [stdout] 2026-05-15T02:52:16.913904Z TRACE timesimp: eliminated outliers inliers=[0.017741, 0.011675, 0.002955, 0.011345]
[INFO] [stdout] 2026-05-15T02:52:16.913918Z DEBUG timesimp: storing calculated offset offset=10µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2026-05-15T02:52:16.950995Z TRACE new{response=Response { client: 2026-05-15T02:52:16.930248143Z, server: 2026-05-15T02:52:21.940597283Z } current=2026-05-15T02:52:16.950807183Z}: timesimp::delta: response processing internals latency=10ms 279µs 520ns local_at_midpoint=2026-05-15T02:52:16.940527663Z delta=5s 69µs 620ns
[INFO] [stdout] 2026-05-15T02:52:16.951090Z TRACE timesimp: obtained raw offset from server latency=10.27952ms delta=5s 69µs 620ns
[INFO] [stdout] 2026-05-15T02:52:16.951122Z TRACE timesimp: response deltas sorted by latency deltas=[4999.99728, 5000.06962, 4999.47649, 4999.54724, 5000.000485]
[INFO] [stdout] 2026-05-15T02:52:16.951190Z TRACE timesimp: statistics about response deltas median=4999.47649 mean=4999.818223 variance=0.07967363176996609 stddev=0.28226517987517713
[INFO] [stdout] 2026-05-15T02:52:16.951221Z TRACE timesimp: eliminated outliers inliers=[4999.47649, 4999.54724]
[INFO] [stdout] 2026-05-15T02:52:16.951235Z DEBUG timesimp: storing calculated offset offset=4s 999ms 511µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2026-05-15T02:52:17.011461Z TRACE new{response=Response { client: 2026-05-15T02:52:16.984261603Z, server: 2026-05-15T02:52:21.999257783Z } current=2026-05-15T02:52:17.011268082Z}: timesimp::delta: response processing internals latency=13ms 503µs 239ns local_at_midpoint=2026-05-15T02:52:16.997764842Z delta=5s 1ms 492µs 941ns
[INFO] [stdout] 2026-05-15T02:52:17.011625Z TRACE timesimp: obtained raw offset from server latency=13.503239ms delta=5s 1ms 492µs 941ns
[INFO] [stdout] 2026-05-15T02:52:17.011652Z TRACE timesimp: sleeping to spread out requests delay=1.545714985s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:17.030431Z TRACE new{response=Response { client: 2026-05-15T02:52:15.49024789Z, server: 2026-05-15T02:52:16.260404061Z } current=2026-05-15T02:52:17.030252752Z}: timesimp::delta: response processing internals latency=770ms 2µs 431ns local_at_midpoint=2026-05-15T02:52:16.260250321Z delta=153µs 740ns
[INFO] [stdout] 2026-05-15T02:52:17.030531Z TRACE timesimp: obtained raw offset from server latency=770.002431ms delta=153µs 740ns
[INFO] [stdout] 2026-05-15T02:52:17.030582Z TRACE timesimp: sleeping to spread out requests delay=1.162388651s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:17.069953Z TRACE new{response=Response { client: 2026-05-15T02:52:17.055369402Z, server: 2026-05-15T02:52:22.062576302Z } current=2026-05-15T02:52:17.069778372Z}: timesimp::delta: response processing internals latency=7ms 204µs 485ns local_at_midpoint=2026-05-15T02:52:17.062573887Z delta=5s 2µs 415ns
[INFO] [stdout] 2026-05-15T02:52:17.070044Z TRACE timesimp: obtained raw offset from server latency=7.204485ms delta=5s 2µs 415ns
[INFO] [stdout] 2026-05-15T02:52:17.070066Z TRACE timesimp: sleeping to spread out requests delay=1.595493761s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:17.443175Z TRACE new{response=Response { client: 2026-05-15T02:52:17.420558308Z, server: 2026-05-15T02:52:12.431759568Z } current=2026-05-15T02:52:17.442962167Z}: timesimp::delta: response processing internals latency=11ms 201µs 929ns local_at_midpoint=2026-05-15T02:52:17.431760237Z delta=5s 669ns ago
[INFO] [stdout] 2026-05-15T02:52:17.443268Z TRACE timesimp: obtained raw offset from server latency=11.201929ms delta=5s 669ns ago
[INFO] [stdout] 2026-05-15T02:52:17.443291Z TRACE timesimp: sleeping to spread out requests delay=1.171019404s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:17.627502Z TRACE new{response=Response { client: 2026-05-15T02:52:17.425556168Z, server: 2026-05-15T02:52:17.525940636Z } current=2026-05-15T02:52:17.627313415Z}: timesimp::delta: response processing internals latency=100ms 878µs 623ns local_at_midpoint=2026-05-15T02:52:17.526434791Z delta=494µs 155ns ago
[INFO] [stdout] 2026-05-15T02:52:17.627595Z TRACE timesimp: obtained raw offset from server latency=100.878623ms delta=494µs 155ns ago
[INFO] [stdout] 2026-05-15T02:52:17.627618Z TRACE timesimp: sleeping to spread out requests delay=413.547176ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:18.244958Z TRACE new{response=Response { client: 2026-05-15T02:52:18.04234149Z, server: 2026-05-15T02:52:18.143393569Z } current=2026-05-15T02:52:18.244775008Z}: timesimp::delta: response processing internals latency=101ms 216µs 759ns local_at_midpoint=2026-05-15T02:52:18.143558249Z delta=164µs 680ns ago
[INFO] [stdout] 2026-05-15T02:52:18.245053Z TRACE timesimp: obtained raw offset from server latency=101.216759ms delta=164µs 680ns ago
[INFO] [stdout] 2026-05-15T02:52:18.245084Z TRACE timesimp: response deltas sorted by latency deltas=[-0.494155, -0.16468, -0.009505, 0.140485, 2.00125]
[INFO] [stdout] 2026-05-15T02:52:18.245104Z TRACE timesimp: statistics about response deltas median=-0.009505 mean=0.294679 variance=0.9654895109925004 stddev=0.9825932581656055
[INFO] [stdout] 2026-05-15T02:52:18.245124Z TRACE timesimp: eliminated outliers inliers=[-0.494155, -0.16468, -0.009505, 0.140485]
[INFO] [stdout] 2026-05-15T02:52:18.245170Z DEBUG timesimp: storing calculated offset offset=131µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2026-05-15T02:52:18.595433Z TRACE new{response=Response { client: 2026-05-15T02:52:18.565262824Z, server: 2026-05-15T02:52:23.580253024Z } current=2026-05-15T02:52:18.595251024Z}: timesimp::delta: response processing internals latency=14ms 994µs 100ns local_at_midpoint=2026-05-15T02:52:18.580256924Z delta=4s 999ms 996µs 100ns
[INFO] [stdout] 2026-05-15T02:52:18.595522Z TRACE timesimp: obtained raw offset from server latency=14.9941ms delta=4s 999ms 996µs 100ns
[INFO] [stdout] 2026-05-15T02:52:18.595545Z TRACE timesimp: sleeping to spread out requests delay=1.861868097s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:18.647439Z TRACE new{response=Response { client: 2026-05-15T02:52:18.620247234Z, server: 2026-05-15T02:52:13.635248873Z } current=2026-05-15T02:52:18.647258553Z}: timesimp::delta: response processing internals latency=13ms 505µs 659ns local_at_midpoint=2026-05-15T02:52:18.633752893Z delta=4s 998ms 504µs 20ns ago
[INFO] [stdout] 2026-05-15T02:52:18.647545Z TRACE timesimp: obtained raw offset from server latency=13.505659ms delta=4s 998ms 504µs 20ns ago
[INFO] [stdout] 2026-05-15T02:52:18.647575Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.002345, -5000.000669, -5000.22049, -4999.661105, -4998.50402]
[INFO] [stdout] 2026-05-15T02:52:18.647595Z TRACE timesimp: statistics about response deltas median=-5000.22049 mean=-4999.6777258 variance=0.4705311170454184 stddev=0.6859527075866225
[INFO] [stdout] 2026-05-15T02:52:18.647614Z TRACE timesimp: eliminated outliers inliers=[-5000.002345, -5000.000669, -5000.22049, -4999.661105]
[INFO] [stdout] 2026-05-15T02:52:18.647626Z DEBUG timesimp: storing calculated offset offset=4s 999ms 971µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2026-05-15T02:52:18.675955Z TRACE new{response=Response { client: 2026-05-15T02:52:18.667389923Z, server: 2026-05-15T02:52:23.671581193Z } current=2026-05-15T02:52:18.675777583Z}: timesimp::delta: response processing internals latency=4ms 193µs 830ns local_at_midpoint=2026-05-15T02:52:18.671583753Z delta=4s 999ms 997µs 440ns
[INFO] [stdout] 2026-05-15T02:52:18.676051Z TRACE timesimp: obtained raw offset from server latency=4.19383ms delta=4s 999ms 997µs 440ns
[INFO] [stdout] 2026-05-15T02:52:18.676080Z TRACE timesimp: response deltas sorted by latency deltas=[4999.99744, 5000.009715, 5000.002415, 5000.000985, 4996.439495]
[INFO] [stdout] 2026-05-15T02:52:18.676100Z TRACE timesimp: statistics about response deltas median=5000.002415 mean=4999.290009999999 variance=2.539218647950479 stddev=1.5934925942565528
[INFO] [stdout] 2026-05-15T02:52:18.676131Z TRACE timesimp: eliminated outliers inliers=[4999.99744, 5000.009715, 5000.002415, 5000.000985]
[INFO] [stdout] 2026-05-15T02:52:18.676169Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2026-05-15T02:52:19.678589Z TRACE new{response=Response { client: 2026-05-15T02:52:18.194430228Z, server: 2026-05-15T02:52:18.93640975Z } current=2026-05-15T02:52:19.678406161Z}: timesimp::delta: response processing internals latency=741ms 987µs 966ns local_at_midpoint=2026-05-15T02:52:18.936418194Z delta=8µs 444ns ago
[INFO] [stdout] 2026-05-15T02:52:19.678677Z TRACE timesimp: obtained raw offset from server latency=741.987966ms delta=8µs 444ns ago
[INFO] [stdout] 2026-05-15T02:52:19.678699Z TRACE timesimp: sleeping to spread out requests delay=1.968518598s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:20.474993Z TRACE new{response=Response { client: 2026-05-15T02:52:20.458390032Z, server: 2026-05-15T02:52:25.466609052Z } current=2026-05-15T02:52:20.474804081Z}: timesimp::delta: response processing internals latency=8ms 207µs 24ns local_at_midpoint=2026-05-15T02:52:20.466597056Z delta=5s 11µs 996ns
[INFO] [stdout] 2026-05-15T02:52:20.475170Z TRACE timesimp: obtained raw offset from server latency=8.207024ms delta=5s 11µs 996ns
[INFO] [stdout] 2026-05-15T02:52:20.475244Z TRACE timesimp: response deltas sorted by latency deltas=[5000.011996, 4999.99113, 4999.991145, 5001.492941, 4999.9961]
[INFO] [stdout] 2026-05-15T02:52:20.475287Z TRACE timesimp: statistics about response deltas median=4999.991145 mean=5000.2966624 variance=0.44728653338843993 stddev=0.668794836544392
[INFO] [stdout] 2026-05-15T02:52:20.475336Z TRACE timesimp: eliminated outliers inliers=[5000.011996, 4999.99113, 4999.991145, 4999.9961]
[INFO] [stdout] 2026-05-15T02:52:20.475371Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2026-05-15T02:52:23.302425Z TRACE new{response=Response { client: 2026-05-15T02:52:21.647684578Z, server: 2026-05-15T02:52:22.474372098Z } current=2026-05-15T02:52:23.302250638Z}: timesimp::delta: response processing internals latency=827ms 283µs 30ns local_at_midpoint=2026-05-15T02:52:22.474967608Z delta=595µs 510ns ago
[INFO] [stdout] 2026-05-15T02:52:23.302521Z TRACE timesimp: obtained raw offset from server latency=827.28303ms delta=595µs 510ns ago
[INFO] [stdout] 2026-05-15T02:52:23.302546Z TRACE timesimp: sleeping to spread out requests delay=289.395116ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.353531Z TRACE new{response=Response { client: 2026-05-15T02:52:23.593117825Z, server: 2026-05-15T02:52:24.473324614Z } current=2026-05-15T02:52:25.353353914Z}: timesimp::delta: response processing internals latency=880ms 118µs 44ns local_at_midpoint=2026-05-15T02:52:24.473235869Z delta=88µs 745ns
[INFO] [stdout] 2026-05-15T02:52:25.353621Z TRACE timesimp: obtained raw offset from server latency=880.118044ms delta=88µs 745ns
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-2e65c6dffb129287)
[INFO] [stdout] 2026-05-15T02:52:25.353651Z TRACE timesimp: response deltas sorted by latency deltas=[-0.008444, 0.15374, -0.59551, 0.088745, -0.956345]
[INFO] [stdout] 2026-05-15T02:52:25.353670Z TRACE timesimp: statistics about response deltas median=-0.59551 mean=-0.2635628 variance=0.2383710337917 stddev=0.4882325611752047
[INFO] [stdout] 2026-05-15T02:52:25.353688Z TRACE timesimp: eliminated outliers inliers=[-0.59551, -0.956345]
[INFO] [stdout] 2026-05-15T02:52:25.353700Z DEBUG timesimp: storing calculated offset offset=775µs ago
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.13s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2026-05-15T02:52:25.357823Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-05-15T02:52:25.357892Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.359316Z TRACE new{response=Response { client: 2026-05-15T02:52:25.359117054Z, server: 2026-05-15T02:52:20.359130994Z } current=2026-05-15T02:52:25.359151884Z}: timesimp::delta: response processing internals latency=17µs 415ns local_at_midpoint=2026-05-15T02:52:25.359134469Z delta=5s 3µs 475ns ago
[INFO] [stdout] 2026-05-15T02:52:25.357817Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:25.357828Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-05-15T02:52:25.361250Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.361306Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.357817Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:52:25.361196Z TRACE timesimp: obtained raw offset from server latency=17.415µs delta=5s 3µs 475ns ago
[INFO] [stdout] 2026-05-15T02:52:25.361429Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.361477Z TRACE timesimp: sleeping to spread out requests delay=680.056009ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.362694Z TRACE new{response=Response { client: 2026-05-15T02:52:25.362574014Z, server: 2026-05-15T02:52:30.362578584Z } current=2026-05-15T02:52:25.362581114Z}: timesimp::delta: response processing internals latency=3µs 550ns local_at_midpoint=2026-05-15T02:52:25.362577564Z delta=5s 1µs 20ns
[INFO] [stdout] 2026-05-15T02:52:25.362833Z TRACE new{response=Response { client: 2026-05-15T02:52:25.362728484Z, server: 2026-05-15T02:52:25.362731724Z } current=2026-05-15T02:52:25.362733564Z}: timesimp::delta: response processing internals latency=2µs 540ns local_at_midpoint=2026-05-15T02:52:25.362731024Z delta=700ns
[INFO] [stdout] 2026-05-15T02:52:25.362743Z TRACE new{response=Response { client: 2026-05-15T02:52:25.362578654Z, server: 2026-05-15T02:52:25.362581644Z } current=2026-05-15T02:52:25.362583574Z}: timesimp::delta: response processing internals latency=2µs 460ns local_at_midpoint=2026-05-15T02:52:25.362581114Z delta=530ns
[INFO] [stdout] 2026-05-15T02:52:25.362902Z TRACE timesimp: obtained raw offset from server latency=2.54µs delta=700ns
[INFO] [stdout] 2026-05-15T02:52:25.362928Z DEBUG timesimp: no offset stored, storing initial delta offset=700ns
[INFO] [stdout] 2026-05-15T02:52:25.362929Z TRACE timesimp: obtained raw offset from server latency=2.46µs delta=530ns
[INFO] [stdout] 2026-05-15T02:52:25.362942Z TRACE timesimp: sleeping to spread out requests delay=1.077825439s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.362950Z TRACE timesimp: sleeping to spread out requests delay=1.283191135s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:25.363131Z TRACE timesimp: obtained raw offset from server latency=3.55µs delta=5s 1µs 20ns
[INFO] [stdout] 2026-05-15T02:52:25.363445Z TRACE timesimp: sleeping to spread out requests delay=736.484551ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:26.043594Z TRACE new{response=Response { client: 2026-05-15T02:52:26.043407246Z, server: 2026-05-15T02:52:21.043417206Z } current=2026-05-15T02:52:26.043421255Z}: timesimp::delta: response processing internals latency=7µs 4ns local_at_midpoint=2026-05-15T02:52:26.04341425Z delta=4s 999ms 997µs 44ns ago
[INFO] [stdout] 2026-05-15T02:52:26.043688Z TRACE timesimp: obtained raw offset from server latency=7.004µs delta=4s 999ms 997µs 44ns ago
[INFO] [stdout] 2026-05-15T02:52:26.043714Z TRACE timesimp: sleeping to spread out requests delay=107.086848ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:26.109644Z TRACE new{response=Response { client: 2026-05-15T02:52:26.109452975Z, server: 2026-05-15T02:52:31.109463535Z } current=2026-05-15T02:52:26.109467995Z}: timesimp::delta: response processing internals latency=7µs 510ns local_at_midpoint=2026-05-15T02:52:26.109460485Z delta=5s 3µs 50ns
[INFO] [stdout] 2026-05-15T02:52:26.109735Z TRACE timesimp: obtained raw offset from server latency=7.51µs delta=5s 3µs 50ns
[INFO] [stdout] 2026-05-15T02:52:26.109759Z TRACE timesimp: sleeping to spread out requests delay=1.37233351s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:26.152566Z TRACE new{response=Response { client: 2026-05-15T02:52:26.152390674Z, server: 2026-05-15T02:52:21.152400134Z } current=2026-05-15T02:52:26.152403914Z}: timesimp::delta: response processing internals latency=6µs 620ns local_at_midpoint=2026-05-15T02:52:26.152397294Z delta=4s 999ms 997µs 160ns ago
[INFO] [stdout] 2026-05-15T02:52:26.152664Z TRACE timesimp: obtained raw offset from server latency=6.62µs delta=4s 999ms 997µs 160ns ago
[INFO] [stdout] 2026-05-15T02:52:26.152688Z TRACE timesimp: sleeping to spread out requests delay=1.945551935s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:26.442569Z TRACE new{response=Response { client: 2026-05-15T02:52:26.442399081Z, server: 2026-05-15T02:52:26.442409171Z } current=2026-05-15T02:52:26.442412351Z}: timesimp::delta: response processing internals latency=6µs 635ns local_at_midpoint=2026-05-15T02:52:26.442405716Z delta=3µs 455ns
[INFO] [stdout] 2026-05-15T02:52:26.442653Z TRACE timesimp: obtained raw offset from server latency=6.635µs delta=3µs 455ns
[INFO] [stdout] 2026-05-15T02:52:26.442675Z TRACE timesimp: sleeping to spread out requests delay=978.663563ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:26.647569Z TRACE new{response=Response { client: 2026-05-15T02:52:26.647393588Z, server: 2026-05-15T02:52:26.647403448Z } current=2026-05-15T02:52:26.647407088Z}: timesimp::delta: response processing internals latency=6µs 750ns local_at_midpoint=2026-05-15T02:52:26.647400338Z delta=3µs 110ns
[INFO] [stdout] 2026-05-15T02:52:26.647647Z TRACE timesimp: obtained raw offset from server latency=6.75µs delta=3µs 110ns
[INFO] [stdout] 2026-05-15T02:52:26.647667Z TRACE timesimp: sleeping to spread out requests delay=607.890212ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:27.257571Z TRACE new{response=Response { client: 2026-05-15T02:52:27.257387201Z, server: 2026-05-15T02:52:27.257396331Z } current=2026-05-15T02:52:27.257399711Z}: timesimp::delta: response processing internals latency=6µs 255ns local_at_midpoint=2026-05-15T02:52:27.257393456Z delta=2µs 875ns
[INFO] [stdout] 2026-05-15T02:52:27.257663Z TRACE timesimp: obtained raw offset from server latency=6.255µs delta=2µs 875ns
[INFO] [stdout] 2026-05-15T02:52:27.257687Z TRACE timesimp: sleeping to spread out requests delay=384.49282ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:27.422546Z TRACE new{response=Response { client: 2026-05-15T02:52:27.422379779Z, server: 2026-05-15T02:52:27.422389779Z } current=2026-05-15T02:52:27.422393029Z}: timesimp::delta: response processing internals latency=6µs 625ns local_at_midpoint=2026-05-15T02:52:27.422386404Z delta=3µs 375ns
[INFO] [stdout] 2026-05-15T02:52:27.422696Z TRACE timesimp: obtained raw offset from server latency=6.625µs delta=3µs 375ns
[INFO] [stdout] 2026-05-15T02:52:27.422740Z TRACE timesimp: sleeping to spread out requests delay=779.492542ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:27.483603Z TRACE new{response=Response { client: 2026-05-15T02:52:27.483427498Z, server: 2026-05-15T02:52:32.483436789Z } current=2026-05-15T02:52:27.483440629Z}: timesimp::delta: response processing internals latency=6µs 565ns local_at_midpoint=2026-05-15T02:52:27.483434063Z delta=5s 2µs 726ns
[INFO] [stdout] 2026-05-15T02:52:27.483688Z TRACE timesimp: obtained raw offset from server latency=6.565µs delta=5s 2µs 726ns
[INFO] [stdout] 2026-05-15T02:52:27.483710Z TRACE timesimp: sleeping to spread out requests delay=566.412426ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:27.643552Z TRACE new{response=Response { client: 2026-05-15T02:52:27.643357637Z, server: 2026-05-15T02:52:27.643367967Z } current=2026-05-15T02:52:27.643372777Z}: timesimp::delta: response processing internals latency=7µs 570ns local_at_midpoint=2026-05-15T02:52:27.643365207Z delta=2µs 760ns
[INFO] [stdout] 2026-05-15T02:52:27.643654Z TRACE timesimp: obtained raw offset from server latency=7.57µs delta=2µs 760ns
[INFO] [stdout] 2026-05-15T02:52:27.643680Z TRACE timesimp: sleeping to spread out requests delay=1.808144581s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:28.051600Z TRACE new{response=Response { client: 2026-05-15T02:52:28.051413842Z, server: 2026-05-15T02:52:33.051424542Z } current=2026-05-15T02:52:28.051428902Z}: timesimp::delta: response processing internals latency=7µs 530ns local_at_midpoint=2026-05-15T02:52:28.051421372Z delta=5s 3µs 170ns
[INFO] [stdout] 2026-05-15T02:52:28.051697Z TRACE timesimp: obtained raw offset from server latency=7.53µs delta=5s 3µs 170ns
[INFO] [stdout] 2026-05-15T02:52:28.051720Z TRACE timesimp: sleeping to spread out requests delay=183.439554ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:28.099563Z TRACE new{response=Response { client: 2026-05-15T02:52:28.099373541Z, server: 2026-05-15T02:52:23.099383671Z } current=2026-05-15T02:52:28.099387601Z}: timesimp::delta: response processing internals latency=7µs 30ns local_at_midpoint=2026-05-15T02:52:28.099380571Z delta=4s 999ms 996µs 900ns ago
[INFO] [stdout] 2026-05-15T02:52:28.099666Z TRACE timesimp: obtained raw offset from server latency=7.03µs delta=4s 999ms 996µs 900ns ago
[INFO] [stdout] 2026-05-15T02:52:28.099695Z TRACE timesimp: sleeping to spread out requests delay=1.956780714s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:28.203567Z TRACE new{response=Response { client: 2026-05-15T02:52:28.20338694Z, server: 2026-05-15T02:52:28.20339676Z } current=2026-05-15T02:52:28.20340009Z}: timesimp::delta: response processing internals latency=6µs 575ns local_at_midpoint=2026-05-15T02:52:28.203393515Z delta=3µs 245ns
[INFO] [stdout] 2026-05-15T02:52:28.206220Z TRACE timesimp: obtained raw offset from server latency=6.575µs delta=3µs 245ns
[INFO] [stdout] 2026-05-15T02:52:28.206267Z TRACE timesimp: sleeping to spread out requests delay=128.279835ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:52:28.236383Z TRACE new{response=Response { client: 2026-05-15T02:52:28.236199629Z, server: 2026-05-15T02:52:33.23620968Z } current=2026-05-15T02:52:28.23622184Z}: timesimp::delta: response processing internals latency=11µs 105ns local_at_midpoint=2026-05-15T02:52:28.236210734Z delta=4s 999ms 998µs 946ns
[INFO] [stdout] 2026-05-15T02:52:28.236472Z TRACE timesimp: obtained raw offset from server latency=11.105µs delta=4s 999ms 998µs 946ns
[INFO] [stdout] 2026-05-15T02:52:28.236505Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00102, 5000.002726, 5000.00305, 5000.00317, 4999.998946]
[INFO] [stdout] 2026-05-15T02:52:28.236528Z TRACE timesimp: statistics about response deltas median=5000.00305 mean=5000.0017824 variance=3.2622608005285327e-6 stddev=0.001806172970822156
[INFO] [stdout] 2026-05-15T02:52:28.236547Z TRACE timesimp: eliminated outliers inliers=[5000.002726, 5000.00305, 5000.00317]
[INFO] [stdout] 2026-05-15T02:52:28.236561Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2026-05-15T02:52:28.335873Z TRACE new{response=Response { client: 2026-05-15T02:52:28.335702088Z, server: 2026-05-15T02:52:28.335711699Z } current=2026-05-15T02:52:28.335714859Z}: timesimp::delta: response processing internals latency=6µs 385ns local_at_midpoint=2026-05-15T02:52:28.335708473Z delta=3µs 226ns
[INFO] [stdout] 2026-05-15T02:52:28.335961Z TRACE timesimp: obtained raw offset from server latency=6.385µs delta=3µs 226ns
[INFO] [stdout] 2026-05-15T02:52:28.335988Z TRACE timesimp: response deltas sorted by latency deltas=[0.0007, 0.003226, 0.003245, 0.003375, 0.003455]
[INFO] [stdout] 2026-05-15T02:52:28.336007Z TRACE timesimp: statistics about response deltas median=0.003245 mean=0.0028002 variance=1.3872876999999999e-6 stddev=0.0011778317791603348
[INFO] [stdout] 2026-05-15T02:52:28.336027Z TRACE timesimp: eliminated outliers inliers=[0.003226, 0.003245, 0.003375, 0.003455]
[INFO] [stdout] 2026-05-15T02:52:28.336040Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2026-05-15T02:52:29.453613Z TRACE new{response=Response { client: 2026-05-15T02:52:29.453437015Z, server: 2026-05-15T02:52:29.453446615Z } current=2026-05-15T02:52:29.453450725Z}: timesimp::delta: response processing internals latency=6µs 855ns local_at_midpoint=2026-05-15T02:52:29.45344387Z delta=2µs 745ns
[INFO] [stdout] 2026-05-15T02:52:29.453703Z TRACE timesimp: obtained raw offset from server latency=6.855µs delta=2µs 745ns
[INFO] [stdout] 2026-05-15T02:52:29.453729Z TRACE timesimp: response deltas sorted by latency deltas=[0.00053, 0.002875, 0.00311, 0.002745, 0.00276]
[INFO] [stdout] 2026-05-15T02:52:29.453749Z TRACE timesimp: statistics about response deltas median=0.00311 mean=0.0024040000000000003 variance=1.1187924999999997e-6 stddev=0.001057729880451526
[INFO] [stdout] 2026-05-15T02:52:29.453771Z TRACE timesimp: eliminated outliers inliers=[0.002875, 0.00311, 0.002745, 0.00276]
[INFO] [stdout] 2026-05-15T02:52:29.453802Z DEBUG timesimp: storing calculated offset offset=2µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2026-05-15T02:52:30.058293Z TRACE new{response=Response { client: 2026-05-15T02:52:30.058073728Z, server: 2026-05-15T02:52:25.058083128Z } current=2026-05-15T02:52:30.058087118Z}: timesimp::delta: response processing internals latency=6µs 695ns local_at_midpoint=2026-05-15T02:52:30.058080423Z delta=4s 999ms 997µs 295ns ago
[INFO] [stdout] 2026-05-15T02:52:30.058385Z TRACE timesimp: obtained raw offset from server latency=6.695µs delta=4s 999ms 997µs 295ns ago
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-f8424559dfcf15b0)
[INFO] [stdout] 2026-05-15T02:52:30.058413Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99716, -4999.997295, -4999.997044, -4999.9969, -5000.003475]
[INFO] [stdout] 2026-05-15T02:52:30.058432Z TRACE timesimp: statistics about response deltas median=-4999.997044 mean=-4999.9983748 variance=8.149952701215074e-6 stddev=0.0028548122006911546
[INFO] [stdout] 2026-05-15T02:52:30.058453Z TRACE timesimp: eliminated outliers inliers=[-4999.99716, -4999.997295, -4999.997044, -4999.9969]
[INFO] [stdout] 2026-05-15T02:52:30.058466Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.70s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/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] [stdout] all doctests ran in 1.67s; merged doctests compilation took 1.65s
[INFO] running `Command { std: "docker" "inspect" "fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6", kill_on_drop: false }`
[INFO] [stdout] fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6