[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 1.98.0-beta.6+cargoflags=--release for beta-1.98-release-3
[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 1.98.0-beta.6
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.98.0-beta.6" "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" "+1.98.0-beta.6" "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/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,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" "-m" "1610612736" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:00c5645b54fe3ce5dae1417175e3c7fb6a6646c021d554ecd63a097b8b9f3602" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] 23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46
[INFO] running `Command { std: "docker" "start" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "build" "--frozen" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling cfg-if v1.0.0
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling pin-project-lite v0.2.16
[INFO] [stderr]    Compiling serde v1.0.219
[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 once_cell v1.21.3
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling ryu v1.0.20
[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 tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 37.75s
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "test" "--frozen" "--no-run" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling scopeguard v1.2.0
[INFO] [stderr]    Compiling futures-core v0.3.31
[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 icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling fnv v1.0.7
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling foreign-types-shared v0.1.1
[INFO] [stderr]    Compiling pin-utils v0.1.0
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling foreign-types v0.3.2
[INFO] [stderr]    Compiling atomic-waker v1.1.2
[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 utf8_iter v1.0.4
[INFO] [stderr]    Compiling try-lock v0.2.5
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling mime v0.3.17
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[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 tracing-attributes v0.1.28
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[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 serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling tracing v0.1.41
[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 icu_normalizer v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[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 `release` profile [optimized] target(s) in 46.42s
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "test" "--frozen" "--release", kill_on_drop: false }`
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 0.11s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/deps/timesimp-fa789e8bca5fd394)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... 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.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/release/deps/client_server-5357a3be2fee2b56)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2026-08-05T16:33:12.030865Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.030887Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.030891Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.030860Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-08-05T16:33:12.030907Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-08-05T16:33:12.030913Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.030898Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.030922Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.030917Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.030931Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.030997Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.031011Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.031105Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.031115Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.031151Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.031164Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.031295Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.031303Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:12.031309Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.031314Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.034386Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032203543Z, server: 2026-08-05T16:33:12.033292652Z } current=2026-08-05T16:33:12.034368702Z}: timesimp::delta: response processing internals latency=1ms 82µs 579ns local_at_midpoint=2026-08-05T16:33:12.033286122Z delta=6µs 530ns
[INFO] [stdout] 2026-08-05T16:33:12.034401Z TRACE timesimp: obtained raw offset from server latency=1.082579ms delta=6µs 530ns
[INFO] [stdout] 2026-08-05T16:33:12.034407Z DEBUG timesimp: no offset stored, storing initial delta offset=6µs 530ns
[INFO] [stdout] 2026-08-05T16:33:12.034409Z TRACE timesimp: sleeping to spread out requests delay=1.236456719s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.047186Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032009772Z, server: 2026-08-05T16:33:17.039089362Z } current=2026-08-05T16:33:12.047167991Z}: timesimp::delta: response processing internals latency=7ms 579µs 109ns local_at_midpoint=2026-08-05T16:33:12.039588881Z delta=4s 999ms 500µs 481ns
[INFO] [stdout] 2026-08-05T16:33:12.047202Z TRACE timesimp: obtained raw offset from server latency=7.579109ms delta=4s 999ms 500µs 481ns
[INFO] [stdout] 2026-08-05T16:33:12.047209Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 500µs 481ns
[INFO] [stdout] 2026-08-05T16:33:12.047213Z TRACE timesimp: sleeping to spread out requests delay=1.739095777s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.052179Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032009203Z, server: 2026-08-05T16:33:17.042085751Z } current=2026-08-05T16:33:12.05216595Z}: timesimp::delta: response processing internals latency=10ms 78µs 373ns local_at_midpoint=2026-08-05T16:33:12.042087576Z delta=4s 999ms 998µs 175ns
[INFO] [stdout] 2026-08-05T16:33:12.052192Z TRACE timesimp: obtained raw offset from server latency=10.078373ms delta=4s 999ms 998µs 175ns
[INFO] [stdout] 2026-08-05T16:33:12.052197Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 998µs 175ns
[INFO] [stdout] 2026-08-05T16:33:12.052199Z TRACE timesimp: sleeping to spread out requests delay=846.828762ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.052196Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032026152Z, server: 2026-08-05T16:33:17.042104502Z } current=2026-08-05T16:33:12.05218105Z}: timesimp::delta: response processing internals latency=10ms 77µs 449ns local_at_midpoint=2026-08-05T16:33:12.042103601Z delta=5s 901ns
[INFO] [stdout] 2026-08-05T16:33:12.052206Z TRACE timesimp: obtained raw offset from server latency=10.077449ms delta=5s 901ns
[INFO] [stdout] 2026-08-05T16:33:12.052210Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 901ns
[INFO] [stdout] 2026-08-05T16:33:12.052213Z TRACE timesimp: sleeping to spread out requests delay=1.457274482s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.054200Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032010263Z, server: 2026-08-05T16:33:12.043097422Z } current=2026-08-05T16:33:12.05418551Z}: timesimp::delta: response processing internals latency=11ms 87µs 623ns local_at_midpoint=2026-08-05T16:33:12.043097886Z delta=464ns ago
[INFO] [stdout] 2026-08-05T16:33:12.054216Z TRACE timesimp: obtained raw offset from server latency=11.087623ms delta=464ns ago
[INFO] [stdout] 2026-08-05T16:33:12.054214Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032040663Z, server: 2026-08-05T16:33:12.043120522Z } current=2026-08-05T16:33:12.05419911Z}: timesimp::delta: response processing internals latency=11ms 79µs 223ns local_at_midpoint=2026-08-05T16:33:12.043119886Z delta=636ns
[INFO] [stdout] 2026-08-05T16:33:12.054220Z TRACE timesimp: sleeping to spread out requests delay=1.766394703s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.054224Z TRACE timesimp: obtained raw offset from server latency=11.079223ms delta=636ns
[INFO] [stdout] 2026-08-05T16:33:12.054228Z TRACE timesimp: sleeping to spread out requests delay=661.841011ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.054436Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032248723Z, server: 2026-08-05T16:33:07.043325102Z } current=2026-08-05T16:33:12.05441049Z}: timesimp::delta: response processing internals latency=11ms 80µs 883ns local_at_midpoint=2026-08-05T16:33:12.043329606Z delta=5s 4µs 504ns ago
[INFO] [stdout] 2026-08-05T16:33:12.054449Z TRACE timesimp: obtained raw offset from server latency=11.080883ms delta=5s 4µs 504ns ago
[INFO] [stdout] 2026-08-05T16:33:12.054454Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 4µs 504ns ago
[INFO] [stdout] 2026-08-05T16:33:12.054458Z TRACE timesimp: sleeping to spread out requests delay=550.281398ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.054588Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032401612Z, server: 2026-08-05T16:33:17.043480461Z } current=2026-08-05T16:33:12.05457586Z}: timesimp::delta: response processing internals latency=11ms 87µs 124ns local_at_midpoint=2026-08-05T16:33:12.043488736Z delta=4s 999ms 991µs 725ns
[INFO] [stdout] 2026-08-05T16:33:12.054601Z TRACE timesimp: obtained raw offset from server latency=11.087124ms delta=4s 999ms 991µs 725ns
[INFO] [stdout] 2026-08-05T16:33:12.054606Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 991µs 725ns
[INFO] [stdout] 2026-08-05T16:33:12.054608Z TRACE timesimp: sleeping to spread out requests delay=456.387659ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.234833Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032403303Z, server: 2026-08-05T16:33:12.133599802Z } current=2026-08-05T16:33:12.234805932Z}: timesimp::delta: response processing internals latency=101ms 201µs 314ns local_at_midpoint=2026-08-05T16:33:12.133604617Z delta=4µs 815ns ago
[INFO] [stdout] 2026-08-05T16:33:12.234855Z TRACE timesimp: obtained raw offset from server latency=101.201314ms delta=4µs 815ns ago
[INFO] [stdout] 2026-08-05T16:33:12.234861Z DEBUG timesimp: no offset stored, storing initial delta offset=4µs 815ns ago
[INFO] [stdout] 2026-08-05T16:33:12.234864Z TRACE timesimp: sleeping to spread out requests delay=1.657750446s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.534423Z TRACE new{response=Response { client: 2026-08-05T16:33:12.512194144Z, server: 2026-08-05T16:33:17.523281253Z } current=2026-08-05T16:33:12.534397172Z}: timesimp::delta: response processing internals latency=11ms 101µs 514ns local_at_midpoint=2026-08-05T16:33:12.523295658Z delta=4s 999ms 985µs 595ns
[INFO] [stdout] 2026-08-05T16:33:12.534446Z TRACE timesimp: obtained raw offset from server latency=11.101514ms delta=4s 999ms 985µs 595ns
[INFO] [stdout] 2026-08-05T16:33:12.534453Z TRACE timesimp: sleeping to spread out requests delay=1.167928791s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.627333Z TRACE new{response=Response { client: 2026-08-05T16:33:12.606085175Z, server: 2026-08-05T16:33:07.616239453Z } current=2026-08-05T16:33:12.627322372Z}: timesimp::delta: response processing internals latency=10ms 618µs 598ns local_at_midpoint=2026-08-05T16:33:12.616703773Z delta=5s 464µs 320ns ago
[INFO] [stdout] 2026-08-05T16:33:12.627348Z TRACE timesimp: obtained raw offset from server latency=10.618598ms delta=5s 464µs 320ns ago
[INFO] [stdout] 2026-08-05T16:33:12.627354Z TRACE timesimp: sleeping to spread out requests delay=128.188777ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.739641Z TRACE new{response=Response { client: 2026-08-05T16:33:12.717387714Z, server: 2026-08-05T16:33:12.728473592Z } current=2026-08-05T16:33:12.739622901Z}: timesimp::delta: response processing internals latency=11ms 117µs 593ns local_at_midpoint=2026-08-05T16:33:12.728505307Z delta=31µs 715ns ago
[INFO] [stdout] 2026-08-05T16:33:12.739663Z TRACE timesimp: obtained raw offset from server latency=11.117593ms delta=31µs 715ns ago
[INFO] [stdout] 2026-08-05T16:33:12.739669Z TRACE timesimp: sleeping to spread out requests delay=1.812121702s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.778766Z TRACE new{response=Response { client: 2026-08-05T16:33:12.75658115Z, server: 2026-08-05T16:33:07.767666938Z } current=2026-08-05T16:33:12.778752177Z}: timesimp::delta: response processing internals latency=11ms 85µs 513ns local_at_midpoint=2026-08-05T16:33:12.767666663Z delta=4s 999ms 999µs 725ns ago
[INFO] [stdout] 2026-08-05T16:33:12.778784Z TRACE timesimp: obtained raw offset from server latency=11.085513ms delta=4s 999ms 999µs 725ns ago
[INFO] [stdout] 2026-08-05T16:33:12.778789Z TRACE timesimp: sleeping to spread out requests delay=50.743738ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.853152Z TRACE new{response=Response { client: 2026-08-05T16:33:12.830961512Z, server: 2026-08-05T16:33:07.842047861Z } current=2026-08-05T16:33:12.85313502Z}: timesimp::delta: response processing internals latency=11ms 86µs 754ns local_at_midpoint=2026-08-05T16:33:12.842048266Z delta=5s 405ns ago
[INFO] [stdout] 2026-08-05T16:33:12.853171Z TRACE timesimp: obtained raw offset from server latency=11.086754ms delta=5s 405ns ago
[INFO] [stdout] 2026-08-05T16:33:12.853177Z TRACE timesimp: sleeping to spread out requests delay=50.390949ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.921349Z TRACE new{response=Response { client: 2026-08-05T16:33:12.900165365Z, server: 2026-08-05T16:33:17.910252174Z } current=2026-08-05T16:33:12.921331123Z}: timesimp::delta: response processing internals latency=10ms 582µs 879ns local_at_midpoint=2026-08-05T16:33:12.910748244Z delta=4s 999ms 503µs 930ns
[INFO] [stdout] 2026-08-05T16:33:12.921378Z TRACE timesimp: obtained raw offset from server latency=10.582879ms delta=4s 999ms 503µs 930ns
[INFO] [stdout] 2026-08-05T16:33:12.921389Z TRACE timesimp: sleeping to spread out requests delay=766.969076ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:12.926556Z TRACE new{response=Response { client: 2026-08-05T16:33:12.904354125Z, server: 2026-08-05T16:33:07.915447334Z } current=2026-08-05T16:33:12.926538512Z}: timesimp::delta: response processing internals latency=11ms 92µs 193ns local_at_midpoint=2026-08-05T16:33:12.915446318Z delta=4s 999ms 998µs 984ns ago
[INFO] [stdout] 2026-08-05T16:33:12.926575Z TRACE timesimp: obtained raw offset from server latency=11.092193ms delta=4s 999ms 998µs 984ns ago
[INFO] [stdout] 2026-08-05T16:33:12.926582Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.46432, -5000.004504, -4999.999725, -5000.000405, -4999.998984]
[INFO] [stdout] 2026-08-05T16:33:12.926587Z TRACE timesimp: statistics about response deltas median=-4999.999725 mean=-5000.0935876 variance=0.04295535648832163 stddev=0.20725674051359977
[INFO] [stdout] 2026-08-05T16:33:12.926591Z TRACE timesimp: eliminated outliers inliers=[-5000.004504, -4999.999725, -5000.000405, -4999.998984]
[INFO] [stdout] 2026-08-05T16:33:12.926594Z DEBUG timesimp: storing calculated offset offset=5s ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2026-08-05T16:33:13.274087Z TRACE new{response=Response { client: 2026-08-05T16:33:13.271854527Z, server: 2026-08-05T16:33:13.272964307Z } current=2026-08-05T16:33:13.274069537Z}: timesimp::delta: response processing internals latency=1ms 107µs 505ns local_at_midpoint=2026-08-05T16:33:13.272962032Z delta=2µs 275ns
[INFO] [stdout] 2026-08-05T16:33:13.274109Z TRACE timesimp: obtained raw offset from server latency=1.107505ms delta=2µs 275ns
[INFO] [stdout] 2026-08-05T16:33:13.274117Z TRACE timesimp: sleeping to spread out requests delay=13.637864ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:13.290442Z TRACE new{response=Response { client: 2026-08-05T16:33:13.288248096Z, server: 2026-08-05T16:33:13.289344616Z } current=2026-08-05T16:33:13.290426866Z}: timesimp::delta: response processing internals latency=1ms 89µs 385ns local_at_midpoint=2026-08-05T16:33:13.289337481Z delta=7µs 135ns
[INFO] [stdout] 2026-08-05T16:33:13.290461Z TRACE timesimp: obtained raw offset from server latency=1.089385ms delta=7µs 135ns
[INFO] [stdout] 2026-08-05T16:33:13.290469Z TRACE timesimp: sleeping to spread out requests delay=1.420003053s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:13.526107Z TRACE new{response=Response { client: 2026-08-05T16:33:13.510858754Z, server: 2026-08-05T16:33:18.518975663Z } current=2026-08-05T16:33:13.526089142Z}: timesimp::delta: response processing internals latency=7ms 615µs 194ns local_at_midpoint=2026-08-05T16:33:13.518473948Z delta=5s 501µs 715ns
[INFO] [stdout] 2026-08-05T16:33:13.526131Z TRACE timesimp: obtained raw offset from server latency=7.615194ms delta=5s 501µs 715ns
[INFO] [stdout] 2026-08-05T16:33:13.526140Z TRACE timesimp: sleeping to spread out requests delay=521.245509ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:13.566191Z TRACE new{response=Response { client: 2026-08-05T16:33:12.032102723Z, server: 2026-08-05T16:33:12.799307315Z } current=2026-08-05T16:33:13.566162518Z}: timesimp::delta: response processing internals latency=767ms 29µs 897ns local_at_midpoint=2026-08-05T16:33:12.79913262Z delta=174µs 695ns
[INFO] [stdout] 2026-08-05T16:33:13.566212Z TRACE timesimp: obtained raw offset from server latency=767.029897ms delta=174µs 695ns
[INFO] [stdout] 2026-08-05T16:33:13.566219Z DEBUG timesimp: no offset stored, storing initial delta offset=174µs 695ns
[INFO] [stdout] 2026-08-05T16:33:13.566221Z TRACE timesimp: sleeping to spread out requests delay=872.110717ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:13.711517Z TRACE new{response=Response { client: 2026-08-05T16:33:13.689240945Z, server: 2026-08-05T16:33:18.700406874Z } current=2026-08-05T16:33:13.711497303Z}: timesimp::delta: response processing internals latency=11ms 128µs 179ns local_at_midpoint=2026-08-05T16:33:13.700369124Z delta=5s 37µs 750ns
[INFO] [stdout] 2026-08-05T16:33:13.711542Z TRACE timesimp: obtained raw offset from server latency=11.128179ms delta=5s 37µs 750ns
[INFO] [stdout] 2026-08-05T16:33:13.711549Z TRACE timesimp: sleeping to spread out requests delay=1.395788883s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:13.726061Z TRACE new{response=Response { client: 2026-08-05T16:33:13.703807894Z, server: 2026-08-05T16:33:18.714916413Z } current=2026-08-05T16:33:13.726038742Z}: timesimp::delta: response processing internals latency=11ms 115µs 424ns local_at_midpoint=2026-08-05T16:33:13.714923318Z delta=4s 999ms 993µs 95ns
[INFO] [stdout] 2026-08-05T16:33:13.726089Z TRACE timesimp: obtained raw offset from server latency=11.115424ms delta=4s 999ms 993µs 95ns
[INFO] [stdout] 2026-08-05T16:33:13.726098Z TRACE timesimp: sleeping to spread out requests delay=458.37758ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:13.797282Z TRACE new{response=Response { client: 2026-08-05T16:33:13.787071855Z, server: 2026-08-05T16:33:18.792161105Z } current=2026-08-05T16:33:13.797247074Z}: timesimp::delta: response processing internals latency=5ms 87µs 609ns local_at_midpoint=2026-08-05T16:33:13.792159464Z delta=5s 1µs 641ns
[INFO] [stdout] 2026-08-05T16:33:13.797305Z TRACE timesimp: obtained raw offset from server latency=5.087609ms delta=5s 1µs 641ns
[INFO] [stdout] 2026-08-05T16:33:13.797312Z TRACE timesimp: sleeping to spread out requests delay=1.567990886s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:13.843436Z TRACE new{response=Response { client: 2026-08-05T16:33:13.821101882Z, server: 2026-08-05T16:33:13.832304741Z } current=2026-08-05T16:33:13.84340876Z}: timesimp::delta: response processing internals latency=11ms 153µs 439ns local_at_midpoint=2026-08-05T16:33:13.832255321Z delta=49µs 420ns
[INFO] [stdout] 2026-08-05T16:33:13.843461Z TRACE timesimp: obtained raw offset from server latency=11.153439ms delta=49µs 420ns
[INFO] [stdout] 2026-08-05T16:33:13.843469Z TRACE timesimp: sleeping to spread out requests delay=1.155079306s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:14.064120Z TRACE new{response=Response { client: 2026-08-05T16:33:14.048859069Z, server: 2026-08-05T16:33:19.056983688Z } current=2026-08-05T16:33:14.064101178Z}: timesimp::delta: response processing internals latency=7ms 621µs 54ns local_at_midpoint=2026-08-05T16:33:14.056480123Z delta=5s 503µs 565ns
[INFO] [stdout] 2026-08-05T16:33:14.064145Z TRACE timesimp: obtained raw offset from server latency=7.621054ms delta=5s 503µs 565ns
[INFO] [stdout] 2026-08-05T16:33:14.064155Z TRACE timesimp: sleeping to spread out requests delay=723.284531ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:14.096154Z TRACE new{response=Response { client: 2026-08-05T16:33:13.893686105Z, server: 2026-08-05T16:33:13.994910505Z } current=2026-08-05T16:33:14.096135115Z}: timesimp::delta: response processing internals latency=101ms 224µs 505ns local_at_midpoint=2026-08-05T16:33:13.99491061Z delta=105ns ago
[INFO] [stdout] 2026-08-05T16:33:14.096177Z TRACE timesimp: obtained raw offset from server latency=101.224505ms delta=105ns ago
[INFO] [stdout] 2026-08-05T16:33:14.096183Z TRACE timesimp: sleeping to spread out requests delay=517.562935ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:14.207994Z TRACE new{response=Response { client: 2026-08-05T16:33:14.185719045Z, server: 2026-08-05T16:33:19.196843424Z } current=2026-08-05T16:33:14.207973443Z}: timesimp::delta: response processing internals latency=11ms 127µs 199ns local_at_midpoint=2026-08-05T16:33:14.196846244Z delta=4s 999ms 997µs 180ns
[INFO] [stdout] 2026-08-05T16:33:14.208020Z TRACE timesimp: obtained raw offset from server latency=11.127199ms delta=4s 999ms 997µs 180ns
[INFO] [stdout] 2026-08-05T16:33:14.208028Z TRACE timesimp: sleeping to spread out requests delay=1.470249539s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:14.574778Z TRACE new{response=Response { client: 2026-08-05T16:33:14.552591768Z, server: 2026-08-05T16:33:14.563675257Z } current=2026-08-05T16:33:14.574759396Z}: timesimp::delta: response processing internals latency=11ms 83µs 814ns local_at_midpoint=2026-08-05T16:33:14.563675582Z delta=325ns ago
[INFO] [stdout] 2026-08-05T16:33:14.574799Z TRACE timesimp: obtained raw offset from server latency=11.083814ms delta=325ns ago
[INFO] [stdout] 2026-08-05T16:33:14.574805Z TRACE timesimp: sleeping to spread out requests delay=1.35694129s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:14.713117Z TRACE new{response=Response { client: 2026-08-05T16:33:14.712000302Z, server: 2026-08-05T16:33:14.713090052Z } current=2026-08-05T16:33:14.713095922Z}: timesimp::delta: response processing internals latency=547µs 810ns local_at_midpoint=2026-08-05T16:33:14.712548112Z delta=541µs 940ns
[INFO] [stdout] 2026-08-05T16:33:14.713142Z TRACE timesimp: obtained raw offset from server latency=547.81µs delta=541µs 940ns
[INFO] [stdout] 2026-08-05T16:33:14.713151Z TRACE timesimp: sleeping to spread out requests delay=919.112249ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:14.802080Z TRACE new{response=Response { client: 2026-08-05T16:33:14.788819285Z, server: 2026-08-05T16:33:19.795937474Z } current=2026-08-05T16:33:14.802060973Z}: timesimp::delta: response processing internals latency=6ms 620µs 844ns local_at_midpoint=2026-08-05T16:33:14.795440129Z delta=5s 497µs 345ns
[INFO] [stdout] 2026-08-05T16:33:14.802105Z TRACE timesimp: obtained raw offset from server latency=6.620844ms delta=5s 497µs 345ns
[INFO] [stdout] 2026-08-05T16:33:14.802115Z TRACE timesimp: sleeping to spread out requests delay=1.704488116s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:14.816859Z TRACE new{response=Response { client: 2026-08-05T16:33:14.614821832Z, server: 2026-08-05T16:33:14.716015002Z } current=2026-08-05T16:33:14.816841362Z}: timesimp::delta: response processing internals latency=101ms 9µs 765ns local_at_midpoint=2026-08-05T16:33:14.715831597Z delta=183µs 405ns
[INFO] [stdout] 2026-08-05T16:33:14.816887Z TRACE timesimp: obtained raw offset from server latency=101.009765ms delta=183µs 405ns
[INFO] [stdout] 2026-08-05T16:33:14.816894Z TRACE timesimp: sleeping to spread out requests delay=425.579765ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.021043Z TRACE new{response=Response { client: 2026-08-05T16:33:14.999788733Z, server: 2026-08-05T16:33:15.009908642Z } current=2026-08-05T16:33:15.021021461Z}: timesimp::delta: response processing internals latency=10ms 616µs 364ns local_at_midpoint=2026-08-05T16:33:15.010405097Z delta=496µs 455ns ago
[INFO] [stdout] 2026-08-05T16:33:15.021072Z TRACE timesimp: obtained raw offset from server latency=10.616364ms delta=496µs 455ns ago
[INFO] [stdout] 2026-08-05T16:33:15.021081Z TRACE timesimp: sleeping to spread out requests delay=439.933328ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.130297Z TRACE new{response=Response { client: 2026-08-05T16:33:15.108065833Z, server: 2026-08-05T16:33:20.119173831Z } current=2026-08-05T16:33:15.13027664Z}: timesimp::delta: response processing internals latency=11ms 105µs 403ns local_at_midpoint=2026-08-05T16:33:15.119171236Z delta=5s 2µs 595ns
[INFO] [stdout] 2026-08-05T16:33:15.130319Z TRACE timesimp: obtained raw offset from server latency=11.105403ms delta=5s 2µs 595ns
[INFO] [stdout] 2026-08-05T16:33:15.130326Z TRACE timesimp: sleeping to spread out requests delay=1.587763555s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.378242Z TRACE new{response=Response { client: 2026-08-05T16:33:15.366011466Z, server: 2026-08-05T16:33:20.372127006Z } current=2026-08-05T16:33:15.378223745Z}: timesimp::delta: response processing internals latency=6ms 106µs 139ns local_at_midpoint=2026-08-05T16:33:15.372117605Z delta=5s 9µs 401ns
[INFO] [stdout] 2026-08-05T16:33:15.378293Z TRACE timesimp: obtained raw offset from server latency=6.106139ms delta=5s 9µs 401ns
[INFO] [stdout] 2026-08-05T16:33:15.378304Z TRACE timesimp: sleeping to spread out requests delay=195.718439ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.445893Z TRACE new{response=Response { client: 2026-08-05T16:33:15.243465819Z, server: 2026-08-05T16:33:15.344661618Z } current=2026-08-05T16:33:15.445874208Z}: timesimp::delta: response processing internals latency=101ms 204µs 194ns local_at_midpoint=2026-08-05T16:33:15.344670013Z delta=8µs 395ns ago
[INFO] [stdout] 2026-08-05T16:33:15.445930Z TRACE timesimp: obtained raw offset from server latency=101.204194ms delta=8µs 395ns ago
[INFO] [stdout] 2026-08-05T16:33:15.445937Z TRACE timesimp: sleeping to spread out requests delay=537.132734ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.484610Z TRACE new{response=Response { client: 2026-08-05T16:33:15.462414187Z, server: 2026-08-05T16:33:15.473503976Z } current=2026-08-05T16:33:15.484593924Z}: timesimp::delta: response processing internals latency=11ms 89µs 868ns local_at_midpoint=2026-08-05T16:33:15.473504055Z delta=79ns ago
[INFO] [stdout] 2026-08-05T16:33:15.484631Z TRACE timesimp: obtained raw offset from server latency=11.089868ms delta=79ns ago
[INFO] [stdout] 2026-08-05T16:33:15.484638Z TRACE timesimp: sleeping to spread out requests delay=433.005663ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.591816Z TRACE new{response=Response { client: 2026-08-05T16:33:15.575623775Z, server: 2026-08-05T16:33:20.583710514Z } current=2026-08-05T16:33:15.591798044Z}: timesimp::delta: response processing internals latency=8ms 87µs 134ns local_at_midpoint=2026-08-05T16:33:15.583710909Z delta=4s 999ms 999µs 605ns
[INFO] [stdout] 2026-08-05T16:33:15.591838Z TRACE timesimp: obtained raw offset from server latency=8.087134ms delta=4s 999ms 999µs 605ns
[INFO] [stdout] 2026-08-05T16:33:15.591845Z TRACE timesimp: sleeping to spread out requests delay=1.445591864s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.635419Z TRACE new{response=Response { client: 2026-08-05T16:33:15.63324608Z, server: 2026-08-05T16:33:15.634328089Z } current=2026-08-05T16:33:15.635402609Z}: timesimp::delta: response processing internals latency=1ms 78µs 264ns local_at_midpoint=2026-08-05T16:33:15.634324344Z delta=3µs 745ns
[INFO] [stdout] 2026-08-05T16:33:15.635443Z TRACE timesimp: obtained raw offset from server latency=1.078264ms delta=3µs 745ns
[INFO] [stdout] 2026-08-05T16:33:15.635449Z TRACE timesimp: response deltas sorted by latency deltas=[0.54194, 0.003745, 0.00653, 0.007135, 0.002275]
[INFO] [stdout] 2026-08-05T16:33:15.635454Z TRACE timesimp: statistics about response deltas median=0.00653 mean=0.11232500000000001 variance=0.0576817963125 stddev=0.24017034852891395
[INFO] [stdout] 2026-08-05T16:33:15.635458Z TRACE timesimp: eliminated outliers inliers=[0.003745, 0.00653, 0.007135, 0.002275]
[INFO] [stdout] 2026-08-05T16:33:15.635461Z DEBUG timesimp: storing calculated offset offset=4µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2026-08-05T16:33:15.700781Z TRACE new{response=Response { client: 2026-08-05T16:33:15.678443235Z, server: 2026-08-05T16:33:20.689656814Z } current=2026-08-05T16:33:15.700760833Z}: timesimp::delta: response processing internals latency=11ms 158µs 799ns local_at_midpoint=2026-08-05T16:33:15.689602034Z delta=5s 54µs 780ns
[INFO] [stdout] 2026-08-05T16:33:15.700807Z TRACE timesimp: obtained raw offset from server latency=11.158799ms delta=5s 54µs 780ns
[INFO] [stdout] 2026-08-05T16:33:15.700816Z TRACE timesimp: response deltas sorted by latency deltas=[4999.991725, 4999.985595, 4999.993095, 4999.99718, 5000.05478]
[INFO] [stdout] 2026-08-05T16:33:15.700822Z TRACE timesimp: statistics about response deltas median=4999.993095 mean=5000.004475 variance=0.0008080828375097518 stddev=0.028426797876471274
[INFO] [stdout] 2026-08-05T16:33:15.700828Z TRACE timesimp: eliminated outliers inliers=[4999.991725, 4999.985595, 4999.993095, 4999.99718]
[INFO] [stdout] 2026-08-05T16:33:15.700833Z DEBUG timesimp: storing calculated offset offset=4s 999ms 991µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2026-08-05T16:33:15.852795Z TRACE new{response=Response { client: 2026-08-05T16:33:14.43919279Z, server: 2026-08-05T16:33:15.145988918Z } current=2026-08-05T16:33:15.852776687Z}: timesimp::delta: response processing internals latency=706ms 791µs 948ns local_at_midpoint=2026-08-05T16:33:15.145984738Z delta=4µs 180ns
[INFO] [stdout] 2026-08-05T16:33:15.852816Z TRACE timesimp: obtained raw offset from server latency=706.791948ms delta=4µs 180ns
[INFO] [stdout] 2026-08-05T16:33:15.852823Z TRACE timesimp: sleeping to spread out requests delay=973.684523ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:15.940474Z TRACE new{response=Response { client: 2026-08-05T16:33:15.918174811Z, server: 2026-08-05T16:33:15.92927964Z } current=2026-08-05T16:33:15.940455869Z}: timesimp::delta: response processing internals latency=11ms 140µs 529ns local_at_midpoint=2026-08-05T16:33:15.92931534Z delta=35µs 700ns ago
[INFO] [stdout] 2026-08-05T16:33:15.940496Z TRACE timesimp: obtained raw offset from server latency=11.140529ms delta=35µs 700ns ago
[INFO] [stdout] 2026-08-05T16:33:15.940504Z TRACE timesimp: response deltas sorted by latency deltas=[-0.496455, -0.000464, -7.9e-5, -0.0357, 0.04942]
[INFO] [stdout] 2026-08-05T16:33:15.940511Z TRACE timesimp: statistics about response deltas median=-7.9e-5 mean=-0.0966556 variance=0.05086827247629999 stddev=0.22553995760463375
[INFO] [stdout] 2026-08-05T16:33:15.940515Z TRACE timesimp: eliminated outliers inliers=[-0.000464, -7.9e-5, -0.0357, 0.04942]
[INFO] [stdout] 2026-08-05T16:33:15.940519Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2026-08-05T16:33:15.954509Z TRACE new{response=Response { client: 2026-08-05T16:33:15.932247509Z, server: 2026-08-05T16:33:15.943415478Z } current=2026-08-05T16:33:15.954497657Z}: timesimp::delta: response processing internals latency=11ms 125µs 74ns local_at_midpoint=2026-08-05T16:33:15.943372583Z delta=42µs 895ns
[INFO] [stdout] 2026-08-05T16:33:15.954526Z TRACE timesimp: obtained raw offset from server latency=11.125074ms delta=42µs 895ns
[INFO] [stdout] 2026-08-05T16:33:15.954533Z TRACE timesimp: sleeping to spread out requests delay=747.872388ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:16.186125Z TRACE new{response=Response { client: 2026-08-05T16:33:15.983559364Z, server: 2026-08-05T16:33:16.084862204Z } current=2026-08-05T16:33:16.186108264Z}: timesimp::delta: response processing internals latency=101ms 274µs 450ns local_at_midpoint=2026-08-05T16:33:16.084833814Z delta=28µs 390ns
[INFO] [stdout] 2026-08-05T16:33:16.186146Z TRACE timesimp: obtained raw offset from server latency=101.27445ms delta=28µs 390ns
[INFO] [stdout] 2026-08-05T16:33:16.186153Z TRACE timesimp: response deltas sorted by latency deltas=[0.183405, -0.004815, -0.008395, -0.000105, 0.02839]
[INFO] [stdout] 2026-08-05T16:33:16.186158Z TRACE timesimp: statistics about response deltas median=-0.008395 mean=0.03969600000000001 variance=0.00666454883 stddev=0.08163668801464205
[INFO] [stdout] 2026-08-05T16:33:16.186162Z TRACE timesimp: eliminated outliers inliers=[-0.004815, -0.008395, -0.000105, 0.02839]
[INFO] [stdout] 2026-08-05T16:33:16.186165Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2026-08-05T16:33:16.520376Z TRACE new{response=Response { client: 2026-08-05T16:33:16.508023071Z, server: 2026-08-05T16:33:21.51425182Z } current=2026-08-05T16:33:16.52035869Z}: timesimp::delta: response processing internals latency=6ms 167µs 809ns local_at_midpoint=2026-08-05T16:33:16.51419088Z delta=5s 60µs 940ns
[INFO] [stdout] 2026-08-05T16:33:16.520398Z TRACE timesimp: obtained raw offset from server latency=6.167809ms delta=5s 60µs 940ns
[INFO] [stdout] 2026-08-05T16:33:16.520405Z TRACE timesimp: response deltas sorted by latency deltas=[5000.06094, 5000.497345, 5000.501715, 5000.503565, 5000.000901]
[INFO] [stdout] 2026-08-05T16:33:16.520410Z TRACE timesimp: statistics about response deltas median=5000.501715 mean=5000.3128932 variance=0.06671285546111713 stddev=0.25828831847591777
[INFO] [stdout] 2026-08-05T16:33:16.520414Z TRACE timesimp: eliminated outliers inliers=[5000.497345, 5000.501715, 5000.503565]
[INFO] [stdout] 2026-08-05T16:33:16.520417Z DEBUG timesimp: storing calculated offset offset=5s 500µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2026-08-05T16:33:16.726684Z TRACE new{response=Response { client: 2026-08-05T16:33:16.704452832Z, server: 2026-08-05T16:33:16.71557268Z } current=2026-08-05T16:33:16.726666869Z}: timesimp::delta: response processing internals latency=11ms 107µs 18ns local_at_midpoint=2026-08-05T16:33:16.71555985Z delta=12µs 830ns
[INFO] [stdout] 2026-08-05T16:33:16.726706Z TRACE timesimp: obtained raw offset from server latency=11.107018ms delta=12µs 830ns
[INFO] [stdout] 2026-08-05T16:33:16.726713Z TRACE timesimp: response deltas sorted by latency deltas=[0.000636, -0.000325, 0.01283, -0.031715, 0.042895]
[INFO] [stdout] 2026-08-05T16:33:16.726720Z TRACE timesimp: statistics about response deltas median=0.01283 mean=0.004864200000000001 variance=0.0007231597657000001 stddev=0.0268916300305504
[INFO] [stdout] 2026-08-05T16:33:16.726724Z TRACE timesimp: eliminated outliers inliers=[0.000636, -0.000325, 0.01283]
[INFO] [stdout] 2026-08-05T16:33:16.726728Z DEBUG timesimp: storing calculated offset offset=4µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2026-08-05T16:33:16.741316Z TRACE new{response=Response { client: 2026-08-05T16:33:16.71913803Z, server: 2026-08-05T16:33:21.730222099Z } current=2026-08-05T16:33:16.741304888Z}: timesimp::delta: response processing internals latency=11ms 83µs 429ns local_at_midpoint=2026-08-05T16:33:16.730221459Z delta=5s 640ns
[INFO] [stdout] 2026-08-05T16:33:16.741334Z TRACE timesimp: obtained raw offset from server latency=11.083429ms delta=5s 640ns
[INFO] [stdout] 2026-08-05T16:33:16.741343Z TRACE timesimp: response deltas sorted by latency deltas=[4999.998175, 4999.50393, 5000.00064, 5000.002595, 5000.03775]
[INFO] [stdout] 2026-08-05T16:33:16.741350Z TRACE timesimp: statistics about response deltas median=5000.00064 mean=4999.9086179999995 variance=0.05144190800754957 stddev=0.22680808629224306
[INFO] [stdout] 2026-08-05T16:33:16.741357Z TRACE timesimp: eliminated outliers inliers=[4999.998175, 5000.00064, 5000.002595, 5000.03775]
[INFO] [stdout] 2026-08-05T16:33:16.741362Z DEBUG timesimp: storing calculated offset offset=5s 9µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2026-08-05T16:33:17.052603Z TRACE new{response=Response { client: 2026-08-05T16:33:17.038430058Z, server: 2026-08-05T16:33:22.045509887Z } current=2026-08-05T16:33:17.052585176Z}: timesimp::delta: response processing internals latency=7ms 77µs 559ns local_at_midpoint=2026-08-05T16:33:17.045507617Z delta=5s 2µs 270ns
[INFO] [stdout] 2026-08-05T16:33:17.052623Z TRACE timesimp: obtained raw offset from server latency=7.077559ms delta=5s 2µs 270ns
[INFO] [stdout] 2026-08-05T16:33:17.052630Z TRACE timesimp: response deltas sorted by latency deltas=[5000.001641, 5000.009401, 5000.00227, 4999.500481, 4999.999605]
[INFO] [stdout] 2026-08-05T16:33:17.052635Z TRACE timesimp: statistics about response deltas median=5000.00227 mean=4999.9026796 variance=0.05056482767179451 stddev=0.224866243958035
[INFO] [stdout] 2026-08-05T16:33:17.052639Z TRACE timesimp: eliminated outliers inliers=[5000.001641, 5000.009401, 5000.00227, 4999.999605]
[INFO] [stdout] 2026-08-05T16:33:17.052642Z DEBUG timesimp: storing calculated offset offset=5s 3µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2026-08-05T16:33:18.267572Z TRACE new{response=Response { client: 2026-08-05T16:33:16.827904399Z, server: 2026-08-05T16:33:17.547737116Z } current=2026-08-05T16:33:18.267554904Z}: timesimp::delta: response processing internals latency=719ms 825µs 252ns local_at_midpoint=2026-08-05T16:33:17.547729651Z delta=7µs 465ns
[INFO] [stdout] 2026-08-05T16:33:18.267593Z TRACE timesimp: obtained raw offset from server latency=719.825252ms delta=7µs 465ns
[INFO] [stdout] 2026-08-05T16:33:18.267600Z TRACE timesimp: sleeping to spread out requests delay=712.845189ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:20.785460Z TRACE new{response=Response { client: 2026-08-05T16:33:18.981406352Z, server: 2026-08-05T16:33:19.883417221Z } current=2026-08-05T16:33:20.78544231Z}: timesimp::delta: response processing internals latency=902ms 17µs 979ns local_at_midpoint=2026-08-05T16:33:19.883424331Z delta=7µs 110ns ago
[INFO] [stdout] 2026-08-05T16:33:20.785480Z TRACE timesimp: obtained raw offset from server latency=902.017979ms delta=7µs 110ns ago
[INFO] [stdout] 2026-08-05T16:33:20.785487Z TRACE timesimp: sleeping to spread out requests delay=1.914431235s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.147201Z TRACE new{response=Response { client: 2026-08-05T16:33:22.700493207Z, server: 2026-08-05T16:33:23.424309264Z } current=2026-08-05T16:33:24.147177511Z}: timesimp::delta: response processing internals latency=723ms 342µs 152ns local_at_midpoint=2026-08-05T16:33:23.423835359Z delta=473µs 905ns
[INFO] [stdout] 2026-08-05T16:33:24.147227Z TRACE timesimp: obtained raw offset from server latency=723.342152ms delta=473µs 905ns
[INFO] [stdout] 2026-08-05T16:33:24.147237Z TRACE timesimp: response deltas sorted by latency deltas=[0.00418, 0.007465, 0.473905, 0.174695, -0.00711]
[INFO] [stdout] 2026-08-05T16:33:24.147244Z TRACE timesimp: statistics about response deltas median=0.473905 mean=0.130627 variance=0.0424777442825 stddev=0.20610129616889847
[INFO] [stdout] 2026-08-05T16:33:24.147250Z TRACE timesimp: eliminated outliers inliers=[0.473905]
[INFO] [stdout] 2026-08-05T16:33:24.147254Z DEBUG timesimp: storing calculated offset offset=473µs
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.12s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/release/deps/in_process-674d4aac00732fde)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2026-08-05T16:33:24.149802Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-08-05T16:33:24.149827Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.149806Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:24.149828Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:33:24.149839Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.149841Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.149833Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-08-05T16:33:24.149855Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.150960Z TRACE new{response=Response { client: 2026-08-05T16:33:24.150945641Z, server: 2026-08-05T16:33:19.150945771Z } current=2026-08-05T16:33:24.150945881Z}: timesimp::delta: response processing internals latency=120ns local_at_midpoint=2026-08-05T16:33:24.150945761Z delta=4s 999ms 999µs 990ns ago
[INFO] [stdout] 2026-08-05T16:33:24.150968Z TRACE new{response=Response { client: 2026-08-05T16:33:24.150954451Z, server: 2026-08-05T16:33:24.150954591Z } current=2026-08-05T16:33:24.150954681Z}: timesimp::delta: response processing internals latency=115ns local_at_midpoint=2026-08-05T16:33:24.150954566Z delta=25ns
[INFO] [stdout] 2026-08-05T16:33:24.150968Z TRACE new{response=Response { client: 2026-08-05T16:33:24.150954941Z, server: 2026-08-05T16:33:24.150954991Z } current=2026-08-05T16:33:24.150955061Z}: timesimp::delta: response processing internals latency=60ns local_at_midpoint=2026-08-05T16:33:24.150955001Z delta=10ns ago
[INFO] [stdout] 2026-08-05T16:33:24.150980Z TRACE timesimp: obtained raw offset from server latency=115ns delta=25ns
[INFO] [stdout] 2026-08-05T16:33:24.150987Z DEBUG timesimp: no offset stored, storing initial delta offset=25ns
[INFO] [stdout] 2026-08-05T16:33:24.150988Z TRACE timesimp: obtained raw offset from server latency=60ns delta=10ns ago
[INFO] [stdout] 2026-08-05T16:33:24.150991Z TRACE timesimp: sleeping to spread out requests delay=1.40527569s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.150975Z TRACE timesimp: obtained raw offset from server latency=120ns delta=4s 999ms 999µs 990ns ago
[INFO] [stdout] 2026-08-05T16:33:24.150994Z TRACE timesimp: sleeping to spread out requests delay=1.350990036s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.150998Z TRACE timesimp: sleeping to spread out requests delay=100.448303ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.150997Z TRACE new{response=Response { client: 2026-08-05T16:33:24.150975641Z, server: 2026-08-05T16:33:29.150975781Z } current=2026-08-05T16:33:24.150975951Z}: timesimp::delta: response processing internals latency=155ns local_at_midpoint=2026-08-05T16:33:24.150975796Z delta=4s 999ms 999µs 985ns
[INFO] [stdout] 2026-08-05T16:33:24.151012Z TRACE timesimp: obtained raw offset from server latency=155ns delta=4s 999ms 999µs 985ns
[INFO] [stdout] 2026-08-05T16:33:24.151019Z TRACE timesimp: sleeping to spread out requests delay=398.361019ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.252240Z TRACE new{response=Response { client: 2026-08-05T16:33:24.252218551Z, server: 2026-08-05T16:33:19.252218871Z } current=2026-08-05T16:33:24.252218951Z}: timesimp::delta: response processing internals latency=200ns local_at_midpoint=2026-08-05T16:33:24.252218751Z delta=4s 999ms 999µs 880ns ago
[INFO] [stdout] 2026-08-05T16:33:24.252288Z TRACE timesimp: obtained raw offset from server latency=200ns delta=4s 999ms 999µs 880ns ago
[INFO] [stdout] 2026-08-05T16:33:24.252296Z TRACE timesimp: sleeping to spread out requests delay=602.690633ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.550589Z TRACE new{response=Response { client: 2026-08-05T16:33:24.550566891Z, server: 2026-08-05T16:33:29.550567221Z } current=2026-08-05T16:33:24.550567681Z}: timesimp::delta: response processing internals latency=395ns local_at_midpoint=2026-08-05T16:33:24.550567286Z delta=4s 999ms 999µs 935ns
[INFO] [stdout] 2026-08-05T16:33:24.550617Z TRACE timesimp: obtained raw offset from server latency=395ns delta=4s 999ms 999µs 935ns
[INFO] [stdout] 2026-08-05T16:33:24.550626Z TRACE timesimp: sleeping to spread out requests delay=789.937317ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:24.856076Z TRACE new{response=Response { client: 2026-08-05T16:33:24.85605763Z, server: 2026-08-05T16:33:19.85605792Z } current=2026-08-05T16:33:24.85605798Z}: timesimp::delta: response processing internals latency=175ns local_at_midpoint=2026-08-05T16:33:24.856057805Z delta=4s 999ms 999µs 885ns ago
[INFO] [stdout] 2026-08-05T16:33:24.856096Z TRACE timesimp: obtained raw offset from server latency=175ns delta=4s 999ms 999µs 885ns ago
[INFO] [stdout] 2026-08-05T16:33:24.856102Z TRACE timesimp: sleeping to spread out requests delay=1.365406384s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:25.341659Z TRACE new{response=Response { client: 2026-08-05T16:33:25.341636321Z, server: 2026-08-05T16:33:30.341636541Z } current=2026-08-05T16:33:25.341636631Z}: timesimp::delta: response processing internals latency=155ns local_at_midpoint=2026-08-05T16:33:25.341636476Z delta=5s 65ns
[INFO] [stdout] 2026-08-05T16:33:25.341688Z TRACE timesimp: obtained raw offset from server latency=155ns delta=5s 65ns
[INFO] [stdout] 2026-08-05T16:33:25.341696Z TRACE timesimp: sleeping to spread out requests delay=1.231732272s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:25.503434Z TRACE new{response=Response { client: 2026-08-05T16:33:25.503413305Z, server: 2026-08-05T16:33:25.503413715Z } current=2026-08-05T16:33:25.503413795Z}: timesimp::delta: response processing internals latency=245ns local_at_midpoint=2026-08-05T16:33:25.50341355Z delta=165ns
[INFO] [stdout] 2026-08-05T16:33:25.503460Z TRACE timesimp: obtained raw offset from server latency=245ns delta=165ns
[INFO] [stdout] 2026-08-05T16:33:25.503469Z TRACE timesimp: sleeping to spread out requests delay=217.792358ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:25.557438Z TRACE new{response=Response { client: 2026-08-05T16:33:25.557420109Z, server: 2026-08-05T16:33:25.557420434Z } current=2026-08-05T16:33:25.557420469Z}: timesimp::delta: response processing internals latency=180ns local_at_midpoint=2026-08-05T16:33:25.557420289Z delta=145ns
[INFO] [stdout] 2026-08-05T16:33:25.557459Z TRACE timesimp: obtained raw offset from server latency=180ns delta=145ns
[INFO] [stdout] 2026-08-05T16:33:25.557465Z TRACE timesimp: sleeping to spread out requests delay=1.012235281s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:25.722820Z TRACE new{response=Response { client: 2026-08-05T16:33:25.722801532Z, server: 2026-08-05T16:33:25.722801812Z } current=2026-08-05T16:33:25.722801883Z}: timesimp::delta: response processing internals latency=175ns local_at_midpoint=2026-08-05T16:33:25.722801707Z delta=105ns
[INFO] [stdout] 2026-08-05T16:33:25.722839Z TRACE timesimp: obtained raw offset from server latency=175ns delta=105ns
[INFO] [stdout] 2026-08-05T16:33:25.722844Z TRACE timesimp: sleeping to spread out requests delay=216.00574ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:25.940164Z TRACE new{response=Response { client: 2026-08-05T16:33:25.940145951Z, server: 2026-08-05T16:33:25.940146251Z } current=2026-08-05T16:33:25.940146311Z}: timesimp::delta: response processing internals latency=180ns local_at_midpoint=2026-08-05T16:33:25.940146131Z delta=120ns
[INFO] [stdout] 2026-08-05T16:33:25.940184Z TRACE timesimp: obtained raw offset from server latency=180ns delta=120ns
[INFO] [stdout] 2026-08-05T16:33:25.940190Z TRACE timesimp: sleeping to spread out requests delay=1.577416987s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:26.222434Z TRACE new{response=Response { client: 2026-08-05T16:33:26.222412962Z, server: 2026-08-05T16:33:21.222413402Z } current=2026-08-05T16:33:26.222413572Z}: timesimp::delta: response processing internals latency=305ns local_at_midpoint=2026-08-05T16:33:26.222413267Z delta=4s 999ms 999µs 865ns ago
[INFO] [stdout] 2026-08-05T16:33:26.222463Z TRACE timesimp: obtained raw offset from server latency=305ns delta=4s 999ms 999µs 865ns ago
[INFO] [stdout] 2026-08-05T16:33:26.222471Z TRACE timesimp: sleeping to spread out requests delay=924.683215ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:26.570456Z TRACE new{response=Response { client: 2026-08-05T16:33:26.570434557Z, server: 2026-08-05T16:33:26.570434882Z } current=2026-08-05T16:33:26.570434937Z}: timesimp::delta: response processing internals latency=190ns local_at_midpoint=2026-08-05T16:33:26.570434747Z delta=135ns
[INFO] [stdout] 2026-08-05T16:33:26.570488Z TRACE timesimp: obtained raw offset from server latency=190ns delta=135ns
[INFO] [stdout] 2026-08-05T16:33:26.570496Z TRACE timesimp: sleeping to spread out requests delay=1.587039701s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:26.574419Z TRACE new{response=Response { client: 2026-08-05T16:33:26.574404187Z, server: 2026-08-05T16:33:31.574404507Z } current=2026-08-05T16:33:26.574404687Z}: timesimp::delta: response processing internals latency=250ns local_at_midpoint=2026-08-05T16:33:26.574404437Z delta=5s 70ns
[INFO] [stdout] 2026-08-05T16:33:26.574445Z TRACE timesimp: obtained raw offset from server latency=250ns delta=5s 70ns
[INFO] [stdout] 2026-08-05T16:33:26.574452Z TRACE timesimp: sleeping to spread out requests delay=89.01298ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:26.664417Z TRACE new{response=Response { client: 2026-08-05T16:33:26.664390608Z, server: 2026-08-05T16:33:31.664391008Z } current=2026-08-05T16:33:26.664391088Z}: timesimp::delta: response processing internals latency=240ns local_at_midpoint=2026-08-05T16:33:26.664390848Z delta=5s 160ns
[INFO] [stdout] 2026-08-05T16:33:26.664449Z TRACE timesimp: obtained raw offset from server latency=240ns delta=5s 160ns
[INFO] [stdout] 2026-08-05T16:33:26.664458Z TRACE timesimp: response deltas sorted by latency deltas=[4999.999985, 5000.000065, 5000.00016, 5000.00007, 4999.999935]
[INFO] [stdout] 2026-08-05T16:33:26.664466Z TRACE timesimp: statistics about response deltas median=5000.00016 mean=5000.000043 variance=7.48249997756473e-9 stddev=8.650144494495297e-5
[INFO] [stdout] 2026-08-05T16:33:26.664472Z TRACE timesimp: eliminated outliers inliers=[5000.00016]
[INFO] [stdout] 2026-08-05T16:33:26.664475Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2026-08-05T16:33:27.148467Z TRACE new{response=Response { client: 2026-08-05T16:33:27.148446159Z, server: 2026-08-05T16:33:22.148446589Z } current=2026-08-05T16:33:27.148446669Z}: timesimp::delta: response processing internals latency=255ns local_at_midpoint=2026-08-05T16:33:27.148446414Z delta=4s 999ms 999µs 825ns ago
[INFO] [stdout] 2026-08-05T16:33:27.148500Z TRACE timesimp: obtained raw offset from server latency=255ns delta=4s 999ms 999µs 825ns ago
[INFO] [stdout] 2026-08-05T16:33:27.148508Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99999, -4999.999885, -4999.99988, -4999.999825, -4999.999865]
[INFO] [stdout] 2026-08-05T16:33:27.148515Z TRACE timesimp: statistics about response deltas median=-4999.99988 mean=-4999.999889000001 variance=3.74250001782304e-9 stddev=6.11759758224014e-5
[INFO] [stdout] 2026-08-05T16:33:27.148522Z TRACE timesimp: eliminated outliers inliers=[-4999.999885, -4999.99988, -4999.999825, -4999.999865]
[INFO] [stdout] 2026-08-05T16:33:27.148526Z DEBUG timesimp: storing calculated offset offset=4s 999ms 999µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2026-08-05T16:33:27.518433Z TRACE new{response=Response { client: 2026-08-05T16:33:27.518409671Z, server: 2026-08-05T16:33:27.518409891Z } current=2026-08-05T16:33:27.518410142Z}: timesimp::delta: response processing internals latency=235ns local_at_midpoint=2026-08-05T16:33:27.518409906Z delta=15ns ago
[INFO] [stdout] 2026-08-05T16:33:27.518530Z TRACE timesimp: obtained raw offset from server latency=235ns delta=15ns ago
[INFO] [stdout] 2026-08-05T16:33:27.518563Z TRACE timesimp: response deltas sorted by latency deltas=[-1e-5, 0.000105, 0.00012, -1.5e-5, 0.000165]
[INFO] [stdout] 2026-08-05T16:33:27.518592Z TRACE timesimp: statistics about response deltas median=0.00012 mean=7.3e-5 variance=6.5824999999999996e-9 stddev=8.11326075015465e-5
[INFO] [stdout] 2026-08-05T16:33:27.518628Z TRACE timesimp: eliminated outliers inliers=[0.000105, 0.00012, 0.000165]
[INFO] [stdout] 2026-08-05T16:33:27.518653Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2026-08-05T16:33:28.158429Z TRACE new{response=Response { client: 2026-08-05T16:33:28.158408197Z, server: 2026-08-05T16:33:28.158408672Z } current=2026-08-05T16:33:28.158408827Z}: timesimp::delta: response processing internals latency=315ns local_at_midpoint=2026-08-05T16:33:28.158408512Z delta=160ns
[INFO] [stdout] 2026-08-05T16:33:28.158460Z TRACE timesimp: obtained raw offset from server latency=315ns delta=160ns
[INFO] [stdout] 2026-08-05T16:33:28.158469Z TRACE timesimp: sleeping to spread out requests delay=60.178578ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:33:28.219686Z TRACE new{response=Response { client: 2026-08-05T16:33:28.219664131Z, server: 2026-08-05T16:33:28.219664556Z } current=2026-08-05T16:33:28.219664701Z}: timesimp::delta: response processing internals latency=285ns local_at_midpoint=2026-08-05T16:33:28.219664416Z delta=140ns
[INFO] [stdout] 2026-08-05T16:33:28.219717Z TRACE timesimp: obtained raw offset from server latency=285ns delta=140ns
[INFO] [stdout] 2026-08-05T16:33:28.219725Z TRACE timesimp: response deltas sorted by latency deltas=[2.5e-5, 0.000145, 0.000135, 0.00014, 0.00016]
[INFO] [stdout] 2026-08-05T16:33:28.219733Z TRACE timesimp: statistics about response deltas median=0.000135 mean=0.00012100000000000001 variance=2.9675e-9 stddev=5.4474764799859396e-5
[INFO] [stdout] 2026-08-05T16:33:28.219739Z TRACE timesimp: eliminated outliers inliers=[0.000145, 0.000135, 0.00014, 0.00016]
[INFO] [stdout] 2026-08-05T16:33:28.219743Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.07s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/deps/timesimp_nodejs-05c3196012939a7f)
[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.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 0.83s; merged doctests compilation took 0.82s
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] [stdout] 23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46