[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.1 for beta-1.98-2
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-5-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-5-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-5-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 1.98.0-beta.1
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.98.0-beta.1" "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.1" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[ERROR] error running command: no output for 300 seconds
[INFO] testing passcod/timesimp against 1.98.0-beta.1 for beta-1.98-2
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-5-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-5-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-5-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 1.98.0-beta.1
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.98.0-beta.1" "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.1" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded proc-macro2 v1.0.94
[INFO] [stderr]   Downloaded smallvec v1.14.0
[INFO] [stderr]   Downloaded socket2 v0.5.9
[INFO] [stderr]   Downloaded windows-targets v0.53.0
[INFO] [stderr]   Downloaded windows-registry v0.4.0
[INFO] [stderr]   Downloaded thiserror v2.0.12
[INFO] [stderr]   Downloaded thiserror-impl v2.0.12
[INFO] [stderr]   Downloaded windows-strings v0.3.1
[INFO] [stderr]   Downloaded redox_syscall v0.5.11
[INFO] [stderr]   Downloaded litemap v0.7.5
[INFO] [stderr]   Downloaded bitflags v2.9.0
[INFO] [stderr]   Downloaded tracing-attributes v0.1.28
[INFO] [stderr]   Downloaded errno v0.3.11
[INFO] [stderr]   Downloaded icu_locid_transform_data v1.5.1
[INFO] [stderr]   Downloaded icu_normalizer_data v1.5.1
[INFO] [stderr]   Downloaded miniz_oxide v0.8.5
[INFO] [stderr]   Downloaded dtor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded ctor v0.4.2
[INFO] [stderr]   Downloaded tempfile v3.19.1
[INFO] [stderr]   Downloaded getrandom v0.3.2
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded napi-build v2.1.6
[INFO] [stderr]   Downloaded napi-derive v3.0.0-alpha.29
[INFO] [stderr]   Downloaded napi-sys v3.0.0-alpha.1
[INFO] [stderr]   Downloaded ctor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded tokio-rustls v0.26.2
[INFO] [stderr]   Downloaded libloading v0.8.6
[INFO] [stderr]   Downloaded dtor v0.0.6
[INFO] [stderr]   Downloaded rustls-pki-types v1.11.0
[INFO] [stderr]   Downloaded portable-atomic-util v0.2.4
[INFO] [stderr]   Downloaded napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]   Downloaded openssl-sys v0.9.107
[INFO] [stderr]   Downloaded hyper-rustls v0.27.5
[INFO] [stderr]   Downloaded hyper-util v0.1.11
[INFO] [stderr]   Downloaded r-efi v5.2.0
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded rand v0.9.1
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded cc v1.2.20
[INFO] [stderr]   Downloaded napi v3.0.0-alpha.33
[INFO] [stderr]   Downloaded tracing-subscriber v0.3.19
[INFO] [stderr]   Downloaded reqwest v0.12.15
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded portable-atomic v1.11.0
[INFO] [stderr]   Downloaded icu_properties_data v1.5.1
[INFO] [stderr]   Downloaded openssl v0.10.72
[INFO] [stderr]   Downloaded rustls v0.23.26
[INFO] [stderr]   Downloaded rustix v1.0.5
[INFO] [stderr]   Downloaded libc v0.2.171
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] [stderr]   Downloaded tokio v1.44.2
[INFO] [stderr]   Downloaded rustls-webpki v0.103.1
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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:3d5ced03c013a94a2f102a4510f48a6e9184255caf5fd8244f58017bde7f5210" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] 9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153
[INFO] running `Command { std: "docker" "start" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling pin-project-lite v0.2.16
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling ryu v1.0.20
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 44.64s
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[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 serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 25s
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", 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" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153" "/opt/rustwide/cargo-home/bin/cargo" "+1.98.0-beta.1" "test" "--frozen", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.31s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-2aee66feffce539a)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-c4bbd53b9bad2c02)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-07-14T04:40:29.841140Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:29.841136Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:29.841195Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.841192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.841120Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:29.841270Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.841314Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-07-14T04:40:29.841343Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.841402Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:29.841424Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.841579Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:29.841603Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.841120Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-07-14T04:40:29.841654Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.841687Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:29.841905Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.844778Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.842398173Z, server: 2026-07-14T04:40:29.843509093Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:29.844622173Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 112µs [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:29.843510173Z [3mdelta[0m[2m=[0m1µs 80ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.844867Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.112ms [3mdelta[0m[2m=[0m1µs 80ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.844888Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m1µs 80ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.844903Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.399150651s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.856951Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.842475243Z, server: 2026-07-14T04:40:34.849619512Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:29.856758491Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 141µs 624ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:29.849616867Z [3mdelta[0m[2m=[0m5s 2µs 645ns
[INFO] [stdout] [2m2026-07-14T04:40:29.857209Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.141624ms [3mdelta[0m[2m=[0m5s 2µs 645ns
[INFO] [stdout] [2m2026-07-14T04:40:29.857322Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 2µs 645ns
[INFO] [stdout] [2m2026-07-14T04:40:29.857933Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m653.147686ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.864219Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.842757923Z, server: 2026-07-14T04:40:34.852887022Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:29.864048101Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 645µs 89ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:29.853403012Z [3mdelta[0m[2m=[0m4s 999ms 484µs 10ns
[INFO] [stdout] [2m2026-07-14T04:40:29.864292Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.645089ms [3mdelta[0m[2m=[0m4s 999ms 484µs 10ns
[INFO] [stdout] [2m2026-07-14T04:40:29.864311Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 484µs 10ns
[INFO] [stdout] [2m2026-07-14T04:40:29.864325Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.750351835s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.864894Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.842527403Z, server: 2026-07-14T04:40:29.853652521Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:29.864785421Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 129µs 9ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:29.853656412Z [3mdelta[0m[2m=[0m3µs 891ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.865277Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.129009ms [3mdelta[0m[2m=[0m3µs 891ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.865324Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m842.710911ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.865070Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.842600973Z, server: 2026-07-14T04:40:34.853707912Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:29.864983131Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 191µs 79ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:29.853792052Z [3mdelta[0m[2m=[0m4s 999ms 915µs 860ns
[INFO] [stdout] [2m2026-07-14T04:40:29.865428Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.191079ms [3mdelta[0m[2m=[0m4s 999ms 915µs 860ns
[INFO] [stdout] [2m2026-07-14T04:40:29.865465Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 915µs 860ns
[INFO] [stdout] [2m2026-07-14T04:40:29.865228Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.842893033Z, server: 2026-07-14T04:40:29.854010752Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:29.865148511Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 127µs 739ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:29.854020772Z [3mdelta[0m[2m=[0m10µs 20ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.865554Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.127739ms [3mdelta[0m[2m=[0m10µs 20ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.865501Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.843183263Z, server: 2026-07-14T04:40:24.854302152Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:29.865387931Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 102µs 334ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:29.854285597Z [3mdelta[0m[2m=[0m4s 999ms 983µs 445ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.865529Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.69557318s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.865664Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m837.315512ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:29.865760Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.102334ms [3mdelta[0m[2m=[0m4s 999ms 983µs 445ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.865861Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 983µs 445ns ago
[INFO] [stdout] [2m2026-07-14T04:40:29.865899Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m236.920421ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:30.126528Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:30.104022948Z, server: 2026-07-14T04:40:25.115195617Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:30.126373736Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 175µs 394ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:30.115198342Z [3mdelta[0m[2m=[0m5s 2µs 725ns ago
[INFO] [stdout] [2m2026-07-14T04:40:30.126611Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.175394ms [3mdelta[0m[2m=[0m5s 2µs 725ns ago
[INFO] [stdout] [2m2026-07-14T04:40:30.126634Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m239.476355ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:30.399235Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:30.367046614Z, server: 2026-07-14T04:40:25.387913442Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:30.399086091Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m16ms 19µs 738ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:30.383066352Z [3mdelta[0m[2m=[0m4s 995ms 152µs 910ns ago
[INFO] [stdout] [2m2026-07-14T04:40:30.399314Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m16.019738ms [3mdelta[0m[2m=[0m4s 995ms 152µs 910ns ago
[INFO] [stdout] [2m2026-07-14T04:40:30.399337Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m796.045703ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:30.531387Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:30.51288315Z, server: 2026-07-14T04:40:35.52206621Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:30.531240438Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 178µs 644ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:30.522061794Z [3mdelta[0m[2m=[0m5s 4µs 416ns
[INFO] [stdout] [2m2026-07-14T04:40:30.531467Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.178644ms [3mdelta[0m[2m=[0m5s 4µs 416ns
[INFO] [stdout] [2m2026-07-14T04:40:30.531491Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.515046183s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:30.729324Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:30.705886492Z, server: 2026-07-14T04:40:30.717996851Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:30.7291701Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 641µs 804ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:30.717528296Z [3mdelta[0m[2m=[0m468µs 555ns
[INFO] [stdout] [2m2026-07-14T04:40:30.729397Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.641804ms [3mdelta[0m[2m=[0m468µs 555ns
[INFO] [stdout] [2m2026-07-14T04:40:30.729415Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.204582332s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:30.733222Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:30.709001482Z, server: 2026-07-14T04:40:30.721888181Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:30.73302945Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 13µs 984ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:30.721015466Z [3mdelta[0m[2m=[0m872µs 715ns
[INFO] [stdout] [2m2026-07-14T04:40:30.733283Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.013984ms [3mdelta[0m[2m=[0m872µs 715ns
[INFO] [stdout] [2m2026-07-14T04:40:30.733304Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.539781333s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:31.218541Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:31.196036057Z, server: 2026-07-14T04:40:26.207216816Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:31.218396815Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 180µs 379ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:31.207216436Z [3mdelta[0m[2m=[0m4s 999ms 999µs 620ns ago
[INFO] [stdout] [2m2026-07-14T04:40:31.218616Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.180379ms [3mdelta[0m[2m=[0m4s 999ms 999µs 620ns ago
[INFO] [stdout] [2m2026-07-14T04:40:31.218638Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.794306822s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:31.246324Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:31.245041302Z, server: 2026-07-14T04:40:31.245084582Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:31.246177392Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m568µs 45ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:31.245609347Z [3mdelta[0m[2m=[0m524µs 765ns ago
[INFO] [stdout] [2m2026-07-14T04:40:31.246401Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m568.045µs [3mdelta[0m[2m=[0m524µs 765ns ago
[INFO] [stdout] [2m2026-07-14T04:40:31.246422Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.662876401s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:31.248111Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:29.842399653Z, server: 2026-07-14T04:40:30.545914147Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:31.248002312Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m702ms 801µs 329ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:30.545200982Z [3mdelta[0m[2m=[0m713µs 165ns
[INFO] [stdout] [2m2026-07-14T04:40:31.248173Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m702.801329ms [3mdelta[0m[2m=[0m713µs 165ns
[INFO] [stdout] [2m2026-07-14T04:40:31.248192Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m713µs 165ns
[INFO] [stdout] [2m2026-07-14T04:40:31.248205Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m831.240905ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:31.588363Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:31.566913022Z, server: 2026-07-14T04:40:36.577033691Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:31.5882145Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 650µs 739ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:31.577563761Z [3mdelta[0m[2m=[0m4s 999ms 469µs 930ns
[INFO] [stdout] [2m2026-07-14T04:40:31.588436Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.650739ms [3mdelta[0m[2m=[0m4s 999ms 469µs 930ns
[INFO] [stdout] [2m2026-07-14T04:40:31.588456Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.105170522s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:31.626511Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:31.616021118Z, server: 2026-07-14T04:40:36.621194557Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:31.626356147Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5ms 167µs 514ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:31.621188632Z [3mdelta[0m[2m=[0m5s 5µs 925ns
[INFO] [stdout] [2m2026-07-14T04:40:31.626757Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.167514ms [3mdelta[0m[2m=[0m5s 5µs 925ns
[INFO] [stdout] [2m2026-07-14T04:40:31.626844Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m409.033385ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:31.957660Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:31.935061288Z, server: 2026-07-14T04:40:31.946233747Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:31.957509506Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 224µs 109ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:31.946285397Z [3mdelta[0m[2m=[0m51µs 650ns ago
[INFO] [stdout] [2m2026-07-14T04:40:31.957743Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.224109ms [3mdelta[0m[2m=[0m51µs 650ns ago
[INFO] [stdout] [2m2026-07-14T04:40:31.957764Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m246.013844ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:32.046343Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:32.037914389Z, server: 2026-07-14T04:40:37.042062348Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:32.046200168Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 142µs 889ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:32.042057278Z [3mdelta[0m[2m=[0m5s 5µs 70ns
[INFO] [stdout] [2m2026-07-14T04:40:32.046496Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.142889ms [3mdelta[0m[2m=[0m5s 5µs 70ns
[INFO] [stdout] [2m2026-07-14T04:40:32.046567Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.314215134s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:32.059450Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:32.046969488Z, server: 2026-07-14T04:40:37.053120837Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:32.059301597Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 166µs 54ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:32.053135542Z [3mdelta[0m[2m=[0m4s 999ms 985µs 295ns
[INFO] [stdout] [2m2026-07-14T04:40:32.059531Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.166054ms [3mdelta[0m[2m=[0m4s 999ms 985µs 295ns
[INFO] [stdout] [2m2026-07-14T04:40:32.059552Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m954.348107ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:32.226401Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:32.204038853Z, server: 2026-07-14T04:40:32.215081472Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:32.226257181Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 109µs 164ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:32.215148017Z [3mdelta[0m[2m=[0m66µs 545ns ago
[INFO] [stdout] [2m2026-07-14T04:40:32.226479Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.109164ms [3mdelta[0m[2m=[0m66µs 545ns ago
[INFO] [stdout] [2m2026-07-14T04:40:32.226500Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.588518813s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:32.299329Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:32.274915037Z, server: 2026-07-14T04:40:32.287911625Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:32.299086594Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 85µs 778ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:32.287000815Z [3mdelta[0m[2m=[0m910µs 810ns
[INFO] [stdout] [2m2026-07-14T04:40:32.299408Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.085778ms [3mdelta[0m[2m=[0m910µs 810ns
[INFO] [stdout] [2m2026-07-14T04:40:32.299428Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.078206066s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:32.714541Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:32.694042548Z, server: 2026-07-14T04:40:37.704216056Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:32.714389886Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 173µs 669ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:32.704216217Z [3mdelta[0m[2m=[0m4s 999ms 999µs 839ns
[INFO] [stdout] [2m2026-07-14T04:40:32.714857Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.173669ms [3mdelta[0m[2m=[0m4s 999ms 999µs 839ns
[INFO] [stdout] [2m2026-07-14T04:40:32.715025Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.912999357s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:32.912364Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:32.911055627Z, server: 2026-07-14T04:40:32.911100357Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:32.912215367Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m579µs 870ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:32.911635497Z [3mdelta[0m[2m=[0m535µs 140ns ago
[INFO] [stdout] [2m2026-07-14T04:40:32.912447Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m579.87µs [3mdelta[0m[2m=[0m535µs 140ns ago
[INFO] [stdout] [2m2026-07-14T04:40:32.912478Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.752205321s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.033531Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.015035308Z, server: 2026-07-14T04:40:38.024203877Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.033382156Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 173µs 424ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.024208732Z [3mdelta[0m[2m=[0m4s 999ms 995µs 145ns
[INFO] [stdout] [2m2026-07-14T04:40:33.033614Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.173424ms [3mdelta[0m[2m=[0m4s 999ms 995µs 145ns
[INFO] [stdout] [2m2026-07-14T04:40:33.033636Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m326.308908ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.036372Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.014011838Z, server: 2026-07-14T04:40:28.025154047Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.036285386Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 136µs 774ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.025148612Z [3mdelta[0m[2m=[0m4s 999ms 994µs 565ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.036434Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.136774ms [3mdelta[0m[2m=[0m4s 999ms 994µs 565ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.036461Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.983445, -4999.994565, -5000.002725, -4999.9996200000005, -4995.15291]
[INFO] [stdout] [2m2026-07-14T04:40:33.036486Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.002725 [3mmean[0m[2m=[0m-4999.026653 [3mvariance[0m[2m=[0m4.689392683333196 [3mstddev[0m[2m=[0m2.165500561840887
[INFO] [stdout] [2m2026-07-14T04:40:33.036515Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.983445, -4999.994565, -5000.002725, -4999.9996200000005]
[INFO] [stdout] [2m2026-07-14T04:40:33.036528Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 995µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-07-14T04:40:33.038045Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:33.038082Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.061778Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.039262216Z, server: 2026-07-14T04:40:38.050421704Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.061594553Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 166µs 168ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.050428384Z [3mdelta[0m[2m=[0m4s 999ms 993µs 320ns
[INFO] [stdout] [2m2026-07-14T04:40:33.061872Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.166168ms [3mdelta[0m[2m=[0m4s 999ms 993µs 320ns
[INFO] [stdout] [2m2026-07-14T04:40:33.061892Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 993µs 320ns
[INFO] [stdout] [2m2026-07-14T04:40:33.061904Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.57238412s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.377343Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.361906406Z, server: 2026-07-14T04:40:38.369038355Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.377196074Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 644µs 834ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.36955124Z [3mdelta[0m[2m=[0m4s 999ms 487µs 115ns
[INFO] [stdout] [2m2026-07-14T04:40:33.377425Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.644834ms [3mdelta[0m[2m=[0m4s 999ms 487µs 115ns
[INFO] [stdout] [2m2026-07-14T04:40:33.377455Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.985295, 5000.002645, 4999.487115, 4999.995145, 5000.004416]
[INFO] [stdout] [2m2026-07-14T04:40:33.377473Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.487115 [3mmean[0m[2m=[0m4999.8949231999995 [3mvariance[0m[2m=[0m0.05202791471619553 [3mstddev[0m[2m=[0m0.2280962838719551
[INFO] [stdout] [2m2026-07-14T04:40:33.377495Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.487115]
[INFO] [stdout] [2m2026-07-14T04:40:33.377506Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 487µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-07-14T04:40:33.377924Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:33.377960Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.406134Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.380337334Z, server: 2026-07-14T04:40:33.392906923Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.405903922Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 783µs 294ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.393120628Z [3mdelta[0m[2m=[0m213µs 705ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.406210Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.783294ms [3mdelta[0m[2m=[0m213µs 705ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.406230Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.128793656s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.419053Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.367896455Z, server: 2026-07-14T04:40:38.378865364Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.41890927Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m25ms 506µs 407ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.393402862Z [3mdelta[0m[2m=[0m4s 985ms 462µs 502ns
[INFO] [stdout] [2m2026-07-14T04:40:33.419131Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m25.506407ms [3mdelta[0m[2m=[0m4s 985ms 462µs 502ns
[INFO] [stdout] [2m2026-07-14T04:40:33.419152Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m74.561086ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.510976Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.495463563Z, server: 2026-07-14T04:40:38.503634842Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.510801741Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 669µs 89ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.503132652Z [3mdelta[0m[2m=[0m5s 502µs 190ns
[INFO] [stdout] [2m2026-07-14T04:40:33.511058Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.669089ms [3mdelta[0m[2m=[0m5s 502µs 190ns
[INFO] [stdout] [2m2026-07-14T04:40:33.511088Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00507, 5000.005925, 5000.50219, 4999.48401, 4985.462502]
[INFO] [stdout] [2m2026-07-14T04:40:33.511107Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.50219 [3mmean[0m[2m=[0m4997.091939399999 [3mvariance[0m[2m=[0m42.39331678009119 [3mstddev[0m[2m=[0m6.511015034546548
[INFO] [stdout] [2m2026-07-14T04:40:33.511126Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00507, 5000.005925, 5000.50219, 4999.48401]
[INFO] [stdout] [2m2026-07-14T04:40:33.511139Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 999µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-07-14T04:40:33.581971Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.379133614Z, server: 2026-07-14T04:40:33.480440964Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.581800675Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 333µs 530ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.480467144Z [3mdelta[0m[2m=[0m26µs 180ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.582050Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.33353ms [3mdelta[0m[2m=[0m26µs 180ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.582069Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m26µs 180ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.582082Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m448.641891ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:33.838566Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:33.816047693Z, server: 2026-07-14T04:40:33.827227962Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.838407971Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 180µs 139ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:33.827227832Z [3mdelta[0m[2m=[0m130ns
[INFO] [stdout] [2m2026-07-14T04:40:33.838651Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.180139ms [3mdelta[0m[2m=[0m130ns
[INFO] [stdout] [2m2026-07-14T04:40:33.838684Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.066545, -0.01002, 0.00013, -0.05165, 0.468555]
[INFO] [stdout] [2m2026-07-14T04:40:33.838724Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00013 [3mmean[0m[2m=[0m0.068094 [3mvariance[0m[2m=[0m0.0508890501675 [3mstddev[0m[2m=[0m0.22558601500868797
[INFO] [stdout] [2m2026-07-14T04:40:33.838750Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.066545, -0.01002, 0.00013, -0.05165]
[INFO] [stdout] [2m2026-07-14T04:40:33.838770Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m32µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-07-14T04:40:33.884187Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:32.080050215Z, server: 2026-07-14T04:40:32.982027741Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:33.884036997Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m901ms 993µs 391ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:32.982043606Z [3mdelta[0m[2m=[0m15µs 865ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.884269Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m901.993391ms [3mdelta[0m[2m=[0m15µs 865ns ago
[INFO] [stdout] [2m2026-07-14T04:40:33.884291Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m932.113489ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:34.233593Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:34.031786663Z, server: 2026-07-14T04:40:34.132101824Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:34.233432234Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 822µs 785ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:34.132609448Z [3mdelta[0m[2m=[0m507µs 624ns ago
[INFO] [stdout] [2m2026-07-14T04:40:34.233674Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.822785ms [3mdelta[0m[2m=[0m507µs 624ns ago
[INFO] [stdout] [2m2026-07-14T04:40:34.233696Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.931768081s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:34.558611Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:34.536095816Z, server: 2026-07-14T04:40:34.547276835Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:34.558456084Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 180µs 134ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:34.54727595Z [3mdelta[0m[2m=[0m885ns
[INFO] [stdout] [2m2026-07-14T04:40:34.558696Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.180134ms [3mdelta[0m[2m=[0m885ns
[INFO] [stdout] [2m2026-07-14T04:40:34.558727Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.003891, 0.000885, 0.872715, 0.91081, -0.213705]
[INFO] [stdout] [2m2026-07-14T04:40:34.558748Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.872715 [3mmean[0m[2m=[0m0.3133628 [3mvariance[0m[2m=[0m0.28647771383419995 [3mstddev[0m[2m=[0m0.5352361290441817
[INFO] [stdout] [2m2026-07-14T04:40:34.558766Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.872715, 0.91081]
[INFO] [stdout] [2m2026-07-14T04:40:34.558785Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m891µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-07-14T04:40:34.651567Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:34.629028318Z, server: 2026-07-14T04:40:39.640175847Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:34.651408506Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 190µs 94ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:34.640218412Z [3mdelta[0m[2m=[0m4s 999ms 957µs 435ns
[INFO] [stdout] [2m2026-07-14T04:40:34.651721Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.190094ms [3mdelta[0m[2m=[0m4s 999ms 957µs 435ns
[INFO] [stdout] [2m2026-07-14T04:40:34.651796Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m433.02591ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:34.660259Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:34.636050847Z, server: 2026-07-14T04:40:39.648924086Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:34.660104075Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 26µs 614ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:34.648077461Z [3mdelta[0m[2m=[0m5s 846µs 625ns
[INFO] [stdout] [2m2026-07-14T04:40:34.660342Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.026614ms [3mdelta[0m[2m=[0m5s 846µs 625ns
[INFO] [stdout] [2m2026-07-14T04:40:34.660365Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m295.518035ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:34.668116Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:34.665743204Z, server: 2026-07-14T04:40:34.666867624Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:34.667980654Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 118µs 725ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:34.666861929Z [3mdelta[0m[2m=[0m5µs 695ns
[INFO] [stdout] [2m2026-07-14T04:40:34.668192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.118725ms [3mdelta[0m[2m=[0m5µs 695ns
[INFO] [stdout] [2m2026-07-14T04:40:34.668211Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.168292792s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:34.985044Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:34.956893157Z, server: 2026-07-14T04:40:39.967164606Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:34.984903524Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 5µs 183ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:34.97089834Z [3mdelta[0m[2m=[0m4s 996ms 266µs 266ns
[INFO] [stdout] [2m2026-07-14T04:40:34.985118Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.005183ms [3mdelta[0m[2m=[0m4s 996ms 266µs 266ns
[INFO] [stdout] [2m2026-07-14T04:40:34.985138Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.288749438s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:35.106665Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:35.086044135Z, server: 2026-07-14T04:40:40.096325064Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:35.106510553Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 233µs 209ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:35.096277344Z [3mdelta[0m[2m=[0m5s 47µs 720ns
[INFO] [stdout] [2m2026-07-14T04:40:35.106745Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.233209ms [3mdelta[0m[2m=[0m5s 47µs 720ns
[INFO] [stdout] [2m2026-07-14T04:40:35.106772Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.999839, 5000.04772, 4999.46993, 4999.957435, 4999.91586]
[INFO] [stdout] [2m2026-07-14T04:40:35.106790Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.46993 [3mmean[0m[2m=[0m4999.8781567999995 [3mvariance[0m[2m=[0m0.054478480278637574 [3mstddev[0m[2m=[0m0.23340625586868397
[INFO] [stdout] [2m2026-07-14T04:40:35.106816Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.46993]
[INFO] [stdout] [2m2026-07-14T04:40:35.106843Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 469µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-07-14T04:40:35.839347Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:35.838043485Z, server: 2026-07-14T04:40:35.838087745Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:35.839202925Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m579µs 720ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:35.838623205Z [3mdelta[0m[2m=[0m535µs 460ns ago
[INFO] [stdout] [2m2026-07-14T04:40:35.839425Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m579.72µs [3mdelta[0m[2m=[0m535µs 460ns ago
[INFO] [stdout] [2m2026-07-14T04:40:35.839449Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.524765, -0.53546, -0.53514, -0.00108, 0.005695]
[INFO] [stdout] [2m2026-07-14T04:40:35.839475Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.53514 [3mmean[0m[2m=[0m-0.31815 [3mvariance[0m[2m=[0m0.08560175583749999 [3mstddev[0m[2m=[0m0.29257777741568136
[INFO] [stdout] [2m2026-07-14T04:40:35.839498Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.524765, -0.53546, -0.53514]
[INFO] [stdout] [2m2026-07-14T04:40:35.839509Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m531µs ago
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-07-14T04:40:36.297558Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:36.275053545Z, server: 2026-07-14T04:40:41.286225834Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:36.297398843Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 172µs 649ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:36.286226194Z [3mdelta[0m[2m=[0m4s 999ms 999µs 640ns
[INFO] [stdout] [2m2026-07-14T04:40:36.297638Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.172649ms [3mdelta[0m[2m=[0m4s 999ms 999µs 640ns
[INFO] [stdout] [2m2026-07-14T04:40:36.297661Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.145503298s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:36.368862Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:36.166044045Z, server: 2026-07-14T04:40:36.267384215Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:36.368693086Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 324µs 520ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:36.267368565Z [3mdelta[0m[2m=[0m15µs 650ns
[INFO] [stdout] [2m2026-07-14T04:40:36.368943Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.32452ms [3mdelta[0m[2m=[0m15µs 650ns
[INFO] [stdout] [2m2026-07-14T04:40:36.368963Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m878.168406ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:36.491201Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:34.81706099Z, server: 2026-07-14T04:40:35.654040792Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:36.491046865Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m836ms 992µs 937ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:35.654053927Z [3mdelta[0m[2m=[0m13µs 135ns ago
[INFO] [stdout] [2m2026-07-14T04:40:36.491456Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m836.992937ms [3mdelta[0m[2m=[0m13µs 135ns ago
[INFO] [stdout] [2m2026-07-14T04:40:36.491543Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m416.854726ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:37.457422Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:37.254911954Z, server: 2026-07-14T04:40:37.356015484Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:37.457281565Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 184µs 805ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:37.356096759Z [3mdelta[0m[2m=[0m81µs 275ns ago
[INFO] [stdout] [2m2026-07-14T04:40:37.457501Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.184805ms [3mdelta[0m[2m=[0m81µs 275ns ago
[INFO] [stdout] [2m2026-07-14T04:40:37.457519Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.064950616s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:37.466999Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:37.444377326Z, server: 2026-07-14T04:40:42.455658325Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:37.466845054Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 233µs 864ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:37.45561119Z [3mdelta[0m[2m=[0m5s 47µs 135ns
[INFO] [stdout] [2m2026-07-14T04:40:37.467082Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.233864ms [3mdelta[0m[2m=[0m5s 47µs 135ns
[INFO] [stdout] [2m2026-07-14T04:40:37.467112Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.99332, 4999.99964, 5000.047135, 5000.846625, 4996.266266]
[INFO] [stdout] [2m2026-07-14T04:40:37.467146Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.047135 [3mmean[0m[2m=[0m4999.4305972 [3mvariance[0m[2m=[0m3.259678047592195 [3mstddev[0m[2m=[0m1.8054578498519966
[INFO] [stdout] [2m2026-07-14T04:40:37.467166Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.99332, 4999.99964, 5000.047135, 5000.846625]
[INFO] [stdout] [2m2026-07-14T04:40:37.467179Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 221µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-07-14T04:40:38.725873Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:38.523035566Z, server: 2026-07-14T04:40:38.624354476Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:38.725685227Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 324µs 830ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:38.624360396Z [3mdelta[0m[2m=[0m5µs 920ns ago
[INFO] [stdout] [2m2026-07-14T04:40:38.725955Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.32483ms [3mdelta[0m[2m=[0m5µs 920ns ago
[INFO] [stdout] [2m2026-07-14T04:40:38.725983Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.507624, -0.081275, 0.01565, -0.00592, -0.02618]
[INFO] [stdout] [2m2026-07-14T04:40:38.726000Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.01565 [3mmean[0m[2m=[0m-0.12106979999999998 [3mvariance[0m[2m=[0m0.04799090748519999 [3mstddev[0m[2m=[0m0.21906827128819908
[INFO] [stdout] [2m2026-07-14T04:40:38.726023Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.081275, 0.01565, -0.00592, -0.02618]
[INFO] [stdout] [2m2026-07-14T04:40:38.726034Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m24µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-07-14T04:40:38.846178Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:36.909043726Z, server: 2026-07-14T04:40:37.881907185Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:38.846036236Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m968ms 496µs 255ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:37.877539981Z [3mdelta[0m[2m=[0m4ms 367µs 204ns
[INFO] [stdout] [2m2026-07-14T04:40:38.846247Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m968.496255ms [3mdelta[0m[2m=[0m4ms 367µs 204ns
[INFO] [stdout] [2m2026-07-14T04:40:38.846265Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m36.322437ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.584060Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:38.883591162Z, server: 2026-07-14T04:40:39.733039703Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:40.583907964Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m850ms 158µs 401ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:39.733749563Z [3mdelta[0m[2m=[0m709µs 860ns ago
[INFO] [stdout] [2m2026-07-14T04:40:40.584143Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m850.158401ms [3mdelta[0m[2m=[0m709µs 860ns ago
[INFO] [stdout] [2m2026-07-14T04:40:40.584172Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.713165, -0.013135, -0.70986, -0.015865, 4.367204]
[INFO] [stdout] [2m2026-07-14T04:40:40.584191Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.70986 [3mmean[0m[2m=[0m0.8683018 [3mvariance[0m[2m=[0m4.0789151153687 [3mstddev[0m[2m=[0m2.0196324208550176
[INFO] [stdout] [2m2026-07-14T04:40:40.584209Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.713165, -0.013135, -0.70986, -0.015865]
[INFO] [stdout] [2m2026-07-14T04:40:40.584221Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m6µs ago
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-405f21f178b7074c)
[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 10.74s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-07-14T04:40:40.587638Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-07-14T04:40:40.587633Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:40.587632Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-14T04:40:40.587713Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.587730Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.587730Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.589071Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:40.588940494Z, server: 2026-07-14T04:40:40.588943414Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:40.588945263Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 384ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:40.588942878Z [3mdelta[0m[2m=[0m536ns
[INFO] [stdout] [2m2026-07-14T04:40:40.589071Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:40.588940343Z, server: 2026-07-14T04:40:40.588943403Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:40.588945274Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 465ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:40.588942808Z [3mdelta[0m[2m=[0m595ns
[INFO] [stdout] [2m2026-07-14T04:40:40.589140Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.384µs [3mdelta[0m[2m=[0m536ns
[INFO] [stdout] [2m2026-07-14T04:40:40.589144Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.465µs [3mdelta[0m[2m=[0m595ns
[INFO] [stdout] [2m2026-07-14T04:40:40.589168Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m887.443118ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.589187Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m595ns
[INFO] [stdout] [2m2026-07-14T04:40:40.589201Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.377114456s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.587634Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-07-14T04:40:40.589909Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.589072Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:40.588928543Z, server: 2026-07-14T04:40:45.588940414Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:40.588943343Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 400ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:40.588935943Z [3mdelta[0m[2m=[0m5s 4µs 471ns
[INFO] [stdout] [2m2026-07-14T04:40:40.590873Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.4µs [3mdelta[0m[2m=[0m5s 4µs 471ns
[INFO] [stdout] [2m2026-07-14T04:40:40.590897Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.030291728s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.591330Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:40.591244973Z, server: 2026-07-14T04:40:35.591247313Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:40.591248763Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1µs 895ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:40.591246868Z [3mdelta[0m[2m=[0m4s 999ms 999µs 555ns ago
[INFO] [stdout] [2m2026-07-14T04:40:40.591384Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.895µs [3mdelta[0m[2m=[0m4s 999ms 999µs 555ns ago
[INFO] [stdout] [2m2026-07-14T04:40:40.591446Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m343.942848ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:40.939056Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:40.938906911Z, server: 2026-07-14T04:40:35.938916011Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:40.938919031Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 60ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:40.938912971Z [3mdelta[0m[2m=[0m4s 999ms 996µs 960ns ago
[INFO] [stdout] [2m2026-07-14T04:40:40.939203Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.06µs [3mdelta[0m[2m=[0m4s 999ms 996µs 960ns ago
[INFO] [stdout] [2m2026-07-14T04:40:40.939266Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m837.297032ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:41.478193Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:41.478040411Z, server: 2026-07-14T04:40:41.478049861Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:41.478053391Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 490ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:41.478046901Z [3mdelta[0m[2m=[0m2µs 960ns
[INFO] [stdout] [2m2026-07-14T04:40:41.478274Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.49µs [3mdelta[0m[2m=[0m2µs 960ns
[INFO] [stdout] [2m2026-07-14T04:40:41.478295Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.755555945s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:41.622196Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:41.622037808Z, server: 2026-07-14T04:40:46.622047308Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:41.622050688Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 440ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:41.622044248Z [3mdelta[0m[2m=[0m5s 3µs 60ns
[INFO] [stdout] [2m2026-07-14T04:40:41.622282Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.44µs [3mdelta[0m[2m=[0m5s 3µs 60ns
[INFO] [stdout] [2m2026-07-14T04:40:41.622303Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.649144522s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:41.778196Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:41.778035123Z, server: 2026-07-14T04:40:36.778044283Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:41.778047703Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 290ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:41.778041413Z [3mdelta[0m[2m=[0m4s 999ms 997µs 130ns ago
[INFO] [stdout] [2m2026-07-14T04:40:41.778360Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.29µs [3mdelta[0m[2m=[0m4s 999ms 997µs 130ns ago
[INFO] [stdout] [2m2026-07-14T04:40:41.778440Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.081966715s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:41.971073Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:41.970914235Z, server: 2026-07-14T04:40:41.97092459Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:41.970927735Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 750ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:41.970920985Z [3mdelta[0m[2m=[0m3µs 605ns
[INFO] [stdout] [2m2026-07-14T04:40:41.971154Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.75µs [3mdelta[0m[2m=[0m3µs 605ns
[INFO] [stdout] [2m2026-07-14T04:40:41.971173Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m746.952559ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:42.719183Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:42.719037416Z, server: 2026-07-14T04:40:42.719047031Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:42.719049805Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 194ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:42.71904361Z [3mdelta[0m[2m=[0m3µs 421ns
[INFO] [stdout] [2m2026-07-14T04:40:42.719252Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.194µs [3mdelta[0m[2m=[0m3µs 421ns
[INFO] [stdout] [2m2026-07-14T04:40:42.719271Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m239.959422ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:42.864059Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:42.863908332Z, server: 2026-07-14T04:40:37.863917572Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:42.863921072Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 370ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:42.863914702Z [3mdelta[0m[2m=[0m4s 999ms 997µs 130ns ago
[INFO] [stdout] [2m2026-07-14T04:40:42.864136Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.37µs [3mdelta[0m[2m=[0m4s 999ms 997µs 130ns ago
[INFO] [stdout] [2m2026-07-14T04:40:42.864156Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m949.112213ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:42.959944Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:42.959766293Z, server: 2026-07-14T04:40:42.959776138Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:42.959778943Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 325ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:42.959772618Z [3mdelta[0m[2m=[0m3µs 520ns
[INFO] [stdout] [2m2026-07-14T04:40:42.960019Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.325µs [3mdelta[0m[2m=[0m3µs 520ns
[INFO] [stdout] [2m2026-07-14T04:40:42.960041Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.262001699s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:43.235195Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:43.235038448Z, server: 2026-07-14T04:40:43.235048148Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:43.235051868Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 710ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:43.235045158Z [3mdelta[0m[2m=[0m2µs 990ns
[INFO] [stdout] [2m2026-07-14T04:40:43.235357Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.71µs [3mdelta[0m[2m=[0m2µs 990ns
[INFO] [stdout] [2m2026-07-14T04:40:43.235435Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.363289527s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:43.275068Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:43.274911204Z, server: 2026-07-14T04:40:48.274920434Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:43.274923684Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 240ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:43.274917444Z [3mdelta[0m[2m=[0m5s 2µs 990ns
[INFO] [stdout] [2m2026-07-14T04:40:43.275151Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.24µs [3mdelta[0m[2m=[0m5s 2µs 990ns
[INFO] [stdout] [2m2026-07-14T04:40:43.275173Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.169162793s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:43.814183Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:43.814035664Z, server: 2026-07-14T04:40:38.814044814Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:43.814048024Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 180ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:43.814041844Z [3mdelta[0m[2m=[0m4s 999ms 997µs 30ns ago
[INFO] [stdout] [2m2026-07-14T04:40:43.814258Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.18µs [3mdelta[0m[2m=[0m4s 999ms 997µs 30ns ago
[INFO] [stdout] [2m2026-07-14T04:40:43.814283Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.999555, -4999.99696, -4999.99703, -4999.99713, -4999.99713]
[INFO] [stdout] [2m2026-07-14T04:40:43.814300Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.99703 [3mmean[0m[2m=[0m-4999.997561 [3mvariance[0m[2m=[0m1.2476800001981617e-6 [3mstddev[0m[2m=[0m0.0011169959714332732
[INFO] [stdout] [2m2026-07-14T04:40:43.814320Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99696, -4999.99703, -4999.99713, -4999.99713]
[INFO] [stdout] [2m2026-07-14T04:40:43.814333Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-07-14T04:40:44.224065Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:44.223906516Z, server: 2026-07-14T04:40:44.22391646Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:44.223919125Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 304ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:44.22391282Z [3mdelta[0m[2m=[0m3µs 640ns
[INFO] [stdout] [2m2026-07-14T04:40:44.224221Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.304µs [3mdelta[0m[2m=[0m3µs 640ns
[INFO] [stdout] [2m2026-07-14T04:40:44.224307Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000595, 0.003421, 0.00364, 0.00352, 0.003605]
[INFO] [stdout] [2m2026-07-14T04:40:44.224377Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00364 [3mmean[0m[2m=[0m0.0029562 [3mvariance[0m[2m=[0m1.7494247000000002e-6 [3mstddev[0m[2m=[0m0.00132265819469733
[INFO] [stdout] [2m2026-07-14T04:40:44.224438Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.003421, 0.00364, 0.00352, 0.003605]
[INFO] [stdout] [2m2026-07-14T04:40:44.224484Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] [2m2026-07-14T04:40:44.446189Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:44.446037685Z, server: 2026-07-14T04:40:49.446046105Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:44.446049805Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 60ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:44.446043745Z [3mdelta[0m[2m=[0m5s 2µs 360ns
[INFO] [stdout] [2m2026-07-14T04:40:44.446268Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.06µs [3mdelta[0m[2m=[0m5s 2µs 360ns
[INFO] [stdout] [2m2026-07-14T04:40:44.446288Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.838802737s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:44.600196Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:44.600038881Z, server: 2026-07-14T04:40:44.600048001Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:44.600051531Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 325ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:44.600045206Z [3mdelta[0m[2m=[0m2µs 795ns
[INFO] [stdout] [2m2026-07-14T04:40:44.600281Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.325µs [3mdelta[0m[2m=[0m2µs 795ns
[INFO] [stdout] [2m2026-07-14T04:40:44.600325Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.851049614s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-14T04:40:46.288037Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:46.287885824Z, server: 2026-07-14T04:40:51.287895244Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:46.287898434Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 305ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:46.287892129Z [3mdelta[0m[2m=[0m5s 3µs 115ns
[INFO] [stdout] [2m2026-07-14T04:40:46.288110Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.305µs [3mdelta[0m[2m=[0m5s 3µs 115ns
[INFO] [stdout] [2m2026-07-14T04:40:46.288134Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00236, 5000.00299, 5000.003115, 5000.00306, 5000.004471]
[INFO] [stdout] [2m2026-07-14T04:40:46.288150Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.003115 [3mmean[0m[2m=[0m5000.0031991999995 [3mvariance[0m[2m=[0m5.979906999384097e-7 [3mstddev[0m[2m=[0m0.0007732985839495696
[INFO] [stdout] [2m2026-07-14T04:40:46.288198Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00236, 5000.00299, 5000.003115, 5000.00306]
[INFO] [stdout] [2m2026-07-14T04:40:46.288231Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-07-14T04:40:46.454059Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-14T04:40:46.453911388Z, server: 2026-07-14T04:40:46.453920658Z } [3mcurrent[0m[2m=[0m2026-07-14T04:40:46.453924188Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 400ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-14T04:40:46.453917788Z [3mdelta[0m[2m=[0m2µs 870ns
[INFO] [stdout] [2m2026-07-14T04:40:46.454130Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.4µs [3mdelta[0m[2m=[0m2µs 870ns
[INFO] [stdout] [2m2026-07-14T04:40:46.454152Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000536, 0.002795, 0.00287, 0.00296, 0.00299]
[INFO] [stdout] [2m2026-07-14T04:40:46.454168Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00287 [3mmean[0m[2m=[0m0.0024301999999999995 [3mvariance[0m[2m=[0m1.1271402000000001e-6 [3mstddev[0m[2m=[0m0.0010616685923582746
[INFO] [stdout] [2m2026-07-14T04:40:46.454185Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.002795, 0.00287, 0.00296, 0.00299]
[INFO] [stdout] [2m2026-07-14T04:40:46.454196Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m2µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.87s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-e945ddf2a2af16be)
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 1.33s; merged doctests compilation took 1.32s
[INFO] running `Command { std: "docker" "inspect" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153", kill_on_drop: false }`
[INFO] [stdout] 9731caeb477e3cbab6f987276270b908b97f2120067d08dbd93e4601c463c153
