[INFO] cloning repository https://github.com/passcod/timesimp
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/passcod/timesimp" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 92be20531742c87fc283ec0ed2fc2aa3b1f638ae
[INFO] testing passcod/timesimp/92be20531742c87fc283ec0ed2fc2aa3b1f638ae against 1.97.0-beta.6 for beta-1.98-1
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-5-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-5-tc1/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-5-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 1.97.0-beta.6
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.97.0-beta.6" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate git repo https://github.com/passcod/timesimp already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.97.0-beta.6" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded windows-registry v0.4.0
[INFO] [stderr]   Downloaded signal-hook-registry v1.4.5
[INFO] [stderr]   Downloaded windows-targets v0.53.0
[INFO] [stderr]   Downloaded windows-strings v0.3.1
[INFO] [stderr]   Downloaded tokio-rustls v0.26.2
[INFO] [stderr]   Downloaded reqwest v0.12.15
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded napi-sys v3.0.0-alpha.1
[INFO] [stderr]   Downloaded ctor v0.4.2
[INFO] [stderr]   Downloaded dtor v0.0.6
[INFO] [stderr]   Downloaded dtor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded ctor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded hyper-rustls v0.27.5
[INFO] [stderr]   Downloaded miniz_oxide v0.8.5
[INFO] [stderr]   Downloaded napi-derive v3.0.0-alpha.29
[INFO] [stderr]   Downloaded napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]   Downloaded semver v1.0.26
[INFO] [stderr]   Downloaded napi-build v2.1.6
[INFO] [stderr]   Downloaded convert_case v0.8.0
[INFO] [stderr]   Downloaded rustls-pki-types v1.11.0
[INFO] [stderr]   Downloaded libloading v0.8.6
[INFO] [stderr]   Downloaded openssl-sys v0.9.107
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded rand v0.9.1
[INFO] [stderr]   Downloaded zerocopy-derive v0.8.24
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded cc v1.2.20
[INFO] [stderr]   Downloaded tokio-util v0.7.15
[INFO] [stderr]   Downloaded napi v3.0.0-alpha.33
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded portable-atomic v1.11.0
[INFO] [stderr]   Downloaded zerocopy v0.8.24
[INFO] [stderr]   Downloaded openssl v0.10.72
[INFO] [stderr]   Downloaded rustls v0.23.26
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] [stderr]   Downloaded windows_x86_64_gnullvm v0.53.0
[INFO] [stderr]   Downloaded windows_aarch64_msvc v0.53.0
[INFO] [stderr]   Downloaded windows_aarch64_gnullvm v0.53.0
[INFO] [stderr]   Downloaded rustls-webpki v0.103.1
[INFO] [stderr]   Downloaded windows_i686_gnullvm v0.53.0
[INFO] [stderr]   Downloaded windows_x86_64_msvc v0.53.0
[INFO] [stderr]   Downloaded windows_i686_msvc v0.53.0
[INFO] [stderr]   Downloaded windows_x86_64_gnu v0.53.0
[INFO] [stderr]   Downloaded windows_i686_gnu v0.53.0
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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:3d5ced03c013a94a2f102a4510f48a6e9184255caf5fd8244f58017bde7f5210" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637
[INFO] running `Command { std: "docker" "start" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637", 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" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.0-beta.6" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637", 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" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.0-beta.6" "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 napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling ryu v1.0.20
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 49.77s
[INFO] running `Command { std: "docker" "inspect" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637", 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" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.0-beta.6" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling futures-core v0.3.31
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling fnv v1.0.7
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling foreign-types-shared v0.1.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 socket2 v0.5.9
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling foreign-types v0.3.2
[INFO] [stderr]    Compiling utf8_iter v1.0.4
[INFO] [stderr]    Compiling atomic-waker v1.1.2
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling try-lock v0.2.5
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling mime v0.3.17
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 40s
[INFO] running `Command { std: "docker" "inspect" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637", 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" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637" "/opt/rustwide/cargo-home/bin/cargo" "+1.97.0-beta.6" "test" "--frozen", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.27s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-2aee66feffce539a)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::client_behind_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. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-c4bbd53b9bad2c02)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-07-10T14:33:18.047919Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:18.048018Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:18.048047Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.048046Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.048042Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:18.048059Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:18.048068Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.048076Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.048105Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:18.048130Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.047919Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-07-10T14:33:18.048199Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.048624Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:18.048653Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.048739Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-07-10T14:33:18.048758Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.051645Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049263632Z, server: 2026-07-10T14:33:18.050383402Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.051497191Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 116µs 779ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.050380411Z [3mdelta[0m[2m=[0m2µs 991ns
[INFO] [stdout] [2m2026-07-10T14:33:18.051713Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.116779ms [3mdelta[0m[2m=[0m2µs 991ns
[INFO] [stdout] [2m2026-07-10T14:33:18.051738Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m2µs 991ns
[INFO] [stdout] [2m2026-07-10T14:33:18.051753Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.159198524s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.059727Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049302042Z, server: 2026-07-10T14:33:23.054433631Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.05955427Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5ms 126µs 114ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.054428156Z [3mdelta[0m[2m=[0m5s 5µs 475ns
[INFO] [stdout] [2m2026-07-10T14:33:18.059812Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.126114ms [3mdelta[0m[2m=[0m5s 5µs 475ns
[INFO] [stdout] [2m2026-07-10T14:33:18.059835Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 5µs 475ns
[INFO] [stdout] [2m2026-07-10T14:33:18.059849Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.073559487s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.066479Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049814662Z, server: 2026-07-10T14:33:23.058148661Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.066302239Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 243µs 788ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.05805845Z [3mdelta[0m[2m=[0m5s 90µs 211ns
[INFO] [stdout] [2m2026-07-10T14:33:18.066561Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.243788ms [3mdelta[0m[2m=[0m5s 90µs 211ns
[INFO] [stdout] [2m2026-07-10T14:33:18.066583Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 90µs 211ns
[INFO] [stdout] [2m2026-07-10T14:33:18.066597Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.038717535s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.071688Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049261782Z, server: 2026-07-10T14:33:23.06038878Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.071534229Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 136µs 223ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.060398005Z [3mdelta[0m[2m=[0m4s 999ms 990µs 775ns
[INFO] [stdout] [2m2026-07-10T14:33:18.071703Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049376122Z, server: 2026-07-10T14:33:18.06048287Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.071597729Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 110µs 803ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.060486925Z [3mdelta[0m[2m=[0m4µs 55ns ago
[INFO] [stdout] [2m2026-07-10T14:33:18.071757Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.136223ms [3mdelta[0m[2m=[0m4s 999ms 990µs 775ns
[INFO] [stdout] [2m2026-07-10T14:33:18.071759Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.110803ms [3mdelta[0m[2m=[0m4µs 55ns ago
[INFO] [stdout] [2m2026-07-10T14:33:18.071775Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 990µs 775ns
[INFO] [stdout] [2m2026-07-10T14:33:18.071777Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.911847074s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.071795Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.489312764s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.073207Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049992012Z, server: 2026-07-10T14:33:13.06204729Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.073109839Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 558µs 913ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.061550925Z [3mdelta[0m[2m=[0m4s 999ms 503µs 635ns ago
[INFO] [stdout] [2m2026-07-10T14:33:18.073271Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.558913ms [3mdelta[0m[2m=[0m4s 999ms 503µs 635ns ago
[INFO] [stdout] [2m2026-07-10T14:33:18.073290Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 503µs 635ns ago
[INFO] [stdout] [2m2026-07-10T14:33:18.073309Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.946123402s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.073469Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049899362Z, server: 2026-07-10T14:33:18.06199384Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.073375628Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 738µs 133ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.061637495Z [3mdelta[0m[2m=[0m356µs 345ns
[INFO] [stdout] [2m2026-07-10T14:33:18.073529Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.738133ms [3mdelta[0m[2m=[0m356µs 345ns
[INFO] [stdout] [2m2026-07-10T14:33:18.073559Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m545.677408ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:18.641767Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.620174943Z, server: 2026-07-10T14:33:18.630441141Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:18.64161249Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 718µs 773ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.630893716Z [3mdelta[0m[2m=[0m452µs 575ns ago
[INFO] [stdout] [2m2026-07-10T14:33:18.641849Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.718773ms [3mdelta[0m[2m=[0m452µs 575ns ago
[INFO] [stdout] [2m2026-07-10T14:33:18.641872Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.563072945s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:19.127195Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:19.106159226Z, server: 2026-07-10T14:33:24.116337654Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:19.127041083Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 440µs 928ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:19.116600154Z [3mdelta[0m[2m=[0m4s 999ms 737µs 500ns
[INFO] [stdout] [2m2026-07-10T14:33:19.127273Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.440928ms [3mdelta[0m[2m=[0m4s 999ms 737µs 500ns
[INFO] [stdout] [2m2026-07-10T14:33:19.127294Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m148.729842ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:19.147803Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:19.135174032Z, server: 2026-07-10T14:33:24.141429891Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:19.14760544Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 215µs 704ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:19.141389736Z [3mdelta[0m[2m=[0m5s 40µs 155ns
[INFO] [stdout] [2m2026-07-10T14:33:19.147987Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.215704ms [3mdelta[0m[2m=[0m5s 40µs 155ns
[INFO] [stdout] [2m2026-07-10T14:33:19.148079Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.821660876s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:19.213534Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:19.211156981Z, server: 2026-07-10T14:33:19.212281321Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:19.213388901Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 115µs 960ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:19.212272941Z [3mdelta[0m[2m=[0m8µs 380ns
[INFO] [stdout] [2m2026-07-10T14:33:19.213611Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.11596ms [3mdelta[0m[2m=[0m8µs 380ns
[INFO] [stdout] [2m2026-07-10T14:33:19.213630Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.520070257s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:19.293691Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:19.277167912Z, server: 2026-07-10T14:33:24.285348331Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:19.29352998Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 181µs 34ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:19.285348946Z [3mdelta[0m[2m=[0m4s 999ms 999µs 385ns
[INFO] [stdout] [2m2026-07-10T14:33:19.293778Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.181034ms [3mdelta[0m[2m=[0m4s 999ms 999µs 385ns
[INFO] [stdout] [2m2026-07-10T14:33:19.293804Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m668.098657ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:19.584756Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:19.562252573Z, server: 2026-07-10T14:33:24.573434931Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:19.58460898Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 178µs 203ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:19.573430776Z [3mdelta[0m[2m=[0m5s 4µs 155ns
[INFO] [stdout] [2m2026-07-10T14:33:19.584834Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.178203ms [3mdelta[0m[2m=[0m5s 4µs 155ns
[INFO] [stdout] [2m2026-07-10T14:33:19.584853Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m660.919239ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:19.767360Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:18.049337812Z, server: 2026-07-10T14:33:18.908156883Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:19.767174085Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m858ms 918µs 136ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:18.908255948Z [3mdelta[0m[2m=[0m99µs 65ns ago
[INFO] [stdout] [2m2026-07-10T14:33:19.767445Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m858.918136ms [3mdelta[0m[2m=[0m99µs 65ns ago
[INFO] [stdout] [2m2026-07-10T14:33:19.767466Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m99µs 65ns ago
[INFO] [stdout] [2m2026-07-10T14:33:19.767481Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.65373399s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:19.977413Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:19.962176938Z, server: 2026-07-10T14:33:24.970119386Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:19.977271965Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 547µs 513ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:19.969724451Z [3mdelta[0m[2m=[0m5s 394µs 935ns
[INFO] [stdout] [2m2026-07-10T14:33:19.977489Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.547513ms [3mdelta[0m[2m=[0m5s 394µs 935ns
[INFO] [stdout] [2m2026-07-10T14:33:19.977510Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.689523813s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:20.010365Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:19.985152875Z, server: 2026-07-10T14:33:19.999033553Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:20.010208401Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 527µs 763ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:19.997680638Z [3mdelta[0m[2m=[0m1ms 352µs 915ns
[INFO] [stdout] [2m2026-07-10T14:33:20.010522Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.527763ms [3mdelta[0m[2m=[0m1ms 352µs 915ns
[INFO] [stdout] [2m2026-07-10T14:33:20.010590Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.207321429s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:20.047212Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:20.023043239Z, server: 2026-07-10T14:33:15.034345678Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:20.047050886Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 3µs 823ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:20.035047062Z [3mdelta[0m[2m=[0m5s 701µs 384ns ago
[INFO] [stdout] [2m2026-07-10T14:33:20.047303Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.003823ms [3mdelta[0m[2m=[0m5s 701µs 384ns ago
[INFO] [stdout] [2m2026-07-10T14:33:20.047328Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.4090452s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:20.258308Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:20.23306618Z, server: 2026-07-10T14:33:20.247034228Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:20.258166307Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 550µs 63ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:20.245616243Z [3mdelta[0m[2m=[0m1ms 417µs 985ns
[INFO] [stdout] [2m2026-07-10T14:33:20.258386Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.550063ms [3mdelta[0m[2m=[0m1ms 417µs 985ns
[INFO] [stdout] [2m2026-07-10T14:33:20.258406Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m438.894492ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:20.268343Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:20.247825308Z, server: 2026-07-10T14:33:25.258008687Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:20.268184525Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 179µs 608ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:20.258004916Z [3mdelta[0m[2m=[0m5s 3µs 771ns
[INFO] [stdout] [2m2026-07-10T14:33:20.268428Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.179608ms [3mdelta[0m[2m=[0m5s 3µs 771ns
[INFO] [stdout] [2m2026-07-10T14:33:20.268453Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.468102604s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:20.721548Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:20.699037116Z, server: 2026-07-10T14:33:20.710209594Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:20.721389093Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 175µs 988ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:20.710213104Z [3mdelta[0m[2m=[0m3µs 510ns ago
[INFO] [stdout] [2m2026-07-10T14:33:20.721636Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.175988ms [3mdelta[0m[2m=[0m3µs 510ns ago
[INFO] [stdout] [2m2026-07-10T14:33:20.721659Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m397.148281ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:20.739283Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:20.735040701Z, server: 2026-07-10T14:33:20.73800424Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:20.73912655Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2ms 42µs 924ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:20.737083625Z [3mdelta[0m[2m=[0m920µs 615ns
[INFO] [stdout] [2m2026-07-10T14:33:20.739371Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.042924ms [3mdelta[0m[2m=[0m920µs 615ns
[INFO] [stdout] [2m2026-07-10T14:33:20.739393Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.988547723s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:20.986540Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:20.972044508Z, server: 2026-07-10T14:33:25.979219797Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:20.986387446Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 171µs 469ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:20.979215977Z [3mdelta[0m[2m=[0m5s 3µs 820ns
[INFO] [stdout] [2m2026-07-10T14:33:20.986804Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.171469ms [3mdelta[0m[2m=[0m5s 3µs 820ns
[INFO] [stdout] [2m2026-07-10T14:33:20.986869Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m332.478139ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.141748Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.120249518Z, server: 2026-07-10T14:33:21.130425976Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.141599445Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 674µs 963ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.130924481Z [3mdelta[0m[2m=[0m498µs 505ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.141836Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.674963ms [3mdelta[0m[2m=[0m498µs 505ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.141864Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.498505, -0.452575, -0.00351, 0.356345, 1.417985]
[INFO] [stdout] [2m2026-07-10T14:33:21.141881Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.00351 [3mmean[0m[2m=[0m0.16394800000000004 [3mvariance[0m[2m=[0m0.61415304287 [3mstddev[0m[2m=[0m0.7836791708792572
[INFO] [stdout] [2m2026-07-10T14:33:21.141899Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.498505, -0.452575, -0.00351, 0.356345]
[INFO] [stdout] [2m2026-07-10T14:33:21.141911Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m149µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-07-10T14:33:21.142415Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:21.142480Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.166206Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.143683164Z, server: 2026-07-10T14:33:26.154854453Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.166032321Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 174µs 578ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.154857742Z [3mdelta[0m[2m=[0m4s 999ms 996µs 711ns
[INFO] [stdout] [2m2026-07-10T14:33:21.166361Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.174578ms [3mdelta[0m[2m=[0m4s 999ms 996µs 711ns
[INFO] [stdout] [2m2026-07-10T14:33:21.166412Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 996µs 711ns
[INFO] [stdout] [2m2026-07-10T14:33:21.166462Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.414906147s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.243184Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.219162854Z, server: 2026-07-10T14:33:21.230404683Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.243034461Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 935µs 803ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.231098657Z [3mdelta[0m[2m=[0m693µs 974ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.243258Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.935803ms [3mdelta[0m[2m=[0m693µs 974ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.243277Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.151921832s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.343784Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.32328718Z, server: 2026-07-10T14:33:26.333461598Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.343635837Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 174µs 328ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.333461508Z [3mdelta[0m[2m=[0m5s 90ns
[INFO] [stdout] [2m2026-07-10T14:33:21.343860Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.174328ms [3mdelta[0m[2m=[0m5s 90ns
[INFO] [stdout] [2m2026-07-10T14:33:21.343879Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m869.949896ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.479709Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.457183851Z, server: 2026-07-10T14:33:16.46836616Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.479551778Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 183µs 963ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.468367814Z [3mdelta[0m[2m=[0m5s 1µs 654ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.479793Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.183963ms [3mdelta[0m[2m=[0m5s 1µs 654ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.479815Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.302426743s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.681698Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.668200152Z, server: 2026-07-10T14:33:26.674372241Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.68154377Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 671µs 809ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.674871961Z [3mdelta[0m[2m=[0m4s 999ms 500µs 280ns
[INFO] [stdout] [2m2026-07-10T14:33:21.681780Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.671809ms [3mdelta[0m[2m=[0m4s 999ms 500µs 280ns
[INFO] [stdout] [2m2026-07-10T14:33:21.681814Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.50028, 5000.394935, 4999.999385, 5000.090211, 4999.7375]
[INFO] [stdout] [2m2026-07-10T14:33:21.681833Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.999385 [3mmean[0m[2m=[0m4999.944462199999 [3mvariance[0m[2m=[0m0.11682903730667679 [3mstddev[0m[2m=[0m0.3418026291687599
[INFO] [stdout] [2m2026-07-10T14:33:21.681855Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.999385, 5000.090211, 4999.7375]
[INFO] [stdout] [2m2026-07-10T14:33:21.681868Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 942µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-07-10T14:33:21.682302Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:21.682335Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.759811Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.737307602Z, server: 2026-07-10T14:33:26.748488841Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.759660879Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 176µs 638ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.74848424Z [3mdelta[0m[2m=[0m5s 4µs 601ns
[INFO] [stdout] [2m2026-07-10T14:33:21.759888Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.176638ms [3mdelta[0m[2m=[0m5s 4µs 601ns
[INFO] [stdout] [2m2026-07-10T14:33:21.759908Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.796650515s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:21.886336Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.68350318Z, server: 2026-07-10T14:33:21.784807886Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:21.886168032Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 332µs 426ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:21.784835606Z [3mdelta[0m[2m=[0m27µs 720ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.886422Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.332426ms [3mdelta[0m[2m=[0m27µs 720ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.886444Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m27µs 720ns ago
[INFO] [stdout] [2m2026-07-10T14:33:21.886457Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m727.568151ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:22.232787Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:22.214274627Z, server: 2026-07-10T14:33:27.223460005Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:22.232636554Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 180µs 963ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:22.22345559Z [3mdelta[0m[2m=[0m5s 4µs 415ns
[INFO] [stdout] [2m2026-07-10T14:33:22.232865Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.180963ms [3mdelta[0m[2m=[0m5s 4µs 415ns
[INFO] [stdout] [2m2026-07-10T14:33:22.232890Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.005475, 5000.040155, 5000.00382, 5000.004415, 5000.00009]
[INFO] [stdout] [2m2026-07-10T14:33:22.232913Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00382 [3mmean[0m[2m=[0m5000.010791000001 [3mvariance[0m[2m=[0m0.00027356599249726057 [3mstddev[0m[2m=[0m0.016539830485747444
[INFO] [stdout] [2m2026-07-10T14:33:22.232936Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.005475, 5000.00382, 5000.004415, 5000.00009]
[INFO] [stdout] [2m2026-07-10T14:33:22.232984Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 3µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-07-10T14:33:22.419081Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:22.396410362Z, server: 2026-07-10T14:33:22.4077153Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:22.418895588Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 242µs 613ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:22.407652975Z [3mdelta[0m[2m=[0m62µs 325ns
[INFO] [stdout] [2m2026-07-10T14:33:22.419169Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.242613ms [3mdelta[0m[2m=[0m62µs 325ns
[INFO] [stdout] [2m2026-07-10T14:33:22.419192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.063784734s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:22.605680Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:22.583166536Z, server: 2026-07-10T14:33:27.594345764Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:22.605523183Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 178µs 323ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:22.594344859Z [3mdelta[0m[2m=[0m5s 905ns
[INFO] [stdout] [2m2026-07-10T14:33:22.605767Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.178323ms [3mdelta[0m[2m=[0m5s 905ns
[INFO] [stdout] [2m2026-07-10T14:33:22.605799Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.780048044s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:22.730138Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:22.728821076Z, server: 2026-07-10T14:33:22.729944805Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:22.729990905Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m584µs 914ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:22.72940599Z [3mdelta[0m[2m=[0m538µs 815ns
[INFO] [stdout] [2m2026-07-10T14:33:22.730488Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m584.914µs [3mdelta[0m[2m=[0m538µs 815ns
[INFO] [stdout] [2m2026-07-10T14:33:22.730566Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.873434044s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:22.805373Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:22.782795868Z, server: 2026-07-10T14:33:17.794043317Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:22.805224015Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 214µs 73ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:22.794009941Z [3mdelta[0m[2m=[0m4s 999ms 966µs 624ns ago
[INFO] [stdout] [2m2026-07-10T14:33:22.805458Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.214073ms [3mdelta[0m[2m=[0m4s 999ms 966µs 624ns ago
[INFO] [stdout] [2m2026-07-10T14:33:22.805481Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.32177959s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:22.818866Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:22.617042201Z, server: 2026-07-10T14:33:22.717382217Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:22.818700003Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 828µs 901ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:22.717871102Z [3mdelta[0m[2m=[0m488µs 885ns ago
[INFO] [stdout] [2m2026-07-10T14:33:22.818973Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.828901ms [3mdelta[0m[2m=[0m488µs 885ns ago
[INFO] [stdout] [2m2026-07-10T14:33:22.818997Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.558317442s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:23.120196Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:21.428049845Z, server: 2026-07-10T14:33:22.273939718Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:23.120029371Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m845ms 989µs 763ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:22.274039608Z [3mdelta[0m[2m=[0m99µs 890ns ago
[INFO] [stdout] [2m2026-07-10T14:33:23.120367Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m845.989763ms [3mdelta[0m[2m=[0m99µs 890ns ago
[INFO] [stdout] [2m2026-07-10T14:33:23.120388Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m766.660276ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:23.506814Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:23.484182781Z, server: 2026-07-10T14:33:23.49546868Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:23.506645748Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 231µs 483ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:23.495414264Z [3mdelta[0m[2m=[0m54µs 416ns
[INFO] [stdout] [2m2026-07-10T14:33:23.506897Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.231483ms [3mdelta[0m[2m=[0m54µs 416ns
[INFO] [stdout] [2m2026-07-10T14:33:23.506925Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.004055, 0.054416, 0.062325, -0.693974, 1.352915]
[INFO] [stdout] [2m2026-07-10T14:33:23.506944Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.062325 [3mmean[0m[2m=[0m0.1543254 [3mvariance[0m[2m=[0m0.5499398035453 [3mstddev[0m[2m=[0m0.7415792631575535
[INFO] [stdout] [2m2026-07-10T14:33:23.507085Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.004055, 0.054416, 0.062325]
[INFO] [stdout] [2m2026-07-10T14:33:23.507101Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m37µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-07-10T14:33:23.577647Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:23.557141141Z, server: 2026-07-10T14:33:28.56731036Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:23.577488868Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 173µs 863ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:23.567315004Z [3mdelta[0m[2m=[0m4s 999ms 995µs 356ns
[INFO] [stdout] [2m2026-07-10T14:33:23.577735Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.173863ms [3mdelta[0m[2m=[0m4s 999ms 995µs 356ns
[INFO] [stdout] [2m2026-07-10T14:33:23.577764Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.995356, 5000.003771, 4999.990775, 5000.004601, 5000.004155]
[INFO] [stdout] [2m2026-07-10T14:33:23.577783Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.990775 [3mmean[0m[2m=[0m4999.999731599999 [3mvariance[0m[2m=[0m3.974020879593525e-5 [3mstddev[0m[2m=[0m0.006303983565646031
[INFO] [stdout] [2m2026-07-10T14:33:23.577805Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.995356, 4999.990775]
[INFO] [stdout] [2m2026-07-10T14:33:23.577816Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 993µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-07-10T14:33:24.150799Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:24.128178312Z, server: 2026-07-10T14:33:19.139450301Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:24.150631909Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 226µs 798ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:24.13940511Z [3mdelta[0m[2m=[0m4s 999ms 954µs 809ns ago
[INFO] [stdout] [2m2026-07-10T14:33:24.150884Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.226798ms [3mdelta[0m[2m=[0m4s 999ms 954µs 809ns ago
[INFO] [stdout] [2m2026-07-10T14:33:24.150912Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-5000.001654, -4999.966624, -4999.954809, -4999.503635, -5000.701384]
[INFO] [stdout] [2m2026-07-10T14:33:24.150930Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.954809 [3mmean[0m[2m=[0m-5000.0256212 [3mvariance[0m[2m=[0m0.18454860470169765 [3mstddev[0m[2m=[0m0.4295912064995019
[INFO] [stdout] [2m2026-07-10T14:33:24.150967Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-5000.001654, -4999.966624, -4999.954809]
[INFO] [stdout] [2m2026-07-10T14:33:24.150986Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 974µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-07-10T14:33:24.409734Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:24.387138827Z, server: 2026-07-10T14:33:29.398310105Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:24.409572184Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 216µs 678ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:24.398355505Z [3mdelta[0m[2m=[0m4s 999ms 954µs 600ns
[INFO] [stdout] [2m2026-07-10T14:33:24.409828Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.216678ms [3mdelta[0m[2m=[0m4s 999ms 954µs 600ns
[INFO] [stdout] [2m2026-07-10T14:33:24.409851Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m818.802288ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:24.584327Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:24.381038808Z, server: 2026-07-10T14:33:24.482346714Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:24.584160529Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 560µs 860ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:24.482599668Z [3mdelta[0m[2m=[0m252µs 954ns ago
[INFO] [stdout] [2m2026-07-10T14:33:24.584414Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.56086ms [3mdelta[0m[2m=[0m252µs 954ns ago
[INFO] [stdout] [2m2026-07-10T14:33:24.584436Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.252723595s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:24.608130Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:24.605715986Z, server: 2026-07-10T14:33:24.606845256Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:24.607974336Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 129µs 175ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:24.606845161Z [3mdelta[0m[2m=[0m95ns
[INFO] [stdout] [2m2026-07-10T14:33:24.608206Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.129175ms [3mdelta[0m[2m=[0m95ns
[INFO] [stdout] [2m2026-07-10T14:33:24.608301Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.538815, 0.00838, 0.002991, 9.5e-5, 0.920615]
[INFO] [stdout] [2m2026-07-10T14:33:24.608367Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.002991 [3mmean[0m[2m=[0m0.2941792 [3mvariance[0m[2m=[0m0.17630643834819998 [3mstddev[0m[2m=[0m0.4198886023080407
[INFO] [stdout] [2m2026-07-10T14:33:24.608389Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00838, 0.002991, 9.5e-5]
[INFO] [stdout] [2m2026-07-10T14:33:24.608401Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-07-10T14:33:25.251858Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:25.23015993Z, server: 2026-07-10T14:33:30.240444939Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:25.251660617Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 750µs 343ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:25.240910273Z [3mdelta[0m[2m=[0m4s 999ms 534µs 666ns
[INFO] [stdout] [2m2026-07-10T14:33:25.251987Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.750343ms [3mdelta[0m[2m=[0m4s 999ms 534µs 666ns
[INFO] [stdout] [2m2026-07-10T14:33:25.252017Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m188.350027ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:25.467539Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:25.44504037Z, server: 2026-07-10T14:33:30.456208029Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:25.467380878Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 170µs 254ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:25.456210624Z [3mdelta[0m[2m=[0m4s 999ms 997µs 405ns
[INFO] [stdout] [2m2026-07-10T14:33:25.467620Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.170254ms [3mdelta[0m[2m=[0m4s 999ms 997µs 405ns
[INFO] [stdout] [2m2026-07-10T14:33:25.467670Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.534666, 4999.997405, 4999.996711, 5000.000905, 4999.9546]
[INFO] [stdout] [2m2026-07-10T14:33:25.467689Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.996711 [3mmean[0m[2m=[0m4999.8968574 [3mvariance[0m[2m=[0m0.04135582061336631 [3mstddev[0m[2m=[0m0.20336130559515572
[INFO] [stdout] [2m2026-07-10T14:33:25.467708Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.997405, 4999.996711, 5000.000905, 4999.9546]
[INFO] [stdout] [2m2026-07-10T14:33:25.467721Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 987µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-07-10T14:33:25.634388Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:23.889295395Z, server: 2026-07-10T14:33:24.762189725Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:25.634239055Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m872ms 471µs 830ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:24.761767225Z [3mdelta[0m[2m=[0m422µs 500ns
[INFO] [stdout] [2m2026-07-10T14:33:25.634465Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m872.47183ms [3mdelta[0m[2m=[0m422µs 500ns
[INFO] [stdout] [2m2026-07-10T14:33:25.634486Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m9.562099ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:26.040058Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:25.838210896Z, server: 2026-07-10T14:33:25.938527782Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:26.039870588Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 829µs 846ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:25.939040742Z [3mdelta[0m[2m=[0m512µs 960ns ago
[INFO] [stdout] [2m2026-07-10T14:33:26.040165Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.829846ms [3mdelta[0m[2m=[0m512µs 960ns ago
[INFO] [stdout] [2m2026-07-10T14:33:26.040190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.533559572s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:27.096186Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:25.645668963Z, server: 2026-07-10T14:33:26.371052553Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:27.096020543Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m725ms 175µs 790ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:26.370844753Z [3mdelta[0m[2m=[0m207µs 800ns
[INFO] [stdout] [2m2026-07-10T14:33:27.096272Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m725.17579ms [3mdelta[0m[2m=[0m207µs 800ns
[INFO] [stdout] [2m2026-07-10T14:33:27.096295Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.028871174s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:27.776638Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:27.575151107Z, server: 2026-07-10T14:33:27.676154593Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:27.776485619Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 667µs 256ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:27.675818363Z [3mdelta[0m[2m=[0m336µs 230ns
[INFO] [stdout] [2m2026-07-10T14:33:27.776722Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.667256ms [3mdelta[0m[2m=[0m336µs 230ns
[INFO] [stdout] [2m2026-07-10T14:33:27.776748Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.33623, -0.488885, -0.51296, -0.02772, -0.252954]
[INFO] [stdout] [2m2026-07-10T14:33:27.776765Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.51296 [3mmean[0m[2m=[0m-0.1892578 [3mvariance[0m[2m=[0m0.12521216698419996 [3mstddev[0m[2m=[0m0.35385331280659216
[INFO] [stdout] [2m2026-07-10T14:33:27.776784Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.488885, -0.51296, -0.252954]
[INFO] [stdout] [2m2026-07-10T14:33:27.776796Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m418µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-07-10T14:33:29.812505Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:28.12631679Z, server: 2026-07-10T14:33:28.969355014Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:29.812253988Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m842ms 968µs 599ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:28.969285389Z [3mdelta[0m[2m=[0m69µs 625ns
[INFO] [stdout] [2m2026-07-10T14:33:29.812593Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m842.968599ms [3mdelta[0m[2m=[0m69µs 625ns
[INFO] [stdout] [2m2026-07-10T14:33:29.812621Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.2078, 0.069625, -0.09989, -0.099065, 0.4225]
[INFO] [stdout] [2m2026-07-10T14:33:29.812639Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.09989 [3mmean[0m[2m=[0m0.100194 [3mvariance[0m[2m=[0m0.049033107192499994 [3mstddev[0m[2m=[0m0.22143420510955392
[INFO] [stdout] [2m2026-07-10T14:33:29.812675Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.069625, -0.09989, -0.099065]
[INFO] [stdout] [2m2026-07-10T14:33:29.812699Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m43µ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 11.77s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-405f21f178b7074c)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-07-10T14:33:29.831476Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-07-10T14:33:29.831612Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:29.833054Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:29.833094Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:29.831480Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-07-10T14:33:29.833987Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:29.834132Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-07-10T14:33:29.834165Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:29.834340Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:29.834134244Z, server: 2026-07-10T14:33:24.834147695Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:29.834150944Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 350ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:29.834142594Z [3mdelta[0m[2m=[0m4s 999ms 994µs 899ns ago
[INFO] [stdout] [2m2026-07-10T14:33:29.834453Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.35µs [3mdelta[0m[2m=[0m4s 999ms 994µs 899ns ago
[INFO] [stdout] [2m2026-07-10T14:33:29.834478Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.043326687s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:29.835281Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:29.835184715Z, server: 2026-07-10T14:33:29.835187324Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:29.835189075Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 180ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:29.835186895Z [3mdelta[0m[2m=[0m429ns
[INFO] [stdout] [2m2026-07-10T14:33:29.835340Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.18µs [3mdelta[0m[2m=[0m429ns
[INFO] [stdout] [2m2026-07-10T14:33:29.835358Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.025461059s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:29.839002Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:29.838875714Z, server: 2026-07-10T14:33:29.838879324Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:29.838881284Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 785ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:29.838878499Z [3mdelta[0m[2m=[0m825ns
[INFO] [stdout] [2m2026-07-10T14:33:29.839068Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.785µs [3mdelta[0m[2m=[0m825ns
[INFO] [stdout] [2m2026-07-10T14:33:29.839095Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m825ns
[INFO] [stdout] [2m2026-07-10T14:33:29.839115Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.221836507s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:29.840214Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:29.840031844Z, server: 2026-07-10T14:33:34.840034554Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:29.840041344Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4µs 750ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:29.840036594Z [3mdelta[0m[2m=[0m4s 999ms 997µs 960ns
[INFO] [stdout] [2m2026-07-10T14:33:29.840275Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.75µs [3mdelta[0m[2m=[0m4s 999ms 997µs 960ns
[INFO] [stdout] [2m2026-07-10T14:33:29.840292Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m513.84872ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:30.356356Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:30.356192243Z, server: 2026-07-10T14:33:35.356201243Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:30.356204663Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 210ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:30.356198453Z [3mdelta[0m[2m=[0m5s 2µs 790ns
[INFO] [stdout] [2m2026-07-10T14:33:30.356440Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.21µs [3mdelta[0m[2m=[0m5s 2µs 790ns
[INFO] [stdout] [2m2026-07-10T14:33:30.356461Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m372.290157ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:30.730202Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:30.730046351Z, server: 2026-07-10T14:33:35.730055881Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:30.730059091Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 370ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:30.730052721Z [3mdelta[0m[2m=[0m5s 3µs 160ns
[INFO] [stdout] [2m2026-07-10T14:33:30.730282Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.37µs [3mdelta[0m[2m=[0m5s 3µs 160ns
[INFO] [stdout] [2m2026-07-10T14:33:30.730302Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m160.56687ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:30.862364Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:30.862199653Z, server: 2026-07-10T14:33:30.862209013Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:30.862213133Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 740ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:30.862206393Z [3mdelta[0m[2m=[0m2µs 620ns
[INFO] [stdout] [2m2026-07-10T14:33:30.862447Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.74µs [3mdelta[0m[2m=[0m2µs 620ns
[INFO] [stdout] [2m2026-07-10T14:33:30.862467Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.069338548s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:30.880346Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:30.88014479Z, server: 2026-07-10T14:33:25.88015461Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:30.88015831Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 760ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:30.88015155Z [3mdelta[0m[2m=[0m4s 999ms 996µs 940ns ago
[INFO] [stdout] [2m2026-07-10T14:33:30.880505Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.76µs [3mdelta[0m[2m=[0m4s 999ms 996µs 940ns ago
[INFO] [stdout] [2m2026-07-10T14:33:30.880547Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.886547013s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:30.891985Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:30.891801178Z, server: 2026-07-10T14:33:35.891810249Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:30.891814018Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 420ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:30.891807598Z [3mdelta[0m[2m=[0m5s 2µs 651ns
[INFO] [stdout] [2m2026-07-10T14:33:30.892082Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.42µs [3mdelta[0m[2m=[0m5s 2µs 651ns
[INFO] [stdout] [2m2026-07-10T14:33:30.892107Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.652045613s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:31.061337Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:31.061172825Z, server: 2026-07-10T14:33:31.06118364Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:31.061186125Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 650ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:31.061179475Z [3mdelta[0m[2m=[0m4µs 165ns
[INFO] [stdout] [2m2026-07-10T14:33:31.061425Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.65µs [3mdelta[0m[2m=[0m4µs 165ns
[INFO] [stdout] [2m2026-07-10T14:33:31.061447Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.333399616s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:31.933349Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:31.933179825Z, server: 2026-07-10T14:33:31.933189115Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:31.933193075Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 625ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:31.93318645Z [3mdelta[0m[2m=[0m2µs 665ns
[INFO] [stdout] [2m2026-07-10T14:33:31.933439Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.625µs [3mdelta[0m[2m=[0m2µs 665ns
[INFO] [stdout] [2m2026-07-10T14:33:31.933460Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m485.085474ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:32.395266Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:32.395103761Z, server: 2026-07-10T14:33:32.395113646Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:32.395116501Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 370ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:32.395110131Z [3mdelta[0m[2m=[0m3µs 515ns
[INFO] [stdout] [2m2026-07-10T14:33:32.395357Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.37µs [3mdelta[0m[2m=[0m3µs 515ns
[INFO] [stdout] [2m2026-07-10T14:33:32.395381Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.823635782s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:32.420331Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:32.420168518Z, server: 2026-07-10T14:33:32.420178558Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:32.420181758Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 620ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:32.420175138Z [3mdelta[0m[2m=[0m3µs 420ns
[INFO] [stdout] [2m2026-07-10T14:33:32.420415Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.62µs [3mdelta[0m[2m=[0m3µs 420ns
[INFO] [stdout] [2m2026-07-10T14:33:32.420435Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.516220849s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:32.548228Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:32.54806517Z, server: 2026-07-10T14:33:37.54807491Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:32.54807826Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 545ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:32.548071715Z [3mdelta[0m[2m=[0m5s 3µs 195ns
[INFO] [stdout] [2m2026-07-10T14:33:32.548315Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.545µs [3mdelta[0m[2m=[0m5s 3µs 195ns
[INFO] [stdout] [2m2026-07-10T14:33:32.548345Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.99796, 5000.00279, 5000.00316, 5000.002651, 5000.003195]
[INFO] [stdout] [2m2026-07-10T14:33:32.548365Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00316 [3mmean[0m[2m=[0m5000.0019512 [3mvariance[0m[2m=[0m5.032804700618087e-6 [3mstddev[0m[2m=[0m0.0022433913391599974
[INFO] [stdout] [2m2026-07-10T14:33:32.548423Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00279, 5000.00316, 5000.002651, 5000.003195]
[INFO] [stdout] [2m2026-07-10T14:33:32.548465Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-07-10T14:33:32.770194Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:32.770040469Z, server: 2026-07-10T14:33:27.770049729Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:32.770053119Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 325ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:32.770046794Z [3mdelta[0m[2m=[0m4s 999ms 997µs 65ns ago
[INFO] [stdout] [2m2026-07-10T14:33:32.770273Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.325µs [3mdelta[0m[2m=[0m4s 999ms 997µs 65ns ago
[INFO] [stdout] [2m2026-07-10T14:33:32.770293Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m199.455154ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:32.970910Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:32.970744062Z, server: 2026-07-10T14:33:27.970752551Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:32.970756211Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 74ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:32.970750136Z [3mdelta[0m[2m=[0m4s 999ms 997µs 585ns ago
[INFO] [stdout] [2m2026-07-10T14:33:32.971012Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.074µs [3mdelta[0m[2m=[0m4s 999ms 997µs 585ns ago
[INFO] [stdout] [2m2026-07-10T14:33:32.971035Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.16704075s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-07-10T14:33:33.938316Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:33.938153848Z, server: 2026-07-10T14:33:33.938163018Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:33.938166198Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 175ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:33.938160023Z [3mdelta[0m[2m=[0m2µs 995ns
[INFO] [stdout] [2m2026-07-10T14:33:33.938403Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.175µs [3mdelta[0m[2m=[0m2µs 995ns
[INFO] [stdout] [2m2026-07-10T14:33:33.938429Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000429, 0.002995, 0.00342, 0.002665, 0.00262]
[INFO] [stdout] [2m2026-07-10T14:33:33.938447Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00342 [3mmean[0m[2m=[0m0.0024258 [3mvariance[0m[2m=[0m1.3486407e-6 [3mstddev[0m[2m=[0m0.0011613099069585173
[INFO] [stdout] [2m2026-07-10T14:33:33.938467Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.002995, 0.00342, 0.002665, 0.00262]
[INFO] [stdout] [2m2026-07-10T14:33:33.938480Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m2µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] [2m2026-07-10T14:33:34.139334Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:34.13917869Z, server: 2026-07-10T14:33:29.13918742Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:34.13919083Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 70ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:34.13918476Z [3mdelta[0m[2m=[0m4s 999ms 997µs 340ns ago
[INFO] [stdout] [2m2026-07-10T14:33:34.139416Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.07µs [3mdelta[0m[2m=[0m4s 999ms 997µs 340ns ago
[INFO] [stdout] [2m2026-07-10T14:33:34.139441Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.99734, -4999.997585, -4999.997065, -4999.99694, -4999.994899]
[INFO] [stdout] [2m2026-07-10T14:33:34.139464Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.997065 [3mmean[0m[2m=[0m-4999.9967658000005 [3mvariance[0m[2m=[0m1.1514006996915433e-6 [3mstddev[0m[2m=[0m0.0010730334103333146
[INFO] [stdout] [2m2026-07-10T14:33:34.139493Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99734, -4999.997585, -4999.997065, -4999.99694]
[INFO] [stdout] [2m2026-07-10T14:33:34.139515Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-07-10T14:33:34.220660Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:34.220508599Z, server: 2026-07-10T14:33:34.220518164Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:34.220520949Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 175ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:34.220514774Z [3mdelta[0m[2m=[0m3µs 390ns
[INFO] [stdout] [2m2026-07-10T14:33:34.220741Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.175µs [3mdelta[0m[2m=[0m3µs 390ns
[INFO] [stdout] [2m2026-07-10T14:33:34.220761Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m900.92477ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-e945ddf2a2af16be)
[INFO] [stdout] [2m2026-07-10T14:33:35.122319Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-07-10T14:33:35.122160854Z, server: 2026-07-10T14:33:35.122170529Z } [3mcurrent[0m[2m=[0m2026-07-10T14:33:35.122173984Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 565ns [3mlocal_at_midpoint[0m[2m=[0m2026-07-10T14:33:35.122167419Z [3mdelta[0m[2m=[0m3µs 110ns
[INFO] [stdout] [2m2026-07-10T14:33:35.122402Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.565µs [3mdelta[0m[2m=[0m3µs 110ns
[INFO] [stdout] [2m2026-07-10T14:33:35.122428Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.000825, 0.00339, 0.003515, 0.00311, 0.004165]
[INFO] [stdout] [2m2026-07-10T14:33:35.122447Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.003515 [3mmean[0m[2m=[0m0.0030009999999999998 [3mvariance[0m[2m=[0m1.6293175000000002e-6 [3mstddev[0m[2m=[0m0.0012764472178668415
[INFO] [stdout] [2m2026-07-10T14:33:35.122468Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00339, 0.003515, 0.00311, 0.004165]
[INFO] [stdout] [2m2026-07-10T14:33:35.122490Z[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 5.29s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 1.37s; merged doctests compilation took 1.33s
[INFO] running `Command { std: "docker" "inspect" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637", kill_on_drop: false }`
[INFO] [stdout] e409426ebef80eb4a015ce34a294bf4dfc2777ceccda80b72e2928a10a0a3637
