[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 master#ec6f9a5b4413f74386267ef8efc93712c2ce6db6 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-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-4-tc1/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-4-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain ec6f9a5b4413f74386267ef8efc93712c2ce6db6
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "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" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded ctor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded napi-sys v3.0.0-alpha.1
[INFO] [stderr]   Downloaded ctor v0.4.2
[INFO] [stderr]   Downloaded dtor v0.0.6
[INFO] [stderr]   Downloaded dtor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded napi-build v2.1.6
[INFO] [stderr]   Downloaded napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]   Downloaded convert_case v0.8.0
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded napi-derive v3.0.0-alpha.29
[INFO] [stderr]   Downloaded napi v3.0.0-alpha.33
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb
[INFO] running `Command { std: "docker" "start" "-a" "cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb", kill_on_drop: false }`
[INFO] [stdout] cf3c06e60af64c8ff35d697a590999f66e5fc87e58f3ca053b6d1d355ad2a0fb
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f
[INFO] running `Command { std: "docker" "start" "-a" "2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling 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 serde_json v1.0.140
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[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 v3.0.0-alpha.33
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[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 27.81s
[INFO] running `Command { std: "docker" "inspect" "2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f", kill_on_drop: false }`
[INFO] [stdout] 2440e8ed912a1354e238f8873a3127808fac714bc1e8e236a0da98aae4093d8f
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7
[INFO] running `Command { std: "docker" "start" "-a" "6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7", 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 writeable v0.5.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[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 openssl v0.10.72
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling futures-util v0.3.31
[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 rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling indexmap v2.9.0
[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 openssl-sys v0.9.107
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling 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 zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling yoke v0.7.5
[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 icu_normalizer v1.5.0
[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 idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling h2 v0.4.9
[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 47.70s
[INFO] running `Command { std: "docker" "inspect" "6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7", kill_on_drop: false }`
[INFO] [stdout] 6988c051d8fb3a8d5b1467cfcdebb60642e5cc52775c0e33c9d01bbed04185b7
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6
[INFO] running `Command { std: "docker" "start" "-a" "fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.31s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-7875ddb3df0d84b6)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.14s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-f04346ec9fba397a)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-05-15T02:52:13.221668Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.221733Z[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:52:13.221666Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.221758Z[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:52:13.221872Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.221903Z[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:52:13.221662Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-05-15T02:52:13.221958Z[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:52:13.222392Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.222430Z[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:52:13.222523Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.222598Z[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:52:13.226202Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.226338Z[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:52:13.233442Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.227809347Z, server: 2026-05-15T02:52:13.230211947Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.233225797Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 708µs 225ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.230517572Z [3mdelta[0m[2m=[0m305µs 625ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.233538Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.708225ms [3mdelta[0m[2m=[0m305µs 625ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.233567Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m305µs 625ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.233581Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m100.274858ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.241509Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.223840647Z, server: 2026-05-15T02:52:18.229000787Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.241281937Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 720µs 645ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.232561292Z [3mdelta[0m[2m=[0m4s 996ms 439µs 495ns
[INFO] [stdout] [2m2026-05-15T02:52:13.241611Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.720645ms [3mdelta[0m[2m=[0m4s 996ms 439µs 495ns
[INFO] [stdout] [2m2026-05-15T02:52:13.241635Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 996ms 439µs 495ns
[INFO] [stdout] [2m2026-05-15T02:52:13.241650Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.947499777s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.245201Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.223626567Z, server: 2026-05-15T02:52:18.233763377Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.244947207Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 660µs 320ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.234286887Z [3mdelta[0m[2m=[0m4s 999ms 476µs 490ns
[INFO] [stdout] [2m2026-05-15T02:52:13.245297Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.66032ms [3mdelta[0m[2m=[0m4s 999ms 476µs 490ns
[INFO] [stdout] [2m2026-05-15T02:52:13.245322Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 476µs 490ns
[INFO] [stdout] [2m2026-05-15T02:52:13.245340Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.445663882s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.250225Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.227623967Z, server: 2026-05-15T02:52:08.238809827Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.250000377Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 188µs 205ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.238812172Z [3mdelta[0m[2m=[0m5s 2µs 345ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.250388Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.188205ms [3mdelta[0m[2m=[0m5s 2µs 345ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.250614Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 2µs 345ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.250914Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m942.412887ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.252005Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.252319Z[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:52:13.256211Z[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:52:13.256322Z[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:52:13.252526Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:13.256383Z[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:52:13.276256Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.257655257Z, server: 2026-05-15T02:52:18.266821726Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.276005906Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 175µs 324ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.266830581Z [3mdelta[0m[2m=[0m4s 999ms 991µs 145ns
[INFO] [stdout] [2m2026-05-15T02:52:13.276356Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.175324ms [3mdelta[0m[2m=[0m4s 999ms 991µs 145ns
[INFO] [stdout] [2m2026-05-15T02:52:13.276382Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 991µs 145ns
[INFO] [stdout] [2m2026-05-15T02:52:13.276398Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.778543963s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.279980Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.257575837Z, server: 2026-05-15T02:52:13.268705217Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.279848466Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 136µs 314ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.268712151Z [3mdelta[0m[2m=[0m6µs 934ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.280128Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.136314ms [3mdelta[0m[2m=[0m6µs 934ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.280206Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m520.484414ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.292189Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.223090927Z, server: 2026-05-15T02:52:18.234220927Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.291960266Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m34ms 434µs 669ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.257525596Z [3mdelta[0m[2m=[0m4s 976ms 695µs 331ns
[INFO] [stdout] [2m2026-05-15T02:52:13.292389Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.223183247Z, server: 2026-05-15T02:52:13.234290227Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.292294076Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m34ms 555µs 414ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.257738661Z [3mdelta[0m[2m=[0m23ms 448µs 434ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.292469Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m34.555414ms [3mdelta[0m[2m=[0m23ms 448µs 434ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.292493Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m451.041085ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.292562Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m34.434669ms [3mdelta[0m[2m=[0m4s 976ms 695µs 331ns
[INFO] [stdout] [2m2026-05-15T02:52:13.292582Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 976ms 695µs 331ns
[INFO] [stdout] [2m2026-05-15T02:52:13.292595Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m718.939152ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.337435Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.334985946Z, server: 2026-05-15T02:52:13.336131666Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.337271476Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 142µs 765ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.336128711Z [3mdelta[0m[2m=[0m2µs 955ns
[INFO] [stdout] [2m2026-05-15T02:52:13.337532Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.142765ms [3mdelta[0m[2m=[0m2µs 955ns
[INFO] [stdout] [2m2026-05-15T02:52:13.337554Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.960373369s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.427462Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.222964437Z, server: 2026-05-15T02:52:13.325247876Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.427250345Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m102ms 142µs 954ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.325107391Z [3mdelta[0m[2m=[0m140µs 485ns
[INFO] [stdout] [2m2026-05-15T02:52:13.427558Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m102.142954ms [3mdelta[0m[2m=[0m140µs 485ns
[INFO] [stdout] [2m2026-05-15T02:52:13.427583Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m140µs 485ns
[INFO] [stdout] [2m2026-05-15T02:52:13.427598Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m771.011869ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.774001Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.745250091Z, server: 2026-05-15T02:52:13.762603411Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.773812511Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 281µs 210ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.759531301Z [3mdelta[0m[2m=[0m3ms 72µs 110ns
[INFO] [stdout] [2m2026-05-15T02:52:13.774098Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.28121ms [3mdelta[0m[2m=[0m3ms 72µs 110ns
[INFO] [stdout] [2m2026-05-15T02:52:13.774124Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m194.810775ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.824622Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.80204716Z, server: 2026-05-15T02:52:13.8132375Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.82442843Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 190µs 635ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.813237795Z [3mdelta[0m[2m=[0m295ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.824720Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.190635ms [3mdelta[0m[2m=[0m295ns ago
[INFO] [stdout] [2m2026-05-15T02:52:13.824744Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m862.687717ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:13.993569Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.969643708Z, server: 2026-05-15T02:52:13.982253458Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:13.993396148Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 876µs 220ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:13.981519928Z [3mdelta[0m[2m=[0m733µs 530ns
[INFO] [stdout] [2m2026-05-15T02:52:13.993744Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.87622ms [3mdelta[0m[2m=[0m733µs 530ns
[INFO] [stdout] [2m2026-05-15T02:52:13.993822Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.199666158s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:14.035040Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:14.012446768Z, server: 2026-05-15T02:52:19.023652308Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:14.034857817Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 205µs 524ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:14.023652292Z [3mdelta[0m[2m=[0m5s 16ns
[INFO] [stdout] [2m2026-05-15T02:52:14.035256Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.205524ms [3mdelta[0m[2m=[0m5s 16ns
[INFO] [stdout] [2m2026-05-15T02:52:14.035336Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.19202038s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:14.219420Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:14.196393506Z, server: 2026-05-15T02:52:09.207599915Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:14.219247305Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 426µs 899ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:14.207820405Z [3mdelta[0m[2m=[0m5s 220µs 490ns ago
[INFO] [stdout] [2m2026-05-15T02:52:14.219514Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.426899ms [3mdelta[0m[2m=[0m5s 220µs 490ns ago
[INFO] [stdout] [2m2026-05-15T02:52:14.219537Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.198438158s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:14.403287Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:14.200378815Z, server: 2026-05-15T02:52:14.301718034Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:14.403076263Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 348µs 724ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:14.301727539Z [3mdelta[0m[2m=[0m9µs 505ns ago
[INFO] [stdout] [2m2026-05-15T02:52:14.403377Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.348724ms [3mdelta[0m[2m=[0m9µs 505ns ago
[INFO] [stdout] [2m2026-05-15T02:52:14.403401Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.171020175s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:14.712439Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:14.68940636Z, server: 2026-05-15T02:52:14.70061045Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:14.712249129Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 421µs 384ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:14.700827744Z [3mdelta[0m[2m=[0m217µs 294ns ago
[INFO] [stdout] [2m2026-05-15T02:52:14.712555Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.421384ms [3mdelta[0m[2m=[0m217µs 294ns ago
[INFO] [stdout] [2m2026-05-15T02:52:14.712582Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.029600699s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:14.715913Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:14.69424317Z, server: 2026-05-15T02:52:19.704537529Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:14.715737409Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 747µs 119ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:14.704990289Z [3mdelta[0m[2m=[0m4s 999ms 547µs 240ns
[INFO] [stdout] [2m2026-05-15T02:52:14.716008Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.747119ms [3mdelta[0m[2m=[0m4s 999ms 547µs 240ns
[INFO] [stdout] [2m2026-05-15T02:52:14.716032Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m114.821889ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:14.852988Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:14.832386848Z, server: 2026-05-15T02:52:19.842590688Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:14.852799968Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 206µs 560ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:14.842593408Z [3mdelta[0m[2m=[0m4s 999ms 997µs 280ns
[INFO] [stdout] [2m2026-05-15T02:52:14.853078Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.20656ms [3mdelta[0m[2m=[0m4s 999ms 997µs 280ns
[INFO] [stdout] [2m2026-05-15T02:52:14.853101Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.034192331s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.076430Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.058251996Z, server: 2026-05-15T02:52:20.067239635Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.076245015Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 996µs 509ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.067248505Z [3mdelta[0m[2m=[0m4s 999ms 991µs 130ns
[INFO] [stdout] [2m2026-05-15T02:52:15.076537Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.996509ms [3mdelta[0m[2m=[0m4s 999ms 991µs 130ns
[INFO] [stdout] [2m2026-05-15T02:52:15.076562Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.902537872s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.155464Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:13.257496937Z, server: 2026-05-15T02:52:14.205419255Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.155254264Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m948ms 878µs 663ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:14.2063756Z [3mdelta[0m[2m=[0m956µs 345ns ago
[INFO] [stdout] [2m2026-05-15T02:52:15.155562Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m948.878663ms [3mdelta[0m[2m=[0m956µs 345ns ago
[INFO] [stdout] [2m2026-05-15T02:52:15.155586Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m956µs 345ns ago
[INFO] [stdout] [2m2026-05-15T02:52:15.155599Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m328.330672ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.206966Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.190400244Z, server: 2026-05-15T02:52:20.198591614Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.206781014Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 190µs 385ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.198590629Z [3mdelta[0m[2m=[0m5s 985ns
[INFO] [stdout] [2m2026-05-15T02:52:15.207073Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.190385ms [3mdelta[0m[2m=[0m5s 985ns
[INFO] [stdout] [2m2026-05-15T02:52:15.207103Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m37.323695ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.218095Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.195402264Z, server: 2026-05-15T02:52:15.206726834Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.217919634Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 258µs 685ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.206660949Z [3mdelta[0m[2m=[0m65µs 885ns
[INFO] [stdout] [2m2026-05-15T02:52:15.218217Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.258685ms [3mdelta[0m[2m=[0m65µs 885ns
[INFO] [stdout] [2m2026-05-15T02:52:15.218241Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m620.587142ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.251110Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.228525423Z, server: 2026-05-15T02:52:20.239721693Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.250925873Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 200µs 225ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.239725648Z [3mdelta[0m[2m=[0m4s 999ms 996µs 45ns
[INFO] [stdout] [2m2026-05-15T02:52:15.251254Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.200225ms [3mdelta[0m[2m=[0m4s 999ms 996µs 45ns
[INFO] [stdout] [2m2026-05-15T02:52:15.251278Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m633.904248ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.258845Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.246355333Z, server: 2026-05-15T02:52:20.252526673Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.258678583Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 161µs 625ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.252516958Z [3mdelta[0m[2m=[0m5s 9µs 715ns
[INFO] [stdout] [2m2026-05-15T02:52:15.258930Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.161625ms [3mdelta[0m[2m=[0m5s 9µs 715ns
[INFO] [stdout] [2m2026-05-15T02:52:15.258950Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.79484218s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.302018Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.299533433Z, server: 2026-05-15T02:52:15.300692473Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.301828823Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 147µs 695ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.300681128Z [3mdelta[0m[2m=[0m11µs 345ns
[INFO] [stdout] [2m2026-05-15T02:52:15.302244Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.147695ms [3mdelta[0m[2m=[0m11µs 345ns
[INFO] [stdout] [2m2026-05-15T02:52:15.302285Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.446394315s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.442649Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.419398091Z, server: 2026-05-15T02:52:10.431275231Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.442474581Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 538µs 245ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.430936336Z [3mdelta[0m[2m=[0m4s 999ms 661µs 105ns ago
[INFO] [stdout] [2m2026-05-15T02:52:15.442745Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.538245ms [3mdelta[0m[2m=[0m4s 999ms 661µs 105ns ago
[INFO] [stdout] [2m2026-05-15T02:52:15.442771Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.976376098s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.778427Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.748253317Z, server: 2026-05-15T02:52:15.763247817Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.778250437Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 998µs 560ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.763251877Z [3mdelta[0m[2m=[0m4µs 60ns ago
[INFO] [stdout] [2m2026-05-15T02:52:15.778522Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.99856ms [3mdelta[0m[2m=[0m4µs 60ns ago
[INFO] [stdout] [2m2026-05-15T02:52:15.778542Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m259.869755ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.789425Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.581253539Z, server: 2026-05-15T02:52:15.687246998Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.789237957Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m103ms 992µs 209ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.685245748Z [3mdelta[0m[2m=[0m2ms 1µs 250ns
[INFO] [stdout] [2m2026-05-15T02:52:15.789534Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m103.992209ms [3mdelta[0m[2m=[0m2ms 1µs 250ns
[INFO] [stdout] [2m2026-05-15T02:52:15.789557Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.634780818s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.863079Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.840398826Z, server: 2026-05-15T02:52:15.851715566Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.862908256Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 254µs 715ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.851653541Z [3mdelta[0m[2m=[0m62µs 25ns
[INFO] [stdout] [2m2026-05-15T02:52:15.863189Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.254715ms [3mdelta[0m[2m=[0m62µs 25ns
[INFO] [stdout] [2m2026-05-15T02:52:15.863268Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.062025, 0.065885, 0.73353, 3.07211, -23.448434]
[INFO] [stdout] [2m2026-05-15T02:52:15.863319Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.73353 [3mmean[0m[2m=[0m-3.9029768 [3mvariance[0m[2m=[0m120.91175789812868 [3mstddev[0m[2m=[0m10.995988263822797
[INFO] [stdout] [2m2026-05-15T02:52:15.863347Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.062025, 0.065885, 0.73353, 3.07211]
[INFO] [stdout] [2m2026-05-15T02:52:15.863362Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m983µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-05-15T02:52:15.908741Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.886168566Z, server: 2026-05-15T02:52:20.897367626Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.908567655Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 199µs 544ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.89736811Z [3mdelta[0m[2m=[0m4s 999ms 999µs 516ns
[INFO] [stdout] [2m2026-05-15T02:52:15.908829Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.199544ms [3mdelta[0m[2m=[0m4s 999ms 999µs 516ns
[INFO] [stdout] [2m2026-05-15T02:52:15.908853Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m907.571486ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:15.911032Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.888402256Z, server: 2026-05-15T02:52:20.899619726Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:15.910836226Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 216µs 985ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:15.899619241Z [3mdelta[0m[2m=[0m5s 485ns
[INFO] [stdout] [2m2026-05-15T02:52:15.911188Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.216985ms [3mdelta[0m[2m=[0m5s 485ns
[INFO] [stdout] [2m2026-05-15T02:52:15.911215Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.015196645s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:16.062674Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:16.040089144Z, server: 2026-05-15T02:52:16.051282664Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:16.062491204Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 201µs 30ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:16.051290174Z [3mdelta[0m[2m=[0m7µs 510ns ago
[INFO] [stdout] [2m2026-05-15T02:52:16.062845Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.20103ms [3mdelta[0m[2m=[0m7µs 510ns ago
[INFO] [stdout] [2m2026-05-15T02:52:16.062942Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.006934, -0.000295, -0.00751, -0.217294, -0.00406]
[INFO] [stdout] [2m2026-05-15T02:52:16.063020Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.00751 [3mmean[0m[2m=[0m-0.0472186 [3mvariance[0m[2m=[0m0.009047438146799999 [3mstddev[0m[2m=[0m0.0951180221976887
[INFO] [stdout] [2m2026-05-15T02:52:16.063100Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.006934, -0.000295, -0.00751, -0.00406]
[INFO] [stdout] [2m2026-05-15T02:52:16.063186Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-05-15T02:52:16.752861Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:16.750413706Z, server: 2026-05-15T02:52:16.751566386Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:16.752683585Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 134µs 939ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:16.751548645Z [3mdelta[0m[2m=[0m17µs 741ns
[INFO] [stdout] [2m2026-05-15T02:52:16.752956Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.134939ms [3mdelta[0m[2m=[0m17µs 741ns
[INFO] [stdout] [2m2026-05-15T02:52:16.752978Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m154.821715ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:16.842844Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:16.820256475Z, server: 2026-05-15T02:52:21.831470225Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:16.842673795Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 208µs 660ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:16.831465135Z [3mdelta[0m[2m=[0m5s 5µs 90ns
[INFO] [stdout] [2m2026-05-15T02:52:16.842930Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.20866ms [3mdelta[0m[2m=[0m5s 5µs 90ns
[INFO] [stdout] [2m2026-05-15T02:52:16.842957Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.999516, 4999.996045, 5000.000016, 5000.00509, 4976.695331]
[INFO] [stdout] [2m2026-05-15T02:52:16.842974Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.000016 [3mmean[0m[2m=[0m4995.3391996 [3mvariance[0m[2m=[0m108.62308428524872 [3mstddev[0m[2m=[0m10.422239888107006
[INFO] [stdout] [2m2026-05-15T02:52:16.842991Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.999516, 4999.996045, 5000.000016, 5000.00509]
[INFO] [stdout] [2m2026-05-15T02:52:16.843007Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-05-15T02:52:16.913737Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:16.911294444Z, server: 2026-05-15T02:52:16.912444674Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:16.913571554Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 138µs 555ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:16.912432999Z [3mdelta[0m[2m=[0m11µs 675ns
[INFO] [stdout] [2m2026-05-15T02:52:16.913836Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.138555ms [3mdelta[0m[2m=[0m11µs 675ns
[INFO] [stdout] [2m2026-05-15T02:52:16.913865Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.017741, 0.011675, 0.002955, 0.011345, -0.305625]
[INFO] [stdout] [2m2026-05-15T02:52:16.913884Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.002955 [3mmean[0m[2m=[0m-0.0523818 [3mvariance[0m[2m=[0m0.0200689663812 [3mstddev[0m[2m=[0m0.14166497937457936
[INFO] [stdout] [2m2026-05-15T02:52:16.913904Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.017741, 0.011675, 0.002955, 0.011345]
[INFO] [stdout] [2m2026-05-15T02:52:16.913918Z[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:52:16.950995Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:16.930248143Z, server: 2026-05-15T02:52:21.940597283Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:16.950807183Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 279µs 520ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:16.940527663Z [3mdelta[0m[2m=[0m5s 69µs 620ns
[INFO] [stdout] [2m2026-05-15T02:52:16.951090Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.27952ms [3mdelta[0m[2m=[0m5s 69µs 620ns
[INFO] [stdout] [2m2026-05-15T02:52:16.951122Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.99728, 5000.06962, 4999.47649, 4999.54724, 5000.000485]
[INFO] [stdout] [2m2026-05-15T02:52:16.951190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.47649 [3mmean[0m[2m=[0m4999.818223 [3mvariance[0m[2m=[0m0.07967363176996609 [3mstddev[0m[2m=[0m0.28226517987517713
[INFO] [stdout] [2m2026-05-15T02:52:16.951221Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.47649, 4999.54724]
[INFO] [stdout] [2m2026-05-15T02:52:16.951235Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 511µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-05-15T02:52:17.011461Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:16.984261603Z, server: 2026-05-15T02:52:21.999257783Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:17.011268082Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 503µs 239ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:16.997764842Z [3mdelta[0m[2m=[0m5s 1ms 492µs 941ns
[INFO] [stdout] [2m2026-05-15T02:52:17.011625Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.503239ms [3mdelta[0m[2m=[0m5s 1ms 492µs 941ns
[INFO] [stdout] [2m2026-05-15T02:52:17.011652Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.545714985s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:17.030431Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:15.49024789Z, server: 2026-05-15T02:52:16.260404061Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:17.030252752Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m770ms 2µs 431ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:16.260250321Z [3mdelta[0m[2m=[0m153µs 740ns
[INFO] [stdout] [2m2026-05-15T02:52:17.030531Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m770.002431ms [3mdelta[0m[2m=[0m153µs 740ns
[INFO] [stdout] [2m2026-05-15T02:52:17.030582Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.162388651s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:17.069953Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:17.055369402Z, server: 2026-05-15T02:52:22.062576302Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:17.069778372Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 204µs 485ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:17.062573887Z [3mdelta[0m[2m=[0m5s 2µs 415ns
[INFO] [stdout] [2m2026-05-15T02:52:17.070044Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.204485ms [3mdelta[0m[2m=[0m5s 2µs 415ns
[INFO] [stdout] [2m2026-05-15T02:52:17.070066Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.595493761s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:17.443175Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:17.420558308Z, server: 2026-05-15T02:52:12.431759568Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:17.442962167Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 201µs 929ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:17.431760237Z [3mdelta[0m[2m=[0m5s 669ns ago
[INFO] [stdout] [2m2026-05-15T02:52:17.443268Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.201929ms [3mdelta[0m[2m=[0m5s 669ns ago
[INFO] [stdout] [2m2026-05-15T02:52:17.443291Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.171019404s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:17.627502Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:17.425556168Z, server: 2026-05-15T02:52:17.525940636Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:17.627313415Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 878µs 623ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:17.526434791Z [3mdelta[0m[2m=[0m494µs 155ns ago
[INFO] [stdout] [2m2026-05-15T02:52:17.627595Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.878623ms [3mdelta[0m[2m=[0m494µs 155ns ago
[INFO] [stdout] [2m2026-05-15T02:52:17.627618Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m413.547176ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:18.244958Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:18.04234149Z, server: 2026-05-15T02:52:18.143393569Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:18.244775008Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 216µs 759ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:18.143558249Z [3mdelta[0m[2m=[0m164µs 680ns ago
[INFO] [stdout] [2m2026-05-15T02:52:18.245053Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.216759ms [3mdelta[0m[2m=[0m164µs 680ns ago
[INFO] [stdout] [2m2026-05-15T02:52:18.245084Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.494155, -0.16468, -0.009505, 0.140485, 2.00125]
[INFO] [stdout] [2m2026-05-15T02:52:18.245104Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.009505 [3mmean[0m[2m=[0m0.294679 [3mvariance[0m[2m=[0m0.9654895109925004 [3mstddev[0m[2m=[0m0.9825932581656055
[INFO] [stdout] [2m2026-05-15T02:52:18.245124Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.494155, -0.16468, -0.009505, 0.140485]
[INFO] [stdout] [2m2026-05-15T02:52:18.245170Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m131µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-05-15T02:52:18.595433Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:18.565262824Z, server: 2026-05-15T02:52:23.580253024Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:18.595251024Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 994µs 100ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:18.580256924Z [3mdelta[0m[2m=[0m4s 999ms 996µs 100ns
[INFO] [stdout] [2m2026-05-15T02:52:18.595522Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.9941ms [3mdelta[0m[2m=[0m4s 999ms 996µs 100ns
[INFO] [stdout] [2m2026-05-15T02:52:18.595545Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.861868097s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:18.647439Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:18.620247234Z, server: 2026-05-15T02:52:13.635248873Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:18.647258553Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 505µs 659ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:18.633752893Z [3mdelta[0m[2m=[0m4s 998ms 504µs 20ns ago
[INFO] [stdout] [2m2026-05-15T02:52:18.647545Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.505659ms [3mdelta[0m[2m=[0m4s 998ms 504µs 20ns ago
[INFO] [stdout] [2m2026-05-15T02:52:18.647575Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-5000.002345, -5000.000669, -5000.22049, -4999.661105, -4998.50402]
[INFO] [stdout] [2m2026-05-15T02:52:18.647595Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.22049 [3mmean[0m[2m=[0m-4999.6777258 [3mvariance[0m[2m=[0m0.4705311170454184 [3mstddev[0m[2m=[0m0.6859527075866225
[INFO] [stdout] [2m2026-05-15T02:52:18.647614Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-5000.002345, -5000.000669, -5000.22049, -4999.661105]
[INFO] [stdout] [2m2026-05-15T02:52:18.647626Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 971µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-05-15T02:52:18.675955Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:18.667389923Z, server: 2026-05-15T02:52:23.671581193Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:18.675777583Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 193µs 830ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:18.671583753Z [3mdelta[0m[2m=[0m4s 999ms 997µs 440ns
[INFO] [stdout] [2m2026-05-15T02:52:18.676051Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.19383ms [3mdelta[0m[2m=[0m4s 999ms 997µs 440ns
[INFO] [stdout] [2m2026-05-15T02:52:18.676080Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.99744, 5000.009715, 5000.002415, 5000.000985, 4996.439495]
[INFO] [stdout] [2m2026-05-15T02:52:18.676100Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.002415 [3mmean[0m[2m=[0m4999.290009999999 [3mvariance[0m[2m=[0m2.539218647950479 [3mstddev[0m[2m=[0m1.5934925942565528
[INFO] [stdout] [2m2026-05-15T02:52:18.676131Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.99744, 5000.009715, 5000.002415, 5000.000985]
[INFO] [stdout] [2m2026-05-15T02:52:18.676169Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 2µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-05-15T02:52:19.678589Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:18.194430228Z, server: 2026-05-15T02:52:18.93640975Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:19.678406161Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m741ms 987µs 966ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:18.936418194Z [3mdelta[0m[2m=[0m8µs 444ns ago
[INFO] [stdout] [2m2026-05-15T02:52:19.678677Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m741.987966ms [3mdelta[0m[2m=[0m8µs 444ns ago
[INFO] [stdout] [2m2026-05-15T02:52:19.678699Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.968518598s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:20.474993Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:20.458390032Z, server: 2026-05-15T02:52:25.466609052Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:20.474804081Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 207µs 24ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:20.466597056Z [3mdelta[0m[2m=[0m5s 11µs 996ns
[INFO] [stdout] [2m2026-05-15T02:52:20.475170Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.207024ms [3mdelta[0m[2m=[0m5s 11µs 996ns
[INFO] [stdout] [2m2026-05-15T02:52:20.475244Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.011996, 4999.99113, 4999.991145, 5001.492941, 4999.9961]
[INFO] [stdout] [2m2026-05-15T02:52:20.475287Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.991145 [3mmean[0m[2m=[0m5000.2966624 [3mvariance[0m[2m=[0m0.44728653338843993 [3mstddev[0m[2m=[0m0.668794836544392
[INFO] [stdout] [2m2026-05-15T02:52:20.475336Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.011996, 4999.99113, 4999.991145, 4999.9961]
[INFO] [stdout] [2m2026-05-15T02:52:20.475371Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 997µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-05-15T02:52:23.302425Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:21.647684578Z, server: 2026-05-15T02:52:22.474372098Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:23.302250638Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m827ms 283µs 30ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:22.474967608Z [3mdelta[0m[2m=[0m595µs 510ns ago
[INFO] [stdout] [2m2026-05-15T02:52:23.302521Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m827.28303ms [3mdelta[0m[2m=[0m595µs 510ns ago
[INFO] [stdout] [2m2026-05-15T02:52:23.302546Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m289.395116ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:25.353531Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:23.593117825Z, server: 2026-05-15T02:52:24.473324614Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:25.353353914Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m880ms 118µs 44ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:24.473235869Z [3mdelta[0m[2m=[0m88µs 745ns
[INFO] [stdout] [2m2026-05-15T02:52:25.353621Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m880.118044ms [3mdelta[0m[2m=[0m88µs 745ns
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-2e65c6dffb129287)
[INFO] [stdout] [2m2026-05-15T02:52:25.353651Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.008444, 0.15374, -0.59551, 0.088745, -0.956345]
[INFO] [stdout] [2m2026-05-15T02:52:25.353670Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.59551 [3mmean[0m[2m=[0m-0.2635628 [3mvariance[0m[2m=[0m0.2383710337917 [3mstddev[0m[2m=[0m0.4882325611752047
[INFO] [stdout] [2m2026-05-15T02:52:25.353688Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.59551, -0.956345]
[INFO] [stdout] [2m2026-05-15T02:52:25.353700Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m775µ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.13s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-05-15T02:52:25.357823Z[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:52:25.357892Z[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:52:25.359316Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:25.359117054Z, server: 2026-05-15T02:52:20.359130994Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:25.359151884Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m17µs 415ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:25.359134469Z [3mdelta[0m[2m=[0m5s 3µs 475ns ago
[INFO] [stdout] [2m2026-05-15T02:52:25.357817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:25.357828Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-05-15T02:52:25.361250Z[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:52:25.361306Z[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:52:25.357817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-15T02:52:25.361196Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m17.415µs [3mdelta[0m[2m=[0m5s 3µs 475ns ago
[INFO] [stdout] [2m2026-05-15T02:52:25.361429Z[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:52:25.361477Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m680.056009ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:25.362694Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:25.362574014Z, server: 2026-05-15T02:52:30.362578584Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:25.362581114Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m3µs 550ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:25.362577564Z [3mdelta[0m[2m=[0m5s 1µs 20ns
[INFO] [stdout] [2m2026-05-15T02:52:25.362833Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:25.362728484Z, server: 2026-05-15T02:52:25.362731724Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:25.362733564Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 540ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:25.362731024Z [3mdelta[0m[2m=[0m700ns
[INFO] [stdout] [2m2026-05-15T02:52:25.362743Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:25.362578654Z, server: 2026-05-15T02:52:25.362581644Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:25.362583574Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 460ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:25.362581114Z [3mdelta[0m[2m=[0m530ns
[INFO] [stdout] [2m2026-05-15T02:52:25.362902Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.54µs [3mdelta[0m[2m=[0m700ns
[INFO] [stdout] [2m2026-05-15T02:52:25.362928Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m700ns
[INFO] [stdout] [2m2026-05-15T02:52:25.362929Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.46µs [3mdelta[0m[2m=[0m530ns
[INFO] [stdout] [2m2026-05-15T02:52:25.362942Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.077825439s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:25.362950Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.283191135s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:25.363131Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m3.55µs [3mdelta[0m[2m=[0m5s 1µs 20ns
[INFO] [stdout] [2m2026-05-15T02:52:25.363445Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m736.484551ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:26.043594Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:26.043407246Z, server: 2026-05-15T02:52:21.043417206Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:26.043421255Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 4ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:26.04341425Z [3mdelta[0m[2m=[0m4s 999ms 997µs 44ns ago
[INFO] [stdout] [2m2026-05-15T02:52:26.043688Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.004µs [3mdelta[0m[2m=[0m4s 999ms 997µs 44ns ago
[INFO] [stdout] [2m2026-05-15T02:52:26.043714Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m107.086848ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:26.109644Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:26.109452975Z, server: 2026-05-15T02:52:31.109463535Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:26.109467995Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 510ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:26.109460485Z [3mdelta[0m[2m=[0m5s 3µs 50ns
[INFO] [stdout] [2m2026-05-15T02:52:26.109735Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.51µs [3mdelta[0m[2m=[0m5s 3µs 50ns
[INFO] [stdout] [2m2026-05-15T02:52:26.109759Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.37233351s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:26.152566Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:26.152390674Z, server: 2026-05-15T02:52:21.152400134Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:26.152403914Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 620ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:26.152397294Z [3mdelta[0m[2m=[0m4s 999ms 997µs 160ns ago
[INFO] [stdout] [2m2026-05-15T02:52:26.152664Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.62µs [3mdelta[0m[2m=[0m4s 999ms 997µs 160ns ago
[INFO] [stdout] [2m2026-05-15T02:52:26.152688Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.945551935s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:26.442569Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:26.442399081Z, server: 2026-05-15T02:52:26.442409171Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:26.442412351Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 635ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:26.442405716Z [3mdelta[0m[2m=[0m3µs 455ns
[INFO] [stdout] [2m2026-05-15T02:52:26.442653Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.635µs [3mdelta[0m[2m=[0m3µs 455ns
[INFO] [stdout] [2m2026-05-15T02:52:26.442675Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m978.663563ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:26.647569Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:26.647393588Z, server: 2026-05-15T02:52:26.647403448Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:26.647407088Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 750ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:26.647400338Z [3mdelta[0m[2m=[0m3µs 110ns
[INFO] [stdout] [2m2026-05-15T02:52:26.647647Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.75µs [3mdelta[0m[2m=[0m3µs 110ns
[INFO] [stdout] [2m2026-05-15T02:52:26.647667Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m607.890212ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:27.257571Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:27.257387201Z, server: 2026-05-15T02:52:27.257396331Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:27.257399711Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 255ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:27.257393456Z [3mdelta[0m[2m=[0m2µs 875ns
[INFO] [stdout] [2m2026-05-15T02:52:27.257663Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.255µs [3mdelta[0m[2m=[0m2µs 875ns
[INFO] [stdout] [2m2026-05-15T02:52:27.257687Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m384.49282ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:27.422546Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:27.422379779Z, server: 2026-05-15T02:52:27.422389779Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:27.422393029Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 625ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:27.422386404Z [3mdelta[0m[2m=[0m3µs 375ns
[INFO] [stdout] [2m2026-05-15T02:52:27.422696Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.625µs [3mdelta[0m[2m=[0m3µs 375ns
[INFO] [stdout] [2m2026-05-15T02:52:27.422740Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m779.492542ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:27.483603Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:27.483427498Z, server: 2026-05-15T02:52:32.483436789Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:27.483440629Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 565ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:27.483434063Z [3mdelta[0m[2m=[0m5s 2µs 726ns
[INFO] [stdout] [2m2026-05-15T02:52:27.483688Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.565µs [3mdelta[0m[2m=[0m5s 2µs 726ns
[INFO] [stdout] [2m2026-05-15T02:52:27.483710Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m566.412426ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:27.643552Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:27.643357637Z, server: 2026-05-15T02:52:27.643367967Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:27.643372777Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 570ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:27.643365207Z [3mdelta[0m[2m=[0m2µs 760ns
[INFO] [stdout] [2m2026-05-15T02:52:27.643654Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.57µs [3mdelta[0m[2m=[0m2µs 760ns
[INFO] [stdout] [2m2026-05-15T02:52:27.643680Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.808144581s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:28.051600Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:28.051413842Z, server: 2026-05-15T02:52:33.051424542Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:28.051428902Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 530ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:28.051421372Z [3mdelta[0m[2m=[0m5s 3µs 170ns
[INFO] [stdout] [2m2026-05-15T02:52:28.051697Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.53µs [3mdelta[0m[2m=[0m5s 3µs 170ns
[INFO] [stdout] [2m2026-05-15T02:52:28.051720Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m183.439554ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:28.099563Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:28.099373541Z, server: 2026-05-15T02:52:23.099383671Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:28.099387601Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 30ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:28.099380571Z [3mdelta[0m[2m=[0m4s 999ms 996µs 900ns ago
[INFO] [stdout] [2m2026-05-15T02:52:28.099666Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.03µs [3mdelta[0m[2m=[0m4s 999ms 996µs 900ns ago
[INFO] [stdout] [2m2026-05-15T02:52:28.099695Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.956780714s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:28.203567Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:28.20338694Z, server: 2026-05-15T02:52:28.20339676Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:28.20340009Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 575ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:28.203393515Z [3mdelta[0m[2m=[0m3µs 245ns
[INFO] [stdout] [2m2026-05-15T02:52:28.206220Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.575µs [3mdelta[0m[2m=[0m3µs 245ns
[INFO] [stdout] [2m2026-05-15T02:52:28.206267Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m128.279835ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-15T02:52:28.236383Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:28.236199629Z, server: 2026-05-15T02:52:33.23620968Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:28.23622184Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11µs 105ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:28.236210734Z [3mdelta[0m[2m=[0m4s 999ms 998µs 946ns
[INFO] [stdout] [2m2026-05-15T02:52:28.236472Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.105µs [3mdelta[0m[2m=[0m4s 999ms 998µs 946ns
[INFO] [stdout] [2m2026-05-15T02:52:28.236505Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00102, 5000.002726, 5000.00305, 5000.00317, 4999.998946]
[INFO] [stdout] [2m2026-05-15T02:52:28.236528Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00305 [3mmean[0m[2m=[0m5000.0017824 [3mvariance[0m[2m=[0m3.2622608005285327e-6 [3mstddev[0m[2m=[0m0.001806172970822156
[INFO] [stdout] [2m2026-05-15T02:52:28.236547Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.002726, 5000.00305, 5000.00317]
[INFO] [stdout] [2m2026-05-15T02:52:28.236561Z[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:52:28.335873Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:28.335702088Z, server: 2026-05-15T02:52:28.335711699Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:28.335714859Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 385ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:28.335708473Z [3mdelta[0m[2m=[0m3µs 226ns
[INFO] [stdout] [2m2026-05-15T02:52:28.335961Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.385µs [3mdelta[0m[2m=[0m3µs 226ns
[INFO] [stdout] [2m2026-05-15T02:52:28.335988Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.0007, 0.003226, 0.003245, 0.003375, 0.003455]
[INFO] [stdout] [2m2026-05-15T02:52:28.336007Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.003245 [3mmean[0m[2m=[0m0.0028002 [3mvariance[0m[2m=[0m1.3872876999999999e-6 [3mstddev[0m[2m=[0m0.0011778317791603348
[INFO] [stdout] [2m2026-05-15T02:52:28.336027Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.003226, 0.003245, 0.003375, 0.003455]
[INFO] [stdout] [2m2026-05-15T02:52:28.336040Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] [2m2026-05-15T02:52:29.453613Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:29.453437015Z, server: 2026-05-15T02:52:29.453446615Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:29.453450725Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 855ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:29.45344387Z [3mdelta[0m[2m=[0m2µs 745ns
[INFO] [stdout] [2m2026-05-15T02:52:29.453703Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.855µs [3mdelta[0m[2m=[0m2µs 745ns
[INFO] [stdout] [2m2026-05-15T02:52:29.453729Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00053, 0.002875, 0.00311, 0.002745, 0.00276]
[INFO] [stdout] [2m2026-05-15T02:52:29.453749Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00311 [3mmean[0m[2m=[0m0.0024040000000000003 [3mvariance[0m[2m=[0m1.1187924999999997e-6 [3mstddev[0m[2m=[0m0.001057729880451526
[INFO] [stdout] [2m2026-05-15T02:52:29.453771Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.002875, 0.00311, 0.002745, 0.00276]
[INFO] [stdout] [2m2026-05-15T02:52:29.453802Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m2µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] [2m2026-05-15T02:52:30.058293Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-15T02:52:30.058073728Z, server: 2026-05-15T02:52:25.058083128Z } [3mcurrent[0m[2m=[0m2026-05-15T02:52:30.058087118Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 695ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-15T02:52:30.058080423Z [3mdelta[0m[2m=[0m4s 999ms 997µs 295ns ago
[INFO] [stdout] [2m2026-05-15T02:52:30.058385Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.695µs [3mdelta[0m[2m=[0m4s 999ms 997µs 295ns ago
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-f8424559dfcf15b0)
[INFO] [stdout] [2m2026-05-15T02:52:30.058413Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.99716, -4999.997295, -4999.997044, -4999.9969, -5000.003475]
[INFO] [stdout] [2m2026-05-15T02:52:30.058432Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.997044 [3mmean[0m[2m=[0m-4999.9983748 [3mvariance[0m[2m=[0m8.149952701215074e-6 [3mstddev[0m[2m=[0m0.0028548122006911546
[INFO] [stdout] [2m2026-05-15T02:52:30.058453Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99716, -4999.997295, -4999.997044, -4999.9969]
[INFO] [stdout] [2m2026-05-15T02:52:30.058466Z[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] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.70s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 1.67s; merged doctests compilation took 1.65s
[INFO] running `Command { std: "docker" "inspect" "fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6", kill_on_drop: false }`
[INFO] [stdout] fd489c288beedbbe781bb2b8109cfa7cd3c904a21a207e3042a5ab1126f0cad6
