[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.97.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-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-tc1/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-2-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 1.97.0-beta.6
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.97.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.97.0-beta.6" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded windows-link v0.1.1
[INFO] [stderr]   Downloaded windows-strings v0.3.1
[INFO] [stderr]   Downloaded windows-registry v0.4.0
[INFO] [stderr]   Downloaded errno v0.3.11
[INFO] [stderr]   Downloaded napi-build v2.1.6
[INFO] [stderr]   Downloaded proc-macro2 v1.0.94
[INFO] [stderr]   Downloaded socket2 v0.5.9
[INFO] [stderr]   Downloaded windows-targets v0.53.0
[INFO] [stderr]   Downloaded windows-result v0.3.2
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded ctor v0.4.2
[INFO] [stderr]   Downloaded ctor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded napi-sys v3.0.0-alpha.1
[INFO] [stderr]   Downloaded dtor v0.0.6
[INFO] [stderr]   Downloaded dtor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded redox_syscall v0.5.11
[INFO] [stderr]   Downloaded rustversion v1.0.20
[INFO] [stderr]   Downloaded semver v1.0.26
[INFO] [stderr]   Downloaded convert_case v0.8.0
[INFO] [stderr]   Downloaded napi-derive v3.0.0-alpha.29
[INFO] [stderr]   Downloaded getrandom v0.3.2
[INFO] [stderr]   Downloaded bitflags v2.9.0
[INFO] [stderr]   Downloaded napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]   Downloaded litemap v0.7.5
[INFO] [stderr]   Downloaded tempfile v3.19.1
[INFO] [stderr]   Downloaded portable-atomic-util v0.2.4
[INFO] [stderr]   Downloaded libloading v0.8.6
[INFO] [stderr]   Downloaded icu_locid_transform_data v1.5.1
[INFO] [stderr]   Downloaded icu_normalizer_data v1.5.1
[INFO] [stderr]   Downloaded r-efi v5.2.0
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded hyper-util v0.1.11
[INFO] [stderr]   Downloaded openssl-sys v0.9.107
[INFO] [stderr]   Downloaded indexmap v2.9.0
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded zerocopy-derive v0.8.24
[INFO] [stderr]   Downloaded cc v1.2.20
[INFO] [stderr]   Downloaded napi v3.0.0-alpha.33
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded portable-atomic v1.11.0
[INFO] [stderr]   Downloaded reqwest v0.12.15
[INFO] [stderr]   Downloaded icu_properties_data v1.5.1
[INFO] [stderr]   Downloaded openssl v0.10.72
[INFO] [stderr]   Downloaded zerocopy v0.8.24
[INFO] [stderr]   Downloaded syn v2.0.100
[INFO] [stderr]   Downloaded rustls v0.23.26
[INFO] [stderr]   Downloaded rustix v1.0.5
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] [stderr]   Downloaded libc v0.2.171
[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-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/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] a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5
[INFO] running `Command { std: "docker" "start" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5", 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" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.0-beta.6" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5", 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" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.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 zerocopy v0.8.24
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling cfg-if v1.0.0
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling pin-project-lite v0.2.16
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling ryu v1.0.20
[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 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 `release` profile [optimized] target(s) in 35.68s
[INFO] running `Command { std: "docker" "inspect" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5", 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" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.0-beta.6" "test" "--frozen" "--no-run" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.100
[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 scopeguard v1.2.0
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling futures-core v0.3.31
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling fnv v1.0.7
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling pin-utils v0.1.0
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling foreign-types-shared v0.1.1
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling foreign-types v0.3.2
[INFO] [stderr]    Compiling utf8_iter v1.0.4
[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 try-lock v0.2.5
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling mime v0.3.17
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling 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 tokio v1.44.2
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[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 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 `release` profile [optimized] target(s) in 1m 27s
[INFO] running `Command { std: "docker" "inspect" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5", 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" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.0-beta.6" "test" "--frozen" "--release", kill_on_drop: false }`
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 0.24s
[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_behind_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/release/deps/client_server-5357a3be2fee2b56)
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2026-08-05T16:31:23.385389Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.385409Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.385422Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.385416Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.385439Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.385445Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.385418Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.385421Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-08-05T16:31:23.385462Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.385466Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.385420Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-08-05T16:31:23.385434Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.385477Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.385482Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.386396Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.386571Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.386550Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.386628Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.386429Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:23.386642Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.389952Z TRACE new{response=Response { client: 2026-08-05T16:31:23.387732743Z, server: 2026-08-05T16:31:23.388841523Z } current=2026-08-05T16:31:23.389924873Z}: timesimp::delta: response processing internals latency=1ms 96µs 65ns local_at_midpoint=2026-08-05T16:31:23.388828808Z delta=12µs 715ns
[INFO] [stdout] 2026-08-05T16:31:23.389974Z TRACE timesimp: obtained raw offset from server latency=1.096065ms delta=12µs 715ns
[INFO] [stdout] 2026-08-05T16:31:23.389982Z DEBUG timesimp: no offset stored, storing initial delta offset=12µs 715ns
[INFO] [stdout] 2026-08-05T16:31:23.389985Z TRACE timesimp: sleeping to spread out requests delay=1.599644544s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.401978Z TRACE new{response=Response { client: 2026-08-05T16:31:23.387743533Z, server: 2026-08-05T16:31:28.394845772Z } current=2026-08-05T16:31:23.401946181Z}: timesimp::delta: response processing internals latency=7ms 101µs 324ns local_at_midpoint=2026-08-05T16:31:23.394844857Z delta=5s 915ns
[INFO] [stdout] 2026-08-05T16:31:23.402008Z TRACE timesimp: obtained raw offset from server latency=7.101324ms delta=5s 915ns
[INFO] [stdout] 2026-08-05T16:31:23.402018Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 915ns
[INFO] [stdout] 2026-08-05T16:31:23.402022Z TRACE timesimp: sleeping to spread out requests delay=276.450383ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.405338Z TRACE new{response=Response { client: 2026-08-05T16:31:23.386542253Z, server: 2026-08-05T16:31:28.394663992Z } current=2026-08-05T16:31:23.405304381Z}: timesimp::delta: response processing internals latency=9ms 381µs 64ns local_at_midpoint=2026-08-05T16:31:23.395923317Z delta=4s 998ms 740µs 675ns
[INFO] [stdout] 2026-08-05T16:31:23.405366Z TRACE timesimp: obtained raw offset from server latency=9.381064ms delta=4s 998ms 740µs 675ns
[INFO] [stdout] 2026-08-05T16:31:23.405375Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 998ms 740µs 675ns
[INFO] [stdout] 2026-08-05T16:31:23.405379Z TRACE timesimp: sleeping to spread out requests delay=1.03757666s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.408783Z TRACE new{response=Response { client: 2026-08-05T16:31:23.386551193Z, server: 2026-08-05T16:31:28.397651562Z } current=2026-08-05T16:31:23.408749551Z}: timesimp::delta: response processing internals latency=11ms 99µs 179ns local_at_midpoint=2026-08-05T16:31:23.397650372Z delta=5s 1µs 190ns
[INFO] [stdout] 2026-08-05T16:31:23.408783Z TRACE new{response=Response { client: 2026-08-05T16:31:23.386573633Z, server: 2026-08-05T16:31:23.397654682Z } current=2026-08-05T16:31:23.408749571Z}: timesimp::delta: response processing internals latency=11ms 87µs 969ns local_at_midpoint=2026-08-05T16:31:23.397661602Z delta=6µs 920ns ago
[INFO] [stdout] 2026-08-05T16:31:23.408854Z TRACE timesimp: obtained raw offset from server latency=11.087969ms delta=6µs 920ns ago
[INFO] [stdout] 2026-08-05T16:31:23.408859Z TRACE timesimp: sleeping to spread out requests delay=1.975667152s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.408783Z TRACE new{response=Response { client: 2026-08-05T16:31:23.386557133Z, server: 2026-08-05T16:31:18.397651772Z } current=2026-08-05T16:31:23.408749611Z}: timesimp::delta: response processing internals latency=11ms 96µs 239ns local_at_midpoint=2026-08-05T16:31:23.397653372Z delta=5s 1µs 600ns ago
[INFO] [stdout] 2026-08-05T16:31:23.408783Z TRACE new{response=Response { client: 2026-08-05T16:31:23.386576773Z, server: 2026-08-05T16:31:28.397670992Z } current=2026-08-05T16:31:23.408762151Z}: timesimp::delta: response processing internals latency=11ms 92µs 689ns local_at_midpoint=2026-08-05T16:31:23.397669462Z delta=5s 1µs 530ns
[INFO] [stdout] 2026-08-05T16:31:23.408914Z TRACE timesimp: obtained raw offset from server latency=11.092689ms delta=5s 1µs 530ns
[INFO] [stdout] 2026-08-05T16:31:23.408783Z TRACE new{response=Response { client: 2026-08-05T16:31:23.386578773Z, server: 2026-08-05T16:31:23.397671312Z } current=2026-08-05T16:31:23.408763141Z}: timesimp::delta: response processing internals latency=11ms 92µs 184ns local_at_midpoint=2026-08-05T16:31:23.397670957Z delta=355ns
[INFO] [stdout] 2026-08-05T16:31:23.408921Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 530ns
[INFO] [stdout] 2026-08-05T16:31:23.408933Z TRACE timesimp: sleeping to spread out requests delay=1.610528397s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.408933Z TRACE timesimp: obtained raw offset from server latency=11.092184ms delta=355ns
[INFO] [stdout] 2026-08-05T16:31:23.408877Z TRACE timesimp: obtained raw offset from server latency=11.096239ms delta=5s 1µs 600ns ago
[INFO] [stdout] 2026-08-05T16:31:23.408940Z TRACE timesimp: sleeping to spread out requests delay=762.957455ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.408946Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 600ns ago
[INFO] [stdout] 2026-08-05T16:31:23.408951Z TRACE timesimp: sleeping to spread out requests delay=1.176727842s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.408839Z TRACE timesimp: obtained raw offset from server latency=11.099179ms delta=5s 1µs 190ns
[INFO] [stdout] 2026-08-05T16:31:23.408963Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 190ns
[INFO] [stdout] 2026-08-05T16:31:23.408967Z TRACE timesimp: sleeping to spread out requests delay=498.709701ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.691745Z TRACE new{response=Response { client: 2026-08-05T16:31:23.680400173Z, server: 2026-08-05T16:31:28.686508553Z } current=2026-08-05T16:31:23.691721842Z}: timesimp::delta: response processing internals latency=5ms 660µs 834ns local_at_midpoint=2026-08-05T16:31:23.686061007Z delta=5s 447µs 546ns
[INFO] [stdout] 2026-08-05T16:31:23.691778Z TRACE timesimp: obtained raw offset from server latency=5.660834ms delta=5s 447µs 546ns
[INFO] [stdout] 2026-08-05T16:31:23.691788Z TRACE timesimp: sleeping to spread out requests delay=666.663444ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.693570Z TRACE new{response=Response { client: 2026-08-05T16:31:23.386562633Z, server: 2026-08-05T16:31:23.593350512Z } current=2026-08-05T16:31:23.693540612Z}: timesimp::delta: response processing internals latency=153ms 488µs 989ns local_at_midpoint=2026-08-05T16:31:23.540051622Z delta=53ms 298µs 890ns
[INFO] [stdout] 2026-08-05T16:31:23.693592Z TRACE timesimp: obtained raw offset from server latency=153.488989ms delta=53ms 298µs 890ns
[INFO] [stdout] 2026-08-05T16:31:23.693600Z DEBUG timesimp: no offset stored, storing initial delta offset=53ms 298µs 890ns
[INFO] [stdout] 2026-08-05T16:31:23.693604Z TRACE timesimp: sleeping to spread out requests delay=885.414758ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:23.943336Z TRACE new{response=Response { client: 2026-08-05T16:31:23.913312Z, server: 2026-08-05T16:31:28.928312818Z } current=2026-08-05T16:31:23.943312917Z}: timesimp::delta: response processing internals latency=15ms 458ns local_at_midpoint=2026-08-05T16:31:23.928312458Z delta=5s 360ns
[INFO] [stdout] 2026-08-05T16:31:23.943377Z TRACE timesimp: obtained raw offset from server latency=15.000458ms delta=5s 360ns
[INFO] [stdout] 2026-08-05T16:31:23.943388Z TRACE timesimp: sleeping to spread out requests delay=1.556714975s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.194639Z TRACE new{response=Response { client: 2026-08-05T16:31:24.172398074Z, server: 2026-08-05T16:31:24.183505463Z } current=2026-08-05T16:31:24.194613892Z}: timesimp::delta: response processing internals latency=11ms 107µs 909ns local_at_midpoint=2026-08-05T16:31:24.183505983Z delta=520ns ago
[INFO] [stdout] 2026-08-05T16:31:24.194670Z TRACE timesimp: obtained raw offset from server latency=11.107909ms delta=520ns ago
[INFO] [stdout] 2026-08-05T16:31:24.194680Z TRACE timesimp: sleeping to spread out requests delay=618.033265ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.373634Z TRACE new{response=Response { client: 2026-08-05T16:31:24.360400465Z, server: 2026-08-05T16:31:29.367506104Z } current=2026-08-05T16:31:24.373612563Z}: timesimp::delta: response processing internals latency=6ms 606µs 49ns local_at_midpoint=2026-08-05T16:31:24.367006514Z delta=5s 499µs 590ns
[INFO] [stdout] 2026-08-05T16:31:24.373666Z TRACE timesimp: obtained raw offset from server latency=6.606049ms delta=5s 499µs 590ns
[INFO] [stdout] 2026-08-05T16:31:24.373676Z TRACE timesimp: sleeping to spread out requests delay=1.213260235s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.459330Z TRACE new{response=Response { client: 2026-08-05T16:31:24.443413916Z, server: 2026-08-05T16:31:29.450522836Z } current=2026-08-05T16:31:24.459309705Z}: timesimp::delta: response processing internals latency=7ms 947µs 894ns local_at_midpoint=2026-08-05T16:31:24.45136181Z delta=4s 999ms 161µs 26ns
[INFO] [stdout] 2026-08-05T16:31:24.459443Z TRACE timesimp: obtained raw offset from server latency=7.947894ms delta=4s 999ms 161µs 26ns
[INFO] [stdout] 2026-08-05T16:31:24.459474Z TRACE timesimp: sleeping to spread out requests delay=1.970999928s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.608734Z TRACE new{response=Response { client: 2026-08-05T16:31:24.586407802Z, server: 2026-08-05T16:31:19.597516481Z } current=2026-08-05T16:31:24.60871275Z}: timesimp::delta: response processing internals latency=11ms 152µs 474ns local_at_midpoint=2026-08-05T16:31:24.597560276Z delta=5s 43µs 795ns ago
[INFO] [stdout] 2026-08-05T16:31:24.608766Z TRACE timesimp: obtained raw offset from server latency=11.152474ms delta=5s 43µs 795ns ago
[INFO] [stdout] 2026-08-05T16:31:24.608776Z TRACE timesimp: sleeping to spread out requests delay=1.930029876s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.782864Z TRACE new{response=Response { client: 2026-08-05T16:31:24.580406023Z, server: 2026-08-05T16:31:24.681639223Z } current=2026-08-05T16:31:24.782842082Z}: timesimp::delta: response processing internals latency=101ms 218µs 29ns local_at_midpoint=2026-08-05T16:31:24.681624052Z delta=15µs 171ns
[INFO] [stdout] 2026-08-05T16:31:24.782903Z TRACE timesimp: obtained raw offset from server latency=101.218029ms delta=15µs 171ns
[INFO] [stdout] 2026-08-05T16:31:24.782912Z TRACE timesimp: sleeping to spread out requests delay=601.914312ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.835653Z TRACE new{response=Response { client: 2026-08-05T16:31:24.813419799Z, server: 2026-08-05T16:31:24.824523738Z } current=2026-08-05T16:31:24.835628107Z}: timesimp::delta: response processing internals latency=11ms 104µs 154ns local_at_midpoint=2026-08-05T16:31:24.824523953Z delta=215ns ago
[INFO] [stdout] 2026-08-05T16:31:24.835686Z TRACE timesimp: obtained raw offset from server latency=11.104154ms delta=215ns ago
[INFO] [stdout] 2026-08-05T16:31:24.835695Z TRACE timesimp: sleeping to spread out requests delay=1.404765706s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.839176Z TRACE new{response=Response { client: 2026-08-05T16:31:23.387752693Z, server: 2026-08-05T16:31:24.11431263Z } current=2026-08-05T16:31:24.839139487Z}: timesimp::delta: response processing internals latency=725ms 693µs 397ns local_at_midpoint=2026-08-05T16:31:24.11344609Z delta=866µs 540ns
[INFO] [stdout] 2026-08-05T16:31:24.839205Z TRACE timesimp: obtained raw offset from server latency=725.693397ms delta=866µs 540ns
[INFO] [stdout] 2026-08-05T16:31:24.839213Z DEBUG timesimp: no offset stored, storing initial delta offset=866µs 540ns
[INFO] [stdout] 2026-08-05T16:31:24.839217Z TRACE timesimp: sleeping to spread out requests delay=687.87312ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:24.993612Z TRACE new{response=Response { client: 2026-08-05T16:31:24.991398871Z, server: 2026-08-05T16:31:24.992494631Z } current=2026-08-05T16:31:24.993586991Z}: timesimp::delta: response processing internals latency=1ms 94µs 60ns local_at_midpoint=2026-08-05T16:31:24.992492931Z delta=1µs 700ns
[INFO] [stdout] 2026-08-05T16:31:24.993645Z TRACE timesimp: obtained raw offset from server latency=1.09406ms delta=1µs 700ns
[INFO] [stdout] 2026-08-05T16:31:24.993655Z TRACE timesimp: sleeping to spread out requests delay=1.097430466s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.045450Z TRACE new{response=Response { client: 2026-08-05T16:31:25.020410768Z, server: 2026-08-05T16:31:30.034316857Z } current=2026-08-05T16:31:25.045427226Z}: timesimp::delta: response processing internals latency=12ms 508µs 229ns local_at_midpoint=2026-08-05T16:31:25.032918997Z delta=5s 1ms 397µs 860ns
[INFO] [stdout] 2026-08-05T16:31:25.045485Z TRACE timesimp: obtained raw offset from server latency=12.508229ms delta=5s 1ms 397µs 860ns
[INFO] [stdout] 2026-08-05T16:31:25.045495Z TRACE timesimp: sleeping to spread out requests delay=579.90787ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.407632Z TRACE new{response=Response { client: 2026-08-05T16:31:25.385397092Z, server: 2026-08-05T16:31:25.39650297Z } current=2026-08-05T16:31:25.407608179Z}: timesimp::delta: response processing internals latency=11ms 105µs 543ns local_at_midpoint=2026-08-05T16:31:25.396502635Z delta=335ns
[INFO] [stdout] 2026-08-05T16:31:25.407663Z TRACE timesimp: obtained raw offset from server latency=11.105543ms delta=335ns
[INFO] [stdout] 2026-08-05T16:31:25.407672Z TRACE timesimp: sleeping to spread out requests delay=256.226038ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.522598Z TRACE new{response=Response { client: 2026-08-05T16:31:25.50039601Z, server: 2026-08-05T16:31:30.511488909Z } current=2026-08-05T16:31:25.522576548Z}: timesimp::delta: response processing internals latency=11ms 90µs 269ns local_at_midpoint=2026-08-05T16:31:25.511486279Z delta=5s 2µs 630ns
[INFO] [stdout] 2026-08-05T16:31:25.522627Z TRACE timesimp: obtained raw offset from server latency=11.090269ms delta=5s 2µs 630ns
[INFO] [stdout] 2026-08-05T16:31:25.522636Z TRACE timesimp: sleeping to spread out requests delay=1.367302049s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.588489Z TRACE new{response=Response { client: 2026-08-05T16:31:25.386393741Z, server: 2026-08-05T16:31:25.488311381Z } current=2026-08-05T16:31:25.588465551Z}: timesimp::delta: response processing internals latency=101ms 35µs 905ns local_at_midpoint=2026-08-05T16:31:25.487429646Z delta=881µs 735ns
[INFO] [stdout] 2026-08-05T16:31:25.588520Z TRACE timesimp: obtained raw offset from server latency=101.035905ms delta=881µs 735ns
[INFO] [stdout] 2026-08-05T16:31:25.588529Z TRACE timesimp: sleeping to spread out requests delay=872.849753ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.607609Z TRACE new{response=Response { client: 2026-08-05T16:31:25.588404631Z, server: 2026-08-05T16:31:30.59849814Z } current=2026-08-05T16:31:25.607587239Z}: timesimp::delta: response processing internals latency=9ms 591µs 304ns local_at_midpoint=2026-08-05T16:31:25.597995935Z delta=5s 502µs 205ns
[INFO] [stdout] 2026-08-05T16:31:25.607643Z TRACE timesimp: obtained raw offset from server latency=9.591304ms delta=5s 502µs 205ns
[INFO] [stdout] 2026-08-05T16:31:25.607653Z TRACE timesimp: sleeping to spread out requests delay=264.470323ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.649445Z TRACE new{response=Response { client: 2026-08-05T16:31:25.627217447Z, server: 2026-08-05T16:31:30.638317646Z } current=2026-08-05T16:31:25.649423595Z}: timesimp::delta: response processing internals latency=11ms 103µs 74ns local_at_midpoint=2026-08-05T16:31:25.638320521Z delta=4s 999ms 997µs 125ns
[INFO] [stdout] 2026-08-05T16:31:25.649476Z TRACE timesimp: obtained raw offset from server latency=11.103074ms delta=4s 999ms 997µs 125ns
[INFO] [stdout] 2026-08-05T16:31:25.649485Z TRACE timesimp: sleeping to spread out requests delay=689.186374ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.687314Z TRACE new{response=Response { client: 2026-08-05T16:31:25.665049273Z, server: 2026-08-05T16:31:25.676162612Z } current=2026-08-05T16:31:25.687289501Z}: timesimp::delta: response processing internals latency=11ms 120µs 114ns local_at_midpoint=2026-08-05T16:31:25.676169387Z delta=6µs 775ns ago
[INFO] [stdout] 2026-08-05T16:31:25.687345Z TRACE timesimp: obtained raw offset from server latency=11.120114ms delta=6µs 775ns ago
[INFO] [stdout] 2026-08-05T16:31:25.687355Z TRACE timesimp: sleeping to spread out requests delay=1.735663803s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:25.889346Z TRACE new{response=Response { client: 2026-08-05T16:31:25.873025092Z, server: 2026-08-05T16:31:30.881136242Z } current=2026-08-05T16:31:25.889322111Z}: timesimp::delta: response processing internals latency=8ms 148µs 509ns local_at_midpoint=2026-08-05T16:31:25.881173601Z delta=4s 999ms 962µs 641ns
[INFO] [stdout] 2026-08-05T16:31:25.889381Z TRACE timesimp: obtained raw offset from server latency=8.148509ms delta=4s 999ms 962µs 641ns
[INFO] [stdout] 2026-08-05T16:31:25.889393Z TRACE timesimp: response deltas sorted by latency deltas=[5000.447546, 5000.49959, 5000.000915, 4999.962641, 5000.502205]
[INFO] [stdout] 2026-08-05T16:31:25.889401Z TRACE timesimp: statistics about response deltas median=5000.000915 mean=5000.2825794 variance=0.07605959945638191 stddev=0.2757890488333101
[INFO] [stdout] 2026-08-05T16:31:25.889407Z TRACE timesimp: eliminated outliers inliers=[5000.000915, 4999.962641]
[INFO] [stdout] 2026-08-05T16:31:25.889411Z DEBUG timesimp: storing calculated offset offset=4s 999ms 981µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2026-08-05T16:31:26.105317Z TRACE new{response=Response { client: 2026-08-05T16:31:26.09631167Z, server: 2026-08-05T16:31:26.102308829Z } current=2026-08-05T16:31:26.105296639Z}: timesimp::delta: response processing internals latency=4ms 492µs 484ns local_at_midpoint=2026-08-05T16:31:26.100804154Z delta=1ms 504µs 675ns
[INFO] [stdout] 2026-08-05T16:31:26.105347Z TRACE timesimp: obtained raw offset from server latency=4.492484ms delta=1ms 504µs 675ns
[INFO] [stdout] 2026-08-05T16:31:26.105355Z TRACE timesimp: sleeping to spread out requests delay=1.528280948s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:26.263647Z TRACE new{response=Response { client: 2026-08-05T16:31:26.241410445Z, server: 2026-08-05T16:31:26.252517054Z } current=2026-08-05T16:31:26.263624943Z}: timesimp::delta: response processing internals latency=11ms 107µs 249ns local_at_midpoint=2026-08-05T16:31:26.252517694Z delta=640ns ago
[INFO] [stdout] 2026-08-05T16:31:26.263680Z TRACE timesimp: obtained raw offset from server latency=11.107249ms delta=640ns ago
[INFO] [stdout] 2026-08-05T16:31:26.263690Z TRACE timesimp: sleeping to spread out requests delay=945.955366ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:26.361559Z TRACE new{response=Response { client: 2026-08-05T16:31:26.339317805Z, server: 2026-08-05T16:31:31.350428954Z } current=2026-08-05T16:31:26.361536713Z}: timesimp::delta: response processing internals latency=11ms 109µs 454ns local_at_midpoint=2026-08-05T16:31:26.350427259Z delta=5s 1µs 695ns
[INFO] [stdout] 2026-08-05T16:31:26.361590Z TRACE timesimp: obtained raw offset from server latency=11.109454ms delta=5s 1µs 695ns
[INFO] [stdout] 2026-08-05T16:31:26.361600Z TRACE timesimp: sleeping to spread out requests delay=1.632582307s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:26.447651Z TRACE new{response=Response { client: 2026-08-05T16:31:26.431416116Z, server: 2026-08-05T16:31:31.439520945Z } current=2026-08-05T16:31:26.447628225Z}: timesimp::delta: response processing internals latency=8ms 106µs 54ns local_at_midpoint=2026-08-05T16:31:26.43952217Z delta=4s 999ms 998µs 775ns
[INFO] [stdout] 2026-08-05T16:31:26.447886Z TRACE timesimp: obtained raw offset from server latency=8.106054ms delta=4s 999ms 998µs 775ns
[INFO] [stdout] 2026-08-05T16:31:26.447952Z TRACE timesimp: sleeping to spread out requests delay=750.171799ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:26.561655Z TRACE new{response=Response { client: 2026-08-05T16:31:26.539401935Z, server: 2026-08-05T16:31:21.550509274Z } current=2026-08-05T16:31:26.561626933Z}: timesimp::delta: response processing internals latency=11ms 112µs 499ns local_at_midpoint=2026-08-05T16:31:26.550514434Z delta=5s 5µs 160ns ago
[INFO] [stdout] 2026-08-05T16:31:26.561689Z TRACE timesimp: obtained raw offset from server latency=11.112499ms delta=5s 5µs 160ns ago
[INFO] [stdout] 2026-08-05T16:31:26.561699Z TRACE timesimp: sleeping to spread out requests delay=1.049761647s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:26.665857Z TRACE new{response=Response { client: 2026-08-05T16:31:26.463395053Z, server: 2026-08-05T16:31:26.564601033Z } current=2026-08-05T16:31:26.665834883Z}: timesimp::delta: response processing internals latency=101ms 219µs 915ns local_at_midpoint=2026-08-05T16:31:26.564614968Z delta=13µs 935ns ago
[INFO] [stdout] 2026-08-05T16:31:26.665889Z TRACE timesimp: obtained raw offset from server latency=101.219915ms delta=13µs 935ns ago
[INFO] [stdout] 2026-08-05T16:31:26.665898Z TRACE timesimp: sleeping to spread out requests delay=1.901718475s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:26.910730Z TRACE new{response=Response { client: 2026-08-05T16:31:26.89041219Z, server: 2026-08-05T16:31:31.900517319Z } current=2026-08-05T16:31:26.910708198Z}: timesimp::delta: response processing internals latency=10ms 148µs 4ns local_at_midpoint=2026-08-05T16:31:26.900560194Z delta=4s 999ms 957µs 125ns
[INFO] [stdout] 2026-08-05T16:31:26.910761Z TRACE timesimp: obtained raw offset from server latency=10.148004ms delta=4s 999ms 957µs 125ns
[INFO] [stdout] 2026-08-05T16:31:26.910770Z TRACE timesimp: sleeping to spread out requests delay=235.323106ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:27.168427Z TRACE new{response=Response { client: 2026-08-05T16:31:27.147105984Z, server: 2026-08-05T16:31:32.158211723Z } current=2026-08-05T16:31:27.168404732Z}: timesimp::delta: response processing internals latency=10ms 649µs 374ns local_at_midpoint=2026-08-05T16:31:27.157755358Z delta=5s 456µs 365ns
[INFO] [stdout] 2026-08-05T16:31:27.168459Z TRACE timesimp: obtained raw offset from server latency=10.649374ms delta=5s 456µs 365ns
[INFO] [stdout] 2026-08-05T16:31:27.168468Z TRACE timesimp: response deltas sorted by latency deltas=[4999.957125, 5000.456365, 5000.00263, 5000.00119, 5000.00036]
[INFO] [stdout] 2026-08-05T16:31:27.168474Z TRACE timesimp: statistics about response deltas median=5000.00263 mean=5000.083533999999 variance=0.043806523917510796 stddev=0.20930008102604927
[INFO] [stdout] 2026-08-05T16:31:27.168483Z TRACE timesimp: eliminated outliers inliers=[4999.957125, 5000.00263, 5000.00119, 5000.00036]
[INFO] [stdout] 2026-08-05T16:31:27.168487Z DEBUG timesimp: storing calculated offset offset=4s 999ms 990µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2026-08-05T16:31:27.211331Z TRACE new{response=Response { client: 2026-08-05T16:31:27.198410389Z, server: 2026-08-05T16:31:32.204516508Z } current=2026-08-05T16:31:27.211303677Z}: timesimp::delta: response processing internals latency=6ms 446µs 644ns local_at_midpoint=2026-08-05T16:31:27.204857033Z delta=4s 999ms 659µs 475ns
[INFO] [stdout] 2026-08-05T16:31:27.211363Z TRACE timesimp: obtained raw offset from server latency=6.446644ms delta=4s 999ms 659µs 475ns
[INFO] [stdout] 2026-08-05T16:31:27.211373Z TRACE timesimp: sleeping to spread out requests delay=1.461616257s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:27.213227Z TRACE new{response=Response { client: 2026-08-05T16:31:25.529312337Z, server: 2026-08-05T16:31:26.371261112Z } current=2026-08-05T16:31:27.213208757Z}: timesimp::delta: response processing internals latency=841ms 948µs 210ns local_at_midpoint=2026-08-05T16:31:26.371260547Z delta=565ns
[INFO] [stdout] 2026-08-05T16:31:27.213252Z TRACE timesimp: obtained raw offset from server latency=841.94821ms delta=565ns
[INFO] [stdout] 2026-08-05T16:31:27.213260Z TRACE timesimp: sleeping to spread out requests delay=1.788941873s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:27.232716Z TRACE new{response=Response { client: 2026-08-05T16:31:27.210397508Z, server: 2026-08-05T16:31:27.221499476Z } current=2026-08-05T16:31:27.232693505Z}: timesimp::delta: response processing internals latency=11ms 147µs 998ns local_at_midpoint=2026-08-05T16:31:27.221545506Z delta=46µs 30ns ago
[INFO] [stdout] 2026-08-05T16:31:27.232747Z TRACE timesimp: obtained raw offset from server latency=11.147998ms delta=46µs 30ns ago
[INFO] [stdout] 2026-08-05T16:31:27.232757Z TRACE timesimp: response deltas sorted by latency deltas=[0.000355, -0.000215, -0.00064, -0.00052, -0.04603]
[INFO] [stdout] 2026-08-05T16:31:27.232763Z TRACE timesimp: statistics about response deltas median=-0.00064 mean=-0.00941 variance=0.0004192181625 stddev=0.020474817764756785
[INFO] [stdout] 2026-08-05T16:31:27.232768Z TRACE timesimp: eliminated outliers inliers=[0.000355, -0.000215, -0.00064, -0.00052]
[INFO] [stdout] 2026-08-05T16:31:27.232773Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2026-08-05T16:31:27.445658Z TRACE new{response=Response { client: 2026-08-05T16:31:27.423420146Z, server: 2026-08-05T16:31:27.434529105Z } current=2026-08-05T16:31:27.445636064Z}: timesimp::delta: response processing internals latency=11ms 107µs 959ns local_at_midpoint=2026-08-05T16:31:27.434528105Z delta=1µs
[INFO] [stdout] 2026-08-05T16:31:27.445691Z TRACE timesimp: obtained raw offset from server latency=11.107959ms delta=1µs
[INFO] [stdout] 2026-08-05T16:31:27.445702Z TRACE timesimp: sleeping to spread out requests delay=172.247701ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:27.634550Z TRACE new{response=Response { client: 2026-08-05T16:31:27.612308827Z, server: 2026-08-05T16:31:22.623416536Z } current=2026-08-05T16:31:27.634527395Z}: timesimp::delta: response processing internals latency=11ms 109µs 284ns local_at_midpoint=2026-08-05T16:31:27.623418111Z delta=5s 1µs 575ns ago
[INFO] [stdout] 2026-08-05T16:31:27.634585Z TRACE timesimp: obtained raw offset from server latency=11.109284ms delta=5s 1µs 575ns ago
[INFO] [stdout] 2026-08-05T16:31:27.634595Z TRACE timesimp: sleeping to spread out requests delay=284.873374ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:27.637741Z TRACE new{response=Response { client: 2026-08-05T16:31:27.635547605Z, server: 2026-08-05T16:31:27.636634135Z } current=2026-08-05T16:31:27.637721694Z}: timesimp::delta: response processing internals latency=1ms 87µs 44ns local_at_midpoint=2026-08-05T16:31:27.636634649Z delta=514ns ago
[INFO] [stdout] 2026-08-05T16:31:27.637769Z TRACE timesimp: obtained raw offset from server latency=1.087044ms delta=514ns ago
[INFO] [stdout] 2026-08-05T16:31:27.637777Z TRACE timesimp: sleeping to spread out requests delay=543.407263ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:27.641327Z TRACE new{response=Response { client: 2026-08-05T16:31:27.619073096Z, server: 2026-08-05T16:31:27.630182015Z } current=2026-08-05T16:31:27.641305244Z}: timesimp::delta: response processing internals latency=11ms 116µs 74ns local_at_midpoint=2026-08-05T16:31:27.63018917Z delta=7µs 155ns ago
[INFO] [stdout] 2026-08-05T16:31:27.641359Z TRACE timesimp: obtained raw offset from server latency=11.116074ms delta=7µs 155ns ago
[INFO] [stdout] 2026-08-05T16:31:27.641369Z TRACE timesimp: response deltas sorted by latency deltas=[-0.00692, 0.000335, 0.001, -0.007155, -0.006775]
[INFO] [stdout] 2026-08-05T16:31:27.641376Z TRACE timesimp: statistics about response deltas median=0.001 mean=-0.0039029999999999994 variance=1.74815575e-5 stddev=0.004181095251246975
[INFO] [stdout] 2026-08-05T16:31:27.641383Z TRACE timesimp: eliminated outliers inliers=[0.000335, 0.001]
[INFO] [stdout] 2026-08-05T16:31:27.641387Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2026-08-05T16:31:27.943327Z TRACE new{response=Response { client: 2026-08-05T16:31:27.920986396Z, server: 2026-08-05T16:31:22.932181445Z } current=2026-08-05T16:31:27.943304494Z}: timesimp::delta: response processing internals latency=11ms 159µs 49ns local_at_midpoint=2026-08-05T16:31:27.932145445Z delta=4s 999ms 964µs ago
[INFO] [stdout] 2026-08-05T16:31:27.943358Z TRACE timesimp: obtained raw offset from server latency=11.159049ms delta=4s 999ms 964µs ago
[INFO] [stdout] 2026-08-05T16:31:27.943368Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.0016, -5000.001575, -5000.00516, -5000.043795, -4999.964]
[INFO] [stdout] 2026-08-05T16:31:27.943375Z TRACE timesimp: statistics about response deltas median=-5000.00516 mean=-5000.003225999999 variance=0.0007984082174926929 stddev=0.02825611823114939
[INFO] [stdout] 2026-08-05T16:31:27.943380Z TRACE timesimp: eliminated outliers inliers=[-5000.0016, -5000.001575, -5000.00516]
[INFO] [stdout] 2026-08-05T16:31:27.943384Z DEBUG timesimp: storing calculated offset offset=5s 2µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2026-08-05T16:31:28.017192Z TRACE new{response=Response { client: 2026-08-05T16:31:27.994951138Z, server: 2026-08-05T16:31:33.006060327Z } current=2026-08-05T16:31:28.017168046Z}: timesimp::delta: response processing internals latency=11ms 108µs 454ns local_at_midpoint=2026-08-05T16:31:28.006059592Z delta=5s 735ns
[INFO] [stdout] 2026-08-05T16:31:28.017225Z TRACE timesimp: obtained raw offset from server latency=11.108454ms delta=5s 735ns
[INFO] [stdout] 2026-08-05T16:31:28.017236Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00153, 4999.997125, 5000.000735, 5000.001695, 5001.39786]
[INFO] [stdout] 2026-08-05T16:31:28.017243Z TRACE timesimp: statistics about response deltas median=5000.000735 mean=5000.279789 variance=0.39065429419266495 stddev=0.6250234349147757
[INFO] [stdout] 2026-08-05T16:31:28.017249Z TRACE timesimp: eliminated outliers inliers=[5000.00153, 4999.997125, 5000.000735, 5000.001695]
[INFO] [stdout] 2026-08-05T16:31:28.017253Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2026-08-05T16:31:28.184619Z TRACE new{response=Response { client: 2026-08-05T16:31:28.18241646Z, server: 2026-08-05T16:31:28.183508619Z } current=2026-08-05T16:31:28.18459835Z}: timesimp::delta: response processing internals latency=1ms 90µs 945ns local_at_midpoint=2026-08-05T16:31:28.183507405Z delta=1µs 214ns
[INFO] [stdout] 2026-08-05T16:31:28.184649Z TRACE timesimp: obtained raw offset from server latency=1.090945ms delta=1µs 214ns
[INFO] [stdout] 2026-08-05T16:31:28.184658Z TRACE timesimp: response deltas sorted by latency deltas=[-0.000514, 0.001214, 0.0017, 0.012715, 1.504675]
[INFO] [stdout] 2026-08-05T16:31:28.184665Z TRACE timesimp: statistics about response deltas median=0.0017 mean=0.303958 variance=0.4505652065055 stddev=0.6712415411053609
[INFO] [stdout] 2026-08-05T16:31:28.184671Z TRACE timesimp: eliminated outliers inliers=[-0.000514, 0.001214, 0.0017, 0.012715]
[INFO] [stdout] 2026-08-05T16:31:28.184675Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2026-08-05T16:31:28.685649Z TRACE new{response=Response { client: 2026-08-05T16:31:28.67341152Z, server: 2026-08-05T16:31:33.679516189Z } current=2026-08-05T16:31:28.685628289Z}: timesimp::delta: response processing internals latency=6ms 108µs 384ns local_at_midpoint=2026-08-05T16:31:28.679519904Z delta=4s 999ms 996µs 285ns
[INFO] [stdout] 2026-08-05T16:31:28.685681Z TRACE timesimp: obtained raw offset from server latency=6.108384ms delta=4s 999ms 996µs 285ns
[INFO] [stdout] 2026-08-05T16:31:28.685691Z TRACE timesimp: response deltas sorted by latency deltas=[4999.996285, 4999.659475, 4999.161026, 4999.998775, 4998.740675]
[INFO] [stdout] 2026-08-05T16:31:28.685698Z TRACE timesimp: statistics about response deltas median=4999.161026 mean=4999.511247200001 variance=0.30283822705931274 stddev=0.5503073932442782
[INFO] [stdout] 2026-08-05T16:31:28.685704Z TRACE timesimp: eliminated outliers inliers=[4999.659475, 4999.161026, 4998.740675]
[INFO] [stdout] 2026-08-05T16:31:28.685708Z DEBUG timesimp: storing calculated offset offset=4s 999ms 187µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2026-08-05T16:31:28.771894Z TRACE new{response=Response { client: 2026-08-05T16:31:28.569421901Z, server: 2026-08-05T16:31:28.670638701Z } current=2026-08-05T16:31:28.77187019Z}: timesimp::delta: response processing internals latency=101ms 224µs 144ns local_at_midpoint=2026-08-05T16:31:28.670646045Z delta=7µs 344ns ago
[INFO] [stdout] 2026-08-05T16:31:28.771934Z TRACE timesimp: obtained raw offset from server latency=101.224144ms delta=7µs 344ns ago
[INFO] [stdout] 2026-08-05T16:31:28.771944Z TRACE timesimp: response deltas sorted by latency deltas=[0.881735, 0.015171, -0.013935, -0.007344, 53.29889]
[INFO] [stdout] 2026-08-05T16:31:28.771952Z TRACE timesimp: statistics about response deltas median=-0.013935 mean=10.8349034 variance=563.6434879208673 stddev=23.74117705424201
[INFO] [stdout] 2026-08-05T16:31:28.771957Z TRACE timesimp: eliminated outliers inliers=[0.881735, 0.015171, -0.013935, -0.007344]
[INFO] [stdout] 2026-08-05T16:31:28.771962Z DEBUG timesimp: storing calculated offset offset=218µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2026-08-05T16:31:30.539188Z TRACE new{response=Response { client: 2026-08-05T16:31:29.003404127Z, server: 2026-08-05T16:31:29.77129383Z } current=2026-08-05T16:31:30.539166802Z}: timesimp::delta: response processing internals latency=767ms 881µs 337ns local_at_midpoint=2026-08-05T16:31:29.771285464Z delta=8µs 366ns
[INFO] [stdout] 2026-08-05T16:31:30.539218Z TRACE timesimp: obtained raw offset from server latency=767.881337ms delta=8µs 366ns
[INFO] [stdout] 2026-08-05T16:31:30.539228Z TRACE timesimp: sleeping to spread out requests delay=1.792833818s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:33.857313Z TRACE new{response=Response { client: 2026-08-05T16:31:32.333162711Z, server: 2026-08-05T16:31:33.095407604Z } current=2026-08-05T16:31:33.857291078Z}: timesimp::delta: response processing internals latency=762ms 64µs 183ns local_at_midpoint=2026-08-05T16:31:33.095226894Z delta=180µs 710ns
[INFO] [stdout] 2026-08-05T16:31:33.857343Z TRACE timesimp: obtained raw offset from server latency=762.064183ms delta=180µs 710ns
[INFO] [stdout] 2026-08-05T16:31:33.857353Z TRACE timesimp: sleeping to spread out requests delay=624.189114ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.328422Z TRACE new{response=Response { client: 2026-08-05T16:31:34.483131505Z, server: 2026-08-05T16:31:35.405406992Z } current=2026-08-05T16:31:36.328402169Z}: timesimp::delta: response processing internals latency=922ms 635µs 332ns local_at_midpoint=2026-08-05T16:31:35.405766837Z delta=359µs 845ns ago
[INFO] [stdout] 2026-08-05T16:31:36.328452Z TRACE timesimp: obtained raw offset from server latency=922.635332ms delta=359µs 845ns ago
[INFO] [stdout] 2026-08-05T16:31:36.328461Z TRACE timesimp: response deltas sorted by latency deltas=[0.86654, 0.18071, 0.008366, 0.000565, -0.359845]
[INFO] [stdout] 2026-08-05T16:31:36.328469Z TRACE timesimp: statistics about response deltas median=0.008366 mean=0.1392672 variance=0.2040324109817 stddev=0.45169946976025993
[INFO] [stdout] 2026-08-05T16:31:36.328475Z TRACE timesimp: eliminated outliers inliers=[0.18071, 0.008366, 0.000565, -0.359845]
[INFO] [stdout] 2026-08-05T16:31:36.328479Z DEBUG timesimp: storing calculated offset offset=42µs ago
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.94s
[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:31:36.331932Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-08-05T16:31:36.331953Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:36.331985Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.331937Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-08-05T16:31:36.332006Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.331937Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-08-05T16:31:36.332021Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.331965Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.333150Z TRACE new{response=Response { client: 2026-08-05T16:31:36.333114828Z, server: 2026-08-05T16:31:36.333114978Z } current=2026-08-05T16:31:36.333115108Z}: timesimp::delta: response processing internals latency=140ns local_at_midpoint=2026-08-05T16:31:36.333114968Z delta=10ns
[INFO] [stdout] 2026-08-05T16:31:36.333179Z TRACE timesimp: obtained raw offset from server latency=140ns delta=10ns
[INFO] [stdout] 2026-08-05T16:31:36.333150Z TRACE new{response=Response { client: 2026-08-05T16:31:36.333132598Z, server: 2026-08-05T16:31:41.333132748Z } current=2026-08-05T16:31:36.333132898Z}: timesimp::delta: response processing internals latency=150ns local_at_midpoint=2026-08-05T16:31:36.333132748Z delta=5s
[INFO] [stdout] 2026-08-05T16:31:36.333187Z DEBUG timesimp: no offset stored, storing initial delta offset=10ns
[INFO] [stdout] 2026-08-05T16:31:36.333191Z TRACE timesimp: sleeping to spread out requests delay=455.581289ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.333200Z TRACE timesimp: obtained raw offset from server latency=150ns delta=5s
[INFO] [stdout] 2026-08-05T16:31:36.333206Z TRACE timesimp: sleeping to spread out requests delay=12.293536ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.333149Z TRACE new{response=Response { client: 2026-08-05T16:31:36.333114688Z, server: 2026-08-05T16:31:36.333114848Z } current=2026-08-05T16:31:36.333115048Z}: timesimp::delta: response processing internals latency=180ns local_at_midpoint=2026-08-05T16:31:36.333114868Z delta=20ns ago
[INFO] [stdout] 2026-08-05T16:31:36.333232Z TRACE timesimp: obtained raw offset from server latency=180ns delta=20ns ago
[INFO] [stdout] 2026-08-05T16:31:36.333154Z TRACE new{response=Response { client: 2026-08-05T16:31:36.333135808Z, server: 2026-08-05T16:31:31.333135968Z } current=2026-08-05T16:31:36.333136088Z}: timesimp::delta: response processing internals latency=140ns local_at_midpoint=2026-08-05T16:31:36.333135948Z delta=4s 999ms 999µs 980ns ago
[INFO] [stdout] 2026-08-05T16:31:36.333259Z TRACE timesimp: obtained raw offset from server latency=140ns delta=4s 999ms 999µs 980ns ago
[INFO] [stdout] 2026-08-05T16:31:36.333297Z TRACE timesimp: sleeping to spread out requests delay=785.525671ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.333239Z TRACE timesimp: sleeping to spread out requests delay=676.229354ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.346340Z TRACE new{response=Response { client: 2026-08-05T16:31:36.346317757Z, server: 2026-08-05T16:31:41.346318117Z } current=2026-08-05T16:31:36.346318287Z}: timesimp::delta: response processing internals latency=265ns local_at_midpoint=2026-08-05T16:31:36.346318022Z delta=5s 95ns
[INFO] [stdout] 2026-08-05T16:31:36.346372Z TRACE timesimp: obtained raw offset from server latency=265ns delta=5s 95ns
[INFO] [stdout] 2026-08-05T16:31:36.346380Z TRACE timesimp: sleeping to spread out requests delay=988.180658ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:36.789437Z TRACE new{response=Response { client: 2026-08-05T16:31:36.789414962Z, server: 2026-08-05T16:31:36.789415432Z } current=2026-08-05T16:31:36.789415502Z}: timesimp::delta: response processing internals latency=270ns local_at_midpoint=2026-08-05T16:31:36.789415232Z delta=200ns
[INFO] [stdout] 2026-08-05T16:31:36.789467Z TRACE timesimp: obtained raw offset from server latency=270ns delta=200ns
[INFO] [stdout] 2026-08-05T16:31:36.789476Z TRACE timesimp: sleeping to spread out requests delay=668.810725ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:37.010123Z TRACE new{response=Response { client: 2026-08-05T16:31:37.01009953Z, server: 2026-08-05T16:31:37.0101001Z } current=2026-08-05T16:31:37.01010029Z}: timesimp::delta: response processing internals latency=380ns local_at_midpoint=2026-08-05T16:31:37.01009991Z delta=190ns
[INFO] [stdout] 2026-08-05T16:31:37.010157Z TRACE timesimp: obtained raw offset from server latency=380ns delta=190ns
[INFO] [stdout] 2026-08-05T16:31:37.010166Z TRACE timesimp: sleeping to spread out requests delay=1.66797551s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:37.119245Z TRACE new{response=Response { client: 2026-08-05T16:31:37.119223239Z, server: 2026-08-05T16:31:32.119223629Z } current=2026-08-05T16:31:37.119223839Z}: timesimp::delta: response processing internals latency=300ns local_at_midpoint=2026-08-05T16:31:37.119223539Z delta=4s 999ms 999µs 910ns ago
[INFO] [stdout] 2026-08-05T16:31:37.119365Z TRACE timesimp: obtained raw offset from server latency=300ns delta=4s 999ms 999µs 910ns ago
[INFO] [stdout] 2026-08-05T16:31:37.119406Z TRACE timesimp: sleeping to spread out requests delay=404.707266ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:37.335435Z TRACE new{response=Response { client: 2026-08-05T16:31:37.335413727Z, server: 2026-08-05T16:31:42.335414147Z } current=2026-08-05T16:31:37.335414327Z}: timesimp::delta: response processing internals latency=300ns local_at_midpoint=2026-08-05T16:31:37.335414027Z delta=5s 120ns
[INFO] [stdout] 2026-08-05T16:31:37.335462Z TRACE timesimp: obtained raw offset from server latency=300ns delta=5s 120ns
[INFO] [stdout] 2026-08-05T16:31:37.335469Z TRACE timesimp: sleeping to spread out requests delay=856.799102ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:37.459308Z TRACE new{response=Response { client: 2026-08-05T16:31:37.459286555Z, server: 2026-08-05T16:31:37.459286945Z } current=2026-08-05T16:31:37.459287105Z}: timesimp::delta: response processing internals latency=275ns local_at_midpoint=2026-08-05T16:31:37.45928683Z delta=115ns
[INFO] [stdout] 2026-08-05T16:31:37.459342Z TRACE timesimp: obtained raw offset from server latency=275ns delta=115ns
[INFO] [stdout] 2026-08-05T16:31:37.459351Z TRACE timesimp: sleeping to spread out requests delay=1.017559018s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:37.527335Z TRACE new{response=Response { client: 2026-08-05T16:31:37.527313408Z, server: 2026-08-05T16:31:32.527313738Z } current=2026-08-05T16:31:37.527313878Z}: timesimp::delta: response processing internals latency=235ns local_at_midpoint=2026-08-05T16:31:37.527313643Z delta=4s 999ms 999µs 905ns ago
[INFO] [stdout] 2026-08-05T16:31:37.527447Z TRACE timesimp: obtained raw offset from server latency=235ns delta=4s 999ms 999µs 905ns ago
[INFO] [stdout] 2026-08-05T16:31:37.527480Z TRACE timesimp: sleeping to spread out requests delay=454.472503ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:37.984331Z TRACE new{response=Response { client: 2026-08-05T16:31:37.984309342Z, server: 2026-08-05T16:31:32.984309752Z } current=2026-08-05T16:31:37.984309942Z}: timesimp::delta: response processing internals latency=300ns local_at_midpoint=2026-08-05T16:31:37.984309642Z delta=4s 999ms 999µs 890ns ago
[INFO] [stdout] 2026-08-05T16:31:37.984438Z TRACE timesimp: obtained raw offset from server latency=300ns delta=4s 999ms 999µs 890ns ago
[INFO] [stdout] 2026-08-05T16:31:37.984470Z TRACE timesimp: sleeping to spread out requests delay=892.284203ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:38.193430Z TRACE new{response=Response { client: 2026-08-05T16:31:38.193408581Z, server: 2026-08-05T16:31:43.193408951Z } current=2026-08-05T16:31:38.193409101Z}: timesimp::delta: response processing internals latency=260ns local_at_midpoint=2026-08-05T16:31:38.193408841Z delta=5s 110ns
[INFO] [stdout] 2026-08-05T16:31:38.193456Z TRACE timesimp: obtained raw offset from server latency=260ns delta=5s 110ns
[INFO] [stdout] 2026-08-05T16:31:38.193465Z TRACE timesimp: sleeping to spread out requests delay=803.527121ms max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:38.479336Z TRACE new{response=Response { client: 2026-08-05T16:31:38.479313952Z, server: 2026-08-05T16:31:38.479314282Z } current=2026-08-05T16:31:38.479314482Z}: timesimp::delta: response processing internals latency=265ns local_at_midpoint=2026-08-05T16:31:38.479314217Z delta=65ns
[INFO] [stdout] 2026-08-05T16:31:38.479369Z TRACE timesimp: obtained raw offset from server latency=265ns delta=65ns
[INFO] [stdout] 2026-08-05T16:31:38.479378Z TRACE timesimp: sleeping to spread out requests delay=1.857963438s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:38.679445Z TRACE new{response=Response { client: 2026-08-05T16:31:38.679424272Z, server: 2026-08-05T16:31:38.679424692Z } current=2026-08-05T16:31:38.679424782Z}: timesimp::delta: response processing internals latency=255ns local_at_midpoint=2026-08-05T16:31:38.679424527Z delta=165ns
[INFO] [stdout] 2026-08-05T16:31:38.679477Z TRACE timesimp: obtained raw offset from server latency=255ns delta=165ns
[INFO] [stdout] 2026-08-05T16:31:38.679486Z TRACE timesimp: sleeping to spread out requests delay=1.843131457s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:38.877435Z TRACE new{response=Response { client: 2026-08-05T16:31:38.877412692Z, server: 2026-08-05T16:31:33.877413122Z } current=2026-08-05T16:31:38.877413372Z}: timesimp::delta: response processing internals latency=340ns local_at_midpoint=2026-08-05T16:31:38.877413032Z delta=4s 999ms 999µs 910ns ago
[INFO] [stdout] 2026-08-05T16:31:38.877538Z TRACE timesimp: obtained raw offset from server latency=340ns delta=4s 999ms 999µs 910ns ago
[INFO] [stdout] 2026-08-05T16:31:38.877573Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.9999800000005, -4999.999905, -4999.99991, -4999.99989, -4999.99991]
[INFO] [stdout] 2026-08-05T16:31:38.877607Z TRACE timesimp: statistics about response deltas median=-4999.99991 mean=-4999.999919 variance=1.230000012888486e-9 stddev=3.5071356017246984e-5
[INFO] [stdout] 2026-08-05T16:31:38.877634Z TRACE timesimp: eliminated outliers inliers=[-4999.999905, -4999.99991, -4999.99989, -4999.99991]
[INFO] [stdout] 2026-08-05T16:31:38.877662Z DEBUG timesimp: storing calculated offset offset=4s 999ms 999µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2026-08-05T16:31:38.999332Z TRACE new{response=Response { client: 2026-08-05T16:31:38.99931078Z, server: 2026-08-05T16:31:43.999311249Z } current=2026-08-05T16:31:38.999311329Z}: timesimp::delta: response processing internals latency=274ns local_at_midpoint=2026-08-05T16:31:38.999311054Z delta=5s 195ns
[INFO] [stdout] 2026-08-05T16:31:38.999362Z TRACE timesimp: obtained raw offset from server latency=274ns delta=5s 195ns
[INFO] [stdout] 2026-08-05T16:31:38.999377Z TRACE timesimp: response deltas sorted by latency deltas=[5000.0, 5000.00011, 5000.000095, 5000.000195, 5000.00012]
[INFO] [stdout] 2026-08-05T16:31:38.999384Z TRACE timesimp: statistics about response deltas median=5000.000095 mean=5000.000104000001 variance=4.867499978718406e-9 stddev=6.976747077770848e-5
[INFO] [stdout] 2026-08-05T16:31:38.999389Z TRACE timesimp: eliminated outliers inliers=[5000.00011, 5000.000095, 5000.00012]
[INFO] [stdout] 2026-08-05T16:31:38.999393Z DEBUG timesimp: storing calculated offset offset=5s
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2026-08-05T16:31:40.338433Z TRACE new{response=Response { client: 2026-08-05T16:31:40.338411254Z, server: 2026-08-05T16:31:40.338411715Z } current=2026-08-05T16:31:40.338411785Z}: timesimp::delta: response processing internals latency=265ns local_at_midpoint=2026-08-05T16:31:40.338411519Z delta=196ns
[INFO] [stdout] 2026-08-05T16:31:40.338466Z TRACE timesimp: obtained raw offset from server latency=265ns delta=196ns
[INFO] [stdout] 2026-08-05T16:31:40.338474Z TRACE timesimp: response deltas sorted by latency deltas=[1e-5, 6.5e-5, 0.000196, 0.0002, 0.000115]
[INFO] [stdout] 2026-08-05T16:31:40.338482Z TRACE timesimp: statistics about response deltas median=0.000196 mean=0.00011719999999999999 variance=6.821700000000001e-9 stddev=8.259358328587034e-5
[INFO] [stdout] 2026-08-05T16:31:40.338489Z TRACE timesimp: eliminated outliers inliers=[0.000196, 0.0002, 0.000115]
[INFO] [stdout] 2026-08-05T16:31:40.338493Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2026-08-05T16:31:40.523517Z TRACE new{response=Response { client: 2026-08-05T16:31:40.523495006Z, server: 2026-08-05T16:31:40.523495446Z } current=2026-08-05T16:31:40.523495606Z}: timesimp::delta: response processing internals latency=300ns local_at_midpoint=2026-08-05T16:31:40.523495306Z delta=140ns
[INFO] [stdout] 2026-08-05T16:31:40.523547Z TRACE timesimp: obtained raw offset from server latency=300ns delta=140ns
[INFO] [stdout] 2026-08-05T16:31:40.523555Z TRACE timesimp: sleeping to spread out requests delay=1.858024312s max_jitter=2s
[INFO] [stdout] 2026-08-05T16:31:42.382439Z TRACE new{response=Response { client: 2026-08-05T16:31:42.382417459Z, server: 2026-08-05T16:31:42.382417859Z } current=2026-08-05T16:31:42.382418039Z}: timesimp::delta: response processing internals latency=290ns local_at_midpoint=2026-08-05T16:31:42.382417749Z delta=110ns
[INFO] [stdout] 2026-08-05T16:31:42.382473Z TRACE timesimp: obtained raw offset from server latency=290ns delta=110ns
[INFO] [stdout] 2026-08-05T16:31:42.382482Z TRACE timesimp: response deltas sorted by latency deltas=[-2e-5, 0.000165, 0.00011, 0.00014, 0.00019]
[INFO] [stdout] 2026-08-05T16:31:42.382490Z TRACE timesimp: statistics about response deltas median=0.00011 mean=0.000117 variance=6.745e-9 stddev=8.212794895770867e-5
[INFO] [stdout] 2026-08-05T16:31:42.382496Z TRACE timesimp: eliminated outliers inliers=[0.000165, 0.00011, 0.00014, 0.00019]
[INFO] [stdout] 2026-08-05T16:31:42.382500Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 6.05s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/deps/timesimp_nodejs-05c3196012939a7f)
[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.06s; merged doctests compilation took 1.04s
[INFO] running `Command { std: "docker" "inspect" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5", kill_on_drop: false }`
[INFO] [stdout] a910ab053dab69b3f5b0835fe6aca81b701b2bb6e5ad4406220a5dcf1775f5a5