[INFO] cloning repository https://github.com/Nehliin/vortex
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/Nehliin/vortex" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2FNehliin%2Fvortex", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2FNehliin%2Fvortex'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 3e7138e358d84e31b519dd6e614dfb1d691ab509
[INFO] testing Nehliin/vortex against try#b83b707f97d809763b7861afa7638871f3339a33 for pr-145838-1
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2FNehliin%2Fvortex" "/workspace/builds/worker-2-tc2/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-tc2/source'...
[INFO] [stderr] done.
[INFO] started tweaking git repo https://github.com/Nehliin/vortex
[INFO] finished tweaking git repo https://github.com/Nehliin/vortex
[INFO] tweaked toml for git repo https://github.com/Nehliin/vortex written to /workspace/builds/worker-2-tc2/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/Nehliin/vortex on toolchain b83b707f97d809763b7861afa7638871f3339a33
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+b83b707f97d809763b7861afa7638871f3339a33" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate git repo https://github.com/Nehliin/vortex 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" "+b83b707f97d809763b7861afa7638871f3339a33" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+b83b707f97d809763b7861afa7638871f3339a33" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 36c91edc22ada0e63eba1ed99a774056e60778be30a7d24afa75c5621b21a987
[INFO] running `Command { std: "docker" "start" "-a" "36c91edc22ada0e63eba1ed99a774056e60778be30a7d24afa75c5621b21a987", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "36c91edc22ada0e63eba1ed99a774056e60778be30a7d24afa75c5621b21a987", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "36c91edc22ada0e63eba1ed99a774056e60778be30a7d24afa75c5621b21a987", kill_on_drop: false }`
[INFO] [stdout] 36c91edc22ada0e63eba1ed99a774056e60778be30a7d24afa75c5621b21a987
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+b83b707f97d809763b7861afa7638871f3339a33" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] edca2198f88a866f9f0cc6e40ef92cd83d6cf2b39b93cb6259ab267a24c154a4
[INFO] running `Command { std: "docker" "start" "-a" "edca2198f88a866f9f0cc6e40ef92cd83d6cf2b39b93cb6259ab267a24c154a4", kill_on_drop: false }`
[INFO] [stderr]    Compiling cfg-if v1.0.1
[INFO] [stderr]    Compiling version_check v0.9.5
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling memchr v2.7.5
[INFO] [stderr]    Compiling autocfg v1.5.0
[INFO] [stderr]    Compiling zerocopy v0.8.26
[INFO] [stderr]    Compiling getrandom v0.3.3
[INFO] [stderr]    Compiling typenum v1.18.0
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling slab v0.4.11
[INFO] [stderr]    Compiling jobserver v0.1.33
[INFO] [stderr]    Compiling socket2 v0.6.0
[INFO] [stderr]    Compiling allocator-api2 v0.2.21
[INFO] [stderr]    Compiling zeroize v1.8.1
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling syn v2.0.104
[INFO] [stderr]    Compiling foldhash v0.1.5
[INFO] [stderr]    Compiling dunce v1.0.5
[INFO] [stderr]    Compiling fs_extra v1.3.0
[INFO] [stderr]    Compiling mio v1.0.4
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling futures-io v0.3.31
[INFO] [stderr]    Compiling bitflags v2.9.1
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling cc v1.2.31
[INFO] [stderr]    Compiling smallvec v1.15.1
[INFO] [stderr]    Compiling cpufeatures v0.2.17
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling aws-lc-rs v1.13.3
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling rustversion v1.0.21
[INFO] [stderr]    Compiling subtle v2.6.1
[INFO] [stderr]    Compiling generic-array v0.14.7
[INFO] [stderr]    Compiling hashbrown v0.15.4
[INFO] [stderr]    Compiling ahash v0.8.12
[INFO] [stderr]    Compiling rustls-pki-types v1.12.0
[INFO] [stderr]    Compiling httparse v1.10.1
[INFO] [stderr]    Compiling ident_case v1.0.1
[INFO] [stderr]    Compiling parking_lot_core v0.9.11
[INFO] [stderr]    Compiling lock_api v0.4.13
[INFO] [stderr]    Compiling signal-hook v0.3.18
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling untrusted v0.9.0
[INFO] [stderr]    Compiling try-lock v0.2.5
[INFO] [stderr]    Compiling rustls v0.23.31
[INFO] [stderr]    Compiling cmake v0.1.54
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling num-traits v0.2.19
[INFO] [stderr]    Compiling aho-corasick v1.1.3
[INFO] [stderr]    Compiling rustc_version v0.4.1
[INFO] [stderr]    Compiling slotmap v1.0.7
[INFO] [stderr]    Compiling getrandom v0.2.16
[INFO] [stderr]    Compiling io-uring v0.6.4
[INFO] [stderr]    Compiling indexmap v2.10.0
[INFO] [stderr]    Compiling radium v0.7.0
[INFO] [stderr]    Compiling thiserror v1.0.69
[INFO] [stderr]    Compiling paste v1.0.15
[INFO] [stderr]    Compiling httpdate v1.0.3
[INFO] [stderr]    Compiling curve25519-dalek v4.1.3
[INFO] [stderr]    Compiling instability v0.3.9
[INFO] [stderr]    Compiling signal-hook-mio v0.2.4
[INFO] [stderr]    Compiling castaway v0.2.4
[INFO] [stderr]    Compiling rand_core v0.6.4
[INFO] [stderr]    Compiling rustix v0.38.44
[INFO] [stderr]    Compiling parking_lot v0.12.4
[INFO] [stderr]    Compiling itertools v0.13.0
[INFO] [stderr]    Compiling raw-cpuid v11.5.0
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling byteorder v1.5.0
[INFO] [stderr]    Compiling custom_derive v0.1.7
[INFO] [stderr]    Compiling unicode-width v0.1.14
[INFO] [stderr]    Compiling unicode-segmentation v1.12.0
[INFO] [stderr]    Compiling io-uring v0.7.9
[INFO] [stderr]    Compiling indoc v2.0.6
[INFO] [stderr]    Compiling tap v1.0.1
[INFO] [stderr]    Compiling aws-lc-sys v0.30.0
[INFO] [stderr]    Compiling tikv-jemalloc-sys v0.5.4+5.3.0-patched
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling signature v2.2.0
[INFO] [stderr]    Compiling heapless v0.8.0
[INFO] [stderr]    Compiling ed25519 v2.2.3
[INFO] [stderr]    Compiling rustls-native-certs v0.8.1
[INFO] [stderr]    Compiling wyz v0.5.1
[INFO] [stderr]    Compiling hash32 v0.3.1
[INFO] [stderr]    Compiling conv v0.3.3
[INFO] [stderr]    Compiling compact_str v0.8.1
[INFO] [stderr]    Compiling block-buffer v0.10.4
[INFO] [stderr]    Compiling crypto-common v0.1.6
[INFO] [stderr]    Compiling crossterm v0.28.1
[INFO] [stderr]    Compiling lru v0.12.5
[INFO] [stderr]    Compiling digest v0.10.7
[INFO] [stderr]    Compiling spin v0.9.8
[INFO] [stderr]    Compiling regex-automata v0.4.9
[INFO] [stderr]    Compiling rand_xoshiro v0.7.0
[INFO] [stderr]    Compiling sha1 v0.10.6
[INFO] [stderr]    Compiling sha2 v0.10.9
[INFO] [stderr]    Compiling socket2 v0.4.10
[INFO] [stderr]    Compiling num_cpus v1.17.0
[INFO] [stderr]    Compiling litrs v0.4.2
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling sketches-ddsketch v0.3.0
[INFO] [stderr]    Compiling cassowary v0.3.0
[INFO] [stderr]    Compiling crc-catalog v2.4.0
[INFO] [stderr]    Compiling serde_json v1.0.142
[INFO] [stderr]    Compiling funty v2.0.0
[INFO] [stderr]    Compiling unicode-width v0.2.0
[INFO] [stderr]    Compiling powerfmt v0.2.0
[INFO] [stderr]    Compiling crc v3.3.0
[INFO] [stderr]    Compiling clap_builder v4.5.42
[INFO] [stderr]    Compiling flume v0.11.1
[INFO] [stderr]    Compiling document-features v0.2.11
[INFO] [stderr]    Compiling btoi v0.4.3
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling bitvec v1.0.1
[INFO] [stderr]    Compiling quanta v0.12.6
[INFO] [stderr]    Compiling metrics v0.24.2
[INFO] [stderr]    Compiling unicode-truncate v1.1.0
[INFO] [stderr]    Compiling dyn-clone v1.0.20
[INFO] [stderr]    Compiling num_threads v0.1.7
[INFO] [stderr]    Compiling darling_core v0.20.11
[INFO] [stderr]    Compiling time-core v0.1.4
[INFO] [stderr]    Compiling lru v0.16.0
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand_chacha v0.3.1
[INFO] [stderr]    Compiling jiff v0.2.15
[INFO] [stderr]    Compiling num-conv v0.1.0
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling sha1_smol v1.0.1
[INFO] [stderr]    Compiling rand v0.9.2
[INFO] [stderr]    Compiling rand v0.8.5
[INFO] [stderr]    Compiling smallvec v2.0.0-alpha.11
[INFO] [stderr]    Compiling crossbeam-channel v0.5.15
[INFO] [stderr]    Compiling human_bytes v0.4.3
[INFO] [stderr]    Compiling metrics-util v0.20.0
[INFO] [stderr]    Compiling serde_derive v1.0.219
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling futures-macro v0.3.31
[INFO] [stderr]    Compiling tracing-attributes v0.1.30
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling thiserror-impl v1.0.69
[INFO] [stderr]    Compiling strum_macros v0.26.4
[INFO] [stderr]    Compiling curve25519-dalek-derive v0.1.1
[INFO] [stderr]    Compiling clap_derive v4.5.41
[INFO] [stderr]    Compiling regex v1.11.1
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling env_filter v0.1.3
[INFO] [stderr]    Compiling lava_torrent v0.11.1
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling darling_macro v0.20.11
[INFO] [stderr]    Compiling darling v0.20.11
[INFO] [stderr]    Compiling strum v0.26.3
[INFO] [stderr]    Compiling ed25519-dalek v2.2.0
[INFO] [stderr]    Compiling ratatui v0.29.0
[INFO] [stderr]    Compiling clap v4.5.42
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling futures-executor v0.3.31
[INFO] [stderr]    Compiling futures v0.3.31
[INFO] [stderr]    Compiling env_logger v0.11.8
[INFO] [stderr]    Compiling throbber-widgets-tui v0.8.0
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling serde_bytes v0.11.17
[INFO] [stderr]    Compiling deranged v0.4.0
[INFO] [stderr]    Compiling bt_bencode v0.8.2
[INFO] [stderr]    Compiling serde_bencoded v0.3.2
[INFO] [stderr]    Compiling serde_bencode v0.2.4
[INFO] [stderr]    Compiling mainline v5.4.0 (https://github.com/Nehliin/mainline.git?branch=feature-gate#60bc6833)
[INFO] [stderr]    Compiling tokio v1.47.1
[INFO] [stderr]    Compiling http v1.3.1
[INFO] [stderr]    Compiling vortex-bittorrent v0.2.0 (/opt/rustwide/workdir/bittorrent)
[INFO] [stderr]    Compiling time v0.3.41
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-uring v0.5.0 (https://github.com/tokio-rs/tokio-uring?branch=master#5fb1a4f6)
[INFO] [stderr]    Compiling h2 v0.4.11
[INFO] [stderr]    Compiling rustls-webpki v0.103.4
[INFO] [stderr]    Compiling vortex-dht v0.1.1 (/opt/rustwide/workdir/dht)
[INFO] [stderr]    Compiling utp-socket v0.1.1 (/opt/rustwide/workdir/utp-socket)
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling tokio-rustls v0.26.2
[INFO] [stderr]    Compiling hyper-util v0.1.16
[INFO] [stderr]    Compiling hyper-rustls v0.27.7
[INFO] [stderr]    Compiling metrics-exporter-prometheus v0.17.2
[INFO] [stderr]    Compiling tikv-jemallocator v0.5.4
[INFO] [stderr]    Compiling vortex-cli v0.1.0 (/opt/rustwide/workdir/cli)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 34s
[INFO] running `Command { std: "docker" "inspect" "edca2198f88a866f9f0cc6e40ef92cd83d6cf2b39b93cb6259ab267a24c154a4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "edca2198f88a866f9f0cc6e40ef92cd83d6cf2b39b93cb6259ab267a24c154a4", kill_on_drop: false }`
[INFO] [stdout] edca2198f88a866f9f0cc6e40ef92cd83d6cf2b39b93cb6259ab267a24c154a4
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+b83b707f97d809763b7861afa7638871f3339a33" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] dd9df5b2899f3456aefc27f2e758ddfe788da7aaf06161bae8bf9210dee4c927
[INFO] running `Command { std: "docker" "start" "-a" "dd9df5b2899f3456aefc27f2e758ddfe788da7aaf06161bae8bf9210dee4c927", kill_on_drop: false }`
[INFO] [stderr]    Compiling num-traits v0.2.19
[INFO] [stderr]    Compiling nibble_vec v0.1.0
[INFO] [stderr]    Compiling endian-type v0.1.2
[INFO] [stderr]    Compiling tokio-stream v0.1.17
[INFO] [stderr]    Compiling radix_trie v0.2.1
[INFO] [stderr]    Compiling utp-socket v0.1.1 (/opt/rustwide/workdir/utp-socket)
[INFO] [stderr]    Compiling ordered-float v4.6.0
[INFO] [stderr]    Compiling btoi v0.4.3
[INFO] [stderr]    Compiling num-integer v0.1.46
[INFO] [stderr]    Compiling serde_bencoded v0.3.2
[INFO] [stderr]    Compiling num-bigint v0.4.6
[INFO] [stderr]    Compiling metrics-util v0.20.0
[INFO] [stderr]    Compiling vortex-dht v0.1.1 (/opt/rustwide/workdir/dht)
[INFO] [stderr]    Compiling metrics-exporter-prometheus v0.17.2
[INFO] [stderr]    Compiling vortex-bittorrent v0.2.0 (/opt/rustwide/workdir/bittorrent)
[INFO] [stderr]    Compiling vortex-cli v0.1.0 (/opt/rustwide/workdir/cli)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 7.03s
[INFO] running `Command { std: "docker" "inspect" "dd9df5b2899f3456aefc27f2e758ddfe788da7aaf06161bae8bf9210dee4c927", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "dd9df5b2899f3456aefc27f2e758ddfe788da7aaf06161bae8bf9210dee4c927", kill_on_drop: false }`
[INFO] [stdout] dd9df5b2899f3456aefc27f2e758ddfe788da7aaf06161bae8bf9210dee4c927
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+b83b707f97d809763b7861afa7638871f3339a33" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] a200d08bbd1591d12eaa0fd3cdec9bde3fc03578d1b62cb6e052bcc5e995f591
[INFO] running `Command { std: "docker" "start" "-a" "a200d08bbd1591d12eaa0fd3cdec9bde3fc03578d1b62cb6e052bcc5e995f591", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.16s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/utp_socket-e3e88bcfc57cb636)
[INFO] [stdout] 
[INFO] [stdout] running 9 tests
[INFO] [stdout] test reorder_buffer::test::index_collision ... ok
[INFO] [stdout] test reorder_buffer::test::insertion_orderd ... ok
[INFO] [stdout] test reorder_buffer::test::insertion_unorderd ... ok
[INFO] [stdout] test reorder_buffer::test::insertion_orderd_large_gap ... ok
[INFO] [stdout] test reorder_buffer::test::insertion_unorderd_large_gap ... ok
[INFO] [stdout] test reorder_buffer::test::removal ... ok
[INFO] [stdout] test reorder_buffer::test::removal_of_last_with_wraparound ... ok
[INFO] [stdout] test reorder_buffer::test::removal_of_last_with_wraparound_v2 ... ok
[INFO] [stdout] test reorder_buffer::test::resizing ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 9 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/end_to_end.rs (/opt/rustwide/target/debug/deps/end_to_end-6b33c5f84cb2898f)
[INFO] [stdout] 
[INFO] [stdout] running 1 test
[INFO] [stdout] test end_to_end ... ignored, Flakey on ci
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/vortex_bittorrent-36ccf44d1d101f56)
[INFO] [stdout] 
[INFO] [stdout] running 51 tests
[INFO] [stdout] test peer_comm::peer_protocol::tests::bitfield ... ok
[INFO] [stdout] test peer_comm::peer_protocol::tests::empty_bitfield ... ok
[INFO] [stdout] test peer_comm::peer_protocol::tests::bitfield_roundtrip ... ok
[INFO] [stdout] test peer_comm::peer_protocol::tests::fuzz_encoded_length_bug ... ok
[INFO] [stdout] test file_store::tests::errors_on_invalid_piece_index ... ok
[INFO] [stdout] test file_store::tests::single_file_misaligned_v2 ... ok
[INFO] [stdout] test file_store::tests::basic_single_file_aligned ... ok
[INFO] [stdout] test file_store::tests::basic_single_file_aligned_unaligned_subpiece ... ok
[INFO] [stdout] test file_store::tests::single_file_misaligned ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x500x920xe40x310x170x330x50x8a0x1c0xed0x9e0xaf] Received invalid bitfield, expected 9, got: 8
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8e0x3c0xe0xdb0x800x70x680xfc0x690xa20xfe0xed] Bifield received
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd80x790x3c0x370x590x810x110x60x120xf20xc20xd1] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x620xd00xec0xb90x490x650x7f0x3b0x6a0x390xf6] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd80x790x3c0x370x590x810x110x60x120xf20xc20xd1] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x730x1b0x820xd20x950x950x4b0xa10xec0x7c0xe10x3d] Bifield received
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa50x470xf60xd20xb30xfd0xa10xbf0xad0xca0x500xa0] Bifield received
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd80x790x3c0x370x590x810x110x60x120xf20xc20xd1] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stdout] test peer_comm::tests::assume_intrest_when_request_recv ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 0
[INFO] [stdout] test peer_comm::tests::bitfield_recv ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stdout] test file_store::tests::multifile_misalinged_v3 ... ok
[INFO] [stdout] test peer_comm::tests::desired_queue_size ... ok
[INFO] [stdout] test file_store::tests::multifile_misalinged_v2 ... ok
[INFO] [stdout] test file_store::tests::multifile_not_multiple_of_piece_size ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa10x690x90x670xc60xbe0xd00x5a0x660x1f0x7d0x63] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::peer_connection] Unexpected extended msg
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xdd0xed0x180x5d0xd70x270xf70xe40x150xaa0x210x17] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa10x690x90x670xc60xbe0xd00x5a0x660x1f0x7d0x63] Recived a piece index: 1, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa10x690x90x670xc60xbe0xd00x5a0x660x1f0x7d0x63] Recived a piece index: 1, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 1 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stdout] test peer_comm::tests::extension_handshake_generates_correct_message ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa10x690x90x670xc60xbe0xd00x5a0x660x1f0x7d0x63] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa10x690x90x670xc60xbe0xd00x5a0x660x1f0x7d0x63] Recived a piece index: 3, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 16384
[INFO] [stdout] test file_store::tests::small_multifile_misalinged ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stdout] test file_store::tests::small_multifile_misalinged_files_and_subpiece ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 3 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stdout] test peer_comm::tests::extension_message_unknown_id ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0x1b0xc00x7e0xc0x810x140xd60x480x310x50x66] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xcb0x260x710x8d0x4f0xb20x7e0x840x2a0xe50xad0x3a] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test peer_comm::tests::extension_handshake_with_reqq ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test peer_comm::tests::fast_ext_have_all ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test peer_comm::tests::extension_handshake_malformed ... ok
[INFO] [stdout] test peer_comm::tests::extension_handshake_missing_m_field ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xbd0x4b0x3f0x380xf60x6a0x970x270x8e0x80x980x61] Bifield received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xbd0x4b0x3f0x380xf60x6a0x970x270x8e0x80x980x61] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xbd0x4b0x3f0x380xf60x6a0x970x270x8e0x80x980x61] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100x210xde0xe40x200x8b0x4f0x240xc0xe70xfd0xbf] Peer have piece with index: 8
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x850x700x920x1d0x5c0x140xb80x50x980x7e0x770xc5] Have None received
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x470xdb0x1f0x1b0x7a0xa00xff0x740x670x4d0x1c0x91] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x110xa60x400x530xdc0xcc0x3a0x720x3a0x10x330xf6] Have all received
[INFO] [stdout] test peer_comm::tests::have_invalid_indicies ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stdout] test peer_comm::tests::extension_protocol_handshake ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x110xa60x400x530xdc0xcc0x3a0x720x3a0x10x330xf6] Piece Reject request was invalid, index=-2 begin=0 length=16384
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0xa00x2a0x9b0x210x670x5a0x7c0xc00xd30xe50x9d] Peer have piece with index: 7
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x110xa60x400x530xdc0xcc0x3a0x720x3a0x10x330xf6] Piece Reject request was invalid, index=2 begin=16385 length=16384
[INFO] [stdout] test peer_comm::tests::have_without_interest ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x260xdd0x410x370x5d0xce0x960x6e0x5a0xea0xfc0xb] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0xa00x2a0x9b0x210x670x5a0x7c0xc00xd30xe50x9d] Peer have piece with index: 7
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x110xa60x400x530xdc0xcc0x3a0x720x3a0x10x330xf6] Piece Reject request was invalid, index=2 begin=0 length=16385
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf00xe30xdd0x250x6a0x9f0xf70x980xc70x2a0x800xc] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(3v1), index: 2
[INFO] [stdout] test peer_comm::tests::invalid_piece ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stdout] test peer_comm::tests::invalid_reject_request ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 7
[INFO] [stdout] test peer_comm::tests::fast_ext_have_none ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x3f0xf30x910xf70xb90xbe0x7b0x1f0xe20x860x3c] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x4e0x770xcb0xb20x10xfe0x880x610x600x6d0xc00xfb] Peer have piece with index: 7
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0xa00x2a0x9b0x210x670x5a0x7c0xc00xd30xe50x9d] Recived a piece index: 7, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 7, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0xa00x2a0x9b0x210x670x5a0x7c0xc00xd30xe50x9d] Recived a piece index: 7, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x3f0xf30x910xf70xb90xbe0x7b0x1f0xe20x860x3c] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 7, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 7 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Peer have piece with index: 1
[INFO] [stdout] test peer_comm::tests::metadata_extension_data_message ... ok
[INFO] [stdout] test peer_comm::tests::metadata_download_single_piece ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Peer have piece with index: 1
[INFO] [stdout] test peer_comm::tests::metadata_extension_piece_bounds_validation ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Peer have piece with index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Peer have piece with index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Peer have piece with index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 2
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::peer_comm::extended_protocol] Got reject request
[INFO] [stdout] test peer_comm::tests::metadata_extension_request_message ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 99
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Peer have piece with index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Peer have piece with index: 3
[INFO] [stdout] test peer_comm::tests::metadata_extension_reject_message ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension unknown type: 99
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Peer have piece with index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Peer have piece with index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Peer have piece with index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Unchoked and start downloading
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Peer have piece with index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Peer have piece with index: 6
[INFO] [stdout] test peer_comm::tests::metadata_extension_invalid_message_type ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Unchoked and start downloading
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 0.65
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 0.65
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x60x4b0xec0xee0x5d0x7e0x720x740x850x350xfa0x80] Peer is choking us!
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x240xfc0x860x70x930xea0xa40xbb0xda0x9e0x30x61] Peer is choking us!
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 1
[INFO] [stdout] test file_store::tests::multifile_misalinged ... ok
[INFO] [stdout] test file_store::tests::basic_multifile_alinged ... ok
[INFO] [stdout] test peer_comm::tests::peer_choke_recv_does_not_support_fast ... ok
[INFO] [stdout] test peer_comm::tests::peer_choke_recv_supports_fast ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x850xaf0xd70x7b0x660x850x130xaa0x680x510x190xb1] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa30xfa0x900x600x570x380x5a0x530x420xb70x3c0x4d] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xce0x970xf60x130x6c0x6f0x300x940x1f0x7c0x550x5a] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa30xfa0x900x600x570x380x5a0x530x420xb70x3c0x4d] Unchoked and start downloading
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::peer_comm::peer_connection] [PeerId -VT0020-0x850xaf0xd70x7b0x660x850x130xaa0x680x510x190xb1]: Subpiece request rejected: 5, 0
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Peer have piece with index: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xce0x970xf60x130x6c0x6f0x300x940x1f0x7c0x550x5a] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x2d0xf0xe80x430x400x90x560xa10x9e0xde0x870x1d] Have all received
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xb30x560xfd0xf20xb20x840x4d0xcc0xdc0xc10xca0xb4] Bifield received
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x2d0xf0xe80x430x400x90x560xa10x9e0xde0x870x1d] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Recived a piece index: 1, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 0
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::event_loop] TIMEOUT: -VT0020-0xce0x970xf60x130x6c0x6f0x300x940x1f0x7c0x550x5a
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x810xe90x330x6d0x6b0x800x2d0x8f0x820x930x950xa8] Bifield received
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x2d0xf0xe80x430x400x90x560xa10x9e0xde0x870x1d] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::peer_comm::peer_connection] [PeerId -VT0020-0xce0x970xf60x130x6c0x6f0x300x940x1f0x7c0x550x5a]: Subpiece timed out: 5, 16384
[INFO] [stdout] test peer_comm::tests::metadata_download_multiple_pieces ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stdout] test peer_comm::tests::unchoke_recv ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stdout] test peer_comm::tests::reject_request_requests_new ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 4
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Recived a piece index: 1, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xb30x560xfd0xf20xb20x840x4d0xcc0xdc0xc10xca0xb4] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xce0x970xf60x130x6c0x6f0x300x940x1f0x7c0x550x5a] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 1 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1.5
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Peer have piece with index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xb30x560xfd0xf20xb20x840x4d0xcc0xdc0xc10xca0xb4] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stdout] test peer_comm::tests::snubbed_peer ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Peer have piece with index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Recived a piece index: 3, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 3 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::event_loop] [Peer -VT0020-0x100xd10x5e0x9a0x7c0xc90xd10x230x960xdb0xa10x91] Exiting slow start
[INFO] [stdout] test peer_comm::tests::slow_start ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 1 completed!
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 3 completed!
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 7
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 7
[INFO] [stdout] test peer_comm::tests::endgame_mode ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 2 completed!
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xbd0x4b0x3f0x380xf60x6a0x970x270x8e0x80x980x61] Recived a piece index: 4, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xbd0x4b0x3f0x380xf60x6a0x970x270x8e0x80x980x61] Recived a piece index: 4, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 4 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x3f0xf30x910xf70xb90xbe0x7b0x1f0xe20x860x3c] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::peer_connection] Received unexpected piece message, index: 5
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x3f0xf30x910xf70xb90xbe0x7b0x1f0xe20x860x3c] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 7 completed!
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x540x200x9c0xf10x230x530xee0xb0x4e0xe50x5d0xef] Peer have piece with index: 7
[INFO] [stdout] test peer_comm::tests::have ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 5 completed!
[INFO] [stdout] test peer_comm::tests::piece_recv ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 2 completed!
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x810xe90x330x6d0x6b0x800x2d0x8f0x820x930x950xa8] Recived a piece index: 4, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x810xe90x330x6d0x6b0x800x2d0x8f0x820x930x950xa8] Recived a piece index: 4, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 16384
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 4 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 4 completed!
[INFO] [stdout] test peer_comm::tests::interest_is_updated_when_recv_piece ... ok
[INFO] [stderr] [2025-09-01T05:00:26Z DEBUG vortex_bittorrent] Piece 5 completed!
[INFO] [stderr] [2025-09-01T05:00:26Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x3f0xf30x910xf70xb90xbe0x7b0x1f0xe20x860x3c] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T05:00:26Z ERROR vortex_bittorrent::peer_comm::peer_connection] Received unexpected piece message, index: 5
[INFO] [stdout] test peer_comm::tests::handles_duplicate_piece_recv ... ok
[INFO] [stderr] [2025-09-01T05:00:27Z DEBUG vortex_bittorrent] Piece 4 completed!
[INFO] [stdout] test peer_comm::tests::send_have_to_peers_when_piece_completes ... ok
[INFO] [stdout] test event_loop::tests::handshake_timeout has been running for over 60 seconds
[ERROR] error running command: no output for 300 seconds
[INFO] running `Command { std: "docker" "inspect" "a200d08bbd1591d12eaa0fd3cdec9bde3fc03578d1b62cb6e052bcc5e995f591", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a200d08bbd1591d12eaa0fd3cdec9bde3fc03578d1b62cb6e052bcc5e995f591", kill_on_drop: false }`
[INFO] [stdout] a200d08bbd1591d12eaa0fd3cdec9bde3fc03578d1b62cb6e052bcc5e995f591