[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 try#33835004928d3bf65db4d4712e1330766263b0bd 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-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-4-tc2/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-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 33835004928d3bf65db4d4712e1330766263b0bd
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+33835004928d3bf65db4d4712e1330766263b0bd" "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" "+33835004928d3bf65db4d4712e1330766263b0bd" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+33835004928d3bf65db4d4712e1330766263b0bd" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235
[INFO] running `Command { std: "docker" "start" "-a" "3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235", kill_on_drop: false }`
[INFO] [stdout] 3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+33835004928d3bf65db4d4712e1330766263b0bd" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15
[INFO] running `Command { std: "docker" "start" "-a" "91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15", 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 zerocopy v0.8.24
[INFO] [stderr]    Compiling getrandom v0.3.2
[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 ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[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-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[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 20.49s
[INFO] running `Command { std: "docker" "inspect" "91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15", kill_on_drop: false }`
[INFO] [stdout] 91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+33835004928d3bf65db4d4712e1330766263b0bd" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46
[INFO] running `Command { std: "docker" "start" "-a" "2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46", 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 icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling write16 v1.0.0
[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 overload v0.1.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling getrandom v0.3.2
[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 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 zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling thiserror v2.0.12
[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 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 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]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 31.37s
[INFO] running `Command { std: "docker" "inspect" "2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46", kill_on_drop: false }`
[INFO] [stdout] 2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+33835004928d3bf65db4d4712e1330766263b0bd" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21
[INFO] running `Command { std: "docker" "start" "-a" "0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.26s
[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_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-f04346ec9fba397a)
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2026-05-15T02:53:26.868738Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.868706Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.868704Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.868787Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.868788Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.868818Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.868694Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-05-15T02:53:26.868698Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.868864Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.868881Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.869343Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.872184Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.872571Z TRACE new{response=Response { client: 2026-05-15T02:53:26.870056931Z, server: 2026-05-15T02:53:26.871209561Z } current=2026-05-15T02:53:26.872333281Z}: timesimp::delta: response processing internals latency=1ms 138µs 175ns local_at_midpoint=2026-05-15T02:53:26.871195106Z delta=14µs 455ns
[INFO] [stdout] 2026-05-15T02:53:26.872657Z TRACE timesimp: obtained raw offset from server latency=1.138175ms delta=14µs 455ns
[INFO] [stdout] 2026-05-15T02:53:26.872686Z DEBUG timesimp: no offset stored, storing initial delta offset=14µs 455ns
[INFO] [stdout] 2026-05-15T02:53:26.872712Z TRACE timesimp: sleeping to spread out requests delay=110.994261ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.875498Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.875563Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.880543Z TRACE new{response=Response { client: 2026-05-15T02:53:26.870071811Z, server: 2026-05-15T02:53:31.875199761Z } current=2026-05-15T02:53:26.880336081Z}: timesimp::delta: response processing internals latency=5ms 132µs 135ns local_at_midpoint=2026-05-15T02:53:26.875203946Z delta=4s 999ms 995µs 815ns
[INFO] [stdout] 2026-05-15T02:53:26.880632Z TRACE timesimp: obtained raw offset from server latency=5.132135ms delta=4s 999ms 995µs 815ns
[INFO] [stdout] 2026-05-15T02:53:26.880658Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 995µs 815ns
[INFO] [stdout] 2026-05-15T02:53:26.880673Z TRACE timesimp: sleeping to spread out requests delay=1.187996066s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.870338Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-05-15T02:53:26.881052Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.870636Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.881805Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.888533Z TRACE new{response=Response { client: 2026-05-15T02:53:26.870017931Z, server: 2026-05-15T02:53:31.879183841Z } current=2026-05-15T02:53:26.88834702Z}: timesimp::delta: response processing internals latency=9ms 164µs 544ns local_at_midpoint=2026-05-15T02:53:26.879182475Z delta=5s 1µs 366ns
[INFO] [stdout] 2026-05-15T02:53:26.888695Z TRACE timesimp: obtained raw offset from server latency=9.164544ms delta=5s 1µs 366ns
[INFO] [stdout] 2026-05-15T02:53:26.888786Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 366ns
[INFO] [stdout] 2026-05-15T02:53:26.888866Z TRACE timesimp: sleeping to spread out requests delay=1.871090579s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.892493Z TRACE new{response=Response { client: 2026-05-15T02:53:26.870059031Z, server: 2026-05-15T02:53:26.881194491Z } current=2026-05-15T02:53:26.89234872Z}: timesimp::delta: response processing internals latency=11ms 144µs 844ns local_at_midpoint=2026-05-15T02:53:26.881203875Z delta=9µs 384ns ago
[INFO] [stdout] 2026-05-15T02:53:26.892618Z TRACE timesimp: obtained raw offset from server latency=11.144844ms delta=9µs 384ns ago
[INFO] [stdout] 2026-05-15T02:53:26.892672Z TRACE timesimp: sleeping to spread out requests delay=1.85183682s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.906442Z TRACE new{response=Response { client: 2026-05-15T02:53:26.882402201Z, server: 2026-05-15T02:53:26.8935424Z } current=2026-05-15T02:53:26.90624012Z}: timesimp::delta: response processing internals latency=11ms 918µs 959ns local_at_midpoint=2026-05-15T02:53:26.89432116Z delta=778µs 760ns ago
[INFO] [stdout] 2026-05-15T02:53:26.906530Z TRACE timesimp: obtained raw offset from server latency=11.918959ms delta=778µs 760ns ago
[INFO] [stdout] 2026-05-15T02:53:26.906552Z TRACE timesimp: sleeping to spread out requests delay=77.030649ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.907315Z TRACE new{response=Response { client: 2026-05-15T02:53:26.883513421Z, server: 2026-05-15T02:53:21.894625391Z } current=2026-05-15T02:53:26.90719632Z}: timesimp::delta: response processing internals latency=11ms 841µs 449ns local_at_midpoint=2026-05-15T02:53:26.89535487Z delta=5s 729µs 479ns ago
[INFO] [stdout] 2026-05-15T02:53:26.907373Z TRACE timesimp: obtained raw offset from server latency=11.841449ms delta=5s 729µs 479ns ago
[INFO] [stdout] 2026-05-15T02:53:26.907393Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 729µs 479ns ago
[INFO] [stdout] 2026-05-15T02:53:26.907407Z TRACE timesimp: sleeping to spread out requests delay=1.600639733s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.910593Z TRACE new{response=Response { client: 2026-05-15T02:53:26.882252861Z, server: 2026-05-15T02:53:31.900227491Z } current=2026-05-15T02:53:26.91038771Z}: timesimp::delta: response processing internals latency=14ms 67µs 424ns local_at_midpoint=2026-05-15T02:53:26.896320285Z delta=5s 3ms 907µs 206ns
[INFO] [stdout] 2026-05-15T02:53:26.910683Z TRACE timesimp: obtained raw offset from server latency=14.067424ms delta=5s 3ms 907µs 206ns
[INFO] [stdout] 2026-05-15T02:53:26.910707Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 3ms 907µs 206ns
[INFO] [stdout] 2026-05-15T02:53:26.910723Z TRACE timesimp: sleeping to spread out requests delay=870.793537ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.917378Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:26.917490Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.941866Z TRACE new{response=Response { client: 2026-05-15T02:53:26.91871397Z, server: 2026-05-15T02:53:31.92987538Z } current=2026-05-15T02:53:26.94156856Z}: timesimp::delta: response processing internals latency=11ms 427µs 295ns local_at_midpoint=2026-05-15T02:53:26.930141265Z delta=4s 999ms 734µs 115ns
[INFO] [stdout] 2026-05-15T02:53:26.942041Z TRACE timesimp: obtained raw offset from server latency=11.427295ms delta=4s 999ms 734µs 115ns
[INFO] [stdout] 2026-05-15T02:53:26.942100Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 734µs 115ns
[INFO] [stdout] 2026-05-15T02:53:26.942165Z TRACE timesimp: sleeping to spread out requests delay=75.138953ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:26.989501Z TRACE new{response=Response { client: 2026-05-15T02:53:26.98508333Z, server: 2026-05-15T02:53:26.98819839Z } current=2026-05-15T02:53:26.989337519Z}: timesimp::delta: response processing internals latency=2ms 127µs 94ns local_at_midpoint=2026-05-15T02:53:26.987210424Z delta=987µs 966ns
[INFO] [stdout] 2026-05-15T02:53:26.989594Z TRACE timesimp: obtained raw offset from server latency=2.127094ms delta=987µs 966ns
[INFO] [stdout] 2026-05-15T02:53:26.989617Z TRACE timesimp: sleeping to spread out requests delay=733.028927ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:27.016429Z TRACE new{response=Response { client: 2026-05-15T02:53:26.984877259Z, server: 2026-05-15T02:53:26.996067139Z } current=2026-05-15T02:53:27.016264899Z}: timesimp::delta: response processing internals latency=15ms 693µs 820ns local_at_midpoint=2026-05-15T02:53:27.000571079Z delta=4ms 503µs 940ns ago
[INFO] [stdout] 2026-05-15T02:53:27.016534Z TRACE timesimp: obtained raw offset from server latency=15.69382ms delta=4ms 503µs 940ns ago
[INFO] [stdout] 2026-05-15T02:53:27.016559Z TRACE timesimp: sleeping to spread out requests delay=839.267594ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:27.041060Z TRACE new{response=Response { client: 2026-05-15T02:53:27.018488909Z, server: 2026-05-15T02:53:32.029688529Z } current=2026-05-15T02:53:27.040886959Z}: timesimp::delta: response processing internals latency=11ms 199µs 25ns local_at_midpoint=2026-05-15T02:53:27.029687934Z delta=5s 595ns
[INFO] [stdout] 2026-05-15T02:53:27.041168Z TRACE timesimp: obtained raw offset from server latency=11.199025ms delta=5s 595ns
[INFO] [stdout] 2026-05-15T02:53:27.041193Z TRACE timesimp: sleeping to spread out requests delay=1.682898168s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:27.075449Z TRACE new{response=Response { client: 2026-05-15T02:53:26.870015321Z, server: 2026-05-15T02:53:26.97137285Z } current=2026-05-15T02:53:27.075245158Z}: timesimp::delta: response processing internals latency=102ms 614µs 918ns local_at_midpoint=2026-05-15T02:53:26.972630239Z delta=1ms 257µs 389ns ago
[INFO] [stdout] 2026-05-15T02:53:27.075553Z TRACE timesimp: obtained raw offset from server latency=102.614918ms delta=1ms 257µs 389ns ago
[INFO] [stdout] 2026-05-15T02:53:27.075577Z DEBUG timesimp: no offset stored, storing initial delta offset=1ms 257µs 389ns ago
[INFO] [stdout] 2026-05-15T02:53:27.075592Z TRACE timesimp: sleeping to spread out requests delay=1.814288493s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:27.726810Z TRACE new{response=Response { client: 2026-05-15T02:53:27.724401361Z, server: 2026-05-15T02:53:27.725534471Z } current=2026-05-15T02:53:27.726653371Z}: timesimp::delta: response processing internals latency=1ms 126µs 5ns local_at_midpoint=2026-05-15T02:53:27.725527366Z delta=7µs 105ns
[INFO] [stdout] 2026-05-15T02:53:27.726953Z TRACE timesimp: obtained raw offset from server latency=1.126005ms delta=7µs 105ns
[INFO] [stdout] 2026-05-15T02:53:27.727003Z TRACE timesimp: sleeping to spread out requests delay=1.260270107s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:27.805616Z TRACE new{response=Response { client: 2026-05-15T02:53:27.783422811Z, server: 2026-05-15T02:53:32.794241091Z } current=2026-05-15T02:53:27.80543335Z}: timesimp::delta: response processing internals latency=11ms 5µs 269ns local_at_midpoint=2026-05-15T02:53:27.79442808Z delta=4s 999ms 813µs 11ns
[INFO] [stdout] 2026-05-15T02:53:27.805709Z TRACE timesimp: obtained raw offset from server latency=11.005269ms delta=4s 999ms 813µs 11ns
[INFO] [stdout] 2026-05-15T02:53:27.805735Z TRACE timesimp: sleeping to spread out requests delay=948.586143ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:27.879885Z TRACE new{response=Response { client: 2026-05-15T02:53:27.85740631Z, server: 2026-05-15T02:53:27.86856026Z } current=2026-05-15T02:53:27.87971806Z}: timesimp::delta: response processing internals latency=11ms 155µs 875ns local_at_midpoint=2026-05-15T02:53:27.868562185Z delta=1µs 925ns ago
[INFO] [stdout] 2026-05-15T02:53:27.879984Z TRACE timesimp: obtained raw offset from server latency=11.155875ms delta=1µs 925ns ago
[INFO] [stdout] 2026-05-15T02:53:27.880006Z TRACE timesimp: sleeping to spread out requests delay=1.218187343s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.082958Z TRACE new{response=Response { client: 2026-05-15T02:53:28.070390018Z, server: 2026-05-15T02:53:33.076583058Z } current=2026-05-15T02:53:28.082778987Z}: timesimp::delta: response processing internals latency=6ms 194µs 484ns local_at_midpoint=2026-05-15T02:53:28.076584502Z delta=4s 999ms 998µs 556ns
[INFO] [stdout] 2026-05-15T02:53:28.083059Z TRACE timesimp: obtained raw offset from server latency=6.194484ms delta=4s 999ms 998µs 556ns
[INFO] [stdout] 2026-05-15T02:53:28.083087Z TRACE timesimp: sleeping to spread out requests delay=1.704215944s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.543406Z TRACE new{response=Response { client: 2026-05-15T02:53:28.516252922Z, server: 2026-05-15T02:53:23.528248722Z } current=2026-05-15T02:53:28.543238622Z}: timesimp::delta: response processing internals latency=13ms 492µs 850ns local_at_midpoint=2026-05-15T02:53:28.529745772Z delta=5s 1ms 497µs 50ns ago
[INFO] [stdout] 2026-05-15T02:53:28.543501Z TRACE timesimp: obtained raw offset from server latency=13.49285ms delta=5s 1ms 497µs 50ns ago
[INFO] [stdout] 2026-05-15T02:53:28.543525Z TRACE timesimp: sleeping to spread out requests delay=1.796155876s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.610583Z TRACE new{response=Response { client: 2026-05-15T02:53:26.879241391Z, server: 2026-05-15T02:53:27.745245611Z } current=2026-05-15T02:53:28.610383181Z}: timesimp::delta: response processing internals latency=865ms 570µs 895ns local_at_midpoint=2026-05-15T02:53:27.744812286Z delta=433µs 325ns
[INFO] [stdout] 2026-05-15T02:53:28.610671Z TRACE timesimp: obtained raw offset from server latency=865.570895ms delta=433µs 325ns
[INFO] [stdout] 2026-05-15T02:53:28.610692Z DEBUG timesimp: no offset stored, storing initial delta offset=433µs 325ns
[INFO] [stdout] 2026-05-15T02:53:28.610706Z TRACE timesimp: sleeping to spread out requests delay=1.473334696s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.747942Z TRACE new{response=Response { client: 2026-05-15T02:53:28.72538873Z, server: 2026-05-15T02:53:33.73659816Z } current=2026-05-15T02:53:28.74775936Z}: timesimp::delta: response processing internals latency=11ms 185µs 315ns local_at_midpoint=2026-05-15T02:53:28.736574045Z delta=5s 24µs 115ns
[INFO] [stdout] 2026-05-15T02:53:28.748049Z TRACE timesimp: obtained raw offset from server latency=11.185315ms delta=5s 24µs 115ns
[INFO] [stdout] 2026-05-15T02:53:28.748073Z TRACE timesimp: sleeping to spread out requests delay=1.231711505s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.768864Z TRACE new{response=Response { client: 2026-05-15T02:53:28.74636485Z, server: 2026-05-15T02:53:28.75753629Z } current=2026-05-15T02:53:28.76869686Z}: timesimp::delta: response processing internals latency=11ms 166µs 5ns local_at_midpoint=2026-05-15T02:53:28.757530855Z delta=5µs 435ns
[INFO] [stdout] 2026-05-15T02:53:28.768955Z TRACE timesimp: obtained raw offset from server latency=11.166005ms delta=5µs 435ns
[INFO] [stdout] 2026-05-15T02:53:28.768978Z TRACE timesimp: sleeping to spread out requests delay=722.79068ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.775825Z TRACE new{response=Response { client: 2026-05-15T02:53:28.76135347Z, server: 2026-05-15T02:53:33.76851241Z } current=2026-05-15T02:53:28.775656199Z}: timesimp::delta: response processing internals latency=7ms 151µs 364ns local_at_midpoint=2026-05-15T02:53:28.768504834Z delta=5s 7µs 576ns
[INFO] [stdout] 2026-05-15T02:53:28.775914Z TRACE timesimp: obtained raw offset from server latency=7.151364ms delta=5s 7µs 576ns
[INFO] [stdout] 2026-05-15T02:53:28.775966Z TRACE timesimp: sleeping to spread out requests delay=1.369528848s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.775952Z TRACE new{response=Response { client: 2026-05-15T02:53:28.7553777Z, server: 2026-05-15T02:53:33.76557983Z } current=2026-05-15T02:53:28.77577983Z}: timesimp::delta: response processing internals latency=10ms 201µs 65ns local_at_midpoint=2026-05-15T02:53:28.765578765Z delta=5s 1µs 65ns
[INFO] [stdout] 2026-05-15T02:53:28.776033Z TRACE timesimp: obtained raw offset from server latency=10.201065ms delta=5s 1µs 65ns
[INFO] [stdout] 2026-05-15T02:53:28.776058Z TRACE timesimp: sleeping to spread out requests delay=607.849571ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:28.993370Z TRACE new{response=Response { client: 2026-05-15T02:53:28.988247457Z, server: 2026-05-15T02:53:28.991261917Z } current=2026-05-15T02:53:28.993199947Z}: timesimp::delta: response processing internals latency=2ms 476µs 245ns local_at_midpoint=2026-05-15T02:53:28.990723702Z delta=538µs 215ns
[INFO] [stdout] 2026-05-15T02:53:28.993446Z TRACE timesimp: obtained raw offset from server latency=2.476245ms delta=538µs 215ns
[INFO] [stdout] 2026-05-15T02:53:28.993468Z TRACE timesimp: sleeping to spread out requests delay=840.308912ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:29.094338Z TRACE new{response=Response { client: 2026-05-15T02:53:28.891431068Z, server: 2026-05-15T02:53:28.992791377Z } current=2026-05-15T02:53:29.094156396Z}: timesimp::delta: response processing internals latency=101ms 362µs 664ns local_at_midpoint=2026-05-15T02:53:28.992793732Z delta=2µs 355ns ago
[INFO] [stdout] 2026-05-15T02:53:29.094432Z TRACE timesimp: obtained raw offset from server latency=101.362664ms delta=2µs 355ns ago
[INFO] [stdout] 2026-05-15T02:53:29.094455Z TRACE timesimp: sleeping to spread out requests delay=1.04378456s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:29.121924Z TRACE new{response=Response { client: 2026-05-15T02:53:29.099403706Z, server: 2026-05-15T02:53:29.110591856Z } current=2026-05-15T02:53:29.121755596Z}: timesimp::delta: response processing internals latency=11ms 175µs 945ns local_at_midpoint=2026-05-15T02:53:29.110579651Z delta=12µs 205ns
[INFO] [stdout] 2026-05-15T02:53:29.122013Z TRACE timesimp: obtained raw offset from server latency=11.175945ms delta=12µs 205ns
[INFO] [stdout] 2026-05-15T02:53:29.122036Z TRACE timesimp: sleeping to spread out requests delay=613.941805ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:29.405914Z TRACE new{response=Response { client: 2026-05-15T02:53:29.385374233Z, server: 2026-05-15T02:53:34.395553523Z } current=2026-05-15T02:53:29.405737583Z}: timesimp::delta: response processing internals latency=10ms 181µs 675ns local_at_midpoint=2026-05-15T02:53:29.395555908Z delta=4s 999ms 997µs 615ns
[INFO] [stdout] 2026-05-15T02:53:29.406013Z TRACE timesimp: obtained raw offset from server latency=10.181675ms delta=4s 999ms 997µs 615ns
[INFO] [stdout] 2026-05-15T02:53:29.406039Z TRACE timesimp: sleeping to spread out requests delay=623.528773ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:29.534621Z TRACE new{response=Response { client: 2026-05-15T02:53:29.508245612Z, server: 2026-05-15T02:53:29.523243771Z } current=2026-05-15T02:53:29.534441751Z}: timesimp::delta: response processing internals latency=13ms 98µs 69ns local_at_midpoint=2026-05-15T02:53:29.521343681Z delta=1ms 900µs 90ns
[INFO] [stdout] 2026-05-15T02:53:29.534711Z TRACE timesimp: obtained raw offset from server latency=13.098069ms delta=1ms 900µs 90ns
[INFO] [stdout] 2026-05-15T02:53:29.534733Z TRACE timesimp: sleeping to spread out requests delay=972.044899ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:29.760079Z TRACE new{response=Response { client: 2026-05-15T02:53:29.737397219Z, server: 2026-05-15T02:53:29.748589339Z } current=2026-05-15T02:53:29.759894559Z}: timesimp::delta: response processing internals latency=11ms 248µs 670ns local_at_midpoint=2026-05-15T02:53:29.748645889Z delta=56µs 550ns ago
[INFO] [stdout] 2026-05-15T02:53:29.760209Z TRACE timesimp: obtained raw offset from server latency=11.24867ms delta=56µs 550ns ago
[INFO] [stdout] 2026-05-15T02:53:29.760254Z TRACE timesimp: response deltas sorted by latency deltas=[-0.001925, 0.012205, -0.05655, -0.77876, -4.50394]
[INFO] [stdout] 2026-05-15T02:53:29.760278Z TRACE timesimp: statistics about response deltas median=-0.05655 mean=-1.065794 variance=3.8039272447925003 stddev=1.9503659258694253
[INFO] [stdout] 2026-05-15T02:53:29.760312Z TRACE timesimp: eliminated outliers inliers=[-0.001925, 0.012205, -0.05655, -0.77876]
[INFO] [stdout] 2026-05-15T02:53:29.760327Z DEBUG timesimp: storing calculated offset offset=206µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2026-05-15T02:53:29.808928Z TRACE new{response=Response { client: 2026-05-15T02:53:29.788378259Z, server: 2026-05-15T02:53:34.798577788Z } current=2026-05-15T02:53:29.808764728Z}: timesimp::delta: response processing internals latency=10ms 193µs 234ns local_at_midpoint=2026-05-15T02:53:29.798571493Z delta=5s 6µs 295ns
[INFO] [stdout] 2026-05-15T02:53:29.809022Z TRACE timesimp: obtained raw offset from server latency=10.193234ms delta=5s 6µs 295ns
[INFO] [stdout] 2026-05-15T02:53:29.809049Z TRACE timesimp: sleeping to spread out requests delay=572.959299ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:29.837267Z TRACE new{response=Response { client: 2026-05-15T02:53:29.834852288Z, server: 2026-05-15T02:53:29.835980928Z } current=2026-05-15T02:53:29.837090948Z}: timesimp::delta: response processing internals latency=1ms 119µs 330ns local_at_midpoint=2026-05-15T02:53:29.835971618Z delta=9µs 310ns
[INFO] [stdout] 2026-05-15T02:53:29.837353Z TRACE timesimp: obtained raw offset from server latency=1.11933ms delta=9µs 310ns
[INFO] [stdout] 2026-05-15T02:53:29.837378Z TRACE timesimp: response deltas sorted by latency deltas=[0.00931, 0.007105, 0.014455, 0.987966, 0.538215]
[INFO] [stdout] 2026-05-15T02:53:29.837397Z TRACE timesimp: statistics about response deltas median=0.014455 mean=0.31141019999999997 variance=0.1953041860527 stddev=0.44193233198386833
[INFO] [stdout] 2026-05-15T02:53:29.837416Z TRACE timesimp: eliminated outliers inliers=[0.00931, 0.007105, 0.014455]
[INFO] [stdout] 2026-05-15T02:53:29.837430Z DEBUG timesimp: storing calculated offset offset=10µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2026-05-15T02:53:30.003165Z TRACE new{response=Response { client: 2026-05-15T02:53:29.980460966Z, server: 2026-05-15T02:53:34.991771186Z } current=2026-05-15T02:53:30.002966676Z}: timesimp::delta: response processing internals latency=11ms 252µs 855ns local_at_midpoint=2026-05-15T02:53:29.991713821Z delta=5s 57µs 365ns
[INFO] [stdout] 2026-05-15T02:53:30.003259Z TRACE timesimp: obtained raw offset from server latency=11.252855ms delta=5s 57µs 365ns
[INFO] [stdout] 2026-05-15T02:53:30.003279Z TRACE timesimp: sleeping to spread out requests delay=392.136058ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:30.052987Z TRACE new{response=Response { client: 2026-05-15T02:53:30.031404106Z, server: 2026-05-15T02:53:35.041600246Z } current=2026-05-15T02:53:30.052805576Z}: timesimp::delta: response processing internals latency=10ms 700µs 735ns local_at_midpoint=2026-05-15T02:53:30.042104841Z delta=4s 999ms 495µs 405ns
[INFO] [stdout] 2026-05-15T02:53:30.053089Z TRACE timesimp: obtained raw offset from server latency=10.700735ms delta=4s 999ms 495µs 405ns
[INFO] [stdout] 2026-05-15T02:53:30.053120Z TRACE timesimp: response deltas sorted by latency deltas=[4999.997615, 5000.001065, 4999.495405, 4999.813011, 5003.907206]
[INFO] [stdout] 2026-05-15T02:53:30.053356Z TRACE timesimp: statistics about response deltas median=4999.495405 mean=5000.6428604 variance=3.372374769897492 stddev=1.8364026709568608
[INFO] [stdout] 2026-05-15T02:53:30.053474Z TRACE timesimp: eliminated outliers inliers=[4999.997615, 5000.001065, 4999.495405, 4999.813011]
[INFO] [stdout] 2026-05-15T02:53:30.053567Z DEBUG timesimp: storing calculated offset offset=4s 999ms 826µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2026-05-15T02:53:30.178409Z TRACE new{response=Response { client: 2026-05-15T02:53:30.151264924Z, server: 2026-05-15T02:53:35.166244634Z } current=2026-05-15T02:53:30.178239804Z}: timesimp::delta: response processing internals latency=13ms 487µs 440ns local_at_midpoint=2026-05-15T02:53:30.164752364Z delta=5s 1ms 492µs 270ns
[INFO] [stdout] 2026-05-15T02:53:30.178504Z TRACE timesimp: obtained raw offset from server latency=13.48744ms delta=5s 1ms 492µs 270ns
[INFO] [stdout] 2026-05-15T02:53:30.178528Z TRACE timesimp: sleeping to spread out requests delay=1.889408438s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:30.349448Z TRACE new{response=Response { client: 2026-05-15T02:53:30.139373224Z, server: 2026-05-15T02:53:30.240731623Z } current=2026-05-15T02:53:30.349254892Z}: timesimp::delta: response processing internals latency=104ms 940µs 834ns local_at_midpoint=2026-05-15T02:53:30.244314058Z delta=3ms 582µs 435ns ago
[INFO] [stdout] 2026-05-15T02:53:30.349550Z TRACE timesimp: obtained raw offset from server latency=104.940834ms delta=3ms 582µs 435ns ago
[INFO] [stdout] 2026-05-15T02:53:30.349573Z TRACE timesimp: sleeping to spread out requests delay=1.003878129s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:30.362881Z TRACE new{response=Response { client: 2026-05-15T02:53:30.340359472Z, server: 2026-05-15T02:53:25.351491642Z } current=2026-05-15T02:53:30.362691242Z}: timesimp::delta: response processing internals latency=11ms 165µs 885ns local_at_midpoint=2026-05-15T02:53:30.351525357Z delta=5s 33µs 715ns ago
[INFO] [stdout] 2026-05-15T02:53:30.362979Z TRACE timesimp: obtained raw offset from server latency=11.165885ms delta=5s 33µs 715ns ago
[INFO] [stdout] 2026-05-15T02:53:30.363003Z TRACE timesimp: sleeping to spread out requests delay=1.383897527s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:30.398730Z TRACE new{response=Response { client: 2026-05-15T02:53:30.386260522Z, server: 2026-05-15T02:53:35.392230142Z } current=2026-05-15T02:53:30.398549442Z}: timesimp::delta: response processing internals latency=6ms 144µs 460ns local_at_midpoint=2026-05-15T02:53:30.392404982Z delta=4s 999ms 825µs 160ns
[INFO] [stdout] 2026-05-15T02:53:30.398820Z TRACE timesimp: obtained raw offset from server latency=6.14446ms delta=4s 999ms 825µs 160ns
[INFO] [stdout] 2026-05-15T02:53:30.398844Z TRACE timesimp: sleeping to spread out requests delay=422.853896ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:30.419659Z TRACE new{response=Response { client: 2026-05-15T02:53:30.396967202Z, server: 2026-05-15T02:53:35.408225301Z } current=2026-05-15T02:53:30.419452132Z}: timesimp::delta: response processing internals latency=11ms 242µs 465ns local_at_midpoint=2026-05-15T02:53:30.408209667Z delta=5s 15µs 634ns
[INFO] [stdout] 2026-05-15T02:53:30.419764Z TRACE timesimp: obtained raw offset from server latency=11.242465ms delta=5s 15µs 634ns
[INFO] [stdout] 2026-05-15T02:53:30.419796Z TRACE timesimp: response deltas sorted by latency deltas=[5000.024115, 5000.000595, 5000.015634, 5000.057365, 4999.734115]
[INFO] [stdout] 2026-05-15T02:53:30.419817Z TRACE timesimp: statistics about response deltas median=5000.015634 mean=4999.9663648000005 variance=0.01728881306518124 stddev=0.13148693115736346
[INFO] [stdout] 2026-05-15T02:53:30.419836Z TRACE timesimp: eliminated outliers inliers=[5000.024115, 5000.000595, 5000.015634, 5000.057365]
[INFO] [stdout] 2026-05-15T02:53:30.419850Z DEBUG timesimp: storing calculated offset offset=5s 24µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2026-05-15T02:53:30.531223Z TRACE new{response=Response { client: 2026-05-15T02:53:30.508414291Z, server: 2026-05-15T02:53:30.51975437Z } current=2026-05-15T02:53:30.530978Z}: timesimp::delta: response processing internals latency=11ms 281µs 854ns local_at_midpoint=2026-05-15T02:53:30.519696145Z delta=58µs 225ns
[INFO] [stdout] 2026-05-15T02:53:30.531329Z TRACE timesimp: obtained raw offset from server latency=11.281854ms delta=58µs 225ns
[INFO] [stdout] 2026-05-15T02:53:30.531353Z TRACE timesimp: sleeping to spread out requests delay=1.917608305s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:30.835855Z TRACE new{response=Response { client: 2026-05-15T02:53:30.823379197Z, server: 2026-05-15T02:53:35.829537447Z } current=2026-05-15T02:53:30.835684617Z}: timesimp::delta: response processing internals latency=6ms 152µs 710ns local_at_midpoint=2026-05-15T02:53:30.829531907Z delta=5s 5µs 540ns
[INFO] [stdout] 2026-05-15T02:53:30.835956Z TRACE timesimp: obtained raw offset from server latency=6.15271ms delta=5s 5µs 540ns
[INFO] [stdout] 2026-05-15T02:53:30.835987Z TRACE timesimp: response deltas sorted by latency deltas=[4999.995815, 4999.82516, 5000.00554, 4999.9985560000005, 5000.006295]
[INFO] [stdout] 2026-05-15T02:53:30.836008Z TRACE timesimp: statistics about response deltas median=5000.00554 mean=4999.9662732 variance=0.00624286459869278 stddev=0.07901180037622722
[INFO] [stdout] 2026-05-15T02:53:30.836046Z TRACE timesimp: eliminated outliers inliers=[4999.995815, 5000.00554, 4999.9985560000005, 5000.006295]
[INFO] [stdout] 2026-05-15T02:53:30.836062Z DEBUG timesimp: storing calculated offset offset=5s 1µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2026-05-15T02:53:31.557216Z TRACE new{response=Response { client: 2026-05-15T02:53:31.354333851Z, server: 2026-05-15T02:53:31.4556893Z } current=2026-05-15T02:53:31.557031899Z}: timesimp::delta: response processing internals latency=101ms 349µs 24ns local_at_midpoint=2026-05-15T02:53:31.455682875Z delta=6µs 425ns
[INFO] [stdout] 2026-05-15T02:53:31.557378Z TRACE timesimp: obtained raw offset from server latency=101.349024ms delta=6µs 425ns
[INFO] [stdout] 2026-05-15T02:53:31.557429Z TRACE timesimp: sleeping to spread out requests delay=1.400789831s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:31.770848Z TRACE new{response=Response { client: 2026-05-15T02:53:31.748241217Z, server: 2026-05-15T02:53:26.759449587Z } current=2026-05-15T02:53:31.770676697Z}: timesimp::delta: response processing internals latency=11ms 217µs 740ns local_at_midpoint=2026-05-15T02:53:31.759458957Z delta=5s 9µs 370ns ago
[INFO] [stdout] 2026-05-15T02:53:31.770947Z TRACE timesimp: obtained raw offset from server latency=11.21774ms delta=5s 9µs 370ns ago
[INFO] [stdout] 2026-05-15T02:53:31.770975Z TRACE timesimp: sleeping to spread out requests delay=865.209984ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:31.917574Z TRACE new{response=Response { client: 2026-05-15T02:53:30.085408135Z, server: 2026-05-15T02:53:31.001402385Z } current=2026-05-15T02:53:31.917383475Z}: timesimp::delta: response processing internals latency=915ms 987µs 670ns local_at_midpoint=2026-05-15T02:53:31.001395805Z delta=6µs 580ns
[INFO] [stdout] 2026-05-15T02:53:31.917743Z TRACE timesimp: obtained raw offset from server latency=915.98767ms delta=6µs 580ns
[INFO] [stdout] 2026-05-15T02:53:31.917801Z TRACE timesimp: sleeping to spread out requests delay=1.248700613s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:32.102409Z TRACE new{response=Response { client: 2026-05-15T02:53:32.072243803Z, server: 2026-05-15T02:53:37.087242463Z } current=2026-05-15T02:53:32.102238383Z}: timesimp::delta: response processing internals latency=14ms 997µs 290ns local_at_midpoint=2026-05-15T02:53:32.087241093Z delta=5s 1µs 370ns
[INFO] [stdout] 2026-05-15T02:53:32.102502Z TRACE timesimp: obtained raw offset from server latency=14.99729ms delta=5s 1µs 370ns
[INFO] [stdout] 2026-05-15T02:53:32.102524Z TRACE timesimp: sleeping to spread out requests delay=109.325397ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:32.244419Z TRACE new{response=Response { client: 2026-05-15T02:53:32.223247872Z, server: 2026-05-15T02:53:37.232240972Z } current=2026-05-15T02:53:32.244250012Z}: timesimp::delta: response processing internals latency=10ms 501µs 70ns local_at_midpoint=2026-05-15T02:53:32.233748942Z delta=4s 998ms 492µs 30ns
[INFO] [stdout] 2026-05-15T02:53:32.244513Z TRACE timesimp: obtained raw offset from server latency=10.50107ms delta=4s 998ms 492µs 30ns
[INFO] [stdout] 2026-05-15T02:53:32.244541Z TRACE timesimp: response deltas sorted by latency deltas=[5000.007576, 5000.001366, 4998.49203, 5001.49227, 5000.00137]
[INFO] [stdout] 2026-05-15T02:53:32.244561Z TRACE timesimp: statistics about response deltas median=4998.49203 mean=4999.9989224 variance=1.1252246515803455 stddev=1.0607660682640379
[INFO] [stdout] 2026-05-15T02:53:32.244580Z TRACE timesimp: eliminated outliers inliers=[4998.49203]
[INFO] [stdout] 2026-05-15T02:53:32.244593Z DEBUG timesimp: storing calculated offset offset=4s 998ms 492µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2026-05-15T02:53:32.472909Z TRACE new{response=Response { client: 2026-05-15T02:53:32.450370599Z, server: 2026-05-15T02:53:32.461563259Z } current=2026-05-15T02:53:32.472743299Z}: timesimp::delta: response processing internals latency=11ms 186µs 350ns local_at_midpoint=2026-05-15T02:53:32.461556949Z delta=6µs 310ns
[INFO] [stdout] 2026-05-15T02:53:32.473000Z TRACE timesimp: obtained raw offset from server latency=11.18635ms delta=6µs 310ns
[INFO] [stdout] 2026-05-15T02:53:32.473025Z TRACE timesimp: response deltas sorted by latency deltas=[-0.009384, 0.005435, 0.00631, 0.058225, 1.90009]
[INFO] [stdout] 2026-05-15T02:53:32.473044Z TRACE timesimp: statistics about response deltas median=0.00631 mean=0.3921352 variance=0.7112598745277 stddev=0.8433622439543402
[INFO] [stdout] 2026-05-15T02:53:32.473064Z TRACE timesimp: eliminated outliers inliers=[-0.009384, 0.005435, 0.00631, 0.058225]
[INFO] [stdout] 2026-05-15T02:53:32.473087Z DEBUG timesimp: storing calculated offset offset=15µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2026-05-15T02:53:32.659965Z TRACE new{response=Response { client: 2026-05-15T02:53:32.637408647Z, server: 2026-05-15T02:53:27.648606327Z } current=2026-05-15T02:53:32.659802037Z}: timesimp::delta: response processing internals latency=11ms 196µs 695ns local_at_midpoint=2026-05-15T02:53:32.648605342Z delta=4s 999ms 999µs 15ns ago
[INFO] [stdout] 2026-05-15T02:53:32.660059Z TRACE timesimp: obtained raw offset from server latency=11.196695ms delta=4s 999ms 999µs 15ns ago
[INFO] [stdout] 2026-05-15T02:53:32.660090Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.033715, -4999.999015, -5000.00937, -5000.729479, -5001.49705]
[INFO] [stdout] 2026-05-15T02:53:32.660111Z TRACE timesimp: statistics about response deltas median=-5000.00937 mean=-5000.4537258 variance=0.43629706859068773 stddev=0.660527871168725
[INFO] [stdout] 2026-05-15T02:53:32.660130Z TRACE timesimp: eliminated outliers inliers=[-5000.033715, -4999.999015, -5000.00937]
[INFO] [stdout] 2026-05-15T02:53:32.660180Z DEBUG timesimp: storing calculated offset offset=5s 14µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2026-05-15T02:53:33.162271Z TRACE new{response=Response { client: 2026-05-15T02:53:32.959366233Z, server: 2026-05-15T02:53:33.060703252Z } current=2026-05-15T02:53:33.162071771Z}: timesimp::delta: response processing internals latency=101ms 352µs 769ns local_at_midpoint=2026-05-15T02:53:33.060719002Z delta=15µs 750ns ago
[INFO] [stdout] 2026-05-15T02:53:33.162366Z TRACE timesimp: obtained raw offset from server latency=101.352769ms delta=15µs 750ns ago
[INFO] [stdout] 2026-05-15T02:53:33.162396Z TRACE timesimp: response deltas sorted by latency deltas=[0.006425, -0.01575, -0.002355, -1.257389, -3.582435]
[INFO] [stdout] 2026-05-15T02:53:33.162417Z TRACE timesimp: statistics about response deltas median=-0.002355 mean=-0.9703008000000001 variance=2.4269360758231997 stddev=1.5578626626962981
[INFO] [stdout] 2026-05-15T02:53:33.162446Z TRACE timesimp: eliminated outliers inliers=[0.006425, -0.01575, -0.002355, -1.257389]
[INFO] [stdout] 2026-05-15T02:53:33.162461Z DEBUG timesimp: storing calculated offset offset=317µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2026-05-15T02:53:34.833669Z TRACE new{response=Response { client: 2026-05-15T02:53:33.168317221Z, server: 2026-05-15T02:53:34.001380212Z } current=2026-05-15T02:53:34.833493783Z}: timesimp::delta: response processing internals latency=832ms 588µs 281ns local_at_midpoint=2026-05-15T02:53:34.000905502Z delta=474µs 710ns
[INFO] [stdout] 2026-05-15T02:53:34.833766Z TRACE timesimp: obtained raw offset from server latency=832.588281ms delta=474µs 710ns
[INFO] [stdout] 2026-05-15T02:53:34.833792Z TRACE timesimp: sleeping to spread out requests delay=423.54682ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:36.948575Z TRACE new{response=Response { client: 2026-05-15T02:53:35.258614178Z, server: 2026-05-15T02:53:36.103419998Z } current=2026-05-15T02:53:36.948402609Z}: timesimp::delta: response processing internals latency=844ms 894µs 215ns local_at_midpoint=2026-05-15T02:53:36.103508393Z delta=88µs 395ns ago
[INFO] [stdout] 2026-05-15T02:53:36.948658Z TRACE timesimp: obtained raw offset from server latency=844.894215ms delta=88µs 395ns ago
[INFO] [stdout] 2026-05-15T02:53:36.948681Z TRACE timesimp: sleeping to spread out requests delay=940.05437ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.452552Z TRACE new{response=Response { client: 2026-05-15T02:53:37.890470719Z, server: 2026-05-15T02:53:38.67136786Z } current=2026-05-15T02:53:39.452388912Z}: timesimp::delta: response processing internals latency=780ms 959µs 96ns local_at_midpoint=2026-05-15T02:53:38.671429815Z delta=61µs 955ns ago
[INFO] [stdout] 2026-05-15T02:53:39.452626Z TRACE timesimp: obtained raw offset from server latency=780.959096ms delta=61µs 955ns ago
[INFO] [stdout] 2026-05-15T02:53:39.452652Z TRACE timesimp: response deltas sorted by latency deltas=[-0.061955, 0.47471, -0.088395, 0.433325, 0.00658]
[INFO] [stdout] 2026-05-15T02:53:39.452670Z TRACE timesimp: statistics about response deltas median=-0.088395 mean=0.15285300000000002 variance=0.0769988340325 stddev=0.27748663757467673
[INFO] [stdout] 2026-05-15T02:53:39.452689Z TRACE timesimp: eliminated outliers inliers=[-0.061955, -0.088395, 0.00658]
[INFO] [stdout] 2026-05-15T02:53:39.452701Z DEBUG timesimp: storing calculated offset offset=47µ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.59s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-2e65c6dffb129287)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2026-05-15T02:53:39.456538Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-05-15T02:53:39.456530Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-05-15T02:53:39.456537Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:39.456537Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-05-15T02:53:39.456596Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.456599Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.456610Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.456608Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.458007Z TRACE new{response=Response { client: 2026-05-15T02:53:39.457873141Z, server: 2026-05-15T02:53:39.457876471Z } current=2026-05-15T02:53:39.457878311Z}: timesimp::delta: response processing internals latency=2µs 585ns local_at_midpoint=2026-05-15T02:53:39.457875726Z delta=745ns
[INFO] [stdout] 2026-05-15T02:53:39.458007Z TRACE new{response=Response { client: 2026-05-15T02:53:39.457842741Z, server: 2026-05-15T02:53:44.457858661Z } current=2026-05-15T02:53:39.457862151Z}: timesimp::delta: response processing internals latency=9µs 705ns local_at_midpoint=2026-05-15T02:53:39.457852446Z delta=5s 6µs 215ns
[INFO] [stdout] 2026-05-15T02:53:39.458077Z TRACE timesimp: obtained raw offset from server latency=2.585µs delta=745ns
[INFO] [stdout] 2026-05-15T02:53:39.458094Z TRACE timesimp: sleeping to spread out requests delay=1.831982385s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.458008Z TRACE new{response=Response { client: 2026-05-15T02:53:39.457865581Z, server: 2026-05-15T02:53:34.457869281Z } current=2026-05-15T02:53:39.457871331Z}: timesimp::delta: response processing internals latency=2µs 875ns local_at_midpoint=2026-05-15T02:53:39.457868456Z delta=4s 999ms 999µs 175ns ago
[INFO] [stdout] 2026-05-15T02:53:39.458008Z TRACE new{response=Response { client: 2026-05-15T02:53:39.457842551Z, server: 2026-05-15T02:53:39.457858991Z } current=2026-05-15T02:53:39.457862811Z}: timesimp::delta: response processing internals latency=10µs 130ns local_at_midpoint=2026-05-15T02:53:39.457852681Z delta=6µs 310ns
[INFO] [stdout] 2026-05-15T02:53:39.458175Z TRACE timesimp: obtained raw offset from server latency=2.875µs delta=4s 999ms 999µs 175ns ago
[INFO] [stdout] 2026-05-15T02:53:39.458203Z TRACE timesimp: sleeping to spread out requests delay=1.001725963s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.458107Z TRACE timesimp: obtained raw offset from server latency=9.705µs delta=5s 6µs 215ns
[INFO] [stdout] 2026-05-15T02:53:39.458219Z TRACE timesimp: obtained raw offset from server latency=10.13µs delta=6µs 310ns
[INFO] [stdout] 2026-05-15T02:53:39.458238Z TRACE timesimp: sleeping to spread out requests delay=174.412702ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.458283Z DEBUG timesimp: no offset stored, storing initial delta offset=6µs 310ns
[INFO] [stdout] 2026-05-15T02:53:39.458302Z TRACE timesimp: sleeping to spread out requests delay=74.080251ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.533932Z TRACE new{response=Response { client: 2026-05-15T02:53:39.53375596Z, server: 2026-05-15T02:53:39.53377217Z } current=2026-05-15T02:53:39.5337702Z}: timesimp::delta: response processing internals latency=7µs 120ns local_at_midpoint=2026-05-15T02:53:39.53376308Z delta=9µs 90ns
[INFO] [stdout] 2026-05-15T02:53:39.534019Z TRACE timesimp: obtained raw offset from server latency=7.12µs delta=9µs 90ns
[INFO] [stdout] 2026-05-15T02:53:39.534042Z TRACE timesimp: sleeping to spread out requests delay=1.923018673s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.633846Z TRACE new{response=Response { client: 2026-05-15T02:53:39.633682199Z, server: 2026-05-15T02:53:44.633691429Z } current=2026-05-15T02:53:39.633695579Z}: timesimp::delta: response processing internals latency=6µs 690ns local_at_midpoint=2026-05-15T02:53:39.633688889Z delta=5s 2µs 540ns
[INFO] [stdout] 2026-05-15T02:53:39.633922Z TRACE timesimp: obtained raw offset from server latency=6.69µs delta=5s 2µs 540ns
[INFO] [stdout] 2026-05-15T02:53:39.633940Z TRACE timesimp: sleeping to spread out requests delay=295.822832ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:39.930656Z TRACE new{response=Response { client: 2026-05-15T02:53:39.930492426Z, server: 2026-05-15T02:53:44.930501316Z } current=2026-05-15T02:53:39.930504956Z}: timesimp::delta: response processing internals latency=6µs 265ns local_at_midpoint=2026-05-15T02:53:39.930498691Z delta=5s 2µs 625ns
[INFO] [stdout] 2026-05-15T02:53:39.930730Z TRACE timesimp: obtained raw offset from server latency=6.265µs delta=5s 2µs 625ns
[INFO] [stdout] 2026-05-15T02:53:39.930750Z TRACE timesimp: sleeping to spread out requests delay=805.737642ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:40.460648Z TRACE new{response=Response { client: 2026-05-15T02:53:40.46047921Z, server: 2026-05-15T02:53:35.460487891Z } current=2026-05-15T02:53:40.460491641Z}: timesimp::delta: response processing internals latency=6µs 215ns local_at_midpoint=2026-05-15T02:53:40.460485425Z delta=4s 999ms 997µs 534ns ago
[INFO] [stdout] 2026-05-15T02:53:40.460734Z TRACE timesimp: obtained raw offset from server latency=6.215µs delta=4s 999ms 997µs 534ns ago
[INFO] [stdout] 2026-05-15T02:53:40.460758Z TRACE timesimp: sleeping to spread out requests delay=43.759238ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:40.506339Z TRACE new{response=Response { client: 2026-05-15T02:53:40.50616968Z, server: 2026-05-15T02:53:35.50617825Z } current=2026-05-15T02:53:40.50618214Z}: timesimp::delta: response processing internals latency=6µs 230ns local_at_midpoint=2026-05-15T02:53:40.50617591Z delta=4s 999ms 997µs 660ns ago
[INFO] [stdout] 2026-05-15T02:53:40.506421Z TRACE timesimp: obtained raw offset from server latency=6.23µs delta=4s 999ms 997µs 660ns ago
[INFO] [stdout] 2026-05-15T02:53:40.506444Z TRACE timesimp: sleeping to spread out requests delay=489.080509ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:40.737896Z TRACE new{response=Response { client: 2026-05-15T02:53:40.737732968Z, server: 2026-05-15T02:53:45.737742338Z } current=2026-05-15T02:53:40.737746178Z}: timesimp::delta: response processing internals latency=6µs 605ns local_at_midpoint=2026-05-15T02:53:40.737739573Z delta=5s 2µs 765ns
[INFO] [stdout] 2026-05-15T02:53:40.737969Z TRACE timesimp: obtained raw offset from server latency=6.605µs delta=5s 2µs 765ns
[INFO] [stdout] 2026-05-15T02:53:40.737989Z TRACE timesimp: sleeping to spread out requests delay=1.226484755s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:40.997497Z TRACE new{response=Response { client: 2026-05-15T02:53:40.997303135Z, server: 2026-05-15T02:53:35.997312825Z } current=2026-05-15T02:53:40.997316995Z}: timesimp::delta: response processing internals latency=6µs 930ns local_at_midpoint=2026-05-15T02:53:40.997310065Z delta=4s 999ms 997µs 240ns ago
[INFO] [stdout] 2026-05-15T02:53:40.997586Z TRACE timesimp: obtained raw offset from server latency=6.93µs delta=4s 999ms 997µs 240ns ago
[INFO] [stdout] 2026-05-15T02:53:40.997610Z TRACE timesimp: sleeping to spread out requests delay=1.605770703s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:41.291355Z TRACE new{response=Response { client: 2026-05-15T02:53:41.291219872Z, server: 2026-05-15T02:53:41.291228892Z } current=2026-05-15T02:53:41.291231681Z}: timesimp::delta: response processing internals latency=5µs 904ns local_at_midpoint=2026-05-15T02:53:41.291225776Z delta=3µs 116ns
[INFO] [stdout] 2026-05-15T02:53:41.291413Z TRACE timesimp: obtained raw offset from server latency=5.904µs delta=3µs 116ns
[INFO] [stdout] 2026-05-15T02:53:41.291427Z TRACE timesimp: sleeping to spread out requests delay=1.732837614s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:41.458512Z TRACE new{response=Response { client: 2026-05-15T02:53:41.45832615Z, server: 2026-05-15T02:53:41.45834182Z } current=2026-05-15T02:53:41.458339519Z}: timesimp::delta: response processing internals latency=6µs 684ns local_at_midpoint=2026-05-15T02:53:41.458332834Z delta=8µs 986ns
[INFO] [stdout] 2026-05-15T02:53:41.458596Z TRACE timesimp: obtained raw offset from server latency=6.684µs delta=8µs 986ns
[INFO] [stdout] 2026-05-15T02:53:41.458618Z TRACE timesimp: sleeping to spread out requests delay=1.865190982s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:41.965759Z TRACE new{response=Response { client: 2026-05-15T02:53:41.965581234Z, server: 2026-05-15T02:53:46.965589804Z } current=2026-05-15T02:53:41.965593924Z}: timesimp::delta: response processing internals latency=6µs 345ns local_at_midpoint=2026-05-15T02:53:41.965587579Z delta=5s 2µs 225ns
[INFO] [stdout] 2026-05-15T02:53:41.965848Z TRACE timesimp: obtained raw offset from server latency=6.345µs delta=5s 2µs 225ns
[INFO] [stdout] 2026-05-15T02:53:41.965883Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002625, 5000.002225, 5000.002765, 5000.00254, 5000.006215]
[INFO] [stdout] 2026-05-15T02:53:41.965906Z TRACE timesimp: statistics about response deltas median=5000.002765 mean=5000.003274000001 variance=2.742230000181116e-6 stddev=0.00165596799491449
[INFO] [stdout] 2026-05-15T02:53:41.965927Z TRACE timesimp: eliminated outliers inliers=[5000.002625, 5000.002225, 5000.002765, 5000.00254]
[INFO] [stdout] 2026-05-15T02:53:41.965941Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2026-05-15T02:53:42.604624Z TRACE new{response=Response { client: 2026-05-15T02:53:42.604429137Z, server: 2026-05-15T02:53:37.604439407Z } current=2026-05-15T02:53:42.604443637Z}: timesimp::delta: response processing internals latency=7µs 250ns local_at_midpoint=2026-05-15T02:53:42.604436387Z delta=4s 999ms 996µs 980ns ago
[INFO] [stdout] 2026-05-15T02:53:42.604723Z TRACE timesimp: obtained raw offset from server latency=7.25µs delta=4s 999ms 996µs 980ns ago
[INFO] [stdout] 2026-05-15T02:53:42.604753Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.999175, -4999.997534, -4999.99766, -4999.99724, -4999.99698]
[INFO] [stdout] 2026-05-15T02:53:42.604781Z TRACE timesimp: statistics about response deltas median=-4999.99766 mean=-4999.9977178 variance=7.332992000484969e-7 stddev=0.0008563289088011083
[INFO] [stdout] 2026-05-15T02:53:42.604810Z TRACE timesimp: eliminated outliers inliers=[-4999.997534, -4999.99766, -4999.99724, -4999.99698]
[INFO] [stdout] 2026-05-15T02:53:42.604825Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2026-05-15T02:53:43.025661Z TRACE new{response=Response { client: 2026-05-15T02:53:43.025496153Z, server: 2026-05-15T02:53:43.025505653Z } current=2026-05-15T02:53:43.025509563Z}: timesimp::delta: response processing internals latency=6µs 705ns local_at_midpoint=2026-05-15T02:53:43.025502858Z delta=2µs 795ns
[INFO] [stdout] 2026-05-15T02:53:43.025740Z TRACE timesimp: obtained raw offset from server latency=6.705µs delta=2µs 795ns
[INFO] [stdout] 2026-05-15T02:53:43.025761Z TRACE timesimp: sleeping to spread out requests delay=1.717334826s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:43.324941Z TRACE new{response=Response { client: 2026-05-15T02:53:43.324790039Z, server: 2026-05-15T02:53:43.324805569Z } current=2026-05-15T02:53:43.324802559Z}: timesimp::delta: response processing internals latency=6µs 260ns local_at_midpoint=2026-05-15T02:53:43.324796299Z delta=9µs 270ns
[INFO] [stdout] 2026-05-15T02:53:43.325013Z TRACE timesimp: obtained raw offset from server latency=6.26µs delta=9µs 270ns
[INFO] [stdout] 2026-05-15T02:53:43.325030Z TRACE timesimp: sleeping to spread out requests delay=1.327614281s max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:44.653851Z TRACE new{response=Response { client: 2026-05-15T02:53:44.653694335Z, server: 2026-05-15T02:53:44.653709735Z } current=2026-05-15T02:53:44.653706515Z}: timesimp::delta: response processing internals latency=6µs 90ns local_at_midpoint=2026-05-15T02:53:44.653700425Z delta=9µs 310ns
[INFO] [stdout] 2026-05-15T02:53:44.653922Z TRACE timesimp: obtained raw offset from server latency=6.09µs delta=9µs 310ns
[INFO] [stdout] 2026-05-15T02:53:44.653943Z TRACE timesimp: response deltas sorted by latency deltas=[0.00931, 0.00927, 0.008986, 0.00909, 0.00631]
[INFO] [stdout] 2026-05-15T02:53:44.653960Z TRACE timesimp: statistics about response deltas median=0.008986 mean=0.0085932 variance=1.646491200000001e-6 stddev=0.0012831567324376244
[INFO] [stdout] 2026-05-15T02:53:44.653978Z TRACE timesimp: eliminated outliers inliers=[0.00931, 0.00927, 0.008986, 0.00909]
[INFO] [stdout] 2026-05-15T02:53:44.653991Z DEBUG timesimp: storing calculated offset offset=9µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2026-05-15T02:53:44.743647Z TRACE new{response=Response { client: 2026-05-15T02:53:44.743489384Z, server: 2026-05-15T02:53:44.743499094Z } current=2026-05-15T02:53:44.743501954Z}: timesimp::delta: response processing internals latency=6µs 285ns local_at_midpoint=2026-05-15T02:53:44.743495669Z delta=3µs 425ns
[INFO] [stdout] 2026-05-15T02:53:44.743721Z TRACE timesimp: obtained raw offset from server latency=6.285µs delta=3µs 425ns
[INFO] [stdout] 2026-05-15T02:53:44.743739Z TRACE timesimp: sleeping to spread out requests delay=905.637336ms max_jitter=2s
[INFO] [stdout] 2026-05-15T02:53:45.651058Z TRACE new{response=Response { client: 2026-05-15T02:53:45.650907584Z, server: 2026-05-15T02:53:45.650917204Z } current=2026-05-15T02:53:45.650920284Z}: timesimp::delta: response processing internals latency=6µs 350ns local_at_midpoint=2026-05-15T02:53:45.650913934Z delta=3µs 270ns
[INFO] [stdout] 2026-05-15T02:53:45.651123Z TRACE timesimp: obtained raw offset from server latency=6.35µs delta=3µs 270ns
[INFO] [stdout] 2026-05-15T02:53:45.651176Z TRACE timesimp: response deltas sorted by latency deltas=[0.000745, 0.003116, 0.003425, 0.00327, 0.002795]
[INFO] [stdout] 2026-05-15T02:53:45.651191Z TRACE timesimp: statistics about response deltas median=0.003425 mean=0.0026702 variance=1.2125477e-6 stddev=0.0011011574365185025
[INFO] [stdout] 2026-05-15T02:53:45.651213Z TRACE timesimp: eliminated outliers inliers=[0.003116, 0.003425, 0.00327, 0.002795]
[INFO] [stdout] 2026-05-15T02:53:45.651223Z 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 6.20s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-f8424559dfcf15b0)
[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 0.69s; merged doctests compilation took 0.68s
[INFO] running `Command { std: "docker" "inspect" "0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21", kill_on_drop: false }`
[INFO] [stdout] 0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21