[INFO] cloning repository https://github.com/passcod/timesimp
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/passcod/timesimp" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 92be20531742c87fc283ec0ed2fc2aa3b1f638ae
[INFO] testing passcod/timesimp against try#dec9417b8611e34e787a3e4c37686b5131f9e5c5 for pr-154210
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-2-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-tc2/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-2-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain dec9417b8611e34e787a3e4c37686b5131f9e5c5
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "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" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 6658817c7a8bcd453896e0969ee8605f80e2669653bd9841a7f081fa4577d5cb
[INFO] running `Command { std: "docker" "start" "-a" "6658817c7a8bcd453896e0969ee8605f80e2669653bd9841a7f081fa4577d5cb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "6658817c7a8bcd453896e0969ee8605f80e2669653bd9841a7f081fa4577d5cb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "6658817c7a8bcd453896e0969ee8605f80e2669653bd9841a7f081fa4577d5cb", kill_on_drop: false }`
[INFO] [stdout] 6658817c7a8bcd453896e0969ee8605f80e2669653bd9841a7f081fa4577d5cb
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] aaa6028c338bb2facf72917bca921fb165f2d8f8d7f6a305f87f3bef79d46ac7
[INFO] running `Command { std: "docker" "start" "-a" "aaa6028c338bb2facf72917bca921fb165f2d8f8d7f6a305f87f3bef79d46ac7", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling dtor v0.0.6
[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 quote v1.0.40
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling jiff v0.2.10
[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 33.07s
[INFO] running `Command { std: "docker" "inspect" "aaa6028c338bb2facf72917bca921fb165f2d8f8d7f6a305f87f3bef79d46ac7", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "aaa6028c338bb2facf72917bca921fb165f2d8f8d7f6a305f87f3bef79d46ac7", kill_on_drop: false }`
[INFO] [stdout] aaa6028c338bb2facf72917bca921fb165f2d8f8d7f6a305f87f3bef79d46ac7
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 6f41b948095ef011a2171740283b5cb7ddaa18bd8f109570bdb0c1e875bae1d9
[INFO] running `Command { std: "docker" "start" "-a" "6f41b948095ef011a2171740283b5cb7ddaa18bd8f109570bdb0c1e875bae1d9", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling rand v0.9.1
[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 zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[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 icu_normalizer v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 00s
[INFO] running `Command { std: "docker" "inspect" "6f41b948095ef011a2171740283b5cb7ddaa18bd8f109570bdb0c1e875bae1d9", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "6f41b948095ef011a2171740283b5cb7ddaa18bd8f109570bdb0c1e875bae1d9", kill_on_drop: false }`
[INFO] [stdout] 6f41b948095ef011a2171740283b5cb7ddaa18bd8f109570bdb0c1e875bae1d9
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] f4287048afe1cc1b07987a1797755e19cb9569ae948da97331b7dc7d173bd4b0
[INFO] running `Command { std: "docker" "start" "-a" "f4287048afe1cc1b07987a1797755e19cb9569ae948da97331b7dc7d173bd4b0", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.23s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-072512e717c3300a)
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... 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_response ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-142087cb4dabe45d)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2026-03-31T11:54:13.841442Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-03-31T11:54:13.841526Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.841729Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:13.841732Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-03-31T11:54:13.841753Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.841752Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.841927Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:13.841958Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.842226Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:13.842268Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:13.842298Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.842307Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.843412Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:13.843526Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.846395Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:13.846432Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.848776Z TRACE new{response=Response { client: 2026-03-31T11:54:13.846402397Z, server: 2026-03-31T11:54:13.847514717Z } current=2026-03-31T11:54:13.848624707Z}: timesimp::delta: response processing internals latency=1ms 111µs 155ns local_at_midpoint=2026-03-31T11:54:13.847513552Z delta=1µs 165ns
[INFO] [stdout] 2026-03-31T11:54:13.848853Z TRACE timesimp: obtained raw offset from server latency=1.111155ms delta=1µs 165ns
[INFO] [stdout] 2026-03-31T11:54:13.848879Z DEBUG timesimp: no offset stored, storing initial delta offset=1µs 165ns
[INFO] [stdout] 2026-03-31T11:54:13.848899Z TRACE timesimp: sleeping to spread out requests delay=1.71239571s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.864739Z TRACE new{response=Response { client: 2026-03-31T11:54:13.846320457Z, server: 2026-03-31T11:54:18.855443667Z } current=2026-03-31T11:54:13.864566747Z}: timesimp::delta: response processing internals latency=9ms 123µs 145ns local_at_midpoint=2026-03-31T11:54:13.855443602Z delta=5s 65ns
[INFO] [stdout] 2026-03-31T11:54:13.864830Z TRACE timesimp: obtained raw offset from server latency=9.123145ms delta=5s 65ns
[INFO] [stdout] 2026-03-31T11:54:13.864852Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 65ns
[INFO] [stdout] 2026-03-31T11:54:13.864864Z TRACE timesimp: sleeping to spread out requests delay=1.182702227s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.865838Z TRACE new{response=Response { client: 2026-03-31T11:54:13.843447587Z, server: 2026-03-31T11:54:13.854610477Z } current=2026-03-31T11:54:13.865740007Z}: timesimp::delta: response processing internals latency=11ms 146µs 210ns local_at_midpoint=2026-03-31T11:54:13.854593797Z delta=16µs 680ns
[INFO] [stdout] 2026-03-31T11:54:13.867063Z TRACE new{response=Response { client: 2026-03-31T11:54:13.843751987Z, server: 2026-03-31T11:54:08.854865307Z } current=2026-03-31T11:54:13.866973527Z}: timesimp::delta: response processing internals latency=11ms 610µs 770ns local_at_midpoint=2026-03-31T11:54:13.855362757Z delta=5s 497µs 450ns ago
[INFO] [stdout] 2026-03-31T11:54:13.868249Z TRACE timesimp: obtained raw offset from server latency=11.14621ms delta=16µs 680ns
[INFO] [stdout] 2026-03-31T11:54:13.868695Z TRACE timesimp: sleeping to spread out requests delay=1.372164295s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.869051Z TRACE timesimp: obtained raw offset from server latency=11.61077ms delta=5s 497µs 450ns ago
[INFO] [stdout] 2026-03-31T11:54:13.869390Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 497µs 450ns ago
[INFO] [stdout] 2026-03-31T11:54:13.869724Z TRACE timesimp: sleeping to spread out requests delay=255.194254ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.870511Z TRACE new{response=Response { client: 2026-03-31T11:54:13.846476687Z, server: 2026-03-31T11:54:13.859277517Z } current=2026-03-31T11:54:13.870393507Z}: timesimp::delta: response processing internals latency=11ms 958µs 410ns local_at_midpoint=2026-03-31T11:54:13.858435097Z delta=842µs 420ns
[INFO] [stdout] 2026-03-31T11:54:13.870574Z TRACE timesimp: obtained raw offset from server latency=11.95841ms delta=842µs 420ns
[INFO] [stdout] 2026-03-31T11:54:13.870593Z TRACE timesimp: sleeping to spread out requests delay=690.550827ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.875136Z TRACE new{response=Response { client: 2026-03-31T11:54:13.857327087Z, server: 2026-03-31T11:54:18.864464277Z } current=2026-03-31T11:54:13.874985817Z}: timesimp::delta: response processing internals latency=8ms 829µs 365ns local_at_midpoint=2026-03-31T11:54:13.866156452Z delta=4s 998ms 307µs 825ns
[INFO] [stdout] 2026-03-31T11:54:13.875209Z TRACE timesimp: obtained raw offset from server latency=8.829365ms delta=4s 998ms 307µs 825ns
[INFO] [stdout] 2026-03-31T11:54:13.875248Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 998ms 307µs 825ns
[INFO] [stdout] 2026-03-31T11:54:13.875264Z TRACE timesimp: sleeping to spread out requests delay=1.407947019s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:13.879571Z TRACE new{response=Response { client: 2026-03-31T11:54:13.848313577Z, server: 2026-03-31T11:54:18.868290367Z } current=2026-03-31T11:54:13.879424627Z}: timesimp::delta: response processing internals latency=15ms 555µs 525ns local_at_midpoint=2026-03-31T11:54:13.863869102Z delta=5s 4ms 421µs 265ns
[INFO] [stdout] 2026-03-31T11:54:13.879645Z TRACE timesimp: obtained raw offset from server latency=15.555525ms delta=5s 4ms 421µs 265ns
[INFO] [stdout] 2026-03-31T11:54:13.879665Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 4ms 421µs 265ns
[INFO] [stdout] 2026-03-31T11:54:13.879684Z TRACE timesimp: sleeping to spread out requests delay=1.637827198s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:14.148956Z TRACE new{response=Response { client: 2026-03-31T11:54:14.126454355Z, server: 2026-03-31T11:54:09.137626425Z } current=2026-03-31T11:54:14.148802904Z}: timesimp::delta: response processing internals latency=11ms 174µs 274ns local_at_midpoint=2026-03-31T11:54:14.137628629Z delta=5s 2µs 204ns ago
[INFO] [stdout] 2026-03-31T11:54:14.149042Z TRACE timesimp: obtained raw offset from server latency=11.174274ms delta=5s 2µs 204ns ago
[INFO] [stdout] 2026-03-31T11:54:14.149064Z TRACE timesimp: sleeping to spread out requests delay=61.813407ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:14.235937Z TRACE new{response=Response { client: 2026-03-31T11:54:14.213321514Z, server: 2026-03-31T11:54:09.224501954Z } current=2026-03-31T11:54:14.235777404Z}: timesimp::delta: response processing internals latency=11ms 227µs 945ns local_at_midpoint=2026-03-31T11:54:14.224549459Z delta=5s 47µs 505ns ago
[INFO] [stdout] 2026-03-31T11:54:14.236029Z TRACE timesimp: obtained raw offset from server latency=11.227945ms delta=5s 47µs 505ns ago
[INFO] [stdout] 2026-03-31T11:54:14.236052Z TRACE timesimp: sleeping to spread out requests delay=1.007972381s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:14.591638Z TRACE new{response=Response { client: 2026-03-31T11:54:14.566323061Z, server: 2026-03-31T11:54:14.580313331Z } current=2026-03-31T11:54:14.591484251Z}: timesimp::delta: response processing internals latency=12ms 580µs 595ns local_at_midpoint=2026-03-31T11:54:14.578903656Z delta=1ms 409µs 675ns
[INFO] [stdout] 2026-03-31T11:54:14.591718Z TRACE timesimp: obtained raw offset from server latency=12.580595ms delta=1ms 409µs 675ns
[INFO] [stdout] 2026-03-31T11:54:14.591739Z TRACE timesimp: sleeping to spread out requests delay=1.280331706s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.062489Z TRACE new{response=Response { client: 2026-03-31T11:54:15.048452707Z, server: 2026-03-31T11:54:20.055632817Z } current=2026-03-31T11:54:15.062339457Z}: timesimp::delta: response processing internals latency=6ms 943µs 375ns local_at_midpoint=2026-03-31T11:54:15.055396082Z delta=5s 236µs 735ns
[INFO] [stdout] 2026-03-31T11:54:15.062580Z TRACE timesimp: obtained raw offset from server latency=6.943375ms delta=5s 236µs 735ns
[INFO] [stdout] 2026-03-31T11:54:15.062600Z TRACE timesimp: sleeping to spread out requests delay=1.332840075s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.264601Z TRACE new{response=Response { client: 2026-03-31T11:54:15.242467395Z, server: 2026-03-31T11:54:15.253270875Z } current=2026-03-31T11:54:15.264436355Z}: timesimp::delta: response processing internals latency=10ms 984µs 480ns local_at_midpoint=2026-03-31T11:54:15.253451875Z delta=181µs ago
[INFO] [stdout] 2026-03-31T11:54:15.264687Z TRACE timesimp: obtained raw offset from server latency=10.98448ms delta=181µs ago
[INFO] [stdout] 2026-03-31T11:54:15.264707Z TRACE timesimp: sleeping to spread out requests delay=1.081433048s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.267485Z TRACE new{response=Response { client: 2026-03-31T11:54:15.244451006Z, server: 2026-03-31T11:54:10.256270015Z } current=2026-03-31T11:54:15.267398995Z}: timesimp::delta: response processing internals latency=11ms 473µs 994ns local_at_midpoint=2026-03-31T11:54:15.255925Z delta=4s 999ms 654µs 985ns ago
[INFO] [stdout] 2026-03-31T11:54:15.267562Z TRACE timesimp: obtained raw offset from server latency=11.473994ms delta=4s 999ms 654µs 985ns ago
[INFO] [stdout] 2026-03-31T11:54:15.267583Z TRACE timesimp: sleeping to spread out requests delay=990.943552ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.306402Z TRACE new{response=Response { client: 2026-03-31T11:54:15.285799935Z, server: 2026-03-31T11:54:20.295976445Z } current=2026-03-31T11:54:15.306247315Z}: timesimp::delta: response processing internals latency=10ms 223µs 690ns local_at_midpoint=2026-03-31T11:54:15.296023625Z delta=4s 999ms 952µs 820ns
[INFO] [stdout] 2026-03-31T11:54:15.306485Z TRACE timesimp: obtained raw offset from server latency=10.22369ms delta=4s 999ms 952µs 820ns
[INFO] [stdout] 2026-03-31T11:54:15.306515Z TRACE timesimp: sleeping to spread out requests delay=58.833316ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.387461Z TRACE new{response=Response { client: 2026-03-31T11:54:15.366923974Z, server: 2026-03-31T11:54:20.376094804Z } current=2026-03-31T11:54:15.387302654Z}: timesimp::delta: response processing internals latency=10ms 189µs 340ns local_at_midpoint=2026-03-31T11:54:15.377113314Z delta=4s 998ms 981µs 490ns
[INFO] [stdout] 2026-03-31T11:54:15.387551Z TRACE timesimp: obtained raw offset from server latency=10.18934ms delta=4s 998ms 981µs 490ns
[INFO] [stdout] 2026-03-31T11:54:15.387720Z TRACE timesimp: sleeping to spread out requests delay=1.413642532s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.539946Z TRACE new{response=Response { client: 2026-03-31T11:54:15.519420223Z, server: 2026-03-31T11:54:20.529607403Z } current=2026-03-31T11:54:15.539788903Z}: timesimp::delta: response processing internals latency=10ms 184µs 340ns local_at_midpoint=2026-03-31T11:54:15.529604563Z delta=5s 2µs 840ns
[INFO] [stdout] 2026-03-31T11:54:15.540036Z TRACE timesimp: obtained raw offset from server latency=10.18434ms delta=5s 2µs 840ns
[INFO] [stdout] 2026-03-31T11:54:15.540059Z TRACE timesimp: sleeping to spread out requests delay=663.448354ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.568725Z TRACE new{response=Response { client: 2026-03-31T11:54:15.566330423Z, server: 2026-03-31T11:54:15.567463013Z } current=2026-03-31T11:54:15.568576413Z}: timesimp::delta: response processing internals latency=1ms 122µs 995ns local_at_midpoint=2026-03-31T11:54:15.567453418Z delta=9µs 595ns
[INFO] [stdout] 2026-03-31T11:54:15.568814Z TRACE timesimp: obtained raw offset from server latency=1.122995ms delta=9µs 595ns
[INFO] [stdout] 2026-03-31T11:54:15.568836Z TRACE timesimp: sleeping to spread out requests delay=1.879269177s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.721652Z TRACE new{response=Response { client: 2026-03-31T11:54:13.843677817Z, server: 2026-03-31T11:54:14.782447229Z } current=2026-03-31T11:54:15.721452261Z}: timesimp::delta: response processing internals latency=938ms 887µs 222ns local_at_midpoint=2026-03-31T11:54:14.782565039Z delta=117µs 810ns ago
[INFO] [stdout] 2026-03-31T11:54:15.721741Z TRACE timesimp: obtained raw offset from server latency=938.887222ms delta=117µs 810ns ago
[INFO] [stdout] 2026-03-31T11:54:15.721761Z DEBUG timesimp: no offset stored, storing initial delta offset=117µs 810ns ago
[INFO] [stdout] 2026-03-31T11:54:15.721774Z TRACE timesimp: sleeping to spread out requests delay=1.694107234s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:15.895128Z TRACE new{response=Response { client: 2026-03-31T11:54:15.87244982Z, server: 2026-03-31T11:54:15.88362289Z } current=2026-03-31T11:54:15.89496995Z}: timesimp::delta: response processing internals latency=11ms 260µs 65ns local_at_midpoint=2026-03-31T11:54:15.883709885Z delta=86µs 995ns ago
[INFO] [stdout] 2026-03-31T11:54:15.895295Z TRACE timesimp: obtained raw offset from server latency=11.260065ms delta=86µs 995ns ago
[INFO] [stdout] 2026-03-31T11:54:15.895378Z TRACE timesimp: sleeping to spread out requests delay=1.755843129s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.226037Z TRACE new{response=Response { client: 2026-03-31T11:54:16.205459967Z, server: 2026-03-31T11:54:21.215710047Z } current=2026-03-31T11:54:16.225877747Z}: timesimp::delta: response processing internals latency=10ms 208µs 890ns local_at_midpoint=2026-03-31T11:54:16.215668857Z delta=5s 41µs 190ns
[INFO] [stdout] 2026-03-31T11:54:16.226116Z TRACE timesimp: obtained raw offset from server latency=10.20889ms delta=5s 41µs 190ns
[INFO] [stdout] 2026-03-31T11:54:16.226137Z TRACE timesimp: sleeping to spread out requests delay=1.187500884s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.282816Z TRACE new{response=Response { client: 2026-03-31T11:54:16.259442027Z, server: 2026-03-31T11:54:11.270621067Z } current=2026-03-31T11:54:16.282650577Z}: timesimp::delta: response processing internals latency=11ms 604µs 275ns local_at_midpoint=2026-03-31T11:54:16.271046302Z delta=5s 425µs 235ns ago
[INFO] [stdout] 2026-03-31T11:54:16.282908Z TRACE timesimp: obtained raw offset from server latency=11.604275ms delta=5s 425µs 235ns ago
[INFO] [stdout] 2026-03-31T11:54:16.282940Z TRACE timesimp: response deltas sorted by latency deltas=[-5000.002204, -5000.047505, -4999.654985, -5000.425235, -5000.49745]
[INFO] [stdout] 2026-03-31T11:54:16.282964Z TRACE timesimp: statistics about response deltas median=-4999.654985 mean=-5000.1254758 variance=0.11771433966559347 stddev=0.34309523410504184
[INFO] [stdout] 2026-03-31T11:54:16.282983Z TRACE timesimp: eliminated outliers inliers=[-4999.654985]
[INFO] [stdout] 2026-03-31T11:54:16.282995Z DEBUG timesimp: storing calculated offset offset=4s 999ms 654µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2026-03-31T11:54:16.283408Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:16.283433Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.307139Z TRACE new{response=Response { client: 2026-03-31T11:54:16.284612707Z, server: 2026-03-31T11:54:21.295772257Z } current=2026-03-31T11:54:16.306947766Z}: timesimp::delta: response processing internals latency=11ms 167µs 529ns local_at_midpoint=2026-03-31T11:54:16.295780236Z delta=4s 999ms 992µs 21ns
[INFO] [stdout] 2026-03-31T11:54:16.307296Z TRACE timesimp: obtained raw offset from server latency=11.167529ms delta=4s 999ms 992µs 21ns
[INFO] [stdout] 2026-03-31T11:54:16.307344Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 992µs 21ns
[INFO] [stdout] 2026-03-31T11:54:16.307410Z TRACE timesimp: sleeping to spread out requests delay=311.424698ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.369974Z TRACE new{response=Response { client: 2026-03-31T11:54:16.347458836Z, server: 2026-03-31T11:54:16.358637466Z } current=2026-03-31T11:54:16.369817096Z}: timesimp::delta: response processing internals latency=11ms 179µs 130ns local_at_midpoint=2026-03-31T11:54:16.358637966Z delta=500ns ago
[INFO] [stdout] 2026-03-31T11:54:16.370062Z TRACE timesimp: obtained raw offset from server latency=11.17913ms delta=500ns ago
[INFO] [stdout] 2026-03-31T11:54:16.370085Z TRACE timesimp: sleeping to spread out requests delay=249.286496ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.412125Z TRACE new{response=Response { client: 2026-03-31T11:54:16.396525916Z, server: 2026-03-31T11:54:21.403805556Z } current=2026-03-31T11:54:16.411971425Z}: timesimp::delta: response processing internals latency=7ms 722µs 754ns local_at_midpoint=2026-03-31T11:54:16.40424867Z delta=4s 999ms 556µs 886ns
[INFO] [stdout] 2026-03-31T11:54:16.412285Z TRACE timesimp: obtained raw offset from server latency=7.722754ms delta=4s 999ms 556µs 886ns
[INFO] [stdout] 2026-03-31T11:54:16.412359Z TRACE timesimp: sleeping to spread out requests delay=1.284893761s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.642527Z TRACE new{response=Response { client: 2026-03-31T11:54:16.620040024Z, server: 2026-03-31T11:54:21.631205204Z } current=2026-03-31T11:54:16.642374404Z}: timesimp::delta: response processing internals latency=11ms 167µs 190ns local_at_midpoint=2026-03-31T11:54:16.631207214Z delta=4s 999ms 997µs 990ns
[INFO] [stdout] 2026-03-31T11:54:16.642623Z TRACE timesimp: obtained raw offset from server latency=11.16719ms delta=4s 999ms 997µs 990ns
[INFO] [stdout] 2026-03-31T11:54:16.642644Z TRACE timesimp: sleeping to spread out requests delay=1.972497992s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.644479Z TRACE new{response=Response { client: 2026-03-31T11:54:16.620411524Z, server: 2026-03-31T11:54:16.633279204Z } current=2026-03-31T11:54:16.644395394Z}: timesimp::delta: response processing internals latency=11ms 991µs 935ns local_at_midpoint=2026-03-31T11:54:16.632403459Z delta=875µs 745ns
[INFO] [stdout] 2026-03-31T11:54:16.644549Z TRACE timesimp: obtained raw offset from server latency=11.991935ms delta=875µs 745ns
[INFO] [stdout] 2026-03-31T11:54:16.644569Z TRACE timesimp: sleeping to spread out requests delay=178.743594ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.820709Z TRACE new{response=Response { client: 2026-03-31T11:54:16.803433692Z, server: 2026-03-31T11:54:21.811600902Z } current=2026-03-31T11:54:16.820549982Z}: timesimp::delta: response processing internals latency=8ms 558µs 145ns local_at_midpoint=2026-03-31T11:54:16.811991837Z delta=4s 999ms 609µs 65ns
[INFO] [stdout] 2026-03-31T11:54:16.820801Z TRACE timesimp: obtained raw offset from server latency=8.558145ms delta=4s 999ms 609µs 65ns
[INFO] [stdout] 2026-03-31T11:54:16.820822Z TRACE timesimp: sleeping to spread out requests delay=249.212835ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:16.848658Z TRACE new{response=Response { client: 2026-03-31T11:54:16.823938142Z, server: 2026-03-31T11:54:16.837317122Z } current=2026-03-31T11:54:16.848492232Z}: timesimp::delta: response processing internals latency=12ms 277µs 45ns local_at_midpoint=2026-03-31T11:54:16.836215187Z delta=1ms 101µs 935ns
[INFO] [stdout] 2026-03-31T11:54:16.848814Z TRACE timesimp: obtained raw offset from server latency=12.277045ms delta=1ms 101µs 935ns
[INFO] [stdout] 2026-03-31T11:54:16.848884Z TRACE timesimp: response deltas sorted by latency deltas=[-0.181, 0.01668, -0.0005, 0.875745, 1.101935]
[INFO] [stdout] 2026-03-31T11:54:16.848940Z TRACE timesimp: statistics about response deltas median=-0.0005 mean=0.362572 variance=0.33923431143249994 stddev=0.5824382468833069
[INFO] [stdout] 2026-03-31T11:54:16.848983Z TRACE timesimp: eliminated outliers inliers=[-0.181, 0.01668, -0.0005]
[INFO] [stdout] 2026-03-31T11:54:16.849050Z DEBUG timesimp: storing calculated offset offset=54µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2026-03-31T11:54:16.849571Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:16.849607Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:17.053613Z TRACE new{response=Response { client: 2026-03-31T11:54:16.850787722Z, server: 2026-03-31T11:54:16.952094211Z } current=2026-03-31T11:54:17.05345029Z}: timesimp::delta: response processing internals latency=101ms 331µs 284ns local_at_midpoint=2026-03-31T11:54:16.952119006Z delta=24µs 795ns ago
[INFO] [stdout] 2026-03-31T11:54:17.053700Z TRACE timesimp: obtained raw offset from server latency=101.331284ms delta=24µs 795ns ago
[INFO] [stdout] 2026-03-31T11:54:17.053721Z DEBUG timesimp: no offset stored, storing initial delta offset=24µs 795ns ago
[INFO] [stdout] 2026-03-31T11:54:17.053733Z TRACE timesimp: sleeping to spread out requests delay=768.413456ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:17.083880Z TRACE new{response=Response { client: 2026-03-31T11:54:17.07132167Z, server: 2026-03-31T11:54:22.07747965Z } current=2026-03-31T11:54:17.08371406Z}: timesimp::delta: response processing internals latency=6ms 196µs 195ns local_at_midpoint=2026-03-31T11:54:17.077517865Z delta=4s 999ms 961µs 785ns
[INFO] [stdout] 2026-03-31T11:54:17.083965Z TRACE timesimp: obtained raw offset from server latency=6.196195ms delta=4s 999ms 961µs 785ns
[INFO] [stdout] 2026-03-31T11:54:17.083993Z TRACE timesimp: response deltas sorted by latency deltas=[4999.9617849999995, 4999.609065, 4998.307825, 4998.98149, 4999.95282]
[INFO] [stdout] 2026-03-31T11:54:17.084013Z TRACE timesimp: statistics about response deltas median=4998.307825 mean=4999.362596999999 variance=0.5064806103824833 stddev=0.7116745115447674
[INFO] [stdout] 2026-03-31T11:54:17.084068Z TRACE timesimp: eliminated outliers inliers=[4998.307825, 4998.98149]
[INFO] [stdout] 2026-03-31T11:54:17.084090Z DEBUG timesimp: storing calculated offset offset=4s 998ms 644µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2026-03-31T11:54:17.438470Z TRACE new{response=Response { client: 2026-03-31T11:54:17.415476977Z, server: 2026-03-31T11:54:22.425646387Z } current=2026-03-31T11:54:17.438318077Z}: timesimp::delta: response processing internals latency=11ms 420µs 550ns local_at_midpoint=2026-03-31T11:54:17.426897527Z delta=4s 998ms 748µs 860ns
[INFO] [stdout] 2026-03-31T11:54:17.438566Z TRACE timesimp: obtained raw offset from server latency=11.42055ms delta=4s 998ms 748µs 860ns
[INFO] [stdout] 2026-03-31T11:54:17.438591Z TRACE timesimp: sleeping to spread out requests delay=1.684809688s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:17.450867Z TRACE new{response=Response { client: 2026-03-31T11:54:17.448444427Z, server: 2026-03-31T11:54:17.449584447Z } current=2026-03-31T11:54:17.450710657Z}: timesimp::delta: response processing internals latency=1ms 133µs 115ns local_at_midpoint=2026-03-31T11:54:17.449577542Z delta=6µs 905ns
[INFO] [stdout] 2026-03-31T11:54:17.450956Z TRACE timesimp: obtained raw offset from server latency=1.133115ms delta=6µs 905ns
[INFO] [stdout] 2026-03-31T11:54:17.450977Z TRACE timesimp: sleeping to spread out requests delay=1.636038201s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:17.676833Z TRACE new{response=Response { client: 2026-03-31T11:54:17.654322505Z, server: 2026-03-31T11:54:17.665498135Z } current=2026-03-31T11:54:17.676669255Z}: timesimp::delta: response processing internals latency=11ms 173µs 375ns local_at_midpoint=2026-03-31T11:54:17.66549588Z delta=2µs 255ns
[INFO] [stdout] 2026-03-31T11:54:17.676914Z TRACE timesimp: obtained raw offset from server latency=11.173375ms delta=2µs 255ns
[INFO] [stdout] 2026-03-31T11:54:17.676935Z TRACE timesimp: sleeping to spread out requests delay=322.192252ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:17.717940Z TRACE new{response=Response { client: 2026-03-31T11:54:17.698435845Z, server: 2026-03-31T11:54:22.707615445Z } current=2026-03-31T11:54:17.717793014Z}: timesimp::delta: response processing internals latency=9ms 678µs 584ns local_at_midpoint=2026-03-31T11:54:17.708114429Z delta=4s 999ms 501µs 16ns
[INFO] [stdout] 2026-03-31T11:54:17.718015Z TRACE timesimp: obtained raw offset from server latency=9.678584ms delta=4s 999ms 501µs 16ns
[INFO] [stdout] 2026-03-31T11:54:17.718034Z TRACE timesimp: sleeping to spread out requests delay=1.583097942s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:18.024815Z TRACE new{response=Response { client: 2026-03-31T11:54:18.002307042Z, server: 2026-03-31T11:54:18.013480212Z } current=2026-03-31T11:54:18.024655732Z}: timesimp::delta: response processing internals latency=11ms 174µs 345ns local_at_midpoint=2026-03-31T11:54:18.013481387Z delta=1µs 175ns ago
[INFO] [stdout] 2026-03-31T11:54:18.024894Z TRACE timesimp: obtained raw offset from server latency=11.174345ms delta=1µs 175ns ago
[INFO] [stdout] 2026-03-31T11:54:18.024919Z TRACE timesimp: response deltas sorted by latency deltas=[0.002255, -0.001175, -0.086995, 0.84242, 1.409675]
[INFO] [stdout] 2026-03-31T11:54:18.024937Z TRACE timesimp: statistics about response deltas median=-0.086995 mean=0.43323599999999995 variance=0.441490624805 stddev=0.6644476087736338
[INFO] [stdout] 2026-03-31T11:54:18.024956Z TRACE timesimp: eliminated outliers inliers=[0.002255, -0.001175, -0.086995]
[INFO] [stdout] 2026-03-31T11:54:18.024974Z DEBUG timesimp: storing calculated offset offset=28µs ago
[INFO] [stdout] 2026-03-31T11:54:18.025164Z TRACE new{response=Response { client: 2026-03-31T11:54:17.823462024Z, server: 2026-03-31T11:54:17.923775403Z } current=2026-03-31T11:54:18.025085102Z}: timesimp::delta: response processing internals latency=100ms 811µs 539ns local_at_midpoint=2026-03-31T11:54:17.924273563Z delta=498µs 160ns ago
[INFO] [stdout] 2026-03-31T11:54:18.025226Z TRACE timesimp: obtained raw offset from server latency=100.811539ms delta=498µs 160ns ago
[INFO] [stdout] 2026-03-31T11:54:18.025270Z TRACE timesimp: sleeping to spread out requests delay=697.573267ms max_jitter=2s
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2026-03-31T11:54:18.640473Z TRACE new{response=Response { client: 2026-03-31T11:54:18.616447367Z, server: 2026-03-31T11:54:23.627618197Z } current=2026-03-31T11:54:18.640315517Z}: timesimp::delta: response processing internals latency=11ms 934µs 75ns local_at_midpoint=2026-03-31T11:54:18.628381442Z delta=4s 999ms 236µs 755ns
[INFO] [stdout] 2026-03-31T11:54:18.640552Z TRACE timesimp: obtained raw offset from server latency=11.934075ms delta=4s 999ms 236µs 755ns
[INFO] [stdout] 2026-03-31T11:54:18.640571Z TRACE timesimp: sleeping to spread out requests delay=929.881707ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:18.933152Z TRACE new{response=Response { client: 2026-03-31T11:54:18.730326596Z, server: 2026-03-31T11:54:18.831647195Z } current=2026-03-31T11:54:18.932985494Z}: timesimp::delta: response processing internals latency=101ms 329µs 449ns local_at_midpoint=2026-03-31T11:54:18.831656045Z delta=8µs 850ns ago
[INFO] [stdout] 2026-03-31T11:54:18.933260Z TRACE timesimp: obtained raw offset from server latency=101.329449ms delta=8µs 850ns ago
[INFO] [stdout] 2026-03-31T11:54:18.933283Z TRACE timesimp: sleeping to spread out requests delay=723.419742ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:19.089888Z TRACE new{response=Response { client: 2026-03-31T11:54:19.087464963Z, server: 2026-03-31T11:54:19.088603923Z } current=2026-03-31T11:54:19.089729833Z}: timesimp::delta: response processing internals latency=1ms 132µs 435ns local_at_midpoint=2026-03-31T11:54:19.088597398Z delta=6µs 525ns
[INFO] [stdout] 2026-03-31T11:54:19.089982Z TRACE timesimp: obtained raw offset from server latency=1.132435ms delta=6µs 525ns
[INFO] [stdout] 2026-03-31T11:54:19.090003Z TRACE timesimp: sleeping to spread out requests delay=1.723213951s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:19.147849Z TRACE new{response=Response { client: 2026-03-31T11:54:19.127319863Z, server: 2026-03-31T11:54:24.137499862Z } current=2026-03-31T11:54:19.147682793Z}: timesimp::delta: response processing internals latency=10ms 181µs 465ns local_at_midpoint=2026-03-31T11:54:19.137501328Z delta=4s 999ms 998µs 534ns
[INFO] [stdout] 2026-03-31T11:54:19.147935Z TRACE timesimp: obtained raw offset from server latency=10.181465ms delta=4s 999ms 998µs 534ns
[INFO] [stdout] 2026-03-31T11:54:19.147962Z TRACE timesimp: response deltas sorted by latency deltas=[4999.998534, 5000.00284, 5000.04119, 4998.74886, 5004.421265]
[INFO] [stdout] 2026-03-31T11:54:19.147981Z TRACE timesimp: statistics about response deltas median=5000.04119 mean=5000.6425378 variance=4.7625920521342895 stddev=2.182336374653158
[INFO] [stdout] 2026-03-31T11:54:19.148000Z TRACE timesimp: eliminated outliers inliers=[4999.998534, 5000.00284, 5000.04119, 4998.74886]
[INFO] [stdout] 2026-03-31T11:54:19.148012Z DEBUG timesimp: storing calculated offset offset=4s 999ms 697µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2026-03-31T11:54:19.168708Z TRACE new{response=Response { client: 2026-03-31T11:54:17.417458407Z, server: 2026-03-31T11:54:18.29288804Z } current=2026-03-31T11:54:19.168555652Z}: timesimp::delta: response processing internals latency=875ms 548µs 622ns local_at_midpoint=2026-03-31T11:54:18.293007029Z delta=118µs 989ns ago
[INFO] [stdout] 2026-03-31T11:54:19.168784Z TRACE timesimp: obtained raw offset from server latency=875.548622ms delta=118µs 989ns ago
[INFO] [stdout] 2026-03-31T11:54:19.168812Z TRACE timesimp: sleeping to spread out requests delay=127.81387ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:19.312632Z TRACE new{response=Response { client: 2026-03-31T11:54:19.302379831Z, server: 2026-03-31T11:54:24.308304981Z } current=2026-03-31T11:54:19.312452931Z}: timesimp::delta: response processing internals latency=5ms 36µs 550ns local_at_midpoint=2026-03-31T11:54:19.307416381Z delta=5s 888µs 600ns
[INFO] [stdout] 2026-03-31T11:54:19.312802Z TRACE timesimp: obtained raw offset from server latency=5.03655ms delta=5s 888µs 600ns
[INFO] [stdout] 2026-03-31T11:54:19.312877Z TRACE timesimp: response deltas sorted by latency deltas=[5000.8886, 5000.236735, 4999.556886, 5000.000065, 4999.501016]
[INFO] [stdout] 2026-03-31T11:54:19.312942Z TRACE timesimp: statistics about response deltas median=4999.556886 mean=5000.036660400001 variance=0.3210671372653163 stddev=0.5666278648860434
[INFO] [stdout] 2026-03-31T11:54:19.312990Z TRACE timesimp: eliminated outliers inliers=[4999.556886, 5000.000065, 4999.501016]
[INFO] [stdout] 2026-03-31T11:54:19.313021Z DEBUG timesimp: storing calculated offset offset=4s 999ms 685µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2026-03-31T11:54:19.594946Z TRACE new{response=Response { client: 2026-03-31T11:54:19.572443339Z, server: 2026-03-31T11:54:24.583615799Z } current=2026-03-31T11:54:19.594797329Z}: timesimp::delta: response processing internals latency=11ms 176µs 995ns local_at_midpoint=2026-03-31T11:54:19.583620334Z delta=4s 999ms 995µs 465ns
[INFO] [stdout] 2026-03-31T11:54:19.595020Z TRACE timesimp: obtained raw offset from server latency=11.176995ms delta=4s 999ms 995µs 465ns
[INFO] [stdout] 2026-03-31T11:54:19.595038Z TRACE timesimp: sleeping to spread out requests delay=124.191179ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:19.742948Z TRACE new{response=Response { client: 2026-03-31T11:54:19.720392298Z, server: 2026-03-31T11:54:24.731535017Z } current=2026-03-31T11:54:19.742799957Z}: timesimp::delta: response processing internals latency=11ms 203µs 829ns local_at_midpoint=2026-03-31T11:54:19.731596127Z delta=4s 999ms 938µs 890ns
[INFO] [stdout] 2026-03-31T11:54:19.743116Z TRACE timesimp: obtained raw offset from server latency=11.203829ms delta=4s 999ms 938µs 890ns
[INFO] [stdout] 2026-03-31T11:54:19.743211Z TRACE timesimp: response deltas sorted by latency deltas=[4999.99799, 4999.992021, 4999.995465, 4999.93889, 4999.236755]
[INFO] [stdout] 2026-03-31T11:54:19.743303Z TRACE timesimp: statistics about response deltas median=4999.995465 mean=4999.8322241999995 variance=0.11140550939073422 stddev=0.3337746386272244
[INFO] [stdout] 2026-03-31T11:54:19.743375Z TRACE timesimp: eliminated outliers inliers=[4999.99799, 4999.992021, 4999.995465, 4999.93889]
[INFO] [stdout] 2026-03-31T11:54:19.743443Z DEBUG timesimp: storing calculated offset offset=4s 999ms 981µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2026-03-31T11:54:19.861055Z TRACE new{response=Response { client: 2026-03-31T11:54:19.658227378Z, server: 2026-03-31T11:54:19.759574817Z } current=2026-03-31T11:54:19.860899976Z}: timesimp::delta: response processing internals latency=101ms 336µs 299ns local_at_midpoint=2026-03-31T11:54:19.759563677Z delta=11µs 140ns
[INFO] [stdout] 2026-03-31T11:54:19.861139Z TRACE timesimp: obtained raw offset from server latency=101.336299ms delta=11µs 140ns
[INFO] [stdout] 2026-03-31T11:54:19.861161Z TRACE timesimp: sleeping to spread out requests delay=1.306577635s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:20.816903Z TRACE new{response=Response { client: 2026-03-31T11:54:20.814480459Z, server: 2026-03-31T11:54:20.815621288Z } current=2026-03-31T11:54:20.816746559Z}: timesimp::delta: response processing internals latency=1ms 133µs 50ns local_at_midpoint=2026-03-31T11:54:20.815613509Z delta=7µs 779ns
[INFO] [stdout] 2026-03-31T11:54:20.816987Z TRACE timesimp: obtained raw offset from server latency=1.13305ms delta=7µs 779ns
[INFO] [stdout] 2026-03-31T11:54:20.817013Z TRACE timesimp: response deltas sorted by latency deltas=[0.001165, 0.009595, 0.006525, 0.007779, 0.006905]
[INFO] [stdout] 2026-03-31T11:54:20.817030Z TRACE timesimp: statistics about response deltas median=0.006525 mean=0.0063938 variance=9.946337199999998e-6 stddev=0.0031537814128439526
[INFO] [stdout] 2026-03-31T11:54:20.817049Z TRACE timesimp: eliminated outliers inliers=[0.009595, 0.006525, 0.007779, 0.006905]
[INFO] [stdout] 2026-03-31T11:54:20.817061Z DEBUG timesimp: storing calculated offset offset=7µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2026-03-31T11:54:21.260613Z TRACE new{response=Response { client: 2026-03-31T11:54:19.297199781Z, server: 2026-03-31T11:54:20.279319443Z } current=2026-03-31T11:54:21.260452445Z}: timesimp::delta: response processing internals latency=981ms 626µs 332ns local_at_midpoint=2026-03-31T11:54:20.278826113Z delta=493µs 330ns
[INFO] [stdout] 2026-03-31T11:54:21.260695Z TRACE timesimp: obtained raw offset from server latency=981.626332ms delta=493µs 330ns
[INFO] [stdout] 2026-03-31T11:54:21.260715Z TRACE timesimp: sleeping to spread out requests delay=835.519363ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:21.371549Z TRACE new{response=Response { client: 2026-03-31T11:54:21.168732916Z, server: 2026-03-31T11:54:21.270051565Z } current=2026-03-31T11:54:21.371380914Z}: timesimp::delta: response processing internals latency=101ms 323µs 999ns local_at_midpoint=2026-03-31T11:54:21.270056915Z delta=5µs 350ns ago
[INFO] [stdout] 2026-03-31T11:54:21.371634Z TRACE timesimp: obtained raw offset from server latency=101.323999ms delta=5µs 350ns ago
[INFO] [stdout] 2026-03-31T11:54:21.371662Z TRACE timesimp: response deltas sorted by latency deltas=[-0.49816, -0.00535, -0.00885, -0.024795, 0.01114]
[INFO] [stdout] 2026-03-31T11:54:21.371683Z TRACE timesimp: statistics about response deltas median=-0.00885 mean=-0.105203 variance=0.048417716545 stddev=0.22004026119099204
[INFO] [stdout] 2026-03-31T11:54:21.371705Z TRACE timesimp: eliminated outliers inliers=[-0.00535, -0.00885, -0.024795, 0.01114]
[INFO] [stdout] 2026-03-31T11:54:21.371725Z DEBUG timesimp: storing calculated offset offset=6µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2026-03-31T11:54:23.867018Z TRACE new{response=Response { client: 2026-03-31T11:54:22.097463528Z, server: 2026-03-31T11:54:22.98145031Z } current=2026-03-31T11:54:23.866871433Z}: timesimp::delta: response processing internals latency=884ms 703µs 952ns local_at_midpoint=2026-03-31T11:54:22.98216748Z delta=717µs 170ns ago
[INFO] [stdout] 2026-03-31T11:54:23.867096Z TRACE timesimp: obtained raw offset from server latency=884.703952ms delta=717µs 170ns ago
[INFO] [stdout] 2026-03-31T11:54:23.867115Z TRACE timesimp: sleeping to spread out requests delay=15.971368ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.453016Z TRACE new{response=Response { client: 2026-03-31T11:54:23.884329033Z, server: 2026-03-31T11:54:24.668319446Z } current=2026-03-31T11:54:25.4528514Z}: timesimp::delta: response processing internals latency=784ms 261µs 183ns local_at_midpoint=2026-03-31T11:54:24.668590216Z delta=270µs 770ns ago
[INFO] [stdout] 2026-03-31T11:54:25.453110Z TRACE timesimp: obtained raw offset from server latency=784.261183ms delta=270µs 770ns ago
[INFO] [stdout] 2026-03-31T11:54:25.453137Z TRACE timesimp: response deltas sorted by latency deltas=[-0.27077, -0.118989, -0.71717, -0.11781, 0.49333]
[INFO] [stdout] 2026-03-31T11:54:25.453157Z TRACE timesimp: statistics about response deltas median=-0.71717 mean=-0.1462818 variance=0.18801736096619998 stddev=0.4336096873528081
[INFO] [stdout] 2026-03-31T11:54:25.453188Z TRACE timesimp: eliminated outliers inliers=[-0.71717]
[INFO] [stdout] 2026-03-31T11:54:25.453207Z DEBUG timesimp: storing calculated offset offset=717µ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 11.62s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-cc647bc1b3bbdf3a)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2026-03-31T11:54:25.463779Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:25.464046Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.464010Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2026-03-31T11:54:25.464082Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.463787Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2026-03-31T11:54:25.464143Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.465424Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2026-03-31T11:54:25.465562Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.465631Z TRACE new{response=Response { client: 2026-03-31T11:54:25.46554142Z, server: 2026-03-31T11:54:25.465543949Z } current=2026-03-31T11:54:25.46554546Z}: timesimp::delta: response processing internals latency=2µs 20ns local_at_midpoint=2026-03-31T11:54:25.46554344Z delta=509ns
[INFO] [stdout] 2026-03-31T11:54:25.465695Z TRACE timesimp: obtained raw offset from server latency=2.02µs delta=509ns
[INFO] [stdout] 2026-03-31T11:54:25.465715Z DEBUG timesimp: no offset stored, storing initial delta offset=509ns
[INFO] [stdout] 2026-03-31T11:54:25.465737Z TRACE timesimp: sleeping to spread out requests delay=1.15359464s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.465926Z TRACE new{response=Response { client: 2026-03-31T11:54:25.465835689Z, server: 2026-03-31T11:54:25.46583796Z } current=2026-03-31T11:54:25.465839469Z}: timesimp::delta: response processing internals latency=1µs 890ns local_at_midpoint=2026-03-31T11:54:25.465837579Z delta=381ns
[INFO] [stdout] 2026-03-31T11:54:25.465987Z TRACE timesimp: obtained raw offset from server latency=1.89µs delta=381ns
[INFO] [stdout] 2026-03-31T11:54:25.466010Z TRACE timesimp: sleeping to spread out requests delay=341.834343ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.465446Z TRACE new{response=Response { client: 2026-03-31T11:54:25.465294479Z, server: 2026-03-31T11:54:30.465315479Z } current=2026-03-31T11:54:25.465318279Z}: timesimp::delta: response processing internals latency=11µs 900ns local_at_midpoint=2026-03-31T11:54:25.465306379Z delta=5s 9µs 100ns
[INFO] [stdout] 2026-03-31T11:54:25.466071Z TRACE timesimp: obtained raw offset from server latency=11.9µs delta=5s 9µs 100ns
[INFO] [stdout] 2026-03-31T11:54:25.466090Z TRACE timesimp: sleeping to spread out requests delay=1.125961227s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.467200Z TRACE new{response=Response { client: 2026-03-31T11:54:25.46681874Z, server: 2026-03-31T11:54:20.466821369Z } current=2026-03-31T11:54:25.46682298Z}: timesimp::delta: response processing internals latency=2µs 120ns local_at_midpoint=2026-03-31T11:54:25.46682086Z delta=4s 999ms 999µs 491ns ago
[INFO] [stdout] 2026-03-31T11:54:25.467381Z TRACE timesimp: obtained raw offset from server latency=2.12µs delta=4s 999ms 999µs 491ns ago
[INFO] [stdout] 2026-03-31T11:54:25.467470Z TRACE timesimp: sleeping to spread out requests delay=543.479784ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:25.810903Z TRACE new{response=Response { client: 2026-03-31T11:54:25.810690457Z, server: 2026-03-31T11:54:25.810699766Z } current=2026-03-31T11:54:25.810703817Z}: timesimp::delta: response processing internals latency=6µs 680ns local_at_midpoint=2026-03-31T11:54:25.810697137Z delta=2µs 629ns
[INFO] [stdout] 2026-03-31T11:54:25.810993Z TRACE timesimp: obtained raw offset from server latency=6.68µs delta=2µs 629ns
[INFO] [stdout] 2026-03-31T11:54:25.811015Z TRACE timesimp: sleeping to spread out requests delay=1.63509255s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:26.012795Z TRACE new{response=Response { client: 2026-03-31T11:54:26.012440895Z, server: 2026-03-31T11:54:21.012450125Z } current=2026-03-31T11:54:26.012453705Z}: timesimp::delta: response processing internals latency=6µs 405ns local_at_midpoint=2026-03-31T11:54:26.0124473Z delta=4s 999ms 997µs 175ns ago
[INFO] [stdout] 2026-03-31T11:54:26.012979Z TRACE timesimp: obtained raw offset from server latency=6.405µs delta=4s 999ms 997µs 175ns ago
[INFO] [stdout] 2026-03-31T11:54:26.013171Z TRACE timesimp: sleeping to spread out requests delay=919.714653ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:26.593828Z TRACE new{response=Response { client: 2026-03-31T11:54:26.59363385Z, server: 2026-03-31T11:54:31.59364337Z } current=2026-03-31T11:54:26.59364667Z}: timesimp::delta: response processing internals latency=6µs 410ns local_at_midpoint=2026-03-31T11:54:26.59364026Z delta=5s 3µs 110ns
[INFO] [stdout] 2026-03-31T11:54:26.593955Z TRACE timesimp: obtained raw offset from server latency=6.41µs delta=5s 3µs 110ns
[INFO] [stdout] 2026-03-31T11:54:26.593978Z TRACE timesimp: sleeping to spread out requests delay=1.706792295s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:26.620586Z TRACE new{response=Response { client: 2026-03-31T11:54:26.62042508Z, server: 2026-03-31T11:54:26.620434359Z } current=2026-03-31T11:54:26.62043762Z}: timesimp::delta: response processing internals latency=6µs 270ns local_at_midpoint=2026-03-31T11:54:26.62043135Z delta=3µs 9ns
[INFO] [stdout] 2026-03-31T11:54:26.624282Z TRACE timesimp: obtained raw offset from server latency=6.27µs delta=3µs 9ns
[INFO] [stdout] 2026-03-31T11:54:26.624358Z TRACE timesimp: sleeping to spread out requests delay=1.101836077s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:26.934682Z TRACE new{response=Response { client: 2026-03-31T11:54:26.934522057Z, server: 2026-03-31T11:54:21.934531677Z } current=2026-03-31T11:54:26.934535537Z}: timesimp::delta: response processing internals latency=6µs 740ns local_at_midpoint=2026-03-31T11:54:26.934528797Z delta=4s 999ms 997µs 120ns ago
[INFO] [stdout] 2026-03-31T11:54:26.934764Z TRACE timesimp: obtained raw offset from server latency=6.74µs delta=4s 999ms 997µs 120ns ago
[INFO] [stdout] 2026-03-31T11:54:26.934796Z TRACE timesimp: sleeping to spread out requests delay=1.004728134s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:27.448573Z TRACE new{response=Response { client: 2026-03-31T11:54:27.448405253Z, server: 2026-03-31T11:54:27.448415633Z } current=2026-03-31T11:54:27.448419213Z}: timesimp::delta: response processing internals latency=6µs 980ns local_at_midpoint=2026-03-31T11:54:27.448412233Z delta=3µs 400ns
[INFO] [stdout] 2026-03-31T11:54:27.448654Z TRACE timesimp: obtained raw offset from server latency=6.98µs delta=3µs 400ns
[INFO] [stdout] 2026-03-31T11:54:27.448674Z TRACE timesimp: sleeping to spread out requests delay=1.329428937s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:27.727603Z TRACE new{response=Response { client: 2026-03-31T11:54:27.72744684Z, server: 2026-03-31T11:54:27.727456509Z } current=2026-03-31T11:54:27.72745956Z}: timesimp::delta: response processing internals latency=6µs 360ns local_at_midpoint=2026-03-31T11:54:27.7274532Z delta=3µs 309ns
[INFO] [stdout] 2026-03-31T11:54:27.727678Z TRACE timesimp: obtained raw offset from server latency=6.36µs delta=3µs 309ns
[INFO] [stdout] 2026-03-31T11:54:27.727698Z TRACE timesimp: sleeping to spread out requests delay=424.411478ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:27.941616Z TRACE new{response=Response { client: 2026-03-31T11:54:27.941451519Z, server: 2026-03-31T11:54:22.941461469Z } current=2026-03-31T11:54:27.941464689Z}: timesimp::delta: response processing internals latency=6µs 585ns local_at_midpoint=2026-03-31T11:54:27.941458104Z delta=4s 999ms 996µs 635ns ago
[INFO] [stdout] 2026-03-31T11:54:27.941753Z TRACE timesimp: obtained raw offset from server latency=6.585µs delta=4s 999ms 996µs 635ns ago
[INFO] [stdout] 2026-03-31T11:54:27.941807Z TRACE timesimp: sleeping to spread out requests delay=231.027694ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:28.153543Z TRACE new{response=Response { client: 2026-03-31T11:54:28.153380437Z, server: 2026-03-31T11:54:28.153390196Z } current=2026-03-31T11:54:28.153393907Z}: timesimp::delta: response processing internals latency=6µs 735ns local_at_midpoint=2026-03-31T11:54:28.153387172Z delta=3µs 24ns
[INFO] [stdout] 2026-03-31T11:54:28.153670Z TRACE timesimp: obtained raw offset from server latency=6.735µs delta=3µs 24ns
[INFO] [stdout] 2026-03-31T11:54:28.153714Z TRACE timesimp: sleeping to spread out requests delay=1.905876899s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:28.176454Z TRACE new{response=Response { client: 2026-03-31T11:54:28.176263367Z, server: 2026-03-31T11:54:23.176273997Z } current=2026-03-31T11:54:28.176277837Z}: timesimp::delta: response processing internals latency=7µs 235ns local_at_midpoint=2026-03-31T11:54:28.176270602Z delta=4s 999ms 996µs 605ns ago
[INFO] [stdout] 2026-03-31T11:54:28.176550Z TRACE timesimp: obtained raw offset from server latency=7.235µs delta=4s 999ms 996µs 605ns ago
[INFO] [stdout] 2026-03-31T11:54:28.176582Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.9994910000005, -4999.997175, -4999.9966349999995, -4999.99712, -4999.996605]
[INFO] [stdout] 2026-03-31T11:54:28.176610Z TRACE timesimp: statistics about response deltas median=-4999.9966349999995 mean=-4999.997405200001 variance=1.4296052005399958e-6 stddev=0.0011956609889680252
[INFO] [stdout] 2026-03-31T11:54:28.176638Z TRACE timesimp: eliminated outliers inliers=[-4999.997175, -4999.9966349999995, -4999.99712, -4999.996605]
[INFO] [stdout] 2026-03-31T11:54:28.176658Z DEBUG timesimp: storing calculated offset offset=4s 999ms 996µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 2026-03-31T11:54:28.302598Z TRACE new{response=Response { client: 2026-03-31T11:54:28.302443436Z, server: 2026-03-31T11:54:33.302452405Z } current=2026-03-31T11:54:28.302455656Z}: timesimp::delta: response processing internals latency=6µs 110ns local_at_midpoint=2026-03-31T11:54:28.302449546Z delta=5s 2µs 859ns
[INFO] [stdout] 2026-03-31T11:54:28.302676Z TRACE timesimp: obtained raw offset from server latency=6.11µs delta=5s 2µs 859ns
[INFO] [stdout] 2026-03-31T11:54:28.302694Z TRACE timesimp: sleeping to spread out requests delay=116.446007ms max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:28.421487Z TRACE new{response=Response { client: 2026-03-31T11:54:28.421323444Z, server: 2026-03-31T11:54:33.421332904Z } current=2026-03-31T11:54:28.421336624Z}: timesimp::delta: response processing internals latency=6µs 590ns local_at_midpoint=2026-03-31T11:54:28.421330034Z delta=5s 2µs 870ns
[INFO] [stdout] 2026-03-31T11:54:28.421858Z TRACE timesimp: obtained raw offset from server latency=6.59µs delta=5s 2µs 870ns
[INFO] [stdout] 2026-03-31T11:54:28.422600Z TRACE timesimp: sleeping to spread out requests delay=1.280185507s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:28.781490Z TRACE new{response=Response { client: 2026-03-31T11:54:28.781324472Z, server: 2026-03-31T11:54:28.781333832Z } current=2026-03-31T11:54:28.781337581Z}: timesimp::delta: response processing internals latency=6µs 554ns local_at_midpoint=2026-03-31T11:54:28.781331026Z delta=2µs 806ns
[INFO] [stdout] 2026-03-31T11:54:28.781579Z TRACE timesimp: obtained raw offset from server latency=6.554µs delta=2µs 806ns
[INFO] [stdout] 2026-03-31T11:54:28.781598Z TRACE timesimp: sleeping to spread out requests delay=1.570951072s max_jitter=2s
[INFO] [stdout] 2026-03-31T11:54:29.703881Z TRACE new{response=Response { client: 2026-03-31T11:54:29.703712863Z, server: 2026-03-31T11:54:34.703722253Z } current=2026-03-31T11:54:29.703725663Z}: timesimp::delta: response processing internals latency=6µs 400ns local_at_midpoint=2026-03-31T11:54:29.703719263Z delta=5s 2µs 990ns
[INFO] [stdout] 2026-03-31T11:54:29.703957Z TRACE timesimp: obtained raw offset from server latency=6.4µs delta=5s 2µs 990ns
[INFO] [stdout] 2026-03-31T11:54:29.703981Z TRACE timesimp: response deltas sorted by latency deltas=[5000.002859, 5000.00299, 5000.00311, 5000.00287, 5000.0091]
[INFO] [stdout] 2026-03-31T11:54:29.704006Z TRACE timesimp: statistics about response deltas median=5000.00311 mean=5000.0041858 variance=7.557093200464677e-6 stddev=0.002749016769767816
[INFO] [stdout] 2026-03-31T11:54:29.704031Z TRACE timesimp: eliminated outliers inliers=[5000.002859, 5000.00299, 5000.00311, 5000.00287]
[INFO] [stdout] 2026-03-31T11:54:29.704050Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2026-03-31T11:54:30.061633Z TRACE new{response=Response { client: 2026-03-31T11:54:30.06145907Z, server: 2026-03-31T11:54:30.061469329Z } current=2026-03-31T11:54:30.06147265Z}: timesimp::delta: response processing internals latency=6µs 790ns local_at_midpoint=2026-03-31T11:54:30.06146586Z delta=3µs 469ns
[INFO] [stdout] 2026-03-31T11:54:30.061725Z TRACE timesimp: obtained raw offset from server latency=6.79µs delta=3µs 469ns
[INFO] [stdout] 2026-03-31T11:54:30.061751Z TRACE timesimp: response deltas sorted by latency deltas=[0.000509, 0.003009, 0.003309, 0.003024, 0.003469]
[INFO] [stdout] 2026-03-31T11:54:30.061774Z TRACE timesimp: statistics about response deltas median=0.003309 mean=0.002664 variance=1.4891750000000002e-6 stddev=0.00122031758161554
[INFO] [stdout] 2026-03-31T11:54:30.061807Z TRACE timesimp: eliminated outliers inliers=[0.003009, 0.003309, 0.003024, 0.003469]
[INFO] [stdout] 2026-03-31T11:54:30.061827Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2026-03-31T11:54:30.353464Z TRACE new{response=Response { client: 2026-03-31T11:54:30.353301598Z, server: 2026-03-31T11:54:30.353311368Z } current=2026-03-31T11:54:30.353315198Z}: timesimp::delta: response processing internals latency=6µs 800ns local_at_midpoint=2026-03-31T11:54:30.353308398Z delta=2µs 970ns
[INFO] [stdout] 2026-03-31T11:54:30.353558Z TRACE timesimp: obtained raw offset from server latency=6.8µs delta=2µs 970ns
[INFO] [stdout] 2026-03-31T11:54:30.353583Z TRACE timesimp: response deltas sorted by latency deltas=[0.000381, 0.002806, 0.002629, 0.00297, 0.0034]
[INFO] [stdout] 2026-03-31T11:54:30.353604Z TRACE timesimp: statistics about response deltas median=0.002629 mean=0.0024372 variance=1.4029046999999998e-6 stddev=0.001184442780382404
[INFO] [stdout] 2026-03-31T11:54:30.353627Z TRACE timesimp: eliminated outliers inliers=[0.002806, 0.002629, 0.00297, 0.0034]
[INFO] [stdout] 2026-03-31T11:54:30.353639Z 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 4.89s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-e2773855b3afcad4)
[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.39s; merged doctests compilation took 1.36s
[INFO] running `Command { std: "docker" "inspect" "f4287048afe1cc1b07987a1797755e19cb9569ae948da97331b7dc7d173bd4b0", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "f4287048afe1cc1b07987a1797755e19cb9569ae948da97331b7dc7d173bd4b0", kill_on_drop: false }`
[INFO] [stdout] f4287048afe1cc1b07987a1797755e19cb9569ae948da97331b7dc7d173bd4b0