[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 master#ec6f9a5b4413f74386267ef8efc93712c2ce6db6 for pr-155739
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fpasscod%2Ftimesimp" "/workspace/builds/worker-5-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-5-tc1/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/passcod/timesimp
[INFO] finished tweaking git repo https://github.com/passcod/timesimp
[INFO] tweaked toml for git repo https://github.com/passcod/timesimp written to /workspace/builds/worker-5-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/passcod/timesimp on toolchain ec6f9a5b4413f74386267ef8efc93712c2ce6db6
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate git repo https://github.com/passcod/timesimp already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded signal-hook-registry v1.4.5
[INFO] [stderr]   Downloaded socket2 v0.5.9
[INFO] [stderr]   Downloaded jiff-tzdb-platform v0.1.3
[INFO] [stderr]   Downloaded windows-strings v0.3.1
[INFO] [stderr]   Downloaded utf16_iter v1.0.5
[INFO] [stderr]   Downloaded jiff-tzdb v0.1.4
[INFO] [stderr]   Downloaded write16 v1.0.0
[INFO] [stderr]   Downloaded dtor v0.0.6
[INFO] [stderr]   Downloaded dtor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded wasm-bindgen-shared v0.2.100
[INFO] [stderr]   Downloaded thread_local v1.1.8
[INFO] [stderr]   Downloaded windows-targets v0.53.0
[INFO] [stderr]   Downloaded napi-sys v3.0.0-alpha.1
[INFO] [stderr]   Downloaded ctor v0.4.2
[INFO] [stderr]   Downloaded ctor-proc-macro v0.0.5
[INFO] [stderr]   Downloaded wit-bindgen-rt v0.39.0
[INFO] [stderr]   Downloaded form_urlencoded v1.2.1
[INFO] [stderr]   Downloaded wasm-bindgen-macro v0.2.100
[INFO] [stderr]   Downloaded wasm-bindgen-futures v0.4.50
[INFO] [stderr]   Downloaded convert_case v0.8.0
[INFO] [stderr]   Downloaded napi-build v2.1.6
[INFO] [stderr]   Downloaded synstructure v0.13.1
[INFO] [stderr]   Downloaded icu_provider_macros v1.5.0
[INFO] [stderr]   Downloaded napi-derive v3.0.0-alpha.29
[INFO] [stderr]   Downloaded napi-derive-backend v2.0.0-alpha.28
[INFO] [stderr]   Downloaded semver v1.0.26
[INFO] [stderr]   Downloaded idna_adapter v1.2.0
[INFO] [stderr]   Downloaded stable_deref_trait v1.2.0
[INFO] [stderr]   Downloaded percent-encoding v2.3.1
[INFO] [stderr]   Downloaded windows-link v0.1.1
[INFO] [stderr]   Downloaded windows-result v0.3.2
[INFO] [stderr]   Downloaded errno v0.3.11
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded libloading v0.8.6
[INFO] [stderr]   Downloaded smallvec v1.14.0
[INFO] [stderr]   Downloaded zerovec-derive v0.10.3
[INFO] [stderr]   Downloaded yoke-derive v0.7.5
[INFO] [stderr]   Downloaded writeable v0.5.5
[INFO] [stderr]   Downloaded litemap v0.7.5
[INFO] [stderr]   Downloaded slab v0.4.9
[INFO] [stderr]   Downloaded portable-atomic v1.11.0
[INFO] [stderr]   Downloaded napi v3.0.0-alpha.33
[INFO] [stderr]   Downloaded icu_locid_transform v1.5.0
[INFO] [stderr]   Downloaded overload v0.1.1
[INFO] [stderr]   Downloaded nu-ansi-term v0.46.0
[INFO] [stderr]   Downloaded wasm-bindgen-backend v0.2.100
[INFO] [stderr]   Downloaded rustversion v1.0.20
[INFO] [stderr]   Downloaded tinystr v0.7.6
[INFO] [stderr]   Downloaded security-framework-sys v2.14.0
[INFO] [stderr]   Downloaded rustls-pemfile v2.2.0
[INFO] [stderr]   Downloaded wasm-bindgen v0.2.100
[INFO] [stderr]   Downloaded wasm-bindgen-macro-support v0.2.100
[INFO] [stderr]   Downloaded yoke v0.7.5
[INFO] [stderr]   Downloaded icu_locid_transform_data v1.5.1
[INFO] [stderr]   Downloaded getrandom v0.3.2
[INFO] [stderr]   Downloaded system-configuration v0.6.1
[INFO] [stderr]   Downloaded rustls-pki-types v1.11.0
[INFO] [stderr]   Downloaded tokio-rustls v0.26.2
[INFO] [stderr]   Downloaded redox_syscall v0.5.11
[INFO] [stderr]   Downloaded bitflags v2.9.0
[INFO] [stderr]   Downloaded miniz_oxide v0.8.5
[INFO] [stderr]   Downloaded tracing-attributes v0.1.28
[INFO] [stderr]   Downloaded url v2.5.4
[INFO] [stderr]   Downloaded icu_normalizer_data v1.5.1
[INFO] [stderr]   Downloaded native-tls v0.2.14
[INFO] [stderr]   Downloaded hyper-rustls v0.27.5
[INFO] [stderr]   Downloaded log v0.4.27
[INFO] [stderr]   Downloaded icu_properties v1.5.1
[INFO] [stderr]   Downloaded icu_locid v1.5.0
[INFO] [stderr]   Downloaded schannel v0.1.27
[INFO] [stderr]   Downloaded rand v0.9.1
[INFO] [stderr]   Downloaded tempfile v3.19.1
[INFO] [stderr]   Downloaded js-sys v0.3.77
[INFO] [stderr]   Downloaded icu_provider v1.5.0
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] [stderr]   Downloaded tracing-core v0.1.33
[INFO] [stderr]   Downloaded icu_normalizer v1.5.0
[INFO] [stderr]   Downloaded r-efi v5.2.0
[INFO] [stderr]   Downloaded openssl-sys v0.9.107
[INFO] [stderr]   Downloaded hyper-util v0.1.11
[INFO] [stderr]   Downloaded indexmap v2.9.0
[INFO] [stderr]   Downloaded bumpalo v3.17.0
[INFO] [stderr]   Downloaded security-framework v2.11.1
[INFO] [stderr]   Downloaded cc v1.2.20
[INFO] [stderr]   Downloaded icu_collections v1.5.0
[INFO] [stderr]   Downloaded tokio-util v0.7.15
[INFO] [stderr]   Downloaded mio v1.0.3
[INFO] [stderr]   Downloaded serde_json v1.0.140
[INFO] [stderr]   Downloaded idna v1.0.3
[INFO] [stderr]   Downloaded wasi v0.14.2+wasi-0.2.4
[INFO] [stderr]   Downloaded hashbrown v0.15.2
[INFO] [stderr]   Downloaded zerovec v0.10.4
[INFO] [stderr]   Downloaded hyper v1.6.0
[INFO] [stderr]   Downloaded tracing-subscriber v0.3.19
[INFO] [stderr]   Downloaded reqwest v0.12.15
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded icu_properties_data v1.5.1
[INFO] [stderr]   Downloaded zerocopy v0.8.24
[INFO] [stderr]   Downloaded openssl v0.10.72
[INFO] [stderr]   Downloaded object v0.36.7
[INFO] [stderr]   Downloaded rustls v0.23.26
[INFO] [stderr]   Downloaded rustix v1.0.5
[INFO] [stderr]   Downloaded web-sys v0.3.77
[INFO] [stderr]   Downloaded windows-registry v0.4.0
[INFO] [stderr]   Downloaded libc v0.2.171
[INFO] [stderr]   Downloaded windows_aarch64_gnullvm v0.53.0
[INFO] [stderr]   Downloaded tokio v1.44.2
[INFO] [stderr]   Downloaded windows_x86_64_gnullvm v0.53.0
[INFO] [stderr]   Downloaded windows_aarch64_msvc v0.53.0
[INFO] [stderr]   Downloaded windows_x86_64_msvc v0.53.0
[INFO] [stderr]   Downloaded rustls-webpki v0.103.1
[INFO] [stderr]   Downloaded windows_x86_64_gnu v0.53.0
[INFO] [stderr]   Downloaded windows_i686_gnullvm v0.53.0
[INFO] [stderr]   Downloaded windows_i686_gnu v0.53.0
[INFO] [stderr]   Downloaded windows_i686_msvc v0.53.0
[INFO] [stderr]   Downloaded linux-raw-sys v0.9.4
[INFO] [stderr]   Downloaded zerocopy-derive v0.8.24
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 50021f0139726060dbd6173fe9d1c25492acedd5a8d2d6d808043eef12c1e5a4
[INFO] running `Command { std: "docker" "start" "-a" "50021f0139726060dbd6173fe9d1c25492acedd5a8d2d6d808043eef12c1e5a4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "50021f0139726060dbd6173fe9d1c25492acedd5a8d2d6d808043eef12c1e5a4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "50021f0139726060dbd6173fe9d1c25492acedd5a8d2d6d808043eef12c1e5a4", kill_on_drop: false }`
[INFO] [stdout] 50021f0139726060dbd6173fe9d1c25492acedd5a8d2d6d808043eef12c1e5a4
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 7714ce7e3d7953ec5f72d012de5c2cd985f4ed55e6adf52765ef2d8173250427
[INFO] running `Command { std: "docker" "start" "-a" "7714ce7e3d7953ec5f72d012de5c2cd985f4ed55e6adf52765ef2d8173250427", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling unicode-ident v1.0.18
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling zerocopy v0.8.24
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling napi-build v2.1.6
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling pin-project-lite v0.2.16
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling dtor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling ctor-proc-macro v0.0.5
[INFO] [stderr]    Compiling serde_json v1.0.140
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling ryu v1.0.20
[INFO] [stderr]    Compiling itoa v1.0.15
[INFO] [stderr]    Compiling napi v3.0.0-alpha.33
[INFO] [stderr]    Compiling convert_case v0.8.0
[INFO] [stderr]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling napi-sys v3.0.0-alpha.1
[INFO] [stderr]    Compiling dtor v0.0.6
[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 thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir/lib)
[INFO] [stderr]    Compiling napi-derive v3.0.0-alpha.29
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 29.47s
[INFO] running `Command { std: "docker" "inspect" "7714ce7e3d7953ec5f72d012de5c2cd985f4ed55e6adf52765ef2d8173250427", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "7714ce7e3d7953ec5f72d012de5c2cd985f4ed55e6adf52765ef2d8173250427", kill_on_drop: false }`
[INFO] [stdout] 7714ce7e3d7953ec5f72d012de5c2cd985f4ed55e6adf52765ef2d8173250427
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 6df33885dc67182ad1e0d813acc0e3cbdce8fcd7477c59ef091d055039cea116
[INFO] running `Command { std: "docker" "start" "-a" "6df33885dc67182ad1e0d813acc0e3cbdce8fcd7477c59ef091d055039cea116", 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 futures-core v0.3.31
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling pkg-config v0.3.32
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling vcpkg v0.2.15
[INFO] [stderr]    Compiling writeable v0.5.5
[INFO] [stderr]    Compiling litemap v0.7.5
[INFO] [stderr]    Compiling icu_locid_transform_data v1.5.1
[INFO] [stderr]    Compiling 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 equivalent v1.0.2
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling hashbrown v0.15.2
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling foreign-types-shared v0.1.1
[INFO] [stderr]    Compiling pin-utils v0.1.0
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling foreign-types v0.3.2
[INFO] [stderr]    Compiling utf16_iter v1.0.5
[INFO] [stderr]    Compiling try-lock v0.2.5
[INFO] [stderr]    Compiling write16 v1.0.0
[INFO] [stderr]    Compiling atomic-waker v1.1.2
[INFO] [stderr]    Compiling utf8_iter v1.0.4
[INFO] [stderr]    Compiling lock_api v0.4.12
[INFO] [stderr]    Compiling slab v0.4.9
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling percent-encoding v2.3.1
[INFO] [stderr]    Compiling sync_wrapper v1.0.2
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling tower-layer v0.3.3
[INFO] [stderr]    Compiling rustls-pki-types v1.11.0
[INFO] [stderr]    Compiling indexmap v2.9.0
[INFO] [stderr]    Compiling form_urlencoded v1.2.1
[INFO] [stderr]    Compiling overload v0.1.1
[INFO] [stderr]    Compiling nu-ansi-term v0.46.0
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling encoding_rs v0.8.35
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling mime v0.3.17
[INFO] [stderr]    Compiling ipnet v2.11.0
[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 rustls-pemfile v2.2.0
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[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 displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling yoke v0.7.5
[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 napi-derive v3.0.0-alpha.29
[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 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]    Compiling timesimp-nodejs v1.0.3 (/opt/rustwide/workdir/nodejs)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 57.38s
[INFO] running `Command { std: "docker" "inspect" "6df33885dc67182ad1e0d813acc0e3cbdce8fcd7477c59ef091d055039cea116", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "6df33885dc67182ad1e0d813acc0e3cbdce8fcd7477c59ef091d055039cea116", kill_on_drop: false }`
[INFO] [stdout] 6df33885dc67182ad1e0d813acc0e3cbdce8fcd7477c59ef091d055039cea116
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+ec6f9a5b4413f74386267ef8efc93712c2ce6db6" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 6a252f220f14e760b46b9abfd213aa1de002bfb59ee49839cfe5fdbd1ae96b0a
[INFO] running `Command { std: "docker" "start" "-a" "6a252f220f14e760b46b9abfd213aa1de002bfb59ee49839cfe5fdbd1ae96b0a", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.32s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-7875ddb3df0d84b6)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test messages::tests::round_trip_response ... ok
[INFO] [stdout] test messages::tests::specific_requests ... ok
[INFO] [stdout] test messages::tests::round_trip_request ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.04s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-f04346ec9fba397a)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-05-11T19:48:10.343049Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-05-11T19:48:10.343194Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.343055Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-05-11T19:48:10.343442Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.346891Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.346949Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.347236Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.347294Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.347494Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.347635Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.347778Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.347840Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.347857Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.347986Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.348449Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.348532Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.348939Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.349020Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.351693Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.34928168Z, server: 2026-05-11T19:48:10.350400809Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.351531989Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 125µs 154ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.350406834Z [3mdelta[0m[2m=[0m6µs 25ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.351829Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.125154ms [3mdelta[0m[2m=[0m6µs 25ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.351911Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m6µs 25ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.351981Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m169.224825ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.352786Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:10.352848Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.366937Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.3444783Z, server: 2026-05-11T19:48:10.355618779Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.366744569Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 133µs 134ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.355611434Z [3mdelta[0m[2m=[0m7µs 345ns
[INFO] [stdout] [2m2026-05-11T19:48:10.367106Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.133134ms [3mdelta[0m[2m=[0m7µs 345ns
[INFO] [stdout] [2m2026-05-11T19:48:10.367200Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m750.9612ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.367345Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.3447497Z, server: 2026-05-11T19:48:10.355861629Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.367057069Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 153µs 684ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.355903384Z [3mdelta[0m[2m=[0m41µs 755ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.367706Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.153684ms [3mdelta[0m[2m=[0m41µs 755ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.367738Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.679571334s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.370449Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.3490731Z, server: 2026-05-11T19:48:15.359201959Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.370325209Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 626µs 54ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.359699154Z [3mdelta[0m[2m=[0m4s 999ms 502µs 805ns
[INFO] [stdout] [2m2026-05-11T19:48:10.370750Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.626054ms [3mdelta[0m[2m=[0m4s 999ms 502µs 805ns
[INFO] [stdout] [2m2026-05-11T19:48:10.370818Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 999ms 502µs 805ns
[INFO] [stdout] [2m2026-05-11T19:48:10.371003Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.378478474s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.371407Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.349200909Z, server: 2026-05-11T19:48:15.360798449Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.371224699Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 11µs 895ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.360212804Z [3mdelta[0m[2m=[0m5s 585µs 645ns
[INFO] [stdout] [2m2026-05-11T19:48:10.371503Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.011895ms [3mdelta[0m[2m=[0m5s 585µs 645ns
[INFO] [stdout] [2m2026-05-11T19:48:10.371524Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 585µs 645ns
[INFO] [stdout] [2m2026-05-11T19:48:10.371545Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m889.401968ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.371571Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.34826697Z, server: 2026-05-11T19:48:15.357808879Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.371467489Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 600µs 259ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.359867229Z [3mdelta[0m[2m=[0m4s 997ms 941µs 650ns
[INFO] [stdout] [2m2026-05-11T19:48:10.371632Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.600259ms [3mdelta[0m[2m=[0m4s 997ms 941µs 650ns
[INFO] [stdout] [2m2026-05-11T19:48:10.371652Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 997ms 941µs 650ns
[INFO] [stdout] [2m2026-05-11T19:48:10.371665Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.788058126s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.372108Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.3497631Z, server: 2026-05-11T19:48:15.360891249Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.372006019Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 121µs 459ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.360884559Z [3mdelta[0m[2m=[0m5s 6µs 690ns
[INFO] [stdout] [2m2026-05-11T19:48:10.372173Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.121459ms [3mdelta[0m[2m=[0m5s 6µs 690ns
[INFO] [stdout] [2m2026-05-11T19:48:10.372196Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 6µs 690ns
[INFO] [stdout] [2m2026-05-11T19:48:10.372223Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.856643872s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.376697Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.350330749Z, server: 2026-05-11T19:48:05.365473269Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.376597799Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 133µs 525ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.363464274Z [3mdelta[0m[2m=[0m4s 997ms 991µs 5ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.376758Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.133525ms [3mdelta[0m[2m=[0m4s 997ms 991µs 5ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.376777Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 997ms 991µs 5ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.376791Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m452.990757ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.536636Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.527520563Z, server: 2026-05-11T19:48:10.533479013Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.536465993Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 472µs 715ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.531993278Z [3mdelta[0m[2m=[0m1ms 485µs 735ns
[INFO] [stdout] [2m2026-05-11T19:48:10.536729Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.472715ms [3mdelta[0m[2m=[0m1ms 485µs 735ns
[INFO] [stdout] [2m2026-05-11T19:48:10.536752Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.94316352s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.558458Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.356541939Z, server: 2026-05-11T19:48:10.456862956Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.558229592Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 843µs 826ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.457385765Z [3mdelta[0m[2m=[0m522µs 809ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.558550Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.843826ms [3mdelta[0m[2m=[0m522µs 809ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.558574Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m522µs 809ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.558589Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m83.943397ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.845819Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.642950809Z, server: 2026-05-11T19:48:10.744323825Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.845657301Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 353µs 246ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.744304055Z [3mdelta[0m[2m=[0m19µs 770ns
[INFO] [stdout] [2m2026-05-11T19:48:10.845991Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.353246ms [3mdelta[0m[2m=[0m19µs 770ns
[INFO] [stdout] [2m2026-05-11T19:48:10.846043Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.909121401s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:10.858770Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.836238322Z, server: 2026-05-11T19:48:05.847410371Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:10.858595351Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 178µs 514ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:10.847416836Z [3mdelta[0m[2m=[0m5s 6µs 465ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.858858Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.178514ms [3mdelta[0m[2m=[0m5s 6µs 465ns ago
[INFO] [stdout] [2m2026-05-11T19:48:10.858882Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m761.328617ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:11.142929Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:11.120494759Z, server: 2026-05-11T19:48:11.13163338Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:11.142769871Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 137µs 556ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:11.131632315Z [3mdelta[0m[2m=[0m1µs 65ns
[INFO] [stdout] [2m2026-05-11T19:48:11.143083Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.137556ms [3mdelta[0m[2m=[0m1µs 65ns
[INFO] [stdout] [2m2026-05-11T19:48:11.143165Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m321.452737ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:11.281196Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:11.262644422Z, server: 2026-05-11T19:48:16.271831655Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:11.281031177Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 193µs 377ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:11.271837799Z [3mdelta[0m[2m=[0m4s 999ms 993µs 856ns
[INFO] [stdout] [2m2026-05-11T19:48:11.281364Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.193377ms [3mdelta[0m[2m=[0m4s 999ms 993µs 856ns
[INFO] [stdout] [2m2026-05-11T19:48:11.281412Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.646849829s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:11.489638Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:11.465656155Z, server: 2026-05-11T19:48:11.476802046Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:11.489482296Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 913µs 70ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:11.477569225Z [3mdelta[0m[2m=[0m767µs 179ns ago
[INFO] [stdout] [2m2026-05-11T19:48:11.489781Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.91307ms [3mdelta[0m[2m=[0m767µs 179ns ago
[INFO] [stdout] [2m2026-05-11T19:48:11.489825Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.406900658s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:11.645011Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:11.621657457Z, server: 2026-05-11T19:48:06.632920338Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:11.644833438Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 587µs 990ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:11.633245447Z [3mdelta[0m[2m=[0m5s 325µs 109ns ago
[INFO] [stdout] [2m2026-05-11T19:48:11.645096Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.58799ms [3mdelta[0m[2m=[0m5s 325µs 109ns ago
[INFO] [stdout] [2m2026-05-11T19:48:11.645120Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m523.372182ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:11.770985Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:11.750655381Z, server: 2026-05-11T19:48:16.760620883Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:11.770817414Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 81µs 16ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:11.760736397Z [3mdelta[0m[2m=[0m4s 999ms 884µs 486ns
[INFO] [stdout] [2m2026-05-11T19:48:11.771078Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.081016ms [3mdelta[0m[2m=[0m4s 999ms 884µs 486ns
[INFO] [stdout] [2m2026-05-11T19:48:11.771101Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m321.997059ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:11.820590Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:10.34850118Z, server: 2026-05-11T19:48:11.084493539Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:11.820377024Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m735ms 937µs 922ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:11.084439102Z [3mdelta[0m[2m=[0m54µs 437ns
[INFO] [stdout] [2m2026-05-11T19:48:11.820673Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m735.937922ms [3mdelta[0m[2m=[0m54µs 437ns
[INFO] [stdout] [2m2026-05-11T19:48:11.820694Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m54µs 437ns
[INFO] [stdout] [2m2026-05-11T19:48:11.820708Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.29724224s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.071588Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.048664766Z, server: 2026-05-11T19:48:12.060192276Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.071394817Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 365µs 25ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.060029791Z [3mdelta[0m[2m=[0m162µs 485ns
[INFO] [stdout] [2m2026-05-11T19:48:12.071684Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.365025ms [3mdelta[0m[2m=[0m162µs 485ns
[INFO] [stdout] [2m2026-05-11T19:48:12.071709Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.678896538s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.115905Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.093633949Z, server: 2026-05-11T19:48:17.105551209Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.115739671Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 52µs 861ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.10468681Z [3mdelta[0m[2m=[0m5s 864µs 399ns
[INFO] [stdout] [2m2026-05-11T19:48:12.115989Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.052861ms [3mdelta[0m[2m=[0m5s 864µs 399ns
[INFO] [stdout] [2m2026-05-11T19:48:12.116010Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m755.066826ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.173217Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.160652264Z, server: 2026-05-11T19:48:17.166843789Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.173037234Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 192µs 485ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.166844749Z [3mdelta[0m[2m=[0m4s 999ms 999µs 40ns
[INFO] [stdout] [2m2026-05-11T19:48:12.173316Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.192485ms [3mdelta[0m[2m=[0m4s 999ms 999µs 40ns
[INFO] [stdout] [2m2026-05-11T19:48:12.173342Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.917546782s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.191232Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.169641586Z, server: 2026-05-11T19:48:07.180848567Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.191049499Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 703µs 956ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.180345542Z [3mdelta[0m[2m=[0m4s 999ms 496µs 975ns ago
[INFO] [stdout] [2m2026-05-11T19:48:12.191667Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.703956ms [3mdelta[0m[2m=[0m4s 999ms 496µs 975ns ago
[INFO] [stdout] [2m2026-05-11T19:48:12.191771Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.096068252s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.252214Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.229657577Z, server: 2026-05-11T19:48:17.240853018Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.252043229Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 192µs 826ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.240850403Z [3mdelta[0m[2m=[0m5s 2µs 615ns
[INFO] [stdout] [2m2026-05-11T19:48:12.252297Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.192826ms [3mdelta[0m[2m=[0m5s 2µs 615ns
[INFO] [stdout] [2m2026-05-11T19:48:12.252321Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m622.454938ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.484128Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.48166556Z, server: 2026-05-11T19:48:12.482819009Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.483965368Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 149µs 904ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.482815464Z [3mdelta[0m[2m=[0m3µs 545ns
[INFO] [stdout] [2m2026-05-11T19:48:12.484222Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.149904ms [3mdelta[0m[2m=[0m3µs 545ns
[INFO] [stdout] [2m2026-05-11T19:48:12.484244Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.962007013s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.894220Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.87165538Z, server: 2026-05-11T19:48:17.88284788Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.894037911Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 191µs 265ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.882846645Z [3mdelta[0m[2m=[0m5s 1µs 235ns
[INFO] [stdout] [2m2026-05-11T19:48:12.894317Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.191265ms [3mdelta[0m[2m=[0m5s 1µs 235ns
[INFO] [stdout] [2m2026-05-11T19:48:12.894343Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m63.469564ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.898124Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.875633886Z, server: 2026-05-11T19:48:17.886805217Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.897985238Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 175µs 676ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.886809562Z [3mdelta[0m[2m=[0m4s 999ms 995µs 655ns
[INFO] [stdout] [2m2026-05-11T19:48:12.898203Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.175676ms [3mdelta[0m[2m=[0m4s 999ms 995µs 655ns
[INFO] [stdout] [2m2026-05-11T19:48:12.898225Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m123.214502ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.920690Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.898572277Z, server: 2026-05-11T19:48:12.909374448Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.920518459Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 973µs 91ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.909545368Z [3mdelta[0m[2m=[0m170µs 920ns ago
[INFO] [stdout] [2m2026-05-11T19:48:12.920774Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.973091ms [3mdelta[0m[2m=[0m170µs 920ns ago
[INFO] [stdout] [2m2026-05-11T19:48:12.920797Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.077326427s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.948161Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.929651002Z, server: 2026-05-11T19:48:17.938824754Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.947991797Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 170µs 397ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.938821399Z [3mdelta[0m[2m=[0m5s 3µs 355ns
[INFO] [stdout] [2m2026-05-11T19:48:12.948254Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.170397ms [3mdelta[0m[2m=[0m5s 3µs 355ns
[INFO] [stdout] [2m2026-05-11T19:48:12.948280Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.606942637s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.958534Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.756660904Z, server: 2026-05-11T19:48:12.857069751Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.958355158Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 847µs 127ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.857508031Z [3mdelta[0m[2m=[0m438µs 280ns ago
[INFO] [stdout] [2m2026-05-11T19:48:12.958619Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.847127ms [3mdelta[0m[2m=[0m438µs 280ns ago
[INFO] [stdout] [2m2026-05-11T19:48:12.958641Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.716811419s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:12.985843Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:12.962559195Z, server: 2026-05-11T19:48:17.974493245Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:12.985671566Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 556µs 185ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:12.97411538Z [3mdelta[0m[2m=[0m5s 377µs 865ns
[INFO] [stdout] [2m2026-05-11T19:48:12.985933Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.556185ms [3mdelta[0m[2m=[0m5s 377µs 865ns
[INFO] [stdout] [2m2026-05-11T19:48:12.985969Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.884486, 4999.502805, 5000.864399, 5000.001235, 5000.377865]
[INFO] [stdout] [2m2026-05-11T19:48:12.986000Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.864399 [3mmean[0m[2m=[0m5000.126158000001 [3mvariance[0m[2m=[0m0.2677340655130675 [3mstddev[0m[2m=[0m0.5174302518340684
[INFO] [stdout] [2m2026-05-11T19:48:12.986026Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.864399, 5000.377865]
[INFO] [stdout] [2m2026-05-11T19:48:12.986039Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 621µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-05-11T19:48:13.045338Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:13.022622375Z, server: 2026-05-11T19:48:18.033822536Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:13.045158857Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 268µs 241ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:13.033890616Z [3mdelta[0m[2m=[0m4s 999ms 931µs 920ns
[INFO] [stdout] [2m2026-05-11T19:48:13.045450Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.268241ms [3mdelta[0m[2m=[0m4s 999ms 931µs 920ns
[INFO] [stdout] [2m2026-05-11T19:48:13.045480Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m858.315217ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:13.330695Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:13.301603616Z, server: 2026-05-11T19:48:08.315528515Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:13.330522902Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 459µs 643ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:13.316063259Z [3mdelta[0m[2m=[0m5s 534µs 744ns ago
[INFO] [stdout] [2m2026-05-11T19:48:13.330788Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.459643ms [3mdelta[0m[2m=[0m5s 534µs 744ns ago
[INFO] [stdout] [2m2026-05-11T19:48:13.330819Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.496975, -5000.006465, -5000.325109, -4997.991005, -5000.534744]
[INFO] [stdout] [2m2026-05-11T19:48:13.330840Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.325109 [3mmean[0m[2m=[0m-4999.670859600001 [3mvariance[0m[2m=[0m1.034779212432916 [3mstddev[0m[2m=[0m1.0172409805119513
[INFO] [stdout] [2m2026-05-11T19:48:13.330859Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.496975, -5000.006465, -5000.325109, -5000.534744]
[INFO] [stdout] [2m2026-05-11T19:48:13.330873Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 90µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-05-11T19:48:13.774901Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:13.751662526Z, server: 2026-05-11T19:48:13.763533756Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:13.774728247Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 532µs 860ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:13.763195386Z [3mdelta[0m[2m=[0m338µs 370ns
[INFO] [stdout] [2m2026-05-11T19:48:13.774991Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.53286ms [3mdelta[0m[2m=[0m338µs 370ns
[INFO] [stdout] [2m2026-05-11T19:48:13.775015Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.801971936s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:13.927097Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:13.90452961Z, server: 2026-05-11T19:48:18.915716471Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:13.926902502Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 186µs 446ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:13.915716056Z [3mdelta[0m[2m=[0m5s 415ns
[INFO] [stdout] [2m2026-05-11T19:48:13.927180Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.186446ms [3mdelta[0m[2m=[0m5s 415ns
[INFO] [stdout] [2m2026-05-11T19:48:13.927209Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00669, 4999.995655, 5000.000415, 5000.002615, 4999.93192]
[INFO] [stdout] [2m2026-05-11T19:48:13.927229Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.000415 [3mmean[0m[2m=[0m4999.987459 [3mvariance[0m[2m=[0m0.000979787142505952 [3mstddev[0m[2m=[0m0.03130155175875394
[INFO] [stdout] [2m2026-05-11T19:48:13.927251Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00669, 4999.995655, 5000.000415, 5000.002615]
[INFO] [stdout] [2m2026-05-11T19:48:13.927265Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 1µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-05-11T19:48:14.023083Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:14.000524132Z, server: 2026-05-11T19:48:14.011719432Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:14.022911613Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 193µs 740ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:14.011717872Z [3mdelta[0m[2m=[0m1µs 560ns
[INFO] [stdout] [2m2026-05-11T19:48:14.023170Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.19374ms [3mdelta[0m[2m=[0m1µs 560ns
[INFO] [stdout] [2m2026-05-11T19:48:14.023204Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.17092, 0.007345, 0.001065, 0.00156, -0.767179]
[INFO] [stdout] [2m2026-05-11T19:48:14.023225Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.001065 [3mmean[0m[2m=[0m-0.1856258 [3mvariance[0m[2m=[0m0.11138752329070004 [3mstddev[0m[2m=[0m0.33374769406049837
[INFO] [stdout] [2m2026-05-11T19:48:14.023248Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.17092, 0.007345, 0.001065, 0.00156]
[INFO] [stdout] [2m2026-05-11T19:48:14.023262Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m40µs ago
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-05-11T19:48:14.099175Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:14.092662596Z, server: 2026-05-11T19:48:19.095831783Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:14.09900502Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m3ms 171µs 212ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:14.095833808Z [3mdelta[0m[2m=[0m4s 999ms 997µs 975ns
[INFO] [stdout] [2m2026-05-11T19:48:14.099270Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m3.171212ms [3mdelta[0m[2m=[0m4s 999ms 997µs 975ns
[INFO] [stdout] [2m2026-05-11T19:48:14.099293Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.701077383s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:14.474649Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:14.465547759Z, server: 2026-05-11T19:48:14.471517784Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:14.474490782Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 471µs 511ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:14.47001927Z [3mdelta[0m[2m=[0m1ms 498µs 514ns
[INFO] [stdout] [2m2026-05-11T19:48:14.474799Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.471511ms [3mdelta[0m[2m=[0m1ms 498µs 514ns
[INFO] [stdout] [2m2026-05-11T19:48:14.474831Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m439.206818ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:14.574500Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:14.555786585Z, server: 2026-05-11T19:48:19.564992317Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:14.57430466Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 259µs 37ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:14.565045622Z [3mdelta[0m[2m=[0m4s 999ms 946µs 695ns
[INFO] [stdout] [2m2026-05-11T19:48:14.574593Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.259037ms [3mdelta[0m[2m=[0m4s 999ms 946µs 695ns
[INFO] [stdout] [2m2026-05-11T19:48:14.574619Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.694367849s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:14.738816Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:13.118675886Z, server: 2026-05-11T19:48:13.92864344Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:14.738649674Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m809ms 986µs 894ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:13.92866278Z [3mdelta[0m[2m=[0m19µs 340ns ago
[INFO] [stdout] [2m2026-05-11T19:48:14.738905Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m809.986894ms [3mdelta[0m[2m=[0m19µs 340ns ago
[INFO] [stdout] [2m2026-05-11T19:48:14.738928Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m544.958817ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:14.878788Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:14.675937426Z, server: 2026-05-11T19:48:14.777292763Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:14.87862609Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 344µs 332ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:14.777281758Z [3mdelta[0m[2m=[0m11µs 5ns
[INFO] [stdout] [2m2026-05-11T19:48:14.878940Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.344332ms [3mdelta[0m[2m=[0m11µs 5ns
[INFO] [stdout] [2m2026-05-11T19:48:14.879022Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.887198848s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:14.927680Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:14.920616375Z, server: 2026-05-11T19:48:14.924541562Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:14.927510709Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m3ms 447µs 167ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:14.924063542Z [3mdelta[0m[2m=[0m478µs 20ns
[INFO] [stdout] [2m2026-05-11T19:48:14.927771Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m3.447167ms [3mdelta[0m[2m=[0m478µs 20ns
[INFO] [stdout] [2m2026-05-11T19:48:14.927800Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.006025, 0.003545, 0.47802, 1.498514, 1.485735]
[INFO] [stdout] [2m2026-05-11T19:48:14.927824Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.47802 [3mmean[0m[2m=[0m0.6919578 [3mvariance[0m[2m=[0m0.5718691753916999 [3mstddev[0m[2m=[0m0.756220321990688
[INFO] [stdout] [2m2026-05-11T19:48:14.927859Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.006025, 0.003545, 0.47802]
[INFO] [stdout] [2m2026-05-11T19:48:14.927874Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m158µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-05-11T19:48:15.604214Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:15.581526582Z, server: 2026-05-11T19:48:15.592827462Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:15.604022373Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 247µs 895ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:15.592774477Z [3mdelta[0m[2m=[0m52µs 985ns
[INFO] [stdout] [2m2026-05-11T19:48:15.604318Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.247895ms [3mdelta[0m[2m=[0m52µs 985ns
[INFO] [stdout] [2m2026-05-11T19:48:15.604346Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m294.107804ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:15.809165Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:15.801658031Z, server: 2026-05-11T19:48:20.805831297Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:15.809002245Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m3ms 672µs 107ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:15.805330138Z [3mdelta[0m[2m=[0m5s 501µs 159ns
[INFO] [stdout] [2m2026-05-11T19:48:15.809251Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m3.672107ms [3mdelta[0m[2m=[0m5s 501µs 159ns
[INFO] [stdout] [2m2026-05-11T19:48:15.809273Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m467.273628ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:15.921354Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:15.89968949Z, server: 2026-05-11T19:48:15.909883902Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:15.921178122Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 744µs 316ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:15.910433806Z [3mdelta[0m[2m=[0m549µs 904ns ago
[INFO] [stdout] [2m2026-05-11T19:48:15.921471Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.744316ms [3mdelta[0m[2m=[0m549µs 904ns ago
[INFO] [stdout] [2m2026-05-11T19:48:15.921503Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.549904, -0.041755, 0.052985, 0.162485, 0.33837]
[INFO] [stdout] [2m2026-05-11T19:48:15.921524Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.052985 [3mmean[0m[2m=[0m-0.007563799999999998 [3mvariance[0m[2m=[0m0.11188871905969998 [3mstddev[0m[2m=[0m0.3344977115911258
[INFO] [stdout] [2m2026-05-11T19:48:15.921544Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.041755, 0.052985, 0.162485, 0.33837]
[INFO] [stdout] [2m2026-05-11T19:48:15.921557Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m128µs
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-05-11T19:48:16.290075Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:16.280525407Z, server: 2026-05-11T19:48:21.284715483Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:16.289907679Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 691µs 136ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:16.285216543Z [3mdelta[0m[2m=[0m4s 999ms 498µs 940ns
[INFO] [stdout] [2m2026-05-11T19:48:16.290167Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.691136ms [3mdelta[0m[2m=[0m4s 999ms 498µs 940ns
[INFO] [stdout] [2m2026-05-11T19:48:16.290208Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[4999.997975, 5000.501159, 4999.4989399999995, 4999.99904, 4997.94165]
[INFO] [stdout] [2m2026-05-11T19:48:16.290229Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.4989399999995 [3mmean[0m[2m=[0m4999.5877528 [3mvariance[0m[2m=[0m0.9723231105170775 [3mstddev[0m[2m=[0m0.9860644555591067
[INFO] [stdout] [2m2026-05-11T19:48:16.290248Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4999.997975, 4999.4989399999995, 4999.99904]
[INFO] [stdout] [2m2026-05-11T19:48:16.290260Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 831µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-05-11T19:48:16.292115Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:16.270652815Z, server: 2026-05-11T19:48:21.280820647Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:16.291961668Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 654µs 426ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:16.281307241Z [3mdelta[0m[2m=[0m4s 999ms 513µs 406ns
[INFO] [stdout] [2m2026-05-11T19:48:16.292188Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.654426ms [3mdelta[0m[2m=[0m4s 999ms 513µs 406ns
[INFO] [stdout] [2m2026-05-11T19:48:16.292221Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.003355, 4999.993856, 4999.946695, 4999.513406, 5000.585645]
[INFO] [stdout] [2m2026-05-11T19:48:16.292239Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.946695 [3mmean[0m[2m=[0m5000.008591399999 [3mvariance[0m[2m=[0m0.14556878846933616 [3mstddev[0m[2m=[0m0.3815347801568504
[INFO] [stdout] [2m2026-05-11T19:48:16.292257Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.003355, 4999.993856, 4999.946695]
[INFO] [stdout] [2m2026-05-11T19:48:16.292269Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 981µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-05-11T19:48:16.695966Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:15.284693636Z, server: 2026-05-11T19:48:15.990555515Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:16.695790756Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m705ms 548µs 560ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:15.990242196Z [3mdelta[0m[2m=[0m313µs 319ns
[INFO] [stdout] [2m2026-05-11T19:48:16.696054Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m705.54856ms [3mdelta[0m[2m=[0m313µs 319ns
[INFO] [stdout] [2m2026-05-11T19:48:16.696078Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m595.975832ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:16.969819Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:16.767657037Z, server: 2026-05-11T19:48:16.868597123Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:16.9696462Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 994µs 581ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:16.868651618Z [3mdelta[0m[2m=[0m54µs 495ns ago
[INFO] [stdout] [2m2026-05-11T19:48:16.969907Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.994581ms [3mdelta[0m[2m=[0m54µs 495ns ago
[INFO] [stdout] [2m2026-05-11T19:48:16.969935Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.522809, -0.43828, -0.054495, 0.011005, 0.01977]
[INFO] [stdout] [2m2026-05-11T19:48:16.969956Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.054495 [3mmean[0m[2m=[0m-0.19696180000000002 [3mvariance[0m[2m=[0m0.06873263088369999 [3mstddev[0m[2m=[0m0.2621690883450984
[INFO] [stdout] [2m2026-05-11T19:48:16.969975Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.054495, 0.011005, 0.01977]
[INFO] [stdout] [2m2026-05-11T19:48:16.969997Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m7µs ago
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-05-11T19:48:18.952841Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:17.292661215Z, server: 2026-05-11T19:48:18.122649252Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:18.95266497Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m830ms 1µs 877ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:18.122663092Z [3mdelta[0m[2m=[0m13µs 840ns ago
[INFO] [stdout] [2m2026-05-11T19:48:18.952956Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m830.001877ms [3mdelta[0m[2m=[0m13µs 840ns ago
[INFO] [stdout] [2m2026-05-11T19:48:18.952983Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.861532159s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.370718Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:20.815659779Z, server: 2026-05-11T19:48:21.591673731Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:22.37051762Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m777ms 428µs 920ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:21.593088699Z [3mdelta[0m[2m=[0m1ms 414µs 968ns ago
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-2e65c6dffb129287)
[INFO] [stdout] [2m2026-05-11T19:48:22.370815Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m777.42892ms [3mdelta[0m[2m=[0m1ms 414µs 968ns ago
[INFO] [stdout] [2m2026-05-11T19:48:22.370848Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.313319, 0.054437, -1.414968, -0.01934, -0.01384]
[INFO] [stdout] [2m2026-05-11T19:48:22.370869Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-1.414968 [3mmean[0m[2m=[0m-0.2160784 [3mvariance[0m[2m=[0m0.46759570755530006 [3mstddev[0m[2m=[0m0.6838097012731685
[INFO] [stdout] [2m2026-05-11T19:48:22.370889Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-1.414968]
[INFO] [stdout] [2m2026-05-11T19:48:22.370901Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m1ms 414µ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.03s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-05-11T19:48:22.376569Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:22.376692Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.376775Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-05-11T19:48:22.376838Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.378125Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:22.377936504Z, server: 2026-05-11T19:48:22.377950754Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:22.377954694Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9µs 95ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:22.377945599Z [3mdelta[0m[2m=[0m5µs 155ns
[INFO] [stdout] [2m2026-05-11T19:48:22.378256Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.095µs [3mdelta[0m[2m=[0m5µs 155ns
[INFO] [stdout] [2m2026-05-11T19:48:22.378375Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5µs 155ns
[INFO] [stdout] [2m2026-05-11T19:48:22.378442Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.965143992s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.378336Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:22.378120454Z, server: 2026-05-11T19:48:27.378123944Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:22.378125564Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 555ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:22.378123009Z [3mdelta[0m[2m=[0m5s 935ns
[INFO] [stdout] [2m2026-05-11T19:48:22.378625Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.555µs [3mdelta[0m[2m=[0m5s 935ns
[INFO] [stdout] [2m2026-05-11T19:48:22.378657Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m115.800723ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.383665Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-05-11T19:48:22.383861Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.383665Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-05-11T19:48:22.383993Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.385378Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:22.385220368Z, server: 2026-05-11T19:48:17.385227878Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:22.385231108Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5µs 370ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:22.385225738Z [3mdelta[0m[2m=[0m4s 999ms 997µs 860ns ago
[INFO] [stdout] [2m2026-05-11T19:48:22.385462Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.37µs [3mdelta[0m[2m=[0m4s 999ms 997µs 860ns ago
[INFO] [stdout] [2m2026-05-11T19:48:22.385480Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.522366624s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.385682Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:22.385596888Z, server: 2026-05-11T19:48:22.385599128Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:22.385600508Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1µs 810ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:22.385598698Z [3mdelta[0m[2m=[0m430ns
[INFO] [stdout] [2m2026-05-11T19:48:22.385731Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.81µs [3mdelta[0m[2m=[0m430ns
[INFO] [stdout] [2m2026-05-11T19:48:22.385746Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.725876106s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:22.502861Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:22.502566462Z, server: 2026-05-11T19:48:27.502575902Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:22.502579242Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 390ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:22.502572852Z [3mdelta[0m[2m=[0m5s 3µs 50ns
[INFO] [stdout] [2m2026-05-11T19:48:22.502957Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.39µs [3mdelta[0m[2m=[0m5s 3µs 50ns
[INFO] [stdout] [2m2026-05-11T19:48:22.502984Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m740.681945ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:23.244823Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:23.244659532Z, server: 2026-05-11T19:48:28.244668092Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:23.244671602Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 35ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:23.244665567Z [3mdelta[0m[2m=[0m5s 2µs 525ns
[INFO] [stdout] [2m2026-05-11T19:48:23.244903Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.035µs [3mdelta[0m[2m=[0m5s 2µs 525ns
[INFO] [stdout] [2m2026-05-11T19:48:23.244923Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.950429119s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:23.910700Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:23.910524594Z, server: 2026-05-11T19:48:18.910534194Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:23.910537834Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 620ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:23.910531214Z [3mdelta[0m[2m=[0m4s 999ms 997µs 20ns ago
[INFO] [stdout] [2m2026-05-11T19:48:23.910789Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.62µs [3mdelta[0m[2m=[0m4s 999ms 997µs 20ns ago
[INFO] [stdout] [2m2026-05-11T19:48:23.910811Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m453.881685ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:24.113696Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:24.113530178Z, server: 2026-05-11T19:48:24.113539838Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:24.113543098Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 460ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:24.113536638Z [3mdelta[0m[2m=[0m3µs 200ns
[INFO] [stdout] [2m2026-05-11T19:48:24.113782Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.46µs [3mdelta[0m[2m=[0m3µs 200ns
[INFO] [stdout] [2m2026-05-11T19:48:24.113803Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m658.817501ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:24.346695Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:24.346523596Z, server: 2026-05-11T19:48:24.346537941Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:24.346536226Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 315ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:24.346529911Z [3mdelta[0m[2m=[0m8µs 30ns
[INFO] [stdout] [2m2026-05-11T19:48:24.346783Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.315µs [3mdelta[0m[2m=[0m8µs 30ns
[INFO] [stdout] [2m2026-05-11T19:48:24.346807Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.607164093s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:24.371698Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:24.371526055Z, server: 2026-05-11T19:48:19.371534965Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:24.371538575Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 260ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:24.371532315Z [3mdelta[0m[2m=[0m4s 999ms 997µs 350ns ago
[INFO] [stdout] [2m2026-05-11T19:48:24.371786Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.26µs [3mdelta[0m[2m=[0m4s 999ms 997µs 350ns ago
[INFO] [stdout] [2m2026-05-11T19:48:24.371808Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m822.362883ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:24.774827Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:24.774662594Z, server: 2026-05-11T19:48:24.774671864Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:24.774675234Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 320ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:24.774668914Z [3mdelta[0m[2m=[0m2µs 950ns
[INFO] [stdout] [2m2026-05-11T19:48:24.774909Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.32µs [3mdelta[0m[2m=[0m2µs 950ns
[INFO] [stdout] [2m2026-05-11T19:48:24.774929Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.514842486s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:25.195849Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:25.195656158Z, server: 2026-05-11T19:48:20.195665618Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:25.195669638Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 740ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:25.195662898Z [3mdelta[0m[2m=[0m4s 999ms 997µs 280ns ago
[INFO] [stdout] [2m2026-05-11T19:48:25.195943Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.74µs [3mdelta[0m[2m=[0m4s 999ms 997µs 280ns ago
[INFO] [stdout] [2m2026-05-11T19:48:25.195968Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m164.935988ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:25.197624Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:25.197516736Z, server: 2026-05-11T19:48:30.197522136Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:25.197524807Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4µs 35ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:25.197520771Z [3mdelta[0m[2m=[0m5s 1µs 365ns
[INFO] [stdout] [2m2026-05-11T19:48:25.197741Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.035µs [3mdelta[0m[2m=[0m5s 1µs 365ns
[INFO] [stdout] [2m2026-05-11T19:48:25.197795Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m777.298765ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:25.361980Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:25.361789521Z, server: 2026-05-11T19:48:20.361799681Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:25.361803381Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 930ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:25.361796451Z [3mdelta[0m[2m=[0m4s 999ms 996µs 770ns ago
[INFO] [stdout] [2m2026-05-11T19:48:25.362074Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.93µs [3mdelta[0m[2m=[0m4s 999ms 996µs 770ns ago
[INFO] [stdout] [2m2026-05-11T19:48:25.362106Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.9978599999995, -4999.99735, -4999.99702, -4999.99728, -4999.99677]
[INFO] [stdout] [2m2026-05-11T19:48:25.362129Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.99702 [3mmean[0m[2m=[0m-4999.997256 [3mvariance[0m[2m=[0m1.665299999117112e-7 [3mstddev[0m[2m=[0m0.00040808087422925275
[INFO] [stdout] [2m2026-05-11T19:48:25.362151Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99735, -4999.99702, -4999.99728, -4999.99677]
[INFO] [stdout] [2m2026-05-11T19:48:25.362165Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 997µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-05-11T19:48:25.954850Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:25.954682004Z, server: 2026-05-11T19:48:25.954696799Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:25.954695944Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 970ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:25.954688974Z [3mdelta[0m[2m=[0m7µs 825ns
[INFO] [stdout] [2m2026-05-11T19:48:25.954933Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.97µs [3mdelta[0m[2m=[0m7µs 825ns
[INFO] [stdout] [2m2026-05-11T19:48:25.954955Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m563.644478ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:25.977730Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:25.977535665Z, server: 2026-05-11T19:48:30.977546905Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:25.977550815Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 575ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:25.97754324Z [3mdelta[0m[2m=[0m5s 3µs 665ns
[INFO] [stdout] [2m2026-05-11T19:48:25.977819Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.575µs [3mdelta[0m[2m=[0m5s 3µs 665ns
[INFO] [stdout] [2m2026-05-11T19:48:25.977848Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.000935, 5000.001365, 5000.002525, 5000.00305, 5000.003665]
[INFO] [stdout] [2m2026-05-11T19:48:25.977868Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.002525 [3mmean[0m[2m=[0m5000.002308 [3mvariance[0m[2m=[0m1.3033700001511487e-6 [3mstddev[0m[2m=[0m0.0011416523114114686
[INFO] [stdout] [2m2026-05-11T19:48:25.977888Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.002525, 5000.00305, 5000.003665]
[INFO] [stdout] [2m2026-05-11T19:48:25.977901Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 3µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-05-11T19:48:26.292695Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:26.292521856Z, server: 2026-05-11T19:48:26.292531196Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:26.292534496Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 320ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:26.292528176Z [3mdelta[0m[2m=[0m3µs 20ns
[INFO] [stdout] [2m2026-05-11T19:48:26.292778Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.32µs [3mdelta[0m[2m=[0m3µs 20ns
[INFO] [stdout] [2m2026-05-11T19:48:26.292799Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m32.278124ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:26.329703Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:26.329524726Z, server: 2026-05-11T19:48:26.329534766Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:26.329538586Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 930ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:26.329531656Z [3mdelta[0m[2m=[0m3µs 110ns
[INFO] [stdout] [2m2026-05-11T19:48:26.329800Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.93µs [3mdelta[0m[2m=[0m3µs 110ns
[INFO] [stdout] [2m2026-05-11T19:48:26.329830Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00043, 0.00295, 0.00302, 0.0032, 0.00311]
[INFO] [stdout] [2m2026-05-11T19:48:26.329850Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00302 [3mmean[0m[2m=[0m0.002542 [3mvariance[0m[2m=[0m1.40277e-6 [3mstddev[0m[2m=[0m0.001184385916836231
[INFO] [stdout] [2m2026-05-11T19:48:26.329878Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00295, 0.00302, 0.0032, 0.00311]
[INFO] [stdout] [2m2026-05-11T19:48:26.329894Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stdout] [2m2026-05-11T19:48:26.519838Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:26.519668869Z, server: 2026-05-11T19:48:26.519683415Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:26.519681789Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 460ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:26.519675329Z [3mdelta[0m[2m=[0m8µs 86ns
[INFO] [stdout] [2m2026-05-11T19:48:26.519924Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.46µs [3mdelta[0m[2m=[0m8µs 86ns
[INFO] [stdout] [2m2026-05-11T19:48:26.519945Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.132468863s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-05-11T19:48:27.654721Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-05-11T19:48:27.654532156Z, server: 2026-05-11T19:48:27.654548971Z } [3mcurrent[0m[2m=[0m2026-05-11T19:48:27.654547587Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 715ns [3mlocal_at_midpoint[0m[2m=[0m2026-05-11T19:48:27.654539871Z [3mdelta[0m[2m=[0m9µs 100ns
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp_nodejs-f8424559dfcf15b0)
[INFO] [stdout] [2m2026-05-11T19:48:27.654812Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.715µs [3mdelta[0m[2m=[0m9µs 100ns
[INFO] [stdout] [2m2026-05-11T19:48:27.654839Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00803, 0.008086, 0.007825, 0.0091, 0.005155]
[INFO] [stdout] [2m2026-05-11T19:48:27.654860Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.007825 [3mmean[0m[2m=[0m0.0076392000000000005 [3mvariance[0m[2m=[0m2.173015700000001e-6 [3mstddev[0m[2m=[0m0.0014741152261611033
[INFO] [stdout] [2m2026-05-11T19:48:27.654885Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00803, 0.008086, 0.007825, 0.0091]
[INFO] [stdout] [2m2026-05-11T19:48:27.654899Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m8µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.28s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests timesimp
[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] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test lib/src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test lib/src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 1.89s; merged doctests compilation took 1.86s
[INFO] running `Command { std: "docker" "inspect" "6a252f220f14e760b46b9abfd213aa1de002bfb59ee49839cfe5fdbd1ae96b0a", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "6a252f220f14e760b46b9abfd213aa1de002bfb59ee49839cfe5fdbd1ae96b0a", kill_on_drop: false }`
[INFO] [stdout] 6a252f220f14e760b46b9abfd213aa1de002bfb59ee49839cfe5fdbd1ae96b0a
