[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 master#cdb45c87e2cd43495379f7e867e3cc15dcee9f93 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-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-2-tc1/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-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/Nehliin/vortex on toolchain cdb45c87e2cd43495379f7e867e3cc15dcee9f93
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "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" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]     Updating git repository `https://github.com/Nehliin/mainline.git`
[INFO] [stderr]     Updating git repository `https://github.com/tokio-rs/tokio-uring`
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded serde_bencoded v0.3.2
[INFO] [stderr]   Downloaded serde_bytes v0.11.17
[INFO] [stderr]   Downloaded human_bytes v0.4.3
[INFO] [stderr]   Downloaded sketches-ddsketch v0.3.0
[INFO] [stderr]   Downloaded lru v0.16.0
[INFO] [stderr]   Downloaded tikv-jemallocator v0.5.4
[INFO] [stderr]   Downloaded endian-type v0.1.2
[INFO] [stderr]   Downloaded hash32 v0.3.1
[INFO] [stderr]   Downloaded dyn-clone v1.0.20
[INFO] [stderr]   Downloaded castaway v0.2.4
[INFO] [stderr]   Downloaded serde_bencode v0.2.4
[INFO] [stderr]   Downloaded litrs v0.4.2
[INFO] [stderr]   Downloaded clap v4.5.42
[INFO] [stderr]   Downloaded ed25519-dalek v2.2.0
[INFO] [stderr]   Downloaded throbber-widgets-tui v0.8.0
[INFO] [stderr]   Downloaded heapless v0.8.0
[INFO] [stderr]   Downloaded metrics-exporter-prometheus v0.17.2
[INFO] [stderr]   Downloaded bt_bencode v0.8.2
[INFO] [stderr]   Downloaded metrics v0.24.2
[INFO] [stderr]   Downloaded jiff-static v0.2.15
[INFO] [stderr]   Downloaded clap_builder v4.5.42
[INFO] [stderr]   Downloaded bindgen v0.69.5
[INFO] [stderr]   Downloaded radix_trie v0.2.1
[INFO] [stderr]   Downloaded aws-lc-rs v1.13.3
[INFO] [stderr]   Downloaded metrics-util v0.20.0
[INFO] [stderr]   Downloaded nibble_vec v0.1.0
[INFO] [stderr]   Downloaded io-uring v0.6.4
[INFO] [stderr]   Downloaded instability v0.3.9
[INFO] [stderr]   Downloaded custom_derive v0.1.7
[INFO] [stderr]   Downloaded conv v0.3.3
[INFO] [stderr]   Downloaded rustls v0.23.31
[INFO] [stderr]   Downloaded rand_xoshiro v0.7.0
[INFO] [stderr]   Downloaded smallvec v2.0.0-alpha.11
[INFO] [stderr]   Downloaded jiff v0.2.15
[INFO] [stderr]   Downloaded lava_torrent v0.11.1
[INFO] [stderr]   Downloaded tokio v1.47.1
[INFO] [stderr]   Downloaded tikv-jemalloc-sys v0.5.4+5.3.0-patched
[INFO] [stderr]   Downloaded aws-lc-sys v0.30.0
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] d47843ca4a16c3b78092d42ed4a18b2a378de2fe27db64a57ac2a9c1fe4c345e
[INFO] running `Command { std: "docker" "start" "-a" "d47843ca4a16c3b78092d42ed4a18b2a378de2fe27db64a57ac2a9c1fe4c345e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "d47843ca4a16c3b78092d42ed4a18b2a378de2fe27db64a57ac2a9c1fe4c345e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "d47843ca4a16c3b78092d42ed4a18b2a378de2fe27db64a57ac2a9c1fe4c345e", kill_on_drop: false }`
[INFO] [stdout] d47843ca4a16c3b78092d42ed4a18b2a378de2fe27db64a57ac2a9c1fe4c345e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] a8162ae42e292b56b65aa5c01a8c0f09677c0a39ee2b9ffc77162eb2e27f083f
[INFO] running `Command { std: "docker" "start" "-a" "a8162ae42e292b56b65aa5c01a8c0f09677c0a39ee2b9ffc77162eb2e27f083f", 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 autocfg v1.5.0
[INFO] [stderr]    Compiling memchr v2.7.5
[INFO] [stderr]    Compiling zerocopy v0.8.26
[INFO] [stderr]    Compiling getrandom v0.3.3
[INFO] [stderr]    Compiling typenum v1.18.0
[INFO] [stderr]    Compiling jobserver v0.1.33
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling socket2 v0.6.0
[INFO] [stderr]    Compiling slab v0.4.11
[INFO] [stderr]    Compiling allocator-api2 v0.2.21
[INFO] [stderr]    Compiling fs_extra v1.3.0
[INFO] [stderr]    Compiling syn v2.0.104
[INFO] [stderr]    Compiling zeroize v1.8.1
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling dunce v1.0.5
[INFO] [stderr]    Compiling mio v1.0.4
[INFO] [stderr]    Compiling foldhash v0.1.5
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling futures-io v0.3.31
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling bitflags v2.9.1
[INFO] [stderr]    Compiling smallvec v1.15.1
[INFO] [stderr]    Compiling cpufeatures v0.2.17
[INFO] [stderr]    Compiling lock_api v0.4.13
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling cc v1.2.31
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rustversion v1.0.21
[INFO] [stderr]    Compiling aws-lc-rs v1.13.3
[INFO] [stderr]    Compiling generic-array v0.14.7
[INFO] [stderr]    Compiling ahash v0.8.12
[INFO] [stderr]    Compiling subtle v2.6.1
[INFO] [stderr]    Compiling hashbrown v0.15.4
[INFO] [stderr]    Compiling rustls-pki-types v1.12.0
[INFO] [stderr]    Compiling signal-hook v0.3.18
[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 signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling rustls v0.23.31
[INFO] [stderr]    Compiling untrusted v0.9.0
[INFO] [stderr]    Compiling try-lock v0.2.5
[INFO] [stderr]    Compiling want v0.3.1
[INFO] [stderr]    Compiling slotmap v1.0.7
[INFO] [stderr]    Compiling aho-corasick v1.1.3
[INFO] [stderr]    Compiling rustc_version v0.4.1
[INFO] [stderr]    Compiling num-traits v0.2.19
[INFO] [stderr]    Compiling getrandom v0.2.16
[INFO] [stderr]    Compiling io-uring v0.6.4
[INFO] [stderr]    Compiling httpdate v1.0.3
[INFO] [stderr]    Compiling radium v0.7.0
[INFO] [stderr]    Compiling thiserror v1.0.69
[INFO] [stderr]    Compiling instability v0.3.9
[INFO] [stderr]    Compiling curve25519-dalek v4.1.3
[INFO] [stderr]    Compiling paste v1.0.15
[INFO] [stderr]    Compiling rustix v0.38.44
[INFO] [stderr]    Compiling castaway v0.2.4
[INFO] [stderr]    Compiling rand_core v0.6.4
[INFO] [stderr]    Compiling signal-hook-mio v0.2.4
[INFO] [stderr]    Compiling cmake v0.1.54
[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 indexmap v2.10.0
[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 tap v1.0.1
[INFO] [stderr]    Compiling openssl-probe v0.1.6
[INFO] [stderr]    Compiling custom_derive v0.1.7
[INFO] [stderr]    Compiling byteorder v1.5.0
[INFO] [stderr]    Compiling tower-service v0.3.3
[INFO] [stderr]    Compiling heapless v0.8.0
[INFO] [stderr]    Compiling signature v2.2.0
[INFO] [stderr]    Compiling crypto-common v0.1.6
[INFO] [stderr]    Compiling block-buffer v0.10.4
[INFO] [stderr]    Compiling indoc v2.0.6
[INFO] [stderr]    Compiling hash32 v0.3.1
[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 digest v0.10.7
[INFO] [stderr]    Compiling conv v0.3.3
[INFO] [stderr]    Compiling compact_str v0.8.1
[INFO] [stderr]    Compiling sha1 v0.10.6
[INFO] [stderr]    Compiling sha2 v0.10.9
[INFO] [stderr]    Compiling lru v0.12.5
[INFO] [stderr]    Compiling regex-automata v0.4.9
[INFO] [stderr]    Compiling crossterm v0.28.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 spin v0.9.8
[INFO] [stderr]    Compiling rand_xoshiro v0.7.0
[INFO] [stderr]    Compiling socket2 v0.4.10
[INFO] [stderr]    Compiling ppv-lite86 v0.2.21
[INFO] [stderr]    Compiling num_cpus v1.17.0
[INFO] [stderr]    Compiling crc-catalog v2.4.0
[INFO] [stderr]    Compiling powerfmt v0.2.0
[INFO] [stderr]    Compiling sketches-ddsketch v0.3.0
[INFO] [stderr]    Compiling metrics v0.24.2
[INFO] [stderr]    Compiling unicode-width v0.2.0
[INFO] [stderr]    Compiling litrs v0.4.2
[INFO] [stderr]    Compiling funty v2.0.0
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand_chacha v0.3.1
[INFO] [stderr]    Compiling cassowary v0.3.0
[INFO] [stderr]    Compiling serde_json v1.0.142
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling rand v0.9.2
[INFO] [stderr]    Compiling rand v0.8.5
[INFO] [stderr]    Compiling bitvec v1.0.1
[INFO] [stderr]    Compiling document-features v0.2.11
[INFO] [stderr]    Compiling quanta v0.12.6
[INFO] [stderr]    Compiling clap_builder v4.5.42
[INFO] [stderr]    Compiling btoi v0.4.3
[INFO] [stderr]    Compiling crc v3.3.0
[INFO] [stderr]    Compiling flume v0.11.1
[INFO] [stderr]    Compiling jiff v0.2.15
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling dyn-clone v1.0.20
[INFO] [stderr]    Compiling num_threads v0.1.7
[INFO] [stderr]    Compiling lru v0.16.0
[INFO] [stderr]    Compiling metrics-util v0.20.0
[INFO] [stderr]    Compiling unicode-truncate v1.1.0
[INFO] [stderr]    Compiling sha1_smol v1.0.1
[INFO] [stderr]    Compiling time-core v0.1.4
[INFO] [stderr]    Compiling smallvec v2.0.0-alpha.11
[INFO] [stderr]    Compiling num-conv v0.1.0
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling crossbeam-channel v0.5.15
[INFO] [stderr]    Compiling human_bytes v0.4.3
[INFO] [stderr]    Compiling darling_core v0.20.11
[INFO] [stderr]    Compiling regex v1.11.1
[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 curve25519-dalek-derive v0.1.1
[INFO] [stderr]    Compiling strum_macros v0.26.4
[INFO] [stderr]    Compiling env_filter v0.1.3
[INFO] [stderr]    Compiling clap_derive v4.5.41
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling lava_torrent v0.11.1
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling darling_macro v0.20.11
[INFO] [stderr]    Compiling strum v0.26.3
[INFO] [stderr]    Compiling clap v4.5.42
[INFO] [stderr]    Compiling darling v0.20.11
[INFO] [stderr]    Compiling ed25519-dalek v2.2.0
[INFO] [stderr]    Compiling ratatui v0.29.0
[INFO] [stderr]    Compiling env_logger v0.11.8
[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 throbber-widgets-tui v0.8.0
[INFO] [stderr]    Compiling bytes v1.10.1
[INFO] [stderr]    Compiling serde_bytes v0.11.17
[INFO] [stderr]    Compiling bt_bencode v0.8.2
[INFO] [stderr]    Compiling deranged v0.4.0
[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 rustls-webpki v0.103.4
[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 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 2m 55s
[INFO] running `Command { std: "docker" "inspect" "a8162ae42e292b56b65aa5c01a8c0f09677c0a39ee2b9ffc77162eb2e27f083f", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a8162ae42e292b56b65aa5c01a8c0f09677c0a39ee2b9ffc77162eb2e27f083f", kill_on_drop: false }`
[INFO] [stdout] a8162ae42e292b56b65aa5c01a8c0f09677c0a39ee2b9ffc77162eb2e27f083f
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] e16bf1321b43fffe131f20966371bc807b2334a9e08d6580fea730eabfdfd88c
[INFO] running `Command { std: "docker" "start" "-a" "e16bf1321b43fffe131f20966371bc807b2334a9e08d6580fea730eabfdfd88c", 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 17.90s
[INFO] running `Command { std: "docker" "inspect" "e16bf1321b43fffe131f20966371bc807b2334a9e08d6580fea730eabfdfd88c", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "e16bf1321b43fffe131f20966371bc807b2334a9e08d6580fea730eabfdfd88c", kill_on_drop: false }`
[INFO] [stdout] e16bf1321b43fffe131f20966371bc807b2334a9e08d6580fea730eabfdfd88c
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-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:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] cd631cda8694f5f74cf72115fa58e4984035348a8e8c1d4d7105dd169a4dcfc8
[INFO] running `Command { std: "docker" "start" "-a" "cd631cda8694f5f74cf72115fa58e4984035348a8e8c1d4d7105dd169a4dcfc8", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.48s
[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::insertion_orderd_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::insertion_unorderd ... ok
[INFO] [stdout] test reorder_buffer::test::insertion_unorderd_large_gap ... ok
[INFO] [stdout] test reorder_buffer::test::removal_of_last_with_wraparound_v2 ... ok
[INFO] [stdout] test reorder_buffer::test::resizing ... ok
[INFO] [stdout] test reorder_buffer::test::insertion_orderd ... ok
[INFO] [stderr]      Running tests/end_to_end.rs (/opt/rustwide/target/debug/deps/end_to_end-6b33c5f84cb2898f)
[INFO] [stdout] test reorder_buffer::test::index_collision ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 9 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
[INFO] [stdout] 
[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::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 peer_comm::peer_protocol::tests::bitfield ... ok
[INFO] [stdout] test file_store::tests::errors_on_invalid_piece_index ... ok
[INFO] [stdout] test file_store::tests::basic_single_file_aligned ... ok
[INFO] [stdout] test file_store::tests::single_file_misaligned_v2 ... ok
[INFO] [stdout] test file_store::tests::basic_single_file_aligned_unaligned_subpiece ... ok
[INFO] [stderr] [2025-09-01T04:52:41Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x900xb50x6a0x620xec0x970x370x970x850x750xc0xc1] Have all received
[INFO] [stderr] [2025-09-01T04:52:41Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stdout] test file_store::tests::single_file_misaligned ... ok
[INFO] [stderr] [2025-09-01T04:52:41Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x900xb50x6a0x620xec0x970x370x970x850x750xc0xc1] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:41Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T04:52:41Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:41Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x900xb50x6a0x620xec0x970x370x970x850x750xc0xc1] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:41Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T04:52:41Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:41Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:41Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T04:52:41Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:41Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:41Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 0
[INFO] [stderr] [2025-09-01T04:52:41Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:41Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T04:52:41Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xbc0x900x960x00x80x8b0x9f0x560x50x1c0xcc0x25] Have all received
[INFO] [stdout] test peer_comm::tests::assume_intrest_when_request_recv ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x1d0xd10x400xf80x650xcd0x1e0x8c0xe00x180xf30x51] Received invalid bitfield, expected 9, got: 8
[INFO] [stdout] test file_store::tests::multifile_misalinged_v2 ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x220xf0x980xda0x630x130x590xa80xe10x660x390x21] Bifield received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xac0x730x170xc70x380xf0x610xea0x60xcd0xd90x25] Bifield received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xb70x7a0xb20x70xc10x390x670x130x230x7a0xbe0xb9] Bifield received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x5c0xe50x4e0xe60x520xb60x5e0x1c0x3c0x5f0x430xe] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xb70x780x230xab0x4c0xa60xae0xff0x7d0x740x2a0xaf] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x5c0xe50x4e0xe60x520xb60x5e0x1c0x3c0x5f0x430xe] Recived a piece index: 1, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x5c0xe50x4e0xe60x520xb60x5e0x1c0x3c0x5f0x430xe] Recived a piece index: 1, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 1 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x5c0xe50x4e0xe60x520xb60x5e0x1c0x3c0x5f0x430xe] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x5c0xe50x4e0xe60x520xb60x5e0x1c0x3c0x5f0x430xe] Recived a piece index: 3, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 3 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test peer_comm::tests::bitfield_recv ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test peer_comm::tests::extension_handshake_generates_correct_message ... ok
[INFO] [stdout] test peer_comm::tests::desired_queue_size ... ok
[INFO] [stdout] test file_store::tests::multifile_not_multiple_of_piece_size ... ok
[INFO] [stdout] test file_store::tests::multifile_misalinged_v3 ... ok
[INFO] [stdout] test peer_comm::tests::extension_handshake_malformed ... ok
[INFO] [stdout] test file_store::tests::small_multifile_misalinged_files_and_subpiece ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test peer_comm::tests::extension_handshake_missing_m_field ... ok
[INFO] [stdout] test peer_comm::tests::extension_handshake_with_reqq ... ok
[INFO] [stdout] test file_store::tests::small_multifile_misalinged ... ok
[INFO] [stdout] test peer_comm::tests::extension_protocol_handshake ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stdout] test peer_comm::tests::metadata_download_multiple_pieces ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xce0x1f0x630xb90xbb0x190x7b0xd70xe00xf10x650x23] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x4d0x220xf60xb30xcc0xa40xf40x770xec0xb70x180xc8] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x3e0x490xde0xb0x990xe80x400x4d0xd0x5e0x340x6f] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(3v1), index: 2
[INFO] [stdout] test peer_comm::tests::invalid_piece ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stdout] test peer_comm::tests::metadata_extension_data_message ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 1 completed!
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 3 completed!
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 7
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 7
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf90x8a0x4f0x30xaa0x810x900x360x6b0xce0xaf0x7a] Peer have piece with index: 8
[INFO] [stdout] test peer_comm::tests::have_without_interest ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x330x9f0xeb0x120x620xc10x70xd40x380x370xe0x61] Have all received
[INFO] [stdout] test peer_comm::tests::endgame_mode ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 2
[INFO] [stdout] test peer_comm::tests::metadata_extension_piece_bounds_validation ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x330x9f0xeb0x120x620xc10x70xd40x380x370xe0x61] Piece Reject request was invalid, index=-2 begin=0 length=16384
[INFO] [stderr] [2025-09-01T04:52:42Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x330x9f0xeb0x120x620xc10x70xd40x380x370xe0x61] Piece Reject request was invalid, index=2 begin=16385 length=16384
[INFO] [stderr] [2025-09-01T04:52:42Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x330x9f0xeb0x120x620xc10x70xd40x380x370xe0x61] Piece Reject request was invalid, index=2 begin=0 length=16385
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z ERROR vortex_bittorrent::peer_comm::peer_connection] Unexpected extended msg
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 99
[INFO] [stderr] [2025-09-01T04:52:42Z ERROR vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension unknown type: 99
[INFO] [stdout] test peer_comm::tests::invalid_reject_request ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe70xcf0xdd0xb50x800xb60xd10x970x730x4d0xad0xd9] Peer have piece with index: 7
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe70xcf0xdd0xb50x800xb60xd10x970x730x4d0xad0xd9] Peer have piece with index: 7
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x430xe0x4c0x450xc70xc40x10x190x450xce0x950x94] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xaa0xea0xd0xc10xeb0x3e0xf10xa0xd30x50xf20x18] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x7c0x200xe10xb20x430xff0xe90x910x20xfb0x27] Bifield received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x7c0x200xe10xb20x430xff0xe90x910x20xfb0x27] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x7c0x200xe10xb20x430xff0xe90x910x20xfb0x27] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 7
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x3c0x900xca0xb00xa50x230x320xea0x6e0xe80x800xf8] Peer have piece with index: 7
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe70xcf0xdd0xb50x800xb60xd10x970x730x4d0xad0xd9] Recived a piece index: 7, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 7, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe70xcf0xdd0xb50x800xb60xd10x970x730x4d0xad0xd9] Recived a piece index: 7, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 7, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 7 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x540x7f0x410xcd0x2f0x450x5e0xcd0x410xab0xda0xae] Have None received
[INFO] [stdout] test peer_comm::tests::extension_message_unknown_id ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x500x7c0xd40xc40x240x7a0x800x770x670x170x71] Have all received
[INFO] [stdout] test peer_comm::tests::fast_ext_have_all ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stdout] test peer_comm::tests::metadata_extension_invalid_message_type ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x500x7c0xd40xc40x240x7a0x800x770x670x170x71] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stdout] test peer_comm::tests::fast_ext_have_none ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stdout] test peer_comm::tests::metadata_download_single_piece ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stdout] test file_store::tests::basic_multifile_alinged ... ok
[INFO] [stdout] test peer_comm::tests::have_invalid_indicies ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Peer have piece with index: 1
[INFO] [stdout] test file_store::tests::multifile_misalinged ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Peer have piece with index: 2
[INFO] [stdout] test peer_comm::tests::metadata_extension_request_message ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Peer have piece with index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Peer have piece with index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Peer have piece with index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Peer have piece with index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Unchoked and start downloading
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 0.65
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf30x3d0xa90xe10xb0x410xb90xfa0x100x40xc80x1e] Peer is choking us!
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8f0xaf0xae0x110xa30xc10xc90x830xb80xcd0x570x2a] Bifield received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe40xc70x140x4b0x90x80xc60x240xb90x860xd10x35] Bifield received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8f0xaf0xae0x110xa30xc10xc90x830xb80xcd0x570x2a] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8f0xaf0xae0x110xa30xc10xc90x830xb80xcd0x570x2a] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stdout] test peer_comm::tests::peer_choke_recv_supports_fast ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x9b0xa10xb40x450xa10x990xe00x200x7a0x840x6d0xda] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x9b0xa10xb40x450xa10x990xe00x200x7a0x840x6d0xda] Unchoked and start downloading
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 2
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::peer_comm::extended_protocol] Got reject request
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xf60xdc0x660x440x700xb10xe30xb50xf40xaa0x30x4f] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::peer_comm::peer_connection] [PeerId -VT0020-0xf60xdc0x660x440x700xb10xe30xb50xf40xaa0x30x4f]: Subpiece request rejected: 5, 0
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930x280x1d0x8b0xe90x580x30x470x5c0xbc0x260x9c] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930x280x1d0x8b0xe90x580x30x470x5c0xbc0x260x9c] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930x280x1d0x8b0xe90x580x30x470x5c0xbc0x260x9c] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Peer have piece with index: 1
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Recived a piece index: 1, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Recived a piece index: 1, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 1 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 1.5
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Peer have piece with index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Peer have piece with index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Recived a piece index: 3, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 3 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::event_loop] [Peer -VT0020-0xd50x120xda0xed0xd90x7b0xa70xba0x5b0x1c0x4e0x19] Exiting slow start
[INFO] [stdout] test peer_comm::tests::unchoke_recv ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Peer have piece with index: 1
[INFO] [stdout] test peer_comm::tests::metadata_extension_reject_message ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Peer have piece with index: 2
[INFO] [stdout] test peer_comm::tests::reject_request_requests_new ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Peer have piece with index: 3
[INFO] [stdout] test peer_comm::tests::slow_start ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Peer have piece with index: 4
[INFO] [stdout] test peer_comm::tests::snubbed_peer ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Peer have piece with index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Peer have piece with index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Unchoked and start downloading
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xeb0x780x870x760x860x3c0xd60x7d0x790xf80xeb0x8] Have all received
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xeb0x780x870x760x860x3c0xd60x7d0x790xf80xeb0x8] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::event_loop] TIMEOUT: -VT0020-0xeb0x780x870x760x860x3c0xd60x7d0x790xf80xeb0x8
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::peer_comm::peer_connection] [PeerId -VT0020-0xeb0x780x870x760x860x3c0xd60x7d0x790xf80xeb0x8]: Subpiece timed out: 5, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xeb0x780x870x760x860x3c0xd60x7d0x790xf80xeb0x8] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T04:52:42Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::event_loop] Tick!: 0.65
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xea0xb90xd10x900xc40xe0x5e0x900xe00x230xee0x2e] Peer is choking us!
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 1
[INFO] [stdout] test peer_comm::tests::peer_choke_recv_does_not_support_fast ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 2 completed!
[INFO] [stdout] test peer_comm::tests::have ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x7c0x200xe10xb20x430xff0xe90x910x20xfb0x27] Recived a piece index: 4, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x800x7c0x200xe10xb20x430xff0xe90x910x20xfb0x27] Recived a piece index: 4, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 4 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 7 completed!
[INFO] [stderr] [2025-09-01T04:52:42Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xee0xe40x3a0x770xb80x440x440xb90x810xa40xea0xd3] Peer have piece with index: 7
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x500x7c0xd40xc40x240x7a0x800x770x670x170x71] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stdout] test peer_comm::tests::piece_recv ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z ERROR vortex_bittorrent::peer_comm::peer_connection] Received unexpected piece message, index: 5
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x500x7c0xd40xc40x240x7a0x800x770x670x170x71] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 5 completed!
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 2 completed!
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe40xc70x140x4b0x90x80xc60x240xb90x860xd10x35] Recived a piece index: 4, begin: 0, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe40xc70x140x4b0x90x80xc60x240xb90x860xd10x35] Recived a piece index: 4, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 16384
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 4 download completed, sending to hash thread
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 4 completed!
[INFO] [stdout] test peer_comm::tests::interest_is_updated_when_recv_piece ... ok
[INFO] [stderr] [2025-09-01T04:52:42Z DEBUG vortex_bittorrent] Piece 5 completed!
[INFO] [stderr] [2025-09-01T04:52:42Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x500x7c0xd40xc40x240x7a0x800x770x670x170x71] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-01T04:52:42Z 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-01T04:52:42Z 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" "cd631cda8694f5f74cf72115fa58e4984035348a8e8c1d4d7105dd169a4dcfc8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "cd631cda8694f5f74cf72115fa58e4984035348a8e8c1d4d7105dd169a4dcfc8", kill_on_drop: false }`
[INFO] [stdout] cd631cda8694f5f74cf72115fa58e4984035348a8e8c1d4d7105dd169a4dcfc8