[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.1 for beta-1.98-2
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-5-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-5-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-5-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 1.98.0-beta.1
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.98.0-beta.1" "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.1" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[ERROR] error running command: no output for 300 seconds
[INFO] testing passcod/timesimp against 1.98.0-beta.1 for beta-1.98-2
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-5-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-5-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-5-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 1.98.0-beta.1
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.98.0-beta.1" "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.1" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded proc-macro2 v1.0.94
[INFO] [stderr]   Downloaded smallvec v1.14.0
[INFO] [stderr]   Downloaded socket2 v0.5.9
[INFO] [stderr]   Downloaded windows-targets v0.53.0
[INFO] [stderr]   Downloaded windows-registry v0.4.0
[INFO] [stderr]   Downloaded thiserror v2.0.12
[INFO] [stderr]   Downloaded thiserror-impl v2.0.12
[INFO] [stderr]   Downloaded windows-strings v0.3.1
[INFO] [stderr]   Downloaded redox_syscall v0.5.11
[INFO] [stderr]   Downloaded litemap v0.7.5
[INFO] [stderr]   Downloaded bitflags v2.9.0
[INFO] [stderr]   Downloaded tracing-attributes v0.1.28
[INFO] [stderr]   Downloaded errno v0.3.11
[INFO] [stderr]   Downloaded icu_locid_transform_data v1.5.1
[INFO] [stderr]   Downloaded icu_normalizer_data v1.5.1
[INFO] [stderr]   Downloaded miniz_oxide v0.8.5
[INFO] [stderr]   Downloaded dtor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded ctor v0.4.2
[INFO] [stderr]   Downloaded tempfile v3.19.1
[INFO] [stderr]   Downloaded getrandom v0.3.2
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded napi-build v2.1.6
[INFO] [stderr]   Downloaded napi-derive v3.0.0-alpha.29
[INFO] [stderr]   Downloaded napi-sys v3.0.0-alpha.1
[INFO] [stderr]   Downloaded ctor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded tokio-rustls v0.26.2
[INFO] [stderr]   Downloaded libloading v0.8.6
[INFO] [stderr]   Downloaded dtor v0.0.6
[INFO] [stderr]   Downloaded rustls-pki-types v1.11.0
[INFO] [stderr]   Downloaded portable-atomic-util v0.2.4
[INFO] [stderr]   Downloaded napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]   Downloaded openssl-sys v0.9.107
[INFO] [stderr]   Downloaded hyper-rustls v0.27.5
[INFO] [stderr]   Downloaded hyper-util v0.1.11
[INFO] [stderr]   Downloaded r-efi v5.2.0
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded rand v0.9.1
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded cc v1.2.20
[INFO] [stderr]   Downloaded napi v3.0.0-alpha.33
[INFO] [stderr]   Downloaded tracing-subscriber v0.3.19
[INFO] [stderr]   Downloaded reqwest v0.12.15
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded portable-atomic v1.11.0
[INFO] [stderr]   Downloaded icu_properties_data v1.5.1
[INFO] [stderr]   Downloaded openssl v0.10.72
[INFO] [stderr]   Downloaded rustls v0.23.26
[INFO] [stderr]   Downloaded rustix v1.0.5
[INFO] [stderr]   Downloaded libc v0.2.171
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] [stderr]   Downloaded tokio v1.44.2
[INFO] [stderr]   Downloaded rustls-webpki v0.103.1
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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:3d5ced03c013a94a2f102a4510f48a6e9184255caf5fd8244f58017bde7f5210" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] 9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153
[INFO] running `Command { std: "docker" "start" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling pin-project-lite v0.2.16
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling ryu v1.0.20
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[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 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 44.64s
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling indexmap v2.9.0
[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 parking_lot v0.12.3
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[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 serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 25s
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "test" "--frozen", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.31s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-2aee66feffce539a)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... 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.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-c4bbd53b9bad2c02)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2026-07-14T04:40:29.841140Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:29.841136Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:29.841195Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.841192Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.841120Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:29.841270Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.841314Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-07-14T04:40:29.841343Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.841402Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:29.841424Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.841579Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:29.841603Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.841120Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-07-14T04:40:29.841654Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.841687Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:29.841905Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.844778Z TRACE new{response=Response { client: 2026-07-14T04:40:29.842398173Z, server: 2026-07-14T04:40:29.843509093Z } current=2026-07-14T04:40:29.844622173Z}: timesimp::delta: response processing internals latency=1ms 112µs local_at_midpoint=2026-07-14T04:40:29.843510173Z delta=1µs 80ns ago
[INFO] [stdout] 2026-07-14T04:40:29.844867Z TRACE timesimp: obtained raw offset from server latency=1.112ms delta=1µs 80ns ago
[INFO] [stdout] 2026-07-14T04:40:29.844888Z DEBUG timesimp: no offset stored, storing initial delta offset=1µs 80ns ago
[INFO] [stdout] 2026-07-14T04:40:29.844903Z TRACE timesimp: sleeping to spread out requests delay=1.399150651s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.856951Z TRACE new{response=Response { client: 2026-07-14T04:40:29.842475243Z, server: 2026-07-14T04:40:34.849619512Z } current=2026-07-14T04:40:29.856758491Z}: timesimp::delta: response processing internals latency=7ms 141µs 624ns local_at_midpoint=2026-07-14T04:40:29.849616867Z delta=5s 2µs 645ns
[INFO] [stdout] 2026-07-14T04:40:29.857209Z TRACE timesimp: obtained raw offset from server latency=7.141624ms delta=5s 2µs 645ns
[INFO] [stdout] 2026-07-14T04:40:29.857322Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 2µs 645ns
[INFO] [stdout] 2026-07-14T04:40:29.857933Z TRACE timesimp: sleeping to spread out requests delay=653.147686ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.864219Z TRACE new{response=Response { client: 2026-07-14T04:40:29.842757923Z, server: 2026-07-14T04:40:34.852887022Z } current=2026-07-14T04:40:29.864048101Z}: timesimp::delta: response processing internals latency=10ms 645µs 89ns local_at_midpoint=2026-07-14T04:40:29.853403012Z delta=4s 999ms 484µs 10ns
[INFO] [stdout] 2026-07-14T04:40:29.864292Z TRACE timesimp: obtained raw offset from server latency=10.645089ms delta=4s 999ms 484µs 10ns
[INFO] [stdout] 2026-07-14T04:40:29.864311Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 484µs 10ns
[INFO] [stdout] 2026-07-14T04:40:29.864325Z TRACE timesimp: sleeping to spread out requests delay=1.750351835s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.864894Z TRACE new{response=Response { client: 2026-07-14T04:40:29.842527403Z, server: 2026-07-14T04:40:29.853652521Z } current=2026-07-14T04:40:29.864785421Z}: timesimp::delta: response processing internals latency=11ms 129µs 9ns local_at_midpoint=2026-07-14T04:40:29.853656412Z delta=3µs 891ns ago
[INFO] [stdout] 2026-07-14T04:40:29.865277Z TRACE timesimp: obtained raw offset from server latency=11.129009ms delta=3µs 891ns ago
[INFO] [stdout] 2026-07-14T04:40:29.865324Z TRACE timesimp: sleeping to spread out requests delay=842.710911ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.865070Z TRACE new{response=Response { client: 2026-07-14T04:40:29.842600973Z, server: 2026-07-14T04:40:34.853707912Z } current=2026-07-14T04:40:29.864983131Z}: timesimp::delta: response processing internals latency=11ms 191µs 79ns local_at_midpoint=2026-07-14T04:40:29.853792052Z delta=4s 999ms 915µs 860ns
[INFO] [stdout] 2026-07-14T04:40:29.865428Z TRACE timesimp: obtained raw offset from server latency=11.191079ms delta=4s 999ms 915µs 860ns
[INFO] [stdout] 2026-07-14T04:40:29.865465Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 915µs 860ns
[INFO] [stdout] 2026-07-14T04:40:29.865228Z TRACE new{response=Response { client: 2026-07-14T04:40:29.842893033Z, server: 2026-07-14T04:40:29.854010752Z } current=2026-07-14T04:40:29.865148511Z}: timesimp::delta: response processing internals latency=11ms 127µs 739ns local_at_midpoint=2026-07-14T04:40:29.854020772Z delta=10µs 20ns ago
[INFO] [stdout] 2026-07-14T04:40:29.865554Z TRACE timesimp: obtained raw offset from server latency=11.127739ms delta=10µs 20ns ago
[INFO] [stdout] 2026-07-14T04:40:29.865501Z TRACE new{response=Response { client: 2026-07-14T04:40:29.843183263Z, server: 2026-07-14T04:40:24.854302152Z } current=2026-07-14T04:40:29.865387931Z}: timesimp::delta: response processing internals latency=11ms 102µs 334ns local_at_midpoint=2026-07-14T04:40:29.854285597Z delta=4s 999ms 983µs 445ns ago
[INFO] [stdout] 2026-07-14T04:40:29.865529Z TRACE timesimp: sleeping to spread out requests delay=1.69557318s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.865664Z TRACE timesimp: sleeping to spread out requests delay=837.315512ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:29.865760Z TRACE timesimp: obtained raw offset from server latency=11.102334ms delta=4s 999ms 983µs 445ns ago
[INFO] [stdout] 2026-07-14T04:40:29.865861Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 983µs 445ns ago
[INFO] [stdout] 2026-07-14T04:40:29.865899Z TRACE timesimp: sleeping to spread out requests delay=236.920421ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:30.126528Z TRACE new{response=Response { client: 2026-07-14T04:40:30.104022948Z, server: 2026-07-14T04:40:25.115195617Z } current=2026-07-14T04:40:30.126373736Z}: timesimp::delta: response processing internals latency=11ms 175µs 394ns local_at_midpoint=2026-07-14T04:40:30.115198342Z delta=5s 2µs 725ns ago
[INFO] [stdout] 2026-07-14T04:40:30.126611Z TRACE timesimp: obtained raw offset from server latency=11.175394ms delta=5s 2µs 725ns ago
[INFO] [stdout] 2026-07-14T04:40:30.126634Z TRACE timesimp: sleeping to spread out requests delay=239.476355ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:30.399235Z TRACE new{response=Response { client: 2026-07-14T04:40:30.367046614Z, server: 2026-07-14T04:40:25.387913442Z } current=2026-07-14T04:40:30.399086091Z}: timesimp::delta: response processing internals latency=16ms 19µs 738ns local_at_midpoint=2026-07-14T04:40:30.383066352Z delta=4s 995ms 152µs 910ns ago
[INFO] [stdout] 2026-07-14T04:40:30.399314Z TRACE timesimp: obtained raw offset from server latency=16.019738ms delta=4s 995ms 152µs 910ns ago
[INFO] [stdout] 2026-07-14T04:40:30.399337Z TRACE timesimp: sleeping to spread out requests delay=796.045703ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:30.531387Z TRACE new{response=Response { client: 2026-07-14T04:40:30.51288315Z, server: 2026-07-14T04:40:35.52206621Z } current=2026-07-14T04:40:30.531240438Z}: timesimp::delta: response processing internals latency=9ms 178µs 644ns local_at_midpoint=2026-07-14T04:40:30.522061794Z delta=5s 4µs 416ns
[INFO] [stdout] 2026-07-14T04:40:30.531467Z TRACE timesimp: obtained raw offset from server latency=9.178644ms delta=5s 4µs 416ns
[INFO] [stdout] 2026-07-14T04:40:30.531491Z TRACE timesimp: sleeping to spread out requests delay=1.515046183s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:30.729324Z TRACE new{response=Response { client: 2026-07-14T04:40:30.705886492Z, server: 2026-07-14T04:40:30.717996851Z } current=2026-07-14T04:40:30.7291701Z}: timesimp::delta: response processing internals latency=11ms 641µs 804ns local_at_midpoint=2026-07-14T04:40:30.717528296Z delta=468µs 555ns
[INFO] [stdout] 2026-07-14T04:40:30.729397Z TRACE timesimp: obtained raw offset from server latency=11.641804ms delta=468µs 555ns
[INFO] [stdout] 2026-07-14T04:40:30.729415Z TRACE timesimp: sleeping to spread out requests delay=1.204582332s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:30.733222Z TRACE new{response=Response { client: 2026-07-14T04:40:30.709001482Z, server: 2026-07-14T04:40:30.721888181Z } current=2026-07-14T04:40:30.73302945Z}: timesimp::delta: response processing internals latency=12ms 13µs 984ns local_at_midpoint=2026-07-14T04:40:30.721015466Z delta=872µs 715ns
[INFO] [stdout] 2026-07-14T04:40:30.733283Z TRACE timesimp: obtained raw offset from server latency=12.013984ms delta=872µs 715ns
[INFO] [stdout] 2026-07-14T04:40:30.733304Z TRACE timesimp: sleeping to spread out requests delay=1.539781333s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:31.218541Z TRACE new{response=Response { client: 2026-07-14T04:40:31.196036057Z, server: 2026-07-14T04:40:26.207216816Z } current=2026-07-14T04:40:31.218396815Z}: timesimp::delta: response processing internals latency=11ms 180µs 379ns local_at_midpoint=2026-07-14T04:40:31.207216436Z delta=4s 999ms 999µs 620ns ago
[INFO] [stdout] 2026-07-14T04:40:31.218616Z TRACE timesimp: obtained raw offset from server latency=11.180379ms delta=4s 999ms 999µs 620ns ago
[INFO] [stdout] 2026-07-14T04:40:31.218638Z TRACE timesimp: sleeping to spread out requests delay=1.794306822s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:31.246324Z TRACE new{response=Response { client: 2026-07-14T04:40:31.245041302Z, server: 2026-07-14T04:40:31.245084582Z } current=2026-07-14T04:40:31.246177392Z}: timesimp::delta: response processing internals latency=568µs 45ns local_at_midpoint=2026-07-14T04:40:31.245609347Z delta=524µs 765ns ago
[INFO] [stdout] 2026-07-14T04:40:31.246401Z TRACE timesimp: obtained raw offset from server latency=568.045µs delta=524µs 765ns ago
[INFO] [stdout] 2026-07-14T04:40:31.246422Z TRACE timesimp: sleeping to spread out requests delay=1.662876401s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:31.248111Z TRACE new{response=Response { client: 2026-07-14T04:40:29.842399653Z, server: 2026-07-14T04:40:30.545914147Z } current=2026-07-14T04:40:31.248002312Z}: timesimp::delta: response processing internals latency=702ms 801µs 329ns local_at_midpoint=2026-07-14T04:40:30.545200982Z delta=713µs 165ns
[INFO] [stdout] 2026-07-14T04:40:31.248173Z TRACE timesimp: obtained raw offset from server latency=702.801329ms delta=713µs 165ns
[INFO] [stdout] 2026-07-14T04:40:31.248192Z DEBUG timesimp: no offset stored, storing initial delta offset=713µs 165ns
[INFO] [stdout] 2026-07-14T04:40:31.248205Z TRACE timesimp: sleeping to spread out requests delay=831.240905ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:31.588363Z TRACE new{response=Response { client: 2026-07-14T04:40:31.566913022Z, server: 2026-07-14T04:40:36.577033691Z } current=2026-07-14T04:40:31.5882145Z}: timesimp::delta: response processing internals latency=10ms 650µs 739ns local_at_midpoint=2026-07-14T04:40:31.577563761Z delta=4s 999ms 469µs 930ns
[INFO] [stdout] 2026-07-14T04:40:31.588436Z TRACE timesimp: obtained raw offset from server latency=10.650739ms delta=4s 999ms 469µs 930ns
[INFO] [stdout] 2026-07-14T04:40:31.588456Z TRACE timesimp: sleeping to spread out requests delay=1.105170522s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:31.626511Z TRACE new{response=Response { client: 2026-07-14T04:40:31.616021118Z, server: 2026-07-14T04:40:36.621194557Z } current=2026-07-14T04:40:31.626356147Z}: timesimp::delta: response processing internals latency=5ms 167µs 514ns local_at_midpoint=2026-07-14T04:40:31.621188632Z delta=5s 5µs 925ns
[INFO] [stdout] 2026-07-14T04:40:31.626757Z TRACE timesimp: obtained raw offset from server latency=5.167514ms delta=5s 5µs 925ns
[INFO] [stdout] 2026-07-14T04:40:31.626844Z TRACE timesimp: sleeping to spread out requests delay=409.033385ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:31.957660Z TRACE new{response=Response { client: 2026-07-14T04:40:31.935061288Z, server: 2026-07-14T04:40:31.946233747Z } current=2026-07-14T04:40:31.957509506Z}: timesimp::delta: response processing internals latency=11ms 224µs 109ns local_at_midpoint=2026-07-14T04:40:31.946285397Z delta=51µs 650ns ago
[INFO] [stdout] 2026-07-14T04:40:31.957743Z TRACE timesimp: obtained raw offset from server latency=11.224109ms delta=51µs 650ns ago
[INFO] [stdout] 2026-07-14T04:40:31.957764Z TRACE timesimp: sleeping to spread out requests delay=246.013844ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:32.046343Z TRACE new{response=Response { client: 2026-07-14T04:40:32.037914389Z, server: 2026-07-14T04:40:37.042062348Z } current=2026-07-14T04:40:32.046200168Z}: timesimp::delta: response processing internals latency=4ms 142µs 889ns local_at_midpoint=2026-07-14T04:40:32.042057278Z delta=5s 5µs 70ns
[INFO] [stdout] 2026-07-14T04:40:32.046496Z TRACE timesimp: obtained raw offset from server latency=4.142889ms delta=5s 5µs 70ns
[INFO] [stdout] 2026-07-14T04:40:32.046567Z TRACE timesimp: sleeping to spread out requests delay=1.314215134s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:32.059450Z TRACE new{response=Response { client: 2026-07-14T04:40:32.046969488Z, server: 2026-07-14T04:40:37.053120837Z } current=2026-07-14T04:40:32.059301597Z}: timesimp::delta: response processing internals latency=6ms 166µs 54ns local_at_midpoint=2026-07-14T04:40:32.053135542Z delta=4s 999ms 985µs 295ns
[INFO] [stdout] 2026-07-14T04:40:32.059531Z TRACE timesimp: obtained raw offset from server latency=6.166054ms delta=4s 999ms 985µs 295ns
[INFO] [stdout] 2026-07-14T04:40:32.059552Z TRACE timesimp: sleeping to spread out requests delay=954.348107ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:32.226401Z TRACE new{response=Response { client: 2026-07-14T04:40:32.204038853Z, server: 2026-07-14T04:40:32.215081472Z } current=2026-07-14T04:40:32.226257181Z}: timesimp::delta: response processing internals latency=11ms 109µs 164ns local_at_midpoint=2026-07-14T04:40:32.215148017Z delta=66µs 545ns ago
[INFO] [stdout] 2026-07-14T04:40:32.226479Z TRACE timesimp: obtained raw offset from server latency=11.109164ms delta=66µs 545ns ago
[INFO] [stdout] 2026-07-14T04:40:32.226500Z TRACE timesimp: sleeping to spread out requests delay=1.588518813s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:32.299329Z TRACE new{response=Response { client: 2026-07-14T04:40:32.274915037Z, server: 2026-07-14T04:40:32.287911625Z } current=2026-07-14T04:40:32.299086594Z}: timesimp::delta: response processing internals latency=12ms 85µs 778ns local_at_midpoint=2026-07-14T04:40:32.287000815Z delta=910µs 810ns
[INFO] [stdout] 2026-07-14T04:40:32.299408Z TRACE timesimp: obtained raw offset from server latency=12.085778ms delta=910µs 810ns
[INFO] [stdout] 2026-07-14T04:40:32.299428Z TRACE timesimp: sleeping to spread out requests delay=1.078206066s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:32.714541Z TRACE new{response=Response { client: 2026-07-14T04:40:32.694042548Z, server: 2026-07-14T04:40:37.704216056Z } current=2026-07-14T04:40:32.714389886Z}: timesimp::delta: response processing internals latency=10ms 173µs 669ns local_at_midpoint=2026-07-14T04:40:32.704216217Z delta=4s 999ms 999µs 839ns
[INFO] [stdout] 2026-07-14T04:40:32.714857Z TRACE timesimp: obtained raw offset from server latency=10.173669ms delta=4s 999ms 999µs 839ns
[INFO] [stdout] 2026-07-14T04:40:32.715025Z TRACE timesimp: sleeping to spread out requests delay=1.912999357s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:32.912364Z TRACE new{response=Response { client: 2026-07-14T04:40:32.911055627Z, server: 2026-07-14T04:40:32.911100357Z } current=2026-07-14T04:40:32.912215367Z}: timesimp::delta: response processing internals latency=579µs 870ns local_at_midpoint=2026-07-14T04:40:32.911635497Z delta=535µs 140ns ago
[INFO] [stdout] 2026-07-14T04:40:32.912447Z TRACE timesimp: obtained raw offset from server latency=579.87µs delta=535µs 140ns ago
[INFO] [stdout] 2026-07-14T04:40:32.912478Z TRACE timesimp: sleeping to spread out requests delay=1.752205321s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.033531Z TRACE new{response=Response { client: 2026-07-14T04:40:33.015035308Z, server: 2026-07-14T04:40:38.024203877Z } current=2026-07-14T04:40:33.033382156Z}: timesimp::delta: response processing internals latency=9ms 173µs 424ns local_at_midpoint=2026-07-14T04:40:33.024208732Z delta=4s 999ms 995µs 145ns
[INFO] [stdout] 2026-07-14T04:40:33.033614Z TRACE timesimp: obtained raw offset from server latency=9.173424ms delta=4s 999ms 995µs 145ns
[INFO] [stdout] 2026-07-14T04:40:33.033636Z TRACE timesimp: sleeping to spread out requests delay=326.308908ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.036372Z TRACE new{response=Response { client: 2026-07-14T04:40:33.014011838Z, server: 2026-07-14T04:40:28.025154047Z } current=2026-07-14T04:40:33.036285386Z}: timesimp::delta: response processing internals latency=11ms 136µs 774ns local_at_midpoint=2026-07-14T04:40:33.025148612Z delta=4s 999ms 994µs 565ns ago
[INFO] [stdout] 2026-07-14T04:40:33.036434Z TRACE timesimp: obtained raw offset from server latency=11.136774ms delta=4s 999ms 994µs 565ns ago
[INFO] [stdout] 2026-07-14T04:40:33.036461Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.983445, -4999.994565, -5000.002725, -4999.9996200000005, -4995.15291]
[INFO] [stdout] 2026-07-14T04:40:33.036486Z TRACE timesimp: statistics about response deltas median=-5000.002725 mean=-4999.026653 variance=4.689392683333196 stddev=2.165500561840887
[INFO] [stdout] 2026-07-14T04:40:33.036515Z TRACE timesimp: eliminated outliers inliers=[-4999.983445, -4999.994565, -5000.002725, -4999.9996200000005]
[INFO] [stdout] 2026-07-14T04:40:33.036528Z DEBUG timesimp: storing calculated offset offset=4s 999ms 995µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2026-07-14T04:40:33.038045Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:33.038082Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.061778Z TRACE new{response=Response { client: 2026-07-14T04:40:33.039262216Z, server: 2026-07-14T04:40:38.050421704Z } current=2026-07-14T04:40:33.061594553Z}: timesimp::delta: response processing internals latency=11ms 166µs 168ns local_at_midpoint=2026-07-14T04:40:33.050428384Z delta=4s 999ms 993µs 320ns
[INFO] [stdout] 2026-07-14T04:40:33.061872Z TRACE timesimp: obtained raw offset from server latency=11.166168ms delta=4s 999ms 993µs 320ns
[INFO] [stdout] 2026-07-14T04:40:33.061892Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 993µs 320ns
[INFO] [stdout] 2026-07-14T04:40:33.061904Z TRACE timesimp: sleeping to spread out requests delay=1.57238412s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.377343Z TRACE new{response=Response { client: 2026-07-14T04:40:33.361906406Z, server: 2026-07-14T04:40:38.369038355Z } current=2026-07-14T04:40:33.377196074Z}: timesimp::delta: response processing internals latency=7ms 644µs 834ns local_at_midpoint=2026-07-14T04:40:33.36955124Z delta=4s 999ms 487µs 115ns
[INFO] [stdout] 2026-07-14T04:40:33.377425Z TRACE timesimp: obtained raw offset from server latency=7.644834ms delta=4s 999ms 487µs 115ns
[INFO] [stdout] 2026-07-14T04:40:33.377455Z TRACE timesimp: response deltas sorted by latency deltas=[4999.985295, 5000.002645, 4999.487115, 4999.995145, 5000.004416]
[INFO] [stdout] 2026-07-14T04:40:33.377473Z TRACE timesimp: statistics about response deltas median=4999.487115 mean=4999.8949231999995 variance=0.05202791471619553 stddev=0.2280962838719551
[INFO] [stdout] 2026-07-14T04:40:33.377495Z TRACE timesimp: eliminated outliers inliers=[4999.487115]
[INFO] [stdout] 2026-07-14T04:40:33.377506Z DEBUG timesimp: storing calculated offset offset=4s 999ms 487µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2026-07-14T04:40:33.377924Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:33.377960Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.406134Z TRACE new{response=Response { client: 2026-07-14T04:40:33.380337334Z, server: 2026-07-14T04:40:33.392906923Z } current=2026-07-14T04:40:33.405903922Z}: timesimp::delta: response processing internals latency=12ms 783µs 294ns local_at_midpoint=2026-07-14T04:40:33.393120628Z delta=213µs 705ns ago
[INFO] [stdout] 2026-07-14T04:40:33.406210Z TRACE timesimp: obtained raw offset from server latency=12.783294ms delta=213µs 705ns ago
[INFO] [stdout] 2026-07-14T04:40:33.406230Z TRACE timesimp: sleeping to spread out requests delay=1.128793656s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.419053Z TRACE new{response=Response { client: 2026-07-14T04:40:33.367896455Z, server: 2026-07-14T04:40:38.378865364Z } current=2026-07-14T04:40:33.41890927Z}: timesimp::delta: response processing internals latency=25ms 506µs 407ns local_at_midpoint=2026-07-14T04:40:33.393402862Z delta=4s 985ms 462µs 502ns
[INFO] [stdout] 2026-07-14T04:40:33.419131Z TRACE timesimp: obtained raw offset from server latency=25.506407ms delta=4s 985ms 462µs 502ns
[INFO] [stdout] 2026-07-14T04:40:33.419152Z TRACE timesimp: sleeping to spread out requests delay=74.561086ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.510976Z TRACE new{response=Response { client: 2026-07-14T04:40:33.495463563Z, server: 2026-07-14T04:40:38.503634842Z } current=2026-07-14T04:40:33.510801741Z}: timesimp::delta: response processing internals latency=7ms 669µs 89ns local_at_midpoint=2026-07-14T04:40:33.503132652Z delta=5s 502µs 190ns
[INFO] [stdout] 2026-07-14T04:40:33.511058Z TRACE timesimp: obtained raw offset from server latency=7.669089ms delta=5s 502µs 190ns
[INFO] [stdout] 2026-07-14T04:40:33.511088Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00507, 5000.005925, 5000.50219, 4999.48401, 4985.462502]
[INFO] [stdout] 2026-07-14T04:40:33.511107Z TRACE timesimp: statistics about response deltas median=5000.50219 mean=4997.091939399999 variance=42.39331678009119 stddev=6.511015034546548
[INFO] [stdout] 2026-07-14T04:40:33.511126Z TRACE timesimp: eliminated outliers inliers=[5000.00507, 5000.005925, 5000.50219, 4999.48401]
[INFO] [stdout] 2026-07-14T04:40:33.511139Z DEBUG timesimp: storing calculated offset offset=4s 999ms 999µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2026-07-14T04:40:33.581971Z TRACE new{response=Response { client: 2026-07-14T04:40:33.379133614Z, server: 2026-07-14T04:40:33.480440964Z } current=2026-07-14T04:40:33.581800675Z}: timesimp::delta: response processing internals latency=101ms 333µs 530ns local_at_midpoint=2026-07-14T04:40:33.480467144Z delta=26µs 180ns ago
[INFO] [stdout] 2026-07-14T04:40:33.582050Z TRACE timesimp: obtained raw offset from server latency=101.33353ms delta=26µs 180ns ago
[INFO] [stdout] 2026-07-14T04:40:33.582069Z DEBUG timesimp: no offset stored, storing initial delta offset=26µs 180ns ago
[INFO] [stdout] 2026-07-14T04:40:33.582082Z TRACE timesimp: sleeping to spread out requests delay=448.641891ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:33.838566Z TRACE new{response=Response { client: 2026-07-14T04:40:33.816047693Z, server: 2026-07-14T04:40:33.827227962Z } current=2026-07-14T04:40:33.838407971Z}: timesimp::delta: response processing internals latency=11ms 180µs 139ns local_at_midpoint=2026-07-14T04:40:33.827227832Z delta=130ns
[INFO] [stdout] 2026-07-14T04:40:33.838651Z TRACE timesimp: obtained raw offset from server latency=11.180139ms delta=130ns
[INFO] [stdout] 2026-07-14T04:40:33.838684Z TRACE timesimp: response deltas sorted by latency deltas=[-0.066545, -0.01002, 0.00013, -0.05165, 0.468555]
[INFO] [stdout] 2026-07-14T04:40:33.838724Z TRACE timesimp: statistics about response deltas median=0.00013 mean=0.068094 variance=0.0508890501675 stddev=0.22558601500868797
[INFO] [stdout] 2026-07-14T04:40:33.838750Z TRACE timesimp: eliminated outliers inliers=[-0.066545, -0.01002, 0.00013, -0.05165]
[INFO] [stdout] 2026-07-14T04:40:33.838770Z DEBUG timesimp: storing calculated offset offset=32µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2026-07-14T04:40:33.884187Z TRACE new{response=Response { client: 2026-07-14T04:40:32.080050215Z, server: 2026-07-14T04:40:32.982027741Z } current=2026-07-14T04:40:33.884036997Z}: timesimp::delta: response processing internals latency=901ms 993µs 391ns local_at_midpoint=2026-07-14T04:40:32.982043606Z delta=15µs 865ns ago
[INFO] [stdout] 2026-07-14T04:40:33.884269Z TRACE timesimp: obtained raw offset from server latency=901.993391ms delta=15µs 865ns ago
[INFO] [stdout] 2026-07-14T04:40:33.884291Z TRACE timesimp: sleeping to spread out requests delay=932.113489ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:34.233593Z TRACE new{response=Response { client: 2026-07-14T04:40:34.031786663Z, server: 2026-07-14T04:40:34.132101824Z } current=2026-07-14T04:40:34.233432234Z}: timesimp::delta: response processing internals latency=100ms 822µs 785ns local_at_midpoint=2026-07-14T04:40:34.132609448Z delta=507µs 624ns ago
[INFO] [stdout] 2026-07-14T04:40:34.233674Z TRACE timesimp: obtained raw offset from server latency=100.822785ms delta=507µs 624ns ago
[INFO] [stdout] 2026-07-14T04:40:34.233696Z TRACE timesimp: sleeping to spread out requests delay=1.931768081s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:34.558611Z TRACE new{response=Response { client: 2026-07-14T04:40:34.536095816Z, server: 2026-07-14T04:40:34.547276835Z } current=2026-07-14T04:40:34.558456084Z}: timesimp::delta: response processing internals latency=11ms 180µs 134ns local_at_midpoint=2026-07-14T04:40:34.54727595Z delta=885ns
[INFO] [stdout] 2026-07-14T04:40:34.558696Z TRACE timesimp: obtained raw offset from server latency=11.180134ms delta=885ns
[INFO] [stdout] 2026-07-14T04:40:34.558727Z TRACE timesimp: response deltas sorted by latency deltas=[-0.003891, 0.000885, 0.872715, 0.91081, -0.213705]
[INFO] [stdout] 2026-07-14T04:40:34.558748Z TRACE timesimp: statistics about response deltas median=0.872715 mean=0.3133628 variance=0.28647771383419995 stddev=0.5352361290441817
[INFO] [stdout] 2026-07-14T04:40:34.558766Z TRACE timesimp: eliminated outliers inliers=[0.872715, 0.91081]
[INFO] [stdout] 2026-07-14T04:40:34.558785Z DEBUG timesimp: storing calculated offset offset=891µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2026-07-14T04:40:34.651567Z TRACE new{response=Response { client: 2026-07-14T04:40:34.629028318Z, server: 2026-07-14T04:40:39.640175847Z } current=2026-07-14T04:40:34.651408506Z}: timesimp::delta: response processing internals latency=11ms 190µs 94ns local_at_midpoint=2026-07-14T04:40:34.640218412Z delta=4s 999ms 957µs 435ns
[INFO] [stdout] 2026-07-14T04:40:34.651721Z TRACE timesimp: obtained raw offset from server latency=11.190094ms delta=4s 999ms 957µs 435ns
[INFO] [stdout] 2026-07-14T04:40:34.651796Z TRACE timesimp: sleeping to spread out requests delay=433.02591ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:34.660259Z TRACE new{response=Response { client: 2026-07-14T04:40:34.636050847Z, server: 2026-07-14T04:40:39.648924086Z } current=2026-07-14T04:40:34.660104075Z}: timesimp::delta: response processing internals latency=12ms 26µs 614ns local_at_midpoint=2026-07-14T04:40:34.648077461Z delta=5s 846µs 625ns
[INFO] [stdout] 2026-07-14T04:40:34.660342Z TRACE timesimp: obtained raw offset from server latency=12.026614ms delta=5s 846µs 625ns
[INFO] [stdout] 2026-07-14T04:40:34.660365Z TRACE timesimp: sleeping to spread out requests delay=295.518035ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:34.668116Z TRACE new{response=Response { client: 2026-07-14T04:40:34.665743204Z, server: 2026-07-14T04:40:34.666867624Z } current=2026-07-14T04:40:34.667980654Z}: timesimp::delta: response processing internals latency=1ms 118µs 725ns local_at_midpoint=2026-07-14T04:40:34.666861929Z delta=5µs 695ns
[INFO] [stdout] 2026-07-14T04:40:34.668192Z TRACE timesimp: obtained raw offset from server latency=1.118725ms delta=5µs 695ns
[INFO] [stdout] 2026-07-14T04:40:34.668211Z TRACE timesimp: sleeping to spread out requests delay=1.168292792s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:34.985044Z TRACE new{response=Response { client: 2026-07-14T04:40:34.956893157Z, server: 2026-07-14T04:40:39.967164606Z } current=2026-07-14T04:40:34.984903524Z}: timesimp::delta: response processing internals latency=14ms 5µs 183ns local_at_midpoint=2026-07-14T04:40:34.97089834Z delta=4s 996ms 266µs 266ns
[INFO] [stdout] 2026-07-14T04:40:34.985118Z TRACE timesimp: obtained raw offset from server latency=14.005183ms delta=4s 996ms 266µs 266ns
[INFO] [stdout] 2026-07-14T04:40:34.985138Z TRACE timesimp: sleeping to spread out requests delay=1.288749438s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:35.106665Z TRACE new{response=Response { client: 2026-07-14T04:40:35.086044135Z, server: 2026-07-14T04:40:40.096325064Z } current=2026-07-14T04:40:35.106510553Z}: timesimp::delta: response processing internals latency=10ms 233µs 209ns local_at_midpoint=2026-07-14T04:40:35.096277344Z delta=5s 47µs 720ns
[INFO] [stdout] 2026-07-14T04:40:35.106745Z TRACE timesimp: obtained raw offset from server latency=10.233209ms delta=5s 47µs 720ns
[INFO] [stdout] 2026-07-14T04:40:35.106772Z TRACE timesimp: response deltas sorted by latency deltas=[4999.999839, 5000.04772, 4999.46993, 4999.957435, 4999.91586]
[INFO] [stdout] 2026-07-14T04:40:35.106790Z TRACE timesimp: statistics about response deltas median=4999.46993 mean=4999.8781567999995 variance=0.054478480278637574 stddev=0.23340625586868397
[INFO] [stdout] 2026-07-14T04:40:35.106816Z TRACE timesimp: eliminated outliers inliers=[4999.46993]
[INFO] [stdout] 2026-07-14T04:40:35.106843Z DEBUG timesimp: storing calculated offset offset=4s 999ms 469µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2026-07-14T04:40:35.839347Z TRACE new{response=Response { client: 2026-07-14T04:40:35.838043485Z, server: 2026-07-14T04:40:35.838087745Z } current=2026-07-14T04:40:35.839202925Z}: timesimp::delta: response processing internals latency=579µs 720ns local_at_midpoint=2026-07-14T04:40:35.838623205Z delta=535µs 460ns ago
[INFO] [stdout] 2026-07-14T04:40:35.839425Z TRACE timesimp: obtained raw offset from server latency=579.72µs delta=535µs 460ns ago
[INFO] [stdout] 2026-07-14T04:40:35.839449Z TRACE timesimp: response deltas sorted by latency deltas=[-0.524765, -0.53546, -0.53514, -0.00108, 0.005695]
[INFO] [stdout] 2026-07-14T04:40:35.839475Z TRACE timesimp: statistics about response deltas median=-0.53514 mean=-0.31815 variance=0.08560175583749999 stddev=0.29257777741568136
[INFO] [stdout] 2026-07-14T04:40:35.839498Z TRACE timesimp: eliminated outliers inliers=[-0.524765, -0.53546, -0.53514]
[INFO] [stdout] 2026-07-14T04:40:35.839509Z DEBUG timesimp: storing calculated offset offset=531µs ago
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2026-07-14T04:40:36.297558Z TRACE new{response=Response { client: 2026-07-14T04:40:36.275053545Z, server: 2026-07-14T04:40:41.286225834Z } current=2026-07-14T04:40:36.297398843Z}: timesimp::delta: response processing internals latency=11ms 172µs 649ns local_at_midpoint=2026-07-14T04:40:36.286226194Z delta=4s 999ms 999µs 640ns
[INFO] [stdout] 2026-07-14T04:40:36.297638Z TRACE timesimp: obtained raw offset from server latency=11.172649ms delta=4s 999ms 999µs 640ns
[INFO] [stdout] 2026-07-14T04:40:36.297661Z TRACE timesimp: sleeping to spread out requests delay=1.145503298s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:36.368862Z TRACE new{response=Response { client: 2026-07-14T04:40:36.166044045Z, server: 2026-07-14T04:40:36.267384215Z } current=2026-07-14T04:40:36.368693086Z}: timesimp::delta: response processing internals latency=101ms 324µs 520ns local_at_midpoint=2026-07-14T04:40:36.267368565Z delta=15µs 650ns
[INFO] [stdout] 2026-07-14T04:40:36.368943Z TRACE timesimp: obtained raw offset from server latency=101.32452ms delta=15µs 650ns
[INFO] [stdout] 2026-07-14T04:40:36.368963Z TRACE timesimp: sleeping to spread out requests delay=878.168406ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:36.491201Z TRACE new{response=Response { client: 2026-07-14T04:40:34.81706099Z, server: 2026-07-14T04:40:35.654040792Z } current=2026-07-14T04:40:36.491046865Z}: timesimp::delta: response processing internals latency=836ms 992µs 937ns local_at_midpoint=2026-07-14T04:40:35.654053927Z delta=13µs 135ns ago
[INFO] [stdout] 2026-07-14T04:40:36.491456Z TRACE timesimp: obtained raw offset from server latency=836.992937ms delta=13µs 135ns ago
[INFO] [stdout] 2026-07-14T04:40:36.491543Z TRACE timesimp: sleeping to spread out requests delay=416.854726ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:37.457422Z TRACE new{response=Response { client: 2026-07-14T04:40:37.254911954Z, server: 2026-07-14T04:40:37.356015484Z } current=2026-07-14T04:40:37.457281565Z}: timesimp::delta: response processing internals latency=101ms 184µs 805ns local_at_midpoint=2026-07-14T04:40:37.356096759Z delta=81µs 275ns ago
[INFO] [stdout] 2026-07-14T04:40:37.457501Z TRACE timesimp: obtained raw offset from server latency=101.184805ms delta=81µs 275ns ago
[INFO] [stdout] 2026-07-14T04:40:37.457519Z TRACE timesimp: sleeping to spread out requests delay=1.064950616s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:37.466999Z TRACE new{response=Response { client: 2026-07-14T04:40:37.444377326Z, server: 2026-07-14T04:40:42.455658325Z } current=2026-07-14T04:40:37.466845054Z}: timesimp::delta: response processing internals latency=11ms 233µs 864ns local_at_midpoint=2026-07-14T04:40:37.45561119Z delta=5s 47µs 135ns
[INFO] [stdout] 2026-07-14T04:40:37.467082Z TRACE timesimp: obtained raw offset from server latency=11.233864ms delta=5s 47µs 135ns
[INFO] [stdout] 2026-07-14T04:40:37.467112Z TRACE timesimp: response deltas sorted by latency deltas=[4999.99332, 4999.99964, 5000.047135, 5000.846625, 4996.266266]
[INFO] [stdout] 2026-07-14T04:40:37.467146Z TRACE timesimp: statistics about response deltas median=5000.047135 mean=4999.4305972 variance=3.259678047592195 stddev=1.8054578498519966
[INFO] [stdout] 2026-07-14T04:40:37.467166Z TRACE timesimp: eliminated outliers inliers=[4999.99332, 4999.99964, 5000.047135, 5000.846625]
[INFO] [stdout] 2026-07-14T04:40:37.467179Z DEBUG timesimp: storing calculated offset offset=5s 221µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2026-07-14T04:40:38.725873Z TRACE new{response=Response { client: 2026-07-14T04:40:38.523035566Z, server: 2026-07-14T04:40:38.624354476Z } current=2026-07-14T04:40:38.725685227Z}: timesimp::delta: response processing internals latency=101ms 324µs 830ns local_at_midpoint=2026-07-14T04:40:38.624360396Z delta=5µs 920ns ago
[INFO] [stdout] 2026-07-14T04:40:38.725955Z TRACE timesimp: obtained raw offset from server latency=101.32483ms delta=5µs 920ns ago
[INFO] [stdout] 2026-07-14T04:40:38.725983Z TRACE timesimp: response deltas sorted by latency deltas=[-0.507624, -0.081275, 0.01565, -0.00592, -0.02618]
[INFO] [stdout] 2026-07-14T04:40:38.726000Z TRACE timesimp: statistics about response deltas median=0.01565 mean=-0.12106979999999998 variance=0.04799090748519999 stddev=0.21906827128819908
[INFO] [stdout] 2026-07-14T04:40:38.726023Z TRACE timesimp: eliminated outliers inliers=[-0.081275, 0.01565, -0.00592, -0.02618]
[INFO] [stdout] 2026-07-14T04:40:38.726034Z DEBUG timesimp: storing calculated offset offset=24µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2026-07-14T04:40:38.846178Z TRACE new{response=Response { client: 2026-07-14T04:40:36.909043726Z, server: 2026-07-14T04:40:37.881907185Z } current=2026-07-14T04:40:38.846036236Z}: timesimp::delta: response processing internals latency=968ms 496µs 255ns local_at_midpoint=2026-07-14T04:40:37.877539981Z delta=4ms 367µs 204ns
[INFO] [stdout] 2026-07-14T04:40:38.846247Z TRACE timesimp: obtained raw offset from server latency=968.496255ms delta=4ms 367µs 204ns
[INFO] [stdout] 2026-07-14T04:40:38.846265Z TRACE timesimp: sleeping to spread out requests delay=36.322437ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.584060Z TRACE new{response=Response { client: 2026-07-14T04:40:38.883591162Z, server: 2026-07-14T04:40:39.733039703Z } current=2026-07-14T04:40:40.583907964Z}: timesimp::delta: response processing internals latency=850ms 158µs 401ns local_at_midpoint=2026-07-14T04:40:39.733749563Z delta=709µs 860ns ago
[INFO] [stdout] 2026-07-14T04:40:40.584143Z TRACE timesimp: obtained raw offset from server latency=850.158401ms delta=709µs 860ns ago
[INFO] [stdout] 2026-07-14T04:40:40.584172Z TRACE timesimp: response deltas sorted by latency deltas=[0.713165, -0.013135, -0.70986, -0.015865, 4.367204]
[INFO] [stdout] 2026-07-14T04:40:40.584191Z TRACE timesimp: statistics about response deltas median=-0.70986 mean=0.8683018 variance=4.0789151153687 stddev=2.0196324208550176
[INFO] [stdout] 2026-07-14T04:40:40.584209Z TRACE timesimp: eliminated outliers inliers=[0.713165, -0.013135, -0.70986, -0.015865]
[INFO] [stdout] 2026-07-14T04:40:40.584221Z DEBUG timesimp: storing calculated offset offset=6µs ago
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-405f21f178b7074c)
[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.74s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2026-07-14T04:40:40.587638Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-07-14T04:40:40.587633Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:40.587632Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-07-14T04:40:40.587713Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.587730Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.587730Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.589071Z TRACE new{response=Response { client: 2026-07-14T04:40:40.588940494Z, server: 2026-07-14T04:40:40.588943414Z } current=2026-07-14T04:40:40.588945263Z}: timesimp::delta: response processing internals latency=2µs 384ns local_at_midpoint=2026-07-14T04:40:40.588942878Z delta=536ns
[INFO] [stdout] 2026-07-14T04:40:40.589071Z TRACE new{response=Response { client: 2026-07-14T04:40:40.588940343Z, server: 2026-07-14T04:40:40.588943403Z } current=2026-07-14T04:40:40.588945274Z}: timesimp::delta: response processing internals latency=2µs 465ns local_at_midpoint=2026-07-14T04:40:40.588942808Z delta=595ns
[INFO] [stdout] 2026-07-14T04:40:40.589140Z TRACE timesimp: obtained raw offset from server latency=2.384µs delta=536ns
[INFO] [stdout] 2026-07-14T04:40:40.589144Z TRACE timesimp: obtained raw offset from server latency=2.465µs delta=595ns
[INFO] [stdout] 2026-07-14T04:40:40.589168Z TRACE timesimp: sleeping to spread out requests delay=887.443118ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.589187Z DEBUG timesimp: no offset stored, storing initial delta offset=595ns
[INFO] [stdout] 2026-07-14T04:40:40.589201Z TRACE timesimp: sleeping to spread out requests delay=1.377114456s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.587634Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-07-14T04:40:40.589909Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.589072Z TRACE new{response=Response { client: 2026-07-14T04:40:40.588928543Z, server: 2026-07-14T04:40:45.588940414Z } current=2026-07-14T04:40:40.588943343Z}: timesimp::delta: response processing internals latency=7µs 400ns local_at_midpoint=2026-07-14T04:40:40.588935943Z delta=5s 4µs 471ns
[INFO] [stdout] 2026-07-14T04:40:40.590873Z TRACE timesimp: obtained raw offset from server latency=7.4µs delta=5s 4µs 471ns
[INFO] [stdout] 2026-07-14T04:40:40.590897Z TRACE timesimp: sleeping to spread out requests delay=1.030291728s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.591330Z TRACE new{response=Response { client: 2026-07-14T04:40:40.591244973Z, server: 2026-07-14T04:40:35.591247313Z } current=2026-07-14T04:40:40.591248763Z}: timesimp::delta: response processing internals latency=1µs 895ns local_at_midpoint=2026-07-14T04:40:40.591246868Z delta=4s 999ms 999µs 555ns ago
[INFO] [stdout] 2026-07-14T04:40:40.591384Z TRACE timesimp: obtained raw offset from server latency=1.895µs delta=4s 999ms 999µs 555ns ago
[INFO] [stdout] 2026-07-14T04:40:40.591446Z TRACE timesimp: sleeping to spread out requests delay=343.942848ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:40.939056Z TRACE new{response=Response { client: 2026-07-14T04:40:40.938906911Z, server: 2026-07-14T04:40:35.938916011Z } current=2026-07-14T04:40:40.938919031Z}: timesimp::delta: response processing internals latency=6µs 60ns local_at_midpoint=2026-07-14T04:40:40.938912971Z delta=4s 999ms 996µs 960ns ago
[INFO] [stdout] 2026-07-14T04:40:40.939203Z TRACE timesimp: obtained raw offset from server latency=6.06µs delta=4s 999ms 996µs 960ns ago
[INFO] [stdout] 2026-07-14T04:40:40.939266Z TRACE timesimp: sleeping to spread out requests delay=837.297032ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:41.478193Z TRACE new{response=Response { client: 2026-07-14T04:40:41.478040411Z, server: 2026-07-14T04:40:41.478049861Z } current=2026-07-14T04:40:41.478053391Z}: timesimp::delta: response processing internals latency=6µs 490ns local_at_midpoint=2026-07-14T04:40:41.478046901Z delta=2µs 960ns
[INFO] [stdout] 2026-07-14T04:40:41.478274Z TRACE timesimp: obtained raw offset from server latency=6.49µs delta=2µs 960ns
[INFO] [stdout] 2026-07-14T04:40:41.478295Z TRACE timesimp: sleeping to spread out requests delay=1.755555945s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:41.622196Z TRACE new{response=Response { client: 2026-07-14T04:40:41.622037808Z, server: 2026-07-14T04:40:46.622047308Z } current=2026-07-14T04:40:41.622050688Z}: timesimp::delta: response processing internals latency=6µs 440ns local_at_midpoint=2026-07-14T04:40:41.622044248Z delta=5s 3µs 60ns
[INFO] [stdout] 2026-07-14T04:40:41.622282Z TRACE timesimp: obtained raw offset from server latency=6.44µs delta=5s 3µs 60ns
[INFO] [stdout] 2026-07-14T04:40:41.622303Z TRACE timesimp: sleeping to spread out requests delay=1.649144522s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:41.778196Z TRACE new{response=Response { client: 2026-07-14T04:40:41.778035123Z, server: 2026-07-14T04:40:36.778044283Z } current=2026-07-14T04:40:41.778047703Z}: timesimp::delta: response processing internals latency=6µs 290ns local_at_midpoint=2026-07-14T04:40:41.778041413Z delta=4s 999ms 997µs 130ns ago
[INFO] [stdout] 2026-07-14T04:40:41.778360Z TRACE timesimp: obtained raw offset from server latency=6.29µs delta=4s 999ms 997µs 130ns ago
[INFO] [stdout] 2026-07-14T04:40:41.778440Z TRACE timesimp: sleeping to spread out requests delay=1.081966715s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:41.971073Z TRACE new{response=Response { client: 2026-07-14T04:40:41.970914235Z, server: 2026-07-14T04:40:41.97092459Z } current=2026-07-14T04:40:41.970927735Z}: timesimp::delta: response processing internals latency=6µs 750ns local_at_midpoint=2026-07-14T04:40:41.970920985Z delta=3µs 605ns
[INFO] [stdout] 2026-07-14T04:40:41.971154Z TRACE timesimp: obtained raw offset from server latency=6.75µs delta=3µs 605ns
[INFO] [stdout] 2026-07-14T04:40:41.971173Z TRACE timesimp: sleeping to spread out requests delay=746.952559ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:42.719183Z TRACE new{response=Response { client: 2026-07-14T04:40:42.719037416Z, server: 2026-07-14T04:40:42.719047031Z } current=2026-07-14T04:40:42.719049805Z}: timesimp::delta: response processing internals latency=6µs 194ns local_at_midpoint=2026-07-14T04:40:42.71904361Z delta=3µs 421ns
[INFO] [stdout] 2026-07-14T04:40:42.719252Z TRACE timesimp: obtained raw offset from server latency=6.194µs delta=3µs 421ns
[INFO] [stdout] 2026-07-14T04:40:42.719271Z TRACE timesimp: sleeping to spread out requests delay=239.959422ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:42.864059Z TRACE new{response=Response { client: 2026-07-14T04:40:42.863908332Z, server: 2026-07-14T04:40:37.863917572Z } current=2026-07-14T04:40:42.863921072Z}: timesimp::delta: response processing internals latency=6µs 370ns local_at_midpoint=2026-07-14T04:40:42.863914702Z delta=4s 999ms 997µs 130ns ago
[INFO] [stdout] 2026-07-14T04:40:42.864136Z TRACE timesimp: obtained raw offset from server latency=6.37µs delta=4s 999ms 997µs 130ns ago
[INFO] [stdout] 2026-07-14T04:40:42.864156Z TRACE timesimp: sleeping to spread out requests delay=949.112213ms max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:42.959944Z TRACE new{response=Response { client: 2026-07-14T04:40:42.959766293Z, server: 2026-07-14T04:40:42.959776138Z } current=2026-07-14T04:40:42.959778943Z}: timesimp::delta: response processing internals latency=6µs 325ns local_at_midpoint=2026-07-14T04:40:42.959772618Z delta=3µs 520ns
[INFO] [stdout] 2026-07-14T04:40:42.960019Z TRACE timesimp: obtained raw offset from server latency=6.325µs delta=3µs 520ns
[INFO] [stdout] 2026-07-14T04:40:42.960041Z TRACE timesimp: sleeping to spread out requests delay=1.262001699s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:43.235195Z TRACE new{response=Response { client: 2026-07-14T04:40:43.235038448Z, server: 2026-07-14T04:40:43.235048148Z } current=2026-07-14T04:40:43.235051868Z}: timesimp::delta: response processing internals latency=6µs 710ns local_at_midpoint=2026-07-14T04:40:43.235045158Z delta=2µs 990ns
[INFO] [stdout] 2026-07-14T04:40:43.235357Z TRACE timesimp: obtained raw offset from server latency=6.71µs delta=2µs 990ns
[INFO] [stdout] 2026-07-14T04:40:43.235435Z TRACE timesimp: sleeping to spread out requests delay=1.363289527s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:43.275068Z TRACE new{response=Response { client: 2026-07-14T04:40:43.274911204Z, server: 2026-07-14T04:40:48.274920434Z } current=2026-07-14T04:40:43.274923684Z}: timesimp::delta: response processing internals latency=6µs 240ns local_at_midpoint=2026-07-14T04:40:43.274917444Z delta=5s 2µs 990ns
[INFO] [stdout] 2026-07-14T04:40:43.275151Z TRACE timesimp: obtained raw offset from server latency=6.24µs delta=5s 2µs 990ns
[INFO] [stdout] 2026-07-14T04:40:43.275173Z TRACE timesimp: sleeping to spread out requests delay=1.169162793s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:43.814183Z TRACE new{response=Response { client: 2026-07-14T04:40:43.814035664Z, server: 2026-07-14T04:40:38.814044814Z } current=2026-07-14T04:40:43.814048024Z}: timesimp::delta: response processing internals latency=6µs 180ns local_at_midpoint=2026-07-14T04:40:43.814041844Z delta=4s 999ms 997µs 30ns ago
[INFO] [stdout] 2026-07-14T04:40:43.814258Z TRACE timesimp: obtained raw offset from server latency=6.18µs delta=4s 999ms 997µs 30ns ago
[INFO] [stdout] 2026-07-14T04:40:43.814283Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.999555, -4999.99696, -4999.99703, -4999.99713, -4999.99713]
[INFO] [stdout] 2026-07-14T04:40:43.814300Z TRACE timesimp: statistics about response deltas median=-4999.99703 mean=-4999.997561 variance=1.2476800001981617e-6 stddev=0.0011169959714332732
[INFO] [stdout] 2026-07-14T04:40:43.814320Z TRACE timesimp: eliminated outliers inliers=[-4999.99696, -4999.99703, -4999.99713, -4999.99713]
[INFO] [stdout] 2026-07-14T04:40:43.814333Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2026-07-14T04:40:44.224065Z TRACE new{response=Response { client: 2026-07-14T04:40:44.223906516Z, server: 2026-07-14T04:40:44.22391646Z } current=2026-07-14T04:40:44.223919125Z}: timesimp::delta: response processing internals latency=6µs 304ns local_at_midpoint=2026-07-14T04:40:44.22391282Z delta=3µs 640ns
[INFO] [stdout] 2026-07-14T04:40:44.224221Z TRACE timesimp: obtained raw offset from server latency=6.304µs delta=3µs 640ns
[INFO] [stdout] 2026-07-14T04:40:44.224307Z TRACE timesimp: response deltas sorted by latency deltas=[0.000595, 0.003421, 0.00364, 0.00352, 0.003605]
[INFO] [stdout] 2026-07-14T04:40:44.224377Z TRACE timesimp: statistics about response deltas median=0.00364 mean=0.0029562 variance=1.7494247000000002e-6 stddev=0.00132265819469733
[INFO] [stdout] 2026-07-14T04:40:44.224438Z TRACE timesimp: eliminated outliers inliers=[0.003421, 0.00364, 0.00352, 0.003605]
[INFO] [stdout] 2026-07-14T04:40:44.224484Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2026-07-14T04:40:44.446189Z TRACE new{response=Response { client: 2026-07-14T04:40:44.446037685Z, server: 2026-07-14T04:40:49.446046105Z } current=2026-07-14T04:40:44.446049805Z}: timesimp::delta: response processing internals latency=6µs 60ns local_at_midpoint=2026-07-14T04:40:44.446043745Z delta=5s 2µs 360ns
[INFO] [stdout] 2026-07-14T04:40:44.446268Z TRACE timesimp: obtained raw offset from server latency=6.06µs delta=5s 2µs 360ns
[INFO] [stdout] 2026-07-14T04:40:44.446288Z TRACE timesimp: sleeping to spread out requests delay=1.838802737s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:44.600196Z TRACE new{response=Response { client: 2026-07-14T04:40:44.600038881Z, server: 2026-07-14T04:40:44.600048001Z } current=2026-07-14T04:40:44.600051531Z}: timesimp::delta: response processing internals latency=6µs 325ns local_at_midpoint=2026-07-14T04:40:44.600045206Z delta=2µs 795ns
[INFO] [stdout] 2026-07-14T04:40:44.600281Z TRACE timesimp: obtained raw offset from server latency=6.325µs delta=2µs 795ns
[INFO] [stdout] 2026-07-14T04:40:44.600325Z TRACE timesimp: sleeping to spread out requests delay=1.851049614s max_jitter=2s
[INFO] [stdout] 2026-07-14T04:40:46.288037Z TRACE new{response=Response { client: 2026-07-14T04:40:46.287885824Z, server: 2026-07-14T04:40:51.287895244Z } current=2026-07-14T04:40:46.287898434Z}: timesimp::delta: response processing internals latency=6µs 305ns local_at_midpoint=2026-07-14T04:40:46.287892129Z delta=5s 3µs 115ns
[INFO] [stdout] 2026-07-14T04:40:46.288110Z TRACE timesimp: obtained raw offset from server latency=6.305µs delta=5s 3µs 115ns
[INFO] [stdout] 2026-07-14T04:40:46.288134Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00236, 5000.00299, 5000.003115, 5000.00306, 5000.004471]
[INFO] [stdout] 2026-07-14T04:40:46.288150Z TRACE timesimp: statistics about response deltas median=5000.003115 mean=5000.0031991999995 variance=5.979906999384097e-7 stddev=0.0007732985839495696
[INFO] [stdout] 2026-07-14T04:40:46.288198Z TRACE timesimp: eliminated outliers inliers=[5000.00236, 5000.00299, 5000.003115, 5000.00306]
[INFO] [stdout] 2026-07-14T04:40:46.288231Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2026-07-14T04:40:46.454059Z TRACE new{response=Response { client: 2026-07-14T04:40:46.453911388Z, server: 2026-07-14T04:40:46.453920658Z } current=2026-07-14T04:40:46.453924188Z}: timesimp::delta: response processing internals latency=6µs 400ns local_at_midpoint=2026-07-14T04:40:46.453917788Z delta=2µs 870ns
[INFO] [stdout] 2026-07-14T04:40:46.454130Z TRACE timesimp: obtained raw offset from server latency=6.4µs delta=2µs 870ns
[INFO] [stdout] 2026-07-14T04:40:46.454152Z TRACE timesimp: response deltas sorted by latency deltas=[0.000536, 0.002795, 0.00287, 0.00296, 0.00299]
[INFO] [stdout] 2026-07-14T04:40:46.454168Z TRACE timesimp: statistics about response deltas median=0.00287 mean=0.0024301999999999995 variance=1.1271402000000001e-6 stddev=0.0010616685923582746
[INFO] [stdout] 2026-07-14T04:40:46.454185Z TRACE timesimp: eliminated outliers inliers=[0.002795, 0.00287, 0.00296, 0.00299]
[INFO] [stdout] 2026-07-14T04:40:46.454196Z DEBUG timesimp: storing calculated offset offset=2µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.87s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-e945ddf2a2af16be)
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 1.33s; merged doctests compilation took 1.32s
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", kill_on_drop: false }`
[INFO] [stdout] 9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153