[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 beta-2026-03-05 for beta-1.95-1
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-7-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-7-tc2/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-7-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain beta-2026-03-05
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2026-03-05" "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" "+beta-2026-03-05" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2026-03-05" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] a120ca9c46b713796fa0f0046399d4d61db46b1f3caad579bfee9d796d45502d
[INFO] running `Command { std: "docker" "start" "-a" "a120ca9c46b713796fa0f0046399d4d61db46b1f3caad579bfee9d796d45502d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "a120ca9c46b713796fa0f0046399d4d61db46b1f3caad579bfee9d796d45502d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a120ca9c46b713796fa0f0046399d4d61db46b1f3caad579bfee9d796d45502d", kill_on_drop: false }`
[INFO] [stdout] a120ca9c46b713796fa0f0046399d4d61db46b1f3caad579bfee9d796d45502d
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-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" "+beta-2026-03-05" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] bd7a289ffde07dbbb4e145454b6d5928c52e8638222a7bd2d9fe86d3fd4d496b
[INFO] running `Command { std: "docker" "start" "-a" "bd7a289ffde07dbbb4e145454b6d5928c52e8638222a7bd2d9fe86d3fd4d496b", 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 thiserror v2.0.12
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[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 convert_case v0.8.0
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling syn v2.0.100
[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 napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 23.35s
[INFO] running `Command { std: "docker" "inspect" "bd7a289ffde07dbbb4e145454b6d5928c52e8638222a7bd2d9fe86d3fd4d496b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "bd7a289ffde07dbbb4e145454b6d5928c52e8638222a7bd2d9fe86d3fd4d496b", kill_on_drop: false }`
[INFO] [stdout] bd7a289ffde07dbbb4e145454b6d5928c52e8638222a7bd2d9fe86d3fd4d496b
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-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" "+beta-2026-03-05" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 23d2065ccb6b9908ea3134fb0fd660b322a679137e5c41df30f8b96ef506bd1f
[INFO] running `Command { std: "docker" "start" "-a" "23d2065ccb6b9908ea3134fb0fd660b322a679137e5c41df30f8b96ef506bd1f", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 47.28s
[INFO] running `Command { std: "docker" "inspect" "23d2065ccb6b9908ea3134fb0fd660b322a679137e5c41df30f8b96ef506bd1f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "23d2065ccb6b9908ea3134fb0fd660b322a679137e5c41df30f8b96ef506bd1f", kill_on_drop: false }`
[INFO] [stdout] 23d2065ccb6b9908ea3134fb0fd660b322a679137e5c41df30f8b96ef506bd1f
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-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" "+beta-2026-03-05" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] fc525abd8429b13f1761d787cc0883b68d4beee20f70fd60052b9e75720cb3bc
[INFO] running `Command { std: "docker" "start" "-a" "fc525abd8429b13f1761d787cc0883b68d4beee20f70fd60052b9e75720cb3bc", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.22s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-2aee66feffce539a)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.17s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-c4bbd53b9bad2c02)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-03-10T14:50:08.006092Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.006186Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.008198Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-03-10T14:50:08.008259Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.008437Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.008511Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.010475Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-03-10T14:50:08.010566Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.010525Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.010837Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.010893Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.010909Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.011062Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.011103Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.012606Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.012648Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.022323Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.022479Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.026142Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.023717654Z, server: 2026-03-10T14:50:08.024842794Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.025961334Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 121µs 840ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.024839494Z [3mdelta[0m[2m=[0m3µs 300ns
[INFO] [stdout] [2m2026-03-10T14:50:08.026265Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.12184ms [3mdelta[0m[2m=[0m3µs 300ns
[INFO] [stdout] [2m2026-03-10T14:50:08.026319Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m3µs 300ns
[INFO] [stdout] [2m2026-03-10T14:50:08.026364Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m540.974502ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.027820Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.009940136Z, server: 2026-03-10T14:50:13.021477415Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.027628114Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 843µs 989ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.018784125Z [3mdelta[0m[2m=[0m5s 2ms 693µs 290ns
[INFO] [stdout] [2m2026-03-10T14:50:08.027907Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.843989ms [3mdelta[0m[2m=[0m5s 2ms 693µs 290ns
[INFO] [stdout] [2m2026-03-10T14:50:08.027929Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 2ms 693µs 290ns
[INFO] [stdout] [2m2026-03-10T14:50:08.027943Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m603.19655ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.030578Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.012086325Z, server: 2026-03-10T14:50:13.021267025Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.030431354Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 172µs 514ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.021258839Z [3mdelta[0m[2m=[0m5s 8µs 186ns
[INFO] [stdout] [2m2026-03-10T14:50:08.030661Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.172514ms [3mdelta[0m[2m=[0m5s 8µs 186ns
[INFO] [stdout] [2m2026-03-10T14:50:08.030685Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 8µs 186ns
[INFO] [stdout] [2m2026-03-10T14:50:08.030699Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m282.336255ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.032707Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.010335345Z, server: 2026-03-10T14:50:08.021433835Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.032573684Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 119µs 169ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.021454514Z [3mdelta[0m[2m=[0m20µs 679ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.032784Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.119169ms [3mdelta[0m[2m=[0m20µs 679ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.032806Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m592.75919ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.034546Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.011468045Z, server: 2026-03-10T14:50:13.022602595Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.034427094Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 479µs 524ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.022947569Z [3mdelta[0m[2m=[0m4s 999ms 655µs 26ns
[INFO] [stdout] [2m2026-03-10T14:50:08.034623Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.479524ms [3mdelta[0m[2m=[0m4s 999ms 655µs 26ns
[INFO] [stdout] [2m2026-03-10T14:50:08.034646Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 655µs 26ns
[INFO] [stdout] [2m2026-03-10T14:50:08.034672Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.509867934s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.035257Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.011748305Z, server: 2026-03-10T14:50:08.022925624Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.034640954Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 446µs 324ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.023194629Z [3mdelta[0m[2m=[0m269µs 5ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.035337Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.446324ms [3mdelta[0m[2m=[0m269µs 5ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.035494Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m496.302533ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.044711Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.016528145Z, server: 2026-03-10T14:50:13.027682654Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.044502813Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 987µs 334ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.030515479Z [3mdelta[0m[2m=[0m4s 997ms 167µs 175ns
[INFO] [stdout] [2m2026-03-10T14:50:08.044815Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.987334ms [3mdelta[0m[2m=[0m4s 997ms 167µs 175ns
[INFO] [stdout] [2m2026-03-10T14:50:08.044840Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 997ms 167µs 175ns
[INFO] [stdout] [2m2026-03-10T14:50:08.044867Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.991738032s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.225684Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.012288585Z, server: 2026-03-10T14:50:08.113614837Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.225478398Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m106ms 594µs 906ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.118883491Z [3mdelta[0m[2m=[0m5ms 268µs 654ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.225775Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m106.594906ms [3mdelta[0m[2m=[0m5ms 268µs 654ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.225797Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5ms 268µs 654ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.225811Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m697.851631ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.308683Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:08.308757Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.332598Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.309997761Z, server: 2026-03-10T14:50:03.321194261Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.33236431Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 183µs 274ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.321181035Z [3mdelta[0m[2m=[0m4s 999ms 986µs 774ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.332696Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.183274ms [3mdelta[0m[2m=[0m4s 999ms 986µs 774ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.332724Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 986µs 774ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.332741Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m387.599895ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.334150Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.313608941Z, server: 2026-03-10T14:50:13.32376808Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.33405646Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 223µs 759ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.3238327Z [3mdelta[0m[2m=[0m4s 999ms 935µs 380ns
[INFO] [stdout] [2m2026-03-10T14:50:08.334279Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.223759ms [3mdelta[0m[2m=[0m4s 999ms 935µs 380ns
[INFO] [stdout] [2m2026-03-10T14:50:08.334335Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.990670137s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.555780Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.532594754Z, server: 2026-03-10T14:50:08.543732983Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.555612962Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 509µs 104ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.544103858Z [3mdelta[0m[2m=[0m370µs 875ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.555872Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.509104ms [3mdelta[0m[2m=[0m370µs 875ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.555897Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.325888041s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.571659Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.569205161Z, server: 2026-03-10T14:50:08.570353711Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.571497661Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 146µs 250ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.570351411Z [3mdelta[0m[2m=[0m2µs 300ns
[INFO] [stdout] [2m2026-03-10T14:50:08.571750Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.14625ms [3mdelta[0m[2m=[0m2µs 300ns
[INFO] [stdout] [2m2026-03-10T14:50:08.571772Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.315436316s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.652305Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.631619386Z, server: 2026-03-10T14:50:13.641865085Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.652136754Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 258µs 684ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.64187807Z [3mdelta[0m[2m=[0m4s 999ms 987µs 15ns
[INFO] [stdout] [2m2026-03-10T14:50:08.652420Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.258684ms [3mdelta[0m[2m=[0m4s 999ms 987µs 15ns
[INFO] [stdout] [2m2026-03-10T14:50:08.652447Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.471981351s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.652598Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.629476766Z, server: 2026-03-10T14:50:08.641805995Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.652519474Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 521µs 354ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.64099812Z [3mdelta[0m[2m=[0m807µs 875ns
[INFO] [stdout] [2m2026-03-10T14:50:08.652653Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.521354ms [3mdelta[0m[2m=[0m807µs 875ns
[INFO] [stdout] [2m2026-03-10T14:50:08.652672Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.974864726s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:08.761647Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.723475189Z, server: 2026-03-10T14:50:03.739466687Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:08.761473596Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m18ms 999µs 203ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.742474392Z [3mdelta[0m[2m=[0m5s 3ms 7µs 705ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.761740Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m18.999203ms [3mdelta[0m[2m=[0m5s 3ms 7µs 705ns ago
[INFO] [stdout] [2m2026-03-10T14:50:08.761765Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.876610824s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:09.126756Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.924597173Z, server: 2026-03-10T14:50:09.025927525Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:09.126595277Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 999µs 52ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:09.025596225Z [3mdelta[0m[2m=[0m331µs 300ns
[INFO] [stdout] [2m2026-03-10T14:50:09.126843Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.999052ms [3mdelta[0m[2m=[0m331µs 300ns
[INFO] [stdout] [2m2026-03-10T14:50:09.126864Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.51379684s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:09.569005Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:09.546452963Z, server: 2026-03-10T14:50:14.557643002Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:09.568835072Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 191µs 54ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:09.557644017Z [3mdelta[0m[2m=[0m4s 999ms 998µs 985ns
[INFO] [stdout] [2m2026-03-10T14:50:09.569092Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.191054ms [3mdelta[0m[2m=[0m4s 999ms 998µs 985ns
[INFO] [stdout] [2m2026-03-10T14:50:09.569116Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m99.678376ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:09.690946Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:09.670391953Z, server: 2026-03-10T14:50:14.680576183Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:09.690766892Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 187µs 469ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:09.680579422Z [3mdelta[0m[2m=[0m4s 999ms 996µs 761ns
[INFO] [stdout] [2m2026-03-10T14:50:09.691053Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.187469ms [3mdelta[0m[2m=[0m4s 999ms 996µs 761ns
[INFO] [stdout] [2m2026-03-10T14:50:09.691081Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m512.556272ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:09.776673Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:08.012086715Z, server: 2026-03-10T14:50:08.893612205Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:09.776472965Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m882ms 193µs 125ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:08.89427984Z [3mdelta[0m[2m=[0m667µs 635ns ago
[INFO] [stdout] [2m2026-03-10T14:50:09.776759Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m882.193125ms [3mdelta[0m[2m=[0m667µs 635ns ago
[INFO] [stdout] [2m2026-03-10T14:50:09.776782Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m667µs 635ns ago
[INFO] [stdout] [2m2026-03-10T14:50:09.776796Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.441562274s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:09.899671Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:09.894467556Z, server: 2026-03-10T14:50:09.898410675Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:09.899518735Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 525µs 589ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:09.896993145Z [3mdelta[0m[2m=[0m1ms 417µs 530ns
[INFO] [stdout] [2m2026-03-10T14:50:09.899760Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.525589ms [3mdelta[0m[2m=[0m1ms 417µs 530ns
[INFO] [stdout] [2m2026-03-10T14:50:09.899784Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.056416324s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:09.906820Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:09.882604267Z, server: 2026-03-10T14:50:09.895465246Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:09.906646715Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 21µs 224ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:09.894625491Z [3mdelta[0m[2m=[0m839µs 755ns
[INFO] [stdout] [2m2026-03-10T14:50:09.906917Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.021224ms [3mdelta[0m[2m=[0m839µs 755ns
[INFO] [stdout] [2m2026-03-10T14:50:09.906945Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m637.213495ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.061182Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.038632784Z, server: 2026-03-10T14:50:15.049828353Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.061021993Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 194µs 604ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.049827388Z [3mdelta[0m[2m=[0m5s 965ns
[INFO] [stdout] [2m2026-03-10T14:50:10.061345Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.194604ms [3mdelta[0m[2m=[0m5s 965ns
[INFO] [stdout] [2m2026-03-10T14:50:10.061414Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m16.886663ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.102235Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.079645961Z, server: 2026-03-10T14:50:15.09083954Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.102045709Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 199µs 874ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.090845835Z [3mdelta[0m[2m=[0m4s 999ms 993µs 705ns
[INFO] [stdout] [2m2026-03-10T14:50:10.102431Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.199874ms [3mdelta[0m[2m=[0m4s 999ms 993µs 705ns
[INFO] [stdout] [2m2026-03-10T14:50:10.102501Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.340025811s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.142007Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.125572587Z, server: 2026-03-10T14:50:15.133721077Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.141848276Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 137µs 844ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.133710431Z [3mdelta[0m[2m=[0m5s 10µs 646ns
[INFO] [stdout] [2m2026-03-10T14:50:10.142101Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.137844ms [3mdelta[0m[2m=[0m5s 10µs 646ns
[INFO] [stdout] [2m2026-03-10T14:50:10.142126Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m272.479852ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.228004Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.205472841Z, server: 2026-03-10T14:50:15.21666108Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.227847699Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 187µs 429ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.21666027Z [3mdelta[0m[2m=[0m5s 810ns
[INFO] [stdout] [2m2026-03-10T14:50:10.228090Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.187429ms [3mdelta[0m[2m=[0m5s 810ns
[INFO] [stdout] [2m2026-03-10T14:50:10.228112Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.783087156s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.333932Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.327483071Z, server: 2026-03-10T14:50:15.330635941Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.333772551Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m3ms 144µs 740ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.330627811Z [3mdelta[0m[2m=[0m5s 8µs 130ns
[INFO] [stdout] [2m2026-03-10T14:50:10.334027Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m3.14474ms [3mdelta[0m[2m=[0m5s 8µs 130ns
[INFO] [stdout] [2m2026-03-10T14:50:10.334049Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m303.138338ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.434336Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.415894654Z, server: 2026-03-10T14:50:15.425036544Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.434165963Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 135µs 654ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.425030308Z [3mdelta[0m[2m=[0m5s 6µs 236ns
[INFO] [stdout] [2m2026-03-10T14:50:10.434491Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.135654ms [3mdelta[0m[2m=[0m5s 6µs 236ns
[INFO] [stdout] [2m2026-03-10T14:50:10.434514Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.503949895s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.571197Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.544613814Z, server: 2026-03-10T14:50:10.555811143Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.571036612Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 211µs 399ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.557825213Z [3mdelta[0m[2m=[0m2ms 14µs 70ns ago
[INFO] [stdout] [2m2026-03-10T14:50:10.571287Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.211399ms [3mdelta[0m[2m=[0m2ms 14µs 70ns ago
[INFO] [stdout] [2m2026-03-10T14:50:10.571312Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m542.837124ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.656162Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.637597267Z, server: 2026-03-10T14:50:15.646850956Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.655995935Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 199µs 334ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.646796601Z [3mdelta[0m[2m=[0m5s 54µs 355ns
[INFO] [stdout] [2m2026-03-10T14:50:10.656262Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.199334ms [3mdelta[0m[2m=[0m5s 54µs 355ns
[INFO] [stdout] [2m2026-03-10T14:50:10.656287Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m60.739997ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.664747Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.639580416Z, server: 2026-03-10T14:50:05.653451455Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.664613294Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 516µs 439ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.652096855Z [3mdelta[0m[2m=[0m4s 998ms 645µs 400ns ago
[INFO] [stdout] [2m2026-03-10T14:50:10.664835Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.516439ms [3mdelta[0m[2m=[0m4s 998ms 645µs 400ns ago
[INFO] [stdout] [2m2026-03-10T14:50:10.664858Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m735.022004ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.666585Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.633474787Z, server: 2026-03-10T14:50:10.648428616Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.666430224Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m16ms 477µs 718ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.649952505Z [3mdelta[0m[2m=[0m1ms 523µs 889ns ago
[INFO] [stdout] [2m2026-03-10T14:50:10.666669Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m16.477718ms [3mdelta[0m[2m=[0m1ms 523µs 889ns ago
[INFO] [stdout] [2m2026-03-10T14:50:10.666689Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.629675454s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.736410Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.71783726Z, server: 2026-03-10T14:50:15.7270295Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.736209019Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 185µs 879ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.727023139Z [3mdelta[0m[2m=[0m5s 6µs 361ns
[INFO] [stdout] [2m2026-03-10T14:50:10.736511Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.185879ms [3mdelta[0m[2m=[0m5s 6µs 361ns
[INFO] [stdout] [2m2026-03-10T14:50:10.736545Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00813, 5000.008186, 5000.006361, 5000.054355, 4999.93538]
[INFO] [stdout] [2m2026-03-10T14:50:10.736568Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.006361 [3mmean[0m[2m=[0m5000.0024824 [3mvariance[0m[2m=[0m0.0018182421733090935 [3mstddev[0m[2m=[0m0.04264085099184928
[INFO] [stdout] [2m2026-03-10T14:50:10.736588Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00813, 5000.008186, 5000.006361]
[INFO] [stdout] [2m2026-03-10T14:50:10.736614Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 7µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-03-10T14:50:10.852444Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.650513915Z, server: 2026-03-10T14:50:10.751909778Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.852262699Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 874µs 392ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.751388307Z [3mdelta[0m[2m=[0m521µs 471ns
[INFO] [stdout] [2m2026-03-10T14:50:10.852607Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.874392ms [3mdelta[0m[2m=[0m521µs 471ns
[INFO] [stdout] [2m2026-03-10T14:50:10.852676Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.219957997s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:10.960075Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:10.957626251Z, server: 2026-03-10T14:50:10.958770611Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:10.959897801Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 135µs 775ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:10.958762026Z [3mdelta[0m[2m=[0m8µs 585ns
[INFO] [stdout] [2m2026-03-10T14:50:10.960173Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.135775ms [3mdelta[0m[2m=[0m8µs 585ns
[INFO] [stdout] [2m2026-03-10T14:50:10.960199Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.735976211s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:11.137231Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:11.114625478Z, server: 2026-03-10T14:50:11.125819988Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:11.137043437Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 208µs 979ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:11.125834457Z [3mdelta[0m[2m=[0m14µs 469ns ago
[INFO] [stdout] [2m2026-03-10T14:50:11.137422Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.208979ms [3mdelta[0m[2m=[0m14µs 469ns ago
[INFO] [stdout] [2m2026-03-10T14:50:11.137529Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.014469, -0.269005, -0.370875, 0.839755, -2.01407]
[INFO] [stdout] [2m2026-03-10T14:50:11.137576Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.370875 [3mmean[0m[2m=[0m-0.36573279999999997 [3mvariance[0m[2m=[0m1.0757463318891998 [3mstddev[0m[2m=[0m1.037181918416051
[INFO] [stdout] [2m2026-03-10T14:50:11.137660Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.014469, -0.269005, -0.370875]
[INFO] [stdout] [2m2026-03-10T14:50:11.137700Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m218µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-03-10T14:50:11.424972Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:11.402468916Z, server: 2026-03-10T14:50:06.413638155Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:11.424800534Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 165µs 809ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:11.413634725Z [3mdelta[0m[2m=[0m4s 999ms 996µs 570ns ago
[INFO] [stdout] [2m2026-03-10T14:50:11.425071Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.165809ms [3mdelta[0m[2m=[0m4s 999ms 996µs 570ns ago
[INFO] [stdout] [2m2026-03-10T14:50:11.425099Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.979432046s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:11.467139Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:11.444599732Z, server: 2026-03-10T14:50:16.455782382Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:11.466965771Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 183µs 19ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:11.455782751Z [3mdelta[0m[2m=[0m4s 999ms 999µs 631ns
[INFO] [stdout] [2m2026-03-10T14:50:11.467240Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.183019ms [3mdelta[0m[2m=[0m4s 999ms 999µs 631ns
[INFO] [stdout] [2m2026-03-10T14:50:11.467266Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.100481449s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:11.952074Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:11.939612723Z, server: 2026-03-10T14:50:16.945761343Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:11.951897062Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 142µs 169ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:11.945754892Z [3mdelta[0m[2m=[0m5s 6µs 451ns
[INFO] [stdout] [2m2026-03-10T14:50:11.952186Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.142169ms [3mdelta[0m[2m=[0m5s 6µs 451ns
[INFO] [stdout] [2m2026-03-10T14:50:11.952216Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.006451, 5000.010646, 5002.69329, 5000.006236, 4999.987015]
[INFO] [stdout] [2m2026-03-10T14:50:11.952237Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5002.69329 [3mmean[0m[2m=[0m5000.5407276 [3mvariance[0m[2m=[0m1.4480604469325304 [3mstddev[0m[2m=[0m1.2033538328075124
[INFO] [stdout] [2m2026-03-10T14:50:11.952259Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5002.69329]
[INFO] [stdout] [2m2026-03-10T14:50:11.952272Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 2ms 693µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-03-10T14:50:12.034184Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:12.012631537Z, server: 2026-03-10T14:50:17.023824946Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:12.034005825Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 687µs 144ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:12.023318681Z [3mdelta[0m[2m=[0m5s 506µs 265ns
[INFO] [stdout] [2m2026-03-10T14:50:12.034297Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.687144ms [3mdelta[0m[2m=[0m5s 506µs 265ns
[INFO] [stdout] [2m2026-03-10T14:50:12.034329Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.996761, 5000.506265, 5000.00081, 4999.998985, 4999.655026]
[INFO] [stdout] [2m2026-03-10T14:50:12.034349Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00081 [3mmean[0m[2m=[0m5000.0315694 [3mvariance[0m[2m=[0m0.09258508831622661 [3mstddev[0m[2m=[0m0.3042779786909112
[INFO] [stdout] [2m2026-03-10T14:50:12.034398Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.996761, 5000.00081, 4999.998985]
[INFO] [stdout] [2m2026-03-10T14:50:12.034428Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 998µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-03-10T14:50:12.275670Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:12.073609513Z, server: 2026-03-10T14:50:12.174158894Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:12.275482516Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 936µs 501ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:12.174546014Z [3mdelta[0m[2m=[0m387µs 120ns ago
[INFO] [stdout] [2m2026-03-10T14:50:12.275766Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.936501ms [3mdelta[0m[2m=[0m387µs 120ns ago
[INFO] [stdout] [2m2026-03-10T14:50:12.275789Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.58096077s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:12.328674Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:12.297877035Z, server: 2026-03-10T14:50:12.309107844Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:12.328483382Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m15ms 303µs 173ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:12.313180208Z [3mdelta[0m[2m=[0m4ms 72µs 364ns ago
[INFO] [stdout] [2m2026-03-10T14:50:12.328781Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m15.303173ms [3mdelta[0m[2m=[0m4ms 72µs 364ns ago
[INFO] [stdout] [2m2026-03-10T14:50:12.328809Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m384.419021ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:12.591851Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:12.569228983Z, server: 2026-03-10T14:50:17.580455052Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:12.591659801Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 215µs 409ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:12.580444392Z [3mdelta[0m[2m=[0m5s 10µs 660ns
[INFO] [stdout] [2m2026-03-10T14:50:12.591963Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.215409ms [3mdelta[0m[2m=[0m5s 10µs 660ns
[INFO] [stdout] [2m2026-03-10T14:50:12.592079Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.999631, 5000.000965, 4999.993705, 5000.01066, 4997.1671750000005]
[INFO] [stdout] [2m2026-03-10T14:50:12.592105Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.993705 [3mmean[0m[2m=[0m4999.4344272 [3mvariance[0m[2m=[0m1.606422212533534 [3mstddev[0m[2m=[0m1.2674471241568754
[INFO] [stdout] [2m2026-03-10T14:50:12.592128Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.999631, 5000.000965, 4999.993705, 5000.01066]
[INFO] [stdout] [2m2026-03-10T14:50:12.592144Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 1µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-03-10T14:50:12.700023Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:12.697464583Z, server: 2026-03-10T14:50:12.698723053Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:12.699853783Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 194µs 600ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:12.698659183Z [3mdelta[0m[2m=[0m63µs 870ns
[INFO] [stdout] [2m2026-03-10T14:50:12.700124Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.1946ms [3mdelta[0m[2m=[0m63µs 870ns
[INFO] [stdout] [2m2026-03-10T14:50:12.700150Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.0033, 0.008585, 0.0023, 0.06387, 1.41753]
[INFO] [stdout] [2m2026-03-10T14:50:12.700171Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.0023 [3mmean[0m[2m=[0m0.29911699999999997 [3mvariance[0m[2m=[0m0.39155141539499994 [3mstddev[0m[2m=[0m0.6257406934146124
[INFO] [stdout] [2m2026-03-10T14:50:12.700195Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.0033, 0.008585, 0.0023, 0.06387]
[INFO] [stdout] [2m2026-03-10T14:50:12.700221Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m19µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-03-10T14:50:12.737131Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:12.714486891Z, server: 2026-03-10T14:50:12.725682301Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:12.73689687Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 204µs 989ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:12.72569188Z [3mdelta[0m[2m=[0m9µs 579ns ago
[INFO] [stdout] [2m2026-03-10T14:50:12.737237Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.204989ms [3mdelta[0m[2m=[0m9µs 579ns ago
[INFO] [stdout] [2m2026-03-10T14:50:12.737269Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.020679, -0.009579, 0.807875, -4.072364, -1.523889]
[INFO] [stdout] [2m2026-03-10T14:50:12.737290Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.807875 [3mmean[0m[2m=[0m-0.9637271999999999 [3mvariance[0m[2m=[0m3.7289292616562 [3mstddev[0m[2m=[0m1.9310435680367752
[INFO] [stdout] [2m2026-03-10T14:50:12.737311Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.020679, -0.009579, 0.807875]
[INFO] [stdout] [2m2026-03-10T14:50:12.737325Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m259µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-03-10T14:50:13.107773Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:11.21958604Z, server: 2026-03-10T14:50:12.165473215Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:13.10761815Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m944ms 16µs 55ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:12.163602095Z [3mdelta[0m[2m=[0m1ms 871µs 120ns
[INFO] [stdout] [2m2026-03-10T14:50:13.107844Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m944.016055ms [3mdelta[0m[2m=[0m1ms 871µs 120ns
[INFO] [stdout] [2m2026-03-10T14:50:13.107867Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.890082234s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:13.428660Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:13.405644407Z, server: 2026-03-10T14:50:08.416848116Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:13.428476165Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 415µs 879ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:13.417060286Z [3mdelta[0m[2m=[0m5s 212µs 170ns ago
[INFO] [stdout] [2m2026-03-10T14:50:13.428862Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.415879ms [3mdelta[0m[2m=[0m5s 212µs 170ns ago
[INFO] [stdout] [2m2026-03-10T14:50:13.428989Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.99657, -4999.986774, -5000.21217, -4998.6454, -5003.007705]
[INFO] [stdout] [2m2026-03-10T14:50:13.429095Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.21217 [3mmean[0m[2m=[0m-5000.3697238 [3mvariance[0m[2m=[0m2.56073872161687 [3mstddev[0m[2m=[0m1.6002308338539382
[INFO] [stdout] [2m2026-03-10T14:50:13.429148Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99657, -4999.986774, -5000.21217, -4998.6454]
[INFO] [stdout] [2m2026-03-10T14:50:13.429243Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 710µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-03-10T14:50:14.066738Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:13.85763626Z, server: 2026-03-10T14:50:13.965178682Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:14.066559444Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m104ms 461µs 592ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:13.962097852Z [3mdelta[0m[2m=[0m3ms 80µs 830ns
[INFO] [stdout] [2m2026-03-10T14:50:14.066822Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m104.461592ms [3mdelta[0m[2m=[0m3ms 80µs 830ns
[INFO] [stdout] [2m2026-03-10T14:50:14.066848Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.521471, -0.38712, 0.3313, 3.08083, -5.268654]
[INFO] [stdout] [2m2026-03-10T14:50:14.066867Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.3313 [3mmean[0m[2m=[0m-0.3444345999999999 [3mvariance[0m[2m=[0m9.2971515201178 [3mstddev[0m[2m=[0m3.049123073953854
[INFO] [stdout] [2m2026-03-10T14:50:14.066886Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.521471, -0.38712, 0.3313, 3.08083]
[INFO] [stdout] [2m2026-03-10T14:50:14.066899Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m886µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-03-10T14:50:16.865684Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:14.99962492Z, server: 2026-03-10T14:50:15.929615616Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:16.865500451Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m932ms 937µs 765ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:15.932562685Z [3mdelta[0m[2m=[0m2ms 947µs 69ns ago
[INFO] [stdout] [2m2026-03-10T14:50:16.865782Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m932.937765ms [3mdelta[0m[2m=[0m2ms 947µs 69ns ago
[INFO] [stdout] [2m2026-03-10T14:50:16.865808Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.633131571s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:20.441008Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:18.500636011Z, server: 2026-03-10T14:50:19.470666904Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:20.440821097Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m970ms 92µs 543ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:19.470728554Z [3mdelta[0m[2m=[0m61µs 650ns ago
[INFO] [stdout] [2m2026-03-10T14:50:20.441104Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m970.092543ms [3mdelta[0m[2m=[0m61µs 650ns ago
[INFO] [stdout] [2m2026-03-10T14:50:20.441128Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.295118696s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.573857Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:21.737607524Z, server: 2026-03-10T14:50:22.655613461Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:23.573692068Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m918ms 42µs 272ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:22.655649796Z [3mdelta[0m[2m=[0m36µs 335ns ago
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-405f21f178b7074c)
[INFO] [stdout] [2m2026-03-10T14:50:23.573947Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m918.042272ms [3mdelta[0m[2m=[0m36µs 335ns ago
[INFO] [stdout] [2m2026-03-10T14:50:23.573974Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.667635, -0.036335, -2.947069, 1.87112, -0.06165]
[INFO] [stdout] [2m2026-03-10T14:50:23.573993Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-2.947069 [3mmean[0m[2m=[0m-0.3683138 [3mvariance[0m[2m=[0m2.9897219791897 [3mstddev[0m[2m=[0m1.729081252917196
[INFO] [stdout] [2m2026-03-10T14:50:23.574016Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-2.947069]
[INFO] [stdout] [2m2026-03-10T14:50:23.574028Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m2ms 947µ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 15.57s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-03-10T14:50:23.581190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:23.581190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-03-10T14:50:23.581302Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.581200Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-10T14:50:23.581322Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.581339Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.582717Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:23.582563367Z, server: 2026-03-10T14:50:18.582576037Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:23.582578717Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 675ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:23.582571042Z [3mdelta[0m[2m=[0m4s 999ms 995µs 5ns ago
[INFO] [stdout] [2m2026-03-10T14:50:23.582719Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:23.582563577Z, server: 2026-03-10T14:50:23.582576487Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:23.582578747Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 585ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:23.582571162Z [3mdelta[0m[2m=[0m5µs 325ns
[INFO] [stdout] [2m2026-03-10T14:50:23.582798Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.675µs [3mdelta[0m[2m=[0m4s 999ms 995µs 5ns ago
[INFO] [stdout] [2m2026-03-10T14:50:23.582723Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:23.582567277Z, server: 2026-03-10T14:50:23.582577407Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:23.582580767Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 745ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:23.582574022Z [3mdelta[0m[2m=[0m3µs 385ns
[INFO] [stdout] [2m2026-03-10T14:50:23.582823Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.585µs [3mdelta[0m[2m=[0m5µs 325ns
[INFO] [stdout] [2m2026-03-10T14:50:23.582817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.080559796s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.582843Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.745µs [3mdelta[0m[2m=[0m3µs 385ns
[INFO] [stdout] [2m2026-03-10T14:50:23.582847Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m400.964344ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.582922Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m3µs 385ns
[INFO] [stdout] [2m2026-03-10T14:50:23.583038Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.268132473s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.583566Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-03-10T14:50:23.583606Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.587574Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:23.587459807Z, server: 2026-03-10T14:50:28.587463647Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:23.587465667Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 930ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:23.587462737Z [3mdelta[0m[2m=[0m5s 910ns
[INFO] [stdout] [2m2026-03-10T14:50:23.587650Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.93µs [3mdelta[0m[2m=[0m5s 910ns
[INFO] [stdout] [2m2026-03-10T14:50:23.587672Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.260455962s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:23.985793Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:23.985625155Z, server: 2026-03-10T14:50:23.985634985Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:23.985638985Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 915ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:23.98563207Z [3mdelta[0m[2m=[0m2µs 915ns
[INFO] [stdout] [2m2026-03-10T14:50:23.985876Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.915µs [3mdelta[0m[2m=[0m2µs 915ns
[INFO] [stdout] [2m2026-03-10T14:50:23.985899Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m495.336969ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:24.482797Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:24.482609056Z, server: 2026-03-10T14:50:24.482619786Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:24.482624126Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 535ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:24.482616591Z [3mdelta[0m[2m=[0m3µs 195ns
[INFO] [stdout] [2m2026-03-10T14:50:24.482897Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.535µs [3mdelta[0m[2m=[0m3µs 195ns
[INFO] [stdout] [2m2026-03-10T14:50:24.482922Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m142.456818ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:24.630675Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:24.630492804Z, server: 2026-03-10T14:50:24.630504074Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:24.630508234Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 715ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:24.630500519Z [3mdelta[0m[2m=[0m3µs 555ns
[INFO] [stdout] [2m2026-03-10T14:50:24.630772Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.715µs [3mdelta[0m[2m=[0m3µs 555ns
[INFO] [stdout] [2m2026-03-10T14:50:24.630797Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m594.569224ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:24.664798Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:24.664600321Z, server: 2026-03-10T14:50:19.664612141Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:24.664615451Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 565ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:24.664607886Z [3mdelta[0m[2m=[0m4s 999ms 995µs 745ns ago
[INFO] [stdout] [2m2026-03-10T14:50:24.664904Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.565µs [3mdelta[0m[2m=[0m4s 999ms 995µs 745ns ago
[INFO] [stdout] [2m2026-03-10T14:50:24.664932Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.957662792s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:24.849815Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:24.849636827Z, server: 2026-03-10T14:50:29.849647637Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:24.849650957Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 65ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:24.849643892Z [3mdelta[0m[2m=[0m5s 3µs 745ns
[INFO] [stdout] [2m2026-03-10T14:50:24.849910Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.065µs [3mdelta[0m[2m=[0m5s 3µs 745ns
[INFO] [stdout] [2m2026-03-10T14:50:24.849933Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.876937098s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:24.852911Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:24.852740176Z, server: 2026-03-10T14:50:24.852753721Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:24.852754276Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 50ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:24.852747226Z [3mdelta[0m[2m=[0m6µs 495ns
[INFO] [stdout] [2m2026-03-10T14:50:24.853002Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.05µs [3mdelta[0m[2m=[0m6µs 495ns
[INFO] [stdout] [2m2026-03-10T14:50:24.853024Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m823.889733ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:25.226955Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:25.226772497Z, server: 2026-03-10T14:50:25.226782457Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:25.226786077Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 790ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:25.226779287Z [3mdelta[0m[2m=[0m3µs 170ns
[INFO] [stdout] [2m2026-03-10T14:50:25.227060Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.79µs [3mdelta[0m[2m=[0m3µs 170ns
[INFO] [stdout] [2m2026-03-10T14:50:25.227089Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00317, 0.002915, 0.003195, 0.005325, 0.003555]
[INFO] [stdout] [2m2026-03-10T14:50:25.227108Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.003195 [3mmean[0m[2m=[0m0.003632 [3mvariance[0m[2m=[0m9.476699999999999e-7 [3mstddev[0m[2m=[0m0.000973483435914551
[INFO] [stdout] [2m2026-03-10T14:50:25.227133Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00317, 0.002915, 0.003195, 0.003555]
[INFO] [stdout] [2m2026-03-10T14:50:25.227146Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] [2m2026-03-10T14:50:25.678848Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:25.678643621Z, server: 2026-03-10T14:50:25.678657766Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:25.678658321Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 350ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:25.678650971Z [3mdelta[0m[2m=[0m6µs 795ns
[INFO] [stdout] [2m2026-03-10T14:50:25.678945Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.35µs [3mdelta[0m[2m=[0m6µs 795ns
[INFO] [stdout] [2m2026-03-10T14:50:25.678969Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m301.825674ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:25.989510Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:25.989285366Z, server: 2026-03-10T14:50:25.989300641Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:25.989301506Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 70ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:25.989293436Z [3mdelta[0m[2m=[0m7µs 205ns
[INFO] [stdout] [2m2026-03-10T14:50:25.989610Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.07µs [3mdelta[0m[2m=[0m7µs 205ns
[INFO] [stdout] [2m2026-03-10T14:50:25.989635Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.672517955s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:26.635695Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:26.635494025Z, server: 2026-03-10T14:50:21.635504345Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:26.635508905Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 440ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:26.635501465Z [3mdelta[0m[2m=[0m4s 999ms 997µs 120ns ago
[INFO] [stdout] [2m2026-03-10T14:50:26.635800Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.44µs [3mdelta[0m[2m=[0m4s 999ms 997µs 120ns ago
[INFO] [stdout] [2m2026-03-10T14:50:26.635823Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.150994366s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:26.729754Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:26.729546157Z, server: 2026-03-10T14:50:31.729559357Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:26.729563987Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 915ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:26.729555072Z [3mdelta[0m[2m=[0m5s 4µs 285ns
[INFO] [stdout] [2m2026-03-10T14:50:26.729869Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.915µs [3mdelta[0m[2m=[0m5s 4µs 285ns
[INFO] [stdout] [2m2026-03-10T14:50:26.729894Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m639.435551ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:27.370777Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:27.370599406Z, server: 2026-03-10T14:50:32.370609206Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:27.370613566Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 80ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:27.370606486Z [3mdelta[0m[2m=[0m5s 2µs 720ns
[INFO] [stdout] [2m2026-03-10T14:50:27.370873Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.08µs [3mdelta[0m[2m=[0m5s 2µs 720ns
[INFO] [stdout] [2m2026-03-10T14:50:27.370896Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m342.304753ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:27.665684Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:27.665494333Z, server: 2026-03-10T14:50:27.665508188Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:27.665509063Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 365ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:27.665501698Z [3mdelta[0m[2m=[0m6µs 490ns
[INFO] [stdout] [2m2026-03-10T14:50:27.665779Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.365µs [3mdelta[0m[2m=[0m6µs 490ns
[INFO] [stdout] [2m2026-03-10T14:50:27.665805Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.003385, 0.006495, 0.006795, 0.00649, 0.007205]
[INFO] [stdout] [2m2026-03-10T14:50:27.665823Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.006795 [3mmean[0m[2m=[0m0.0060739999999999995 [3mvariance[0m[2m=[0m2.3450049999999995e-6 [3mstddev[0m[2m=[0m0.0015313409156683562
[INFO] [stdout] [2m2026-03-10T14:50:27.665842Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.006495, 0.006795, 0.00649, 0.007205]
[INFO] [stdout] [2m2026-03-10T14:50:27.665855Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m6µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] [2m2026-03-10T14:50:27.714839Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:27.714652959Z, server: 2026-03-10T14:50:32.714662729Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:27.714666879Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 960ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:27.714659919Z [3mdelta[0m[2m=[0m5s 2µs 810ns
[INFO] [stdout] [2m2026-03-10T14:50:27.714936Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.96µs [3mdelta[0m[2m=[0m5s 2µs 810ns
[INFO] [stdout] [2m2026-03-10T14:50:27.714967Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00091, 5000.00281, 5000.003745, 5000.00272, 5000.004285]
[INFO] [stdout] [2m2026-03-10T14:50:27.714988Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.003745 [3mmean[0m[2m=[0m5000.002893999999 [3mvariance[0m[2m=[0m1.658167500194613e-6 [3mstddev[0m[2m=[0m0.0012876985284586656
[INFO] [stdout] [2m2026-03-10T14:50:27.715010Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00281, 5000.003745, 5000.00272, 5000.004285]
[INFO] [stdout] [2m2026-03-10T14:50:27.715024Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 3µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-03-10T14:50:27.795686Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:27.795496832Z, server: 2026-03-10T14:50:22.795508023Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:27.795511483Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 325ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:27.795504157Z [3mdelta[0m[2m=[0m4s 999ms 996µs 134ns ago
[INFO] [stdout] [2m2026-03-10T14:50:27.795794Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.325µs [3mdelta[0m[2m=[0m4s 999ms 996µs 134ns ago
[INFO] [stdout] [2m2026-03-10T14:50:27.795819Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.791104426s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-10T14:50:29.588823Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-10T14:50:29.58863616Z, server: 2026-03-10T14:50:24.58864739Z } [3mcurrent[0m[2m=[0m2026-03-10T14:50:29.58865105Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 445ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-10T14:50:29.588643605Z [3mdelta[0m[2m=[0m4s 999ms 996µs 215ns ago
[INFO] [stdout] [2m2026-03-10T14:50:29.588926Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.445µs [3mdelta[0m[2m=[0m4s 999ms 996µs 215ns ago
[INFO] [stdout] [2m2026-03-10T14:50:29.588954Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.996134, -4999.99712, -4999.996215, -4999.995745, -4999.995005]
[INFO] [stdout] [2m2026-03-10T14:50:29.588973Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.996215 [3mmean[0m[2m=[0m-4999.9960438 [3mvariance[0m[2m=[0m5.910097001039453e-7 [3mstddev[0m[2m=[0m0.0007687715526110115
[INFO] [stdout] [2m2026-03-10T14:50:29.588995Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.996134, -4999.996215, -4999.995745]
[INFO] [stdout] [2m2026-03-10T14:50:29.589018Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 996µ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 6.01s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-e945ddf2a2af16be)
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 1.32s; merged doctests compilation took 1.29s
[INFO] running `Command { std: "docker" "inspect" "fc525abd8429b13f1761d787cc0883b68d4beee20f70fd60052b9e75720cb3bc", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "fc525abd8429b13f1761d787cc0883b68d4beee20f70fd60052b9e75720cb3bc", kill_on_drop: false }`
[INFO] [stdout] fc525abd8429b13f1761d787cc0883b68d4beee20f70fd60052b9e75720cb3bc
