[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#028592fec99e54cc92def5a2a849c673b066dd93 for pr-146098
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-2-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-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-2-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 028592fec99e54cc92def5a2a849c673b066dd93
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+028592fec99e54cc92def5a2a849c673b066dd93" "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" "+028592fec99e54cc92def5a2a849c673b066dd93" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+028592fec99e54cc92def5a2a849c673b066dd93" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] fe4f37c4e71f592aab9b74c70d1ccb0203e28cc98b98bb017f9ef6126ee31854
[INFO] running `Command { std: "docker" "start" "-a" "fe4f37c4e71f592aab9b74c70d1ccb0203e28cc98b98bb017f9ef6126ee31854", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "fe4f37c4e71f592aab9b74c70d1ccb0203e28cc98b98bb017f9ef6126ee31854", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "fe4f37c4e71f592aab9b74c70d1ccb0203e28cc98b98bb017f9ef6126ee31854", kill_on_drop: false }`
[INFO] [stdout] fe4f37c4e71f592aab9b74c70d1ccb0203e28cc98b98bb017f9ef6126ee31854
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+028592fec99e54cc92def5a2a849c673b066dd93" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 8153a099fb3da0715c86196a64abf99f14b31a48207253d7ab78105a7ecfd15d
[INFO] running `Command { std: "docker" "start" "-a" "8153a099fb3da0715c86196a64abf99f14b31a48207253d7ab78105a7ecfd15d", 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 thiserror v2.0.12
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[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 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.09s
[INFO] running `Command { std: "docker" "inspect" "8153a099fb3da0715c86196a64abf99f14b31a48207253d7ab78105a7ecfd15d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "8153a099fb3da0715c86196a64abf99f14b31a48207253d7ab78105a7ecfd15d", kill_on_drop: false }`
[INFO] [stdout] 8153a099fb3da0715c86196a64abf99f14b31a48207253d7ab78105a7ecfd15d
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+028592fec99e54cc92def5a2a849c673b066dd93" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 91b6f8a2a08d1c2f908c03946783e309e7fa8502fae9806cb84ec0d74d9f252b
[INFO] running `Command { std: "docker" "start" "-a" "91b6f8a2a08d1c2f908c03946783e309e7fa8502fae9806cb84ec0d74d9f252b", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[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 rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[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 yoke v0.7.5
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling zerovec v0.10.4
[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 timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 52.03s
[INFO] running `Command { std: "docker" "inspect" "91b6f8a2a08d1c2f908c03946783e309e7fa8502fae9806cb84ec0d74d9f252b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "91b6f8a2a08d1c2f908c03946783e309e7fa8502fae9806cb84ec0d74d9f252b", kill_on_drop: false }`
[INFO] [stdout] 91b6f8a2a08d1c2f908c03946783e309e7fa8502fae9806cb84ec0d74d9f252b
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+028592fec99e54cc92def5a2a849c673b066dd93" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 9c1da747ee3824f3f9629708b878c257f0e7495c39258de181f54338a95ddc41
[INFO] running `Command { std: "docker" "start" "-a" "9c1da747ee3824f3f9629708b878c257f0e7495c39258de181f54338a95ddc41", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.24s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-7576d8e666b90f75)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[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.03s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-f436547971196ab6)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-09-29T01:56:38.696283Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-29T01:56:38.696287Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.696390Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.696405Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.696283Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.696431Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.696466Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-29T01:56:38.696486Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.696296Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.696734Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.696296Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.696764Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.697552Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.697629Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.697775Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.697803Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.698051Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.698088Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.698291Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:38.698326Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.703011Z TRACE new{response=Response { client: 2025-09-29T01:56:38.699503832Z, server: 2025-09-29T01:56:38.701661072Z } current=2025-09-29T01:56:38.702799562Z}: timesimp::delta: response processing internals latency=1ms 647µs 865ns local_at_midpoint=2025-09-29T01:56:38.701151697Z delta=509µs 375ns
[INFO] [stdout] 2025-09-29T01:56:38.703175Z TRACE timesimp: obtained raw offset from server latency=1.647865ms delta=509µs 375ns
[INFO] [stdout] 2025-09-29T01:56:38.703251Z DEBUG timesimp: no offset stored, storing initial delta offset=509µs 375ns
[INFO] [stdout] 2025-09-29T01:56:38.703301Z TRACE timesimp: sleeping to spread out requests delay=1.420534414s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.714865Z TRACE new{response=Response { client: 2025-09-29T01:56:38.697785772Z, server: 2025-09-29T01:56:43.705950442Z } current=2025-09-29T01:56:38.714662962Z}: timesimp::delta: response processing internals latency=8ms 438µs 595ns local_at_midpoint=2025-09-29T01:56:38.706224367Z delta=4s 999ms 726µs 75ns
[INFO] [stdout] 2025-09-29T01:56:38.715070Z TRACE timesimp: obtained raw offset from server latency=8.438595ms delta=4s 999ms 726µs 75ns
[INFO] [stdout] 2025-09-29T01:56:38.715157Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 726µs 75ns
[INFO] [stdout] 2025-09-29T01:56:38.715200Z TRACE timesimp: sleeping to spread out requests delay=427.262325ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.718418Z TRACE new{response=Response { client: 2025-09-29T01:56:38.697983662Z, server: 2025-09-29T01:56:43.708119382Z } current=2025-09-29T01:56:38.718244932Z}: timesimp::delta: response processing internals latency=10ms 130µs 635ns local_at_midpoint=2025-09-29T01:56:38.708114297Z delta=5s 5µs 85ns
[INFO] [stdout] 2025-09-29T01:56:38.718488Z TRACE timesimp: obtained raw offset from server latency=10.130635ms delta=5s 5µs 85ns
[INFO] [stdout] 2025-09-29T01:56:38.718504Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 5µs 85ns
[INFO] [stdout] 2025-09-29T01:56:38.718514Z TRACE timesimp: sleeping to spread out requests delay=724.209317ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.719420Z TRACE new{response=Response { client: 2025-09-29T01:56:38.697928472Z, server: 2025-09-29T01:56:43.709060302Z } current=2025-09-29T01:56:38.719225162Z}: timesimp::delta: response processing internals latency=10ms 648µs 345ns local_at_midpoint=2025-09-29T01:56:38.708576817Z delta=5s 483µs 485ns
[INFO] [stdout] 2025-09-29T01:56:38.719500Z TRACE timesimp: obtained raw offset from server latency=10.648345ms delta=5s 483µs 485ns
[INFO] [stdout] 2025-09-29T01:56:38.719516Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 483µs 485ns
[INFO] [stdout] 2025-09-29T01:56:38.719526Z TRACE timesimp: sleeping to spread out requests delay=1.295346958s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.720158Z TRACE new{response=Response { client: 2025-09-29T01:56:38.697775092Z, server: 2025-09-29T01:56:38.708953012Z } current=2025-09-29T01:56:38.720044532Z}: timesimp::delta: response processing internals latency=11ms 134µs 720ns local_at_midpoint=2025-09-29T01:56:38.708909812Z delta=43µs 200ns
[INFO] [stdout] 2025-09-29T01:56:38.720224Z TRACE timesimp: obtained raw offset from server latency=11.13472ms delta=43µs 200ns
[INFO] [stdout] 2025-09-29T01:56:38.720240Z TRACE timesimp: sleeping to spread out requests delay=560.529778ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.720404Z TRACE new{response=Response { client: 2025-09-29T01:56:38.697690552Z, server: 2025-09-29T01:56:38.708886682Z } current=2025-09-29T01:56:38.720304752Z}: timesimp::delta: response processing internals latency=11ms 307µs 100ns local_at_midpoint=2025-09-29T01:56:38.708997652Z delta=110µs 970ns ago
[INFO] [stdout] 2025-09-29T01:56:38.720460Z TRACE timesimp: obtained raw offset from server latency=11.3071ms delta=110µs 970ns ago
[INFO] [stdout] 2025-09-29T01:56:38.720476Z TRACE timesimp: sleeping to spread out requests delay=483.372911ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.721342Z TRACE new{response=Response { client: 2025-09-29T01:56:38.698870502Z, server: 2025-09-29T01:56:43.710013552Z } current=2025-09-29T01:56:38.721236782Z}: timesimp::delta: response processing internals latency=11ms 183µs 140ns local_at_midpoint=2025-09-29T01:56:38.710053642Z delta=4s 999ms 959µs 910ns
[INFO] [stdout] 2025-09-29T01:56:38.721405Z TRACE timesimp: obtained raw offset from server latency=11.18314ms delta=4s 999ms 959µs 910ns
[INFO] [stdout] 2025-09-29T01:56:38.721421Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 959µs 910ns
[INFO] [stdout] 2025-09-29T01:56:38.721432Z TRACE timesimp: sleeping to spread out requests delay=301.333679ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.723997Z TRACE new{response=Response { client: 2025-09-29T01:56:38.699293042Z, server: 2025-09-29T01:56:33.712671042Z } current=2025-09-29T01:56:38.723840372Z}: timesimp::delta: response processing internals latency=12ms 273µs 665ns local_at_midpoint=2025-09-29T01:56:38.711566707Z delta=4s 998ms 895µs 665ns ago
[INFO] [stdout] 2025-09-29T01:56:38.724076Z TRACE timesimp: obtained raw offset from server latency=12.273665ms delta=4s 998ms 895µs 665ns ago
[INFO] [stdout] 2025-09-29T01:56:38.724137Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 998ms 895µs 665ns ago
[INFO] [stdout] 2025-09-29T01:56:38.724153Z TRACE timesimp: sleeping to spread out requests delay=392.852512ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:38.904916Z TRACE new{response=Response { client: 2025-09-29T01:56:38.698968042Z, server: 2025-09-29T01:56:38.80269488Z } current=2025-09-29T01:56:38.904707077Z}: timesimp::delta: response processing internals latency=102ms 869µs 517ns local_at_midpoint=2025-09-29T01:56:38.801837559Z delta=857µs 321ns
[INFO] [stdout] 2025-09-29T01:56:38.905013Z TRACE timesimp: obtained raw offset from server latency=102.869517ms delta=857µs 321ns
[INFO] [stdout] 2025-09-29T01:56:38.905033Z DEBUG timesimp: no offset stored, storing initial delta offset=857µs 321ns
[INFO] [stdout] 2025-09-29T01:56:38.905045Z TRACE timesimp: sleeping to spread out requests delay=1.311377745s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.048263Z TRACE new{response=Response { client: 2025-09-29T01:56:39.026704394Z, server: 2025-09-29T01:56:44.036896363Z } current=2025-09-29T01:56:39.048094663Z}: timesimp::delta: response processing internals latency=10ms 695µs 134ns local_at_midpoint=2025-09-29T01:56:39.037399528Z delta=4s 999ms 496µs 835ns
[INFO] [stdout] 2025-09-29T01:56:39.048356Z TRACE timesimp: obtained raw offset from server latency=10.695134ms delta=4s 999ms 496µs 835ns
[INFO] [stdout] 2025-09-29T01:56:39.048378Z TRACE timesimp: sleeping to spread out requests delay=1.289216237s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.141397Z TRACE new{response=Response { client: 2025-09-29T01:56:39.118820371Z, server: 2025-09-29T01:56:34.130012801Z } current=2025-09-29T01:56:39.141213771Z}: timesimp::delta: response processing internals latency=11ms 196µs 700ns local_at_midpoint=2025-09-29T01:56:39.130017071Z delta=5s 4µs 270ns ago
[INFO] [stdout] 2025-09-29T01:56:39.141502Z TRACE timesimp: obtained raw offset from server latency=11.1967ms delta=5s 4µs 270ns ago
[INFO] [stdout] 2025-09-29T01:56:39.141525Z TRACE timesimp: sleeping to spread out requests delay=1.43758436s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.157863Z TRACE new{response=Response { client: 2025-09-29T01:56:39.143824731Z, server: 2025-09-29T01:56:44.150106491Z } current=2025-09-29T01:56:39.15769421Z}: timesimp::delta: response processing internals latency=6ms 934µs 739ns local_at_midpoint=2025-09-29T01:56:39.15075947Z delta=4s 999ms 347µs 21ns
[INFO] [stdout] 2025-09-29T01:56:39.157975Z TRACE timesimp: obtained raw offset from server latency=6.934739ms delta=4s 999ms 347µs 21ns
[INFO] [stdout] 2025-09-29T01:56:39.157998Z TRACE timesimp: sleeping to spread out requests delay=1.110275528s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.226563Z TRACE new{response=Response { client: 2025-09-29T01:56:39.204852169Z, server: 2025-09-29T01:56:39.215191929Z } current=2025-09-29T01:56:39.226390769Z}: timesimp::delta: response processing internals latency=10ms 769µs 300ns local_at_midpoint=2025-09-29T01:56:39.215621469Z delta=429µs 540ns ago
[INFO] [stdout] 2025-09-29T01:56:39.226677Z TRACE timesimp: obtained raw offset from server latency=10.7693ms delta=429µs 540ns ago
[INFO] [stdout] 2025-09-29T01:56:39.226697Z TRACE timesimp: sleeping to spread out requests delay=1.003285825s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.304233Z TRACE new{response=Response { client: 2025-09-29T01:56:39.281808327Z, server: 2025-09-29T01:56:39.292950587Z } current=2025-09-29T01:56:39.304076447Z}: timesimp::delta: response processing internals latency=11ms 134µs 60ns local_at_midpoint=2025-09-29T01:56:39.292942387Z delta=8µs 200ns
[INFO] [stdout] 2025-09-29T01:56:39.304320Z TRACE timesimp: obtained raw offset from server latency=11.13406ms delta=8µs 200ns
[INFO] [stdout] 2025-09-29T01:56:39.304338Z TRACE timesimp: sleeping to spread out requests delay=124.171802ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.451315Z TRACE new{response=Response { client: 2025-09-29T01:56:39.443852563Z, server: 2025-09-29T01:56:44.448011123Z } current=2025-09-29T01:56:39.451146523Z}: timesimp::delta: response processing internals latency=3ms 646µs 980ns local_at_midpoint=2025-09-29T01:56:39.447499543Z delta=5s 511µs 580ns
[INFO] [stdout] 2025-09-29T01:56:39.451494Z TRACE timesimp: obtained raw offset from server latency=3.64698ms delta=5s 511µs 580ns
[INFO] [stdout] 2025-09-29T01:56:39.451569Z TRACE timesimp: sleeping to spread out requests delay=241.827029ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.454108Z TRACE new{response=Response { client: 2025-09-29T01:56:39.429713213Z, server: 2025-09-29T01:56:39.442730643Z } current=2025-09-29T01:56:39.453935943Z}: timesimp::delta: response processing internals latency=12ms 111µs 365ns local_at_midpoint=2025-09-29T01:56:39.441824578Z delta=906µs 65ns
[INFO] [stdout] 2025-09-29T01:56:39.454200Z TRACE timesimp: obtained raw offset from server latency=12.111365ms delta=906µs 65ns
[INFO] [stdout] 2025-09-29T01:56:39.454220Z TRACE timesimp: sleeping to spread out requests delay=1.336986818s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:39.713505Z TRACE new{response=Response { client: 2025-09-29T01:56:39.694941656Z, server: 2025-09-29T01:56:44.704132066Z } current=2025-09-29T01:56:39.713334626Z}: timesimp::delta: response processing internals latency=9ms 196µs 485ns local_at_midpoint=2025-09-29T01:56:39.704138141Z delta=4s 999ms 993µs 925ns
[INFO] [stdout] 2025-09-29T01:56:39.713619Z TRACE timesimp: obtained raw offset from server latency=9.196485ms delta=4s 999ms 993µs 925ns
[INFO] [stdout] 2025-09-29T01:56:39.713644Z TRACE timesimp: sleeping to spread out requests delay=465.991491ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.037405Z TRACE new{response=Response { client: 2025-09-29T01:56:40.015844978Z, server: 2025-09-29T01:56:45.027037068Z } current=2025-09-29T01:56:40.037232497Z}: timesimp::delta: response processing internals latency=10ms 693µs 759ns local_at_midpoint=2025-09-29T01:56:40.026538737Z delta=5s 498µs 331ns
[INFO] [stdout] 2025-09-29T01:56:40.037488Z TRACE timesimp: obtained raw offset from server latency=10.693759ms delta=5s 498µs 331ns
[INFO] [stdout] 2025-09-29T01:56:40.037507Z TRACE timesimp: sleeping to spread out requests delay=1.676377943s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.127242Z TRACE new{response=Response { client: 2025-09-29T01:56:40.124806155Z, server: 2025-09-29T01:56:40.125952025Z } current=2025-09-29T01:56:40.127078885Z}: timesimp::delta: response processing internals latency=1ms 136µs 365ns local_at_midpoint=2025-09-29T01:56:40.12594252Z delta=9µs 505ns
[INFO] [stdout] 2025-09-29T01:56:40.127329Z TRACE timesimp: obtained raw offset from server latency=1.136365ms delta=9µs 505ns
[INFO] [stdout] 2025-09-29T01:56:40.127350Z TRACE timesimp: sleeping to spread out requests delay=160.064222ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.159859Z TRACE new{response=Response { client: 2025-09-29T01:56:38.697690492Z, server: 2025-09-29T01:56:39.428669503Z } current=2025-09-29T01:56:40.159661214Z}: timesimp::delta: response processing internals latency=730ms 985µs 361ns local_at_midpoint=2025-09-29T01:56:39.428675853Z delta=6µs 350ns ago
[INFO] [stdout] 2025-09-29T01:56:40.159959Z TRACE timesimp: obtained raw offset from server latency=730.985361ms delta=6µs 350ns ago
[INFO] [stdout] 2025-09-29T01:56:40.159976Z DEBUG timesimp: no offset stored, storing initial delta offset=6µs 350ns ago
[INFO] [stdout] 2025-09-29T01:56:40.159987Z TRACE timesimp: sleeping to spread out requests delay=401.112593ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.207127Z TRACE new{response=Response { client: 2025-09-29T01:56:40.182716054Z, server: 2025-09-29T01:56:45.196716553Z } current=2025-09-29T01:56:40.206950673Z}: timesimp::delta: response processing internals latency=12ms 117µs 309ns local_at_midpoint=2025-09-29T01:56:40.194833363Z delta=5s 1ms 883µs 190ns
[INFO] [stdout] 2025-09-29T01:56:40.207213Z TRACE timesimp: obtained raw offset from server latency=12.117309ms delta=5s 1ms 883µs 190ns
[INFO] [stdout] 2025-09-29T01:56:40.207234Z TRACE timesimp: sleeping to spread out requests delay=295.318888ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.253528Z TRACE new{response=Response { client: 2025-09-29T01:56:40.231873442Z, server: 2025-09-29T01:56:40.242164042Z } current=2025-09-29T01:56:40.253361652Z}: timesimp::delta: response processing internals latency=10ms 744µs 105ns local_at_midpoint=2025-09-29T01:56:40.242617547Z delta=453µs 505ns ago
[INFO] [stdout] 2025-09-29T01:56:40.253638Z TRACE timesimp: obtained raw offset from server latency=10.744105ms delta=453µs 505ns ago
[INFO] [stdout] 2025-09-29T01:56:40.253667Z TRACE timesimp: sleeping to spread out requests delay=290.086606ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.291142Z TRACE new{response=Response { client: 2025-09-29T01:56:40.288712001Z, server: 2025-09-29T01:56:40.289859541Z } current=2025-09-29T01:56:40.290984361Z}: timesimp::delta: response processing internals latency=1ms 136µs 180ns local_at_midpoint=2025-09-29T01:56:40.289848181Z delta=11µs 360ns
[INFO] [stdout] 2025-09-29T01:56:40.291230Z TRACE timesimp: obtained raw offset from server latency=1.13618ms delta=11µs 360ns
[INFO] [stdout] 2025-09-29T01:56:40.291248Z TRACE timesimp: sleeping to spread out requests delay=621.968455ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.293792Z TRACE new{response=Response { client: 2025-09-29T01:56:40.269794001Z, server: 2025-09-29T01:56:45.280955781Z } current=2025-09-29T01:56:40.293673251Z}: timesimp::delta: response processing internals latency=11ms 939µs 625ns local_at_midpoint=2025-09-29T01:56:40.281733626Z delta=4s 999ms 222µs 155ns
[INFO] [stdout] 2025-09-29T01:56:40.293864Z TRACE timesimp: obtained raw offset from server latency=11.939625ms delta=4s 999ms 222µs 155ns
[INFO] [stdout] 2025-09-29T01:56:40.293881Z TRACE timesimp: sleeping to spread out requests delay=1.825893124s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.361355Z TRACE new{response=Response { client: 2025-09-29T01:56:40.338802929Z, server: 2025-09-29T01:56:45.349997899Z } current=2025-09-29T01:56:40.361191879Z}: timesimp::delta: response processing internals latency=11ms 194µs 475ns local_at_midpoint=2025-09-29T01:56:40.349997404Z delta=5s 495ns
[INFO] [stdout] 2025-09-29T01:56:40.361437Z TRACE timesimp: obtained raw offset from server latency=11.194475ms delta=5s 495ns
[INFO] [stdout] 2025-09-29T01:56:40.361456Z TRACE timesimp: sleeping to spread out requests delay=195.613235ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.422869Z TRACE new{response=Response { client: 2025-09-29T01:56:40.217840633Z, server: 2025-09-29T01:56:40.31919019Z } current=2025-09-29T01:56:40.422695367Z}: timesimp::delta: response processing internals latency=102ms 427µs 367ns local_at_midpoint=2025-09-29T01:56:40.320268Z delta=1ms 77µs 810ns ago
[INFO] [stdout] 2025-09-29T01:56:40.422963Z TRACE timesimp: obtained raw offset from server latency=102.427367ms delta=1ms 77µs 810ns ago
[INFO] [stdout] 2025-09-29T01:56:40.422983Z TRACE timesimp: sleeping to spread out requests delay=1.614762813s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.518392Z TRACE new{response=Response { client: 2025-09-29T01:56:40.503826015Z, server: 2025-09-29T01:56:45.511020935Z } current=2025-09-29T01:56:40.518215575Z}: timesimp::delta: response processing internals latency=7ms 194µs 780ns local_at_midpoint=2025-09-29T01:56:40.511020795Z delta=5s 140ns
[INFO] [stdout] 2025-09-29T01:56:40.518478Z TRACE timesimp: obtained raw offset from server latency=7.19478ms delta=5s 140ns
[INFO] [stdout] 2025-09-29T01:56:40.518509Z TRACE timesimp: response deltas sorted by latency deltas=[5000.51158, 5000.00014, 4999.993925, 5000.005085, 5001.88319]
[INFO] [stdout] 2025-09-29T01:56:40.518527Z TRACE timesimp: statistics about response deltas median=4999.993925 mean=5000.478784000001 variance=0.6655027154172803 stddev=0.8157834978824224
[INFO] [stdout] 2025-09-29T01:56:40.518542Z TRACE timesimp: eliminated outliers inliers=[5000.51158, 5000.00014, 4999.993925, 5000.005085]
[INFO] [stdout] 2025-09-29T01:56:40.518553Z DEBUG timesimp: storing calculated offset offset=5s 127µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-09-29T01:56:40.566808Z TRACE new{response=Response { client: 2025-09-29T01:56:40.544173634Z, server: 2025-09-29T01:56:40.555463084Z } current=2025-09-29T01:56:40.566630294Z}: timesimp::delta: response processing internals latency=11ms 228µs 330ns local_at_midpoint=2025-09-29T01:56:40.555401964Z delta=61µs 120ns
[INFO] [stdout] 2025-09-29T01:56:40.566897Z TRACE timesimp: obtained raw offset from server latency=11.22833ms delta=61µs 120ns
[INFO] [stdout] 2025-09-29T01:56:40.566919Z TRACE timesimp: sleeping to spread out requests delay=1.626701569s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.586862Z TRACE new{response=Response { client: 2025-09-29T01:56:40.560710204Z, server: 2025-09-29T01:56:45.572698823Z } current=2025-09-29T01:56:40.586697813Z}: timesimp::delta: response processing internals latency=12ms 993µs 804ns local_at_midpoint=2025-09-29T01:56:40.573704008Z delta=4s 998ms 994µs 815ns
[INFO] [stdout] 2025-09-29T01:56:40.586954Z TRACE timesimp: obtained raw offset from server latency=12.993804ms delta=4s 998ms 994µs 815ns
[INFO] [stdout] 2025-09-29T01:56:40.586971Z TRACE timesimp: sleeping to spread out requests delay=992.475216ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.603346Z TRACE new{response=Response { client: 2025-09-29T01:56:40.580799863Z, server: 2025-09-29T01:56:35.591991003Z } current=2025-09-29T01:56:40.603178013Z}: timesimp::delta: response processing internals latency=11ms 189µs 75ns local_at_midpoint=2025-09-29T01:56:40.591988938Z delta=4s 999ms 997µs 935ns ago
[INFO] [stdout] 2025-09-29T01:56:40.603428Z TRACE timesimp: obtained raw offset from server latency=11.189075ms delta=4s 999ms 997µs 935ns ago
[INFO] [stdout] 2025-09-29T01:56:40.603446Z TRACE timesimp: sleeping to spread out requests delay=464.047208ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.815513Z TRACE new{response=Response { client: 2025-09-29T01:56:40.792849948Z, server: 2025-09-29T01:56:40.804039107Z } current=2025-09-29T01:56:40.815347857Z}: timesimp::delta: response processing internals latency=11ms 248µs 954ns local_at_midpoint=2025-09-29T01:56:40.804098902Z delta=59µs 795ns ago
[INFO] [stdout] 2025-09-29T01:56:40.815621Z TRACE timesimp: obtained raw offset from server latency=11.248954ms delta=59µs 795ns ago
[INFO] [stdout] 2025-09-29T01:56:40.815654Z TRACE timesimp: sleeping to spread out requests delay=1.248370834s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:40.924002Z TRACE new{response=Response { client: 2025-09-29T01:56:40.918714674Z, server: 2025-09-29T01:56:40.922683084Z } current=2025-09-29T01:56:40.923832294Z}: timesimp::delta: response processing internals latency=2ms 558µs 810ns local_at_midpoint=2025-09-29T01:56:40.921273484Z delta=1ms 409µs 600ns
[INFO] [stdout] 2025-09-29T01:56:40.924094Z TRACE timesimp: obtained raw offset from server latency=2.55881ms delta=1ms 409µs 600ns
[INFO] [stdout] 2025-09-29T01:56:40.924115Z TRACE timesimp: sleeping to spread out requests delay=208.927211ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:41.103759Z TRACE new{response=Response { client: 2025-09-29T01:56:41.08117937Z, server: 2025-09-29T01:56:36.0923756Z } current=2025-09-29T01:56:41.103571029Z}: timesimp::delta: response processing internals latency=11ms 195µs 829ns local_at_midpoint=2025-09-29T01:56:41.092375199Z delta=4s 999ms 999µs 599ns ago
[INFO] [stdout] 2025-09-29T01:56:41.103850Z TRACE timesimp: obtained raw offset from server latency=11.195829ms delta=4s 999ms 999µs 599ns ago
[INFO] [stdout] 2025-09-29T01:56:41.103872Z TRACE timesimp: sleeping to spread out requests delay=606.111572ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:41.146847Z TRACE new{response=Response { client: 2025-09-29T01:56:41.135688149Z, server: 2025-09-29T01:56:41.142745628Z } current=2025-09-29T01:56:41.146677188Z}: timesimp::delta: response processing internals latency=5ms 494µs 519ns local_at_midpoint=2025-09-29T01:56:41.141182668Z delta=1ms 562µs 960ns
[INFO] [stdout] 2025-09-29T01:56:41.146949Z TRACE timesimp: obtained raw offset from server latency=5.494519ms delta=1ms 562µs 960ns
[INFO] [stdout] 2025-09-29T01:56:41.146977Z TRACE timesimp: response deltas sorted by latency deltas=[0.01136, 0.009505, 0.509375, 1.4096, 1.56296]
[INFO] [stdout] 2025-09-29T01:56:41.146994Z TRACE timesimp: statistics about response deltas median=0.509375 mean=0.70056 variance=0.5588942097124999 stddev=0.7475922750487058
[INFO] [stdout] 2025-09-29T01:56:41.147009Z TRACE timesimp: eliminated outliers inliers=[0.01136, 0.009505, 0.509375]
[INFO] [stdout] 2025-09-29T01:56:41.147031Z DEBUG timesimp: storing calculated offset offset=176µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-09-29T01:56:41.603408Z TRACE new{response=Response { client: 2025-09-29T01:56:41.580839537Z, server: 2025-09-29T01:56:46.592033037Z } current=2025-09-29T01:56:41.603237716Z}: timesimp::delta: response processing internals latency=11ms 199µs 89ns local_at_midpoint=2025-09-29T01:56:41.592038626Z delta=4s 999ms 994µs 411ns
[INFO] [stdout] 2025-09-29T01:56:41.603583Z TRACE timesimp: obtained raw offset from server latency=11.199089ms delta=4s 999ms 994µs 411ns
[INFO] [stdout] 2025-09-29T01:56:41.603696Z TRACE timesimp: response deltas sorted by latency deltas=[4999.496835, 4999.95991, 5000.000495, 4999.994411, 4998.994815]
[INFO] [stdout] 2025-09-29T01:56:41.603775Z TRACE timesimp: statistics about response deltas median=5000.000495 mean=4999.6892932 variance=0.19562925341613085 stddev=0.44229995864360067
[INFO] [stdout] 2025-09-29T01:56:41.603835Z TRACE timesimp: eliminated outliers inliers=[4999.95991, 5000.000495, 4999.994411]
[INFO] [stdout] 2025-09-29T01:56:41.603866Z DEBUG timesimp: storing calculated offset offset=4s 999ms 984µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2025-09-29T01:56:41.742877Z TRACE new{response=Response { client: 2025-09-29T01:56:41.711716834Z, server: 2025-09-29T01:56:36.729703883Z } current=2025-09-29T01:56:41.742700143Z}: timesimp::delta: response processing internals latency=15ms 491µs 654ns local_at_midpoint=2025-09-29T01:56:41.727208488Z delta=4s 997ms 504µs 605ns ago
[INFO] [stdout] 2025-09-29T01:56:41.742975Z TRACE timesimp: obtained raw offset from server latency=15.491654ms delta=4s 997ms 504µs 605ns ago
[INFO] [stdout] 2025-09-29T01:56:41.743005Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.997935, -4999.999599, -5000.00427, -4998.895665, -4997.504605]
[INFO] [stdout] 2025-09-29T01:56:41.743023Z TRACE timesimp: statistics about response deltas median=-5000.00427 mean=-4999.2804148 variance=1.214390088970286 stddev=1.1019936882624537
[INFO] [stdout] 2025-09-29T01:56:41.743047Z TRACE timesimp: eliminated outliers inliers=[-4999.997935, -4999.999599, -5000.00427]
[INFO] [stdout] 2025-09-29T01:56:41.743059Z DEBUG timesimp: storing calculated offset offset=5s ago
[INFO] [stdout] 2025-09-29T01:56:41.744109Z TRACE new{response=Response { client: 2025-09-29T01:56:41.723699333Z, server: 2025-09-29T01:56:46.733868533Z } current=2025-09-29T01:56:41.744023123Z}: timesimp::delta: response processing internals latency=10ms 161µs 895ns local_at_midpoint=2025-09-29T01:56:41.733861228Z delta=5s 7µs 305ns
[INFO] [stdout] 2025-09-29T01:56:41.744166Z TRACE timesimp: obtained raw offset from server latency=10.161895ms delta=5s 7µs 305ns
[INFO] [stdout] 2025-09-29T01:56:41.744182Z TRACE timesimp: sleeping to spread out requests delay=213.08232ms max_jitter=2s
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-09-29T01:56:41.980307Z TRACE new{response=Response { client: 2025-09-29T01:56:41.958649957Z, server: 2025-09-29T01:56:46.969935747Z } current=2025-09-29T01:56:41.980135467Z}: timesimp::delta: response processing internals latency=10ms 742µs 755ns local_at_midpoint=2025-09-29T01:56:41.969392712Z delta=5s 543µs 35ns
[INFO] [stdout] 2025-09-29T01:56:41.980401Z TRACE timesimp: obtained raw offset from server latency=10.742755ms delta=5s 543µs 35ns
[INFO] [stdout] 2025-09-29T01:56:41.980424Z TRACE timesimp: sleeping to spread out requests delay=1.631818673s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:42.096975Z TRACE new{response=Response { client: 2025-09-29T01:56:42.072729844Z, server: 2025-09-29T01:56:42.085696914Z } current=2025-09-29T01:56:42.096794754Z}: timesimp::delta: response processing internals latency=12ms 32µs 455ns local_at_midpoint=2025-09-29T01:56:42.084762299Z delta=934µs 615ns
[INFO] [stdout] 2025-09-29T01:56:42.097062Z TRACE timesimp: obtained raw offset from server latency=12.032455ms delta=934µs 615ns
[INFO] [stdout] 2025-09-29T01:56:42.097087Z TRACE timesimp: response deltas sorted by latency deltas=[0.0082, 0.0432, -0.059795, 0.934615, 0.906065]
[INFO] [stdout] 2025-09-29T01:56:42.097102Z TRACE timesimp: statistics about response deltas median=-0.059795 mean=0.366457 variance=0.2571285600575 stddev=0.5070784555248823
[INFO] [stdout] 2025-09-29T01:56:42.097122Z TRACE timesimp: eliminated outliers inliers=[0.0082, 0.0432, -0.059795]
[INFO] [stdout] 2025-09-29T01:56:42.097132Z DEBUG timesimp: storing calculated offset offset=2µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-09-29T01:56:42.138390Z TRACE new{response=Response { client: 2025-09-29T01:56:42.120813413Z, server: 2025-09-29T01:56:47.130015953Z } current=2025-09-29T01:56:42.138212542Z}: timesimp::delta: response processing internals latency=8ms 699µs 564ns local_at_midpoint=2025-09-29T01:56:42.129512977Z delta=5s 502µs 976ns
[INFO] [stdout] 2025-09-29T01:56:42.138480Z TRACE timesimp: obtained raw offset from server latency=8.699564ms delta=5s 502µs 976ns
[INFO] [stdout] 2025-09-29T01:56:42.138501Z TRACE timesimp: sleeping to spread out requests delay=1.733601387s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:42.228872Z TRACE new{response=Response { client: 2025-09-29T01:56:42.200710471Z, server: 2025-09-29T01:56:42.214709581Z } current=2025-09-29T01:56:42.22870285Z}: timesimp::delta: response processing internals latency=13ms 996µs 189ns local_at_midpoint=2025-09-29T01:56:42.21470666Z delta=2µs 921ns
[INFO] [stdout] 2025-09-29T01:56:42.228958Z TRACE timesimp: obtained raw offset from server latency=13.996189ms delta=2µs 921ns
[INFO] [stdout] 2025-09-29T01:56:42.228983Z TRACE timesimp: response deltas sorted by latency deltas=[-0.453505, -0.42954, 0.06112, -0.11097, 0.002921]
[INFO] [stdout] 2025-09-29T01:56:42.228998Z TRACE timesimp: statistics about response deltas median=0.06112 mean=-0.18599480000000002 variance=0.0583148990077 stddev=0.2414847800746457
[INFO] [stdout] 2025-09-29T01:56:42.229020Z TRACE timesimp: eliminated outliers inliers=[0.06112, -0.11097, 0.002921]
[INFO] [stdout] 2025-09-29T01:56:42.229029Z DEBUG timesimp: storing calculated offset offset=15µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2025-09-29T01:56:42.244526Z TRACE new{response=Response { client: 2025-09-29T01:56:42.041703125Z, server: 2025-09-29T01:56:42.143012622Z } current=2025-09-29T01:56:42.24435349Z}: timesimp::delta: response processing internals latency=101ms 325µs 182ns local_at_midpoint=2025-09-29T01:56:42.143028307Z delta=15µs 685ns ago
[INFO] [stdout] 2025-09-29T01:56:42.244652Z TRACE timesimp: obtained raw offset from server latency=101.325182ms delta=15µs 685ns ago
[INFO] [stdout] 2025-09-29T01:56:42.244672Z TRACE timesimp: sleeping to spread out requests delay=370.305803ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:42.379052Z TRACE new{response=Response { client: 2025-09-29T01:56:40.562818274Z, server: 2025-09-29T01:56:41.47170092Z } current=2025-09-29T01:56:42.378881286Z}: timesimp::delta: response processing internals latency=908ms 31µs 506ns local_at_midpoint=2025-09-29T01:56:41.47084978Z delta=851µs 140ns
[INFO] [stdout] 2025-09-29T01:56:42.379139Z TRACE timesimp: obtained raw offset from server latency=908.031506ms delta=851µs 140ns
[INFO] [stdout] 2025-09-29T01:56:42.379159Z TRACE timesimp: sleeping to spread out requests delay=29.891781ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:42.819201Z TRACE new{response=Response { client: 2025-09-29T01:56:42.61632695Z, server: 2025-09-29T01:56:42.717717438Z } current=2025-09-29T01:56:42.819040505Z}: timesimp::delta: response processing internals latency=101ms 356µs 777ns local_at_midpoint=2025-09-29T01:56:42.717683727Z delta=33µs 711ns
[INFO] [stdout] 2025-09-29T01:56:42.819358Z TRACE timesimp: obtained raw offset from server latency=101.356777ms delta=33µs 711ns
[INFO] [stdout] 2025-09-29T01:56:42.819423Z TRACE timesimp: sleeping to spread out requests delay=612.428154ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:43.636749Z TRACE new{response=Response { client: 2025-09-29T01:56:43.433867079Z, server: 2025-09-29T01:56:43.535213666Z } current=2025-09-29T01:56:43.636549783Z}: timesimp::delta: response processing internals latency=101ms 341µs 352ns local_at_midpoint=2025-09-29T01:56:43.535208431Z delta=5µs 235ns
[INFO] [stdout] 2025-09-29T01:56:43.636834Z TRACE timesimp: obtained raw offset from server latency=101.341352ms delta=5µs 235ns
[INFO] [stdout] 2025-09-29T01:56:43.636860Z TRACE timesimp: response deltas sorted by latency deltas=[-0.015685, 0.005235, 0.033711, -1.07781, 0.857321]
[INFO] [stdout] 2025-09-29T01:56:43.636876Z TRACE timesimp: statistics about response deltas median=0.033711 mean=-0.03944559999999999 variance=0.4725759430787999 stddev=0.6874415924853543
[INFO] [stdout] 2025-09-29T01:56:43.636892Z TRACE timesimp: eliminated outliers inliers=[-0.015685, 0.005235, 0.033711]
[INFO] [stdout] 2025-09-29T01:56:43.636908Z DEBUG timesimp: storing calculated offset offset=7µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-09-29T01:56:43.641866Z TRACE new{response=Response { client: 2025-09-29T01:56:43.613847214Z, server: 2025-09-29T01:56:48.625043364Z } current=2025-09-29T01:56:43.641695703Z}: timesimp::delta: response processing internals latency=13ms 924µs 244ns local_at_midpoint=2025-09-29T01:56:43.627771458Z delta=4s 997ms 271µs 906ns
[INFO] [stdout] 2025-09-29T01:56:43.641962Z TRACE timesimp: obtained raw offset from server latency=13.924244ms delta=4s 997ms 271µs 906ns
[INFO] [stdout] 2025-09-29T01:56:43.641988Z TRACE timesimp: response deltas sorted by latency deltas=[5000.007305, 5000.483485, 5000.498331, 5000.543035, 4997.271906]
[INFO] [stdout] 2025-09-29T01:56:43.642010Z TRACE timesimp: statistics about response deltas median=5000.498331 mean=4999.760812399999 variance=1.983368809475586 stddev=1.4083212735294408
[INFO] [stdout] 2025-09-29T01:56:43.642037Z TRACE timesimp: eliminated outliers inliers=[5000.007305, 5000.483485, 5000.498331, 5000.543035]
[INFO] [stdout] 2025-09-29T01:56:43.642049Z DEBUG timesimp: storing calculated offset offset=5s 383µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-09-29T01:56:43.887428Z TRACE new{response=Response { client: 2025-09-29T01:56:43.873852487Z, server: 2025-09-29T01:56:48.881052137Z } current=2025-09-29T01:56:43.887255477Z}: timesimp::delta: response processing internals latency=6ms 701µs 495ns local_at_midpoint=2025-09-29T01:56:43.880553982Z delta=5s 498µs 155ns
[INFO] [stdout] 2025-09-29T01:56:43.887516Z TRACE timesimp: obtained raw offset from server latency=6.701495ms delta=5s 498µs 155ns
[INFO] [stdout] 2025-09-29T01:56:43.887542Z TRACE timesimp: response deltas sorted by latency deltas=[5000.498155, 4999.347021, 4999.7260750000005, 5000.502976, 4999.222155]
[INFO] [stdout] 2025-09-29T01:56:43.887565Z TRACE timesimp: statistics about response deltas median=4999.7260750000005 mean=4999.8592763999995 variance=0.377146731676746 stddev=0.6141227333984193
[INFO] [stdout] 2025-09-29T01:56:43.887580Z TRACE timesimp: eliminated outliers inliers=[4999.347021, 4999.7260750000005, 4999.222155]
[INFO] [stdout] 2025-09-29T01:56:43.887621Z DEBUG timesimp: storing calculated offset offset=4s 999ms 431µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-09-29T01:56:43.991017Z TRACE new{response=Response { client: 2025-09-29T01:56:42.410486455Z, server: 2025-09-29T01:56:43.200272115Z } current=2025-09-29T01:56:43.990839874Z}: timesimp::delta: response processing internals latency=790ms 176µs 709ns local_at_midpoint=2025-09-29T01:56:43.200663164Z delta=391µs 49ns ago
[INFO] [stdout] 2025-09-29T01:56:43.991107Z TRACE timesimp: obtained raw offset from server latency=790.176709ms delta=391µs 49ns ago
[INFO] [stdout] 2025-09-29T01:56:43.991127Z TRACE timesimp: sleeping to spread out requests delay=1.431163644s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:46.954125Z TRACE new{response=Response { client: 2025-09-29T01:56:45.427206787Z, server: 2025-09-29T01:56:46.190852637Z } current=2025-09-29T01:56:46.953960397Z}: timesimp::delta: response processing internals latency=763ms 376µs 805ns local_at_midpoint=2025-09-29T01:56:46.190583592Z delta=269µs 45ns
[INFO] [stdout] 2025-09-29T01:56:46.954216Z TRACE timesimp: obtained raw offset from server latency=763.376805ms delta=269µs 45ns
[INFO] [stdout] 2025-09-29T01:56:46.954235Z TRACE timesimp: sleeping to spread out requests delay=320.486456ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.900915Z TRACE new{response=Response { client: 2025-09-29T01:56:47.275871629Z, server: 2025-09-29T01:56:48.087846637Z } current=2025-09-29T01:56:48.900740306Z}: timesimp::delta: response processing internals latency=812ms 434µs 338ns local_at_midpoint=2025-09-29T01:56:48.088305967Z delta=459µs 330ns ago
[INFO] [stdout] 2025-09-29T01:56:48.900999Z TRACE timesimp: obtained raw offset from server latency=812.434338ms delta=459µs 330ns ago
[INFO] [stdout] 2025-09-29T01:56:48.901025Z TRACE timesimp: response deltas sorted by latency deltas=[-0.00635, 0.269045, -0.391049, -0.45933, 0.85114]
[INFO] [stdout] 2025-09-29T01:56:48.901043Z TRACE timesimp: statistics about response deltas median=-0.391049 mean=0.05269119999999998 variance=0.2867215976597 stddev=0.5354639088301844
[INFO] [stdout] 2025-09-29T01:56:48.901059Z TRACE timesimp: eliminated outliers inliers=[-0.00635, -0.391049, -0.45933]
[INFO] [stdout] 2025-09-29T01:56:48.901070Z DEBUG timesimp: storing calculated offset offset=285µ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 10.21s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-8a8f317043a374d8)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-09-29T01:56:48.905388Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:48.905433Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-29T01:56:48.905491Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.905511Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.905415Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-29T01:56:48.905544Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.906903Z TRACE new{response=Response { client: 2025-09-29T01:56:48.906742736Z, server: 2025-09-29T01:56:48.906757826Z } current=2025-09-29T01:56:48.906760976Z}: timesimp::delta: response processing internals latency=9µs 120ns local_at_midpoint=2025-09-29T01:56:48.906751856Z delta=5µs 970ns
[INFO] [stdout] 2025-09-29T01:56:48.906913Z TRACE new{response=Response { client: 2025-09-29T01:56:48.906756536Z, server: 2025-09-29T01:56:48.906760106Z } current=2025-09-29T01:56:48.906762106Z}: timesimp::delta: response processing internals latency=2µs 785ns local_at_midpoint=2025-09-29T01:56:48.906759321Z delta=785ns
[INFO] [stdout] 2025-09-29T01:56:48.906979Z TRACE timesimp: obtained raw offset from server latency=9.12µs delta=5µs 970ns
[INFO] [stdout] 2025-09-29T01:56:48.906992Z TRACE timesimp: sleeping to spread out requests delay=1.518371092s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.906965Z TRACE new{response=Response { client: 2025-09-29T01:56:48.906800906Z, server: 2025-09-29T01:56:53.906809466Z } current=2025-09-29T01:56:48.906812536Z}: timesimp::delta: response processing internals latency=5µs 815ns local_at_midpoint=2025-09-29T01:56:48.906806721Z delta=5s 2µs 745ns
[INFO] [stdout] 2025-09-29T01:56:48.906990Z TRACE timesimp: obtained raw offset from server latency=2.785µs delta=785ns
[INFO] [stdout] 2025-09-29T01:56:48.907015Z DEBUG timesimp: no offset stored, storing initial delta offset=785ns
[INFO] [stdout] 2025-09-29T01:56:48.907021Z TRACE timesimp: obtained raw offset from server latency=5.815µs delta=5s 2µs 745ns
[INFO] [stdout] 2025-09-29T01:56:48.907036Z TRACE timesimp: sleeping to spread out requests delay=1.669073951s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.907026Z TRACE timesimp: sleeping to spread out requests delay=1.493927628s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.907633Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-29T01:56:48.907720Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:48.909077Z TRACE new{response=Response { client: 2025-09-29T01:56:48.908955416Z, server: 2025-09-29T01:56:43.908959466Z } current=2025-09-29T01:56:48.908961296Z}: timesimp::delta: response processing internals latency=2µs 940ns local_at_midpoint=2025-09-29T01:56:48.908958356Z delta=4s 999ms 998µs 890ns ago
[INFO] [stdout] 2025-09-29T01:56:48.909174Z TRACE timesimp: obtained raw offset from server latency=2.94µs delta=4s 999ms 998µs 890ns ago
[INFO] [stdout] 2025-09-29T01:56:48.909215Z TRACE timesimp: sleeping to spread out requests delay=1.490674749s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:50.401219Z TRACE new{response=Response { client: 2025-09-29T01:56:50.401036487Z, server: 2025-09-29T01:56:45.401047117Z } current=2025-09-29T01:56:50.401051317Z}: timesimp::delta: response processing internals latency=7µs 415ns local_at_midpoint=2025-09-29T01:56:50.401043902Z delta=4s 999ms 996µs 785ns ago
[INFO] [stdout] 2025-09-29T01:56:50.401367Z TRACE timesimp: obtained raw offset from server latency=7.415µs delta=4s 999ms 996µs 785ns ago
[INFO] [stdout] 2025-09-29T01:56:50.401422Z TRACE timesimp: sleeping to spread out requests delay=439.615294ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:50.401982Z TRACE new{response=Response { client: 2025-09-29T01:56:50.401882537Z, server: 2025-09-29T01:56:50.401887122Z } current=2025-09-29T01:56:50.401888317Z}: timesimp::delta: response processing internals latency=2µs 890ns local_at_midpoint=2025-09-29T01:56:50.401885427Z delta=1µs 695ns
[INFO] [stdout] 2025-09-29T01:56:50.402039Z TRACE timesimp: obtained raw offset from server latency=2.89µs delta=1µs 695ns
[INFO] [stdout] 2025-09-29T01:56:50.402054Z TRACE timesimp: sleeping to spread out requests delay=904.315102ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:50.427080Z TRACE new{response=Response { client: 2025-09-29T01:56:50.426910357Z, server: 2025-09-29T01:56:50.426919677Z } current=2025-09-29T01:56:50.426922946Z}: timesimp::delta: response processing internals latency=6µs 294ns local_at_midpoint=2025-09-29T01:56:50.426916651Z delta=3µs 26ns
[INFO] [stdout] 2025-09-29T01:56:50.427162Z TRACE timesimp: obtained raw offset from server latency=6.294µs delta=3µs 26ns
[INFO] [stdout] 2025-09-29T01:56:50.427180Z TRACE timesimp: sleeping to spread out requests delay=1.77959972s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:50.583873Z TRACE new{response=Response { client: 2025-09-29T01:56:50.583700582Z, server: 2025-09-29T01:56:55.583710182Z } current=2025-09-29T01:56:50.583714042Z}: timesimp::delta: response processing internals latency=6µs 730ns local_at_midpoint=2025-09-29T01:56:50.583707312Z delta=5s 2µs 870ns
[INFO] [stdout] 2025-09-29T01:56:50.583957Z TRACE timesimp: obtained raw offset from server latency=6.73µs delta=5s 2µs 870ns
[INFO] [stdout] 2025-09-29T01:56:50.583976Z TRACE timesimp: sleeping to spread out requests delay=1.418811099s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:50.843051Z TRACE new{response=Response { client: 2025-09-29T01:56:50.842866966Z, server: 2025-09-29T01:56:45.842877766Z } current=2025-09-29T01:56:50.842881146Z}: timesimp::delta: response processing internals latency=7µs 90ns local_at_midpoint=2025-09-29T01:56:50.842874056Z delta=4s 999ms 996µs 290ns ago
[INFO] [stdout] 2025-09-29T01:56:50.843137Z TRACE timesimp: obtained raw offset from server latency=7.09µs delta=4s 999ms 996µs 290ns ago
[INFO] [stdout] 2025-09-29T01:56:50.843156Z TRACE timesimp: sleeping to spread out requests delay=541.714431ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:51.308018Z TRACE new{response=Response { client: 2025-09-29T01:56:51.307840643Z, server: 2025-09-29T01:56:51.307852239Z } current=2025-09-29T01:56:51.307855414Z}: timesimp::delta: response processing internals latency=7µs 385ns local_at_midpoint=2025-09-29T01:56:51.307848028Z delta=4µs 211ns
[INFO] [stdout] 2025-09-29T01:56:51.308099Z TRACE timesimp: obtained raw offset from server latency=7.385µs delta=4µs 211ns
[INFO] [stdout] 2025-09-29T01:56:51.308116Z TRACE timesimp: sleeping to spread out requests delay=1.452351186s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:51.393888Z TRACE new{response=Response { client: 2025-09-29T01:56:51.393708831Z, server: 2025-09-29T01:56:46.393720011Z } current=2025-09-29T01:56:51.393723441Z}: timesimp::delta: response processing internals latency=7µs 305ns local_at_midpoint=2025-09-29T01:56:51.393716136Z delta=4s 999ms 996µs 125ns ago
[INFO] [stdout] 2025-09-29T01:56:51.393988Z TRACE timesimp: obtained raw offset from server latency=7.305µs delta=4s 999ms 996µs 125ns ago
[INFO] [stdout] 2025-09-29T01:56:51.394007Z TRACE timesimp: sleeping to spread out requests delay=1.732645628s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:52.004669Z TRACE new{response=Response { client: 2025-09-29T01:56:52.004451115Z, server: 2025-09-29T01:56:57.004462705Z } current=2025-09-29T01:56:52.004467115Z}: timesimp::delta: response processing internals latency=8µs local_at_midpoint=2025-09-29T01:56:52.004459115Z delta=5s 3µs 590ns
[INFO] [stdout] 2025-09-29T01:56:52.004759Z TRACE timesimp: obtained raw offset from server latency=8µs delta=5s 3µs 590ns
[INFO] [stdout] 2025-09-29T01:56:52.004779Z TRACE timesimp: sleeping to spread out requests delay=1.401853959s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:52.208026Z TRACE new{response=Response { client: 2025-09-29T01:56:52.20785747Z, server: 2025-09-29T01:56:52.20786722Z } current=2025-09-29T01:56:52.20787084Z}: timesimp::delta: response processing internals latency=6µs 685ns local_at_midpoint=2025-09-29T01:56:52.207864155Z delta=3µs 65ns
[INFO] [stdout] 2025-09-29T01:56:52.208104Z TRACE timesimp: obtained raw offset from server latency=6.685µs delta=3µs 65ns
[INFO] [stdout] 2025-09-29T01:56:52.208120Z TRACE timesimp: sleeping to spread out requests delay=512.179779ms max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:52.722034Z TRACE new{response=Response { client: 2025-09-29T01:56:52.721862757Z, server: 2025-09-29T01:56:52.721872377Z } current=2025-09-29T01:56:52.721875806Z}: timesimp::delta: response processing internals latency=6µs 524ns local_at_midpoint=2025-09-29T01:56:52.721869281Z delta=3µs 96ns
[INFO] [stdout] 2025-09-29T01:56:52.722117Z TRACE timesimp: obtained raw offset from server latency=6.524µs delta=3µs 96ns
[INFO] [stdout] 2025-09-29T01:56:52.722136Z TRACE timesimp: sleeping to spread out requests delay=1.974019091s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:52.762051Z TRACE new{response=Response { client: 2025-09-29T01:56:52.761868265Z, server: 2025-09-29T01:56:52.76187991Z } current=2025-09-29T01:56:52.761882716Z}: timesimp::delta: response processing internals latency=7µs 225ns local_at_midpoint=2025-09-29T01:56:52.76187549Z delta=4µs 420ns
[INFO] [stdout] 2025-09-29T01:56:52.762146Z TRACE timesimp: obtained raw offset from server latency=7.225µs delta=4µs 420ns
[INFO] [stdout] 2025-09-29T01:56:52.762166Z TRACE timesimp: sleeping to spread out requests delay=1.061907701s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:53.129896Z TRACE new{response=Response { client: 2025-09-29T01:56:53.129719266Z, server: 2025-09-29T01:56:48.129728836Z } current=2025-09-29T01:56:53.129732516Z}: timesimp::delta: response processing internals latency=6µs 625ns local_at_midpoint=2025-09-29T01:56:53.129725891Z delta=4s 999ms 997µs 55ns ago
[INFO] [stdout] 2025-09-29T01:56:53.130076Z TRACE timesimp: obtained raw offset from server latency=6.625µs delta=4s 999ms 997µs 55ns ago
[INFO] [stdout] 2025-09-29T01:56:53.130198Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99889, -4999.997055, -4999.99629, -4999.996125, -4999.996785]
[INFO] [stdout] 2025-09-29T01:56:53.130271Z TRACE timesimp: statistics about response deltas median=-4999.99629 mean=-4999.997028999999 variance=1.2217174999564801e-6 stddev=0.0011053133039805863
[INFO] [stdout] 2025-09-29T01:56:53.130465Z TRACE timesimp: eliminated outliers inliers=[-4999.997055, -4999.99629, -4999.996125, -4999.996785]
[INFO] [stdout] 2025-09-29T01:56:53.130528Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2025-09-29T01:56:53.407995Z TRACE new{response=Response { client: 2025-09-29T01:56:53.407830609Z, server: 2025-09-29T01:56:58.407840909Z } current=2025-09-29T01:56:53.407843959Z}: timesimp::delta: response processing internals latency=6µs 675ns local_at_midpoint=2025-09-29T01:56:53.407837284Z delta=5s 3µs 625ns
[INFO] [stdout] 2025-09-29T01:56:53.408075Z TRACE timesimp: obtained raw offset from server latency=6.675µs delta=5s 3µs 625ns
[INFO] [stdout] 2025-09-29T01:56:53.408094Z TRACE timesimp: sleeping to spread out requests delay=1.41863845s max_jitter=2s
[INFO] [stdout] 2025-09-29T01:56:53.826010Z TRACE new{response=Response { client: 2025-09-29T01:56:53.825845418Z, server: 2025-09-29T01:56:53.825856303Z } current=2025-09-29T01:56:53.825858778Z}: timesimp::delta: response processing internals latency=6µs 680ns local_at_midpoint=2025-09-29T01:56:53.825852098Z delta=4µs 205ns
[INFO] [stdout] 2025-09-29T01:56:53.826087Z TRACE timesimp: obtained raw offset from server latency=6.68µs delta=4µs 205ns
[INFO] [stdout] 2025-09-29T01:56:53.826109Z TRACE timesimp: response deltas sorted by latency deltas=[0.000785, 0.001695, 0.004205, 0.00442, 0.004211]
[INFO] [stdout] 2025-09-29T01:56:53.826124Z TRACE timesimp: statistics about response deltas median=0.004205 mean=0.0030632 variance=2.8810562000000006e-6 stddev=0.0016973674322314544
[INFO] [stdout] 2025-09-29T01:56:53.826138Z TRACE timesimp: eliminated outliers inliers=[0.004205, 0.00442, 0.004211]
[INFO] [stdout] 2025-09-29T01:56:53.826147Z DEBUG timesimp: storing calculated offset offset=4µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2025-09-29T01:56:54.698885Z TRACE new{response=Response { client: 2025-09-29T01:56:54.698707565Z, server: 2025-09-29T01:56:54.698717065Z } current=2025-09-29T01:56:54.698720675Z}: timesimp::delta: response processing internals latency=6µs 555ns local_at_midpoint=2025-09-29T01:56:54.69871412Z delta=2µs 945ns
[INFO] [stdout] 2025-09-29T01:56:54.698976Z TRACE timesimp: obtained raw offset from server latency=6.555µs delta=2µs 945ns
[INFO] [stdout] 2025-09-29T01:56:54.699002Z TRACE timesimp: response deltas sorted by latency deltas=[0.003026, 0.003096, 0.002945, 0.003065, 0.00597]
[INFO] [stdout] 2025-09-29T01:56:54.699030Z TRACE timesimp: statistics about response deltas median=0.002945 mean=0.0036204 variance=1.7283902999999994e-6 stddev=0.0013146825852653557
[INFO] [stdout] 2025-09-29T01:56:54.699046Z TRACE timesimp: eliminated outliers inliers=[0.003026, 0.003096, 0.002945, 0.003065]
[INFO] [stdout] 2025-09-29T01:56:54.699057Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2025-09-29T01:56:54.828031Z TRACE new{response=Response { client: 2025-09-29T01:56:54.827850672Z, server: 2025-09-29T01:56:59.827861202Z } current=2025-09-29T01:56:54.827865292Z}: timesimp::delta: response processing internals latency=7µs 310ns local_at_midpoint=2025-09-29T01:56:54.827857982Z delta=5s 3µs 220ns
[INFO] [stdout] 2025-09-29T01:56:54.828111Z TRACE timesimp: obtained raw offset from server latency=7.31µs delta=5s 3µs 220ns
[INFO] [stdout] 2025-09-29T01:56:54.828137Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002745, 5000.003625, 5000.00287, 5000.00322, 5000.00359]
[INFO] [stdout] 2025-09-29T01:56:54.828152Z TRACE timesimp: statistics about response deltas median=5000.00287 mean=5000.00321 variance=1.6213750011408483e-7 stddev=0.00040266301061071504
[INFO] [stdout] 2025-09-29T01:56:54.828168Z TRACE timesimp: eliminated outliers inliers=[5000.002745, 5000.00287, 5000.00322]
[INFO] [stdout] 2025-09-29T01:56:54.828178Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.92s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-cb84ba97497a9796)
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[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] [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.04s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "9c1da747ee3824f3f9629708b878c257f0e7495c39258de181f54338a95ddc41", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "9c1da747ee3824f3f9629708b878c257f0e7495c39258de181f54338a95ddc41", kill_on_drop: false }`
[INFO] [stdout] 9c1da747ee3824f3f9629708b878c257f0e7495c39258de181f54338a95ddc41