[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against try#16fbf98f22730e073c09e7b03f0eafb87a295545 for pr-145628
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-3-tc2/source
[INFO] started tweaking crates.io crate timesimp 1.0.0
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate timesimp 1.0.0
[INFO] tweaked toml for crates.io crate timesimp 1.0.0 written to /workspace/builds/worker-3-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain 16fbf98f22730e073c09e7b03f0eafb87a295545
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+16fbf98f22730e073c09e7b03f0eafb87a295545" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate crates.io crate timesimp 1.0.0 already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+16fbf98f22730e073c09e7b03f0eafb87a295545" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+16fbf98f22730e073c09e7b03f0eafb87a295545" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 1a639e1e89c521a0bde1cd51ba1850ca5aec9d68a2fcd8c75dfd16d7135d2dfb
[INFO] running `Command { std: "docker" "start" "-a" "1a639e1e89c521a0bde1cd51ba1850ca5aec9d68a2fcd8c75dfd16d7135d2dfb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "1a639e1e89c521a0bde1cd51ba1850ca5aec9d68a2fcd8c75dfd16d7135d2dfb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "1a639e1e89c521a0bde1cd51ba1850ca5aec9d68a2fcd8c75dfd16d7135d2dfb", kill_on_drop: false }`
[INFO] [stdout] 1a639e1e89c521a0bde1cd51ba1850ca5aec9d68a2fcd8c75dfd16d7135d2dfb
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+16fbf98f22730e073c09e7b03f0eafb87a295545" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 7ac5c423637f083ab39cca70b5ede1810f24e4dbec9facdb9decfcc9b0111f94
[INFO] running `Command { std: "docker" "start" "-a" "7ac5c423637f083ab39cca70b5ede1810f24e4dbec9facdb9decfcc9b0111f94", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 20.04s
[INFO] running `Command { std: "docker" "inspect" "7ac5c423637f083ab39cca70b5ede1810f24e4dbec9facdb9decfcc9b0111f94", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "7ac5c423637f083ab39cca70b5ede1810f24e4dbec9facdb9decfcc9b0111f94", kill_on_drop: false }`
[INFO] [stdout] 7ac5c423637f083ab39cca70b5ede1810f24e4dbec9facdb9decfcc9b0111f94
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+16fbf98f22730e073c09e7b03f0eafb87a295545" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 9f17dfa75b16a0cbd197ba89ae5c3872046a2f96b53dd3ebdb83d76e6ec6dc15
[INFO] running `Command { std: "docker" "start" "-a" "9f17dfa75b16a0cbd197ba89ae5c3872046a2f96b53dd3ebdb83d76e6ec6dc15", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling smallvec v1.14.0
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling 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 openssl-sys v0.9.107
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 14s
[INFO] running `Command { std: "docker" "inspect" "9f17dfa75b16a0cbd197ba89ae5c3872046a2f96b53dd3ebdb83d76e6ec6dc15", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "9f17dfa75b16a0cbd197ba89ae5c3872046a2f96b53dd3ebdb83d76e6ec6dc15", kill_on_drop: false }`
[INFO] [stdout] 9f17dfa75b16a0cbd197ba89ae5c3872046a2f96b53dd3ebdb83d76e6ec6dc15
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3-tc2/source:/opt/rustwide/workdir:ro,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" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+16fbf98f22730e073c09e7b03f0eafb87a295545" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] a1418d2a6c06e9a6c316db3c20a782a59aa104ee00d07f70a42719ccf9e8053c
[INFO] running `Command { std: "docker" "start" "-a" "a1418d2a6c06e9a6c316db3c20a782a59aa104ee00d07f70a42719ccf9e8053c", 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-7957b5c2dc13f12b)
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[INFO] [stdout] test delta::tests::client_ahead_of_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::client_equal_server ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-1c01cc53c6a498a7)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-09-01T03:01:13.364056Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-01T03:01:13.364128Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.364441Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:13.364468Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.364522Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:13.364553Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.364929Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:13.364994Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.365713Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:13.365909Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.366379Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:13.366496Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.369943Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-01T03:01:13.370173Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:13.370215Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.370257Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.373942Z TRACE new{response=Response { client: 2025-09-01T03:01:13.368836912Z, server: 2025-09-01T03:01:13.370828761Z } current=2025-09-01T03:01:13.37378536Z}: timesimp::delta: response processing internals latency=2ms 474µs 224ns local_at_midpoint=2025-09-01T03:01:13.371311136Z delta=482µs 375ns ago
[INFO] [stdout] 2025-09-01T03:01:13.374136Z TRACE timesimp: obtained raw offset from server latency=2.474224ms delta=482µs 375ns ago
[INFO] [stdout] 2025-09-01T03:01:13.374198Z DEBUG timesimp: no offset stored, storing initial delta offset=482µs 375ns ago
[INFO] [stdout] 2025-09-01T03:01:13.374297Z TRACE timesimp: sleeping to spread out requests delay=195.536608ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.380279Z TRACE new{response=Response { client: 2025-09-01T03:01:13.365848753Z, server: 2025-09-01T03:01:18.37299648Z } current=2025-09-01T03:01:13.380117199Z}: timesimp::delta: response processing internals latency=7ms 134µs 223ns local_at_midpoint=2025-09-01T03:01:13.372982976Z delta=5s 13µs 504ns
[INFO] [stdout] 2025-09-01T03:01:13.380427Z TRACE timesimp: obtained raw offset from server latency=7.134223ms delta=5s 13µs 504ns
[INFO] [stdout] 2025-09-01T03:01:13.380901Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 13µs 504ns
[INFO] [stdout] 2025-09-01T03:01:13.381245Z TRACE timesimp: sleeping to spread out requests delay=1.492171145s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.386080Z TRACE new{response=Response { client: 2025-09-01T03:01:13.365718973Z, server: 2025-09-01T03:01:18.37580753Z } current=2025-09-01T03:01:13.385934417Z}: timesimp::delta: response processing internals latency=10ms 107µs 722ns local_at_midpoint=2025-09-01T03:01:13.375826695Z delta=4s 999ms 980µs 835ns
[INFO] [stdout] 2025-09-01T03:01:13.386140Z TRACE timesimp: obtained raw offset from server latency=10.107722ms delta=4s 999ms 980µs 835ns
[INFO] [stdout] 2025-09-01T03:01:13.386155Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 980µs 835ns
[INFO] [stdout] 2025-09-01T03:01:13.386164Z TRACE timesimp: sleeping to spread out requests delay=1.877447295s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.387722Z TRACE new{response=Response { client: 2025-09-01T03:01:13.365381963Z, server: 2025-09-01T03:01:13.3765127Z } current=2025-09-01T03:01:13.387624947Z}: timesimp::delta: response processing internals latency=11ms 121µs 492ns local_at_midpoint=2025-09-01T03:01:13.376503455Z delta=9µs 245ns
[INFO] [stdout] 2025-09-01T03:01:13.387791Z TRACE timesimp: obtained raw offset from server latency=11.121492ms delta=9µs 245ns
[INFO] [stdout] 2025-09-01T03:01:13.387805Z TRACE timesimp: sleeping to spread out requests delay=813.778018ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.388733Z TRACE new{response=Response { client: 2025-09-01T03:01:13.368054572Z, server: 2025-09-01T03:01:18.379522359Z } current=2025-09-01T03:01:13.388638487Z}: timesimp::delta: response processing internals latency=10ms 291µs 957ns local_at_midpoint=2025-09-01T03:01:13.378346529Z delta=5s 1ms 175µs 830ns
[INFO] [stdout] 2025-09-01T03:01:13.388920Z TRACE timesimp: obtained raw offset from server latency=10.291957ms delta=5s 1ms 175µs 830ns
[INFO] [stdout] 2025-09-01T03:01:13.389019Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1ms 175µs 830ns
[INFO] [stdout] 2025-09-01T03:01:13.389207Z TRACE timesimp: sleeping to spread out requests delay=1.048042365s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.400442Z TRACE new{response=Response { client: 2025-09-01T03:01:13.378859779Z, server: 2025-09-01T03:01:13.388977966Z } current=2025-09-01T03:01:13.400144243Z}: timesimp::delta: response processing internals latency=10ms 642µs 232ns local_at_midpoint=2025-09-01T03:01:13.389502011Z delta=524µs 45ns ago
[INFO] [stdout] 2025-09-01T03:01:13.400524Z TRACE timesimp: obtained raw offset from server latency=10.642232ms delta=524µs 45ns ago
[INFO] [stdout] 2025-09-01T03:01:13.400543Z TRACE timesimp: sleeping to spread out requests delay=1.931344557s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.403969Z TRACE new{response=Response { client: 2025-09-01T03:01:13.378945309Z, server: 2025-09-01T03:01:08.390060236Z } current=2025-09-01T03:01:13.403838942Z}: timesimp::delta: response processing internals latency=12ms 446µs 816ns local_at_midpoint=2025-09-01T03:01:13.391392125Z delta=5s 1ms 331µs 889ns ago
[INFO] [stdout] 2025-09-01T03:01:13.404290Z TRACE timesimp: obtained raw offset from server latency=12.446816ms delta=5s 1ms 331µs 889ns ago
[INFO] [stdout] 2025-09-01T03:01:13.404702Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1ms 331µs 889ns ago
[INFO] [stdout] 2025-09-01T03:01:13.404899Z TRACE timesimp: sleeping to spread out requests delay=1.155018225s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:13.573948Z TRACE new{response=Response { client: 2025-09-01T03:01:13.571839167Z, server: 2025-09-01T03:01:13.571877107Z } current=2025-09-01T03:01:13.573800006Z}: timesimp::delta: response processing internals latency=980µs 419ns local_at_midpoint=2025-09-01T03:01:13.572819586Z delta=942µs 479ns ago
[INFO] [stdout] 2025-09-01T03:01:13.574021Z TRACE timesimp: obtained raw offset from server latency=980.419µs delta=942µs 479ns ago
[INFO] [stdout] 2025-09-01T03:01:13.574038Z TRACE timesimp: sleeping to spread out requests delay=1.741990921s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:14.227360Z TRACE new{response=Response { client: 2025-09-01T03:01:14.204853607Z, server: 2025-09-01T03:01:14.216027674Z } current=2025-09-01T03:01:14.227206581Z}: timesimp::delta: response processing internals latency=11ms 176µs 487ns local_at_midpoint=2025-09-01T03:01:14.216030094Z delta=2µs 420ns ago
[INFO] [stdout] 2025-09-01T03:01:14.227435Z TRACE timesimp: obtained raw offset from server latency=11.176487ms delta=2µs 420ns ago
[INFO] [stdout] 2025-09-01T03:01:14.227450Z TRACE timesimp: sleeping to spread out requests delay=427.031635ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:14.464043Z TRACE new{response=Response { client: 2025-09-01T03:01:14.438985354Z, server: 2025-09-01T03:01:19.450163091Z } current=2025-09-01T03:01:14.463887247Z}: timesimp::delta: response processing internals latency=12ms 450µs 946ns local_at_midpoint=2025-09-01T03:01:14.4514363Z delta=4s 998ms 726µs 791ns
[INFO] [stdout] 2025-09-01T03:01:14.464121Z TRACE timesimp: obtained raw offset from server latency=12.450946ms delta=4s 998ms 726µs 791ns
[INFO] [stdout] 2025-09-01T03:01:14.464139Z TRACE timesimp: sleeping to spread out requests delay=288.47618ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:14.583671Z TRACE new{response=Response { client: 2025-09-01T03:01:14.561058451Z, server: 2025-09-01T03:01:09.572240868Z } current=2025-09-01T03:01:14.583427055Z}: timesimp::delta: response processing internals latency=11ms 184µs 302ns local_at_midpoint=2025-09-01T03:01:14.572242753Z delta=5s 1µs 885ns ago
[INFO] [stdout] 2025-09-01T03:01:14.583861Z TRACE timesimp: obtained raw offset from server latency=11.184302ms delta=5s 1µs 885ns ago
[INFO] [stdout] 2025-09-01T03:01:14.583963Z TRACE timesimp: sleeping to spread out requests delay=533.833389ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:14.677494Z TRACE new{response=Response { client: 2025-09-01T03:01:14.654994086Z, server: 2025-09-01T03:01:14.666171583Z } current=2025-09-01T03:01:14.67734819Z}: timesimp::delta: response processing internals latency=11ms 177µs 52ns local_at_midpoint=2025-09-01T03:01:14.666171138Z delta=445ns
[INFO] [stdout] 2025-09-01T03:01:14.677570Z TRACE timesimp: obtained raw offset from server latency=11.177052ms delta=445ns
[INFO] [stdout] 2025-09-01T03:01:14.677586Z TRACE timesimp: sleeping to spread out requests delay=1.873294215s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:14.768610Z TRACE new{response=Response { client: 2025-09-01T03:01:14.753664459Z, server: 2025-09-01T03:01:19.760850027Z } current=2025-09-01T03:01:14.768443725Z}: timesimp::delta: response processing internals latency=7ms 389µs 633ns local_at_midpoint=2025-09-01T03:01:14.761054092Z delta=4s 999ms 795µs 935ns
[INFO] [stdout] 2025-09-01T03:01:14.768681Z TRACE timesimp: obtained raw offset from server latency=7.389633ms delta=4s 999ms 795µs 935ns
[INFO] [stdout] 2025-09-01T03:01:14.768696Z TRACE timesimp: sleeping to spread out requests delay=1.293005163s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:14.774638Z TRACE new{response=Response { client: 2025-09-01T03:01:13.367226552Z, server: 2025-09-01T03:01:14.070859333Z } current=2025-09-01T03:01:14.774468963Z}: timesimp::delta: response processing internals latency=703ms 621µs 205ns local_at_midpoint=2025-09-01T03:01:14.070847757Z delta=11µs 576ns
[INFO] [stdout] 2025-09-01T03:01:14.774706Z TRACE timesimp: obtained raw offset from server latency=703.621205ms delta=11µs 576ns
[INFO] [stdout] 2025-09-01T03:01:14.774722Z DEBUG timesimp: no offset stored, storing initial delta offset=11µs 576ns
[INFO] [stdout] 2025-09-01T03:01:14.774859Z TRACE timesimp: sleeping to spread out requests delay=923.981105ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:14.897858Z TRACE new{response=Response { client: 2025-09-01T03:01:14.874986006Z, server: 2025-09-01T03:01:19.886901943Z } current=2025-09-01T03:01:14.89765826Z}: timesimp::delta: response processing internals latency=11ms 336µs 127ns local_at_midpoint=2025-09-01T03:01:14.886322133Z delta=5s 579µs 810ns
[INFO] [stdout] 2025-09-01T03:01:14.898039Z TRACE timesimp: obtained raw offset from server latency=11.336127ms delta=5s 579µs 810ns
[INFO] [stdout] 2025-09-01T03:01:14.898097Z TRACE timesimp: sleeping to spread out requests delay=1.383559911s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:15.143246Z TRACE new{response=Response { client: 2025-09-01T03:01:15.119855881Z, server: 2025-09-01T03:01:10.131848437Z } current=2025-09-01T03:01:15.143023324Z}: timesimp::delta: response processing internals latency=11ms 583µs 721ns local_at_midpoint=2025-09-01T03:01:15.131439602Z delta=4s 999ms 591µs 165ns ago
[INFO] [stdout] 2025-09-01T03:01:15.143385Z TRACE timesimp: obtained raw offset from server latency=11.583721ms delta=4s 999ms 591µs 165ns ago
[INFO] [stdout] 2025-09-01T03:01:15.143421Z TRACE timesimp: sleeping to spread out requests delay=1.434462829s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:15.286983Z TRACE new{response=Response { client: 2025-09-01T03:01:15.265854011Z, server: 2025-09-01T03:01:20.276029968Z } current=2025-09-01T03:01:15.286832616Z}: timesimp::delta: response processing internals latency=10ms 489µs 302ns local_at_midpoint=2025-09-01T03:01:15.276343313Z delta=4s 999ms 686µs 655ns
[INFO] [stdout] 2025-09-01T03:01:15.287059Z TRACE timesimp: obtained raw offset from server latency=10.489302ms delta=4s 999ms 686µs 655ns
[INFO] [stdout] 2025-09-01T03:01:15.287077Z TRACE timesimp: sleeping to spread out requests delay=1.6297693s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:15.320333Z TRACE new{response=Response { client: 2025-09-01T03:01:15.317949407Z, server: 2025-09-01T03:01:15.319073637Z } current=2025-09-01T03:01:15.320189307Z}: timesimp::delta: response processing internals latency=1ms 119µs 950ns local_at_midpoint=2025-09-01T03:01:15.319069357Z delta=4µs 280ns
[INFO] [stdout] 2025-09-01T03:01:15.320408Z TRACE timesimp: obtained raw offset from server latency=1.11995ms delta=4µs 280ns
[INFO] [stdout] 2025-09-01T03:01:15.320425Z TRACE timesimp: sleeping to spread out requests delay=1.041104638s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:15.356013Z TRACE new{response=Response { client: 2025-09-01T03:01:15.333024123Z, server: 2025-09-01T03:01:15.34420769Z } current=2025-09-01T03:01:15.355848667Z}: timesimp::delta: response processing internals latency=11ms 412µs 272ns local_at_midpoint=2025-09-01T03:01:15.344436395Z delta=228µs 705ns ago
[INFO] [stdout] 2025-09-01T03:01:15.356469Z TRACE timesimp: obtained raw offset from server latency=11.412272ms delta=228µs 705ns ago
[INFO] [stdout] 2025-09-01T03:01:15.356565Z TRACE timesimp: sleeping to spread out requests delay=1.35256974s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.077495Z TRACE new{response=Response { client: 2025-09-01T03:01:16.062984777Z, server: 2025-09-01T03:01:21.070163755Z } current=2025-09-01T03:01:16.077347833Z}: timesimp::delta: response processing internals latency=7ms 181µs 528ns local_at_midpoint=2025-09-01T03:01:16.070166305Z delta=4s 999ms 997µs 450ns
[INFO] [stdout] 2025-09-01T03:01:16.077586Z TRACE timesimp: obtained raw offset from server latency=7.181528ms delta=4s 999ms 997µs 450ns
[INFO] [stdout] 2025-09-01T03:01:16.077603Z TRACE timesimp: sleeping to spread out requests delay=1.635123443s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.303515Z TRACE new{response=Response { client: 2025-09-01T03:01:16.282984308Z, server: 2025-09-01T03:01:21.293170945Z } current=2025-09-01T03:01:16.303358152Z}: timesimp::delta: response processing internals latency=10ms 186µs 922ns local_at_midpoint=2025-09-01T03:01:16.29317123Z delta=4s 999ms 999µs 715ns
[INFO] [stdout] 2025-09-01T03:01:16.303600Z TRACE timesimp: obtained raw offset from server latency=10.186922ms delta=4s 999ms 999µs 715ns
[INFO] [stdout] 2025-09-01T03:01:16.303619Z TRACE timesimp: sleeping to spread out requests delay=1.705857557s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.365391Z TRACE new{response=Response { client: 2025-09-01T03:01:16.362987586Z, server: 2025-09-01T03:01:16.364121156Z } current=2025-09-01T03:01:16.365238006Z}: timesimp::delta: response processing internals latency=1ms 125µs 210ns local_at_midpoint=2025-09-01T03:01:16.364112796Z delta=8µs 360ns
[INFO] [stdout] 2025-09-01T03:01:16.365474Z TRACE timesimp: obtained raw offset from server latency=1.12521ms delta=8µs 360ns
[INFO] [stdout] 2025-09-01T03:01:16.365491Z TRACE timesimp: sleeping to spread out requests delay=1.794255231s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.574604Z TRACE new{response=Response { client: 2025-09-01T03:01:16.551990725Z, server: 2025-09-01T03:01:16.563172372Z } current=2025-09-01T03:01:16.574442879Z}: timesimp::delta: response processing internals latency=11ms 226µs 77ns local_at_midpoint=2025-09-01T03:01:16.563216802Z delta=44µs 430ns ago
[INFO] [stdout] 2025-09-01T03:01:16.574680Z TRACE timesimp: obtained raw offset from server latency=11.226077ms delta=44µs 430ns ago
[INFO] [stdout] 2025-09-01T03:01:16.574698Z TRACE timesimp: sleeping to spread out requests delay=939.435449ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.606000Z TRACE new{response=Response { client: 2025-09-01T03:01:16.580910337Z, server: 2025-09-01T03:01:11.592092784Z } current=2025-09-01T03:01:16.605847531Z}: timesimp::delta: response processing internals latency=12ms 468µs 597ns local_at_midpoint=2025-09-01T03:01:16.593378934Z delta=5s 1ms 286µs 150ns ago
[INFO] [stdout] 2025-09-01T03:01:16.606075Z TRACE timesimp: obtained raw offset from server latency=12.468597ms delta=5s 1ms 286µs 150ns ago
[INFO] [stdout] 2025-09-01T03:01:16.606091Z TRACE timesimp: sleeping to spread out requests delay=92.589238ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.722271Z TRACE new{response=Response { client: 2025-09-01T03:01:16.699875076Z, server: 2025-09-01T03:01:11.711005452Z } current=2025-09-01T03:01:16.722121999Z}: timesimp::delta: response processing internals latency=11ms 123µs 461ns local_at_midpoint=2025-09-01T03:01:16.710998537Z delta=4s 999ms 993µs 85ns ago
[INFO] [stdout] 2025-09-01T03:01:16.722437Z TRACE timesimp: obtained raw offset from server latency=11.123461ms delta=4s 999ms 993µs 85ns ago
[INFO] [stdout] 2025-09-01T03:01:16.722465Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.993085, -5000.001885, -4999.591165, -5001.331889, -5001.28615]
[INFO] [stdout] 2025-09-01T03:01:16.722481Z TRACE timesimp: statistics about response deltas median=-4999.591165 mean=-5000.4408348 variance=0.6559077385103153 stddev=0.8098813113724228
[INFO] [stdout] 2025-09-01T03:01:16.722495Z TRACE timesimp: eliminated outliers inliers=[-4999.993085, -5000.001885, -4999.591165]
[INFO] [stdout] 2025-09-01T03:01:16.722504Z DEBUG timesimp: storing calculated offset offset=4s 999ms 862µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-09-01T03:01:16.723916Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:16.723947Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.732564Z TRACE new{response=Response { client: 2025-09-01T03:01:16.710070902Z, server: 2025-09-01T03:01:16.72124369Z } current=2025-09-01T03:01:16.732418687Z}: timesimp::delta: response processing internals latency=11ms 173µs 892ns local_at_midpoint=2025-09-01T03:01:16.721244794Z delta=1µs 104ns ago
[INFO] [stdout] 2025-09-01T03:01:16.732632Z TRACE timesimp: obtained raw offset from server latency=11.173892ms delta=1µs 104ns ago
[INFO] [stdout] 2025-09-01T03:01:16.732646Z TRACE timesimp: sleeping to spread out requests delay=1.304820387s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.747587Z TRACE new{response=Response { client: 2025-09-01T03:01:16.725114419Z, server: 2025-09-01T03:01:21.736249026Z } current=2025-09-01T03:01:16.747417212Z}: timesimp::delta: response processing internals latency=11ms 151µs 396ns local_at_midpoint=2025-09-01T03:01:16.736265815Z delta=4s 999ms 983µs 211ns
[INFO] [stdout] 2025-09-01T03:01:16.747724Z TRACE timesimp: obtained raw offset from server latency=11.151396ms delta=4s 999ms 983µs 211ns
[INFO] [stdout] 2025-09-01T03:01:16.747791Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 983µs 211ns
[INFO] [stdout] 2025-09-01T03:01:16.747825Z TRACE timesimp: sleeping to spread out requests delay=850.923916ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:16.940902Z TRACE new{response=Response { client: 2025-09-01T03:01:16.918376787Z, server: 2025-09-01T03:01:21.929555654Z } current=2025-09-01T03:01:16.940737691Z}: timesimp::delta: response processing internals latency=11ms 180µs 452ns local_at_midpoint=2025-09-01T03:01:16.929557239Z delta=4s 999ms 998µs 415ns
[INFO] [stdout] 2025-09-01T03:01:16.940976Z TRACE timesimp: obtained raw offset from server latency=11.180452ms delta=4s 999ms 998µs 415ns
[INFO] [stdout] 2025-09-01T03:01:16.940992Z TRACE timesimp: sleeping to spread out requests delay=768.849274ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:17.545215Z TRACE new{response=Response { client: 2025-09-01T03:01:17.520883584Z, server: 2025-09-01T03:01:17.533847011Z } current=2025-09-01T03:01:17.545047968Z}: timesimp::delta: response processing internals latency=12ms 82µs 192ns local_at_midpoint=2025-09-01T03:01:17.532965776Z delta=881µs 235ns
[INFO] [stdout] 2025-09-01T03:01:17.545291Z TRACE timesimp: obtained raw offset from server latency=12.082192ms delta=881µs 235ns
[INFO] [stdout] 2025-09-01T03:01:17.545321Z TRACE timesimp: response deltas sorted by latency deltas=[0.009245, -0.00242, 0.000445, -0.04443, 0.881235]
[INFO] [stdout] 2025-09-01T03:01:17.545335Z TRACE timesimp: statistics about response deltas median=0.000445 mean=0.168815 variance=0.1590370383625 stddev=0.39879448135913315
[INFO] [stdout] 2025-09-01T03:01:17.545348Z TRACE timesimp: eliminated outliers inliers=[0.009245, -0.00242, 0.000445, -0.04443]
[INFO] [stdout] 2025-09-01T03:01:17.545357Z DEBUG timesimp: storing calculated offset offset=9µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-09-01T03:01:17.546947Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:17.546983Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:17.586127Z TRACE new{response=Response { client: 2025-09-01T03:01:15.699990724Z, server: 2025-09-01T03:01:16.642984081Z } current=2025-09-01T03:01:17.585972507Z}: timesimp::delta: response processing internals latency=942ms 990µs 891ns local_at_midpoint=2025-09-01T03:01:16.642981615Z delta=2µs 466ns
[INFO] [stdout] 2025-09-01T03:01:17.586206Z TRACE timesimp: obtained raw offset from server latency=942.990891ms delta=2µs 466ns
[INFO] [stdout] 2025-09-01T03:01:17.586225Z TRACE timesimp: sleeping to spread out requests delay=1.703798096s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:17.623966Z TRACE new{response=Response { client: 2025-09-01T03:01:17.600603973Z, server: 2025-09-01T03:01:22.61170004Z } current=2025-09-01T03:01:17.623820717Z}: timesimp::delta: response processing internals latency=11ms 608µs 372ns local_at_midpoint=2025-09-01T03:01:17.612212345Z delta=4s 999ms 487µs 695ns
[INFO] [stdout] 2025-09-01T03:01:17.624106Z TRACE timesimp: obtained raw offset from server latency=11.608372ms delta=4s 999ms 487µs 695ns
[INFO] [stdout] 2025-09-01T03:01:17.624143Z TRACE timesimp: sleeping to spread out requests delay=194.28497ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:17.731140Z TRACE new{response=Response { client: 2025-09-01T03:01:17.710963063Z, server: 2025-09-01T03:01:22.720816691Z } current=2025-09-01T03:01:17.730983608Z}: timesimp::delta: response processing internals latency=10ms 10µs 272ns local_at_midpoint=2025-09-01T03:01:17.720973335Z delta=4s 999ms 843µs 356ns
[INFO] [stdout] 2025-09-01T03:01:17.731212Z TRACE timesimp: obtained raw offset from server latency=10.010272ms delta=4s 999ms 843µs 356ns
[INFO] [stdout] 2025-09-01T03:01:17.731228Z TRACE timesimp: sleeping to spread out requests delay=475.902µs max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:17.732601Z TRACE new{response=Response { client: 2025-09-01T03:01:17.714173223Z, server: 2025-09-01T03:01:22.7233959Z } current=2025-09-01T03:01:17.732522427Z}: timesimp::delta: response processing internals latency=9ms 174µs 602ns local_at_midpoint=2025-09-01T03:01:17.723347825Z delta=5s 48µs 75ns
[INFO] [stdout] 2025-09-01T03:01:17.732651Z TRACE timesimp: obtained raw offset from server latency=9.174602ms delta=5s 48µs 75ns
[INFO] [stdout] 2025-09-01T03:01:17.732670Z TRACE timesimp: response deltas sorted by latency deltas=[4999.99745, 4999.795935, 5000.048075, 5001.17583, 4998.726791]
[INFO] [stdout] 2025-09-01T03:01:17.732683Z TRACE timesimp: statistics about response deltas median=5000.048075 mean=4999.9488162 variance=0.7586246680047255 stddev=0.870990624521714
[INFO] [stdout] 2025-09-01T03:01:17.732696Z TRACE timesimp: eliminated outliers inliers=[4999.99745, 4999.795935, 5000.048075]
[INFO] [stdout] 2025-09-01T03:01:17.732708Z DEBUG timesimp: storing calculated offset offset=4s 999ms 947µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-09-01T03:01:17.750994Z TRACE new{response=Response { client: 2025-09-01T03:01:17.548158477Z, server: 2025-09-01T03:01:17.64947781Z } current=2025-09-01T03:01:17.750833463Z}: timesimp::delta: response processing internals latency=101ms 337µs 493ns local_at_midpoint=2025-09-01T03:01:17.64949597Z delta=18µs 160ns ago
[INFO] [stdout] 2025-09-01T03:01:17.751074Z TRACE timesimp: obtained raw offset from server latency=101.337493ms delta=18µs 160ns ago
[INFO] [stdout] 2025-09-01T03:01:17.751091Z DEBUG timesimp: no offset stored, storing initial delta offset=18µs 160ns ago
[INFO] [stdout] 2025-09-01T03:01:17.751102Z TRACE timesimp: sleeping to spread out requests delay=315.435324ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:17.754788Z TRACE new{response=Response { client: 2025-09-01T03:01:17.733359917Z, server: 2025-09-01T03:01:22.744517004Z } current=2025-09-01T03:01:17.754663992Z}: timesimp::delta: response processing internals latency=10ms 652µs 37ns local_at_midpoint=2025-09-01T03:01:17.744011954Z delta=5s 505µs 50ns
[INFO] [stdout] 2025-09-01T03:01:17.754852Z TRACE timesimp: obtained raw offset from server latency=10.652037ms delta=5s 505µs 50ns
[INFO] [stdout] 2025-09-01T03:01:17.754877Z TRACE timesimp: response deltas sorted by latency deltas=[4999.843356, 4999.980835, 4999.6866549999995, 5000.50505, 4999.998415]
[INFO] [stdout] 2025-09-01T03:01:17.754892Z TRACE timesimp: statistics about response deltas median=4999.6866549999995 mean=5000.0028622 variance=0.09453169569168644 stddev=0.30746007170311795
[INFO] [stdout] 2025-09-01T03:01:17.754907Z TRACE timesimp: eliminated outliers inliers=[4999.843356, 4999.980835, 4999.6866549999995]
[INFO] [stdout] 2025-09-01T03:01:17.754917Z DEBUG timesimp: storing calculated offset offset=4s 999ms 836µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-09-01T03:01:17.843351Z TRACE new{response=Response { client: 2025-09-01T03:01:17.820844584Z, server: 2025-09-01T03:01:22.832017081Z } current=2025-09-01T03:01:17.843186308Z}: timesimp::delta: response processing internals latency=11ms 170µs 862ns local_at_midpoint=2025-09-01T03:01:17.832015446Z delta=5s 1µs 635ns
[INFO] [stdout] 2025-09-01T03:01:17.843426Z TRACE timesimp: obtained raw offset from server latency=11.170862ms delta=5s 1µs 635ns
[INFO] [stdout] 2025-09-01T03:01:17.843442Z TRACE timesimp: sleeping to spread out requests delay=1.668036502s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:18.027004Z TRACE new{response=Response { client: 2025-09-01T03:01:18.010532773Z, server: 2025-09-01T03:01:23.018712231Z } current=2025-09-01T03:01:18.026851188Z}: timesimp::delta: response processing internals latency=8ms 159µs 207ns local_at_midpoint=2025-09-01T03:01:18.01869198Z delta=5s 20µs 251ns
[INFO] [stdout] 2025-09-01T03:01:18.027085Z TRACE timesimp: obtained raw offset from server latency=8.159207ms delta=5s 20µs 251ns
[INFO] [stdout] 2025-09-01T03:01:18.027105Z TRACE timesimp: sleeping to spread out requests delay=1.513201244s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:18.061346Z TRACE new{response=Response { client: 2025-09-01T03:01:18.038622535Z, server: 2025-09-01T03:01:18.049920092Z } current=2025-09-01T03:01:18.061103869Z}: timesimp::delta: response processing internals latency=11ms 240µs 667ns local_at_midpoint=2025-09-01T03:01:18.049863202Z delta=56µs 890ns
[INFO] [stdout] 2025-09-01T03:01:18.061512Z TRACE timesimp: obtained raw offset from server latency=11.240667ms delta=56µs 890ns
[INFO] [stdout] 2025-09-01T03:01:18.061611Z TRACE timesimp: sleeping to spread out requests delay=798.023365ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:18.163123Z TRACE new{response=Response { client: 2025-09-01T03:01:18.160742302Z, server: 2025-09-01T03:01:18.161878472Z } current=2025-09-01T03:01:18.162988092Z}: timesimp::delta: response processing internals latency=1ms 122µs 895ns local_at_midpoint=2025-09-01T03:01:18.161865197Z delta=13µs 275ns
[INFO] [stdout] 2025-09-01T03:01:18.163191Z TRACE timesimp: obtained raw offset from server latency=1.122895ms delta=13µs 275ns
[INFO] [stdout] 2025-09-01T03:01:18.163210Z TRACE timesimp: response deltas sorted by latency deltas=[-0.942479, 0.00428, 0.013275, 0.00836, -0.482375]
[INFO] [stdout] 2025-09-01T03:01:18.163221Z TRACE timesimp: statistics about response deltas median=0.013275 mean=-0.2797878 variance=0.1824526686367 stddev=0.4271447865030077
[INFO] [stdout] 2025-09-01T03:01:18.163234Z TRACE timesimp: eliminated outliers inliers=[0.00428, 0.013275, 0.00836]
[INFO] [stdout] 2025-09-01T03:01:18.163241Z DEBUG timesimp: storing calculated offset offset=8µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-09-01T03:01:18.271672Z TRACE new{response=Response { client: 2025-09-01T03:01:18.069859397Z, server: 2025-09-01T03:01:18.17017458Z } current=2025-09-01T03:01:18.271518713Z}: timesimp::delta: response processing internals latency=100ms 829µs 658ns local_at_midpoint=2025-09-01T03:01:18.170689055Z delta=514µs 475ns ago
[INFO] [stdout] 2025-09-01T03:01:18.271745Z TRACE timesimp: obtained raw offset from server latency=100.829658ms delta=514µs 475ns ago
[INFO] [stdout] 2025-09-01T03:01:18.271776Z TRACE timesimp: sleeping to spread out requests delay=1.135750209s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:18.885006Z TRACE new{response=Response { client: 2025-09-01T03:01:18.861056874Z, server: 2025-09-01T03:01:18.872212931Z } current=2025-09-01T03:01:18.884847568Z}: timesimp::delta: response processing internals latency=11ms 895µs 347ns local_at_midpoint=2025-09-01T03:01:18.872952221Z delta=739µs 290ns ago
[INFO] [stdout] 2025-09-01T03:01:18.885091Z TRACE timesimp: obtained raw offset from server latency=11.895347ms delta=739µs 290ns ago
[INFO] [stdout] 2025-09-01T03:01:18.885118Z TRACE timesimp: response deltas sorted by latency deltas=[-0.524045, -0.001104, 0.05689, -0.228705, -0.73929]
[INFO] [stdout] 2025-09-01T03:01:18.885133Z TRACE timesimp: statistics about response deltas median=0.05689 mean=-0.2872508 variance=0.1160378558907 stddev=0.34064329714629643
[INFO] [stdout] 2025-09-01T03:01:18.885147Z TRACE timesimp: eliminated outliers inliers=[-0.001104, 0.05689, -0.228705]
[INFO] [stdout] 2025-09-01T03:01:18.885156Z DEBUG timesimp: storing calculated offset offset=57µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2025-09-01T03:01:19.539208Z TRACE new{response=Response { client: 2025-09-01T03:01:19.513816078Z, server: 2025-09-01T03:01:24.527849995Z } current=2025-09-01T03:01:19.539050581Z}: timesimp::delta: response processing internals latency=12ms 617µs 251ns local_at_midpoint=2025-09-01T03:01:19.526433329Z delta=5s 1ms 416µs 666ns
[INFO] [stdout] 2025-09-01T03:01:19.539284Z TRACE timesimp: obtained raw offset from server latency=12.617251ms delta=5s 1ms 416µs 666ns
[INFO] [stdout] 2025-09-01T03:01:19.539307Z TRACE timesimp: sleeping to spread out requests delay=211.000365ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:19.553407Z TRACE new{response=Response { client: 2025-09-01T03:01:19.540942171Z, server: 2025-09-01T03:01:24.547091249Z } current=2025-09-01T03:01:19.553252738Z}: timesimp::delta: response processing internals latency=6ms 155µs 283ns local_at_midpoint=2025-09-01T03:01:19.547097454Z delta=4s 999ms 993µs 795ns
[INFO] [stdout] 2025-09-01T03:01:19.553486Z TRACE timesimp: obtained raw offset from server latency=6.155283ms delta=4s 999ms 993µs 795ns
[INFO] [stdout] 2025-09-01T03:01:19.553510Z TRACE timesimp: response deltas sorted by latency deltas=[4999.993795, 5000.013504, 5000.020251, 4999.999715, 5000.57981]
[INFO] [stdout] 2025-09-01T03:01:19.553542Z TRACE timesimp: statistics about response deltas median=5000.020251 mean=5000.121415 variance=0.0657756673105536 stddev=0.2564676730322042
[INFO] [stdout] 2025-09-01T03:01:19.553558Z TRACE timesimp: eliminated outliers inliers=[4999.993795, 5000.013504, 5000.020251, 4999.999715]
[INFO] [stdout] 2025-09-01T03:01:19.553568Z DEBUG timesimp: storing calculated offset offset=5s 6µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-09-01T03:01:19.611806Z TRACE new{response=Response { client: 2025-09-01T03:01:19.408992127Z, server: 2025-09-01T03:01:19.510277089Z } current=2025-09-01T03:01:19.611629212Z}: timesimp::delta: response processing internals latency=101ms 318µs 542ns local_at_midpoint=2025-09-01T03:01:19.510310669Z delta=33µs 580ns ago
[INFO] [stdout] 2025-09-01T03:01:19.611881Z TRACE timesimp: obtained raw offset from server latency=101.318542ms delta=33µs 580ns ago
[INFO] [stdout] 2025-09-01T03:01:19.611896Z TRACE timesimp: sleeping to spread out requests delay=1.094893144s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:19.774500Z TRACE new{response=Response { client: 2025-09-01T03:01:19.751979614Z, server: 2025-09-01T03:01:24.763163841Z } current=2025-09-01T03:01:19.774351798Z}: timesimp::delta: response processing internals latency=11ms 186µs 92ns local_at_midpoint=2025-09-01T03:01:19.763165706Z delta=4s 999ms 998µs 135ns
[INFO] [stdout] 2025-09-01T03:01:19.774574Z TRACE timesimp: obtained raw offset from server latency=11.186092ms delta=4s 999ms 998µs 135ns
[INFO] [stdout] 2025-09-01T03:01:19.774597Z TRACE timesimp: response deltas sorted by latency deltas=[4999.983211, 5000.001635, 4999.998135, 4999.487695, 5001.416666]
[INFO] [stdout] 2025-09-01T03:01:19.774610Z TRACE timesimp: statistics about response deltas median=4999.998135 mean=5000.177468399999 variance=0.5280529563899887 stddev=0.7266725234863286
[INFO] [stdout] 2025-09-01T03:01:19.774628Z TRACE timesimp: eliminated outliers inliers=[4999.983211, 5000.001635, 4999.998135, 4999.487695]
[INFO] [stdout] 2025-09-01T03:01:19.774638Z DEBUG timesimp: storing calculated offset offset=4s 999ms 867µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2025-09-01T03:01:20.910854Z TRACE new{response=Response { client: 2025-09-01T03:01:20.707989447Z, server: 2025-09-01T03:01:20.80933742Z } current=2025-09-01T03:01:20.910672402Z}: timesimp::delta: response processing internals latency=101ms 341µs 477ns local_at_midpoint=2025-09-01T03:01:20.809330924Z delta=6µs 496ns
[INFO] [stdout] 2025-09-01T03:01:20.910936Z TRACE timesimp: obtained raw offset from server latency=101.341477ms delta=6µs 496ns
[INFO] [stdout] 2025-09-01T03:01:20.910954Z TRACE timesimp: sleeping to spread out requests delay=1.319270072s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:20.929128Z TRACE new{response=Response { client: 2025-09-01T03:01:19.290987718Z, server: 2025-09-01T03:01:20.109988458Z } current=2025-09-01T03:01:20.928970498Z}: timesimp::delta: response processing internals latency=818ms 991µs 390ns local_at_midpoint=2025-09-01T03:01:20.109979108Z delta=9µs 350ns
[INFO] [stdout] 2025-09-01T03:01:20.929208Z TRACE timesimp: obtained raw offset from server latency=818.99139ms delta=9µs 350ns
[INFO] [stdout] 2025-09-01T03:01:20.929225Z TRACE timesimp: sleeping to spread out requests delay=973.712246ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:22.433679Z TRACE new{response=Response { client: 2025-09-01T03:01:22.231855377Z, server: 2025-09-01T03:01:22.3321741Z } current=2025-09-01T03:01:22.433518563Z}: timesimp::delta: response processing internals latency=100ms 831µs 593ns local_at_midpoint=2025-09-01T03:01:22.33268697Z delta=512µs 870ns ago
[INFO] [stdout] 2025-09-01T03:01:22.433778Z TRACE timesimp: obtained raw offset from server latency=100.831593ms delta=512µs 870ns ago
[INFO] [stdout] 2025-09-01T03:01:22.433804Z TRACE timesimp: response deltas sorted by latency deltas=[-0.514475, -0.51287, -0.03358, -0.01816, 0.006496]
[INFO] [stdout] 2025-09-01T03:01:22.433819Z TRACE timesimp: statistics about response deltas median=-0.03358 mean=-0.21451779999999995 variance=0.0747825824892 stddev=0.2734640424063098
[INFO] [stdout] 2025-09-01T03:01:22.433835Z TRACE timesimp: eliminated outliers inliers=[-0.03358, -0.01816, 0.006496]
[INFO] [stdout] 2025-09-01T03:01:22.433845Z DEBUG timesimp: storing calculated offset offset=15µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-09-01T03:01:23.569062Z TRACE new{response=Response { client: 2025-09-01T03:01:21.909861284Z, server: 2025-09-01T03:01:22.753853547Z } current=2025-09-01T03:01:23.568914207Z}: timesimp::delta: response processing internals latency=829ms 526µs 461ns local_at_midpoint=2025-09-01T03:01:22.739387745Z delta=14ms 465µs 802ns
[INFO] [stdout] 2025-09-01T03:01:23.569134Z TRACE timesimp: obtained raw offset from server latency=829.526461ms delta=14ms 465µs 802ns
[INFO] [stdout] 2025-09-01T03:01:23.569149Z TRACE timesimp: sleeping to spread out requests delay=1.327166299s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.503014Z TRACE new{response=Response { client: 2025-09-01T03:01:24.89697925Z, server: 2025-09-01T03:01:25.698976774Z } current=2025-09-01T03:01:26.502850888Z}: timesimp::delta: response processing internals latency=802ms 935µs 819ns local_at_midpoint=2025-09-01T03:01:25.699915069Z delta=938µs 295ns ago
[INFO] [stdout] 2025-09-01T03:01:26.503094Z TRACE timesimp: obtained raw offset from server latency=802.935819ms delta=938µs 295ns ago
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-9d1c06fe72bb6515)
[INFO] [stdout] 2025-09-01T03:01:26.503119Z TRACE timesimp: response deltas sorted by latency deltas=[0.011576, -0.938295, 0.00935, 14.465802, 0.002466]
[INFO] [stdout] 2025-09-01T03:01:26.503135Z TRACE timesimp: statistics about response deltas median=0.00935 mean=2.7101797999999997 variance=43.3536699440052 stddev=6.584350381321243
[INFO] [stdout] 2025-09-01T03:01:26.503152Z TRACE timesimp: eliminated outliers inliers=[0.011576, -0.938295, 0.00935, 0.002466]
[INFO] [stdout] 2025-09-01T03:01:26.503163Z DEBUG timesimp: storing calculated offset offset=228µ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 13.14s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-09-01T03:01:26.508958Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-09-01T03:01:26.508940Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:26.509024Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.509031Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.509016Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-09-01T03:01:26.509103Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.510459Z TRACE new{response=Response { client: 2025-09-01T03:01:26.510318636Z, server: 2025-09-01T03:01:21.510324246Z } current=2025-09-01T03:01:26.510332256Z}: timesimp::delta: response processing internals latency=6µs 810ns local_at_midpoint=2025-09-01T03:01:26.510325446Z delta=5s 1µs 200ns ago
[INFO] [stdout] 2025-09-01T03:01:26.510517Z TRACE timesimp: obtained raw offset from server latency=6.81µs delta=5s 1µs 200ns ago
[INFO] [stdout] 2025-09-01T03:01:26.510532Z TRACE timesimp: sleeping to spread out requests delay=1.06325899s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.510649Z TRACE new{response=Response { client: 2025-09-01T03:01:26.510564676Z, server: 2025-09-01T03:01:26.510566976Z } current=2025-09-01T03:01:26.510568596Z}: timesimp::delta: response processing internals latency=1µs 960ns local_at_midpoint=2025-09-01T03:01:26.510566636Z delta=340ns
[INFO] [stdout] 2025-09-01T03:01:26.510704Z TRACE timesimp: obtained raw offset from server latency=1.96µs delta=340ns
[INFO] [stdout] 2025-09-01T03:01:26.510732Z DEBUG timesimp: no offset stored, storing initial delta offset=340ns
[INFO] [stdout] 2025-09-01T03:01:26.510750Z TRACE timesimp: sleeping to spread out requests delay=1.613116112s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.510460Z TRACE new{response=Response { client: 2025-09-01T03:01:26.510318026Z, server: 2025-09-01T03:01:26.510324226Z } current=2025-09-01T03:01:26.510333996Z}: timesimp::delta: response processing internals latency=7µs 985ns local_at_midpoint=2025-09-01T03:01:26.510326011Z delta=1µs 785ns ago
[INFO] [stdout] 2025-09-01T03:01:26.510800Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-09-01T03:01:26.510826Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.510829Z TRACE timesimp: obtained raw offset from server latency=7.985µs delta=1µs 785ns ago
[INFO] [stdout] 2025-09-01T03:01:26.510845Z TRACE timesimp: sleeping to spread out requests delay=136.854742ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.512938Z TRACE new{response=Response { client: 2025-09-01T03:01:26.512842675Z, server: 2025-09-01T03:01:31.512845555Z } current=2025-09-01T03:01:26.512847785Z}: timesimp::delta: response processing internals latency=2µs 555ns local_at_midpoint=2025-09-01T03:01:26.51284523Z delta=5s 325ns
[INFO] [stdout] 2025-09-01T03:01:26.512991Z TRACE timesimp: obtained raw offset from server latency=2.555µs delta=5s 325ns
[INFO] [stdout] 2025-09-01T03:01:26.513005Z TRACE timesimp: sleeping to spread out requests delay=1.831033164s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:26.648371Z TRACE new{response=Response { client: 2025-09-01T03:01:26.648213549Z, server: 2025-09-01T03:01:26.648221829Z } current=2025-09-01T03:01:26.648225269Z}: timesimp::delta: response processing internals latency=5µs 860ns local_at_midpoint=2025-09-01T03:01:26.648219409Z delta=2µs 420ns
[INFO] [stdout] 2025-09-01T03:01:26.648435Z TRACE timesimp: obtained raw offset from server latency=5.86µs delta=2µs 420ns
[INFO] [stdout] 2025-09-01T03:01:26.648449Z TRACE timesimp: sleeping to spread out requests delay=1.179158505s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:27.575215Z TRACE new{response=Response { client: 2025-09-01T03:01:27.575057299Z, server: 2025-09-01T03:01:22.575065509Z } current=2025-09-01T03:01:27.575069069Z}: timesimp::delta: response processing internals latency=5µs 885ns local_at_midpoint=2025-09-01T03:01:27.575063184Z delta=4s 999ms 997µs 675ns ago
[INFO] [stdout] 2025-09-01T03:01:27.575309Z TRACE timesimp: obtained raw offset from server latency=5.885µs delta=4s 999ms 997µs 675ns ago
[INFO] [stdout] 2025-09-01T03:01:27.575325Z TRACE timesimp: sleeping to spread out requests delay=1.660636754s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:27.828141Z TRACE new{response=Response { client: 2025-09-01T03:01:27.827984331Z, server: 2025-09-01T03:01:27.827992731Z } current=2025-09-01T03:01:27.827996501Z}: timesimp::delta: response processing internals latency=6µs 85ns local_at_midpoint=2025-09-01T03:01:27.827990416Z delta=2µs 315ns
[INFO] [stdout] 2025-09-01T03:01:27.828211Z TRACE timesimp: obtained raw offset from server latency=6.085µs delta=2µs 315ns
[INFO] [stdout] 2025-09-01T03:01:27.828227Z TRACE timesimp: sleeping to spread out requests delay=1.135173897s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:28.125200Z TRACE new{response=Response { client: 2025-09-01T03:01:28.125036741Z, server: 2025-09-01T03:01:28.125045261Z } current=2025-09-01T03:01:28.125048391Z}: timesimp::delta: response processing internals latency=5µs 825ns local_at_midpoint=2025-09-01T03:01:28.125042566Z delta=2µs 695ns
[INFO] [stdout] 2025-09-01T03:01:28.125549Z TRACE timesimp: obtained raw offset from server latency=5.825µs delta=2µs 695ns
[INFO] [stdout] 2025-09-01T03:01:28.126219Z TRACE timesimp: sleeping to spread out requests delay=881.521668ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:28.345141Z TRACE new{response=Response { client: 2025-09-01T03:01:28.344981892Z, server: 2025-09-01T03:01:33.344991132Z } current=2025-09-01T03:01:28.344994382Z}: timesimp::delta: response processing internals latency=6µs 245ns local_at_midpoint=2025-09-01T03:01:28.344988137Z delta=5s 2µs 995ns
[INFO] [stdout] 2025-09-01T03:01:28.345214Z TRACE timesimp: obtained raw offset from server latency=6.245µs delta=5s 2µs 995ns
[INFO] [stdout] 2025-09-01T03:01:28.345228Z TRACE timesimp: sleeping to spread out requests delay=322.080252ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:28.668127Z TRACE new{response=Response { client: 2025-09-01T03:01:28.667976445Z, server: 2025-09-01T03:01:33.667985195Z } current=2025-09-01T03:01:28.667988675Z}: timesimp::delta: response processing internals latency=6µs 115ns local_at_midpoint=2025-09-01T03:01:28.66798256Z delta=5s 2µs 635ns
[INFO] [stdout] 2025-09-01T03:01:28.668194Z TRACE timesimp: obtained raw offset from server latency=6.115µs delta=5s 2µs 635ns
[INFO] [stdout] 2025-09-01T03:01:28.668210Z TRACE timesimp: sleeping to spread out requests delay=1.455275159s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:28.964558Z TRACE new{response=Response { client: 2025-09-01T03:01:28.964387836Z, server: 2025-09-01T03:01:28.964396445Z } current=2025-09-01T03:01:28.964400005Z}: timesimp::delta: response processing internals latency=6µs 84ns local_at_midpoint=2025-09-01T03:01:28.96439392Z delta=2µs 525ns
[INFO] [stdout] 2025-09-01T03:01:28.964630Z TRACE timesimp: obtained raw offset from server latency=6.084µs delta=2µs 525ns
[INFO] [stdout] 2025-09-01T03:01:28.964649Z TRACE timesimp: sleeping to spread out requests delay=300.996834ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:29.009699Z TRACE new{response=Response { client: 2025-09-01T03:01:29.009539833Z, server: 2025-09-01T03:01:29.009556393Z } current=2025-09-01T03:01:29.009559583Z}: timesimp::delta: response processing internals latency=9µs 875ns local_at_midpoint=2025-09-01T03:01:29.009549708Z delta=6µs 685ns
[INFO] [stdout] 2025-09-01T03:01:29.009781Z TRACE timesimp: obtained raw offset from server latency=9.875µs delta=6µs 685ns
[INFO] [stdout] 2025-09-01T03:01:29.009798Z TRACE timesimp: sleeping to spread out requests delay=371.001834ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:29.237232Z TRACE new{response=Response { client: 2025-09-01T03:01:29.236987062Z, server: 2025-09-01T03:01:24.236995342Z } current=2025-09-01T03:01:29.236998802Z}: timesimp::delta: response processing internals latency=5µs 870ns local_at_midpoint=2025-09-01T03:01:29.236992932Z delta=4s 999ms 997µs 590ns ago
[INFO] [stdout] 2025-09-01T03:01:29.237308Z TRACE timesimp: obtained raw offset from server latency=5.87µs delta=4s 999ms 997µs 590ns ago
[INFO] [stdout] 2025-09-01T03:01:29.237327Z TRACE timesimp: sleeping to spread out requests delay=1.072796239s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:29.274511Z TRACE new{response=Response { client: 2025-09-01T03:01:29.274349002Z, server: 2025-09-01T03:01:29.274357512Z } current=2025-09-01T03:01:29.274360982Z}: timesimp::delta: response processing internals latency=5µs 990ns local_at_midpoint=2025-09-01T03:01:29.274354992Z delta=2µs 520ns
[INFO] [stdout] 2025-09-01T03:01:29.274590Z TRACE timesimp: obtained raw offset from server latency=5.99µs delta=2µs 520ns
[INFO] [stdout] 2025-09-01T03:01:29.274617Z TRACE timesimp: response deltas sorted by latency deltas=[0.00242, 0.00252, 0.002525, 0.002315, -0.001785]
[INFO] [stdout] 2025-09-01T03:01:29.274631Z TRACE timesimp: statistics about response deltas median=0.002525 mean=0.0015989999999999997 variance=3.5859675e-6 stddev=0.0018936650971066663
[INFO] [stdout] 2025-09-01T03:01:29.274646Z TRACE timesimp: eliminated outliers inliers=[0.00242, 0.00252, 0.002525, 0.002315]
[INFO] [stdout] 2025-09-01T03:01:29.274654Z DEBUG timesimp: storing calculated offset offset=2µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2025-09-01T03:01:29.382566Z TRACE new{response=Response { client: 2025-09-01T03:01:29.382394883Z, server: 2025-09-01T03:01:29.382404243Z } current=2025-09-01T03:01:29.382407173Z}: timesimp::delta: response processing internals latency=6µs 145ns local_at_midpoint=2025-09-01T03:01:29.382401028Z delta=3µs 215ns
[INFO] [stdout] 2025-09-01T03:01:29.382722Z TRACE timesimp: obtained raw offset from server latency=6.145µs delta=3µs 215ns
[INFO] [stdout] 2025-09-01T03:01:29.382790Z TRACE timesimp: sleeping to spread out requests delay=336.535947ms max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:29.736064Z TRACE new{response=Response { client: 2025-09-01T03:01:29.735911408Z, server: 2025-09-01T03:01:29.735921148Z } current=2025-09-01T03:01:29.735924188Z}: timesimp::delta: response processing internals latency=6µs 390ns local_at_midpoint=2025-09-01T03:01:29.735917798Z delta=3µs 350ns
[INFO] [stdout] 2025-09-01T03:01:29.736124Z TRACE timesimp: obtained raw offset from server latency=6.39µs delta=3µs 350ns
[INFO] [stdout] 2025-09-01T03:01:29.736141Z TRACE timesimp: response deltas sorted by latency deltas=[0.00034, 0.002695, 0.003215, 0.00335, 0.006685]
[INFO] [stdout] 2025-09-01T03:01:29.736153Z TRACE timesimp: statistics about response deltas median=0.003215 mean=0.0032570000000000003 variance=5.1465825e-6 stddev=0.002268608053410725
[INFO] [stdout] 2025-09-01T03:01:29.736165Z TRACE timesimp: eliminated outliers inliers=[0.002695, 0.003215, 0.00335]
[INFO] [stdout] 2025-09-01T03:01:29.736172Z DEBUG timesimp: storing calculated offset offset=3µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2025-09-01T03:01:30.124131Z TRACE new{response=Response { client: 2025-09-01T03:01:30.123984313Z, server: 2025-09-01T03:01:35.123992573Z } current=2025-09-01T03:01:30.123995913Z}: timesimp::delta: response processing internals latency=5µs 800ns local_at_midpoint=2025-09-01T03:01:30.123990113Z delta=5s 2µs 460ns
[INFO] [stdout] 2025-09-01T03:01:30.124198Z TRACE timesimp: obtained raw offset from server latency=5.8µs delta=5s 2µs 460ns
[INFO] [stdout] 2025-09-01T03:01:30.124213Z TRACE timesimp: sleeping to spread out requests delay=1.312237237s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:30.314012Z TRACE new{response=Response { client: 2025-09-01T03:01:30.313852152Z, server: 2025-09-01T03:01:25.313861272Z } current=2025-09-01T03:01:30.313864682Z}: timesimp::delta: response processing internals latency=6µs 265ns local_at_midpoint=2025-09-01T03:01:30.313858417Z delta=4s 999ms 997µs 145ns ago
[INFO] [stdout] 2025-09-01T03:01:30.314091Z TRACE timesimp: obtained raw offset from server latency=6.265µs delta=4s 999ms 997µs 145ns ago
[INFO] [stdout] 2025-09-01T03:01:30.314109Z TRACE timesimp: sleeping to spread out requests delay=1.182794464s max_jitter=2s
[INFO] [stdout] 2025-09-01T03:01:31.438976Z TRACE new{response=Response { client: 2025-09-01T03:01:31.43882Z, server: 2025-09-01T03:01:36.43882802Z } current=2025-09-01T03:01:31.43883107Z}: timesimp::delta: response processing internals latency=5µs 535ns local_at_midpoint=2025-09-01T03:01:31.438825535Z delta=5s 2µs 485ns
[INFO] [stdout] 2025-09-01T03:01:31.439050Z TRACE timesimp: obtained raw offset from server latency=5.535µs delta=5s 2µs 485ns
[INFO] [stdout] 2025-09-01T03:01:31.439073Z TRACE timesimp: response deltas sorted by latency deltas=[5000.000325, 5000.002485, 5000.00246, 5000.002635, 5000.002995]
[INFO] [stdout] 2025-09-01T03:01:31.439087Z TRACE timesimp: statistics about response deltas median=5000.00246 mean=5000.0021799999995 variance=1.1209249998684638e-6 stddev=0.0010587374555896584
[INFO] [stdout] 2025-09-01T03:01:31.439107Z TRACE timesimp: eliminated outliers inliers=[5000.002485, 5000.00246, 5000.002635, 5000.002995]
[INFO] [stdout] 2025-09-01T03:01:31.439116Z DEBUG timesimp: storing calculated offset offset=5s 2µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2025-09-01T03:01:31.498165Z TRACE new{response=Response { client: 2025-09-01T03:01:31.498000814Z, server: 2025-09-01T03:01:26.498010004Z } current=2025-09-01T03:01:31.498013614Z}: timesimp::delta: response processing internals latency=6µs 400ns local_at_midpoint=2025-09-01T03:01:31.498007214Z delta=4s 999ms 997µs 210ns ago
[INFO] [stdout] 2025-09-01T03:01:31.498372Z TRACE timesimp: obtained raw offset from server latency=6.4µs delta=4s 999ms 997µs 210ns ago
[INFO] [stdout] 2025-09-01T03:01:31.498398Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.99759, -4999.997675, -4999.997145, -4999.9972099999995, -5000.0012]
[INFO] [stdout] 2025-09-01T03:01:31.498413Z TRACE timesimp: statistics about response deltas median=-4999.997145 mean=-4999.998164 variance=2.933592499731762e-6 stddev=0.0017127733357720637
[INFO] [stdout] 2025-09-01T03:01:31.498432Z TRACE timesimp: eliminated outliers inliers=[-4999.99759, -4999.997675, -4999.997145, -4999.9972099999995]
[INFO] [stdout] 2025-09-01T03:01:31.498450Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.99s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "a1418d2a6c06e9a6c316db3c20a782a59aa104ee00d07f70a42719ccf9e8053c", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a1418d2a6c06e9a6c316db3c20a782a59aa104ee00d07f70a42719ccf9e8053c", kill_on_drop: false }`
[INFO] [stdout] a1418d2a6c06e9a6c316db3c20a782a59aa104ee00d07f70a42719ccf9e8053c