[INFO] cloning repository https://github.com/passcod/timesimp
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/passcod/timesimp" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 92be20531742c87fc283ec0ed2fc2aa3b1f638ae
[INFO] testing passcod/timesimp against 1.98.0-beta.6+cargoflags=--release for beta-1.98-release-3
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-2-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-tc2/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-2-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 1.98.0-beta.6
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.98.0-beta.6" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate git repo https://github.com/passcod/timesimp already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.98.0-beta.6" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-m" "1610612736" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:00c5645b54fe3ce5dae1417175e3c7fb6a6646c021d554ecd63a097b8b9f3602" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] 23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46
[INFO] running `Command { std: "docker" "start" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "build" "--frozen" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling cfg-if v1.0.0
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling pin-project-lite v0.2.16
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling ryu v1.0.20
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 37.75s
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "test" "--frozen" "--no-run" "--message-format=json" "--release", 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 bytes v1.10.1
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling scopeguard v1.2.0
[INFO] [stderr]    Compiling futures-core v0.3.31
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling fnv v1.0.7
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling foreign-types-shared v0.1.1
[INFO] [stderr]    Compiling pin-utils v0.1.0
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling foreign-types v0.3.2
[INFO] [stderr]    Compiling atomic-waker v1.1.2
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling utf8_iter v1.0.4
[INFO] [stderr]    Compiling try-lock v0.2.5
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling indexmap v2.9.0
[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 encoding_rs v0.8.35
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling mime v0.3.17
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[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 icu_normalizer v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 46.42s
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.6" "test" "--frozen" "--release", kill_on_drop: false }`
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 0.11s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/deps/timesimp-fa789e8bca5fd394)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/release/deps/client_server-5357a3be2fee2b56)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-08-05T16:33:12.030865Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.030887Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.030891Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.030860Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-08-05T16:33:12.030907Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-08-05T16:33:12.030913Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.030898Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.030922Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.030917Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.030931Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.030997Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.031011Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.031105Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.031115Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.031151Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.031164Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.031295Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.031303Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:12.031309Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.031314Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.034386Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032203543Z, server: 2026-08-05T16:33:12.033292652Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.034368702Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 82µs 579ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.033286122Z [3mdelta[0m[2m=[0m6µs 530ns
[INFO] [stdout] [2m2026-08-05T16:33:12.034401Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.082579ms [3mdelta[0m[2m=[0m6µs 530ns
[INFO] [stdout] [2m2026-08-05T16:33:12.034407Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m6µs 530ns
[INFO] [stdout] [2m2026-08-05T16:33:12.034409Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.236456719s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.047186Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032009772Z, server: 2026-08-05T16:33:17.039089362Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.047167991Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 579µs 109ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.039588881Z [3mdelta[0m[2m=[0m4s 999ms 500µs 481ns
[INFO] [stdout] [2m2026-08-05T16:33:12.047202Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.579109ms [3mdelta[0m[2m=[0m4s 999ms 500µs 481ns
[INFO] [stdout] [2m2026-08-05T16:33:12.047209Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 500µs 481ns
[INFO] [stdout] [2m2026-08-05T16:33:12.047213Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.739095777s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.052179Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032009203Z, server: 2026-08-05T16:33:17.042085751Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.05216595Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 78µs 373ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.042087576Z [3mdelta[0m[2m=[0m4s 999ms 998µs 175ns
[INFO] [stdout] [2m2026-08-05T16:33:12.052192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.078373ms [3mdelta[0m[2m=[0m4s 999ms 998µs 175ns
[INFO] [stdout] [2m2026-08-05T16:33:12.052197Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 998µs 175ns
[INFO] [stdout] [2m2026-08-05T16:33:12.052199Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m846.828762ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.052196Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032026152Z, server: 2026-08-05T16:33:17.042104502Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.05218105Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 77µs 449ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.042103601Z [3mdelta[0m[2m=[0m5s 901ns
[INFO] [stdout] [2m2026-08-05T16:33:12.052206Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.077449ms [3mdelta[0m[2m=[0m5s 901ns
[INFO] [stdout] [2m2026-08-05T16:33:12.052210Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 901ns
[INFO] [stdout] [2m2026-08-05T16:33:12.052213Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.457274482s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.054200Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032010263Z, server: 2026-08-05T16:33:12.043097422Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.05418551Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 87µs 623ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.043097886Z [3mdelta[0m[2m=[0m464ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.054216Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.087623ms [3mdelta[0m[2m=[0m464ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.054214Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032040663Z, server: 2026-08-05T16:33:12.043120522Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.05419911Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 79µs 223ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.043119886Z [3mdelta[0m[2m=[0m636ns
[INFO] [stdout] [2m2026-08-05T16:33:12.054220Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.766394703s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.054224Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.079223ms [3mdelta[0m[2m=[0m636ns
[INFO] [stdout] [2m2026-08-05T16:33:12.054228Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m661.841011ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.054436Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032248723Z, server: 2026-08-05T16:33:07.043325102Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.05441049Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 80µs 883ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.043329606Z [3mdelta[0m[2m=[0m5s 4µs 504ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.054449Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.080883ms [3mdelta[0m[2m=[0m5s 4µs 504ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.054454Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 4µs 504ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.054458Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m550.281398ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.054588Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032401612Z, server: 2026-08-05T16:33:17.043480461Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.05457586Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 87µs 124ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.043488736Z [3mdelta[0m[2m=[0m4s 999ms 991µs 725ns
[INFO] [stdout] [2m2026-08-05T16:33:12.054601Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.087124ms [3mdelta[0m[2m=[0m4s 999ms 991µs 725ns
[INFO] [stdout] [2m2026-08-05T16:33:12.054606Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 991µs 725ns
[INFO] [stdout] [2m2026-08-05T16:33:12.054608Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m456.387659ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.234833Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032403303Z, server: 2026-08-05T16:33:12.133599802Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.234805932Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 201µs 314ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.133604617Z [3mdelta[0m[2m=[0m4µs 815ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.234855Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.201314ms [3mdelta[0m[2m=[0m4µs 815ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.234861Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4µs 815ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.234864Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.657750446s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.534423Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.512194144Z, server: 2026-08-05T16:33:17.523281253Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.534397172Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 101µs 514ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.523295658Z [3mdelta[0m[2m=[0m4s 999ms 985µs 595ns
[INFO] [stdout] [2m2026-08-05T16:33:12.534446Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.101514ms [3mdelta[0m[2m=[0m4s 999ms 985µs 595ns
[INFO] [stdout] [2m2026-08-05T16:33:12.534453Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.167928791s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.627333Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.606085175Z, server: 2026-08-05T16:33:07.616239453Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.627322372Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 618µs 598ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.616703773Z [3mdelta[0m[2m=[0m5s 464µs 320ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.627348Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.618598ms [3mdelta[0m[2m=[0m5s 464µs 320ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.627354Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m128.188777ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.739641Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.717387714Z, server: 2026-08-05T16:33:12.728473592Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.739622901Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 117µs 593ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.728505307Z [3mdelta[0m[2m=[0m31µs 715ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.739663Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.117593ms [3mdelta[0m[2m=[0m31µs 715ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.739669Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.812121702s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.778766Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.75658115Z, server: 2026-08-05T16:33:07.767666938Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.778752177Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 85µs 513ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.767666663Z [3mdelta[0m[2m=[0m4s 999ms 999µs 725ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.778784Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.085513ms [3mdelta[0m[2m=[0m4s 999ms 999µs 725ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.778789Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m50.743738ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.853152Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.830961512Z, server: 2026-08-05T16:33:07.842047861Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.85313502Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 86µs 754ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.842048266Z [3mdelta[0m[2m=[0m5s 405ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.853171Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.086754ms [3mdelta[0m[2m=[0m5s 405ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.853177Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m50.390949ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.921349Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.900165365Z, server: 2026-08-05T16:33:17.910252174Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.921331123Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 582µs 879ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.910748244Z [3mdelta[0m[2m=[0m4s 999ms 503µs 930ns
[INFO] [stdout] [2m2026-08-05T16:33:12.921378Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.582879ms [3mdelta[0m[2m=[0m4s 999ms 503µs 930ns
[INFO] [stdout] [2m2026-08-05T16:33:12.921389Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m766.969076ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:12.926556Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.904354125Z, server: 2026-08-05T16:33:07.915447334Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:12.926538512Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 92µs 193ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.915446318Z [3mdelta[0m[2m=[0m4s 999ms 998µs 984ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.926575Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.092193ms [3mdelta[0m[2m=[0m4s 999ms 998µs 984ns ago
[INFO] [stdout] [2m2026-08-05T16:33:12.926582Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-5000.46432, -5000.004504, -4999.999725, -5000.000405, -4999.998984]
[INFO] [stdout] [2m2026-08-05T16:33:12.926587Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.999725 [3mmean[0m[2m=[0m-5000.0935876 [3mvariance[0m[2m=[0m0.04295535648832163 [3mstddev[0m[2m=[0m0.20725674051359977
[INFO] [stdout] [2m2026-08-05T16:33:12.926591Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-5000.004504, -4999.999725, -5000.000405, -4999.998984]
[INFO] [stdout] [2m2026-08-05T16:33:12.926594Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-08-05T16:33:13.274087Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.271854527Z, server: 2026-08-05T16:33:13.272964307Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.274069537Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 107µs 505ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.272962032Z [3mdelta[0m[2m=[0m2µs 275ns
[INFO] [stdout] [2m2026-08-05T16:33:13.274109Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.107505ms [3mdelta[0m[2m=[0m2µs 275ns
[INFO] [stdout] [2m2026-08-05T16:33:13.274117Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m13.637864ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:13.290442Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.288248096Z, server: 2026-08-05T16:33:13.289344616Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.290426866Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 89µs 385ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.289337481Z [3mdelta[0m[2m=[0m7µs 135ns
[INFO] [stdout] [2m2026-08-05T16:33:13.290461Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.089385ms [3mdelta[0m[2m=[0m7µs 135ns
[INFO] [stdout] [2m2026-08-05T16:33:13.290469Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.420003053s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:13.526107Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.510858754Z, server: 2026-08-05T16:33:18.518975663Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.526089142Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 615µs 194ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.518473948Z [3mdelta[0m[2m=[0m5s 501µs 715ns
[INFO] [stdout] [2m2026-08-05T16:33:13.526131Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.615194ms [3mdelta[0m[2m=[0m5s 501µs 715ns
[INFO] [stdout] [2m2026-08-05T16:33:13.526140Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m521.245509ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:13.566191Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:12.032102723Z, server: 2026-08-05T16:33:12.799307315Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.566162518Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m767ms 29µs 897ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:12.79913262Z [3mdelta[0m[2m=[0m174µs 695ns
[INFO] [stdout] [2m2026-08-05T16:33:13.566212Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m767.029897ms [3mdelta[0m[2m=[0m174µs 695ns
[INFO] [stdout] [2m2026-08-05T16:33:13.566219Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m174µs 695ns
[INFO] [stdout] [2m2026-08-05T16:33:13.566221Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m872.110717ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:13.711517Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.689240945Z, server: 2026-08-05T16:33:18.700406874Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.711497303Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 128µs 179ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.700369124Z [3mdelta[0m[2m=[0m5s 37µs 750ns
[INFO] [stdout] [2m2026-08-05T16:33:13.711542Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.128179ms [3mdelta[0m[2m=[0m5s 37µs 750ns
[INFO] [stdout] [2m2026-08-05T16:33:13.711549Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.395788883s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:13.726061Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.703807894Z, server: 2026-08-05T16:33:18.714916413Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.726038742Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 115µs 424ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.714923318Z [3mdelta[0m[2m=[0m4s 999ms 993µs 95ns
[INFO] [stdout] [2m2026-08-05T16:33:13.726089Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.115424ms [3mdelta[0m[2m=[0m4s 999ms 993µs 95ns
[INFO] [stdout] [2m2026-08-05T16:33:13.726098Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m458.37758ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:13.797282Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.787071855Z, server: 2026-08-05T16:33:18.792161105Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.797247074Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5ms 87µs 609ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.792159464Z [3mdelta[0m[2m=[0m5s 1µs 641ns
[INFO] [stdout] [2m2026-08-05T16:33:13.797305Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.087609ms [3mdelta[0m[2m=[0m5s 1µs 641ns
[INFO] [stdout] [2m2026-08-05T16:33:13.797312Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.567990886s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:13.843436Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.821101882Z, server: 2026-08-05T16:33:13.832304741Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:13.84340876Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 153µs 439ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.832255321Z [3mdelta[0m[2m=[0m49µs 420ns
[INFO] [stdout] [2m2026-08-05T16:33:13.843461Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.153439ms [3mdelta[0m[2m=[0m49µs 420ns
[INFO] [stdout] [2m2026-08-05T16:33:13.843469Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.155079306s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:14.064120Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.048859069Z, server: 2026-08-05T16:33:19.056983688Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:14.064101178Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 621µs 54ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:14.056480123Z [3mdelta[0m[2m=[0m5s 503µs 565ns
[INFO] [stdout] [2m2026-08-05T16:33:14.064145Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.621054ms [3mdelta[0m[2m=[0m5s 503µs 565ns
[INFO] [stdout] [2m2026-08-05T16:33:14.064155Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m723.284531ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:14.096154Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:13.893686105Z, server: 2026-08-05T16:33:13.994910505Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:14.096135115Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 224µs 505ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:13.99491061Z [3mdelta[0m[2m=[0m105ns ago
[INFO] [stdout] [2m2026-08-05T16:33:14.096177Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.224505ms [3mdelta[0m[2m=[0m105ns ago
[INFO] [stdout] [2m2026-08-05T16:33:14.096183Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m517.562935ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:14.207994Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.185719045Z, server: 2026-08-05T16:33:19.196843424Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:14.207973443Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 127µs 199ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:14.196846244Z [3mdelta[0m[2m=[0m4s 999ms 997µs 180ns
[INFO] [stdout] [2m2026-08-05T16:33:14.208020Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.127199ms [3mdelta[0m[2m=[0m4s 999ms 997µs 180ns
[INFO] [stdout] [2m2026-08-05T16:33:14.208028Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.470249539s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:14.574778Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.552591768Z, server: 2026-08-05T16:33:14.563675257Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:14.574759396Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 83µs 814ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:14.563675582Z [3mdelta[0m[2m=[0m325ns ago
[INFO] [stdout] [2m2026-08-05T16:33:14.574799Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.083814ms [3mdelta[0m[2m=[0m325ns ago
[INFO] [stdout] [2m2026-08-05T16:33:14.574805Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.35694129s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:14.713117Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.712000302Z, server: 2026-08-05T16:33:14.713090052Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:14.713095922Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m547µs 810ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:14.712548112Z [3mdelta[0m[2m=[0m541µs 940ns
[INFO] [stdout] [2m2026-08-05T16:33:14.713142Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m547.81µs [3mdelta[0m[2m=[0m541µs 940ns
[INFO] [stdout] [2m2026-08-05T16:33:14.713151Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m919.112249ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:14.802080Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.788819285Z, server: 2026-08-05T16:33:19.795937474Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:14.802060973Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 620µs 844ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:14.795440129Z [3mdelta[0m[2m=[0m5s 497µs 345ns
[INFO] [stdout] [2m2026-08-05T16:33:14.802105Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.620844ms [3mdelta[0m[2m=[0m5s 497µs 345ns
[INFO] [stdout] [2m2026-08-05T16:33:14.802115Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.704488116s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:14.816859Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.614821832Z, server: 2026-08-05T16:33:14.716015002Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:14.816841362Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 9µs 765ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:14.715831597Z [3mdelta[0m[2m=[0m183µs 405ns
[INFO] [stdout] [2m2026-08-05T16:33:14.816887Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.009765ms [3mdelta[0m[2m=[0m183µs 405ns
[INFO] [stdout] [2m2026-08-05T16:33:14.816894Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m425.579765ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.021043Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.999788733Z, server: 2026-08-05T16:33:15.009908642Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.021021461Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 616µs 364ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.010405097Z [3mdelta[0m[2m=[0m496µs 455ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.021072Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.616364ms [3mdelta[0m[2m=[0m496µs 455ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.021081Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m439.933328ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.130297Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.108065833Z, server: 2026-08-05T16:33:20.119173831Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.13027664Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 105µs 403ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.119171236Z [3mdelta[0m[2m=[0m5s 2µs 595ns
[INFO] [stdout] [2m2026-08-05T16:33:15.130319Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.105403ms [3mdelta[0m[2m=[0m5s 2µs 595ns
[INFO] [stdout] [2m2026-08-05T16:33:15.130326Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.587763555s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.378242Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.366011466Z, server: 2026-08-05T16:33:20.372127006Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.378223745Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 106µs 139ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.372117605Z [3mdelta[0m[2m=[0m5s 9µs 401ns
[INFO] [stdout] [2m2026-08-05T16:33:15.378293Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.106139ms [3mdelta[0m[2m=[0m5s 9µs 401ns
[INFO] [stdout] [2m2026-08-05T16:33:15.378304Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m195.718439ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.445893Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.243465819Z, server: 2026-08-05T16:33:15.344661618Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.445874208Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 204µs 194ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.344670013Z [3mdelta[0m[2m=[0m8µs 395ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.445930Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.204194ms [3mdelta[0m[2m=[0m8µs 395ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.445937Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m537.132734ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.484610Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.462414187Z, server: 2026-08-05T16:33:15.473503976Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.484593924Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 89µs 868ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.473504055Z [3mdelta[0m[2m=[0m79ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.484631Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.089868ms [3mdelta[0m[2m=[0m79ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.484638Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m433.005663ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.591816Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.575623775Z, server: 2026-08-05T16:33:20.583710514Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.591798044Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 87µs 134ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.583710909Z [3mdelta[0m[2m=[0m4s 999ms 999µs 605ns
[INFO] [stdout] [2m2026-08-05T16:33:15.591838Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.087134ms [3mdelta[0m[2m=[0m4s 999ms 999µs 605ns
[INFO] [stdout] [2m2026-08-05T16:33:15.591845Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.445591864s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.635419Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.63324608Z, server: 2026-08-05T16:33:15.634328089Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.635402609Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 78µs 264ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.634324344Z [3mdelta[0m[2m=[0m3µs 745ns
[INFO] [stdout] [2m2026-08-05T16:33:15.635443Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.078264ms [3mdelta[0m[2m=[0m3µs 745ns
[INFO] [stdout] [2m2026-08-05T16:33:15.635449Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.54194, 0.003745, 0.00653, 0.007135, 0.002275]
[INFO] [stdout] [2m2026-08-05T16:33:15.635454Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00653 [3mmean[0m[2m=[0m0.11232500000000001 [3mvariance[0m[2m=[0m0.0576817963125 [3mstddev[0m[2m=[0m0.24017034852891395
[INFO] [stdout] [2m2026-08-05T16:33:15.635458Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.003745, 0.00653, 0.007135, 0.002275]
[INFO] [stdout] [2m2026-08-05T16:33:15.635461Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-08-05T16:33:15.700781Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.678443235Z, server: 2026-08-05T16:33:20.689656814Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.700760833Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 158µs 799ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.689602034Z [3mdelta[0m[2m=[0m5s 54µs 780ns
[INFO] [stdout] [2m2026-08-05T16:33:15.700807Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.158799ms [3mdelta[0m[2m=[0m5s 54µs 780ns
[INFO] [stdout] [2m2026-08-05T16:33:15.700816Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.991725, 4999.985595, 4999.993095, 4999.99718, 5000.05478]
[INFO] [stdout] [2m2026-08-05T16:33:15.700822Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.993095 [3mmean[0m[2m=[0m5000.004475 [3mvariance[0m[2m=[0m0.0008080828375097518 [3mstddev[0m[2m=[0m0.028426797876471274
[INFO] [stdout] [2m2026-08-05T16:33:15.700828Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.991725, 4999.985595, 4999.993095, 4999.99718]
[INFO] [stdout] [2m2026-08-05T16:33:15.700833Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 991µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-08-05T16:33:15.852795Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:14.43919279Z, server: 2026-08-05T16:33:15.145988918Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.852776687Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m706ms 791µs 948ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.145984738Z [3mdelta[0m[2m=[0m4µs 180ns
[INFO] [stdout] [2m2026-08-05T16:33:15.852816Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m706.791948ms [3mdelta[0m[2m=[0m4µs 180ns
[INFO] [stdout] [2m2026-08-05T16:33:15.852823Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m973.684523ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:15.940474Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.918174811Z, server: 2026-08-05T16:33:15.92927964Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.940455869Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 140µs 529ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.92931534Z [3mdelta[0m[2m=[0m35µs 700ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.940496Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.140529ms [3mdelta[0m[2m=[0m35µs 700ns ago
[INFO] [stdout] [2m2026-08-05T16:33:15.940504Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.496455, -0.000464, -7.9e-5, -0.0357, 0.04942]
[INFO] [stdout] [2m2026-08-05T16:33:15.940511Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-7.9e-5 [3mmean[0m[2m=[0m-0.0966556 [3mvariance[0m[2m=[0m0.05086827247629999 [3mstddev[0m[2m=[0m0.22553995760463375
[INFO] [stdout] [2m2026-08-05T16:33:15.940515Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.000464, -7.9e-5, -0.0357, 0.04942]
[INFO] [stdout] [2m2026-08-05T16:33:15.940519Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-08-05T16:33:15.954509Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.932247509Z, server: 2026-08-05T16:33:15.943415478Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:15.954497657Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 125µs 74ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:15.943372583Z [3mdelta[0m[2m=[0m42µs 895ns
[INFO] [stdout] [2m2026-08-05T16:33:15.954526Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.125074ms [3mdelta[0m[2m=[0m42µs 895ns
[INFO] [stdout] [2m2026-08-05T16:33:15.954533Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m747.872388ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:16.186125Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:15.983559364Z, server: 2026-08-05T16:33:16.084862204Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:16.186108264Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 274µs 450ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:16.084833814Z [3mdelta[0m[2m=[0m28µs 390ns
[INFO] [stdout] [2m2026-08-05T16:33:16.186146Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.27445ms [3mdelta[0m[2m=[0m28µs 390ns
[INFO] [stdout] [2m2026-08-05T16:33:16.186153Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.183405, -0.004815, -0.008395, -0.000105, 0.02839]
[INFO] [stdout] [2m2026-08-05T16:33:16.186158Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.008395 [3mmean[0m[2m=[0m0.03969600000000001 [3mvariance[0m[2m=[0m0.00666454883 [3mstddev[0m[2m=[0m0.08163668801464205
[INFO] [stdout] [2m2026-08-05T16:33:16.186162Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.004815, -0.008395, -0.000105, 0.02839]
[INFO] [stdout] [2m2026-08-05T16:33:16.186165Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-08-05T16:33:16.520376Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:16.508023071Z, server: 2026-08-05T16:33:21.51425182Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:16.52035869Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 167µs 809ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:16.51419088Z [3mdelta[0m[2m=[0m5s 60µs 940ns
[INFO] [stdout] [2m2026-08-05T16:33:16.520398Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.167809ms [3mdelta[0m[2m=[0m5s 60µs 940ns
[INFO] [stdout] [2m2026-08-05T16:33:16.520405Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.06094, 5000.497345, 5000.501715, 5000.503565, 5000.000901]
[INFO] [stdout] [2m2026-08-05T16:33:16.520410Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.501715 [3mmean[0m[2m=[0m5000.3128932 [3mvariance[0m[2m=[0m0.06671285546111713 [3mstddev[0m[2m=[0m0.25828831847591777
[INFO] [stdout] [2m2026-08-05T16:33:16.520414Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.497345, 5000.501715, 5000.503565]
[INFO] [stdout] [2m2026-08-05T16:33:16.520417Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 500µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-08-05T16:33:16.726684Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:16.704452832Z, server: 2026-08-05T16:33:16.71557268Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:16.726666869Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 107µs 18ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:16.71555985Z [3mdelta[0m[2m=[0m12µs 830ns
[INFO] [stdout] [2m2026-08-05T16:33:16.726706Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.107018ms [3mdelta[0m[2m=[0m12µs 830ns
[INFO] [stdout] [2m2026-08-05T16:33:16.726713Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000636, -0.000325, 0.01283, -0.031715, 0.042895]
[INFO] [stdout] [2m2026-08-05T16:33:16.726720Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.01283 [3mmean[0m[2m=[0m0.004864200000000001 [3mvariance[0m[2m=[0m0.0007231597657000001 [3mstddev[0m[2m=[0m0.0268916300305504
[INFO] [stdout] [2m2026-08-05T16:33:16.726724Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.000636, -0.000325, 0.01283]
[INFO] [stdout] [2m2026-08-05T16:33:16.726728Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-08-05T16:33:16.741316Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:16.71913803Z, server: 2026-08-05T16:33:21.730222099Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:16.741304888Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 83µs 429ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:16.730221459Z [3mdelta[0m[2m=[0m5s 640ns
[INFO] [stdout] [2m2026-08-05T16:33:16.741334Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.083429ms [3mdelta[0m[2m=[0m5s 640ns
[INFO] [stdout] [2m2026-08-05T16:33:16.741343Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.998175, 4999.50393, 5000.00064, 5000.002595, 5000.03775]
[INFO] [stdout] [2m2026-08-05T16:33:16.741350Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00064 [3mmean[0m[2m=[0m4999.9086179999995 [3mvariance[0m[2m=[0m0.05144190800754957 [3mstddev[0m[2m=[0m0.22680808629224306
[INFO] [stdout] [2m2026-08-05T16:33:16.741357Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.998175, 5000.00064, 5000.002595, 5000.03775]
[INFO] [stdout] [2m2026-08-05T16:33:16.741362Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 9µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-08-05T16:33:17.052603Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:17.038430058Z, server: 2026-08-05T16:33:22.045509887Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:17.052585176Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 77µs 559ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:17.045507617Z [3mdelta[0m[2m=[0m5s 2µs 270ns
[INFO] [stdout] [2m2026-08-05T16:33:17.052623Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.077559ms [3mdelta[0m[2m=[0m5s 2µs 270ns
[INFO] [stdout] [2m2026-08-05T16:33:17.052630Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.001641, 5000.009401, 5000.00227, 4999.500481, 4999.999605]
[INFO] [stdout] [2m2026-08-05T16:33:17.052635Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00227 [3mmean[0m[2m=[0m4999.9026796 [3mvariance[0m[2m=[0m0.05056482767179451 [3mstddev[0m[2m=[0m0.224866243958035
[INFO] [stdout] [2m2026-08-05T16:33:17.052639Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.001641, 5000.009401, 5000.00227, 4999.999605]
[INFO] [stdout] [2m2026-08-05T16:33:17.052642Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 3µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-08-05T16:33:18.267572Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:16.827904399Z, server: 2026-08-05T16:33:17.547737116Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:18.267554904Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m719ms 825µs 252ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:17.547729651Z [3mdelta[0m[2m=[0m7µs 465ns
[INFO] [stdout] [2m2026-08-05T16:33:18.267593Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m719.825252ms [3mdelta[0m[2m=[0m7µs 465ns
[INFO] [stdout] [2m2026-08-05T16:33:18.267600Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m712.845189ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:20.785460Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:18.981406352Z, server: 2026-08-05T16:33:19.883417221Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:20.78544231Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m902ms 17µs 979ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:19.883424331Z [3mdelta[0m[2m=[0m7µs 110ns ago
[INFO] [stdout] [2m2026-08-05T16:33:20.785480Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m902.017979ms [3mdelta[0m[2m=[0m7µs 110ns ago
[INFO] [stdout] [2m2026-08-05T16:33:20.785487Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.914431235s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.147201Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:22.700493207Z, server: 2026-08-05T16:33:23.424309264Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.147177511Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m723ms 342µs 152ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:23.423835359Z [3mdelta[0m[2m=[0m473µs 905ns
[INFO] [stdout] [2m2026-08-05T16:33:24.147227Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m723.342152ms [3mdelta[0m[2m=[0m473µs 905ns
[INFO] [stdout] [2m2026-08-05T16:33:24.147237Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00418, 0.007465, 0.473905, 0.174695, -0.00711]
[INFO] [stdout] [2m2026-08-05T16:33:24.147244Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.473905 [3mmean[0m[2m=[0m0.130627 [3mvariance[0m[2m=[0m0.0424777442825 [3mstddev[0m[2m=[0m0.20610129616889847
[INFO] [stdout] [2m2026-08-05T16:33:24.147250Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.473905]
[INFO] [stdout] [2m2026-08-05T16:33:24.147254Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m473µs
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.12s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/release/deps/in_process-674d4aac00732fde)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-08-05T16:33:24.149802Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-08-05T16:33:24.149827Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.149806Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:24.149828Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-08-05T16:33:24.149839Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.149841Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.149833Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-08-05T16:33:24.149855Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.150960Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:24.150945641Z, server: 2026-08-05T16:33:19.150945771Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.150945881Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m120ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:24.150945761Z [3mdelta[0m[2m=[0m4s 999ms 999µs 990ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.150968Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:24.150954451Z, server: 2026-08-05T16:33:24.150954591Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.150954681Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m115ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:24.150954566Z [3mdelta[0m[2m=[0m25ns
[INFO] [stdout] [2m2026-08-05T16:33:24.150968Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:24.150954941Z, server: 2026-08-05T16:33:24.150954991Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.150955061Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m60ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:24.150955001Z [3mdelta[0m[2m=[0m10ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.150980Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m115ns [3mdelta[0m[2m=[0m25ns
[INFO] [stdout] [2m2026-08-05T16:33:24.150987Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m25ns
[INFO] [stdout] [2m2026-08-05T16:33:24.150988Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m60ns [3mdelta[0m[2m=[0m10ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.150991Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.40527569s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.150975Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m120ns [3mdelta[0m[2m=[0m4s 999ms 999µs 990ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.150994Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.350990036s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.150998Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m100.448303ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.150997Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:24.150975641Z, server: 2026-08-05T16:33:29.150975781Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.150975951Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m155ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:24.150975796Z [3mdelta[0m[2m=[0m4s 999ms 999µs 985ns
[INFO] [stdout] [2m2026-08-05T16:33:24.151012Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m155ns [3mdelta[0m[2m=[0m4s 999ms 999µs 985ns
[INFO] [stdout] [2m2026-08-05T16:33:24.151019Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m398.361019ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.252240Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:24.252218551Z, server: 2026-08-05T16:33:19.252218871Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.252218951Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m200ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:24.252218751Z [3mdelta[0m[2m=[0m4s 999ms 999µs 880ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.252288Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m200ns [3mdelta[0m[2m=[0m4s 999ms 999µs 880ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.252296Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m602.690633ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.550589Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:24.550566891Z, server: 2026-08-05T16:33:29.550567221Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.550567681Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m395ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:24.550567286Z [3mdelta[0m[2m=[0m4s 999ms 999µs 935ns
[INFO] [stdout] [2m2026-08-05T16:33:24.550617Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m395ns [3mdelta[0m[2m=[0m4s 999ms 999µs 935ns
[INFO] [stdout] [2m2026-08-05T16:33:24.550626Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m789.937317ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:24.856076Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:24.85605763Z, server: 2026-08-05T16:33:19.85605792Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:24.85605798Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m175ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:24.856057805Z [3mdelta[0m[2m=[0m4s 999ms 999µs 885ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.856096Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m175ns [3mdelta[0m[2m=[0m4s 999ms 999µs 885ns ago
[INFO] [stdout] [2m2026-08-05T16:33:24.856102Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.365406384s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:25.341659Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:25.341636321Z, server: 2026-08-05T16:33:30.341636541Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:25.341636631Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m155ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:25.341636476Z [3mdelta[0m[2m=[0m5s 65ns
[INFO] [stdout] [2m2026-08-05T16:33:25.341688Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m155ns [3mdelta[0m[2m=[0m5s 65ns
[INFO] [stdout] [2m2026-08-05T16:33:25.341696Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.231732272s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:25.503434Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:25.503413305Z, server: 2026-08-05T16:33:25.503413715Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:25.503413795Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m245ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:25.50341355Z [3mdelta[0m[2m=[0m165ns
[INFO] [stdout] [2m2026-08-05T16:33:25.503460Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m245ns [3mdelta[0m[2m=[0m165ns
[INFO] [stdout] [2m2026-08-05T16:33:25.503469Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m217.792358ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:25.557438Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:25.557420109Z, server: 2026-08-05T16:33:25.557420434Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:25.557420469Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m180ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:25.557420289Z [3mdelta[0m[2m=[0m145ns
[INFO] [stdout] [2m2026-08-05T16:33:25.557459Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m180ns [3mdelta[0m[2m=[0m145ns
[INFO] [stdout] [2m2026-08-05T16:33:25.557465Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.012235281s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:25.722820Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:25.722801532Z, server: 2026-08-05T16:33:25.722801812Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:25.722801883Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m175ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:25.722801707Z [3mdelta[0m[2m=[0m105ns
[INFO] [stdout] [2m2026-08-05T16:33:25.722839Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m175ns [3mdelta[0m[2m=[0m105ns
[INFO] [stdout] [2m2026-08-05T16:33:25.722844Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m216.00574ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:25.940164Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:25.940145951Z, server: 2026-08-05T16:33:25.940146251Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:25.940146311Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m180ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:25.940146131Z [3mdelta[0m[2m=[0m120ns
[INFO] [stdout] [2m2026-08-05T16:33:25.940184Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m180ns [3mdelta[0m[2m=[0m120ns
[INFO] [stdout] [2m2026-08-05T16:33:25.940190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.577416987s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:26.222434Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:26.222412962Z, server: 2026-08-05T16:33:21.222413402Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:26.222413572Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m305ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:26.222413267Z [3mdelta[0m[2m=[0m4s 999ms 999µs 865ns ago
[INFO] [stdout] [2m2026-08-05T16:33:26.222463Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m305ns [3mdelta[0m[2m=[0m4s 999ms 999µs 865ns ago
[INFO] [stdout] [2m2026-08-05T16:33:26.222471Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m924.683215ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:26.570456Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:26.570434557Z, server: 2026-08-05T16:33:26.570434882Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:26.570434937Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m190ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:26.570434747Z [3mdelta[0m[2m=[0m135ns
[INFO] [stdout] [2m2026-08-05T16:33:26.570488Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m190ns [3mdelta[0m[2m=[0m135ns
[INFO] [stdout] [2m2026-08-05T16:33:26.570496Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.587039701s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:26.574419Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:26.574404187Z, server: 2026-08-05T16:33:31.574404507Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:26.574404687Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m250ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:26.574404437Z [3mdelta[0m[2m=[0m5s 70ns
[INFO] [stdout] [2m2026-08-05T16:33:26.574445Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m250ns [3mdelta[0m[2m=[0m5s 70ns
[INFO] [stdout] [2m2026-08-05T16:33:26.574452Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m89.01298ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:26.664417Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:26.664390608Z, server: 2026-08-05T16:33:31.664391008Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:26.664391088Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m240ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:26.664390848Z [3mdelta[0m[2m=[0m5s 160ns
[INFO] [stdout] [2m2026-08-05T16:33:26.664449Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m240ns [3mdelta[0m[2m=[0m5s 160ns
[INFO] [stdout] [2m2026-08-05T16:33:26.664458Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.999985, 5000.000065, 5000.00016, 5000.00007, 4999.999935]
[INFO] [stdout] [2m2026-08-05T16:33:26.664466Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00016 [3mmean[0m[2m=[0m5000.000043 [3mvariance[0m[2m=[0m7.48249997756473e-9 [3mstddev[0m[2m=[0m8.650144494495297e-5
[INFO] [stdout] [2m2026-08-05T16:33:26.664472Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00016]
[INFO] [stdout] [2m2026-08-05T16:33:26.664475Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-08-05T16:33:27.148467Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:27.148446159Z, server: 2026-08-05T16:33:22.148446589Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:27.148446669Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m255ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:27.148446414Z [3mdelta[0m[2m=[0m4s 999ms 999µs 825ns ago
[INFO] [stdout] [2m2026-08-05T16:33:27.148500Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m255ns [3mdelta[0m[2m=[0m4s 999ms 999µs 825ns ago
[INFO] [stdout] [2m2026-08-05T16:33:27.148508Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.99999, -4999.999885, -4999.99988, -4999.999825, -4999.999865]
[INFO] [stdout] [2m2026-08-05T16:33:27.148515Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.99988 [3mmean[0m[2m=[0m-4999.999889000001 [3mvariance[0m[2m=[0m3.74250001782304e-9 [3mstddev[0m[2m=[0m6.11759758224014e-5
[INFO] [stdout] [2m2026-08-05T16:33:27.148522Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.999885, -4999.99988, -4999.999825, -4999.999865]
[INFO] [stdout] [2m2026-08-05T16:33:27.148526Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 999µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-08-05T16:33:27.518433Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:27.518409671Z, server: 2026-08-05T16:33:27.518409891Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:27.518410142Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m235ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:27.518409906Z [3mdelta[0m[2m=[0m15ns ago
[INFO] [stdout] [2m2026-08-05T16:33:27.518530Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m235ns [3mdelta[0m[2m=[0m15ns ago
[INFO] [stdout] [2m2026-08-05T16:33:27.518563Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-1e-5, 0.000105, 0.00012, -1.5e-5, 0.000165]
[INFO] [stdout] [2m2026-08-05T16:33:27.518592Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00012 [3mmean[0m[2m=[0m7.3e-5 [3mvariance[0m[2m=[0m6.5824999999999996e-9 [3mstddev[0m[2m=[0m8.11326075015465e-5
[INFO] [stdout] [2m2026-08-05T16:33:27.518628Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.000105, 0.00012, 0.000165]
[INFO] [stdout] [2m2026-08-05T16:33:27.518653Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m0s
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] [2m2026-08-05T16:33:28.158429Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:28.158408197Z, server: 2026-08-05T16:33:28.158408672Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:28.158408827Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m315ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:28.158408512Z [3mdelta[0m[2m=[0m160ns
[INFO] [stdout] [2m2026-08-05T16:33:28.158460Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m315ns [3mdelta[0m[2m=[0m160ns
[INFO] [stdout] [2m2026-08-05T16:33:28.158469Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m60.178578ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-08-05T16:33:28.219686Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-08-05T16:33:28.219664131Z, server: 2026-08-05T16:33:28.219664556Z } [3mcurrent[0m[2m=[0m2026-08-05T16:33:28.219664701Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m285ns [3mlocal_at_midpoint[0m[2m=[0m2026-08-05T16:33:28.219664416Z [3mdelta[0m[2m=[0m140ns
[INFO] [stdout] [2m2026-08-05T16:33:28.219717Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m285ns [3mdelta[0m[2m=[0m140ns
[INFO] [stdout] [2m2026-08-05T16:33:28.219725Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[2.5e-5, 0.000145, 0.000135, 0.00014, 0.00016]
[INFO] [stdout] [2m2026-08-05T16:33:28.219733Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.000135 [3mmean[0m[2m=[0m0.00012100000000000001 [3mvariance[0m[2m=[0m2.9675e-9 [3mstddev[0m[2m=[0m5.4474764799859396e-5
[INFO] [stdout] [2m2026-08-05T16:33:28.219739Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.000145, 0.000135, 0.00014, 0.00016]
[INFO] [stdout] [2m2026-08-05T16:33:28.219743Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m0s
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.07s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/deps/timesimp_nodejs-05c3196012939a7f)
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[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] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 0.83s; merged doctests compilation took 0.82s
[INFO] running `Command { std: "docker" "inspect" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46", kill_on_drop: false }`
[INFO] [stdout] 23945de364308d79c9d96e88f63f385b6cca8187dc327a6df653125213d24b46
