[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#33835004928d3bf65db4d4712e1330766263b0bd for pr-155739-1
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-4-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-4-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-4-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 33835004928d3bf65db4d4712e1330766263b0bd
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+33835004928d3bf65db4d4712e1330766263b0bd" "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" "+33835004928d3bf65db4d4712e1330766263b0bd" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+33835004928d3bf65db4d4712e1330766263b0bd" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235
[INFO] running `Command { std: "docker" "start" "-a" "3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235", kill_on_drop: false }`
[INFO] [stdout] 3919f3ba1eb4b745841a65890eeea332c99f8e8af7fbc3f4b0abbddee2811235
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+33835004928d3bf65db4d4712e1330766263b0bd" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15
[INFO] running `Command { std: "docker" "start" "-a" "91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15", 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 thiserror v2.0.12
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling jiff v0.2.10
[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 dtor v0.0.6
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 20.49s
[INFO] running `Command { std: "docker" "inspect" "91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15", kill_on_drop: false }`
[INFO] [stdout] 91c1d16be7ee61008225732747e61edc3c8042bda1d7eb9bf383bcfda2deef15
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+33835004928d3bf65db4d4712e1330766263b0bd" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46
[INFO] running `Command { std: "docker" "start" "-a" "2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling 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 icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling futures-util v0.3.31
[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 futures-channel v0.3.31
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[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 rand_core v0.9.3
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[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 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 thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling zerovec v0.10.4
[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]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 31.37s
[INFO] running `Command { std: "docker" "inspect" "2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46", kill_on_drop: false }`
[INFO] [stdout] 2e34462e89e56214b9595844ce74cde60993d9a0c8f9b2cba790492d08268f46
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+33835004928d3bf65db4d4712e1330766263b0bd" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21
[INFO] running `Command { std: "docker" "start" "-a" "0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.26s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-7875ddb3df0d84b6)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-f04346ec9fba397a)
[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] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-05-15T02:53:26.868738Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.868706Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.868704Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.868787Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.868788Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.868818Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.868694Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-05-15T02:53:26.868698Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.868864Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.868881Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.869343Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.872184Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.872571Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.870056931Z, server: 2026-05-15T02:53:26.871209561Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.872333281Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 138µs 175ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.871195106Z [3mdelta[0m[2m=[0m14µs 455ns
[INFO] [stdout] [2m2026-05-15T02:53:26.872657Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.138175ms [3mdelta[0m[2m=[0m14µs 455ns
[INFO] [stdout] [2m2026-05-15T02:53:26.872686Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m14µs 455ns
[INFO] [stdout] [2m2026-05-15T02:53:26.872712Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m110.994261ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.875498Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.875563Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.880543Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.870071811Z, server: 2026-05-15T02:53:31.875199761Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.880336081Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5ms 132µs 135ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.875203946Z [3mdelta[0m[2m=[0m4s 999ms 995µs 815ns
[INFO] [stdout] [2m2026-05-15T02:53:26.880632Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.132135ms [3mdelta[0m[2m=[0m4s 999ms 995µs 815ns
[INFO] [stdout] [2m2026-05-15T02:53:26.880658Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 995µs 815ns
[INFO] [stdout] [2m2026-05-15T02:53:26.880673Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.187996066s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.870338Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-05-15T02:53:26.881052Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.870636Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.881805Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.888533Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.870017931Z, server: 2026-05-15T02:53:31.879183841Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.88834702Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 164µs 544ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.879182475Z [3mdelta[0m[2m=[0m5s 1µs 366ns
[INFO] [stdout] [2m2026-05-15T02:53:26.888695Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.164544ms [3mdelta[0m[2m=[0m5s 1µs 366ns
[INFO] [stdout] [2m2026-05-15T02:53:26.888786Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 1µs 366ns
[INFO] [stdout] [2m2026-05-15T02:53:26.888866Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.871090579s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.892493Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.870059031Z, server: 2026-05-15T02:53:26.881194491Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.89234872Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 144µs 844ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.881203875Z [3mdelta[0m[2m=[0m9µs 384ns ago
[INFO] [stdout] [2m2026-05-15T02:53:26.892618Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.144844ms [3mdelta[0m[2m=[0m9µs 384ns ago
[INFO] [stdout] [2m2026-05-15T02:53:26.892672Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.85183682s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.906442Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.882402201Z, server: 2026-05-15T02:53:26.8935424Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.90624012Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 918µs 959ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.89432116Z [3mdelta[0m[2m=[0m778µs 760ns ago
[INFO] [stdout] [2m2026-05-15T02:53:26.906530Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.918959ms [3mdelta[0m[2m=[0m778µs 760ns ago
[INFO] [stdout] [2m2026-05-15T02:53:26.906552Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m77.030649ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.907315Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.883513421Z, server: 2026-05-15T02:53:21.894625391Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.90719632Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 841µs 449ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.89535487Z [3mdelta[0m[2m=[0m5s 729µs 479ns ago
[INFO] [stdout] [2m2026-05-15T02:53:26.907373Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.841449ms [3mdelta[0m[2m=[0m5s 729µs 479ns ago
[INFO] [stdout] [2m2026-05-15T02:53:26.907393Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 729µs 479ns ago
[INFO] [stdout] [2m2026-05-15T02:53:26.907407Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.600639733s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.910593Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.882252861Z, server: 2026-05-15T02:53:31.900227491Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.91038771Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 67µs 424ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.896320285Z [3mdelta[0m[2m=[0m5s 3ms 907µs 206ns
[INFO] [stdout] [2m2026-05-15T02:53:26.910683Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.067424ms [3mdelta[0m[2m=[0m5s 3ms 907µs 206ns
[INFO] [stdout] [2m2026-05-15T02:53:26.910707Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 3ms 907µs 206ns
[INFO] [stdout] [2m2026-05-15T02:53:26.910723Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m870.793537ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.917378Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:26.917490Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.941866Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.91871397Z, server: 2026-05-15T02:53:31.92987538Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.94156856Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 427µs 295ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.930141265Z [3mdelta[0m[2m=[0m4s 999ms 734µs 115ns
[INFO] [stdout] [2m2026-05-15T02:53:26.942041Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.427295ms [3mdelta[0m[2m=[0m4s 999ms 734µs 115ns
[INFO] [stdout] [2m2026-05-15T02:53:26.942100Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 734µs 115ns
[INFO] [stdout] [2m2026-05-15T02:53:26.942165Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m75.138953ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:26.989501Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.98508333Z, server: 2026-05-15T02:53:26.98819839Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:26.989337519Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 127µs 94ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.987210424Z [3mdelta[0m[2m=[0m987µs 966ns
[INFO] [stdout] [2m2026-05-15T02:53:26.989594Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.127094ms [3mdelta[0m[2m=[0m987µs 966ns
[INFO] [stdout] [2m2026-05-15T02:53:26.989617Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m733.028927ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:27.016429Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.984877259Z, server: 2026-05-15T02:53:26.996067139Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:27.016264899Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m15ms 693µs 820ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:27.000571079Z [3mdelta[0m[2m=[0m4ms 503µs 940ns ago
[INFO] [stdout] [2m2026-05-15T02:53:27.016534Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m15.69382ms [3mdelta[0m[2m=[0m4ms 503µs 940ns ago
[INFO] [stdout] [2m2026-05-15T02:53:27.016559Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m839.267594ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:27.041060Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:27.018488909Z, server: 2026-05-15T02:53:32.029688529Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:27.040886959Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 199µs 25ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:27.029687934Z [3mdelta[0m[2m=[0m5s 595ns
[INFO] [stdout] [2m2026-05-15T02:53:27.041168Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.199025ms [3mdelta[0m[2m=[0m5s 595ns
[INFO] [stdout] [2m2026-05-15T02:53:27.041193Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.682898168s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:27.075449Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.870015321Z, server: 2026-05-15T02:53:26.97137285Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:27.075245158Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m102ms 614µs 918ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:26.972630239Z [3mdelta[0m[2m=[0m1ms 257µs 389ns ago
[INFO] [stdout] [2m2026-05-15T02:53:27.075553Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m102.614918ms [3mdelta[0m[2m=[0m1ms 257µs 389ns ago
[INFO] [stdout] [2m2026-05-15T02:53:27.075577Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m1ms 257µs 389ns ago
[INFO] [stdout] [2m2026-05-15T02:53:27.075592Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.814288493s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:27.726810Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:27.724401361Z, server: 2026-05-15T02:53:27.725534471Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:27.726653371Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 126µs 5ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:27.725527366Z [3mdelta[0m[2m=[0m7µs 105ns
[INFO] [stdout] [2m2026-05-15T02:53:27.726953Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.126005ms [3mdelta[0m[2m=[0m7µs 105ns
[INFO] [stdout] [2m2026-05-15T02:53:27.727003Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.260270107s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:27.805616Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:27.783422811Z, server: 2026-05-15T02:53:32.794241091Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:27.80543335Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 5µs 269ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:27.79442808Z [3mdelta[0m[2m=[0m4s 999ms 813µs 11ns
[INFO] [stdout] [2m2026-05-15T02:53:27.805709Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.005269ms [3mdelta[0m[2m=[0m4s 999ms 813µs 11ns
[INFO] [stdout] [2m2026-05-15T02:53:27.805735Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m948.586143ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:27.879885Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:27.85740631Z, server: 2026-05-15T02:53:27.86856026Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:27.87971806Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 155µs 875ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:27.868562185Z [3mdelta[0m[2m=[0m1µs 925ns ago
[INFO] [stdout] [2m2026-05-15T02:53:27.879984Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.155875ms [3mdelta[0m[2m=[0m1µs 925ns ago
[INFO] [stdout] [2m2026-05-15T02:53:27.880006Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.218187343s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.082958Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.070390018Z, server: 2026-05-15T02:53:33.076583058Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.082778987Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 194µs 484ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.076584502Z [3mdelta[0m[2m=[0m4s 999ms 998µs 556ns
[INFO] [stdout] [2m2026-05-15T02:53:28.083059Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.194484ms [3mdelta[0m[2m=[0m4s 999ms 998µs 556ns
[INFO] [stdout] [2m2026-05-15T02:53:28.083087Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.704215944s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.543406Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.516252922Z, server: 2026-05-15T02:53:23.528248722Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.543238622Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 492µs 850ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.529745772Z [3mdelta[0m[2m=[0m5s 1ms 497µs 50ns ago
[INFO] [stdout] [2m2026-05-15T02:53:28.543501Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.49285ms [3mdelta[0m[2m=[0m5s 1ms 497µs 50ns ago
[INFO] [stdout] [2m2026-05-15T02:53:28.543525Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.796155876s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.610583Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:26.879241391Z, server: 2026-05-15T02:53:27.745245611Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.610383181Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m865ms 570µs 895ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:27.744812286Z [3mdelta[0m[2m=[0m433µs 325ns
[INFO] [stdout] [2m2026-05-15T02:53:28.610671Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m865.570895ms [3mdelta[0m[2m=[0m433µs 325ns
[INFO] [stdout] [2m2026-05-15T02:53:28.610692Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m433µs 325ns
[INFO] [stdout] [2m2026-05-15T02:53:28.610706Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.473334696s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.747942Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.72538873Z, server: 2026-05-15T02:53:33.73659816Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.74775936Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 185µs 315ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.736574045Z [3mdelta[0m[2m=[0m5s 24µs 115ns
[INFO] [stdout] [2m2026-05-15T02:53:28.748049Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.185315ms [3mdelta[0m[2m=[0m5s 24µs 115ns
[INFO] [stdout] [2m2026-05-15T02:53:28.748073Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.231711505s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.768864Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.74636485Z, server: 2026-05-15T02:53:28.75753629Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.76869686Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 166µs 5ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.757530855Z [3mdelta[0m[2m=[0m5µs 435ns
[INFO] [stdout] [2m2026-05-15T02:53:28.768955Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.166005ms [3mdelta[0m[2m=[0m5µs 435ns
[INFO] [stdout] [2m2026-05-15T02:53:28.768978Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m722.79068ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.775825Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.76135347Z, server: 2026-05-15T02:53:33.76851241Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.775656199Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 151µs 364ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.768504834Z [3mdelta[0m[2m=[0m5s 7µs 576ns
[INFO] [stdout] [2m2026-05-15T02:53:28.775914Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.151364ms [3mdelta[0m[2m=[0m5s 7µs 576ns
[INFO] [stdout] [2m2026-05-15T02:53:28.775966Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.369528848s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.775952Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.7553777Z, server: 2026-05-15T02:53:33.76557983Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.77577983Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 201µs 65ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.765578765Z [3mdelta[0m[2m=[0m5s 1µs 65ns
[INFO] [stdout] [2m2026-05-15T02:53:28.776033Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.201065ms [3mdelta[0m[2m=[0m5s 1µs 65ns
[INFO] [stdout] [2m2026-05-15T02:53:28.776058Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m607.849571ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:28.993370Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.988247457Z, server: 2026-05-15T02:53:28.991261917Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:28.993199947Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 476µs 245ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.990723702Z [3mdelta[0m[2m=[0m538µs 215ns
[INFO] [stdout] [2m2026-05-15T02:53:28.993446Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.476245ms [3mdelta[0m[2m=[0m538µs 215ns
[INFO] [stdout] [2m2026-05-15T02:53:28.993468Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m840.308912ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:29.094338Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:28.891431068Z, server: 2026-05-15T02:53:28.992791377Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:29.094156396Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 362µs 664ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:28.992793732Z [3mdelta[0m[2m=[0m2µs 355ns ago
[INFO] [stdout] [2m2026-05-15T02:53:29.094432Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.362664ms [3mdelta[0m[2m=[0m2µs 355ns ago
[INFO] [stdout] [2m2026-05-15T02:53:29.094455Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.04378456s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:29.121924Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:29.099403706Z, server: 2026-05-15T02:53:29.110591856Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:29.121755596Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 175µs 945ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:29.110579651Z [3mdelta[0m[2m=[0m12µs 205ns
[INFO] [stdout] [2m2026-05-15T02:53:29.122013Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.175945ms [3mdelta[0m[2m=[0m12µs 205ns
[INFO] [stdout] [2m2026-05-15T02:53:29.122036Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m613.941805ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:29.405914Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:29.385374233Z, server: 2026-05-15T02:53:34.395553523Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:29.405737583Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 181µs 675ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:29.395555908Z [3mdelta[0m[2m=[0m4s 999ms 997µs 615ns
[INFO] [stdout] [2m2026-05-15T02:53:29.406013Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.181675ms [3mdelta[0m[2m=[0m4s 999ms 997µs 615ns
[INFO] [stdout] [2m2026-05-15T02:53:29.406039Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m623.528773ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:29.534621Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:29.508245612Z, server: 2026-05-15T02:53:29.523243771Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:29.534441751Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 98µs 69ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:29.521343681Z [3mdelta[0m[2m=[0m1ms 900µs 90ns
[INFO] [stdout] [2m2026-05-15T02:53:29.534711Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.098069ms [3mdelta[0m[2m=[0m1ms 900µs 90ns
[INFO] [stdout] [2m2026-05-15T02:53:29.534733Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m972.044899ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:29.760079Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:29.737397219Z, server: 2026-05-15T02:53:29.748589339Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:29.759894559Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 248µs 670ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:29.748645889Z [3mdelta[0m[2m=[0m56µs 550ns ago
[INFO] [stdout] [2m2026-05-15T02:53:29.760209Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.24867ms [3mdelta[0m[2m=[0m56µs 550ns ago
[INFO] [stdout] [2m2026-05-15T02:53:29.760254Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.001925, 0.012205, -0.05655, -0.77876, -4.50394]
[INFO] [stdout] [2m2026-05-15T02:53:29.760278Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.05655 [3mmean[0m[2m=[0m-1.065794 [3mvariance[0m[2m=[0m3.8039272447925003 [3mstddev[0m[2m=[0m1.9503659258694253
[INFO] [stdout] [2m2026-05-15T02:53:29.760312Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.001925, 0.012205, -0.05655, -0.77876]
[INFO] [stdout] [2m2026-05-15T02:53:29.760327Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m206µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-05-15T02:53:29.808928Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:29.788378259Z, server: 2026-05-15T02:53:34.798577788Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:29.808764728Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 193µs 234ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:29.798571493Z [3mdelta[0m[2m=[0m5s 6µs 295ns
[INFO] [stdout] [2m2026-05-15T02:53:29.809022Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.193234ms [3mdelta[0m[2m=[0m5s 6µs 295ns
[INFO] [stdout] [2m2026-05-15T02:53:29.809049Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m572.959299ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:29.837267Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:29.834852288Z, server: 2026-05-15T02:53:29.835980928Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:29.837090948Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 119µs 330ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:29.835971618Z [3mdelta[0m[2m=[0m9µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:29.837353Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.11933ms [3mdelta[0m[2m=[0m9µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:29.837378Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00931, 0.007105, 0.014455, 0.987966, 0.538215]
[INFO] [stdout] [2m2026-05-15T02:53:29.837397Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.014455 [3mmean[0m[2m=[0m0.31141019999999997 [3mvariance[0m[2m=[0m0.1953041860527 [3mstddev[0m[2m=[0m0.44193233198386833
[INFO] [stdout] [2m2026-05-15T02:53:29.837416Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00931, 0.007105, 0.014455]
[INFO] [stdout] [2m2026-05-15T02:53:29.837430Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m10µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-05-15T02:53:30.003165Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:29.980460966Z, server: 2026-05-15T02:53:34.991771186Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.002966676Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 252µs 855ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:29.991713821Z [3mdelta[0m[2m=[0m5s 57µs 365ns
[INFO] [stdout] [2m2026-05-15T02:53:30.003259Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.252855ms [3mdelta[0m[2m=[0m5s 57µs 365ns
[INFO] [stdout] [2m2026-05-15T02:53:30.003279Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m392.136058ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:30.052987Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.031404106Z, server: 2026-05-15T02:53:35.041600246Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.052805576Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 700µs 735ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.042104841Z [3mdelta[0m[2m=[0m4s 999ms 495µs 405ns
[INFO] [stdout] [2m2026-05-15T02:53:30.053089Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.700735ms [3mdelta[0m[2m=[0m4s 999ms 495µs 405ns
[INFO] [stdout] [2m2026-05-15T02:53:30.053120Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.997615, 5000.001065, 4999.495405, 4999.813011, 5003.907206]
[INFO] [stdout] [2m2026-05-15T02:53:30.053356Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.495405 [3mmean[0m[2m=[0m5000.6428604 [3mvariance[0m[2m=[0m3.372374769897492 [3mstddev[0m[2m=[0m1.8364026709568608
[INFO] [stdout] [2m2026-05-15T02:53:30.053474Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.997615, 5000.001065, 4999.495405, 4999.813011]
[INFO] [stdout] [2m2026-05-15T02:53:30.053567Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 826µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-05-15T02:53:30.178409Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.151264924Z, server: 2026-05-15T02:53:35.166244634Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.178239804Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 487µs 440ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.164752364Z [3mdelta[0m[2m=[0m5s 1ms 492µs 270ns
[INFO] [stdout] [2m2026-05-15T02:53:30.178504Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.48744ms [3mdelta[0m[2m=[0m5s 1ms 492µs 270ns
[INFO] [stdout] [2m2026-05-15T02:53:30.178528Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.889408438s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:30.349448Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.139373224Z, server: 2026-05-15T02:53:30.240731623Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.349254892Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m104ms 940µs 834ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.244314058Z [3mdelta[0m[2m=[0m3ms 582µs 435ns ago
[INFO] [stdout] [2m2026-05-15T02:53:30.349550Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m104.940834ms [3mdelta[0m[2m=[0m3ms 582µs 435ns ago
[INFO] [stdout] [2m2026-05-15T02:53:30.349573Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.003878129s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:30.362881Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.340359472Z, server: 2026-05-15T02:53:25.351491642Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.362691242Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 165µs 885ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.351525357Z [3mdelta[0m[2m=[0m5s 33µs 715ns ago
[INFO] [stdout] [2m2026-05-15T02:53:30.362979Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.165885ms [3mdelta[0m[2m=[0m5s 33µs 715ns ago
[INFO] [stdout] [2m2026-05-15T02:53:30.363003Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.383897527s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:30.398730Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.386260522Z, server: 2026-05-15T02:53:35.392230142Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.398549442Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 144µs 460ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.392404982Z [3mdelta[0m[2m=[0m4s 999ms 825µs 160ns
[INFO] [stdout] [2m2026-05-15T02:53:30.398820Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.14446ms [3mdelta[0m[2m=[0m4s 999ms 825µs 160ns
[INFO] [stdout] [2m2026-05-15T02:53:30.398844Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m422.853896ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:30.419659Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.396967202Z, server: 2026-05-15T02:53:35.408225301Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.419452132Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 242µs 465ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.408209667Z [3mdelta[0m[2m=[0m5s 15µs 634ns
[INFO] [stdout] [2m2026-05-15T02:53:30.419764Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.242465ms [3mdelta[0m[2m=[0m5s 15µs 634ns
[INFO] [stdout] [2m2026-05-15T02:53:30.419796Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.024115, 5000.000595, 5000.015634, 5000.057365, 4999.734115]
[INFO] [stdout] [2m2026-05-15T02:53:30.419817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.015634 [3mmean[0m[2m=[0m4999.9663648000005 [3mvariance[0m[2m=[0m0.01728881306518124 [3mstddev[0m[2m=[0m0.13148693115736346
[INFO] [stdout] [2m2026-05-15T02:53:30.419836Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.024115, 5000.000595, 5000.015634, 5000.057365]
[INFO] [stdout] [2m2026-05-15T02:53:30.419850Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 24µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-05-15T02:53:30.531223Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.508414291Z, server: 2026-05-15T02:53:30.51975437Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.530978Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 281µs 854ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.519696145Z [3mdelta[0m[2m=[0m58µs 225ns
[INFO] [stdout] [2m2026-05-15T02:53:30.531329Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.281854ms [3mdelta[0m[2m=[0m58µs 225ns
[INFO] [stdout] [2m2026-05-15T02:53:30.531353Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.917608305s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:30.835855Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.823379197Z, server: 2026-05-15T02:53:35.829537447Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:30.835684617Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 152µs 710ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:30.829531907Z [3mdelta[0m[2m=[0m5s 5µs 540ns
[INFO] [stdout] [2m2026-05-15T02:53:30.835956Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.15271ms [3mdelta[0m[2m=[0m5s 5µs 540ns
[INFO] [stdout] [2m2026-05-15T02:53:30.835987Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.995815, 4999.82516, 5000.00554, 4999.9985560000005, 5000.006295]
[INFO] [stdout] [2m2026-05-15T02:53:30.836008Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00554 [3mmean[0m[2m=[0m4999.9662732 [3mvariance[0m[2m=[0m0.00624286459869278 [3mstddev[0m[2m=[0m0.07901180037622722
[INFO] [stdout] [2m2026-05-15T02:53:30.836046Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.995815, 5000.00554, 4999.9985560000005, 5000.006295]
[INFO] [stdout] [2m2026-05-15T02:53:30.836062Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 1µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-05-15T02:53:31.557216Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:31.354333851Z, server: 2026-05-15T02:53:31.4556893Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:31.557031899Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 349µs 24ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:31.455682875Z [3mdelta[0m[2m=[0m6µs 425ns
[INFO] [stdout] [2m2026-05-15T02:53:31.557378Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.349024ms [3mdelta[0m[2m=[0m6µs 425ns
[INFO] [stdout] [2m2026-05-15T02:53:31.557429Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.400789831s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:31.770848Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:31.748241217Z, server: 2026-05-15T02:53:26.759449587Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:31.770676697Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 217µs 740ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:31.759458957Z [3mdelta[0m[2m=[0m5s 9µs 370ns ago
[INFO] [stdout] [2m2026-05-15T02:53:31.770947Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.21774ms [3mdelta[0m[2m=[0m5s 9µs 370ns ago
[INFO] [stdout] [2m2026-05-15T02:53:31.770975Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m865.209984ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:31.917574Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:30.085408135Z, server: 2026-05-15T02:53:31.001402385Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:31.917383475Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m915ms 987µs 670ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:31.001395805Z [3mdelta[0m[2m=[0m6µs 580ns
[INFO] [stdout] [2m2026-05-15T02:53:31.917743Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m915.98767ms [3mdelta[0m[2m=[0m6µs 580ns
[INFO] [stdout] [2m2026-05-15T02:53:31.917801Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.248700613s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:32.102409Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:32.072243803Z, server: 2026-05-15T02:53:37.087242463Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:32.102238383Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 997µs 290ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:32.087241093Z [3mdelta[0m[2m=[0m5s 1µs 370ns
[INFO] [stdout] [2m2026-05-15T02:53:32.102502Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.99729ms [3mdelta[0m[2m=[0m5s 1µs 370ns
[INFO] [stdout] [2m2026-05-15T02:53:32.102524Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m109.325397ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:32.244419Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:32.223247872Z, server: 2026-05-15T02:53:37.232240972Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:32.244250012Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 501µs 70ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:32.233748942Z [3mdelta[0m[2m=[0m4s 998ms 492µs 30ns
[INFO] [stdout] [2m2026-05-15T02:53:32.244513Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.50107ms [3mdelta[0m[2m=[0m4s 998ms 492µs 30ns
[INFO] [stdout] [2m2026-05-15T02:53:32.244541Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.007576, 5000.001366, 4998.49203, 5001.49227, 5000.00137]
[INFO] [stdout] [2m2026-05-15T02:53:32.244561Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4998.49203 [3mmean[0m[2m=[0m4999.9989224 [3mvariance[0m[2m=[0m1.1252246515803455 [3mstddev[0m[2m=[0m1.0607660682640379
[INFO] [stdout] [2m2026-05-15T02:53:32.244580Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4998.49203]
[INFO] [stdout] [2m2026-05-15T02:53:32.244593Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 998ms 492µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-05-15T02:53:32.472909Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:32.450370599Z, server: 2026-05-15T02:53:32.461563259Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:32.472743299Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 186µs 350ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:32.461556949Z [3mdelta[0m[2m=[0m6µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:32.473000Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.18635ms [3mdelta[0m[2m=[0m6µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:32.473025Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.009384, 0.005435, 0.00631, 0.058225, 1.90009]
[INFO] [stdout] [2m2026-05-15T02:53:32.473044Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00631 [3mmean[0m[2m=[0m0.3921352 [3mvariance[0m[2m=[0m0.7112598745277 [3mstddev[0m[2m=[0m0.8433622439543402
[INFO] [stdout] [2m2026-05-15T02:53:32.473064Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.009384, 0.005435, 0.00631, 0.058225]
[INFO] [stdout] [2m2026-05-15T02:53:32.473087Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m15µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-05-15T02:53:32.659965Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:32.637408647Z, server: 2026-05-15T02:53:27.648606327Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:32.659802037Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 196µs 695ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:32.648605342Z [3mdelta[0m[2m=[0m4s 999ms 999µs 15ns ago
[INFO] [stdout] [2m2026-05-15T02:53:32.660059Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.196695ms [3mdelta[0m[2m=[0m4s 999ms 999µs 15ns ago
[INFO] [stdout] [2m2026-05-15T02:53:32.660090Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-5000.033715, -4999.999015, -5000.00937, -5000.729479, -5001.49705]
[INFO] [stdout] [2m2026-05-15T02:53:32.660111Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.00937 [3mmean[0m[2m=[0m-5000.4537258 [3mvariance[0m[2m=[0m0.43629706859068773 [3mstddev[0m[2m=[0m0.660527871168725
[INFO] [stdout] [2m2026-05-15T02:53:32.660130Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-5000.033715, -4999.999015, -5000.00937]
[INFO] [stdout] [2m2026-05-15T02:53:32.660180Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 14µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-05-15T02:53:33.162271Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:32.959366233Z, server: 2026-05-15T02:53:33.060703252Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:33.162071771Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 352µs 769ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:33.060719002Z [3mdelta[0m[2m=[0m15µs 750ns ago
[INFO] [stdout] [2m2026-05-15T02:53:33.162366Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.352769ms [3mdelta[0m[2m=[0m15µs 750ns ago
[INFO] [stdout] [2m2026-05-15T02:53:33.162396Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.006425, -0.01575, -0.002355, -1.257389, -3.582435]
[INFO] [stdout] [2m2026-05-15T02:53:33.162417Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.002355 [3mmean[0m[2m=[0m-0.9703008000000001 [3mvariance[0m[2m=[0m2.4269360758231997 [3mstddev[0m[2m=[0m1.5578626626962981
[INFO] [stdout] [2m2026-05-15T02:53:33.162446Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.006425, -0.01575, -0.002355, -1.257389]
[INFO] [stdout] [2m2026-05-15T02:53:33.162461Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m317µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-05-15T02:53:34.833669Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:33.168317221Z, server: 2026-05-15T02:53:34.001380212Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:34.833493783Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m832ms 588µs 281ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:34.000905502Z [3mdelta[0m[2m=[0m474µs 710ns
[INFO] [stdout] [2m2026-05-15T02:53:34.833766Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m832.588281ms [3mdelta[0m[2m=[0m474µs 710ns
[INFO] [stdout] [2m2026-05-15T02:53:34.833792Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m423.54682ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:36.948575Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:35.258614178Z, server: 2026-05-15T02:53:36.103419998Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:36.948402609Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m844ms 894µs 215ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:36.103508393Z [3mdelta[0m[2m=[0m88µs 395ns ago
[INFO] [stdout] [2m2026-05-15T02:53:36.948658Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m844.894215ms [3mdelta[0m[2m=[0m88µs 395ns ago
[INFO] [stdout] [2m2026-05-15T02:53:36.948681Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m940.05437ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.452552Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:37.890470719Z, server: 2026-05-15T02:53:38.67136786Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.452388912Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m780ms 959µs 96ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:38.671429815Z [3mdelta[0m[2m=[0m61µs 955ns ago
[INFO] [stdout] [2m2026-05-15T02:53:39.452626Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m780.959096ms [3mdelta[0m[2m=[0m61µs 955ns ago
[INFO] [stdout] [2m2026-05-15T02:53:39.452652Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.061955, 0.47471, -0.088395, 0.433325, 0.00658]
[INFO] [stdout] [2m2026-05-15T02:53:39.452670Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.088395 [3mmean[0m[2m=[0m0.15285300000000002 [3mvariance[0m[2m=[0m0.0769988340325 [3mstddev[0m[2m=[0m0.27748663757467673
[INFO] [stdout] [2m2026-05-15T02:53:39.452689Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.061955, -0.088395, 0.00658]
[INFO] [stdout] [2m2026-05-15T02:53:39.452701Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m47µ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.59s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-2e65c6dffb129287)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-05-15T02:53:39.456538Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-05-15T02:53:39.456530Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-05-15T02:53:39.456537Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:39.456537Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:53:39.456596Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.456599Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.456610Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.456608Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.458007Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:39.457873141Z, server: 2026-05-15T02:53:39.457876471Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.457878311Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 585ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:39.457875726Z [3mdelta[0m[2m=[0m745ns
[INFO] [stdout] [2m2026-05-15T02:53:39.458007Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:39.457842741Z, server: 2026-05-15T02:53:44.457858661Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.457862151Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 705ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:39.457852446Z [3mdelta[0m[2m=[0m5s 6µs 215ns
[INFO] [stdout] [2m2026-05-15T02:53:39.458077Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.585µs [3mdelta[0m[2m=[0m745ns
[INFO] [stdout] [2m2026-05-15T02:53:39.458094Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.831982385s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.458008Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:39.457865581Z, server: 2026-05-15T02:53:34.457869281Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.457871331Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 875ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:39.457868456Z [3mdelta[0m[2m=[0m4s 999ms 999µs 175ns ago
[INFO] [stdout] [2m2026-05-15T02:53:39.458008Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:39.457842551Z, server: 2026-05-15T02:53:39.457858991Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.457862811Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10µs 130ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:39.457852681Z [3mdelta[0m[2m=[0m6µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:39.458175Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.875µs [3mdelta[0m[2m=[0m4s 999ms 999µs 175ns ago
[INFO] [stdout] [2m2026-05-15T02:53:39.458203Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.001725963s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.458107Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.705µs [3mdelta[0m[2m=[0m5s 6µs 215ns
[INFO] [stdout] [2m2026-05-15T02:53:39.458219Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.13µs [3mdelta[0m[2m=[0m6µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:39.458238Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m174.412702ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.458283Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m6µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:39.458302Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m74.080251ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.533932Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:39.53375596Z, server: 2026-05-15T02:53:39.53377217Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.5337702Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 120ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:39.53376308Z [3mdelta[0m[2m=[0m9µs 90ns
[INFO] [stdout] [2m2026-05-15T02:53:39.534019Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.12µs [3mdelta[0m[2m=[0m9µs 90ns
[INFO] [stdout] [2m2026-05-15T02:53:39.534042Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.923018673s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.633846Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:39.633682199Z, server: 2026-05-15T02:53:44.633691429Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.633695579Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 690ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:39.633688889Z [3mdelta[0m[2m=[0m5s 2µs 540ns
[INFO] [stdout] [2m2026-05-15T02:53:39.633922Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.69µs [3mdelta[0m[2m=[0m5s 2µs 540ns
[INFO] [stdout] [2m2026-05-15T02:53:39.633940Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m295.822832ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:39.930656Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:39.930492426Z, server: 2026-05-15T02:53:44.930501316Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:39.930504956Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 265ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:39.930498691Z [3mdelta[0m[2m=[0m5s 2µs 625ns
[INFO] [stdout] [2m2026-05-15T02:53:39.930730Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.265µs [3mdelta[0m[2m=[0m5s 2µs 625ns
[INFO] [stdout] [2m2026-05-15T02:53:39.930750Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m805.737642ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:40.460648Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:40.46047921Z, server: 2026-05-15T02:53:35.460487891Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:40.460491641Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 215ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:40.460485425Z [3mdelta[0m[2m=[0m4s 999ms 997µs 534ns ago
[INFO] [stdout] [2m2026-05-15T02:53:40.460734Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.215µs [3mdelta[0m[2m=[0m4s 999ms 997µs 534ns ago
[INFO] [stdout] [2m2026-05-15T02:53:40.460758Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m43.759238ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:40.506339Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:40.50616968Z, server: 2026-05-15T02:53:35.50617825Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:40.50618214Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 230ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:40.50617591Z [3mdelta[0m[2m=[0m4s 999ms 997µs 660ns ago
[INFO] [stdout] [2m2026-05-15T02:53:40.506421Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.23µs [3mdelta[0m[2m=[0m4s 999ms 997µs 660ns ago
[INFO] [stdout] [2m2026-05-15T02:53:40.506444Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m489.080509ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:40.737896Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:40.737732968Z, server: 2026-05-15T02:53:45.737742338Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:40.737746178Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 605ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:40.737739573Z [3mdelta[0m[2m=[0m5s 2µs 765ns
[INFO] [stdout] [2m2026-05-15T02:53:40.737969Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.605µs [3mdelta[0m[2m=[0m5s 2µs 765ns
[INFO] [stdout] [2m2026-05-15T02:53:40.737989Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.226484755s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:40.997497Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:40.997303135Z, server: 2026-05-15T02:53:35.997312825Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:40.997316995Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 930ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:40.997310065Z [3mdelta[0m[2m=[0m4s 999ms 997µs 240ns ago
[INFO] [stdout] [2m2026-05-15T02:53:40.997586Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.93µs [3mdelta[0m[2m=[0m4s 999ms 997µs 240ns ago
[INFO] [stdout] [2m2026-05-15T02:53:40.997610Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.605770703s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:41.291355Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:41.291219872Z, server: 2026-05-15T02:53:41.291228892Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:41.291231681Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5µs 904ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:41.291225776Z [3mdelta[0m[2m=[0m3µs 116ns
[INFO] [stdout] [2m2026-05-15T02:53:41.291413Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.904µs [3mdelta[0m[2m=[0m3µs 116ns
[INFO] [stdout] [2m2026-05-15T02:53:41.291427Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.732837614s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:41.458512Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:41.45832615Z, server: 2026-05-15T02:53:41.45834182Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:41.458339519Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 684ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:41.458332834Z [3mdelta[0m[2m=[0m8µs 986ns
[INFO] [stdout] [2m2026-05-15T02:53:41.458596Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.684µs [3mdelta[0m[2m=[0m8µs 986ns
[INFO] [stdout] [2m2026-05-15T02:53:41.458618Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.865190982s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:41.965759Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:41.965581234Z, server: 2026-05-15T02:53:46.965589804Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:41.965593924Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 345ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:41.965587579Z [3mdelta[0m[2m=[0m5s 2µs 225ns
[INFO] [stdout] [2m2026-05-15T02:53:41.965848Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.345µs [3mdelta[0m[2m=[0m5s 2µs 225ns
[INFO] [stdout] [2m2026-05-15T02:53:41.965883Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.002625, 5000.002225, 5000.002765, 5000.00254, 5000.006215]
[INFO] [stdout] [2m2026-05-15T02:53:41.965906Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.002765 [3mmean[0m[2m=[0m5000.003274000001 [3mvariance[0m[2m=[0m2.742230000181116e-6 [3mstddev[0m[2m=[0m0.00165596799491449
[INFO] [stdout] [2m2026-05-15T02:53:41.965927Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.002625, 5000.002225, 5000.002765, 5000.00254]
[INFO] [stdout] [2m2026-05-15T02:53:41.965941Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-05-15T02:53:42.604624Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:42.604429137Z, server: 2026-05-15T02:53:37.604439407Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:42.604443637Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 250ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:42.604436387Z [3mdelta[0m[2m=[0m4s 999ms 996µs 980ns ago
[INFO] [stdout] [2m2026-05-15T02:53:42.604723Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.25µs [3mdelta[0m[2m=[0m4s 999ms 996µs 980ns ago
[INFO] [stdout] [2m2026-05-15T02:53:42.604753Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.999175, -4999.997534, -4999.99766, -4999.99724, -4999.99698]
[INFO] [stdout] [2m2026-05-15T02:53:42.604781Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.99766 [3mmean[0m[2m=[0m-4999.9977178 [3mvariance[0m[2m=[0m7.332992000484969e-7 [3mstddev[0m[2m=[0m0.0008563289088011083
[INFO] [stdout] [2m2026-05-15T02:53:42.604810Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.997534, -4999.99766, -4999.99724, -4999.99698]
[INFO] [stdout] [2m2026-05-15T02:53:42.604825Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-05-15T02:53:43.025661Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:43.025496153Z, server: 2026-05-15T02:53:43.025505653Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:43.025509563Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 705ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:43.025502858Z [3mdelta[0m[2m=[0m2µs 795ns
[INFO] [stdout] [2m2026-05-15T02:53:43.025740Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.705µs [3mdelta[0m[2m=[0m2µs 795ns
[INFO] [stdout] [2m2026-05-15T02:53:43.025761Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.717334826s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:43.324941Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:43.324790039Z, server: 2026-05-15T02:53:43.324805569Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:43.324802559Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 260ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:43.324796299Z [3mdelta[0m[2m=[0m9µs 270ns
[INFO] [stdout] [2m2026-05-15T02:53:43.325013Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.26µs [3mdelta[0m[2m=[0m9µs 270ns
[INFO] [stdout] [2m2026-05-15T02:53:43.325030Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.327614281s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:44.653851Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:44.653694335Z, server: 2026-05-15T02:53:44.653709735Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:44.653706515Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 90ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:44.653700425Z [3mdelta[0m[2m=[0m9µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:44.653922Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.09µs [3mdelta[0m[2m=[0m9µs 310ns
[INFO] [stdout] [2m2026-05-15T02:53:44.653943Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00931, 0.00927, 0.008986, 0.00909, 0.00631]
[INFO] [stdout] [2m2026-05-15T02:53:44.653960Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.008986 [3mmean[0m[2m=[0m0.0085932 [3mvariance[0m[2m=[0m1.646491200000001e-6 [3mstddev[0m[2m=[0m0.0012831567324376244
[INFO] [stdout] [2m2026-05-15T02:53:44.653978Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00931, 0.00927, 0.008986, 0.00909]
[INFO] [stdout] [2m2026-05-15T02:53:44.653991Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m9µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] [2m2026-05-15T02:53:44.743647Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:44.743489384Z, server: 2026-05-15T02:53:44.743499094Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:44.743501954Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 285ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:44.743495669Z [3mdelta[0m[2m=[0m3µs 425ns
[INFO] [stdout] [2m2026-05-15T02:53:44.743721Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.285µs [3mdelta[0m[2m=[0m3µs 425ns
[INFO] [stdout] [2m2026-05-15T02:53:44.743739Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m905.637336ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:53:45.651058Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:53:45.650907584Z, server: 2026-05-15T02:53:45.650917204Z } [3mcurrent[0m[2m=[0m2026-05-15T02:53:45.650920284Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 350ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:53:45.650913934Z [3mdelta[0m[2m=[0m3µs 270ns
[INFO] [stdout] [2m2026-05-15T02:53:45.651123Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.35µs [3mdelta[0m[2m=[0m3µs 270ns
[INFO] [stdout] [2m2026-05-15T02:53:45.651176Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000745, 0.003116, 0.003425, 0.00327, 0.002795]
[INFO] [stdout] [2m2026-05-15T02:53:45.651191Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.003425 [3mmean[0m[2m=[0m0.0026702 [3mvariance[0m[2m=[0m1.2125477e-6 [3mstddev[0m[2m=[0m0.0011011574365185025
[INFO] [stdout] [2m2026-05-15T02:53:45.651213Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.003116, 0.003425, 0.00327, 0.002795]
[INFO] [stdout] [2m2026-05-15T02:53:45.651223Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µ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 6.20s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-f8424559dfcf15b0)
[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 0.69s; merged doctests compilation took 0.68s
[INFO] running `Command { std: "docker" "inspect" "0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21", kill_on_drop: false }`
[INFO] [stdout] 0d69d5e8e9f0770b9470c61a01d2ea9eb17fbb59b3473922fd7866b67abffc21
