[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against 1.99.0-beta.8 for beta-1.100-2
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-4-tc1/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-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain 1.99.0-beta.8
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.99.0-beta.8" "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.99.0-beta.8" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded miniz_oxide v0.8.5
[INFO] [stderr]   Downloaded smallvec v1.14.0
[INFO] [stderr]   Downloaded tempfile v3.19.1
[INFO] [stderr]   Downloaded errno v0.3.11
[INFO] [stderr]   Downloaded rustix v1.0.5
[INFO] [stderr]   Downloaded cc v1.2.20
[INFO] [stderr]   Downloaded rustls-pki-types v1.11.0
[INFO] [stderr]   Downloaded openssl-sys v0.9.107
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded openssl v0.10.72
[INFO] [stderr]   Downloaded rustls v0.23.26
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded portable-atomic v1.11.0
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] [stderr]   Downloaded rustls-webpki v0.103.1
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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] 320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681
[INFO] running `Command { std: "docker" "start" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681", 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" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681", 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" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "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 zerocopy v0.8.24
[INFO] [stderr]    Compiling getrandom v0.3.2
[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 thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 9.83s
[INFO] running `Command { std: "docker" "inspect" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681", 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" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "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 writeable v0.5.5
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling tracing-core v0.1.33
[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 icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling serde v1.0.219
[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 thread_local v1.1.8
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[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 indexmap v2.9.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling synstructure v0.13.1
[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-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[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 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]     Finished `test` profile [unoptimized + debuginfo] target(s) in 37.91s
[INFO] running `Command { std: "docker" "inspect" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681", 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" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "test" "--frozen", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.43s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/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::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... 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/deps/client_server-c44eda2a8c9c80bc)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-10-06T19:57:01.659282Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.659264Z[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:57:01.659370Z[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:57:01.659396Z[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:57:01.659234Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-10-06T19:57:01.659554Z[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:57:01.659241Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.659681Z[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:57:01.660002Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.660107Z[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:57:01.660104Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.660201Z[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:57:01.660342Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.660377Z[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:57:01.660421Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.660461Z[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:57:01.661117Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.661152Z[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:57:01.661413Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:01.661447Z[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:57:01.665112Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.662631555Z, server: 2026-10-06T19:57:01.663756145Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.664887985Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 128µs 215ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.66375977Z [3mdelta[0m[2m=[0m3µs 625ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.665178Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.128215ms [3mdelta[0m[2m=[0m3µs 625ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.665206Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m3µs 625ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.665219Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m769.098872ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.671481Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.660898145Z, server: 2026-10-06T19:57:06.666088835Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.671245135Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5ms 173µs 495ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.66607164Z [3mdelta[0m[2m=[0m5s 17µs 195ns
[INFO] [stdout] [2m2026-10-06T19:57:01.671567Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.173495ms [3mdelta[0m[2m=[0m5s 17µs 195ns
[INFO] [stdout] [2m2026-10-06T19:57:01.671590Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 17µs 195ns
[INFO] [stdout] [2m2026-10-06T19:57:01.671606Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m769.145401ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.681333Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.660637205Z, server: 2026-10-06T19:57:06.670888255Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.681125585Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 244µs 190ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.670881395Z [3mdelta[0m[2m=[0m5s 6µs 860ns
[INFO] [stdout] [2m2026-10-06T19:57:01.681418Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.24419ms [3mdelta[0m[2m=[0m5s 6µs 860ns
[INFO] [stdout] [2m2026-10-06T19:57:01.681439Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 6µs 860ns
[INFO] [stdout] [2m2026-10-06T19:57:01.681453Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.165210943s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.682319Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.660884805Z, server: 2026-10-06T19:57:01.671043445Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.682198255Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 656µs 725ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.67154153Z [3mdelta[0m[2m=[0m498µs 85ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.682385Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.656725ms [3mdelta[0m[2m=[0m498µs 85ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.682407Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.357377052s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.683937Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.661552245Z, server: 2026-10-06T19:57:01.672711675Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.683844495Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 146µs 125ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.67269837Z [3mdelta[0m[2m=[0m13µs 305ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684006Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.146125ms [3mdelta[0m[2m=[0m13µs 305ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684027Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.494513646s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.684082Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.661605175Z, server: 2026-10-06T19:56:56.672788885Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.683948635Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 171µs 730ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.672776905Z [3mdelta[0m[2m=[0m4s 999ms 988µs 20ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.684092Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.661656505Z, server: 2026-10-06T19:57:06.672789465Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.683949935Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 146µs 715ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.67280322Z [3mdelta[0m[2m=[0m4s 999ms 986µs 245ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684049Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.661398585Z, server: 2026-10-06T19:57:06.672538145Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.683728005Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 164µs 710ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.672563295Z [3mdelta[0m[2m=[0m4s 999ms 974µs 850ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684158Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.146715ms [3mdelta[0m[2m=[0m4s 999ms 986µs 245ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684145Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.17173ms [3mdelta[0m[2m=[0m4s 999ms 988µs 20ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.684198Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.16471ms [3mdelta[0m[2m=[0m4s 999ms 974µs 850ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684206Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 988µs 20ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.684229Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m744.612634ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.684235Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 974µs 850ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684253Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m71.217671ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.684181Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 986µs 245ns
[INFO] [stdout] [2m2026-10-06T19:57:01.684280Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.610579444s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.773249Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.756660044Z, server: 2026-10-06T19:57:06.764833234Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.773052684Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 196µs 320ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.764856364Z [3mdelta[0m[2m=[0m4s 999ms 976µs 870ns
[INFO] [stdout] [2m2026-10-06T19:57:01.773370Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.19632ms [3mdelta[0m[2m=[0m4s 999ms 976µs 870ns
[INFO] [stdout] [2m2026-10-06T19:57:01.773397Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.671637137s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:01.865332Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.662334105Z, server: 2026-10-06T19:57:01.763678104Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:01.865081893Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 373µs 894ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:01.763707999Z [3mdelta[0m[2m=[0m29µs 895ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.866102Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.373894ms [3mdelta[0m[2m=[0m29µs 895ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.866176Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m29µs 895ns ago
[INFO] [stdout] [2m2026-10-06T19:57:01.866194Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.829344687s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:02.437690Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:02.435188116Z, server: 2026-10-06T19:57:02.436355306Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:02.437501876Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 156µs 880ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:02.436344996Z [3mdelta[0m[2m=[0m10µs 310ns
[INFO] [stdout] [2m2026-10-06T19:57:02.437778Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.15688ms [3mdelta[0m[2m=[0m10µs 310ns
[INFO] [stdout] [2m2026-10-06T19:57:02.437809Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m522.251892ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:02.449844Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:02.441234656Z, server: 2026-10-06T19:57:07.445430226Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:02.449649666Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 207µs 505ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:02.445442161Z [3mdelta[0m[2m=[0m4s 999ms 988µs 65ns
[INFO] [stdout] [2m2026-10-06T19:57:02.450045Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.207505ms [3mdelta[0m[2m=[0m4s 999ms 988µs 65ns
[INFO] [stdout] [2m2026-10-06T19:57:02.450081Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m405.630255ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:02.452628Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:02.430182956Z, server: 2026-10-06T19:56:57.441315426Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:02.452473516Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 145µs 280ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:02.441328236Z [3mdelta[0m[2m=[0m5s 12µs 810ns ago
[INFO] [stdout] [2m2026-10-06T19:57:02.452711Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.14528ms [3mdelta[0m[2m=[0m5s 12µs 810ns ago
[INFO] [stdout] [2m2026-10-06T19:57:02.452735Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.261771208s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:02.874524Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:02.856872781Z, server: 2026-10-06T19:57:07.866039401Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:02.874288921Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 708µs 70ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:02.865580851Z [3mdelta[0m[2m=[0m5s 458µs 550ns
[INFO] [stdout] [2m2026-10-06T19:57:02.874524Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:02.848476921Z, server: 2026-10-06T19:57:07.863087141Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:02.874349601Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 936µs 340ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:02.861413261Z [3mdelta[0m[2m=[0m5s 1ms 673µs 880ns
[INFO] [stdout] [2m2026-10-06T19:57:02.874643Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.70807ms [3mdelta[0m[2m=[0m5s 458µs 550ns
[INFO] [stdout] [2m2026-10-06T19:57:02.874643Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.93634ms [3mdelta[0m[2m=[0m5s 1ms 673µs 880ns
[INFO] [stdout] [2m2026-10-06T19:57:02.874669Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m196.555639ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:02.874669Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.045674194s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:02.964093Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:02.96155591Z, server: 2026-10-06T19:57:02.96271737Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:02.963896769Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 170µs 429ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:02.962726339Z [3mdelta[0m[2m=[0m8µs 969ns ago
[INFO] [stdout] [2m2026-10-06T19:57:02.964250Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.170429ms [3mdelta[0m[2m=[0m8µs 969ns ago
[INFO] [stdout] [2m2026-10-06T19:57:02.964312Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.924250832s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.062935Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.040255179Z, server: 2026-10-06T19:57:03.051488468Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.062726248Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 235µs 534ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.051490713Z [3mdelta[0m[2m=[0m2µs 245ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.063147Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.235534ms [3mdelta[0m[2m=[0m2µs 245ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.063275Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.835889447s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.081721Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.073189148Z, server: 2026-10-06T19:57:08.077354968Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.081525208Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 168µs 30ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.077357178Z [3mdelta[0m[2m=[0m4s 999ms 997µs 790ns
[INFO] [stdout] [2m2026-10-06T19:57:03.081805Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.16803ms [3mdelta[0m[2m=[0m4s 999ms 997µs 790ns
[INFO] [stdout] [2m2026-10-06T19:57:03.081830Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m296.507284ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.181351Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:01.661669495Z, server: 2026-10-06T19:57:02.421485376Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.181145097Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m759ms 737µs 801ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:02.421407296Z [3mdelta[0m[2m=[0m78µs 80ns
[INFO] [stdout] [2m2026-10-06T19:57:03.181426Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m759.737801ms [3mdelta[0m[2m=[0m78µs 80ns
[INFO] [stdout] [2m2026-10-06T19:57:03.181456Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m78µs 80ns
[INFO] [stdout] [2m2026-10-06T19:57:03.181475Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.55159916s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.202908Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.180230647Z, server: 2026-10-06T19:57:03.191424517Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.202722087Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 245µs 720ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.191476367Z [3mdelta[0m[2m=[0m51µs 850ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.203180Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.24572ms [3mdelta[0m[2m=[0m51µs 850ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.203265Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m612.1506ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.318216Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.295624996Z, server: 2026-10-06T19:57:08.306819205Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.318020625Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 197µs 814ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.30682281Z [3mdelta[0m[2m=[0m4s 999ms 996µs 395ns
[INFO] [stdout] [2m2026-10-06T19:57:03.318310Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.197814ms [3mdelta[0m[2m=[0m4s 999ms 996µs 395ns
[INFO] [stdout] [2m2026-10-06T19:57:03.318334Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m574.677145ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.392857Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.380200984Z, server: 2026-10-06T19:57:08.386399204Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.392676415Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 237µs 715ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.386438699Z [3mdelta[0m[2m=[0m4s 999ms 960µs 505ns
[INFO] [stdout] [2m2026-10-06T19:57:03.392965Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.237715ms [3mdelta[0m[2m=[0m4s 999ms 960µs 505ns
[INFO] [stdout] [2m2026-10-06T19:57:03.393016Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.99779, 4999.988065, 5000.017195, 4999.960505, 5000.45855]
[INFO] [stdout] [2m2026-10-06T19:57:03.393047Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.017195 [3mmean[0m[2m=[0m5000.084421 [3mvariance[0m[2m=[0m0.04415910691754737 [3mstddev[0m[2m=[0m0.21014068363253072
[INFO] [stdout] [2m2026-10-06T19:57:03.393074Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.99779, 4999.988065, 5000.017195, 4999.960505]
[INFO] [stdout] [2m2026-10-06T19:57:03.393095Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 990µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-10-06T19:57:03.464901Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.446212664Z, server: 2026-10-06T19:57:08.455518514Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.464716544Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 251µs 940ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.455464604Z [3mdelta[0m[2m=[0m5s 53µs 910ns
[INFO] [stdout] [2m2026-10-06T19:57:03.465014Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.25194ms [3mdelta[0m[2m=[0m5s 53µs 910ns
[INFO] [stdout] [2m2026-10-06T19:57:03.465041Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m12.107014ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.498873Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.478258873Z, server: 2026-10-06T19:57:08.488462093Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.498680523Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 210µs 825ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.488469698Z [3mdelta[0m[2m=[0m4s 999ms 992µs 395ns
[INFO] [stdout] [2m2026-10-06T19:57:03.498993Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.210825ms [3mdelta[0m[2m=[0m4s 999ms 992µs 395ns
[INFO] [stdout] [2m2026-10-06T19:57:03.499022Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.891714283s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.737906Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.716246591Z, server: 2026-10-06T19:56:58.726447911Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.7376924Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 722µs 904ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.726969495Z [3mdelta[0m[2m=[0m5s 521µs 584ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.738024Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.722904ms [3mdelta[0m[2m=[0m5s 521µs 584ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.738051Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m76.840322ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.839007Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.816241689Z, server: 2026-10-06T19:57:03.827474379Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.838789279Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 273µs 795ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.827515484Z [3mdelta[0m[2m=[0m41µs 105ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.839184Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.273795ms [3mdelta[0m[2m=[0m41µs 105ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.839234Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.816449339Z, server: 2026-10-06T19:56:58.827694759Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.839008349Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 279µs 505ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.827728844Z [3mdelta[0m[2m=[0m5s 34µs 85ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.839329Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.279505ms [3mdelta[0m[2m=[0m5s 34µs 85ns ago
[INFO] [stdout] [2m2026-10-06T19:57:03.839273Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.43604942s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.839353Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m661.391853ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.899127Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.696236331Z, server: 2026-10-06T19:57:03.797589859Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.898920188Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 341µs 928ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.797578259Z [3mdelta[0m[2m=[0m11µs 600ns
[INFO] [stdout] [2m2026-10-06T19:57:03.899225Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.341928ms [3mdelta[0m[2m=[0m11µs 600ns
[INFO] [stdout] [2m2026-10-06T19:57:03.899254Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.39187202s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.916517Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.893703588Z, server: 2026-10-06T19:57:08.905010938Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.916324358Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 310µs 385ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.905013973Z [3mdelta[0m[2m=[0m4s 999ms 996µs 965ns
[INFO] [stdout] [2m2026-10-06T19:57:03.916622Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.310385ms [3mdelta[0m[2m=[0m4s 999ms 996µs 965ns
[INFO] [stdout] [2m2026-10-06T19:57:03.916646Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.586527992s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:03.942891Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:03.922244688Z, server: 2026-10-06T19:57:08.932444858Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:03.942667938Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 211µs 625ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:03.932456313Z [3mdelta[0m[2m=[0m4s 999ms 988µs 545ns
[INFO] [stdout] [2m2026-10-06T19:57:03.943000Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.211625ms [3mdelta[0m[2m=[0m4s 999ms 988µs 545ns
[INFO] [stdout] [2m2026-10-06T19:57:03.943026Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.014943116s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:04.523917Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:04.502243591Z, server: 2026-10-06T19:56:59.512471291Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:04.523692531Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 724µs 470ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:04.512968061Z [3mdelta[0m[2m=[0m5s 496µs 770ns ago
[INFO] [stdout] [2m2026-10-06T19:57:04.524117Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.72447ms [3mdelta[0m[2m=[0m5s 496µs 770ns ago
[INFO] [stdout] [2m2026-10-06T19:57:04.524250Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-5000.521584, -5000.49677, -5000.01281, -4999.98802, -5000.034085]
[INFO] [stdout] [2m2026-10-06T19:57:04.524343Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.01281 [3mmean[0m[2m=[0m-5000.2106538 [3mvariance[0m[2m=[0m0.07460614710216196 [3mstddev[0m[2m=[0m0.27314125851317655
[INFO] [stdout] [2m2026-10-06T19:57:04.524421Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-5000.01281, -4999.98802, -5000.034085]
[INFO] [stdout] [2m2026-10-06T19:57:04.524467Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 11µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-10-06T19:57:04.892644Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:04.890200326Z, server: 2026-10-06T19:57:04.891348046Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:04.892470376Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 135µs 25ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:04.891335351Z [3mdelta[0m[2m=[0m12µs 695ns
[INFO] [stdout] [2m2026-10-06T19:57:04.892722Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.135025ms [3mdelta[0m[2m=[0m12µs 695ns
[INFO] [stdout] [2m2026-10-06T19:57:04.892751Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m955.875109ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:04.922800Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:04.900213596Z, server: 2026-10-06T19:57:04.911400196Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:04.922603936Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 195µs 170ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:04.911408766Z [3mdelta[0m[2m=[0m8µs 570ns ago
[INFO] [stdout] [2m2026-10-06T19:57:04.922891Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.19517ms [3mdelta[0m[2m=[0m8µs 570ns ago
[INFO] [stdout] [2m2026-10-06T19:57:04.922915Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.820507097s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:04.978866Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:04.958311116Z, server: 2026-10-06T19:57:09.968493645Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:04.978684995Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 186µs 939ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:04.968498055Z [3mdelta[0m[2m=[0m4s 999ms 995µs 590ns
[INFO] [stdout] [2m2026-10-06T19:57:04.978956Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.186939ms [3mdelta[0m[2m=[0m4s 999ms 995µs 590ns
[INFO] [stdout] [2m2026-10-06T19:57:04.979001Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m855.029061ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:05.300431Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.277248882Z, server: 2026-10-06T19:57:05.289063412Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:05.300257061Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 504µs 89ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.288752971Z [3mdelta[0m[2m=[0m310µs 441ns
[INFO] [stdout] [2m2026-10-06T19:57:05.300518Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.504089ms [3mdelta[0m[2m=[0m310µs 441ns
[INFO] [stdout] [2m2026-10-06T19:57:05.300540Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.705057374s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:05.414900Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.39223961Z, server: 2026-10-06T19:57:10.4034541Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:05.41468268Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 221µs 535ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.403461145Z [3mdelta[0m[2m=[0m4s 999ms 992µs 955ns
[INFO] [stdout] [2m2026-10-06T19:57:05.415017Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.221535ms [3mdelta[0m[2m=[0m4s 999ms 992µs 955ns
[INFO] [stdout] [2m2026-10-06T19:57:05.415050Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.97687, 5000.05391, 4999.992395, 4999.97485, 4999.992955]
[INFO] [stdout] [2m2026-10-06T19:57:05.415080Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.992395 [3mmean[0m[2m=[0m4999.9981960000005 [3mvariance[0m[2m=[0m0.0010412508674900475 [3mstddev[0m[2m=[0m0.03226841904230896
[INFO] [stdout] [2m2026-10-06T19:57:05.415148Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.97687, 4999.992395, 4999.97485, 4999.992955]
[INFO] [stdout] [2m2026-10-06T19:57:05.415212Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 984µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-10-06T19:57:05.495108Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.292250932Z, server: 2026-10-06T19:57:05.39357617Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:05.494907529Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 328µs 298ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.39357923Z [3mdelta[0m[2m=[0m3µs 60ns ago
[INFO] [stdout] [2m2026-10-06T19:57:05.495192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.328298ms [3mdelta[0m[2m=[0m3µs 60ns ago
[INFO] [stdout] [2m2026-10-06T19:57:05.495214Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m390.408744ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:05.526721Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.504201399Z, server: 2026-10-06T19:57:10.515353049Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:05.526528759Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 163µs 680ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.515365079Z [3mdelta[0m[2m=[0m4s 999ms 987µs 970ns
[INFO] [stdout] [2m2026-10-06T19:57:05.527653Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.16368ms [3mdelta[0m[2m=[0m4s 999ms 987µs 970ns
[INFO] [stdout] [2m2026-10-06T19:57:05.527721Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m390.94813ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:05.852834Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.850379845Z, server: 2026-10-06T19:57:05.851535035Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:05.852663465Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 141µs 810ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.851521655Z [3mdelta[0m[2m=[0m13µs 380ns
[INFO] [stdout] [2m2026-10-06T19:57:05.852941Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.14181ms [3mdelta[0m[2m=[0m13µs 380ns
[INFO] [stdout] [2m2026-10-06T19:57:05.852970Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.003625, 0.012695, 0.01338, 0.01031, -0.008969]
[INFO] [stdout] [2m2026-10-06T19:57:05.853012Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.01338 [3mmean[0m[2m=[0m0.0047582 [3mvariance[0m[2m=[0m0.0001067161937 [3mstddev[0m[2m=[0m0.010330353028817553
[INFO] [stdout] [2m2026-10-06T19:57:05.853040Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.012695, 0.01338, 0.01031]
[INFO] [stdout] [2m2026-10-06T19:57:05.853056Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m12µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-10-06T19:57:05.855952Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.835293385Z, server: 2026-10-06T19:57:10.845530505Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:05.855757555Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 232µs 85ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.84552547Z [3mdelta[0m[2m=[0m5s 5µs 35ns
[INFO] [stdout] [2m2026-10-06T19:57:05.856059Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.232085ms [3mdelta[0m[2m=[0m5s 5µs 35ns
[INFO] [stdout] [2m2026-10-06T19:57:05.856096Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.99559, 4999.988545, 5000.005035, 5000.00686, 5001.67388]
[INFO] [stdout] [2m2026-10-06T19:57:05.856116Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.005035 [3mmean[0m[2m=[0m5000.333982000001 [3mvariance[0m[2m=[0m0.5610943621824952 [3mstddev[0m[2m=[0m0.7490623219615943
[INFO] [stdout] [2m2026-10-06T19:57:05.856134Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.99559, 4999.988545, 5000.005035, 5000.00686]
[INFO] [stdout] [2m2026-10-06T19:57:05.856147Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 999µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-10-06T19:57:05.942664Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.920007784Z, server: 2026-10-06T19:57:10.931205404Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:05.942477614Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 234µs 915ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.931242699Z [3mdelta[0m[2m=[0m4s 999ms 962µs 705ns
[INFO] [stdout] [2m2026-10-06T19:57:05.942761Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.234915ms [3mdelta[0m[2m=[0m4s 999ms 962µs 705ns
[INFO] [stdout] [2m2026-10-06T19:57:05.942790Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.986245, 4999.98797, 4999.996395, 4999.962705, 4999.996965]
[INFO] [stdout] [2m2026-10-06T19:57:05.942808Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.996395 [3mmean[0m[2m=[0m4999.986056 [3mvariance[0m[2m=[0m0.00019371738000324243 [3mstddev[0m[2m=[0m0.013918239112877836
[INFO] [stdout] [2m2026-10-06T19:57:05.942827Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.986245, 4999.98797, 4999.996395, 4999.996965]
[INFO] [stdout] [2m2026-10-06T19:57:05.942841Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 991µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-10-06T19:57:06.089363Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:05.887045984Z, server: 2026-10-06T19:57:05.988452673Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:06.089197662Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 75µs 839ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.988121823Z [3mdelta[0m[2m=[0m330µs 850ns
[INFO] [stdout] [2m2026-10-06T19:57:06.089443Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.075839ms [3mdelta[0m[2m=[0m330µs 850ns
[INFO] [stdout] [2m2026-10-06T19:57:06.089464Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.17268044s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:06.297198Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:04.734098578Z, server: 2026-10-06T19:57:05.515178169Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:06.297014099Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m781ms 457µs 760ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:05.515556338Z [3mdelta[0m[2m=[0m378µs 169ns ago
[INFO] [stdout] [2m2026-10-06T19:57:06.297275Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m781.45776ms [3mdelta[0m[2m=[0m378µs 169ns ago
[INFO] [stdout] [2m2026-10-06T19:57:06.297296Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m274.597907ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:06.768450Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:06.745789594Z, server: 2026-10-06T19:57:06.757062444Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:06.768252494Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 231µs 450ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:06.757021044Z [3mdelta[0m[2m=[0m41µs 400ns
[INFO] [stdout] [2m2026-10-06T19:57:06.768536Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.23145ms [3mdelta[0m[2m=[0m41µs 400ns
[INFO] [stdout] [2m2026-10-06T19:57:06.768558Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.78378618s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:07.028855Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:07.006243421Z, server: 2026-10-06T19:57:07.017460611Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:07.02868036Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 218µs 469ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:07.01746189Z [3mdelta[0m[2m=[0m1µs 279ns ago
[INFO] [stdout] [2m2026-10-06T19:57:07.028937Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.218469ms [3mdelta[0m[2m=[0m1µs 279ns ago
[INFO] [stdout] [2m2026-10-06T19:57:07.028965Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.013305, -0.001279, -0.05185, -0.041105, 0.310441]
[INFO] [stdout] [2m2026-10-06T19:57:07.029010Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.05185 [3mmean[0m[2m=[0m0.0459024 [3mvariance[0m[2m=[0m0.0225987913108 [3mstddev[0m[2m=[0m0.15032894368949715
[INFO] [stdout] [2m2026-10-06T19:57:07.029045Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.013305, -0.001279, -0.05185, -0.041105]
[INFO] [stdout] [2m2026-10-06T19:57:07.029059Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m20µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-10-06T19:57:07.465906Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:07.264002758Z, server: 2026-10-06T19:57:07.364388806Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:07.465754085Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 875µs 663ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:07.364878421Z [3mdelta[0m[2m=[0m489µs 615ns ago
[INFO] [stdout] [2m2026-10-06T19:57:07.466013Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.875663ms [3mdelta[0m[2m=[0m489µs 615ns ago
[INFO] [stdout] [2m2026-10-06T19:57:07.466043Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.489615, 0.33085, -0.00306, 0.0116, -0.029895]
[INFO] [stdout] [2m2026-10-06T19:57:07.466069Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.00306 [3mmean[0m[2m=[0m-0.036024000000000014 [3mvariance[0m[2m=[0m0.08593339061750001 [3mstddev[0m[2m=[0m0.29314397591883073
[INFO] [stdout] [2m2026-10-06T19:57:07.466086Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.00306, 0.0116, -0.029895]
[INFO] [stdout] [2m2026-10-06T19:57:07.466098Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m7µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-10-06T19:57:08.093331Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:06.573853996Z, server: 2026-10-06T19:57:07.333286827Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:08.093155047Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m759ms 650µs 525ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:07.333504521Z [3mdelta[0m[2m=[0m217µs 694ns ago
[INFO] [stdout] [2m2026-10-06T19:57:08.093425Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m759.650525ms [3mdelta[0m[2m=[0m217µs 694ns ago
[INFO] [stdout] [2m2026-10-06T19:57:08.093448Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.662218803s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:08.576728Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:08.554083852Z, server: 2026-10-06T19:57:08.565272862Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:08.576537322Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 226µs 735ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:08.565310587Z [3mdelta[0m[2m=[0m37µs 725ns ago
[INFO] [stdout] [2m2026-10-06T19:57:08.576911Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.226735ms [3mdelta[0m[2m=[0m37µs 725ns ago
[INFO] [stdout] [2m2026-10-06T19:57:08.577014Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.498085, -0.00857, -0.037725, 0.0414, -0.002245]
[INFO] [stdout] [2m2026-10-06T19:57:08.577081Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.037725 [3mmean[0m[2m=[0m-0.10104500000000001 [3mvariance[0m[2m=[0m0.050063456912500005 [3mstddev[0m[2m=[0m0.2237486467277512
[INFO] [stdout] [2m2026-10-06T19:57:08.577133Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.00857, -0.037725, 0.0414, -0.002245]
[INFO] [stdout] [2m2026-10-06T19:57:08.577199Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m1µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-10-06T19:57:11.632441Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:09.756245247Z, server: 2026-10-06T19:57:10.694339216Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:11.632236105Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m937ms 995µs 429ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:10.694240676Z [3mdelta[0m[2m=[0m98µs 540ns
[INFO] [stdout] [2m2026-10-06T19:57:11.632532Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m937.995429ms [3mdelta[0m[2m=[0m98µs 540ns
[INFO] [stdout] [2m2026-10-06T19:57:11.632554Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.169239109s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:14.487029Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:12.802392231Z, server: 2026-10-06T19:57:13.644569911Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:14.486814481Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m842ms 211µs 125ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:13.644603356Z [3mdelta[0m[2m=[0m33µs 445ns ago
[INFO] [stdout] [2m2026-10-06T19:57:14.487122Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m842.211125ms [3mdelta[0m[2m=[0m33µs 445ns ago
[INFO] [stdout] [2m2026-10-06T19:57:14.487162Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.217694, 0.07808, -0.378169, -0.033445, 0.09854]
[INFO] [stdout] [2m2026-10-06T19:57:14.487183Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.378169 [3mmean[0m[2m=[0m-0.09053760000000001 [3mvariance[0m[2m=[0m0.0415855927883 [3mstddev[0m[2m=[0m0.20392545890177616
[INFO] [stdout] [2m2026-10-06T19:57:14.487215Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.217694, -0.378169]
[INFO] [stdout] [2m2026-10-06T19:57:14.487233Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m297µs ago
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.83s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-f9c18dbe40acd213)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-10-06T19:57:14.491912Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-10-06T19:57:14.491901Z[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:57:14.491904Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:14.492006Z[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:57:14.492008Z[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:57:14.491912Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-10-06T19:57:14.492025Z[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:57:14.492036Z[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:57:14.493458Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:14.49325029Z, server: 2026-10-06T19:57:14.49326088Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:14.49326439Z[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:57:14.49325734Z [3mdelta[0m[2m=[0m3µs 540ns
[INFO] [stdout] [2m2026-10-06T19:57:14.493461Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:14.49326343Z, server: 2026-10-06T19:57:14.49326477Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:14.4932655Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1µs 35ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:14.493264465Z [3mdelta[0m[2m=[0m305ns
[INFO] [stdout] [2m2026-10-06T19:57:14.493461Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:14.49324642Z, server: 2026-10-06T19:57:19.49325519Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:14.49326448Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 30ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:14.49325545Z [3mdelta[0m[2m=[0m4s 999ms 999µs 740ns
[INFO] [stdout] [2m2026-10-06T19:57:14.493463Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:14.49324915Z, server: 2026-10-06T19:57:09.49326144Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:14.49326523Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 40ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:14.49325719Z [3mdelta[0m[2m=[0m4s 999ms 995µs 750ns ago
[INFO] [stdout] [2m2026-10-06T19:57:14.493538Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.05µs [3mdelta[0m[2m=[0m3µs 540ns
[INFO] [stdout] [2m2026-10-06T19:57:14.493539Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.035µs [3mdelta[0m[2m=[0m305ns
[INFO] [stdout] [2m2026-10-06T19:57:14.493545Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.03µs [3mdelta[0m[2m=[0m4s 999ms 999µs 740ns
[INFO] [stdout] [2m2026-10-06T19:57:14.493558Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m926.556543ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:14.493560Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.04µs [3mdelta[0m[2m=[0m4s 999ms 995µs 750ns ago
[INFO] [stdout] [2m2026-10-06T19:57:14.493567Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m28.943919ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:14.493570Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m305ns
[INFO] [stdout] [2m2026-10-06T19:57:14.493584Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m274.028022ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:14.493591Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m870.79803ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:14.523060Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:14.52285011Z, server: 2026-10-06T19:57:19.52286014Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:14.52286459Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 240ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:14.52285735Z [3mdelta[0m[2m=[0m5s 2µs 790ns
[INFO] [stdout] [2m2026-10-06T19:57:14.523148Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.24µs [3mdelta[0m[2m=[0m5s 2µs 790ns
[INFO] [stdout] [2m2026-10-06T19:57:14.523169Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.242175429s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:14.769454Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:14.769222327Z, server: 2026-10-06T19:57:09.769233607Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:14.769237627Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 650ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:14.769229977Z [3mdelta[0m[2m=[0m4s 999ms 996µs 370ns ago
[INFO] [stdout] [2m2026-10-06T19:57:14.769546Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.65µs [3mdelta[0m[2m=[0m4s 999ms 996µs 370ns ago
[INFO] [stdout] [2m2026-10-06T19:57:14.769570Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.24070579s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:15.365433Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:15.36523815Z, server: 2026-10-06T19:57:15.365249905Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:15.3652579Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 875ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:15.365248025Z [3mdelta[0m[2m=[0m1µs 880ns
[INFO] [stdout] [2m2026-10-06T19:57:15.365513Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.875µs [3mdelta[0m[2m=[0m1µs 880ns
[INFO] [stdout] [2m2026-10-06T19:57:15.365536Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m497.973135ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:15.421496Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:15.421264139Z, server: 2026-10-06T19:57:15.421278119Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:15.421282289Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 75ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:15.421273214Z [3mdelta[0m[2m=[0m4µs 905ns
[INFO] [stdout] [2m2026-10-06T19:57:15.421625Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.075µs [3mdelta[0m[2m=[0m4µs 905ns
[INFO] [stdout] [2m2026-10-06T19:57:15.421654Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.076631167s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:15.766724Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:15.766514215Z, server: 2026-10-06T19:57:20.766524745Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:15.766529625Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 705ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:15.76652192Z [3mdelta[0m[2m=[0m5s 2µs 825ns
[INFO] [stdout] [2m2026-10-06T19:57:15.766817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.705µs [3mdelta[0m[2m=[0m5s 2µs 825ns
[INFO] [stdout] [2m2026-10-06T19:57:15.766841Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.552890457s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:15.864437Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:15.864231984Z, server: 2026-10-06T19:57:15.864244229Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:15.864248494Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 255ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:15.864240239Z [3mdelta[0m[2m=[0m3µs 990ns
[INFO] [stdout] [2m2026-10-06T19:57:15.864537Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.255µs [3mdelta[0m[2m=[0m3µs 990ns
[INFO] [stdout] [2m2026-10-06T19:57:15.864567Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.470340559s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:16.011503Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:16.011295762Z, server: 2026-10-06T19:57:11.011308312Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:16.011312482Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 360ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:16.011304122Z [3mdelta[0m[2m=[0m4s 999ms 995µs 810ns ago
[INFO] [stdout] [2m2026-10-06T19:57:16.011598Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.36µs [3mdelta[0m[2m=[0m4s 999ms 995µs 810ns ago
[INFO] [stdout] [2m2026-10-06T19:57:16.011626Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m249.802809ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:16.263312Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:16.263099049Z, server: 2026-10-06T19:57:11.263113069Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:16.263117229Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 90ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:16.263108139Z [3mdelta[0m[2m=[0m4s 999ms 995µs 70ns ago
[INFO] [stdout] [2m2026-10-06T19:57:16.263415Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.09µs [3mdelta[0m[2m=[0m4s 999ms 995µs 70ns ago
[INFO] [stdout] [2m2026-10-06T19:57:16.263447Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m39.474201ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:16.304195Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:16.303962459Z, server: 2026-10-06T19:57:11.303974079Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:16.303995639Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m16µs 590ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:16.303979049Z [3mdelta[0m[2m=[0m5s 4µs 970ns ago
[INFO] [stdout] [2m2026-10-06T19:57:16.304295Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m16.59µs [3mdelta[0m[2m=[0m5s 4µs 970ns ago
[INFO] [stdout] [2m2026-10-06T19:57:16.304328Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.99637, -4999.99575, -4999.99581, -4999.99507, -5000.00497]
[INFO] [stdout] [2m2026-10-06T19:57:16.304349Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.99581 [3mmean[0m[2m=[0m-4999.997594 [3mvariance[0m[2m=[0m1.7214279999663776e-5 [3mstddev[0m[2m=[0m0.004149009520314912
[INFO] [stdout] [2m2026-10-06T19:57:16.304371Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99637, -4999.99575, -4999.99581, -4999.99507]
[INFO] [stdout] [2m2026-10-06T19:57:16.304387Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 995µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-10-06T19:57:16.499483Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:16.499272346Z, server: 2026-10-06T19:57:16.499285906Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:16.499290566Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 110ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:16.499281456Z [3mdelta[0m[2m=[0m4µs 450ns
[INFO] [stdout] [2m2026-10-06T19:57:16.499590Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.11µs [3mdelta[0m[2m=[0m4µs 450ns
[INFO] [stdout] [2m2026-10-06T19:57:16.499616Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.203483819s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:17.321522Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:17.321290786Z, server: 2026-10-06T19:57:22.321303636Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:17.321313346Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11µs 280ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:17.321302066Z [3mdelta[0m[2m=[0m5s 1µs 570ns
[INFO] [stdout] [2m2026-10-06T19:57:17.321611Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.28µs [3mdelta[0m[2m=[0m5s 1µs 570ns
[INFO] [stdout] [2m2026-10-06T19:57:17.321636Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.376650724s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:17.339498Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:17.339293446Z, server: 2026-10-06T19:57:17.339304151Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:17.339307366Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 960ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:17.339300406Z [3mdelta[0m[2m=[0m3µs 745ns
[INFO] [stdout] [2m2026-10-06T19:57:17.339595Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.96µs [3mdelta[0m[2m=[0m3µs 745ns
[INFO] [stdout] [2m2026-10-06T19:57:17.339618Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.923482026s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:17.704535Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:17.704345942Z, server: 2026-10-06T19:57:17.704356271Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:17.704359902Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 980ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:17.704352922Z [3mdelta[0m[2m=[0m3µs 349ns
[INFO] [stdout] [2m2026-10-06T19:57:17.704656Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.98µs [3mdelta[0m[2m=[0m3µs 349ns
[INFO] [stdout] [2m2026-10-06T19:57:17.704681Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m580.949372ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-10-06T19:57:18.287672Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:18.287454364Z, server: 2026-10-06T19:57:18.287465724Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:18.287470435Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 35ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:18.287462399Z [3mdelta[0m[2m=[0m3µs 325ns
[INFO] [stdout] [2m2026-10-06T19:57:18.287770Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.035µs [3mdelta[0m[2m=[0m3µs 325ns
[INFO] [stdout] [2m2026-10-06T19:57:18.287798Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.003349, 0.00354, 0.003325, 0.004905, 0.00445]
[INFO] [stdout] [2m2026-10-06T19:57:18.287819Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.003325 [3mmean[0m[2m=[0m0.0039138 [3mvariance[0m[2m=[0m5.188496999999998e-7 [3mstddev[0m[2m=[0m0.0007203122239695782
[INFO] [stdout] [2m2026-10-06T19:57:18.287851Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.003349, 0.00354, 0.003325]
[INFO] [stdout] [2m2026-10-06T19:57:18.287871Z[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:57:18.700415Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:18.699742839Z, server: 2026-10-06T19:57:23.699758479Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:18.69976191Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 535ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:18.699752374Z [3mdelta[0m[2m=[0m5s 6µs 105ns
[INFO] [stdout] [2m2026-10-06T19:57:18.700515Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.535µs [3mdelta[0m[2m=[0m5s 6µs 105ns
[INFO] [stdout] [2m2026-10-06T19:57:18.700543Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00279, 5000.002825, 4999.99974, 5000.006105, 5000.00157]
[INFO] [stdout] [2m2026-10-06T19:57:18.700574Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.99974 [3mmean[0m[2m=[0m5000.002606 [3mvariance[0m[2m=[0m5.403017500118754e-6 [3mstddev[0m[2m=[0m0.002324439179698784
[INFO] [stdout] [2m2026-10-06T19:57:18.700597Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.99974, 5000.00157]
[INFO] [stdout] [2m2026-10-06T19:57:18.700611Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-10-06T19:57:19.264204Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-10-06T19:57:19.263994643Z, server: 2026-10-06T19:57:19.264007008Z } [3mcurrent[0m[2m=[0m2026-10-06T19:57:19.264010852Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 104ns [3mlocal_at_midpoint[0m[2m=[0m2026-10-06T19:57:19.264002747Z [3mdelta[0m[2m=[0m4µs 261ns
[INFO] [stdout] [2m2026-10-06T19:57:19.264295Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.104µs [3mdelta[0m[2m=[0m4µs 261ns
[INFO] [stdout] [2m2026-10-06T19:57:19.264326Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000305, 0.003745, 0.004261, 0.00399, 0.00188]
[INFO] [stdout] [2m2026-10-06T19:57:19.264348Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.004261 [3mmean[0m[2m=[0m0.0028361999999999997 [3mvariance[0m[2m=[0m2.8771296999999997e-6 [3mstddev[0m[2m=[0m0.0016962103937896383
[INFO] [stdout] [2m2026-10-06T19:57:19.264372Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.003745, 0.004261, 0.00399]
[INFO] [stdout] [2m2026-10-06T19:57:19.264388Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.77s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[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.15s; merged doctests compilation took 1.13s
[INFO] running `Command { std: "docker" "inspect" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681", kill_on_drop: false }`
[INFO] [stdout] 320e40dd52e5973898fa7be17f0f04506b51f49c8db19e593670a0e8a290d681
