[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#ad85bc524b1ad696e42061ad8338d382dffbdbe5 for pr-146237
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2FNehliin%2Fvortex" "/workspace/builds/worker-4-tc1/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-4-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-4-tc1/source/Cargo.toml
[INFO] validating manifest of git repo https://github.com/Nehliin/vortex on toolchain ad85bc524b1ad696e42061ad8338d382dffbdbe5
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+ad85bc524b1ad696e42061ad8338d382dffbdbe5" "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" "+ad85bc524b1ad696e42061ad8338d382dffbdbe5" "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 quanta v0.12.6
[INFO] [stderr]   Downloaded sketches-ddsketch v0.3.0
[INFO] [stderr]   Downloaded metrics-util v0.20.0
[INFO] [stderr]   Downloaded smallvec v2.0.0-alpha.11
[INFO] [stderr]   Downloaded rand_xoshiro v0.7.0
[INFO] [stderr]   Downloaded io-uring v0.6.4
[INFO] [stderr]   Downloaded human_bytes v0.4.3
[INFO] [stderr]   Downloaded btoi v0.4.3
[INFO] [stderr]   Downloaded num_threads v0.1.7
[INFO] [stderr]   Downloaded castaway v0.2.4
[INFO] [stderr]   Downloaded humantime v2.2.0
[INFO] [stderr]   Downloaded derive_arbitrary v1.4.1
[INFO] [stderr]   Downloaded metrics-exporter-prometheus v0.17.2
[INFO] [stderr]   Downloaded signal-hook v0.3.18
[INFO] [stderr]   Downloaded clap v4.5.42
[INFO] [stderr]   Downloaded throbber-widgets-tui v0.8.0
[INFO] [stderr]   Downloaded ed25519-dalek v2.2.0
[INFO] [stderr]   Downloaded bt_bencode v0.8.2
[INFO] [stderr]   Downloaded raw-cpuid v11.5.0
[INFO] [stderr]   Downloaded clap_builder v4.5.42
[INFO] [stderr]   Downloaded cc v1.2.31
[INFO] [stderr]   Downloaded aws-lc-rs v1.13.3
[INFO] [stderr]   Downloaded bindgen v0.69.5
[INFO] [stderr]   Downloaded heapless v0.8.0
[INFO] [stderr]   Downloaded security-framework v3.2.0
[INFO] [stderr]   Downloaded prettyplease v0.2.36
[INFO] [stderr]   Downloaded metrics v0.24.2
[INFO] [stderr]   Downloaded compact_str v0.8.1
[INFO] [stderr]   Downloaded rustls v0.23.31
[INFO] [stderr]   Downloaded rustls-native-certs v0.8.1
[INFO] [stderr]   Downloaded core-foundation v0.10.1
[INFO] [stderr]   Downloaded hyper-rustls v0.27.7
[INFO] [stderr]   Downloaded dyn-clone v1.0.20
[INFO] [stderr]   Downloaded lru v0.16.0
[INFO] [stderr]   Downloaded serde_bencode v0.2.4
[INFO] [stderr]   Downloaded tikv-jemallocator v0.5.4
[INFO] [stderr]   Downloaded hash32 v0.3.1
[INFO] [stderr]   Downloaded indoc v2.0.6
[INFO] [stderr]   Downloaded instability v0.3.9
[INFO] [stderr]   Downloaded lava_torrent v0.11.1
[INFO] [stderr]   Downloaded aws-lc-sys v0.30.0
[INFO] [stderr]   Downloaded serde_bencoded v0.3.2
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+ad85bc524b1ad696e42061ad8338d382dffbdbe5" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] ae780a31440d8b4a0da7872862391c4f166a7b93b1fa60887110efa796a94fe0
[INFO] running `Command { std: "docker" "start" "-a" "ae780a31440d8b4a0da7872862391c4f166a7b93b1fa60887110efa796a94fe0", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "ae780a31440d8b4a0da7872862391c4f166a7b93b1fa60887110efa796a94fe0", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "ae780a31440d8b4a0da7872862391c4f166a7b93b1fa60887110efa796a94fe0", kill_on_drop: false }`
[INFO] [stdout] ae780a31440d8b4a0da7872862391c4f166a7b93b1fa60887110efa796a94fe0
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+ad85bc524b1ad696e42061ad8338d382dffbdbe5" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 66300ca7f215fa83984a00a6fcde0231dc37d1f2e4e3e36e5f04034cb9855f9e
[INFO] running `Command { std: "docker" "start" "-a" "66300ca7f215fa83984a00a6fcde0231dc37d1f2e4e3e36e5f04034cb9855f9e", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.174
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling syn v2.0.104
[INFO] [stderr]    Compiling getrandom v0.3.3
[INFO] [stderr]    Compiling dunce v1.0.5
[INFO] [stderr]    Compiling fs_extra v1.3.0
[INFO] [stderr]    Compiling hashbrown v0.15.4
[INFO] [stderr]    Compiling semver v1.0.26
[INFO] [stderr]    Compiling aws-lc-rs v1.13.3
[INFO] [stderr]    Compiling rustversion v1.0.21
[INFO] [stderr]    Compiling ahash v0.8.12
[INFO] [stderr]    Compiling rustls-pki-types v1.12.0
[INFO] [stderr]    Compiling ident_case v1.0.1
[INFO] [stderr]    Compiling signal-hook v0.3.18
[INFO] [stderr]    Compiling rustix v0.38.44
[INFO] [stderr]    Compiling rustls v0.23.31
[INFO] [stderr]    Compiling anstyle-parse v0.2.7
[INFO] [stderr]    Compiling num-traits v0.2.19
[INFO] [stderr]    Compiling aho-corasick v1.1.3
[INFO] [stderr]    Compiling slotmap v1.0.7
[INFO] [stderr]    Compiling linux-raw-sys v0.4.15
[INFO] [stderr]    Compiling anstyle-query v1.1.3
[INFO] [stderr]    Compiling radium v0.7.0
[INFO] [stderr]    Compiling colorchoice v1.0.4
[INFO] [stderr]    Compiling indexmap v2.10.0
[INFO] [stderr]    Compiling io-uring v0.6.4
[INFO] [stderr]    Compiling anstyle v1.0.11
[INFO] [stderr]    Compiling regex-syntax v0.8.5
[INFO] [stderr]    Compiling instability v0.3.9
[INFO] [stderr]    Compiling sha1 v0.10.6
[INFO] [stderr]    Compiling itertools v0.13.0
[INFO] [stderr]    Compiling raw-cpuid v11.5.0
[INFO] [stderr]    Compiling anstream v0.6.19
[INFO] [stderr]    Compiling tap v1.0.1
[INFO] [stderr]    Compiling signature v2.2.0
[INFO] [stderr]    Compiling rustc_version v0.4.1
[INFO] [stderr]    Compiling io-uring v0.7.9
[INFO] [stderr]    Compiling heapless v0.8.0
[INFO] [stderr]    Compiling custom_derive v0.1.7
[INFO] [stderr]    Compiling indoc v2.0.6
[INFO] [stderr]    Compiling rustls-native-certs v0.8.1
[INFO] [stderr]    Compiling castaway v0.2.4
[INFO] [stderr]    Compiling hash32 v0.3.1
[INFO] [stderr]    Compiling compact_str v0.8.1
[INFO] [stderr]    Compiling jobserver v0.1.33
[INFO] [stderr]    Compiling mio v1.0.4
[INFO] [stderr]    Compiling socket2 v0.6.0
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling parking_lot_core v0.9.11
[INFO] [stderr]    Compiling getrandom v0.2.16
[INFO] [stderr]    Compiling curve25519-dalek v4.1.3
[INFO] [stderr]    Compiling cc v1.2.31
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling parking_lot v0.12.4
[INFO] [stderr]    Compiling rand_core v0.6.4
[INFO] [stderr]    Compiling socket2 v0.4.10
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand_chacha v0.3.1
[INFO] [stderr]    Compiling metrics v0.24.2
[INFO] [stderr]    Compiling rand v0.9.2
[INFO] [stderr]    Compiling signal-hook-mio v0.2.4
[INFO] [stderr]    Compiling crossterm v0.28.1
[INFO] [stderr]    Compiling rand_xoshiro v0.7.0
[INFO] [stderr]    Compiling regex-automata v0.4.9
[INFO] [stderr]    Compiling num_cpus v1.17.0
[INFO] [stderr]    Compiling conv v0.3.3
[INFO] [stderr]    Compiling wyz v0.5.1
[INFO] [stderr]    Compiling ed25519 v2.2.3
[INFO] [stderr]    Compiling anyhow v1.0.98
[INFO] [stderr]    Compiling unicode-truncate v1.1.0
[INFO] [stderr]    Compiling lru v0.12.5
[INFO] [stderr]    Compiling sha2 v0.10.9
[INFO] [stderr]    Compiling spin v0.9.8
[INFO] [stderr]    Compiling itertools v0.10.5
[INFO] [stderr]    Compiling litrs v0.4.2
[INFO] [stderr]    Compiling cmake v0.1.54
[INFO] [stderr]    Compiling stable_deref_trait v1.2.0
[INFO] [stderr]    Compiling cassowary v0.3.0
[INFO] [stderr]    Compiling crc-catalog v2.4.0
[INFO] [stderr]    Compiling funty v2.0.0
[INFO] [stderr]    Compiling clap_lex v0.7.5
[INFO] [stderr]    Compiling unicode-width v0.2.0
[INFO] [stderr]    Compiling quanta v0.12.6
[INFO] [stderr]    Compiling sketches-ddsketch v0.3.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 metrics-util v0.20.0
[INFO] [stderr]    Compiling btoi v0.4.3
[INFO] [stderr]    Compiling rand v0.8.5
[INFO] [stderr]    Compiling document-features v0.2.11
[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 bitvec v1.0.1
[INFO] [stderr]    Compiling sha1_smol v1.0.1
[INFO] [stderr]    Compiling smallvec v2.0.0-alpha.11
[INFO] [stderr]    Compiling jiff v0.2.15
[INFO] [stderr]    Compiling dyn-clone v1.0.20
[INFO] [stderr]    Compiling base64 v0.22.1
[INFO] [stderr]    Compiling lru v0.16.0
[INFO] [stderr]    Compiling ipnet v2.11.0
[INFO] [stderr]    Compiling num_threads v0.1.7
[INFO] [stderr]    Compiling human_bytes v0.4.3
[INFO] [stderr]    Compiling humantime v2.2.0
[INFO] [stderr]    Compiling darling_core v0.20.11
[INFO] [stderr]    Compiling regex v1.11.1
[INFO] [stderr]    Compiling env_filter v0.1.3
[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 strum_macros v0.26.4
[INFO] [stderr]    Compiling thiserror-impl v1.0.69
[INFO] [stderr]    Compiling curve25519-dalek-derive v0.1.1
[INFO] [stderr]    Compiling clap_derive v4.5.41
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v1.0.69
[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 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_json v1.0.142
[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 utp-socket v0.1.1 (/opt/rustwide/workdir/utp-socket)
[INFO] [stderr]    Compiling vortex-dht v0.1.1 (/opt/rustwide/workdir/dht)
[INFO] [stderr]    Compiling tokio-rustls v0.26.2
[INFO] [stderr]    Compiling hyper v1.6.0
[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 31s
[INFO] running `Command { std: "docker" "inspect" "66300ca7f215fa83984a00a6fcde0231dc37d1f2e4e3e36e5f04034cb9855f9e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "66300ca7f215fa83984a00a6fcde0231dc37d1f2e4e3e36e5f04034cb9855f9e", kill_on_drop: false }`
[INFO] [stdout] 66300ca7f215fa83984a00a6fcde0231dc37d1f2e4e3e36e5f04034cb9855f9e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+ad85bc524b1ad696e42061ad8338d382dffbdbe5" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] ef6eef4b16db531b819372f52bd308a54ce04e22a02b0401a26b9850977b4c3d
[INFO] running `Command { std: "docker" "start" "-a" "ef6eef4b16db531b819372f52bd308a54ce04e22a02b0401a26b9850977b4c3d", 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 15.37s
[INFO] running `Command { std: "docker" "inspect" "ef6eef4b16db531b819372f52bd308a54ce04e22a02b0401a26b9850977b4c3d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "ef6eef4b16db531b819372f52bd308a54ce04e22a02b0401a26b9850977b4c3d", kill_on_drop: false }`
[INFO] [stdout] ef6eef4b16db531b819372f52bd308a54ce04e22a02b0401a26b9850977b4c3d
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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" "+ad85bc524b1ad696e42061ad8338d382dffbdbe5" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 72ee5817fb9b0cbd812c365527cf92689d50c81f102266a23aa32ab6a16da538
[INFO] running `Command { std: "docker" "start" "-a" "72ee5817fb9b0cbd812c365527cf92689d50c81f102266a23aa32ab6a16da538", 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 ... ok
[INFO] [stdout] test reorder_buffer::test::index_collision ... ok
[INFO] [stdout] test reorder_buffer::test::insertion_orderd_large_gap ... 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 ... 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] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/vortex_bittorrent-36ccf44d1d101f56)
[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] [stdout] 
[INFO] [stdout] running 51 tests
[INFO] [stdout] test peer_comm::peer_protocol::tests::bitfield ... ok
[INFO] [stdout] test peer_comm::peer_protocol::tests::bitfield_roundtrip ... ok
[INFO] [stdout] test peer_comm::peer_protocol::tests::empty_bitfield ... 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::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_v2 ... ok
[INFO] [stdout] test file_store::tests::single_file_misaligned ... ok
[INFO] [stdout] test file_store::tests::multifile_misalinged_v2 ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x2c0xda0xba0x170xe90xbc0x730x360x600xc70x460xd] Received invalid bitfield, expected 9, got: 8
[INFO] [stdout] test peer_comm::tests::assume_intrest_when_request_recv ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa10xd80x8f0x80x550x6e0xd80x7d0x570xea0xc50xf9] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe0x3a0xb00xe20x910xf10x8f0xe20xe20x300xf20x47] Bifield received
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x350xa30x6a0x2f0x440xa80xab0x190x50x6f0x60x1e] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa30xa90x00xc70xb60xf40x6c0x5a0xed0xd90xed0x6e] Bifield received
[INFO] [stdout] test peer_comm::tests::bitfield_recv ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x2c0xa40x1f0xa30x4b0xf10x350xd30xf20x290x960xb8] Bifield received
[INFO] [stdout] test peer_comm::tests::extension_handshake_with_reqq ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x2e0xc80x970xa60x8a0x250x6c0x880xa20x320x200x48] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xac0x490xf40x730x390xb50x830x690xc0x810xda0xa1] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xac0x490xf40x730x390xb50x830x690xc0x810xda0xa1] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xac0x490xf40x730x390xb50x830x690xc0x810xda0xa1] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 0
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stdout] test file_store::tests::small_multifile_misalinged_files_and_subpiece ... ok
[INFO] [stdout] test file_store::tests::multifile_not_multiple_of_piece_size ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x350xa30x6a0x2f0x440xa80xab0x190x50x6f0x60x1e] Recived a piece index: 1, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 0
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x350xa30x6a0x2f0x440xa80xab0x190x50x6f0x60x1e] Recived a piece index: 1, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 1 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x350xa30x6a0x2f0x440xa80xab0x190x50x6f0x60x1e] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x350xa30x6a0x2f0x440xa80xab0x190x50x6f0x60x1e] Recived a piece index: 3, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 3 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:20Z 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_protocol_handshake ... ok
[INFO] [stdout] test file_store::tests::multifile_misalinged_v3 ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z ERROR vortex_bittorrent::peer_comm::peer_connection] Unexpected extended msg
[INFO] [stdout] test peer_comm::tests::desired_queue_size ... ok
[INFO] [stdout] test file_store::tests::small_multifile_misalinged ... ok
[INFO] [stdout] test peer_comm::tests::extension_message_unknown_id ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xb60xc10xd40x60x990x140x3a0x2e0xb40xf30xb60xde] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x160x880x3d0x3c0x890x260x820xa70x1b0xe20xeb0x77] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd0xe40x480xcd0xa40x260xc00xe50x9b0xb00x5a0x94] Have None received
[INFO] [stdout] test peer_comm::tests::extension_handshake_generates_correct_message ... ok
[INFO] [stdout] test peer_comm::tests::extension_handshake_missing_m_field ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xbc0xd0x8f0xa40x3a0xba0x9f0x280x2d0x8c0x340xc2] Peer have piece with index: 8
[INFO] [stdout] test peer_comm::tests::fast_ext_have_all ... ok
[INFO] [stdout] test peer_comm::tests::fast_ext_have_none ... ok
[INFO] [stdout] test peer_comm::tests::have_without_interest ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa00x4f0xa60xf30x220x7c0xb50x9e0xcc0xbb0xa80xb7] Peer have piece with index: 7
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa00x4f0xa60xf30x220x7c0xb50x9e0xcc0xbb0xa80xb7] Peer have piece with index: 7
[INFO] [stderr] [2025-09-10T07:28:20Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 7
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x80x920x70xd00x6c0x130x560x120x6b0xc30x9b0x59] Peer have piece with index: 7
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa00x4f0xa60xf30x220x7c0xb50x9e0xcc0xbb0xa80xb7] Recived a piece index: 7, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 7, 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xa00x4f0xa60xf30x220x7c0xb50x9e0xcc0xbb0xa80xb7] Recived a piece index: 7, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 7, 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stdout] test peer_comm::tests::have_invalid_indicies ... ok
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 7 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Piece 1 completed!
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Piece 3 completed!
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 2
[INFO] [stderr] [2025-09-10T07:28:20Z WARN  vortex_bittorrent::peer_comm::extended_protocol] Got reject request
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 7
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::piece_selector] Peer ConnectionId(1v1) is entering endgame mode
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 7
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930xe30x9a0x520x690xbb0x60x310x570x4f0xfa0xea] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930xe30x9a0x520x690xbb0x60x310x570x4f0xfa0xea] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:20Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd50x680x9c0xc10xaa0x220x730xfc0x110x260x370x50] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:20Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc70xd10x390x600x2b0x60xc00xd00xef0x00xd10xce] Have all received
[INFO] [stderr] [2025-09-10T07:28:20Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xb50xf50x840xdc0x5f0x730x7b0x310x1a0x290x430x61] Have all received
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(3v1), index: 2
[INFO] [stdout] test peer_comm::tests::metadata_extension_data_message ... ok
[INFO] [stdout] test peer_comm::tests::metadata_extension_reject_message ... ok
[INFO] [stdout] test peer_comm::tests::endgame_mode ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test file_store::tests::multifile_misalinged ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stdout] test peer_comm::tests::invalid_piece ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 1
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe30x3d0x6d0xcf0x720x890x980xa00xd00xfa0xa70x40] Bifield received
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe30x3d0x6d0xcf0x720x890x980xa00xd00xfa0xa70x40] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe30x3d0x6d0xcf0x720x890x980xa00xd00xfa0xa70x40] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stdout] test file_store::tests::basic_multifile_alinged ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Peer have piece with index: 1
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Peer have piece with index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Peer have piece with index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Peer have piece with index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Peer have piece with index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Peer have piece with index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Unchoked and start downloading
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stdout] test peer_comm::tests::metadata_extension_piece_bounds_validation ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 0.65
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x190x500xb60x900x270x70xdc0x70xac0xdc0xb80xdf] Peer is choking us!
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Peer have piece with index: 1
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Peer have piece with index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Peer have piece with index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Peer have piece with index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Peer have piece with index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Peer have piece with index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Unchoked and start downloading
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 0.65
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x300x540x8f0x950xd20x370xfb0x960xae0xfa0x1d0x38] Peer is choking us!
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 6
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 1
[INFO] [stdout] test peer_comm::tests::peer_choke_recv_supports_fast ... ok
[INFO] [stdout] test peer_comm::tests::peer_choke_recv_does_not_support_fast ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Piece 7 completed!
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xcc0x220xdc0x560x930x660xb30x3a0xd20xa0x1a0xbd] Peer have piece with index: 7
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stdout] test peer_comm::tests::metadata_download_single_piece ... ok
[INFO] [stdout] test peer_comm::tests::metadata_extension_invalid_message_type ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 99
[INFO] [stderr] [2025-09-10T07:28:21Z ERROR vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension unknown type: 99
[INFO] [stdout] test peer_comm::tests::have ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Peer have piece with index: 1
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 1
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Recived a piece index: 1, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Recived a piece index: 1, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 1, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 1 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 1.5
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Peer have piece with index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x260x460xe30x580x340xb50x3b0xdb0x960xab0x7c0x54] Have all received
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x260x460xe30x580x340xb50x3b0xdb0x960xab0x7c0x54] Unchoked and start downloading
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8e0xc20xe20xb60x970x480x8a0x150xe90x120x8c0xab] Have all received
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8e0xc20xe20xb60x970x480x8a0x150xe90x120x8c0xab] Piece Reject request was invalid, index=-2 begin=0 length=16384
[INFO] [stderr] [2025-09-10T07:28:21Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8e0xc20xe20xb60x970x480x8a0x150xe90x120x8c0xab] Piece Reject request was invalid, index=2 begin=16385 length=16384
[INFO] [stderr] [2025-09-10T07:28:21Z ERROR vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x8e0xc20xe20xb60x970x480x8a0x150xe90x120x8c0xab] Piece Reject request was invalid, index=2 begin=0 length=16385
[INFO] [stdout] test peer_comm::tests::unchoke_recv ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Extended message handshake
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd40x9d0xa00xd90xb50x260x2c0x150x940x9b0x2f0x58] Bifield received
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Peer have piece with index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::piece_selector] Random piece selection failed
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::extended_protocol] Got metadata extension message of type: 0
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x580xad0xbf0x9f0xca0x610xf50x330x5a0x6d0x9c0xfb] Bifield received
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(2v1), index: 4
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd40x9d0xa00xd90xb50x260x2c0x150x940x9b0x2f0x58] Recived a piece index: 2, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Recived a piece index: 3, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 3 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::event_loop] [Peer -VT0020-0x400xf10xc80x9d0x450xfb0xd0x8a0xe80x4a0xae0x2f] Exiting slow start
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd40x9d0xa00xd90xb50x260x2c0x150x940x9b0x2f0x58] Recived a piece index: 2, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 2, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 2 download completed, sending to hash thread
[INFO] [stdout] test peer_comm::tests::invalid_reject_request ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x540x5f0x4c0xa80x590x990x510xc10x2d0x420xb8] Have all received
[INFO] [stdout] test peer_comm::tests::metadata_extension_request_message ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x540x5f0x4c0xa80x590x990x510xc10x2d0x420xb8] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xc0x540x5f0x4c0xa80x590x990x510xc10x2d0x420xb8] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stdout] test peer_comm::tests::slow_start ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930xe30x9a0x520x690xbb0x60x310x570x4f0xfa0xea] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z ERROR vortex_bittorrent::peer_comm::peer_connection] Received unexpected piece message, index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930xe30x9a0x520x690xbb0x60x310x570x4f0xfa0xea] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 5 download completed, sending to hash thread
[INFO] [stdout] test peer_comm::tests::metadata_download_multiple_pieces ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xd90x6e0x430x2c0xa80xfc0xe0x950xe40x6f0xfd0xd] Have all received
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::peer_comm::peer_connection] [PeerId -VT0020-0xd90x6e0x430x2c0xa80xfc0xe0x950xe40x6f0xfd0xd]: Subpiece request rejected: 5, 0
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xfb0x750xba0x5d0x440xc80x620x270xfd0x410x70xcb] Have all received
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xfb0x750xba0x5d0x440xc80x620x270xfd0x410x70xcb] Recived a piece index: 5, begin: 0, length: 16384
[INFO] [stdout] test peer_comm::tests::reject_request_requests_new ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 5, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::event_loop] TIMEOUT: -VT0020-0xfb0x750xba0x5d0x440xc80x620x270xfd0x410x70xcb
[INFO] [stderr] [2025-09-10T07:28:21Z WARN  vortex_bittorrent::peer_comm::peer_connection] [PeerId -VT0020-0xfb0x750xba0x5d0x440xc80x620x270xfd0x410x70xcb]: Subpiece timed out: 5, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Deallocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] marked as not allocated: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 3
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xfb0x750xba0x5d0x440xc80x620x270xfd0x410x70xcb] Recived a piece index: 3, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 3, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z INFO  vortex_bittorrent::event_loop] Tick!: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 5
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Allocating piece: conn_id: ConnectionId(1v1), index: 2
[INFO] [stdout] test peer_comm::tests::snubbed_peer ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Piece 2 completed!
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe30x3d0x6d0xcf0x720x890x980xa00xd00xfa0xa70x40] Recived a piece index: 4, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0xe30x3d0x6d0xcf0x720x890x980xa00xd00xfa0xa70x40] Recived a piece index: 4, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 4 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Piece 5 completed!
[INFO] [stdout] test peer_comm::tests::piece_recv ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Piece 5 completed!
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x930xe30x9a0x520x690xbb0x60x310x570x4f0xfa0xea] Recived a piece index: 5, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z 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-10T07:28:21Z DEBUG vortex_bittorrent] Piece 2 completed!
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x580xad0xbf0x9f0xca0x610xf50x330x5a0x6d0x9c0xfb] Recived a piece index: 4, begin: 0, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 0
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] [Peer: -VT0020-0x580xad0xbf0x9f0xca0x610xf50x330x5a0x6d0x9c0xfb] Recived a piece index: 4, begin: 16384, length: 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::peer_comm::peer_connection] Subpiece completed: 4, 16384
[INFO] [stderr] [2025-09-10T07:28:21Z TRACE vortex_bittorrent::piece_selector] Subpiece index received: 1
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent::peer_comm::peer_connection] Piece 4 download completed, sending to hash thread
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Piece 4 completed!
[INFO] [stdout] test peer_comm::tests::interest_is_updated_when_recv_piece ... ok
[INFO] [stdout] test peer_comm::tests::send_have_to_peers_when_piece_completes ... ok
[INFO] [stderr] [2025-09-10T07:28:21Z DEBUG vortex_bittorrent] Piece 4 completed!
[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" "72ee5817fb9b0cbd812c365527cf92689d50c81f102266a23aa32ab6a16da538", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "72ee5817fb9b0cbd812c365527cf92689d50c81f102266a23aa32ab6a16da538", kill_on_drop: false }`
[INFO] [stdout] 72ee5817fb9b0cbd812c365527cf92689d50c81f102266a23aa32ab6a16da538