[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against 1.100.0-beta.1 for beta-1.100-2
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-4-tc2/source
[INFO] started tweaking crates.io crate timesimp 1.0.0
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate timesimp 1.0.0
[INFO] tweaked toml for crates.io crate timesimp 1.0.0 written to /workspace/builds/worker-4-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain 1.100.0-beta.1
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.100.0-beta.1" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate crates.io crate timesimp 1.0.0 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.100.0-beta.1" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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:3111399a4047eeb3a02b7a90e478d715f38a8c6669b5c4b49d30a17385265909" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] 3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845
[INFO] running `Command { std: "docker" "start" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845", 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" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.0-beta.1" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845", 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" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.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 thiserror v2.0.12
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling 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)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 9.75s
[INFO] running `Command { std: "docker" "inspect" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845", 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" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.0-beta.1" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[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 icu_normalizer v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 42.16s
[INFO] running `Command { std: "docker" "inspect" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845", 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" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845" "/opt/rustwide/cargo-home/bin/cargo" "+1.100.0-beta.1" "test" "--frozen", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.23s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/build/timesimp/66ddc737f7c04c7f/out/timesimp-66ddc737f7c04c7f)
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 5 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/build/timesimp/c44eda2a8c9c80bc/out/client_server-c44eda2a8c9c80bc)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-10-06T19:58:15.783206Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-10-06T19:58:15.783203Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783293Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783213Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783302Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783249Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783320Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783328Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783326Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783317Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783338Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783512Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783287Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783198Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-10-06T19:58:15.783655Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783362Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783199Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:15.783724Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.783582Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.784010Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.787636Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.785196149Z, server: 2026-10-06T19:58:15.786322359Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.787448279Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 126µs 65ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.786322214Z [3mdelta[0m[2m=[0m145ns
[INFO] [stdout] [2m2026-10-06T19:58:15.787758Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.126065ms [3mdelta[0m[2m=[0m145ns
[INFO] [stdout] [2m2026-10-06T19:58:15.787812Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m145ns
[INFO] [stdout] [2m2026-10-06T19:58:15.787848Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m145.632976ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.801060Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.784530889Z, server: 2026-10-06T19:58:20.792690719Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.800831549Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 150µs 330ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.792681219Z [3mdelta[0m[2m=[0m5s 9µs 500ns
[INFO] [stdout] [2m2026-10-06T19:58:15.801155Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.15033ms [3mdelta[0m[2m=[0m5s 9µs 500ns
[INFO] [stdout] [2m2026-10-06T19:58:15.801174Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 9µs 500ns
[INFO] [stdout] [2m2026-10-06T19:58:15.801185Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.257154536s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.803480Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.785076779Z, server: 2026-10-06T19:58:20.794221838Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.803364318Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 143µs 769ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.794220548Z [3mdelta[0m[2m=[0m5s 1µs 290ns
[INFO] [stdout] [2m2026-10-06T19:58:15.803552Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.143769ms [3mdelta[0m[2m=[0m5s 1µs 290ns
[INFO] [stdout] [2m2026-10-06T19:58:15.803572Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 1µs 290ns
[INFO] [stdout] [2m2026-10-06T19:58:15.803712Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.062193758s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.806316Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.784694859Z, server: 2026-10-06T19:58:20.795893759Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.806106249Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 705µs 695ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.795400554Z [3mdelta[0m[2m=[0m5s 493µs 205ns
[INFO] [stdout] [2m2026-10-06T19:58:15.806399Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.705695ms [3mdelta[0m[2m=[0m5s 493µs 205ns
[INFO] [stdout] [2m2026-10-06T19:58:15.806420Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 493µs 205ns
[INFO] [stdout] [2m2026-10-06T19:58:15.806435Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.7658759s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.806909Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.784530889Z, server: 2026-10-06T19:58:15.795662039Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.806774009Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 121µs 560ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.795652449Z [3mdelta[0m[2m=[0m9µs 590ns
[INFO] [stdout] [2m2026-10-06T19:58:15.806969Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.12156ms [3mdelta[0m[2m=[0m9µs 590ns
[INFO] [stdout] [2m2026-10-06T19:58:15.807015Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m623.367437ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.807232Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.784865739Z, server: 2026-10-06T19:58:15.796010269Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.807120458Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 127µs 359ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.795993098Z [3mdelta[0m[2m=[0m17µs 171ns
[INFO] [stdout] [2m2026-10-06T19:58:15.807311Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.127359ms [3mdelta[0m[2m=[0m17µs 171ns
[INFO] [stdout] [2m2026-10-06T19:58:15.807333Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.877954178s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.807409Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.784999929Z, server: 2026-10-06T19:58:20.796139989Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.807267258Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 133µs 664ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.796133593Z [3mdelta[0m[2m=[0m5s 6µs 396ns
[INFO] [stdout] [2m2026-10-06T19:58:15.807478Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.133664ms [3mdelta[0m[2m=[0m5s 6µs 396ns
[INFO] [stdout] [2m2026-10-06T19:58:15.807504Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 6µs 396ns
[INFO] [stdout] [2m2026-10-06T19:58:15.807519Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m204.782473ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.807646Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.785265189Z, server: 2026-10-06T19:58:10.796396799Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.807533289Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 134µs 50ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.796399239Z [3mdelta[0m[2m=[0m5s 2µs 440ns ago
[INFO] [stdout] [2m2026-10-06T19:58:15.807734Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.13405ms [3mdelta[0m[2m=[0m5s 2µs 440ns ago
[INFO] [stdout] [2m2026-10-06T19:58:15.807769Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 2µs 440ns ago
[INFO] [stdout] [2m2026-10-06T19:58:15.807790Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m271.717889ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.937732Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.935295917Z, server: 2026-10-06T19:58:15.936445817Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.937568967Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 136µs 525ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.936432442Z [3mdelta[0m[2m=[0m13µs 375ns
[INFO] [stdout] [2m2026-10-06T19:58:15.937812Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.136525ms [3mdelta[0m[2m=[0m13µs 375ns
[INFO] [stdout] [2m2026-10-06T19:58:15.937834Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.220467077s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:15.986668Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.784711739Z, server: 2026-10-06T19:58:15.886108588Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:15.986446957Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 867µs 609ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:15.885579348Z [3mdelta[0m[2m=[0m529µs 240ns
[INFO] [stdout] [2m2026-10-06T19:58:15.986751Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.867609ms [3mdelta[0m[2m=[0m529µs 240ns
[INFO] [stdout] [2m2026-10-06T19:58:15.986772Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m529µs 240ns
[INFO] [stdout] [2m2026-10-06T19:58:15.986794Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m820.66329ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:16.035922Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:16.014013786Z, server: 2026-10-06T19:58:21.024281416Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:16.035712326Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 849µs 270ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:16.024863056Z [3mdelta[0m[2m=[0m4s 999ms 418µs 360ns
[INFO] [stdout] [2m2026-10-06T19:58:16.036033Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.84927ms [3mdelta[0m[2m=[0m4s 999ms 418µs 360ns
[INFO] [stdout] [2m2026-10-06T19:58:16.036062Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.786256455s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:16.104402Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:16.081727846Z, server: 2026-10-06T19:58:11.092960975Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:16.104201515Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 236µs 834ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:16.09296468Z [3mdelta[0m[2m=[0m5s 3µs 705ns ago
[INFO] [stdout] [2m2026-10-06T19:58:16.104497Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.236834ms [3mdelta[0m[2m=[0m5s 3µs 705ns ago
[INFO] [stdout] [2m2026-10-06T19:58:16.104524Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m287.998771ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:16.417940Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:16.395114792Z, server: 2026-10-06T19:58:11.406560182Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:16.417761811Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 323µs 509ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:16.406438301Z [3mdelta[0m[2m=[0m4s 999ms 878µs 119ns ago
[INFO] [stdout] [2m2026-10-06T19:58:16.418038Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.323509ms [3mdelta[0m[2m=[0m4s 999ms 878µs 119ns ago
[INFO] [stdout] [2m2026-10-06T19:58:16.418060Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m617.82577ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:16.454316Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:16.431230982Z, server: 2026-10-06T19:58:16.442430741Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:16.454085791Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 427µs 404ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:16.442658386Z [3mdelta[0m[2m=[0m227µs 645ns ago
[INFO] [stdout] [2m2026-10-06T19:58:16.454415Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.427404ms [3mdelta[0m[2m=[0m227µs 645ns ago
[INFO] [stdout] [2m2026-10-06T19:58:16.454444Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.533260796s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:16.881118Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:16.866367436Z, server: 2026-10-06T19:58:21.873710576Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:16.880917766Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 275µs 165ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:16.873642601Z [3mdelta[0m[2m=[0m5s 67µs 975ns
[INFO] [stdout] [2m2026-10-06T19:58:16.881226Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.275165ms [3mdelta[0m[2m=[0m5s 67µs 975ns
[INFO] [stdout] [2m2026-10-06T19:58:16.881257Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m588.41932ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.013492Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:16.811060987Z, server: 2026-10-06T19:58:16.911425736Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.013311594Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 125µs 303ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:16.91218629Z [3mdelta[0m[2m=[0m760µs 554ns ago
[INFO] [stdout] [2m2026-10-06T19:58:17.013602Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.125303ms [3mdelta[0m[2m=[0m760µs 554ns ago
[INFO] [stdout] [2m2026-10-06T19:58:17.013630Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.426197608s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.061616Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.036914984Z, server: 2026-10-06T19:58:12.048104354Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.061432234Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 258µs 625ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.049173609Z [3mdelta[0m[2m=[0m5s 1ms 69µs 255ns ago
[INFO] [stdout] [2m2026-10-06T19:58:17.061919Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.258625ms [3mdelta[0m[2m=[0m5s 1ms 69µs 255ns ago
[INFO] [stdout] [2m2026-10-06T19:58:17.061953Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.69782995s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.069566Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.061366674Z, server: 2026-10-06T19:58:22.065051674Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.069242274Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m3ms 937µs 800ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.065304474Z [3mdelta[0m[2m=[0m4s 999ms 747µs 200ns
[INFO] [stdout] [2m2026-10-06T19:58:17.069806Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m3.9378ms [3mdelta[0m[2m=[0m4s 999ms 747µs 200ns
[INFO] [stdout] [2m2026-10-06T19:58:17.069865Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.043592637s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.165383Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.161093722Z, server: 2026-10-06T19:58:17.164050273Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.165191653Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 48µs 965ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.163142687Z [3mdelta[0m[2m=[0m907µs 586ns
[INFO] [stdout] [2m2026-10-06T19:58:17.165469Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.048965ms [3mdelta[0m[2m=[0m907µs 586ns
[INFO] [stdout] [2m2026-10-06T19:58:17.165491Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.269786501s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.483998Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.471261059Z, server: 2026-10-06T19:58:22.477477369Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.483791109Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 265µs 25ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.477526084Z [3mdelta[0m[2m=[0m4s 999ms 951µs 285ns
[INFO] [stdout] [2m2026-10-06T19:58:17.484099Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.265025ms [3mdelta[0m[2m=[0m4s 999ms 951µs 285ns
[INFO] [stdout] [2m2026-10-06T19:58:17.484131Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.494067694s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.594907Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.573263968Z, server: 2026-10-06T19:58:22.583543637Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.594734897Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 735µs 464ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.583999432Z [3mdelta[0m[2m=[0m4s 999ms 544µs 205ns
[INFO] [stdout] [2m2026-10-06T19:58:17.595020Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.735464ms [3mdelta[0m[2m=[0m4s 999ms 544µs 205ns
[INFO] [stdout] [2m2026-10-06T19:58:17.595046Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.010600686s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.687481Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:15.784616589Z, server: 2026-10-06T19:58:16.736199978Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.687220326Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m951ms 301µs 868ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:16.735918457Z [3mdelta[0m[2m=[0m281µs 521ns
[INFO] [stdout] [2m2026-10-06T19:58:17.687591Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m951.301868ms [3mdelta[0m[2m=[0m281µs 521ns
[INFO] [stdout] [2m2026-10-06T19:58:17.687615Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m281µs 521ns
[INFO] [stdout] [2m2026-10-06T19:58:17.687628Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.087762479s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.709911Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.687224196Z, server: 2026-10-06T19:58:17.698411626Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.709719216Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 247µs 510ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.698471706Z [3mdelta[0m[2m=[0m60µs 80ns ago
[INFO] [stdout] [2m2026-10-06T19:58:17.710018Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.24751ms [3mdelta[0m[2m=[0m60µs 80ns ago
[INFO] [stdout] [2m2026-10-06T19:58:17.710043Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.540367546s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:17.846097Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.823296175Z, server: 2026-10-06T19:58:22.834661774Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:17.845871094Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 287µs 459ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.834583634Z [3mdelta[0m[2m=[0m5s 78µs 140ns
[INFO] [stdout] [2m2026-10-06T19:58:17.846190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.287459ms [3mdelta[0m[2m=[0m5s 78µs 140ns
[INFO] [stdout] [2m2026-10-06T19:58:17.846214Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.903560457s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.011239Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:17.988254753Z, server: 2026-10-06T19:58:17.999639592Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.011038272Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 391µs 759ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:17.999646512Z [3mdelta[0m[2m=[0m6µs 920ns ago
[INFO] [stdout] [2m2026-10-06T19:58:18.011330Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.391759ms [3mdelta[0m[2m=[0m6µs 920ns ago
[INFO] [stdout] [2m2026-10-06T19:58:18.011356Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m465.466506ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.122725Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.114241451Z, server: 2026-10-06T19:58:23.118406731Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.122552241Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 155µs 395ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.118396846Z [3mdelta[0m[2m=[0m5s 9µs 885ns
[INFO] [stdout] [2m2026-10-06T19:58:18.122862Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.155395ms [3mdelta[0m[2m=[0m5s 9µs 885ns
[INFO] [stdout] [2m2026-10-06T19:58:18.122905Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m571.668548ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.439696Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.437232677Z, server: 2026-10-06T19:58:18.438373277Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.439499937Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 133µs 630ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.438366307Z [3mdelta[0m[2m=[0m6µs 970ns
[INFO] [stdout] [2m2026-10-06T19:58:18.439795Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.13363ms [3mdelta[0m[2m=[0m6µs 970ns
[INFO] [stdout] [2m2026-10-06T19:58:18.439820Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.934657545s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.501616Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.478548057Z, server: 2026-10-06T19:58:18.489761277Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.501407486Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 429µs 714ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.489977771Z [3mdelta[0m[2m=[0m216µs 494ns ago
[INFO] [stdout] [2m2026-10-06T19:58:18.501706Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.429714ms [3mdelta[0m[2m=[0m216µs 494ns ago
[INFO] [stdout] [2m2026-10-06T19:58:18.501729Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.832054133s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.627798Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.606217185Z, server: 2026-10-06T19:58:23.616417265Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.627618575Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 700µs 695ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.61691788Z [3mdelta[0m[2m=[0m4s 999ms 499µs 385ns
[INFO] [stdout] [2m2026-10-06T19:58:18.627899Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.700695ms [3mdelta[0m[2m=[0m4s 999ms 499µs 385ns
[INFO] [stdout] [2m2026-10-06T19:58:18.627927Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.731821265s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.645845Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.441237827Z, server: 2026-10-06T19:58:18.544314756Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.645672615Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m102ms 217µs 394ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.543455221Z [3mdelta[0m[2m=[0m859µs 535ns
[INFO] [stdout] [2m2026-10-06T19:58:18.649036Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m102.217394ms [3mdelta[0m[2m=[0m859µs 535ns
[INFO] [stdout] [2m2026-10-06T19:58:18.649127Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m666.102621ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.711861Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.695253744Z, server: 2026-10-06T19:58:23.703451154Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.711660424Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 203µs 340ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.703457084Z [3mdelta[0m[2m=[0m4s 999ms 994µs 70ns
[INFO] [stdout] [2m2026-10-06T19:58:18.711949Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.20334ms [3mdelta[0m[2m=[0m4s 999ms 994µs 70ns
[INFO] [stdout] [2m2026-10-06T19:58:18.711971Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m598.639752ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:18.783857Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.761217903Z, server: 2026-10-06T19:58:13.772438523Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:18.783659873Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 220µs 985ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.772438888Z [3mdelta[0m[2m=[0m5s 365ns ago
[INFO] [stdout] [2m2026-10-06T19:58:18.783947Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.220985ms [3mdelta[0m[2m=[0m5s 365ns ago
[INFO] [stdout] [2m2026-10-06T19:58:18.783995Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-5000.00244, -5000.000365, -5000.003705, -4999.878119, -5001.069255]
[INFO] [stdout] [2m2026-10-06T19:58:18.784016Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.003705 [3mmean[0m[2m=[0m-5000.1907768 [3mvariance[0m[2m=[0m0.2440505274863387 [3mstddev[0m[2m=[0m0.49401470371471606
[INFO] [stdout] [2m2026-10-06T19:58:18.784036Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-5000.00244, -5000.000365, -5000.003705, -4999.878119]
[INFO] [stdout] [2m2026-10-06T19:58:18.784049Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 971µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-10-06T19:58:19.001099Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.97929858Z, server: 2026-10-06T19:58:23.98964966Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.00087051Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 785µs 965ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:18.990084545Z [3mdelta[0m[2m=[0m4s 999ms 565µs 115ns
[INFO] [stdout] [2m2026-10-06T19:58:19.001181Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.785965ms [3mdelta[0m[2m=[0m4s 999ms 565µs 115ns
[INFO] [stdout] [2m2026-10-06T19:58:19.001203Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m867.132672ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:19.276281Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.252237237Z, server: 2026-10-06T19:58:19.263421487Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.276078177Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 920µs 470ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.264157707Z [3mdelta[0m[2m=[0m736µs 220ns ago
[INFO] [stdout] [2m2026-10-06T19:58:19.276374Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.92047ms [3mdelta[0m[2m=[0m736µs 220ns ago
[INFO] [stdout] [2m2026-10-06T19:58:19.276397Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m357.145471ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:19.328236Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.311928917Z, server: 2026-10-06T19:58:24.319076307Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.328062016Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 66µs 549ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.319995466Z [3mdelta[0m[2m=[0m4s 999ms 80µs 841ns
[INFO] [stdout] [2m2026-10-06T19:58:19.328320Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.066549ms [3mdelta[0m[2m=[0m4s 999ms 80µs 841ns
[INFO] [stdout] [2m2026-10-06T19:58:19.328348Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.7472, 5000.009885, 4999.080841, 5000.0095, 4999.99407]
[INFO] [stdout] [2m2026-10-06T19:58:19.328368Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.080841 [3mmean[0m[2m=[0m4999.7682992 [3mvariance[0m[2m=[0m0.16013948295074673 [3mstddev[0m[2m=[0m0.4001743157059767
[INFO] [stdout] [2m2026-10-06T19:58:19.328387Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.080841]
[INFO] [stdout] [2m2026-10-06T19:58:19.328408Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 80µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-10-06T19:58:19.520270Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.317361416Z, server: 2026-10-06T19:58:19.418729155Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.520084764Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 361µs 674ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.41872309Z [3mdelta[0m[2m=[0m6µs 65ns
[INFO] [stdout] [2m2026-10-06T19:58:19.520450Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.361674ms [3mdelta[0m[2m=[0m6µs 65ns
[INFO] [stdout] [2m2026-10-06T19:58:19.520535Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m151.769399ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:19.657400Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.634767603Z, server: 2026-10-06T19:58:19.646004483Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.657202232Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 217µs 314ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.645984917Z [3mdelta[0m[2m=[0m19µs 566ns
[INFO] [stdout] [2m2026-10-06T19:58:19.657611Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.217314ms [3mdelta[0m[2m=[0m19µs 566ns
[INFO] [stdout] [2m2026-10-06T19:58:19.657726Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.11388392s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:19.773375Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.750241511Z, server: 2026-10-06T19:58:24.761652071Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.773153271Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 455µs 880ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.761697391Z [3mdelta[0m[2m=[0m4s 999ms 954µs 680ns
[INFO] [stdout] [2m2026-10-06T19:58:19.773585Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.45588ms [3mdelta[0m[2m=[0m4s 999ms 954µs 680ns
[INFO] [stdout] [2m2026-10-06T19:58:19.773664Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m91.371883ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:19.877065Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.674445612Z, server: 2026-10-06T19:58:19.775973591Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.87685503Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 204µs 709ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.775650321Z [3mdelta[0m[2m=[0m323µs 270ns
[INFO] [stdout] [2m2026-10-06T19:58:19.877156Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.204709ms [3mdelta[0m[2m=[0m323µs 270ns
[INFO] [stdout] [2m2026-10-06T19:58:19.877185Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.52924, -0.760554, 0.32327, 0.006065, 0.859535]
[INFO] [stdout] [2m2026-10-06T19:58:19.877203Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.32327 [3mmean[0m[2m=[0m0.19151120000000005 [3mvariance[0m[2m=[0m0.3796238398097 [3mstddev[0m[2m=[0m0.6161362185504923
[INFO] [stdout] [2m2026-10-06T19:58:19.877221Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.52924, 0.32327, 0.006065, 0.859535]
[INFO] [stdout] [2m2026-10-06T19:58:19.877233Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m429µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-10-06T19:58:19.883843Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.86918551Z, server: 2026-10-06T19:58:24.87636894Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.8836439Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 229µs 195ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.876414705Z [3mdelta[0m[2m=[0m4s 999ms 954µs 235ns
[INFO] [stdout] [2m2026-10-06T19:58:19.883938Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.229195ms [3mdelta[0m[2m=[0m4s 999ms 954µs 235ns
[INFO] [stdout] [2m2026-10-06T19:58:19.883969Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.951285, 4999.954235, 5000.067975, 5000.00129, 4999.565115]
[INFO] [stdout] [2m2026-10-06T19:58:19.884017Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.067975 [3mmean[0m[2m=[0m4999.90798 [3mvariance[0m[2m=[0m0.038969103099950456 [3mstddev[0m[2m=[0m0.19740593481440838
[INFO] [stdout] [2m2026-10-06T19:58:19.884039Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.951285, 4999.954235, 5000.067975, 5000.00129]
[INFO] [stdout] [2m2026-10-06T19:58:19.884075Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 993µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-10-06T19:58:19.890481Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:19.86811674Z, server: 2026-10-06T19:58:24.88003338Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:19.89022306Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 53µs 160ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.8791699Z [3mdelta[0m[2m=[0m5s 863µs 480ns
[INFO] [stdout] [2m2026-10-06T19:58:19.890692Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.05316ms [3mdelta[0m[2m=[0m5s 863µs 480ns
[INFO] [stdout] [2m2026-10-06T19:58:19.890798Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.41836, 5000.86348, 5000.006396, 5000.07814, 4999.95468]
[INFO] [stdout] [2m2026-10-06T19:58:19.890843Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.006396 [3mmean[0m[2m=[0m5000.0642112 [3mvariance[0m[2m=[0m0.2678720199473141 [3mstddev[0m[2m=[0m0.5175635419417737
[INFO] [stdout] [2m2026-10-06T19:58:19.890914Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.006396, 5000.07814, 4999.95468]
[INFO] [stdout] [2m2026-10-06T19:58:19.890946Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 13µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-10-06T19:58:20.362477Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:20.337100654Z, server: 2026-10-06T19:58:20.351079384Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:20.362255664Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 577µs 505ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:20.349678159Z [3mdelta[0m[2m=[0m1ms 401µs 225ns
[INFO] [stdout] [2m2026-10-06T19:58:20.362589Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.577505ms [3mdelta[0m[2m=[0m1ms 401µs 225ns
[INFO] [stdout] [2m2026-10-06T19:58:20.362626Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00959, -0.00692, -0.227645, -0.216494, 1.401225]
[INFO] [stdout] [2m2026-10-06T19:58:20.362699Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.227645 [3mmean[0m[2m=[0m0.1919512 [3mvariance[0m[2m=[0m0.46950923431970004 [3mstddev[0m[2m=[0m0.6852074388969372
[INFO] [stdout] [2m2026-10-06T19:58:20.362727Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00959, -0.00692, -0.227645, -0.216494]
[INFO] [stdout] [2m2026-10-06T19:58:20.362744Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m110µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-10-06T19:58:20.382242Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:20.376088854Z, server: 2026-10-06T19:58:20.379050744Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:20.382044394Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 977µs 770ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:20.379066624Z [3mdelta[0m[2m=[0m15µs 880ns ago
[INFO] [stdout] [2m2026-10-06T19:58:20.382345Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.97777ms [3mdelta[0m[2m=[0m15µs 880ns ago
[INFO] [stdout] [2m2026-10-06T19:58:20.382382Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000145, 0.00697, 0.013375, 0.907586, -0.01588]
[INFO] [stdout] [2m2026-10-06T19:58:20.382404Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.013375 [3mmean[0m[2m=[0m0.1824392 [3mvariance[0m[2m=[0m0.16444292646569997 [3mstddev[0m[2m=[0m0.40551563035929944
[INFO] [stdout] [2m2026-10-06T19:58:20.382424Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.000145, 0.00697, 0.013375, -0.01588]
[INFO] [stdout] [2m2026-10-06T19:58:20.382438Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m1µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-10-06T19:58:20.382931Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:20.360347064Z, server: 2026-10-06T19:58:25.371526444Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:20.382729923Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 191µs 429ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:20.371538493Z [3mdelta[0m[2m=[0m4s 999ms 987µs 951ns
[INFO] [stdout] [2m2026-10-06T19:58:20.383036Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.191429ms [3mdelta[0m[2m=[0m4s 999ms 987µs 951ns
[INFO] [stdout] [2m2026-10-06T19:58:20.383064Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.723396687s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:20.737287Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:18.777231463Z, server: 2026-10-06T19:58:19.756189151Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:20.737087559Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m979ms 928µs 48ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:19.757159511Z [3mdelta[0m[2m=[0m970µs 360ns ago
[INFO] [stdout] [2m2026-10-06T19:58:20.737380Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m979.928048ms [3mdelta[0m[2m=[0m970µs 360ns ago
[INFO] [stdout] [2m2026-10-06T19:58:20.737405Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.929051635s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:20.795897Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:20.773121399Z, server: 2026-10-06T19:58:20.784438549Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:20.795669619Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 274µs 110ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:20.784395509Z [3mdelta[0m[2m=[0m43µs 40ns
[INFO] [stdout] [2m2026-10-06T19:58:20.796015Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.27411ms [3mdelta[0m[2m=[0m43µs 40ns
[INFO] [stdout] [2m2026-10-06T19:58:20.796051Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.017171, 0.019566, -0.06008, 0.04304, -0.73622]
[INFO] [stdout] [2m2026-10-06T19:58:20.796075Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.06008 [3mmean[0m[2m=[0m-0.1433046 [3mvariance[0m[2m=[0m0.11136964152279999 [3mstddev[0m[2m=[0m0.3337209036347588
[INFO] [stdout] [2m2026-10-06T19:58:20.796109Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.017171, 0.019566, -0.06008, 0.04304]
[INFO] [stdout] [2m2026-10-06T19:58:20.796133Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-10-06T19:58:22.132163Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:22.107233063Z, server: 2026-10-06T19:58:27.118440883Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:22.131925873Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 346µs 405ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:22.119579468Z [3mdelta[0m[2m=[0m4s 998ms 861µs 415ns
[INFO] [stdout] [2m2026-10-06T19:58:22.132249Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.346405ms [3mdelta[0m[2m=[0m4s 998ms 861µs 415ns
[INFO] [stdout] [2m2026-10-06T19:58:22.132279Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.499385, 5000.493205, 4999.544205, 4999.987951, 4998.861415]
[INFO] [stdout] [2m2026-10-06T19:58:22.132321Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.544205 [3mmean[0m[2m=[0m4999.6772322 [3mvariance[0m[2m=[0m0.36931033732897167 [3mstddev[0m[2m=[0m0.6077090893914388
[INFO] [stdout] [2m2026-10-06T19:58:22.132342Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.499385, 4999.544205, 4999.987951]
[INFO] [stdout] [2m2026-10-06T19:58:22.132355Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 677µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-10-06T19:58:24.338387Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:22.669287827Z, server: 2026-10-06T19:58:23.503271906Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:24.338203837Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m834ms 458µs 5ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:23.503745832Z [3mdelta[0m[2m=[0m473µs 926ns ago
[INFO] [stdout] [2m2026-10-06T19:58:24.338465Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m834.458005ms [3mdelta[0m[2m=[0m473µs 926ns ago
[INFO] [stdout] [2m2026-10-06T19:58:24.338485Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m994.661672ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:26.989385Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:25.335230585Z, server: 2026-10-06T19:58:26.163432335Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:26.989213465Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m826ms 991µs 440ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:26.162222025Z [3mdelta[0m[2m=[0m1ms 210µs 310ns
[INFO] [stdout] [2m2026-10-06T19:58:26.989467Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m826.99144ms [3mdelta[0m[2m=[0m1ms 210µs 310ns
[INFO] [stdout] [2m2026-10-06T19:58:26.989489Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m243.118639ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.911387Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:27.234015912Z, server: 2026-10-06T19:58:28.073338423Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:28.911222463Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m838ms 603µs 275ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:28.072619187Z [3mdelta[0m[2m=[0m719µs 236ns
[INFO] [stdout] [2m2026-10-06T19:58:28.911473Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m838.603275ms [3mdelta[0m[2m=[0m719µs 236ns
[INFO] [stdout] [2m2026-10-06T19:58:28.911501Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[1.21031, -0.473926, 0.719236, 0.281521, -0.97036]
[INFO] [stdout] [2m2026-10-06T19:58:28.911519Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.719236 [3mmean[0m[2m=[0m0.15335619999999997 [3mvariance[0m[2m=[0m0.7775046389802001 [3mstddev[0m[2m=[0m0.8817622349478345
[INFO] [stdout] [2m2026-10-06T19:58:28.911536Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[1.21031, 0.719236, 0.281521]
[INFO] [stdout] [2m2026-10-06T19:58:28.911548Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m737µs
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 13.13s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/build/timesimp/f9c18dbe40acd213/out/in_process-f9c18dbe40acd213)
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-10-06T19:58:28.918316Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-10-06T19:58:28.918591Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.918316Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:28.919024Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.918308Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-10-06T19:58:28.918543Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:58:28.919293Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.919369Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.919762Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:28.919574173Z, server: 2026-10-06T19:58:28.919587333Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:28.919591113Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 470ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:28.919582643Z [3mdelta[0m[2m=[0m4µs 690ns
[INFO] [stdout] [2m2026-10-06T19:58:28.919917Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.47µs [3mdelta[0m[2m=[0m4µs 690ns
[INFO] [stdout] [2m2026-10-06T19:58:28.919959Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m508.720101ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.920141Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:28.919865393Z, server: 2026-10-06T19:58:33.919873253Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:28.919876923Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5µs 765ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:28.919871158Z [3mdelta[0m[2m=[0m5s 2µs 95ns
[INFO] [stdout] [2m2026-10-06T19:58:28.920279Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.765µs [3mdelta[0m[2m=[0m5s 2µs 95ns
[INFO] [stdout] [2m2026-10-06T19:58:28.920364Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m99.569308ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.920372Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:28.920216023Z, server: 2026-10-06T19:58:28.920219033Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:28.920220803Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 390ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:28.920218413Z [3mdelta[0m[2m=[0m620ns
[INFO] [stdout] [2m2026-10-06T19:58:28.920457Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.39µs [3mdelta[0m[2m=[0m620ns
[INFO] [stdout] [2m2026-10-06T19:58:28.920483Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m620ns
[INFO] [stdout] [2m2026-10-06T19:58:28.920496Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m875.519223ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:28.921146Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:28.921025163Z, server: 2026-10-06T19:58:23.921028613Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:28.921030593Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 715ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:28.921027878Z [3mdelta[0m[2m=[0m4s 999ms 999µs 265ns ago
[INFO] [stdout] [2m2026-10-06T19:58:28.921212Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.715µs [3mdelta[0m[2m=[0m4s 999ms 999µs 265ns ago
[INFO] [stdout] [2m2026-10-06T19:58:28.921230Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m640.041766ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:29.021037Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:29.020820352Z, server: 2026-10-06T19:58:34.020830932Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:29.020835402Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 525ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:29.020827877Z [3mdelta[0m[2m=[0m5s 3µs 55ns
[INFO] [stdout] [2m2026-10-06T19:58:29.021149Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.525µs [3mdelta[0m[2m=[0m5s 3µs 55ns
[INFO] [stdout] [2m2026-10-06T19:58:29.021178Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m634.075667ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:29.430449Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:29.430263878Z, server: 2026-10-06T19:58:29.430274688Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:29.430279168Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 645ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:29.430271523Z [3mdelta[0m[2m=[0m3µs 165ns
[INFO] [stdout] [2m2026-10-06T19:58:29.430535Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.645µs [3mdelta[0m[2m=[0m3µs 165ns
[INFO] [stdout] [2m2026-10-06T19:58:29.430556Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m770.375258ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:29.563350Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:29.563156566Z, server: 2026-10-06T19:58:24.563167406Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:29.563171626Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 530ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:29.563164096Z [3mdelta[0m[2m=[0m4s 999ms 996µs 690ns ago
[INFO] [stdout] [2m2026-10-06T19:58:29.563440Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.53µs [3mdelta[0m[2m=[0m4s 999ms 996µs 690ns ago
[INFO] [stdout] [2m2026-10-06T19:58:29.563464Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m619.555109ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:29.656752Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:29.656515035Z, server: 2026-10-06T19:58:34.656529255Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:29.656534045Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 505ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:29.65652454Z [3mdelta[0m[2m=[0m5s 4µs 715ns
[INFO] [stdout] [2m2026-10-06T19:58:29.656854Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.505µs [3mdelta[0m[2m=[0m5s 4µs 715ns
[INFO] [stdout] [2m2026-10-06T19:58:29.656878Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m140.024679ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:29.797508Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:29.797246464Z, server: 2026-10-06T19:58:29.797261033Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:29.797267053Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10µs 294ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:29.797256758Z [3mdelta[0m[2m=[0m4µs 275ns
[INFO] [stdout] [2m2026-10-06T19:58:29.798004Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.294µs [3mdelta[0m[2m=[0m4µs 275ns
[INFO] [stdout] [2m2026-10-06T19:58:29.798106Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m951.05809ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:29.800192Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:29.800059824Z, server: 2026-10-06T19:58:34.800066124Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:29.800070084Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5µs 130ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:29.800064954Z [3mdelta[0m[2m=[0m5s 1µs 170ns
[INFO] [stdout] [2m2026-10-06T19:58:29.800339Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.13µs [3mdelta[0m[2m=[0m5s 1µs 170ns
[INFO] [stdout] [2m2026-10-06T19:58:29.800446Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.910555771s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:30.184402Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:30.184225239Z, server: 2026-10-06T19:58:25.184235109Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:30.184242049Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 405ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:30.184233644Z [3mdelta[0m[2m=[0m4s 999ms 998µs 535ns ago
[INFO] [stdout] [2m2026-10-06T19:58:30.184486Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.405µs [3mdelta[0m[2m=[0m4s 999ms 998µs 535ns ago
[INFO] [stdout] [2m2026-10-06T19:58:30.184507Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.822945739s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:30.202382Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:30.202197499Z, server: 2026-10-06T19:58:30.202208339Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:30.202213009Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 755ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:30.202205254Z [3mdelta[0m[2m=[0m3µs 85ns
[INFO] [stdout] [2m2026-10-06T19:58:30.202459Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.755µs [3mdelta[0m[2m=[0m3µs 85ns
[INFO] [stdout] [2m2026-10-06T19:58:30.202489Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.689288319s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:30.751418Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:30.751235443Z, server: 2026-10-06T19:58:30.751246913Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:30.751250682Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 619ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:30.751243062Z [3mdelta[0m[2m=[0m3µs 851ns
[INFO] [stdout] [2m2026-10-06T19:58:30.751727Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.619µs [3mdelta[0m[2m=[0m3µs 851ns
[INFO] [stdout] [2m2026-10-06T19:58:30.751808Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.059242985s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:31.713511Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:31.713331323Z, server: 2026-10-06T19:58:36.713341613Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:31.713346173Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 425ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:31.713338748Z [3mdelta[0m[2m=[0m5s 2µs 865ns
[INFO] [stdout] [2m2026-10-06T19:58:31.713693Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.425µs [3mdelta[0m[2m=[0m5s 2µs 865ns
[INFO] [stdout] [2m2026-10-06T19:58:31.713818Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00117, 5000.002095, 5000.002865, 5000.003055, 5000.004715]
[INFO] [stdout] [2m2026-10-06T19:58:31.713903Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.002865 [3mmean[0m[2m=[0m5000.00278 [3mvariance[0m[2m=[0m1.7221000004901274e-6 [3mstddev[0m[2m=[0m0.0013122880783159342
[INFO] [stdout] [2m2026-10-06T19:58:31.714010Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.002095, 5000.002865, 5000.003055]
[INFO] [stdout] [2m2026-10-06T19:58:31.714084Z[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-10-06T19:58:31.812485Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:31.812279852Z, server: 2026-10-06T19:58:31.812290512Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:31.812293723Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 935ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:31.812286787Z [3mdelta[0m[2m=[0m3µs 725ns
[INFO] [stdout] [2m2026-10-06T19:58:31.812661Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.935µs [3mdelta[0m[2m=[0m3µs 725ns
[INFO] [stdout] [2m2026-10-06T19:58:31.812748Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m79.286258ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:31.893381Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:31.893185661Z, server: 2026-10-06T19:58:31.893198711Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:31.893202011Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 175ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:31.893193836Z [3mdelta[0m[2m=[0m4µs 875ns
[INFO] [stdout] [2m2026-10-06T19:58:31.893553Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.175µs [3mdelta[0m[2m=[0m4µs 875ns
[INFO] [stdout] [2m2026-10-06T19:58:31.893675Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00062, 0.003725, 0.003851, 0.004875, 0.004275]
[INFO] [stdout] [2m2026-10-06T19:58:31.893760Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.003851 [3mmean[0m[2m=[0m0.0034692 [3mvariance[0m[2m=[0m2.7386832e-6 [3mstddev[0m[2m=[0m0.001654896733938405
[INFO] [stdout] [2m2026-10-06T19:58:31.893839Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.003725, 0.003851, 0.004875, 0.004275]
[INFO] [stdout] [2m2026-10-06T19:58:31.893745Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:31.893541061Z, server: 2026-10-06T19:58:31.893551191Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:31.893555161Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 50ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:31.893548111Z [3mdelta[0m[2m=[0m3µs 80ns
[INFO] [stdout] [2m2026-10-06T19:58:31.894012Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4µs
[INFO] [stdout] [2m2026-10-06T19:58:31.894176Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.05µs [3mdelta[0m[2m=[0m3µs 80ns
[INFO] [stdout] [2m2026-10-06T19:58:31.894253Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m595.047429ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] [2m2026-10-06T19:58:32.010481Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:32.01029639Z, server: 2026-10-06T19:58:27.01031144Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:32.01031531Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 460ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:32.01030585Z [3mdelta[0m[2m=[0m4s 999ms 994µs 410ns ago
[INFO] [stdout] [2m2026-10-06T19:58:32.010570Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.46µs [3mdelta[0m[2m=[0m4s 999ms 994µs 410ns ago
[INFO] [stdout] [2m2026-10-06T19:58:32.010593Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.447952914s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:58:32.492276Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:32.492090085Z, server: 2026-10-06T19:58:32.492101885Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:32.492106145Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 30ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:32.492098115Z [3mdelta[0m[2m=[0m3µs 770ns
[INFO] [stdout] [2m2026-10-06T19:58:32.492394Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.03µs [3mdelta[0m[2m=[0m3µs 770ns
[INFO] [stdout] [2m2026-10-06T19:58:32.492422Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00308, 0.003165, 0.003085, 0.00377, 0.00469]
[INFO] [stdout] [2m2026-10-06T19:58:32.492441Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.003085 [3mmean[0m[2m=[0m0.003558 [3mvariance[0m[2m=[0m4.832574999999999e-7 [3mstddev[0m[2m=[0m0.0006951672460638518
[INFO] [stdout] [2m2026-10-06T19:58:32.492460Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00308, 0.003165, 0.003085, 0.00377]
[INFO] [stdout] [2m2026-10-06T19:58:32.492473Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] [2m2026-10-06T19:58:33.459460Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:58:33.459253176Z, server: 2026-10-06T19:58:28.459263956Z } [3mcurrent[0m[2m=[0m2026-10-06T19:58:33.459268246Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 535ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:58:33.459260711Z [3mdelta[0m[2m=[0m4s 999ms 996µs 755ns ago
[INFO] [stdout] [2m2026-10-06T19:58:33.459554Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.535µs [3mdelta[0m[2m=[0m4s 999ms 996µs 755ns ago
[INFO] [stdout] [2m2026-10-06T19:58:33.459594Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.999265, -4999.99669, -4999.996755, -4999.998535, -4999.99441]
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] [2m2026-10-06T19:58:33.459614Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.996755 [3mmean[0m[2m=[0m-4999.997131 [3mvariance[0m[2m=[0m3.5662174998644724e-6 [3mstddev[0m[2m=[0m0.0018884431418140374
[INFO] [stdout] [2m2026-10-06T19:58:33.459635Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99669, -4999.996755, -4999.998535]
[INFO] [stdout] [2m2026-10-06T19:58:33.459647Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.54s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test 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.44s; merged doctests compilation took 1.41s
[INFO] running `Command { std: "docker" "inspect" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845", kill_on_drop: false }`
[INFO] [stdout] 3d31a7259bb9644197e0ccbaf6ff5b24356775efeb5edcf665c75984dd3b1845
