[INFO] cloning repository https://github.com/passcod/timesimp
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/passcod/timesimp" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 92be20531742c87fc283ec0ed2fc2aa3b1f638ae
[INFO] testing passcod/timesimp against try#17092ad00ed8fe1e7f81a7e38238ff70779034b1 for pr-140985
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-0-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-0-tc2/source'...
[INFO] [stderr] done.
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain 17092ad00ed8fe1e7f81a7e38238ff70779034b1
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+17092ad00ed8fe1e7f81a7e38238ff70779034b1" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[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-0-tc2/source/Cargo.toml
[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" "+17092ad00ed8fe1e7f81a7e38238ff70779034b1" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+17092ad00ed8fe1e7f81a7e38238ff70779034b1" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] a8aac7cb795c0a56fb794855347236aa8c0e11301c3fd78cae98bc7f4dd18a57
[INFO] running `Command { std: "docker" "start" "-a" "a8aac7cb795c0a56fb794855347236aa8c0e11301c3fd78cae98bc7f4dd18a57", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "a8aac7cb795c0a56fb794855347236aa8c0e11301c3fd78cae98bc7f4dd18a57", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a8aac7cb795c0a56fb794855347236aa8c0e11301c3fd78cae98bc7f4dd18a57", kill_on_drop: false }`
[INFO] [stdout] a8aac7cb795c0a56fb794855347236aa8c0e11301c3fd78cae98bc7f4dd18a57
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+17092ad00ed8fe1e7f81a7e38238ff70779034b1" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 3249cc77f7046699c231319fc1a697696a8c9f7edb3f33d34121845fe5c7c421
[INFO] running `Command { std: "docker" "start" "-a" "3249cc77f7046699c231319fc1a697696a8c9f7edb3f33d34121845fe5c7c421", 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 pin-project-lite v0.2.16
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling ryu v1.0.20
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling dtor v0.0.6
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling ctor v0.4.2
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling 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 29.53s
[INFO] running `Command { std: "docker" "inspect" "3249cc77f7046699c231319fc1a697696a8c9f7edb3f33d34121845fe5c7c421", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3249cc77f7046699c231319fc1a697696a8c9f7edb3f33d34121845fe5c7c421", kill_on_drop: false }`
[INFO] [stdout] 3249cc77f7046699c231319fc1a697696a8c9f7edb3f33d34121845fe5c7c421
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+17092ad00ed8fe1e7f81a7e38238ff70779034b1" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 1f2add5c18d909e7c752d610d943b40b5524fe679e74dbd3f5e669f653ead5a8
[INFO] running `Command { std: "docker" "start" "-a" "1f2add5c18d909e7c752d610d943b40b5524fe679e74dbd3f5e669f653ead5a8", 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 bytes v1.10.1
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling futures-core v0.3.31
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling icu_properties_data v1.5.1
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling icu_normalizer_data v1.5.1
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling futures-sink v0.3.31
[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 serde v1.0.219
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling utf8_iter v1.0.4
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling tower-layer v0.3.3
[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 ipnet v2.11.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[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 getrandom v0.3.2
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling zerovec v0.10.4
[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 31.92s
[INFO] running `Command { std: "docker" "inspect" "1f2add5c18d909e7c752d610d943b40b5524fe679e74dbd3f5e669f653ead5a8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "1f2add5c18d909e7c752d610d943b40b5524fe679e74dbd3f5e669f653ead5a8", kill_on_drop: false }`
[INFO] [stdout] 1f2add5c18d909e7c752d610d943b40b5524fe679e74dbd3f5e669f653ead5a8
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-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:eea15d5475069c3ef791f10c2c6b5af2ee421ef2da1e680ecce1cba46243983b" "/opt/rustwide/cargo-home/bin/cargo" "+17092ad00ed8fe1e7f81a7e38238ff70779034b1" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 52b271f9761dbd8489887cfdd78b9aab14b1b4be7113282d1564745a21c85095
[INFO] running `Command { std: "docker" "start" "-a" "52b271f9761dbd8489887cfdd78b9aab14b1b4be7113282d1564745a21c85095", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.16s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-036bdeeb8c9e4dcb)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[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 messages::tests::round_trip_request ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-09243958293458e5)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] 2025-05-16T15:30:44.933541Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933510Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933502Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-05-16T15:30:44.933594Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933523Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933606Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933605Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933629Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933522Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933518Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933646Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933689Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933642Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933710Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933743Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933537Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-05-16T15:30:44.933510Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:44.933709Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933818Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.933836Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.937157Z TRACE new{response=Response { client: 2025-05-16T15:30:44.934825092Z, server: 2025-05-16T15:30:44.935953961Z } current=2025-05-16T15:30:44.937043271Z}: timesimp::delta: response processing internals latency=1ms 109µs 89ns local_at_midpoint=2025-05-16T15:30:44.935934181Z delta=19µs 780ns
[INFO] [stdout] 2025-05-16T15:30:44.937203Z TRACE timesimp: obtained raw offset from server latency=1.109089ms delta=19µs 780ns
[INFO] [stdout] 2025-05-16T15:30:44.937216Z DEBUG timesimp: no offset stored, storing initial delta offset=19µs 780ns
[INFO] [stdout] 2025-05-16T15:30:44.937224Z TRACE timesimp: sleeping to spread out requests delay=784.514415ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.945133Z TRACE new{response=Response { client: 2025-05-16T15:30:44.934825041Z, server: 2025-05-16T15:30:49.939948931Z } current=2025-05-16T15:30:44.94504348Z}: timesimp::delta: response processing internals latency=5ms 109µs 219ns local_at_midpoint=2025-05-16T15:30:44.93993426Z delta=5s 14µs 671ns
[INFO] [stdout] 2025-05-16T15:30:44.945185Z TRACE timesimp: obtained raw offset from server latency=5.109219ms delta=5s 14µs 671ns
[INFO] [stdout] 2025-05-16T15:30:44.945203Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 14µs 671ns
[INFO] [stdout] 2025-05-16T15:30:44.945217Z TRACE timesimp: sleeping to spread out requests delay=170.774822ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.949235Z TRACE new{response=Response { client: 2025-05-16T15:30:44.934928512Z, server: 2025-05-16T15:30:49.94204348Z } current=2025-05-16T15:30:44.94914517Z}: timesimp::delta: response processing internals latency=7ms 108µs 329ns local_at_midpoint=2025-05-16T15:30:44.942036841Z delta=5s 6µs 639ns
[INFO] [stdout] 2025-05-16T15:30:44.949283Z TRACE timesimp: obtained raw offset from server latency=7.108329ms delta=5s 6µs 639ns
[INFO] [stdout] 2025-05-16T15:30:44.949295Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 6µs 639ns
[INFO] [stdout] 2025-05-16T15:30:44.949307Z TRACE timesimp: sleeping to spread out requests delay=46.753588ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.957210Z TRACE new{response=Response { client: 2025-05-16T15:30:44.934857912Z, server: 2025-05-16T15:30:49.94598938Z } current=2025-05-16T15:30:44.957117719Z}: timesimp::delta: response processing internals latency=11ms 129µs 903ns local_at_midpoint=2025-05-16T15:30:44.945987815Z delta=5s 1µs 565ns
[INFO] [stdout] 2025-05-16T15:30:44.957237Z TRACE new{response=Response { client: 2025-05-16T15:30:44.934834372Z, server: 2025-05-16T15:30:44.94598428Z } current=2025-05-16T15:30:44.957129459Z}: timesimp::delta: response processing internals latency=11ms 147µs 543ns local_at_midpoint=2025-05-16T15:30:44.945981915Z delta=2µs 365ns
[INFO] [stdout] 2025-05-16T15:30:44.957262Z TRACE timesimp: obtained raw offset from server latency=11.129903ms delta=5s 1µs 565ns
[INFO] [stdout] 2025-05-16T15:30:44.957280Z DEBUG timesimp: no offset stored, storing initial delta offset=5s 1µs 565ns
[INFO] [stdout] 2025-05-16T15:30:44.957290Z TRACE timesimp: obtained raw offset from server latency=11.147543ms delta=2µs 365ns
[INFO] [stdout] 2025-05-16T15:30:44.957293Z TRACE timesimp: sleeping to spread out requests delay=244.203158ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.957309Z TRACE timesimp: sleeping to spread out requests delay=1.807829638s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.957367Z TRACE new{response=Response { client: 2025-05-16T15:30:44.935016821Z, server: 2025-05-16T15:30:44.94613451Z } current=2025-05-16T15:30:44.957257269Z}: timesimp::delta: response processing internals latency=11ms 120µs 224ns local_at_midpoint=2025-05-16T15:30:44.946137045Z delta=2µs 535ns ago
[INFO] [stdout] 2025-05-16T15:30:44.957427Z TRACE timesimp: obtained raw offset from server latency=11.120224ms delta=2µs 535ns ago
[INFO] [stdout] 2025-05-16T15:30:44.957440Z TRACE timesimp: sleeping to spread out requests delay=1.305990742s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.957431Z TRACE new{response=Response { client: 2025-05-16T15:30:44.935056101Z, server: 2025-05-16T15:30:49.94617966Z } current=2025-05-16T15:30:44.957320919Z}: timesimp::delta: response processing internals latency=11ms 132µs 409ns local_at_midpoint=2025-05-16T15:30:44.94618851Z delta=4s 999ms 991µs 150ns
[INFO] [stdout] 2025-05-16T15:30:44.957504Z TRACE timesimp: obtained raw offset from server latency=11.132409ms delta=4s 999ms 991µs 150ns
[INFO] [stdout] 2025-05-16T15:30:44.957453Z TRACE new{response=Response { client: 2025-05-16T15:30:44.935000701Z, server: 2025-05-16T15:30:39.94613269Z } current=2025-05-16T15:30:44.957260669Z}: timesimp::delta: response processing internals latency=11ms 129µs 984ns local_at_midpoint=2025-05-16T15:30:44.946130685Z delta=4s 999ms 997µs 995ns ago
[INFO] [stdout] 2025-05-16T15:30:44.957516Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 991µs 150ns
[INFO] [stdout] 2025-05-16T15:30:44.957551Z TRACE timesimp: sleeping to spread out requests delay=1.077592294s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:44.957552Z TRACE timesimp: obtained raw offset from server latency=11.129984ms delta=4s 999ms 997µs 995ns ago
[INFO] [stdout] 2025-05-16T15:30:44.957571Z DEBUG timesimp: no offset stored, storing initial delta offset=4s 999ms 997µs 995ns ago
[INFO] [stdout] 2025-05-16T15:30:44.957584Z TRACE timesimp: sleeping to spread out requests delay=1.795270009s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:45.010936Z TRACE new{response=Response { client: 2025-05-16T15:30:44.996484044Z, server: 2025-05-16T15:30:50.003691543Z } current=2025-05-16T15:30:45.010814572Z}: timesimp::delta: response processing internals latency=7ms 165µs 264ns local_at_midpoint=2025-05-16T15:30:45.003649308Z delta=5s 42µs 235ns
[INFO] [stdout] 2025-05-16T15:30:45.010996Z TRACE timesimp: obtained raw offset from server latency=7.165264ms delta=5s 42µs 235ns
[INFO] [stdout] 2025-05-16T15:30:45.011009Z TRACE timesimp: sleeping to spread out requests delay=1.161619806s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:45.135030Z TRACE new{response=Response { client: 2025-05-16T15:30:45.11662181Z, server: 2025-05-16T15:30:50.125780158Z } current=2025-05-16T15:30:45.134902167Z}: timesimp::delta: response processing internals latency=9ms 140µs 178ns local_at_midpoint=2025-05-16T15:30:45.125761988Z delta=5s 18µs 170ns
[INFO] [stdout] 2025-05-16T15:30:45.135086Z TRACE timesimp: obtained raw offset from server latency=9.140178ms delta=5s 18µs 170ns
[INFO] [stdout] 2025-05-16T15:30:45.135098Z TRACE timesimp: sleeping to spread out requests delay=59.619434ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:45.137631Z TRACE new{response=Response { client: 2025-05-16T15:30:44.934966581Z, server: 2025-05-16T15:30:45.036227679Z } current=2025-05-16T15:30:45.137516507Z}: timesimp::delta: response processing internals latency=101ms 274µs 963ns local_at_midpoint=2025-05-16T15:30:45.036241544Z delta=13µs 865ns ago
[INFO] [stdout] 2025-05-16T15:30:45.137688Z TRACE timesimp: obtained raw offset from server latency=101.274963ms delta=13µs 865ns ago
[INFO] [stdout] 2025-05-16T15:30:45.137705Z DEBUG timesimp: no offset stored, storing initial delta offset=13µs 865ns ago
[INFO] [stdout] 2025-05-16T15:30:45.137716Z TRACE timesimp: sleeping to spread out requests delay=1.906269166s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:45.203727Z TRACE new{response=Response { client: 2025-05-16T15:30:45.19539375Z, server: 2025-05-16T15:30:50.19950228Z } current=2025-05-16T15:30:45.203600019Z}: timesimp::delta: response processing internals latency=4ms 103µs 134ns local_at_midpoint=2025-05-16T15:30:45.199496884Z delta=5s 5µs 396ns
[INFO] [stdout] 2025-05-16T15:30:45.203787Z TRACE timesimp: obtained raw offset from server latency=4.103134ms delta=5s 5µs 396ns
[INFO] [stdout] 2025-05-16T15:30:45.203800Z TRACE timesimp: sleeping to spread out requests delay=1.900566705s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:45.222968Z TRACE new{response=Response { client: 2025-05-16T15:30:45.202650839Z, server: 2025-05-16T15:30:50.212779738Z } current=2025-05-16T15:30:45.222887247Z}: timesimp::delta: response processing internals latency=10ms 118µs 204ns local_at_midpoint=2025-05-16T15:30:45.212769043Z delta=5s 10µs 695ns
[INFO] [stdout] 2025-05-16T15:30:45.223011Z TRACE timesimp: obtained raw offset from server latency=10.118204ms delta=5s 10µs 695ns
[INFO] [stdout] 2025-05-16T15:30:45.223022Z TRACE timesimp: sleeping to spread out requests delay=142.109321ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:45.386809Z TRACE new{response=Response { client: 2025-05-16T15:30:45.366325989Z, server: 2025-05-16T15:30:50.376461758Z } current=2025-05-16T15:30:45.386689437Z}: timesimp::delta: response processing internals latency=10ms 181µs 724ns local_at_midpoint=2025-05-16T15:30:45.376507713Z delta=4s 999ms 954µs 45ns
[INFO] [stdout] 2025-05-16T15:30:45.386866Z TRACE timesimp: obtained raw offset from server latency=10.181724ms delta=4s 999ms 954µs 45ns
[INFO] [stdout] 2025-05-16T15:30:45.386879Z TRACE timesimp: sleeping to spread out requests delay=1.781040836s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:45.725008Z TRACE new{response=Response { client: 2025-05-16T15:30:45.722668946Z, server: 2025-05-16T15:30:45.723788746Z } current=2025-05-16T15:30:45.724881896Z}: timesimp::delta: response processing internals latency=1ms 106µs 475ns local_at_midpoint=2025-05-16T15:30:45.723775421Z delta=13µs 325ns
[INFO] [stdout] 2025-05-16T15:30:45.725062Z TRACE timesimp: obtained raw offset from server latency=1.106475ms delta=13µs 325ns
[INFO] [stdout] 2025-05-16T15:30:45.725075Z TRACE timesimp: sleeping to spread out requests delay=1.713032425s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.058285Z TRACE new{response=Response { client: 2025-05-16T15:30:46.035887659Z, server: 2025-05-16T15:30:51.047035398Z } current=2025-05-16T15:30:46.058163446Z}: timesimp::delta: response processing internals latency=11ms 137µs 893ns local_at_midpoint=2025-05-16T15:30:46.047025552Z delta=5s 9µs 846ns
[INFO] [stdout] 2025-05-16T15:30:46.058342Z TRACE timesimp: obtained raw offset from server latency=11.137893ms delta=5s 9µs 846ns
[INFO] [stdout] 2025-05-16T15:30:46.058355Z TRACE timesimp: sleeping to spread out requests delay=561.670404ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.191755Z TRACE new{response=Response { client: 2025-05-16T15:30:46.173392032Z, server: 2025-05-16T15:30:51.182509171Z } current=2025-05-16T15:30:46.1916299Z}: timesimp::delta: response processing internals latency=9ms 118µs 934ns local_at_midpoint=2025-05-16T15:30:46.182510966Z delta=4s 999ms 998µs 205ns
[INFO] [stdout] 2025-05-16T15:30:46.191809Z TRACE timesimp: obtained raw offset from server latency=9.118934ms delta=4s 999ms 998µs 205ns
[INFO] [stdout] 2025-05-16T15:30:46.191822Z TRACE timesimp: sleeping to spread out requests delay=506.140193ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.286342Z TRACE new{response=Response { client: 2025-05-16T15:30:46.264933401Z, server: 2025-05-16T15:30:46.27605612Z } current=2025-05-16T15:30:46.286272669Z}: timesimp::delta: response processing internals latency=10ms 669µs 634ns local_at_midpoint=2025-05-16T15:30:46.275603035Z delta=453µs 85ns
[INFO] [stdout] 2025-05-16T15:30:46.286387Z TRACE timesimp: obtained raw offset from server latency=10.669634ms delta=453µs 85ns
[INFO] [stdout] 2025-05-16T15:30:46.286398Z TRACE timesimp: sleeping to spread out requests delay=563.210241ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.525265Z TRACE new{response=Response { client: 2025-05-16T15:30:44.935028511Z, server: 2025-05-16T15:30:45.730044996Z } current=2025-05-16T15:30:46.52507825Z}: timesimp::delta: response processing internals latency=795ms 24µs 869ns local_at_midpoint=2025-05-16T15:30:45.73005338Z delta=8µs 384ns ago
[INFO] [stdout] 2025-05-16T15:30:46.525344Z TRACE timesimp: obtained raw offset from server latency=795.024869ms delta=8µs 384ns ago
[INFO] [stdout] 2025-05-16T15:30:46.525359Z DEBUG timesimp: no offset stored, storing initial delta offset=8µs 384ns ago
[INFO] [stdout] 2025-05-16T15:30:46.525368Z TRACE timesimp: sleeping to spread out requests delay=1.84998819s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.643524Z TRACE new{response=Response { client: 2025-05-16T15:30:46.621150538Z, server: 2025-05-16T15:30:51.632271387Z } current=2025-05-16T15:30:46.643382356Z}: timesimp::delta: response processing internals latency=11ms 115µs 909ns local_at_midpoint=2025-05-16T15:30:46.632266447Z delta=5s 4µs 940ns
[INFO] [stdout] 2025-05-16T15:30:46.643579Z TRACE timesimp: obtained raw offset from server latency=11.115909ms delta=5s 4µs 940ns
[INFO] [stdout] 2025-05-16T15:30:46.643591Z TRACE timesimp: sleeping to spread out requests delay=1.847593301s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.718821Z TRACE new{response=Response { client: 2025-05-16T15:30:46.698512629Z, server: 2025-05-16T15:30:51.708628608Z } current=2025-05-16T15:30:46.718731857Z}: timesimp::delta: response processing internals latency=10ms 109µs 614ns local_at_midpoint=2025-05-16T15:30:46.708622243Z delta=5s 6µs 365ns
[INFO] [stdout] 2025-05-16T15:30:46.718874Z TRACE timesimp: obtained raw offset from server latency=10.109614ms delta=5s 6µs 365ns
[INFO] [stdout] 2025-05-16T15:30:46.718888Z TRACE timesimp: sleeping to spread out requests delay=223.000656ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.776059Z TRACE new{response=Response { client: 2025-05-16T15:30:46.753691153Z, server: 2025-05-16T15:30:41.764846001Z } current=2025-05-16T15:30:46.77598768Z}: timesimp::delta: response processing internals latency=11ms 148µs 263ns local_at_midpoint=2025-05-16T15:30:46.764839416Z delta=4s 999ms 993µs 415ns ago
[INFO] [stdout] 2025-05-16T15:30:46.776109Z TRACE timesimp: obtained raw offset from server latency=11.148263ms delta=4s 999ms 993µs 415ns ago
[INFO] [stdout] 2025-05-16T15:30:46.776127Z TRACE timesimp: sleeping to spread out requests delay=587.053209ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.788613Z TRACE new{response=Response { client: 2025-05-16T15:30:46.766280251Z, server: 2025-05-16T15:30:46.77740373Z } current=2025-05-16T15:30:46.788540358Z}: timesimp::delta: response processing internals latency=11ms 130µs 53ns local_at_midpoint=2025-05-16T15:30:46.777410304Z delta=6µs 574ns ago
[INFO] [stdout] 2025-05-16T15:30:46.788657Z TRACE timesimp: obtained raw offset from server latency=11.130053ms delta=6µs 574ns ago
[INFO] [stdout] 2025-05-16T15:30:46.788674Z TRACE timesimp: sleeping to spread out requests delay=287.070574ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.873064Z TRACE new{response=Response { client: 2025-05-16T15:30:46.850637271Z, server: 2025-05-16T15:30:46.86187388Z } current=2025-05-16T15:30:46.872994788Z}: timesimp::delta: response processing internals latency=11ms 178µs 758ns local_at_midpoint=2025-05-16T15:30:46.861816029Z delta=57µs 851ns
[INFO] [stdout] 2025-05-16T15:30:46.873108Z TRACE timesimp: obtained raw offset from server latency=11.178758ms delta=57µs 851ns
[INFO] [stdout] 2025-05-16T15:30:46.873120Z TRACE timesimp: sleeping to spread out requests delay=1.143970123s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:46.955609Z TRACE new{response=Response { client: 2025-05-16T15:30:46.94330184Z, server: 2025-05-16T15:30:51.949421609Z } current=2025-05-16T15:30:46.955539568Z}: timesimp::delta: response processing internals latency=6ms 118µs 864ns local_at_midpoint=2025-05-16T15:30:46.949420704Z delta=5s 905ns
[INFO] [stdout] 2025-05-16T15:30:46.955653Z TRACE timesimp: obtained raw offset from server latency=6.118864ms delta=5s 905ns
[INFO] [stdout] 2025-05-16T15:30:46.955677Z TRACE timesimp: response deltas sorted by latency deltas=[5000.000905, 5000.006639, 5000.042235, 4999.998205, 5000.006365]
[INFO] [stdout] 2025-05-16T15:30:46.955688Z TRACE timesimp: statistics about response deltas median=5000.042235 mean=5000.0108698 variance=0.000320415765198941 stddev=0.01790016103835217
[INFO] [stdout] 2025-05-16T15:30:46.955703Z TRACE timesimp: eliminated outliers inliers=[5000.042235]
[INFO] [stdout] 2025-05-16T15:30:46.955718Z DEBUG timesimp: storing calculated offset offset=5s 42µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] 2025-05-16T15:30:47.099488Z TRACE new{response=Response { client: 2025-05-16T15:30:47.077124463Z, server: 2025-05-16T15:30:47.088253992Z } current=2025-05-16T15:30:47.099379951Z}: timesimp::delta: response processing internals latency=11ms 127µs 744ns local_at_midpoint=2025-05-16T15:30:47.088252207Z delta=1µs 785ns
[INFO] [stdout] 2025-05-16T15:30:47.099546Z TRACE timesimp: obtained raw offset from server latency=11.127744ms delta=1µs 785ns
[INFO] [stdout] 2025-05-16T15:30:47.099560Z TRACE timesimp: sleeping to spread out requests delay=1.016677181s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.118283Z TRACE new{response=Response { client: 2025-05-16T15:30:47.10584839Z, server: 2025-05-16T15:30:52.112092809Z } current=2025-05-16T15:30:47.118216529Z}: timesimp::delta: response processing internals latency=6ms 184µs 69ns local_at_midpoint=2025-05-16T15:30:47.112032459Z delta=5s 60µs 350ns
[INFO] [stdout] 2025-05-16T15:30:47.118328Z TRACE timesimp: obtained raw offset from server latency=6.184069ms delta=5s 60µs 350ns
[INFO] [stdout] 2025-05-16T15:30:47.118339Z TRACE timesimp: sleeping to spread out requests delay=34.056623ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.161818Z TRACE new{response=Response { client: 2025-05-16T15:30:47.153489754Z, server: 2025-05-16T15:30:52.157610244Z } current=2025-05-16T15:30:47.161744453Z}: timesimp::delta: response processing internals latency=4ms 127µs 349ns local_at_midpoint=2025-05-16T15:30:47.157617103Z delta=4s 999ms 993µs 141ns
[INFO] [stdout] 2025-05-16T15:30:47.161868Z TRACE timesimp: obtained raw offset from server latency=4.127349ms delta=4s 999ms 993µs 141ns
[INFO] [stdout] 2025-05-16T15:30:47.161883Z TRACE timesimp: response deltas sorted by latency deltas=[5000.005396, 4999.993141, 5000.014671, 5000.06035, 5000.01817]
[INFO] [stdout] 2025-05-16T15:30:47.161894Z TRACE timesimp: statistics about response deltas median=5000.014671 mean=5000.0183455999995 variance=0.0006452167852985563 stddev=0.025401117796241886
[INFO] [stdout] 2025-05-16T15:30:47.161907Z TRACE timesimp: eliminated outliers inliers=[5000.005396, 4999.993141, 5000.014671, 5000.01817]
[INFO] [stdout] 2025-05-16T15:30:47.161915Z DEBUG timesimp: storing calculated offset offset=5s 7µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] 2025-05-16T15:30:47.191057Z TRACE new{response=Response { client: 2025-05-16T15:30:47.168630363Z, server: 2025-05-16T15:30:52.179845651Z } current=2025-05-16T15:30:47.1909793Z}: timesimp::delta: response processing internals latency=11ms 174µs 468ns local_at_midpoint=2025-05-16T15:30:47.179804831Z delta=5s 40µs 820ns
[INFO] [stdout] 2025-05-16T15:30:47.191108Z TRACE timesimp: obtained raw offset from server latency=11.174468ms delta=5s 40µs 820ns
[INFO] [stdout] 2025-05-16T15:30:47.191121Z TRACE timesimp: sleeping to spread out requests delay=12.599205ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.225562Z TRACE new{response=Response { client: 2025-05-16T15:30:47.204261448Z, server: 2025-05-16T15:30:52.214371567Z } current=2025-05-16T15:30:47.225488836Z}: timesimp::delta: response processing internals latency=10ms 613µs 694ns local_at_midpoint=2025-05-16T15:30:47.214875142Z delta=4s 999ms 496µs 425ns
[INFO] [stdout] 2025-05-16T15:30:47.225609Z TRACE timesimp: obtained raw offset from server latency=10.613694ms delta=4s 999ms 496µs 425ns
[INFO] [stdout] 2025-05-16T15:30:47.225622Z TRACE timesimp: response deltas sorted by latency deltas=[5000.010695, 4999.954045, 4999.496425, 5000.001565, 5000.04082]
[INFO] [stdout] 2025-05-16T15:30:47.225632Z TRACE timesimp: statistics about response deltas median=4999.496425 mean=4999.90071 variance=0.05204755669994277 stddev=0.228139336152148
[INFO] [stdout] 2025-05-16T15:30:47.225643Z TRACE timesimp: eliminated outliers inliers=[4999.496425]
[INFO] [stdout] 2025-05-16T15:30:47.225650Z DEBUG timesimp: storing calculated offset offset=4s 999ms 496µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] 2025-05-16T15:30:47.247412Z TRACE new{response=Response { client: 2025-05-16T15:30:47.044812798Z, server: 2025-05-16T15:30:47.146061505Z } current=2025-05-16T15:30:47.247333483Z}: timesimp::delta: response processing internals latency=101ms 260µs 342ns local_at_midpoint=2025-05-16T15:30:47.14607314Z delta=11µs 635ns ago
[INFO] [stdout] 2025-05-16T15:30:47.247462Z TRACE timesimp: obtained raw offset from server latency=101.260342ms delta=11µs 635ns ago
[INFO] [stdout] 2025-05-16T15:30:47.247496Z TRACE timesimp: sleeping to spread out requests delay=88.335722ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.386423Z TRACE new{response=Response { client: 2025-05-16T15:30:47.363934209Z, server: 2025-05-16T15:30:42.375207338Z } current=2025-05-16T15:30:47.386349786Z}: timesimp::delta: response processing internals latency=11ms 207µs 788ns local_at_midpoint=2025-05-16T15:30:47.375141997Z delta=4s 999ms 934µs 659ns ago
[INFO] [stdout] 2025-05-16T15:30:47.386494Z TRACE timesimp: obtained raw offset from server latency=11.207788ms delta=4s 999ms 934µs 659ns ago
[INFO] [stdout] 2025-05-16T15:30:47.386513Z TRACE timesimp: sleeping to spread out requests delay=508.493437ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.441263Z TRACE new{response=Response { client: 2025-05-16T15:30:47.43901018Z, server: 2025-05-16T15:30:47.44010731Z } current=2025-05-16T15:30:47.44119675Z}: timesimp::delta: response processing internals latency=1ms 93µs 285ns local_at_midpoint=2025-05-16T15:30:47.440103465Z delta=3µs 845ns
[INFO] [stdout] 2025-05-16T15:30:47.441306Z TRACE timesimp: obtained raw offset from server latency=1.093285ms delta=3µs 845ns
[INFO] [stdout] 2025-05-16T15:30:47.441317Z TRACE timesimp: sleeping to spread out requests delay=370.454748ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.539379Z TRACE new{response=Response { client: 2025-05-16T15:30:47.336756722Z, server: 2025-05-16T15:30:47.43803838Z } current=2025-05-16T15:30:47.539288988Z}: timesimp::delta: response processing internals latency=101ms 266µs 133ns local_at_midpoint=2025-05-16T15:30:47.438022855Z delta=15µs 525ns
[INFO] [stdout] 2025-05-16T15:30:47.539438Z TRACE timesimp: obtained raw offset from server latency=101.266133ms delta=15µs 525ns
[INFO] [stdout] 2025-05-16T15:30:47.539452Z TRACE timesimp: sleeping to spread out requests delay=661.167233ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.815286Z TRACE new{response=Response { client: 2025-05-16T15:30:47.812950095Z, server: 2025-05-16T15:30:47.814062255Z } current=2025-05-16T15:30:47.815153275Z}: timesimp::delta: response processing internals latency=1ms 101µs 590ns local_at_midpoint=2025-05-16T15:30:47.814051685Z delta=10µs 570ns
[INFO] [stdout] 2025-05-16T15:30:47.815347Z TRACE timesimp: obtained raw offset from server latency=1.10159ms delta=10µs 570ns
[INFO] [stdout] 2025-05-16T15:30:47.815360Z TRACE timesimp: sleeping to spread out requests delay=269.329238ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:47.918729Z TRACE new{response=Response { client: 2025-05-16T15:30:47.896273205Z, server: 2025-05-16T15:30:42.907433544Z } current=2025-05-16T15:30:47.918592272Z}: timesimp::delta: response processing internals latency=11ms 159µs 533ns local_at_midpoint=2025-05-16T15:30:47.907432738Z delta=4s 999ms 999µs 194ns ago
[INFO] [stdout] 2025-05-16T15:30:47.918801Z TRACE timesimp: obtained raw offset from server latency=11.159533ms delta=4s 999ms 999µs 194ns ago
[INFO] [stdout] 2025-05-16T15:30:47.918823Z TRACE timesimp: sleeping to spread out requests delay=874.458718ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:48.040988Z TRACE new{response=Response { client: 2025-05-16T15:30:48.01852484Z, server: 2025-05-16T15:30:48.029663609Z } current=2025-05-16T15:30:48.040841107Z}: timesimp::delta: response processing internals latency=11ms 158µs 133ns local_at_midpoint=2025-05-16T15:30:48.029682973Z delta=19µs 364ns ago
[INFO] [stdout] 2025-05-16T15:30:48.041050Z TRACE timesimp: obtained raw offset from server latency=11.158133ms delta=19µs 364ns ago
[INFO] [stdout] 2025-05-16T15:30:48.041063Z TRACE timesimp: sleeping to spread out requests delay=809.038414ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:48.088170Z TRACE new{response=Response { client: 2025-05-16T15:30:48.085836162Z, server: 2025-05-16T15:30:48.086975682Z } current=2025-05-16T15:30:48.088099672Z}: timesimp::delta: response processing internals latency=1ms 131µs 755ns local_at_midpoint=2025-05-16T15:30:48.086967917Z delta=7µs 765ns
[INFO] [stdout] 2025-05-16T15:30:48.088214Z TRACE timesimp: obtained raw offset from server latency=1.131755ms delta=7µs 765ns
[INFO] [stdout] 2025-05-16T15:30:48.088229Z TRACE timesimp: response deltas sorted by latency deltas=[0.003845, 0.01057, 0.013325, 0.01978, 0.007765]
[INFO] [stdout] 2025-05-16T15:30:48.088240Z TRACE timesimp: statistics about response deltas median=0.013325 mean=0.011057 variance=3.60804825e-5 stddev=0.0060067031306699345
[INFO] [stdout] 2025-05-16T15:30:48.088252Z TRACE timesimp: eliminated outliers inliers=[0.01057, 0.013325, 0.007765]
[INFO] [stdout] 2025-05-16T15:30:48.088260Z DEBUG timesimp: storing calculated offset offset=10µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] 2025-05-16T15:30:48.140198Z TRACE new{response=Response { client: 2025-05-16T15:30:48.117743248Z, server: 2025-05-16T15:30:48.128875427Z } current=2025-05-16T15:30:48.140117896Z}: timesimp::delta: response processing internals latency=11ms 187µs 324ns local_at_midpoint=2025-05-16T15:30:48.128930572Z delta=55µs 145ns ago
[INFO] [stdout] 2025-05-16T15:30:48.140249Z TRACE timesimp: obtained raw offset from server latency=11.187324ms delta=55µs 145ns ago
[INFO] [stdout] 2025-05-16T15:30:48.140262Z TRACE timesimp: sleeping to spread out requests delay=82.387067ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:48.245836Z TRACE new{response=Response { client: 2025-05-16T15:30:48.223531056Z, server: 2025-05-16T15:30:48.234647994Z } current=2025-05-16T15:30:48.245765663Z}: timesimp::delta: response processing internals latency=11ms 117µs 303ns local_at_midpoint=2025-05-16T15:30:48.234648359Z delta=365ns ago
[INFO] [stdout] 2025-05-16T15:30:48.245881Z TRACE timesimp: obtained raw offset from server latency=11.117303ms delta=365ns ago
[INFO] [stdout] 2025-05-16T15:30:48.245895Z TRACE timesimp: response deltas sorted by latency deltas=[-0.000365, 0.001785, -0.006574, 0.002365, -0.055145]
[INFO] [stdout] 2025-05-16T15:30:48.245905Z TRACE timesimp: statistics about response deltas median=-0.006574 mean=-0.0115868 variance=0.0006054578761999999 stddev=0.02460605364945789
[INFO] [stdout] 2025-05-16T15:30:48.245917Z TRACE timesimp: eliminated outliers inliers=[-0.000365, 0.001785, -0.006574, 0.002365]
[INFO] [stdout] 2025-05-16T15:30:48.245925Z DEBUG timesimp: storing calculated offset offset=0s
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] 2025-05-16T15:30:48.405027Z TRACE new{response=Response { client: 2025-05-16T15:30:48.202378288Z, server: 2025-05-16T15:30:48.303630126Z } current=2025-05-16T15:30:48.404947034Z}: timesimp::delta: response processing internals latency=101ms 284µs 373ns local_at_midpoint=2025-05-16T15:30:48.303662661Z delta=32µs 535ns ago
[INFO] [stdout] 2025-05-16T15:30:48.405078Z TRACE timesimp: obtained raw offset from server latency=101.284373ms delta=32µs 535ns ago
[INFO] [stdout] 2025-05-16T15:30:48.405091Z TRACE timesimp: sleeping to spread out requests delay=1.538799834s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:48.515171Z TRACE new{response=Response { client: 2025-05-16T15:30:48.492704663Z, server: 2025-05-16T15:30:53.503870292Z } current=2025-05-16T15:30:48.515027061Z}: timesimp::delta: response processing internals latency=11ms 161µs 199ns local_at_midpoint=2025-05-16T15:30:48.503865862Z delta=5s 4µs 430ns
[INFO] [stdout] 2025-05-16T15:30:48.515238Z TRACE timesimp: obtained raw offset from server latency=11.161199ms delta=5s 4µs 430ns
[INFO] [stdout] 2025-05-16T15:30:48.515253Z TRACE timesimp: sleeping to spread out requests delay=1.435388178s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:48.816286Z TRACE new{response=Response { client: 2025-05-16T15:30:48.793915567Z, server: 2025-05-16T15:30:43.805044306Z } current=2025-05-16T15:30:48.816171994Z}: timesimp::delta: response processing internals latency=11ms 128µs 213ns local_at_midpoint=2025-05-16T15:30:48.80504378Z delta=4s 999ms 999µs 474ns ago
[INFO] [stdout] 2025-05-16T15:30:48.816349Z TRACE timesimp: obtained raw offset from server latency=11.128213ms delta=4s 999ms 999µs 474ns ago
[INFO] [stdout] 2025-05-16T15:30:48.816375Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.999474, -4999.997995, -4999.993415, -4999.999194, -4999.9346590000005]
[INFO] [stdout] 2025-05-16T15:30:48.816393Z TRACE timesimp: statistics about response deltas median=-4999.993415 mean=-4999.9849474 variance=0.0007962127522874072 stddev=0.028217242109876847
[INFO] [stdout] 2025-05-16T15:30:48.816410Z TRACE timesimp: eliminated outliers inliers=[-4999.999474, -4999.997995, -4999.993415, -4999.999194]
[INFO] [stdout] 2025-05-16T15:30:48.816422Z DEBUG timesimp: storing calculated offset offset=4s 999ms 997µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] 2025-05-16T15:30:48.874409Z TRACE new{response=Response { client: 2025-05-16T15:30:48.85208267Z, server: 2025-05-16T15:30:48.863195919Z } current=2025-05-16T15:30:48.874306277Z}: timesimp::delta: response processing internals latency=11ms 111µs 803ns local_at_midpoint=2025-05-16T15:30:48.863194473Z delta=1µs 446ns
[INFO] [stdout] 2025-05-16T15:30:48.874483Z TRACE timesimp: obtained raw offset from server latency=11.111803ms delta=1µs 446ns
[INFO] [stdout] 2025-05-16T15:30:48.874501Z TRACE timesimp: response deltas sorted by latency deltas=[0.453085, 0.001446, -0.002535, -0.019364, 0.057851]
[INFO] [stdout] 2025-05-16T15:30:48.874512Z TRACE timesimp: statistics about response deltas median=-0.002535 mean=0.0980966 variance=0.0402253806013 stddev=0.20056266003745563
[INFO] [stdout] 2025-05-16T15:30:48.874525Z TRACE timesimp: eliminated outliers inliers=[0.001446, -0.002535, -0.019364, 0.057851]
[INFO] [stdout] 2025-05-16T15:30:48.874537Z DEBUG timesimp: storing calculated offset offset=9µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] 2025-05-16T15:30:49.974460Z TRACE new{response=Response { client: 2025-05-16T15:30:49.952052157Z, server: 2025-05-16T15:30:54.963200796Z } current=2025-05-16T15:30:49.974319975Z}: timesimp::delta: response processing internals latency=11ms 133µs 909ns local_at_midpoint=2025-05-16T15:30:49.963186066Z delta=5s 14µs 730ns
[INFO] [stdout] 2025-05-16T15:30:49.974560Z TRACE timesimp: obtained raw offset from server latency=11.133909ms delta=5s 14µs 730ns
[INFO] [stdout] 2025-05-16T15:30:49.974580Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00494, 4999.99115, 5000.01473, 5000.009846, 5000.00443]
[INFO] [stdout] 2025-05-16T15:30:49.974593Z TRACE timesimp: statistics about response deltas median=5000.01473 mean=5000.0050192 variance=7.757644320036942e-5 stddev=0.008807749042767364
[INFO] [stdout] 2025-05-16T15:30:49.974607Z TRACE timesimp: eliminated outliers inliers=[5000.01473, 5000.009846]
[INFO] [stdout] 2025-05-16T15:30:49.974617Z DEBUG timesimp: storing calculated offset offset=5s 12µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] 2025-05-16T15:30:50.147807Z TRACE new{response=Response { client: 2025-05-16T15:30:49.944978598Z, server: 2025-05-16T15:30:50.046250706Z } current=2025-05-16T15:30:50.147604534Z}: timesimp::delta: response processing internals latency=101ms 312µs 968ns local_at_midpoint=2025-05-16T15:30:50.046291566Z delta=40µs 860ns ago
[INFO] [stdout] 2025-05-16T15:30:50.147884Z TRACE timesimp: obtained raw offset from server latency=101.312968ms delta=40µs 860ns ago
[INFO] [stdout] 2025-05-16T15:30:50.147906Z TRACE timesimp: response deltas sorted by latency deltas=[-0.011635, 0.015525, -0.013865, -0.032535, -0.04086]
[INFO] [stdout] 2025-05-16T15:30:50.147920Z TRACE timesimp: statistics about response deltas median=-0.013865 mean=-0.016674 variance=0.00047664788 stddev=0.02183226694596784
[INFO] [stdout] 2025-05-16T15:30:50.147936Z TRACE timesimp: eliminated outliers inliers=[-0.011635, -0.013865, -0.032535]
[INFO] [stdout] 2025-05-16T15:30:50.147945Z DEBUG timesimp: storing calculated offset offset=19µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] 2025-05-16T15:30:50.173274Z TRACE new{response=Response { client: 2025-05-16T15:30:48.376569587Z, server: 2025-05-16T15:30:49.274922609Z } current=2025-05-16T15:30:50.173124081Z}: timesimp::delta: response processing internals latency=898ms 277µs 247ns local_at_midpoint=2025-05-16T15:30:49.274846834Z delta=75µs 775ns
[INFO] [stdout] 2025-05-16T15:30:50.173346Z TRACE timesimp: obtained raw offset from server latency=898.277247ms delta=75µs 775ns
[INFO] [stdout] 2025-05-16T15:30:50.173362Z TRACE timesimp: sleeping to spread out requests delay=1.21903363s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:52.808096Z TRACE new{response=Response { client: 2025-05-16T15:30:51.393878234Z, server: 2025-05-16T15:30:52.100947249Z } current=2025-05-16T15:30:52.807942404Z}: timesimp::delta: response processing internals latency=707ms 32µs 85ns local_at_midpoint=2025-05-16T15:30:52.100910319Z delta=36µs 930ns
[INFO] [stdout] 2025-05-16T15:30:52.808175Z TRACE timesimp: obtained raw offset from server latency=707.032085ms delta=36µs 930ns
[INFO] [stdout] 2025-05-16T15:30:52.808191Z TRACE timesimp: sleeping to spread out requests delay=471.268962ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:54.804443Z TRACE new{response=Response { client: 2025-05-16T15:30:53.281134857Z, server: 2025-05-16T15:30:54.042212515Z } current=2025-05-16T15:30:54.804288773Z}: timesimp::delta: response processing internals latency=761ms 576µs 958ns local_at_midpoint=2025-05-16T15:30:54.042711815Z delta=499µs 300ns ago
[INFO] [stdout] 2025-05-16T15:30:54.804551Z TRACE timesimp: obtained raw offset from server latency=761.576958ms delta=499µs 300ns ago
[INFO] [stdout] 2025-05-16T15:30:54.804567Z TRACE timesimp: sleeping to spread out requests delay=1.411318668s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.716641Z TRACE new{response=Response { client: 2025-05-16T15:30:56.217269873Z, server: 2025-05-16T15:30:56.967312773Z } current=2025-05-16T15:30:57.716488803Z}: timesimp::delta: response processing internals latency=749ms 609µs 465ns local_at_midpoint=2025-05-16T15:30:56.966879338Z delta=433µs 435ns
[INFO] [stdout] 2025-05-16T15:30:57.716714Z TRACE timesimp: obtained raw offset from server latency=749.609465ms delta=433µs 435ns
[INFO] [stdout] 2025-05-16T15:30:57.716736Z TRACE timesimp: response deltas sorted by latency deltas=[0.03693, 0.433435, -0.4993, -0.008384, 0.075775]
[INFO] [stdout] 2025-05-16T15:30:57.716750Z TRACE timesimp: statistics about response deltas median=-0.4993 mean=0.0076912000000000005 variance=0.11101164585469998 stddev=0.33318410204374993
[INFO] [stdout] 2025-05-16T15:30:57.716763Z TRACE timesimp: eliminated outliers inliers=[-0.4993]
[INFO] [stdout] 2025-05-16T15:30:57.716772Z DEBUG timesimp: storing calculated offset offset=499µs ago
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.78s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-574d3266540594fe)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] 2025-05-16T15:30:57.720156Z TRACE timesimp: starting delta collection samples=5 current_offset=5s ago
[INFO] [stdout] 2025-05-16T15:30:57.720176Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:57.720156Z TRACE timesimp: starting delta collection samples=5 current_offset=0s
[INFO] [stdout] 2025-05-16T15:30:57.720215Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.720161Z TRACE timesimp: starting delta collection samples=5 current_offset=5s
[INFO] [stdout] 2025-05-16T15:30:57.720228Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.720223Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.720239Z TRACE timesimp: sleeping to spread out requests delay=0ns max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.721536Z TRACE new{response=Response { client: 2025-05-16T15:30:57.721406292Z, server: 2025-05-16T15:30:57.721410312Z } current=2025-05-16T15:30:57.721412252Z}: timesimp::delta: response processing internals latency=2µs 980ns local_at_midpoint=2025-05-16T15:30:57.721409272Z delta=1µs 40ns
[INFO] [stdout] 2025-05-16T15:30:57.721537Z TRACE new{response=Response { client: 2025-05-16T15:30:57.721402672Z, server: 2025-05-16T15:31:02.721411702Z } current=2025-05-16T15:30:57.721413092Z}: timesimp::delta: response processing internals latency=5µs 210ns local_at_midpoint=2025-05-16T15:30:57.721407882Z delta=5s 3µs 820ns
[INFO] [stdout] 2025-05-16T15:30:57.721587Z TRACE timesimp: obtained raw offset from server latency=2.98µs delta=1µs 40ns
[INFO] [stdout] 2025-05-16T15:30:57.721569Z TRACE new{response=Response { client: 2025-05-16T15:30:57.721413802Z, server: 2025-05-16T15:30:57.721421262Z } current=2025-05-16T15:30:57.721423562Z}: timesimp::delta: response processing internals latency=4µs 880ns local_at_midpoint=2025-05-16T15:30:57.721418682Z delta=2µs 580ns
[INFO] [stdout] 2025-05-16T15:30:57.721538Z TRACE new{response=Response { client: 2025-05-16T15:30:57.721402882Z, server: 2025-05-16T15:30:52.721412982Z } current=2025-05-16T15:30:57.721414462Z}: timesimp::delta: response processing internals latency=5µs 790ns local_at_midpoint=2025-05-16T15:30:57.721408672Z delta=4s 999ms 995µs 690ns ago
[INFO] [stdout] 2025-05-16T15:30:57.721600Z DEBUG timesimp: no offset stored, storing initial delta offset=1µs 40ns
[INFO] [stdout] 2025-05-16T15:30:57.721597Z TRACE timesimp: obtained raw offset from server latency=5.21µs delta=5s 3µs 820ns
[INFO] [stdout] 2025-05-16T15:30:57.721608Z TRACE timesimp: sleeping to spread out requests delay=1.750718645s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.721609Z TRACE timesimp: sleeping to spread out requests delay=913.363384ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.721611Z TRACE timesimp: obtained raw offset from server latency=4.88µs delta=2µs 580ns
[INFO] [stdout] 2025-05-16T15:30:57.721622Z TRACE timesimp: obtained raw offset from server latency=5.79µs delta=4s 999ms 995µs 690ns ago
[INFO] [stdout] 2025-05-16T15:30:57.721622Z TRACE timesimp: sleeping to spread out requests delay=846.617548ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.721653Z TRACE timesimp: sleeping to spread out requests delay=67.048698ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:57.790038Z TRACE new{response=Response { client: 2025-05-16T15:30:57.789950444Z, server: 2025-05-16T15:30:52.789954234Z } current=2025-05-16T15:30:57.789955904Z}: timesimp::delta: response processing internals latency=2µs 730ns local_at_midpoint=2025-05-16T15:30:57.789953174Z delta=4s 999ms 998µs 940ns ago
[INFO] [stdout] 2025-05-16T15:30:57.790091Z TRACE timesimp: obtained raw offset from server latency=2.73µs delta=4s 999ms 998µs 940ns ago
[INFO] [stdout] 2025-05-16T15:30:57.790108Z TRACE timesimp: sleeping to spread out requests delay=1.657833075s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:58.569940Z TRACE new{response=Response { client: 2025-05-16T15:30:58.56979744Z, server: 2025-05-16T15:30:58.56980775Z } current=2025-05-16T15:30:58.56981009Z}: timesimp::delta: response processing internals latency=6µs 325ns local_at_midpoint=2025-05-16T15:30:58.569803765Z delta=3µs 985ns
[INFO] [stdout] 2025-05-16T15:30:58.570003Z TRACE timesimp: obtained raw offset from server latency=6.325µs delta=3µs 985ns
[INFO] [stdout] 2025-05-16T15:30:58.570022Z TRACE timesimp: sleeping to spread out requests delay=1.899225747s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:58.637001Z TRACE new{response=Response { client: 2025-05-16T15:30:58.636844062Z, server: 2025-05-16T15:31:03.636854432Z } current=2025-05-16T15:30:58.636856942Z}: timesimp::delta: response processing internals latency=6µs 440ns local_at_midpoint=2025-05-16T15:30:58.636850502Z delta=5s 3µs 930ns
[INFO] [stdout] 2025-05-16T15:30:58.637063Z TRACE timesimp: obtained raw offset from server latency=6.44µs delta=5s 3µs 930ns
[INFO] [stdout] 2025-05-16T15:30:58.637076Z TRACE timesimp: sleeping to spread out requests delay=696.682069ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:59.334149Z TRACE new{response=Response { client: 2025-05-16T15:30:59.334007258Z, server: 2025-05-16T15:31:04.334017058Z } current=2025-05-16T15:30:59.334019338Z}: timesimp::delta: response processing internals latency=6µs 40ns local_at_midpoint=2025-05-16T15:30:59.334013298Z delta=5s 3µs 760ns
[INFO] [stdout] 2025-05-16T15:30:59.334208Z TRACE timesimp: obtained raw offset from server latency=6.04µs delta=5s 3µs 760ns
[INFO] [stdout] 2025-05-16T15:30:59.334221Z TRACE timesimp: sleeping to spread out requests delay=1.585631205s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:59.450163Z TRACE new{response=Response { client: 2025-05-16T15:30:59.449997294Z, server: 2025-05-16T15:30:54.450008604Z } current=2025-05-16T15:30:59.450011384Z}: timesimp::delta: response processing internals latency=7µs 45ns local_at_midpoint=2025-05-16T15:30:59.450004339Z delta=4s 999ms 995µs 735ns ago
[INFO] [stdout] 2025-05-16T15:30:59.450246Z TRACE timesimp: obtained raw offset from server latency=7.045µs delta=4s 999ms 995µs 735ns ago
[INFO] [stdout] 2025-05-16T15:30:59.450270Z TRACE timesimp: sleeping to spread out requests delay=1.306225623s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:59.473711Z TRACE new{response=Response { client: 2025-05-16T15:30:59.473627101Z, server: 2025-05-16T15:30:59.473632141Z } current=2025-05-16T15:30:59.473632681Z}: timesimp::delta: response processing internals latency=2µs 790ns local_at_midpoint=2025-05-16T15:30:59.473629891Z delta=2µs 250ns
[INFO] [stdout] 2025-05-16T15:30:59.473756Z TRACE timesimp: obtained raw offset from server latency=2.79µs delta=2µs 250ns
[INFO] [stdout] 2025-05-16T15:30:59.473768Z TRACE timesimp: sleeping to spread out requests delay=205.057195ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:59.679298Z TRACE new{response=Response { client: 2025-05-16T15:30:59.679184177Z, server: 2025-05-16T15:30:59.679192077Z } current=2025-05-16T15:30:59.679192847Z}: timesimp::delta: response processing internals latency=4µs 335ns local_at_midpoint=2025-05-16T15:30:59.679188512Z delta=3µs 565ns
[INFO] [stdout] 2025-05-16T15:30:59.679348Z TRACE timesimp: obtained raw offset from server latency=4.335µs delta=3µs 565ns
[INFO] [stdout] 2025-05-16T15:30:59.679360Z TRACE timesimp: sleeping to spread out requests delay=153.810869ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:30:59.834837Z TRACE new{response=Response { client: 2025-05-16T15:30:59.834731988Z, server: 2025-05-16T15:30:59.834738758Z } current=2025-05-16T15:30:59.834739348Z}: timesimp::delta: response processing internals latency=3µs 680ns local_at_midpoint=2025-05-16T15:30:59.834735668Z delta=3µs 90ns
[INFO] [stdout] 2025-05-16T15:30:59.834889Z TRACE timesimp: obtained raw offset from server latency=3.68µs delta=3µs 90ns
[INFO] [stdout] 2025-05-16T15:30:59.834901Z TRACE timesimp: sleeping to spread out requests delay=914.699957ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:31:00.470379Z TRACE new{response=Response { client: 2025-05-16T15:31:00.470233851Z, server: 2025-05-16T15:31:00.470243731Z } current=2025-05-16T15:31:00.470246001Z}: timesimp::delta: response processing internals latency=6µs 75ns local_at_midpoint=2025-05-16T15:31:00.470239926Z delta=3µs 805ns
[INFO] [stdout] 2025-05-16T15:31:00.470441Z TRACE timesimp: obtained raw offset from server latency=6.075µs delta=3µs 805ns
[INFO] [stdout] 2025-05-16T15:31:00.470454Z TRACE timesimp: sleeping to spread out requests delay=330.717674ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:31:00.750205Z TRACE new{response=Response { client: 2025-05-16T15:31:00.750062618Z, server: 2025-05-16T15:31:00.750073618Z } current=2025-05-16T15:31:00.750074888Z}: timesimp::delta: response processing internals latency=6µs 135ns local_at_midpoint=2025-05-16T15:31:00.750068753Z delta=4µs 865ns
[INFO] [stdout] 2025-05-16T15:31:00.750264Z TRACE timesimp: obtained raw offset from server latency=6.135µs delta=4µs 865ns
[INFO] [stdout] 2025-05-16T15:31:00.750283Z TRACE timesimp: response deltas sorted by latency deltas=[0.00225, 0.00104, 0.00309, 0.003565, 0.004865]
[INFO] [stdout] 2025-05-16T15:31:00.750296Z TRACE timesimp: statistics about response deltas median=0.00309 mean=0.0029620000000000002 variance=2.0506075000000004e-6 stddev=0.0014319942388152267
[INFO] [stdout] 2025-05-16T15:31:00.750308Z TRACE timesimp: eliminated outliers inliers=[0.00225, 0.00309, 0.003565]
[INFO] [stdout] 2025-05-16T15:31:00.750316Z DEBUG timesimp: storing calculated offset offset=2µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 2025-05-16T15:31:00.757893Z TRACE new{response=Response { client: 2025-05-16T15:31:00.757799177Z, server: 2025-05-16T15:30:55.757803227Z } current=2025-05-16T15:31:00.757804927Z}: timesimp::delta: response processing internals latency=2µs 875ns local_at_midpoint=2025-05-16T15:31:00.757802052Z delta=4s 999ms 998µs 825ns ago
[INFO] [stdout] 2025-05-16T15:31:00.757961Z TRACE timesimp: obtained raw offset from server latency=2.875µs delta=4s 999ms 998µs 825ns ago
[INFO] [stdout] 2025-05-16T15:31:00.757985Z TRACE timesimp: sleeping to spread out requests delay=1.368204029s max_jitter=2s
[INFO] [stdout] 2025-05-16T15:31:00.803128Z TRACE new{response=Response { client: 2025-05-16T15:31:00.803024751Z, server: 2025-05-16T15:31:00.803031171Z } current=2025-05-16T15:31:00.803033371Z}: timesimp::delta: response processing internals latency=4µs 310ns local_at_midpoint=2025-05-16T15:31:00.803029061Z delta=2µs 110ns
[INFO] [stdout] 2025-05-16T15:31:00.803178Z TRACE timesimp: obtained raw offset from server latency=4.31µs delta=2µs 110ns
[INFO] [stdout] 2025-05-16T15:31:00.803201Z TRACE timesimp: sleeping to spread out requests delay=704.507842ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:31:00.922143Z TRACE new{response=Response { client: 2025-05-16T15:31:00.922001417Z, server: 2025-05-16T15:31:05.922011747Z } current=2025-05-16T15:31:00.922014097Z}: timesimp::delta: response processing internals latency=6µs 340ns local_at_midpoint=2025-05-16T15:31:00.922007757Z delta=5s 3µs 990ns
[INFO] [stdout] 2025-05-16T15:31:00.922208Z TRACE timesimp: obtained raw offset from server latency=6.34µs delta=5s 3µs 990ns
[INFO] [stdout] 2025-05-16T15:31:00.922222Z TRACE timesimp: sleeping to spread out requests delay=472.902926ms max_jitter=2s
[INFO] [stdout] 2025-05-16T15:31:01.397128Z TRACE new{response=Response { client: 2025-05-16T15:31:01.39697748Z, server: 2025-05-16T15:31:06.39698804Z } current=2025-05-16T15:31:01.39699074Z}: timesimp::delta: response processing internals latency=6µs 630ns local_at_midpoint=2025-05-16T15:31:01.39698411Z delta=5s 3µs 930ns
[INFO] [stdout] 2025-05-16T15:31:01.397191Z TRACE timesimp: obtained raw offset from server latency=6.63µs delta=5s 3µs 930ns
[INFO] [stdout] 2025-05-16T15:31:01.397208Z TRACE timesimp: response deltas sorted by latency deltas=[5000.00382, 5000.00376, 5000.00399, 5000.00393, 5000.00393]
[INFO] [stdout] 2025-05-16T15:31:01.397220Z TRACE timesimp: statistics about response deltas median=5000.00399 mean=5000.0038859999995 variance=8.730000030041555e-9 stddev=9.343446917514731e-5
[INFO] [stdout] 2025-05-16T15:31:01.397233Z TRACE timesimp: eliminated outliers inliers=[5000.00399, 5000.00393, 5000.00393]
[INFO] [stdout] 2025-05-16T15:31:01.397240Z DEBUG timesimp: storing calculated offset offset=5s 3µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] 2025-05-16T15:31:01.508289Z TRACE new{response=Response { client: 2025-05-16T15:31:01.508173946Z, server: 2025-05-16T15:31:01.508180086Z } current=2025-05-16T15:31:01.508182526Z}: timesimp::delta: response processing internals latency=4µs 290ns local_at_midpoint=2025-05-16T15:31:01.508178236Z delta=1µs 850ns
[INFO] [stdout] 2025-05-16T15:31:01.508343Z TRACE timesimp: obtained raw offset from server latency=4.29µs delta=1µs 850ns
[INFO] [stdout] 2025-05-16T15:31:01.508358Z TRACE timesimp: response deltas sorted by latency deltas=[0.00185, 0.00211, 0.00258, 0.003805, 0.003985]
[INFO] [stdout] 2025-05-16T15:31:01.508370Z TRACE timesimp: statistics about response deltas median=0.00258 mean=0.0028659999999999996 variance=9.548674999999998e-7 stddev=0.0009771732190353968
[INFO] [stdout] 2025-05-16T15:31:01.508382Z TRACE timesimp: eliminated outliers inliers=[0.00185, 0.00211, 0.00258]
[INFO] [stdout] 2025-05-16T15:31:01.508389Z DEBUG timesimp: storing calculated offset offset=2µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] 2025-05-16T15:31:02.127985Z TRACE new{response=Response { client: 2025-05-16T15:31:02.127836012Z, server: 2025-05-16T15:30:57.127847362Z } current=2025-05-16T15:31:02.127849912Z}: timesimp::delta: response processing internals latency=6µs 950ns local_at_midpoint=2025-05-16T15:31:02.127842962Z delta=4s 999ms 995µs 600ns ago
[INFO] [stdout] 2025-05-16T15:31:02.128055Z TRACE timesimp: obtained raw offset from server latency=6.95µs delta=4s 999ms 995µs 600ns ago
[INFO] [stdout] 2025-05-16T15:31:02.128079Z TRACE timesimp: response deltas sorted by latency deltas=[-4999.9989399999995, -4999.998825, -4999.99569, -4999.9956, -4999.995735]
[INFO] [stdout] 2025-05-16T15:31:02.128095Z TRACE timesimp: statistics about response deltas median=-4999.99569 mean=-4999.996958 variance=3.0904324989629884e-6 stddev=0.0017579625988521452
[INFO] [stdout] 2025-05-16T15:31:02.128111Z TRACE timesimp: eliminated outliers inliers=[-4999.99569, -4999.9956, -4999.995735]
[INFO] [stdout] 2025-05-16T15:31:02.128120Z DEBUG timesimp: storing calculated offset offset=4s 999ms 995µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.41s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-75369b169e5264a2)
[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] running `Command { std: "docker" "inspect" "52b271f9761dbd8489887cfdd78b9aab14b1b4be7113282d1564745a21c85095", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "52b271f9761dbd8489887cfdd78b9aab14b1b4be7113282d1564745a21c85095", kill_on_drop: false }`
[INFO] [stdout] 52b271f9761dbd8489887cfdd78b9aab14b1b4be7113282d1564745a21c85095