[INFO] fetching crate swarmforge 0.1.0...
[INFO] testing swarmforge-0.1.0 against 1.99.0-beta.8+cargoflags=--release for beta-release-1.100-2
[INFO] extracting crate swarmforge 0.1.0 into /workspace/builds/worker-5-tc1/source
[INFO] started tweaking crates.io crate swarmforge 0.1.0
[INFO] removed 0 missing examples
[INFO] finished tweaking crates.io crate swarmforge 0.1.0
[INFO] tweaked toml for crates.io crate swarmforge 0.1.0 written to /workspace/builds/worker-5-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate swarmforge 0.1.0 on toolchain 1.99.0-beta.8
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.99.0-beta.8" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate crates.io crate swarmforge 0.1.0 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" "+1.99.0-beta.8" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded wasm-bindgen-macro v0.2.123
[INFO] [stderr]   Downloaded wasm-bindgen v0.2.123
[INFO] [stderr]   Downloaded wasm-bindgen-shared v0.2.123
[INFO] [stderr]   Downloaded utoipa-axum v0.2.0
[INFO] [stderr]   Downloaded wasm-bindgen-macro-support v0.2.123
[INFO] [stderr]   Downloaded utoipa-swagger-ui v9.0.2
[INFO] [stderr]   Downloaded swarmforge-upnp v0.1.0
[INFO] [stderr]   Downloaded wasm-bindgen-futures v0.4.73
[INFO] [stderr]   Downloaded utoipa v5.5.0
[INFO] [stderr]   Downloaded js-sys v0.3.100
[INFO] [stderr]   Downloaded swarmforge-upnp-serve v0.1.0
[INFO] [stderr]   Downloaded zip v3.0.0
[INFO] [stderr]   Downloaded utoipa-gen v5.5.0
[INFO] [stderr]   Downloaded web-sys v0.3.100
[INFO] [stderr]   Downloaded network-interface v2.0.5
[INFO] [stderr]   Downloaded librqbit-dualstack-sockets v0.7.0
[INFO] [stderr]   Downloaded assert_cfg v0.1.0
[INFO] [stderr]   Downloaded swarmforge-clone-to-owned v0.1.0
[INFO] [stderr]   Downloaded swarmforge-sha1-wrapper v0.1.0
[INFO] [stderr]   Downloaded swarmforge-buffers v0.1.0
[INFO] [stderr]   Downloaded atoi v3.0.0
[INFO] [stderr]   Downloaded swarmforge-bencode v0.1.0
[INFO] [stderr]   Downloaded swarmforge-tracker-comms v0.1.0
[INFO] [stderr]   Downloaded swarmforge-core v0.1.0
[INFO] [stderr]   Downloaded swarmforge-peer-protocol v0.1.0
[INFO] [stderr]   Downloaded leaky-bucket v1.1.2
[INFO] [stderr]   Downloaded swarmforge-lsd v0.1.0
[INFO] [stderr]   Downloaded swarmforge-dht v0.1.0
[INFO] [stderr]   Downloaded whoami v2.1.2
[INFO] [stderr]   Downloaded size_format v1.0.2
[INFO] [stderr]   Downloaded rlimit v0.11.0
[INFO] [stderr]   Downloaded rsqlite-vfs v0.1.1
[INFO] [stderr]   Downloaded dontfrag v1.0.1
[INFO] [stderr]   Downloaded governor v0.10.4
[INFO] [stderr]   Downloaded mediatype v0.19.20
[INFO] [stderr]   Downloaded librqbit-utp v0.7.0
[INFO] [stderr]   Downloaded feed-rs v2.3.1
[INFO] [stderr]   Downloaded async-backtrace v0.2.7
[INFO] [stderr]   Downloaded hdrhistogram v7.5.4
[INFO] [stderr]   Downloaded sqlite-wasm-rs v0.5.5
[INFO] [stderr]   Downloaded async-backtrace-attributes v0.2.7
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,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" "-m" "1610612736" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:77db811e55d90add9212f6832c23229e3de5f1c1f9905e8cb07319ea15df73ac" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d
[INFO] running `Command { std: "docker" "start" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-w" "/opt/rustwide/workdir" "--user" "0:0" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "build" "--frozen" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.117
[INFO] [stderr]    Compiling serde v1.0.228
[INFO] [stderr]    Compiling bitflags v2.13.0
[INFO] [stderr]    Compiling http v1.4.2
[INFO] [stderr]    Compiling mio v1.2.1
[INFO] [stderr]    Compiling cc v1.2.63
[INFO] [stderr]    Compiling typewit v1.15.2
[INFO] [stderr]    Compiling swarmforge-clone-to-owned v0.1.0
[INFO] [stderr]    Compiling getrandom v0.4.2
[INFO] [stderr]    Compiling either v1.16.0
[INFO] [stderr]    Compiling hex v0.3.2
[INFO] [stderr]    Compiling native-tls v0.2.18
[INFO] [stderr]    Compiling fastrand v2.4.1
[INFO] [stderr]    Compiling dirs-sys v0.5.0
[INFO] [stderr]    Compiling atoi v3.0.0
[INFO] [stderr]    Compiling aho-corasick v1.1.4
[INFO] [stderr]    Compiling arrayvec v0.7.6
[INFO] [stderr]    Compiling log v0.4.32
[INFO] [stderr]    Compiling zeroize v1.8.2
[INFO] [stderr]    Compiling directories v6.0.0
[INFO] [stderr]    Compiling rand v0.10.1
[INFO] [stderr]    Compiling serde_json v1.0.150
[INFO] [stderr]    Compiling const_panic v0.2.15
[INFO] [stderr]    Compiling itertools v0.14.0
[INFO] [stderr]    Compiling chardetng v1.0.0
[INFO] [stderr]    Compiling radium v0.7.0
[INFO] [stderr]    Compiling data-encoding v2.11.0
[INFO] [stderr]    Compiling num-integer v0.1.46
[INFO] [stderr]    Compiling num-rational v0.2.4
[INFO] [stderr]    Compiling tap v1.0.1
[INFO] [stderr]    Compiling assert_cfg v0.1.0
[INFO] [stderr]    Compiling wyz v0.5.1
[INFO] [stderr]    Compiling rustls-pki-types v1.14.1
[INFO] [stderr]    Compiling anyhow v1.0.102
[INFO] [stderr]    Compiling funty v2.0.0
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling aws-lc-rs v1.17.0
[INFO] [stderr]    Compiling portable-atomic v1.13.1
[INFO] [stderr]    Compiling nix v0.31.3
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling num-iter v0.1.45
[INFO] [stderr]    Compiling mime_guess v2.0.5
[INFO] [stderr]    Compiling num-complex v0.2.4
[INFO] [stderr]    Compiling rapidhash v4.4.1
[INFO] [stderr]    Compiling raw-cpuid v11.6.0
[INFO] [stderr]    Compiling untrusted v0.7.1
[INFO] [stderr]    Compiling bitvec v1.0.1
[INFO] [stderr]    Compiling virtue v0.0.18
[INFO] [stderr]    Compiling compression-core v0.4.32
[INFO] [stderr]    Compiling cmake v0.1.58
[INFO] [stderr]    Compiling rlimit v0.11.0
[INFO] [stderr]    Compiling metrics v0.24.6
[INFO] [stderr]    Compiling num v0.2.1
[INFO] [stderr]    Compiling compression-codecs v0.4.38
[INFO] [stderr]    Compiling generic-array v0.12.4
[INFO] [stderr]    Compiling swarmforge v0.1.0 (/opt/rustwide/workdir)
[INFO] [stderr]    Compiling regex-automata v0.4.14
[INFO] [stderr]    Compiling openssl-sys v0.9.116
[INFO] [stderr]    Compiling network-interface v2.0.5
[INFO] [stderr]    Compiling aws-lc-sys v0.41.0
[INFO] [stderr]    Compiling serde_html_form v0.2.8
[INFO] [stderr]    Compiling uuid v1.23.3
[INFO] [stderr]    Compiling bincode_derive v2.0.1
[INFO] [stderr]    Compiling spinning_top v0.3.0
[INFO] [stderr]    Compiling quick-xml v0.37.5
[INFO] [stderr]    Compiling openssl v0.10.80
[INFO] [stderr]    Compiling serde_path_to_error v0.1.20
[INFO] [stderr]    Compiling unty v0.0.4
[INFO] [stderr]    Compiling urlencoding v2.1.3
[INFO] [stderr]    Compiling futures-timer v3.0.4
[INFO] [stderr]    Compiling unicase v2.9.0
[INFO] [stderr]    Compiling bincode v2.0.1
[INFO] [stderr]    Compiling quanta v0.12.6
[INFO] [stderr]    Compiling size_format v1.0.2
[INFO] [stderr]    Compiling arc-swap v1.9.1
[INFO] [stderr]    Compiling memmap2 v0.9.10
[INFO] [stderr]    Compiling intervaltree v0.2.7
[INFO] [stderr]    Compiling synstructure v0.13.2
[INFO] [stderr]    Compiling darling_core v0.23.0
[INFO] [stderr]    Compiling tokio-macros v2.7.0
[INFO] [stderr]    Compiling zerofrom-derive v0.1.7
[INFO] [stderr]    Compiling yoke-derive v0.8.2
[INFO] [stderr]    Compiling zerovec-derive v0.11.3
[INFO] [stderr]    Compiling displaydoc v0.2.6
[INFO] [stderr]    Compiling serde_derive v1.0.228
[INFO] [stderr]    Compiling futures-macro v0.3.32
[INFO] [stderr]    Compiling tracing-attributes v0.1.31
[INFO] [stderr]    Compiling tokio v1.52.3
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.18
[INFO] [stderr]    Compiling futures-util v0.3.32
[INFO] [stderr]    Compiling zerofrom v0.1.8
[INFO] [stderr]    Compiling bstr v1.12.1
[INFO] [stderr]    Compiling async-stream-impl v0.3.6
[INFO] [stderr]    Compiling yoke v0.8.3
[INFO] [stderr]    Compiling thiserror-impl v1.0.69
[INFO] [stderr]    Compiling zerovec v0.11.6
[INFO] [stderr]    Compiling zerotrie v0.2.4
[INFO] [stderr]    Compiling async-stream v0.3.6
[INFO] [stderr]    Compiling tracing v0.1.44
[INFO] [stderr]    Compiling regex v1.12.4
[INFO] [stderr]    Compiling async-trait v0.1.89
[INFO] [stderr]    Compiling axum-core v0.5.6
[INFO] [stderr]    Compiling thiserror v2.0.18
[INFO] [stderr]    Compiling tinystr v0.8.3
[INFO] [stderr]    Compiling potential_utf v0.1.5
[INFO] [stderr]    Compiling icu_collections v2.2.0
[INFO] [stderr]    Compiling icu_locale_core v2.2.0
[INFO] [stderr]    Compiling darling_macro v0.23.0
[INFO] [stderr]    Compiling thiserror v1.0.69
[INFO] [stderr]    Compiling darling v0.23.0
[INFO] [stderr]    Compiling serde_with_macros v3.21.0
[INFO] [stderr]    Compiling swarmforge-buffers v0.1.0
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling icu_provider v2.2.0
[INFO] [stderr]    Compiling swarmforge-bencode v0.1.0
[INFO] [stderr]    Compiling chrono v0.4.45
[INFO] [stderr]    Compiling dashmap v6.2.1
[INFO] [stderr]    Compiling serde_with v3.21.0
[INFO] [stderr]    Compiling mediatype v0.19.20
[INFO] [stderr]    Compiling quick-xml v0.40.1
[INFO] [stderr]    Compiling icu_normalizer v2.2.0
[INFO] [stderr]    Compiling icu_properties v2.2.0
[INFO] [stderr]    Compiling crypto-hash v0.3.4
[INFO] [stderr]    Compiling futures-executor v0.3.32
[INFO] [stderr]    Compiling swarmforge-sha1-wrapper v0.1.0
[INFO] [stderr]    Compiling futures v0.3.32
[INFO] [stderr]    Compiling governor v0.10.4
[INFO] [stderr]    Compiling hyper v1.10.1
[INFO] [stderr]    Compiling tower v0.5.3
[INFO] [stderr]    Compiling idna_adapter v1.2.2
[INFO] [stderr]    Compiling idna v1.1.0
[INFO] [stderr]    Compiling tokio-util v0.7.18
[INFO] [stderr]    Compiling backon v1.6.0
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling dontfrag v1.0.1
[INFO] [stderr]    Compiling leaky-bucket v1.1.2
[INFO] [stderr]    Compiling tokio-socks v0.5.3
[INFO] [stderr]    Compiling async-compression v0.4.42
[INFO] [stderr]    Compiling tokio-stream v0.1.18
[INFO] [stderr]    Compiling url v2.5.8
[INFO] [stderr]    Compiling hyper-util v0.1.20
[INFO] [stderr]    Compiling swarmforge-core v0.1.0
[INFO] [stderr]    Compiling tower-http v0.6.11
[INFO] [stderr]    Compiling feed-rs v2.3.1
[INFO] [stderr]    Compiling swarmforge-peer-protocol v0.1.0
[INFO] [stderr]    Compiling axum v0.8.9
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.13.4
[INFO] [stderr]    Compiling librqbit-dualstack-sockets v0.7.0
[INFO] [stderr]    Compiling axum-extra v0.12.6
[INFO] [stderr]    Compiling swarmforge-upnp v0.1.0
[INFO] [stderr]    Compiling librqbit-utp v0.7.0
[INFO] [stderr]    Compiling swarmforge-lsd v0.1.0
[INFO] [stderr]    Compiling swarmforge-tracker-comms v0.1.0
[INFO] [stderr]    Compiling swarmforge-dht v0.1.0
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 3m 30s
[INFO] running `Command { std: "docker" "inspect" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "test" "--frozen" "--no-run" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling tokio v1.52.3
[INFO] [stderr]    Compiling openssl v0.10.80
[INFO] [stderr]    Compiling raw-cpuid v11.6.0
[INFO] [stderr]    Compiling nix v0.31.3
[INFO] [stderr]    Compiling thread_local v1.1.9
[INFO] [stderr]    Compiling tempfile v3.27.0
[INFO] [stderr]    Compiling pollster v0.4.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.23
[INFO] [stderr]    Compiling quanta v0.12.6
[INFO] [stderr]    Compiling governor v0.10.4
[INFO] [stderr]    Compiling crypto-hash v0.3.4
[INFO] [stderr]    Compiling native-tls v0.2.18
[INFO] [stderr]    Compiling swarmforge-sha1-wrapper v0.1.0
[INFO] [stderr]    Compiling hyper v1.10.1
[INFO] [stderr]    Compiling tower v0.5.3
[INFO] [stderr]    Compiling tokio-util v0.7.18
[INFO] [stderr]    Compiling backon v1.6.0
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling leaky-bucket v1.1.2
[INFO] [stderr]    Compiling dontfrag v1.0.1
[INFO] [stderr]    Compiling tokio-socks v0.5.3
[INFO] [stderr]    Compiling async-compression v0.4.42
[INFO] [stderr]    Compiling swarmforge-core v0.1.0
[INFO] [stderr]    Compiling tower-http v0.6.11
[INFO] [stderr]    Compiling tokio-stream v0.1.18
[INFO] [stderr]    Compiling tokio-test v0.4.5
[INFO] [stderr]    Compiling swarmforge-peer-protocol v0.1.0
[INFO] [stderr]    Compiling hyper-util v0.1.20
[INFO] [stderr]    Compiling axum v0.8.9
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.13.4
[INFO] [stderr]    Compiling librqbit-dualstack-sockets v0.7.0
[INFO] [stderr]    Compiling axum-extra v0.12.6
[INFO] [stderr]    Compiling swarmforge-dht v0.1.0
[INFO] [stderr]    Compiling swarmforge-lsd v0.1.0
[INFO] [stderr]    Compiling swarmforge-tracker-comms v0.1.0
[INFO] [stderr]    Compiling librqbit-utp v0.7.0
[INFO] [stderr]    Compiling swarmforge-upnp v0.1.0
[INFO] [stderr]    Compiling swarmforge v0.1.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 2m 19s
[INFO] running `Command { std: "docker" "inspect" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "test" "--frozen" "--release", kill_on_drop: false }`
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 0.69s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/deps/librtbit-69b7dac55a94c5c5)
[INFO] [stdout] 
[INFO] [stdout] running 119 tests
[INFO] [stdout] test chunk_tracker::tests::test_chunk_status_all_complete ... ok
[INFO] [stdout] test chunk_tracker::tests::test_update_only_files_expand ... ok
[INFO] [stdout] test chunk_tracker::tests::test_eta_overflow_safety ... ok
[INFO] [stdout] test chunk_tracker::tests::test_is_chunk_ready_to_upload ... ok
[INFO] [stdout] test chunk_tracker::tests::test_mark_piece_downloaded_updates_hns ... ok
[INFO] [stdout] test chunk_tracker::tests::test_piece_index_large_values ... ok
[INFO] [stdout] test dht_utils::tests::read_metainfo_from_dht ... ignored
[INFO] [stdout] test ip_ranges::tests::test_list_empty ... ok
[INFO] [stdout] test chunk_tracker::tests::test_update_only_files ... ok
[INFO] [stdout] test ip_ranges::tests::test_list_real_url ... ignored
[INFO] [stdout] test chunk_tracker::tests::test_chunk_status_partial ... ok
[INFO] [stdout] test ip_ranges::tests::test_list_plaintext ... ok
[INFO] [stdout] test chunk_tracker::tests::test_compute_chunk_status ... ok
[INFO] [stdout] test ip_ranges::tests::test_manual_ranges ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_handshake_deserialize_too_short ... ok
[INFO] [stdout] test file_info::tests::test_iter_piece_priorities ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_handshake_encoding ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_handshake_roundtrip ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_interested_message ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_message_framing ... ok
[INFO] [stdout] test ip_ranges::tests::test_list_gzipped ... ok
[INFO] [stdout] test chunk_tracker::tests::test_mark_piece_broken_requeues ... ok
[INFO] [stdout] test piece_tracker::tests::test_complete_piece ... ok
[INFO] [stdout] test piece_tracker::tests::test_fail_piece_requeues ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_unchoke_message ... ok
[INFO] [stdout] test chunk_tracker::tests::test_update_only_files_shrink ... ok
[INFO] [stdout] test piece_tracker::tests::test_into_chunks_requeues_inflight ... ok
[INFO] [stdout] test piece_tracker::tests::test_multiple_peers_competing ... ok
[INFO] [stdout] test piece_tracker::tests::test_new_piece_tracker ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_options_default ... ok
[INFO] [stdout] test piece_tracker::tests::test_none_available_when_no_pieces ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_options_serialization ... ok
[INFO] [stdout] test peer_connection::tests::test_peer_connection_handshake_supports_extended ... ok
[INFO] [stdout] test piece_tracker::tests::test_priority_pieces_checked_first ... ok
[INFO] [stdout] test piece_tracker::tests::test_release_pieces_owned_by_peer ... ok
[INFO] [stdout] test piece_tracker::tests::test_all_pieces_completed ... ok
[INFO] [stdout] test piece_tracker::tests::test_reserve_filters_by_peer_has_piece ... ok
[INFO] [stdout] test ip_ranges::tests::test_list_from_plaintext_file ... FAILED
[INFO] [stdout] test read_buf::tests::test_read_buf_miri ... ignored, run with --features=miri only, doesn't work with tokio
[INFO] [stdout] test piece_tracker::tests::test_reserve_piece_from_queue ... ok
[INFO] [stdout] test piece_tracker::tests::test_take_inflight_nonexistent_piece_returns_none ... ok
[INFO] [stdout] test read_buf::tests::test_ringbuf_ranges ... ok
[INFO] [stdout] test read_buf::tests::test_ringbuf_advance ... ok
[INFO] [stdout] test read_buf::tests::test_read_buf_error_large_values ... ok
[INFO] [stdout] test read_buf::tests::test_ringbuf_make_contiguous ... ok
[INFO] [stdout] test read_buf::tests::test_unfilled_ioslices ... ok
[INFO] [stdout] test piece_tracker::tests::test_steal_only_pieces_peer_has ... ok
[INFO] [stdout] test session::helpers::tests::test_merge_two_optional_streams_both ... ok
[INFO] [stdout] test session::helpers::tests::test_merge_two_optional_streams_both_none ... ok
[INFO] [stdout] test session::helpers::tests::test_merge_two_optional_streams_first_only ... ok
[INFO] [stdout] test session::helpers::tests::test_merge_two_optional_streams_second_only ... ok
[INFO] [stdout] test session::helpers::tests::test_torrent_from_bytes_invalid ... ok
[INFO] [stdout] test piece_tracker::tests::test_steal_piece_from_slowest_peer ... ok
[INFO] [stdout] test session::helpers::tests::test_compute_only_files_none ... ok
[INFO] [stdout] test create_torrent_file::tests::test_create_torrent_multi_file ... ok
[INFO] [stdout] test session::peer_sources::tests::disabling_trackers_clears_private_and_public_trackers ... ok
[INFO] [stdout] test session::peer_sources::tests::public_torrents_include_session_trackers ... ok
[INFO] [stdout] test session::helpers::tests::test_compute_only_files_invalid_index ... ok
[INFO] [stdout] test session::helpers::tests::test_compute_only_files_regex ... ok
[INFO] [stdout] test session::peer_sources::tests::private_torrents_keep_all_declared_trackers ... ok
[INFO] [stdout] test session::tests::expand_folder_template_replaces_and_sanitizes_category ... ok
[INFO] [stdout] test session::helpers::tests::test_compute_only_files_mutually_exclusive ... ok
[INFO] [stdout] test create_torrent_file::tests::test_create_torrent_piece_hashes ... ok
[INFO] [stdout] test session::helpers::tests::test_compute_only_files_by_index ... ok
[INFO] [stdout] test create_torrent_file::tests::test_create_torrent_with_trackers ... ok
[INFO] [stdout] test session::helpers::tests::test_torrent_from_bytes_valid ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_filesystem_storage_write_at_offset ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_filesystem_storage_write_and_read ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_filesystem_storage_piece_hash_verification ... ok
[INFO] [stdout] test create_torrent_file::tests::test_create_torrent ... ok
[INFO] [stdout] test session::helpers::tests::test_compute_only_files_regex_no_match ... ok
[INFO] [stdout] 2026-10-18T18:07:30.126712Z  WARN librtbit::storage::filesystem::fs: did not remove "/tmp/.tmp1IJOEO/subdir" as it was not empty
[INFO] [stdout] test create_torrent_file::tests::test_create_torrent_magnet ... ok
[INFO] [stdout] test create_torrent_file::tests::test_create_torrent_single_file ... ok
[INFO] [stdout] test create_torrent_file::tests::test_create_torrent_roundtrip ... ok
[INFO] [stdout] test session::tests::test_torrent_file_from_info_and_bytes ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_ensure_file_length ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_handles_sparse_writes ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_remove_directory_if_empty ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_invalid_file_id ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_file_boundaries ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_remove_directory_not_empty ... ok
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_remove_file ... ok
[INFO] [stdout] test tests::e2e_another_local_client::test_tcp_with_another_client ... ignored
[INFO] [stdout] test tests::e2e_another_local_client::test_utp_with_another_client ... ignored
[INFO] [stdout] test storage::filesystem::opened_file::tests::test_pwrite_all_vectored ... ok
[INFO] [stdout] 2026-10-18T18:07:30.130119Z  INFO librtbit::tests::test_util: created tempdir path="/tmp/test_session_shutdownXsig80"
[INFO] [stdout] 2026-10-18T18:07:30.131236Z  INFO librtbit::tests::e2e: increased ulimit limit=524288
[INFO] [stdout] 2026-10-18T18:07:30.131325Z  INFO librtbit::tests::test_util: created tempdir path="/tmp/rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:30.132358Z  INFO librtbit::tests::e2e: increased ulimit limit=524288
[INFO] [stdout] 2026-10-18T18:07:30.132469Z  INFO librtbit::tests::test_util: created tempdir path="/tmp/rtbit_e2eiMuMbX"
[INFO] [stdout] test storage::filesystem::opened_file::tests::test_write_path_large_file_offsets ... ok
[INFO] [stdout] 2026-10-18T18:07:30.143514Z  INFO librtbit::tests::test_util: created tempdir path="/tmp/test_e2e_streamEB7rIY"
[INFO] [stdout] 2026-10-18T18:07:30.143937Z  INFO librtbit::listen: Listening on TCP 127.0.0.1:16001 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.146426Z  INFO librtbit::tests::test_util: created tempdir path="/tmp/test_delete_initBC6G1u"
[INFO] [stdout] 2026-10-18T18:07:30.150596Z  INFO librtbit::listen: Listening on TCP 127.0.0.1:40133 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.151668Z  INFO librtbit::tests::test_util: created tempdir path="/tmp/test_cancel_tokenxmj6jt"
[INFO] [stdout] 2026-10-18T18:07:30.153108Z  INFO librtbit::tests::test_util: created tempdir path="/tmp/test_pause_init5dxnTw"
[INFO] [stdout] test storage::filesystem::fs::tests::test_storage_take ... ok
[INFO] [stdout] test session_persistence::json::tests::json_store_persists_session_settings ... ok
[INFO] [stdout] test torrent_state::live::peer::stats::atomic::tests::test_backoff_produces_bounded_delays ... ok
[INFO] [stdout] 2026-10-18T18:07:30.161337Z  INFO librtbit::listen: Listening on TCP 127.0.0.1:41089 for incoming peer connections
[INFO] [stdout] test torrent_state::live::peer::stats::atomic::tests::test_backoff_reset_is_independent ... ok
[INFO] [stdout] test session::tests::test_init_semaphore_doesnt_deadlock ... ok
[INFO] [stdout] test torrent_state::live::peer::stats::atomic::tests::test_backoff_reset_produces_new_delays ... ok
[INFO] [stdout] test torrent_state::live::peer_handler::tests::private_torrent_strips_metadata_extensions ... ok
[INFO] [stdout] test torrent_state::live::peer_handler::tests::public_torrent_advertises_metadata_size ... ok
[INFO] [stdout] test tests::mock_tracker::tests::supports_connect_announce_and_scrape ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_active_peer_count ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_dead_peer_pruning_counters_are_decremented ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_dead_peer_pruning_preserves_queued_and_connecting ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_dead_peer_pruning_preserves_recent_peers ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_dead_peer_pruning_removes_stale_dead_peers ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_dead_peer_pruning_removes_stale_not_needed_peers ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_dead_peer_requeue ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_peer_stats_tracking ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_peers_not_permanently_dropped ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_semaphore_permit_returned_on_drop ... ok
[INFO] [stdout] test torrent_state::live::peers::tests::test_backoff_reset_on_rediscovery ... ok
[INFO] [stdout] test session::helpers::tests::torrent_from_file_url_reads_local_torrent ... ok
[INFO] [stdout] 2026-10-18T18:07:30.291193Z  INFO librtbit::tests::e2e_stream: created server session
[INFO] [stdout] 2026-10-18T18:07:30.291382Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.291546Z  INFO librtbit::torrent_state::initializing: Initial check results: have 8.0Ki, needed 0, total selected 8.0Ki torrent=0
[INFO] [stdout] 2026-10-18T18:07:30.291673Z  INFO librtbit::session: added torrent name="test_e2e_streamEB7rIY"
[INFO] [stdout] 2026-10-18T18:07:30.291793Z  INFO librtbit::tests::e2e_stream: server torrent was completed
[INFO] [stdout] 2026-10-18T18:07:30.296590Z  INFO librtbit::session: added torrent name="test_pause_init5dxnTw"
[INFO] [stdout] 2026-10-18T18:07:30.296643Z  INFO librtbit::tests::cancel_init: pause succeeded during initialization
[INFO] [stdout] 2026-10-18T18:07:30.296648Z  INFO librtbit::tests::cancel_init: state after pause: error
[INFO] [stdout] 2026-10-18T18:07:30.296651Z  INFO librtbit::tests::cancel_init: test_pause_during_initialization passed
[INFO] [stdout] test tests::cancel_init::test_pause_during_initialization ... ok
[INFO] [stdout] 2026-10-18T18:07:30.303291Z ERROR librtbit_core::spawn_utils: speed_estimator finished with error: session is dead
[INFO] [stdout] test session::tests::test_magnet_resolution_timeout ... FAILED
[INFO] [stdout] 2026-10-18T18:07:30.320423Z  INFO librtbit::session: added torrent name="test_cancel_tokenxmj6jt"
[INFO] [stdout] 2026-10-18T18:07:30.321129Z  INFO librtbit::session: added torrent name="payload.bin"
[INFO] [stdout] 2026-10-18T18:07:30.324478Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.324676Z  INFO librtbit::torrent_state::initializing: Initial check results: have 16.0Ki, needed 0, total selected 16.0Ki torrent=0
[INFO] [stdout] 2026-10-18T18:07:30.325709Z  INFO librtbit::session: added torrent name="test_delete_initBC6G1u"
[INFO] [stdout] 2026-10-18T18:07:30.325736Z  INFO librtbit::tests::cancel_init: torrent is initializing: true
[INFO] [stdout] 2026-10-18T18:07:30.325796Z  INFO librtbit::session: deleted torrent id=0
[INFO] [stdout] 2026-10-18T18:07:30.325802Z  INFO librtbit::tests::cancel_init: test_delete_cancels_initializing_torrent passed
[INFO] [stdout] 2026-10-18T18:07:30.326536Z ERROR librtbit_core::spawn_utils: speed_estimator finished with error: session is dead
[INFO] [stdout] 2026-10-18T18:07:30.326658Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.327005Z  INFO librtbit::torrent_state::initializing: Initial check results: have 256.0Ki, needed 0, total selected 256.0Ki torrent=0
[INFO] [stdout] 2026-10-18T18:07:30.326553Z  INFO librtbit::session: added torrent name="payload.bin"
[INFO] [stdout] 2026-10-18T18:07:30.327126Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.327279Z  INFO librtbit::torrent_state::initializing: Initial check results: have 0, needed 4.0Ki, total selected 4.0Ki torrent=0
[INFO] [stdout] 2026-10-18T18:07:30.328012Z  INFO librtbit::session: deleted torrent id=0
[INFO] [stdout] 2026-10-18T18:07:30.328037Z  INFO librtbit::tests::cancel_init: test_cancellation_token_propagation passed
[INFO] [stdout] 2026-10-18T18:07:30.328229Z ERROR librtbit_core::spawn_utils: speed_estimator finished with error: session is dead
[INFO] [stdout] 2026-10-18T18:07:30.329251Z  INFO librtbit::listen: Listening on TCP 127.0.0.1:34979 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.338112Z  INFO librtbit::tests::e2e_stream: created client session
[INFO] [stdout] 2026-10-18T18:07:30.338436Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] test tests::cancel_init::test_cancellation_token_propagation ... ok
[INFO] [stdout] 2026-10-18T18:07:30.338571Z  INFO librtbit::torrent_state::initializing: Initial check results: have 0, needed 8.0Ki, total selected 8.0Ki torrent=0
[INFO] [stdout] 2026-10-18T18:07:30.338615Z  INFO librtbit::session: added torrent name="test_e2e_streamEB7rIY"
[INFO] [stdout] 2026-10-18T18:07:30.338993Z  INFO librtbit::tests::e2e_stream: client torrent initialized, starting stream
[INFO] [stdout] test tests::cancel_init::test_delete_cancels_initializing_torrent ... ok
[INFO] [stdout] 2026-10-18T18:07:30.354793Z  INFO librtbit::session: added torrent name="payload.bin"
[INFO] [stdout] 2026-10-18T18:07:30.354839Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.354938Z  INFO librtbit::torrent_state::initializing: Initial check results: have 0, needed 256.0Ki, total selected 256.0Ki torrent=0
[INFO] [stdout] 2026-10-18T18:07:30.365112Z  INFO librtbit::session: added torrent name="test_session_shutdownXsig80"
[INFO] [stdout] 2026-10-18T18:07:30.368131Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.368376Z  INFO librtbit::torrent_state::initializing: Initial check results: have 0, needed 4.0Ki, total selected 4.0Ki torrent=0
[INFO] [stdout] 2026-10-18T18:07:30.401307Z  INFO librtbit::torrent_state::live: torrent finished downloading id=0 info_hash=fc4894ab800502b7974389c51a1955f029d60747
[INFO] [stdout] test tests::mock_tracker::tests::leech_discovers_seed_through_tracker ... ok
[INFO] [stdout] 2026-10-18T18:07:30.424332Z  INFO librtbit::torrent_state::live: torrent finished downloading id=0 info_hash=3ae31587e6ddd3e3e340444c7eb9bbcf65e51003
[INFO] [stdout] test session::tests::test_concurrent_init_limit_configurable ... ok
[INFO] [stdout] test tests::e2e_stream::test_e2e_stream ... ok
[INFO] [stdout] 2026-10-18T18:07:30.542224Z  WARN server{id=0}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.542501Z  INFO server{id=0}: librtbit::listen: Listening on UDP 127.0.0.1:15100 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.545187Z  WARN server{id=3}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.545307Z  WARN server{id=7}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.545485Z  INFO server{id=3}: librtbit::listen: Listening on UDP 127.0.0.1:15103 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.545568Z  INFO server{id=7}: librtbit::listen: Listening on UDP 127.0.0.1:15107 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.547225Z  WARN server{id=11}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.547489Z  INFO server{id=11}: librtbit::listen: Listening on UDP 127.0.0.1:15111 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.548170Z  WARN server{id=5}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.548415Z  INFO server{id=5}: librtbit::listen: Listening on UDP 127.0.0.1:15105 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.550180Z  WARN server{id=13}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.550239Z  WARN server{id=9}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.550417Z  INFO server{id=13}: librtbit::listen: Listening on UDP 127.0.0.1:15113 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.550498Z  INFO server{id=9}: librtbit::listen: Listening on UDP 127.0.0.1:15109 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.553191Z  WARN server{id=15}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.553438Z  INFO server{id=15}: librtbit::listen: Listening on UDP 127.0.0.1:15115 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.554174Z  WARN server{id=17}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.554408Z  INFO server{id=17}: librtbit::listen: Listening on UDP 127.0.0.1:15117 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.558208Z  WARN server{id=18}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.558443Z  INFO server{id=18}: librtbit::listen: Listening on UDP 127.0.0.1:15118 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.565201Z  INFO server{id=0}: librtbit::listen: Listening on TCP 127.0.0.1:15100 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.565211Z  WARN server{id=19}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.569291Z  INFO server{id=19}: librtbit::listen: Listening on UDP 127.0.0.1:15119 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.571216Z  WARN server{id=20}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.571501Z  INFO server{id=20}: librtbit::listen: Listening on UDP 127.0.0.1:15120 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.577235Z  WARN server{id=21}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.577515Z  INFO server{id=21}: librtbit::listen: Listening on UDP 127.0.0.1:15121 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.578198Z  INFO server{id=3}: librtbit::listen: Listening on TCP 127.0.0.1:15103 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.578498Z  WARN server{id=22}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.578723Z  INFO server{id=22}: librtbit::listen: Listening on UDP 127.0.0.1:15122 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.581157Z  INFO server{id=5}: librtbit::listen: Listening on TCP 127.0.0.1:15105 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.582165Z  WARN server{id=23}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.582221Z  INFO server{id=7}: librtbit::listen: Listening on TCP 127.0.0.1:15107 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.582248Z  WARN server{id=24}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.582405Z  INFO server{id=23}: librtbit::listen: Listening on UDP 127.0.0.1:15123 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.582484Z  INFO server{id=24}: librtbit::listen: Listening on UDP 127.0.0.1:15124 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.584212Z  INFO server{id=1}: librtbit::listen: Listening on TCP 127.0.0.1:15101 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.592212Z  INFO server{id=9}: librtbit::listen: Listening on TCP 127.0.0.1:15109 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.601219Z  INFO server{id=11}: librtbit::listen: Listening on TCP 127.0.0.1:15111 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.602218Z  INFO server{id=13}: librtbit::listen: Listening on TCP 127.0.0.1:15113 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.610225Z  INFO server{id=15}: librtbit::listen: Listening on TCP 127.0.0.1:15115 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.633230Z  INFO server{id=17}: librtbit::listen: Listening on TCP 127.0.0.1:15117 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.638245Z  INFO server{id=22}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.645219Z  INFO server{id=18}: librtbit::listen: Listening on TCP 127.0.0.1:15118 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.647623Z  INFO server{id=22}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.647665Z  INFO server{id=22}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.647743Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.648201Z  WARN server{id=25}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.648413Z  INFO server{id=25}: librtbit::listen: Listening on UDP 127.0.0.1:15125 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.654202Z  INFO server{id=19}: librtbit::listen: Listening on TCP 127.0.0.1:15119 for incoming peer connections
[INFO] [stdout] test read_buf::tests::can_read_long_metainfo_correctly ... ok
[INFO] [stdout] 2026-10-18T18:07:30.661806Z  INFO server{id=23}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.663245Z  INFO server{id=20}: librtbit::listen: Listening on TCP 127.0.0.1:15120 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.667269Z  WARN server{id=26}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.667485Z  INFO server{id=26}: librtbit::listen: Listening on UDP 127.0.0.1:15126 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.674343Z  INFO server{id=7}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.674674Z  INFO server{id=7}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.674697Z  INFO server{id=7}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.674768Z  WARN server{id=8}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.674865Z  INFO server{id=8}: librtbit::listen: Listening on UDP 127.0.0.1:15108 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.681927Z  INFO server{id=13}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.682228Z  INFO server{id=13}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.682254Z  INFO server{id=13}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.682324Z  WARN server{id=14}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.682431Z  INFO server{id=14}: librtbit::listen: Listening on UDP 127.0.0.1:15114 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.683134Z  INFO server{id=23}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.683161Z  INFO server{id=23}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.684082Z  INFO server{id=5}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.684352Z  INFO server{id=5}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:30.684373Z  INFO server{id=5}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.684432Z  INFO server{id=6}: librtbit::listen: Listening on TCP 127.0.0.1:15106 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.686371Z  INFO server{id=15}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.687389Z  INFO server{id=17}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.707344Z  INFO server{id=15}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.707588Z  INFO server{id=15}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.707661Z  INFO server{id=20}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.707802Z  INFO server{id=17}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.707845Z  INFO server{id=17}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.707900Z  INFO server{id=20}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.707939Z  INFO server{id=20}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.708040Z  WARN server{id=28}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.708149Z  INFO server{id=28}: librtbit::listen: Listening on UDP 127.0.0.1:15128 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.689067Z  INFO server{id=21}: librtbit::listen: Listening on TCP 127.0.0.1:15121 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.711211Z  INFO server{id=23}: librtbit::listen: Listening on TCP 127.0.0.1:15123 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.707495Z  INFO server{id=22}: librtbit::listen: Listening on TCP 127.0.0.1:15122 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.707554Z  WARN server{id=16}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.711792Z  INFO server{id=16}: librtbit::listen: Listening on UDP 127.0.0.1:15116 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.722103Z  WARN server{id=27}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.722412Z  INFO server{id=27}: librtbit::listen: Listening on UDP 127.0.0.1:15127 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.688881Z  INFO server{id=3}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.729395Z  INFO server{id=3}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:30.729448Z  INFO server{id=3}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.729553Z  INFO server{id=4}: librtbit::listen: Listening on TCP 127.0.0.1:15104 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.734246Z  INFO server{id=1}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.734593Z  INFO server{id=1}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:30.734609Z  INFO server{id=1}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.734675Z  INFO server{id=2}: librtbit::listen: Listening on TCP 127.0.0.1:15102 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.742266Z  INFO server{id=3}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.742547Z  WARN server{id=4}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.742663Z  INFO server{id=4}: librtbit::listen: Listening on UDP 127.0.0.1:15104 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.747269Z  INFO server{id=3}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.756088Z  INFO server{id=3}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.733011Z  INFO server{id=7}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.756520Z  INFO server{id=7}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:30.756567Z  INFO server{id=7}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.756673Z  INFO server{id=8}: librtbit::listen: Listening on TCP 127.0.0.1:15108 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.775207Z  INFO server{id=18}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.775500Z  INFO server{id=18}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.775515Z  INFO server{id=18}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.775576Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.775669Z  WARN server{id=29}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.775760Z  INFO server{id=29}: librtbit::listen: Listening on UDP 127.0.0.1:15129 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.788578Z  INFO server{id=5}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.788762Z  WARN server{id=6}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.788847Z  INFO server{id=5}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.788861Z  INFO server{id=6}: librtbit::listen: Listening on UDP 127.0.0.1:15106 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.788868Z  INFO server{id=5}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.794438Z  INFO server{id=0}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.794715Z  INFO server{id=0}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.794737Z  INFO server{id=0}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.794813Z  WARN server{id=1}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.794918Z  INFO server{id=1}: librtbit::listen: Listening on UDP 127.0.0.1:15101 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.844948Z  INFO server{id=4}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.864324Z  INFO server{id=4}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.864361Z  INFO server{id=4}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.864478Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.864746Z  WARN server{id=30}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.864867Z  INFO server{id=30}: librtbit::listen: Listening on UDP 127.0.0.1:15130 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.886866Z  INFO server{id=9}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.937354Z  INFO server{id=9}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.937394Z  INFO server{id=9}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.937498Z  WARN server{id=10}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:30.937596Z  INFO server{id=10}: librtbit::listen: Listening on UDP 127.0.0.1:15110 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.949422Z  INFO server{id=25}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.950710Z  INFO server{id=0}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.961322Z  INFO server{id=21}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.899221Z  INFO server{id=8}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.967192Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.969149Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.913833Z  INFO server{id=14}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.976537Z  INFO server{id=14}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.976562Z  INFO server{id=14}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.976628Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.977109Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.977322Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.981545Z  INFO server{id=25}: librtbit::listen: Listening on TCP 127.0.0.1:15125 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.983137Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.909881Z  INFO server{id=24}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.920397Z  INFO server{id=8}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.987758Z  INFO server{id=8}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:30.987782Z  INFO server{id=8}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.987832Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.988205Z  INFO server{id=19}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.988476Z  INFO server{id=19}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.988497Z  INFO server{id=19}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.988549Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.989123Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.989371Z  INFO server{id=24}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:30.995692Z  INFO server{id=24}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.995837Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.000179Z  INFO server{id=0}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.000221Z  INFO server{id=0}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.923793Z  INFO server{id=11}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.001645Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.010274Z  INFO server{id=11}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.010397Z  INFO server{id=11}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.923776Z  INFO server{id=13}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.010734Z  INFO server{id=13}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.013461Z  INFO server{id=13}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.016056Z  INFO server{id=14}: librtbit::listen: Listening on TCP 127.0.0.1:15114 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.018240Z  WARN server{id=12}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:31.018488Z  INFO server{id=12}: librtbit::listen: Listening on UDP 127.0.0.1:15112 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:31.020201Z  INFO server{id=21}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.020226Z  INFO server{id=21}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.020512Z  INFO server{id=27}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.020986Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.022012Z  INFO server{id=27}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.023072Z  INFO server{id=27}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.991309Z  INFO server{id=2}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:30.992141Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.023319Z  INFO server{id=2}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.023332Z  INFO server{id=2}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.023373Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.023432Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.025187Z  INFO server{id=26}: librtbit::listen: Listening on TCP 127.0.0.1:15126 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:30.992547Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.992852Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.030175Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.992414Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.970213Z  INFO server{id=8}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.061101Z  INFO server{id=8}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.969481Z  INFO server{id=25}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.061366Z  INFO server{id=25}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:30.969351Z  INFO server{id=24}: librtbit::listen: Listening on TCP 127.0.0.1:15124 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.011557Z  INFO server{id=22}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.061955Z  INFO server{id=27}: librtbit::listen: Listening on TCP 127.0.0.1:15127 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.063646Z  INFO server{id=22}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.063756Z  INFO server{id=22}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.063978Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.034124Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:30.970103Z  WARN server{id=31}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:31.065252Z  INFO server{id=31}: librtbit::listen: Listening on UDP 127.0.0.1:15131 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:30.988016Z  INFO server{id=26}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.070363Z  INFO server{id=26}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.070944Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.031104Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.076129Z  INFO server{id=26}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.032431Z  WARN server{id=2}: librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:31.077120Z  INFO server{id=2}: librtbit::listen: Listening on UDP 127.0.0.1:15102 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:31.093252Z  INFO server{id=9}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.095454Z  INFO server{id=15}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.031293Z  INFO server{id=6}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.100404Z  INFO server{id=16}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.101475Z  INFO server{id=16}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.101501Z  INFO server{id=16}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.101534Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.143590Z  INFO server{id=11}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.216597Z  INFO server{id=6}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.216861Z  INFO server{id=6}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.216876Z  INFO server{id=6}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.216925Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.221362Z  INFO server{id=18}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.228298Z  INFO server{id=25}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.306397Z  INFO server{id=25}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.306440Z  INFO server{id=25}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.306487Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.310252Z  INFO server{id=29}: librtbit::listen: Listening on TCP 127.0.0.1:15129 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.317853Z  INFO server{id=11}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.317895Z  INFO server{id=11}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.317987Z  INFO server{id=12}: librtbit::listen: Listening on TCP 127.0.0.1:15112 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.323662Z  INFO server{id=20}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.323928Z  INFO server{id=20}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.323944Z  INFO server{id=20}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.323987Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.233642Z  INFO server{id=28}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.333047Z  INFO server{id=28}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.333133Z  INFO server{id=28}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.333207Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.333333Z  INFO server{id=30}: librtbit::listen: Listening on TCP 127.0.0.1:15130 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.337282Z  INFO server{id=1}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.337613Z  INFO server{id=1}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.337628Z  INFO server{id=1}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.337676Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.351316Z  INFO server{id=18}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.351352Z  INFO server{id=18}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.351375Z  INFO server{id=31}: librtbit::listen: Listening on TCP 127.0.0.1:15131 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.369518Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.374934Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.237779Z  INFO server{id=29}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.242516Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.392092Z  INFO librtbit::tests::cancel_init: test_session_shutdown_cancels_torrent_tokens passed
[INFO] [stdout] 2026-10-18T18:07:31.397010Z  INFO server{id=27}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.397785Z  INFO server{id=27}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.398063Z  INFO server{id=27}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.258504Z  INFO server{id=17}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.398984Z  INFO server{id=17}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.399340Z  INFO server{id=17}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.399698Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.283241Z  INFO server{id=9}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.400367Z  INFO server{id=9}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.400845Z  INFO server{id=10}: librtbit::listen: Listening on TCP 127.0.0.1:15110 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.401582Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.406091Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.415140Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.416152Z  INFO server{id=2}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.421354Z  INFO server{id=10}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.422342Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.243464Z  INFO server{id=21}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.290256Z  INFO server{id=15}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.435294Z  INFO server{id=15}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.435336Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.297162Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.437254Z  INFO server{id=20}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:31.297256Z  INFO server{id=6}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.439127Z  INFO server{id=6}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.439294Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.442081Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.285753Z  INFO server{id=19}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.446437Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.449299Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.450167Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.376875Z  INFO server{id=29}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.450551Z  INFO server{id=29}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.450592Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.376987Z  INFO server{id=3}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:31.452289Z  INFO server{id=21}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.452349Z  INFO server{id=21}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.452392Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.398169Z  INFO server{id=25}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:31.458109Z  INFO server{id=16}: librtbit::listen: Listening on TCP 127.0.0.1:15116 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.458456Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.458511Z  INFO server{id=2}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.458666Z  INFO server{id=2}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.397248Z  INFO server{id=31}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.463436Z  INFO server{id=31}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.463476Z  INFO server{id=31}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.463498Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.464064Z  INFO server{id=10}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.464087Z  INFO server{id=10}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.473221Z  INFO server{id=19}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.473261Z  INFO server{id=19}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.291823Z  INFO server{id=4}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.476329Z  INFO server{id=4}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.476350Z  INFO server{id=4}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.476371Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.478124Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] test tests::cancel_init::test_session_shutdown_cancels_torrent_tokens ... ok
[INFO] [stdout] 2026-10-18T18:07:31.252366Z  INFO server{id=28}: librtbit::listen: Listening on TCP 127.0.0.1:15128 for incoming peer connections
[INFO] [stdout] 2026-10-18T18:07:31.271580Z  INFO server{id=23}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.499411Z  INFO server{id=23}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.500135Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.503061Z  INFO server{id=23}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.401889Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.637384Z  INFO server{id=12}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.637651Z  INFO server{id=12}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.637664Z  INFO server{id=12}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.637709Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.645047Z  INFO server{id=14}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.645315Z  INFO server{id=14}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.645338Z  INFO server{id=14}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.645358Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.649203Z  INFO server{id=31}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.654213Z  INFO server{id=31}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.654261Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.657472Z  INFO server{id=30}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.658051Z  INFO server{id=31}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.664285Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.677284Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.680089Z  INFO server{id=30}: librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:31.680139Z  INFO server{id=30}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.717376Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.718198Z  INFO server{id=10}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.718471Z  INFO server{id=10}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.718486Z  INFO server{id=10}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.718515Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.735811Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.758762Z  INFO server{id=22}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:31.769239Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.774249Z  INFO server{id=24}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.774552Z  INFO server{id=24}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.774571Z  INFO server{id=24}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.774607Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.777197Z  INFO server{id=18}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:31.782817Z  INFO server{id=13}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:31.788241Z  INFO server{id=29}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.788578Z  INFO server{id=29}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.788601Z  INFO server{id=29}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.788619Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.804132Z  INFO server{id=26}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.804393Z  INFO server{id=26}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.804408Z  INFO server{id=26}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.804430Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.806145Z  INFO server{id=7}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:31.806442Z  INFO server{id=30}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:31.806738Z  INFO server{id=30}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:31.806754Z  INFO server{id=30}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:31.806776Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:31.974384Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:31.999130Z  INFO server{id=8}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.005039Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.008805Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.009086Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.027991Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.033323Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.011859Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.038088Z  INFO server{id=12}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:32.038347Z  INFO server{id=12}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:32.038363Z  INFO server{id=12}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:32.038393Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:32.041386Z  INFO server{id=1}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.041430Z  INFO server{id=12}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.055466Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.058802Z  INFO server{id=31}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.070156Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.076435Z  INFO server{id=26}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.076943Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.088083Z  INFO server{id=28}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:32.088368Z  INFO server{id=28}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:32.088388Z  INFO server{id=28}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:32.088426Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:32.094797Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.097217Z  INFO server{id=24}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.099674Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.100944Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.102212Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.104407Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.104682Z  INFO server{id=16}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.107769Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.110058Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.111075Z  INFO server{id=17}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.111841Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.113056Z  INFO server{id=11}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.117548Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.117705Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.119456Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.126055Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.136981Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.137351Z  INFO server{id=27}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.137529Z  INFO server{id=9}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.137568Z  INFO server{id=23}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.137623Z  INFO server{id=25}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.138097Z  INFO server{id=20}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.138166Z  INFO server{id=3}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.139064Z  INFO server{id=16}: librtbit::tests::e2e: started session
[INFO] [stdout] 2026-10-18T18:07:32.150672Z  INFO server{id=16}: librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:32.150721Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:32.153070Z  INFO server{id=29}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.153112Z  INFO server{id=9}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.153121Z  INFO server{id=1}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.154217Z  INFO server{id=21}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.156050Z  INFO server{id=16}: librtbit::tests::e2e: added torrent
[INFO] [stdout] 2026-10-18T18:07:32.165088Z  INFO server{id=2}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.165132Z  INFO server{id=8}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.166090Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.172803Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.181081Z  INFO server{id=30}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.184496Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.194281Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.195453Z  INFO server{id=0}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.187945Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.202078Z  INFO server{id=0}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.214053Z  INFO server{id=22}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.226426Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.228095Z  INFO server{id=2}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.234977Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.254358Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.256596Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.261319Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.265898Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.267078Z  INFO server{id=31}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.270059Z  INFO server{id=14}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.275082Z  INFO server{id=19}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.289979Z  INFO server{id=5}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.318053Z  INFO server{id=6}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.321444Z  INFO server{id=21}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.334643Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.341074Z  INFO server{id=6}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.349865Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.361099Z  INFO server{id=18}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.364339Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.366973Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.384761Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.433692Z  INFO server{id=28}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.437089Z  INFO server{id=15}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.440201Z  INFO server{id=12}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.443441Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.388518Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.393332Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.393883Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.405088Z  INFO server{id=17}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.447998Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.419082Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.420314Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.433455Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.450652Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.452475Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.457061Z  INFO server{id=16}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.466085Z  INFO server{id=10}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.469485Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.475452Z  INFO server{id=7}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.477518Z  INFO server{id=14}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.480064Z  INFO server{id=4}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.481231Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.510893Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.511212Z  INFO server{id=15}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.485067Z  INFO server{id=23}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.496095Z  INFO server{id=5}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.511316Z  INFO server{id=19}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.512625Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.482769Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.515084Z  INFO server{id=13}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.515266Z  INFO server{id=26}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.519342Z  INFO server{id=11}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.520437Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.523474Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.523902Z  INFO server{id=27}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.532329Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.565540Z  INFO server{id=4}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.565601Z  INFO librtbit::tests::e2e: started all servers, starting client
[INFO] [stdout] 2026-10-18T18:07:32.565801Z  WARN librqbit_utp::socket: couldn't set UDP rcv buf size to requested value. There might be packet loss, try increasing rmem_max or equivalent. prev=212992 current=8388608 expected=167772160
[INFO] [stdout] 2026-10-18T18:07:32.565998Z  INFO librtbit::listen: Listening on UDP 127.0.0.1:15099 for incoming uTP peer connections
[INFO] [stdout] 2026-10-18T18:07:32.575489Z  INFO server{id=24}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.589740Z  INFO server{id=28}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.589803Z  INFO server{id=29}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.608175Z  INFO server{id=30}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.619590Z  INFO server{id=10}: librtbit::tests::e2e: torrent is live
[INFO] [stdout] 2026-10-18T18:07:32.619647Z  INFO librtbit::tests::e2e: started all servers, starting client
[INFO] [stdout] 2026-10-18T18:07:32.638574Z  INFO librtbit::session: will use JSON database: "/tmp/rtbit_e2e_client40vqCK/session" for session persistence
[INFO] [stdout] 2026-10-18T18:07:32.638611Z  INFO librtbit::tests::e2e: started client session
[INFO] [stdout] 2026-10-18T18:07:32.648461Z  INFO librtbit::session: will use JSON database: "/tmp/rtbit_e2e_client92W72s/session" for session persistence
[INFO] [stdout] 2026-10-18T18:07:32.648559Z  INFO librtbit::tests::e2e: started client session
[INFO] [stdout] 2026-10-18T18:07:32.700956Z  INFO librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:32.701066Z  INFO librtbit::tests::e2e: added handle
[INFO] [stdout] 2026-10-18T18:07:32.701754Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:32.705376Z  INFO librtbit::torrent_state::initializing: Initial check results: have 0, needed 61.0Mi, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.780215Z  INFO librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:32.780242Z  INFO librtbit::tests::e2e: added handle
[INFO] [stdout] 2026-10-18T18:07:32.780792Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:32.783273Z  INFO librtbit::torrent_state::initializing: Initial check results: have 0, needed 61.0Mi, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:32.805841Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="0.15%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:32.881103Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="1.89%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:32.902035Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:32.982106Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="5.12%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.002004Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.101279Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="10.91%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.102440Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.180792Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.201799Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.280969Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.302091Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.383099Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.403354Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.481100Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.504102Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.581446Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.602726Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.684102Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.703103Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.782102Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.802106Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.884100Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.902441Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:33.981042Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.002048Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.087108Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.101486Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.182097Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.201553Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.280830Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.301969Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.381133Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.402192Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.480927Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.502334Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.580652Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.602555Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.681741Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.704197Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.781095Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.803200Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.880682Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.901812Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:34.980801Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.002264Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.080795Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.105134Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.180512Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.201750Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.281152Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.301649Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] test tests::mock_tracker::tests::live_tracker_worker_observes_announce_port_update ... ok
[INFO] [stdout] 2026-10-18T18:07:35.380676Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.401405Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.480762Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.502101Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.580469Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.601860Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.681048Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.702101Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.781042Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.804319Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.881107Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.908105Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:35.980437Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.004105Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.083103Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.103127Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.181174Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.202460Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.280598Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.302118Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.381344Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.402118Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.481161Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.501751Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.580812Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.603096Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.681125Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.702108Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.781320Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.801774Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.881224Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.901916Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:36.980439Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.001887Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.081227Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.101957Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.182100Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.202260Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.285102Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.305127Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.383101Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.404118Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.483214Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.502403Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.581098Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.602343Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.681247Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.702068Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.783712Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.83%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.801517Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="13.57%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 0 }"
[INFO] [stdout] 2026-10-18T18:07:37.888663Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="11.98%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 198 }"
[INFO] [stdout] 2026-10-18T18:07:37.901524Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="19.56%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 376 }"
[INFO] [stdout] 2026-10-18T18:07:37.980970Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="17.72%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 375 }"
[INFO] [stdout] 2026-10-18T18:07:38.001514Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="32.36%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 625 }"
[INFO] [stdout] 2026-10-18T18:07:38.080984Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="26.78%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 551 }"
[INFO] [stdout] 2026-10-18T18:07:38.104415Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="49.77%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 968 }"
[INFO] [stdout] 2026-10-18T18:07:38.184109Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="39.99%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 811 }"
[INFO] [stdout] 2026-10-18T18:07:38.202115Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="64.72%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1260 }"
[INFO] [stdout] 2026-10-18T18:07:38.280672Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="49.87%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1003 }"
[INFO] [stdout] 2026-10-18T18:07:38.301883Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="78.04%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1519 }"
[INFO] [stdout] 2026-10-18T18:07:38.380647Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="54.23%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1089 }"
[INFO] [stdout] 2026-10-18T18:07:38.401431Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="85.92%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 32, live_utp: 0, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1674 }"
[INFO] [stdout] 2026-10-18T18:07:38.482715Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="54.43%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1093 }"
[INFO] [stdout] 2026-10-18T18:07:38.492788Z  INFO librtbit::torrent_state::live: torrent finished downloading id=0 info_hash=ed8be3b9ea2145b53ff3917ac9a92fac2abc7777
[INFO] [stdout] 2026-10-18T18:07:38.494821Z  INFO librtbit::tests::e2e: handle is completed
[INFO] [stdout] 2026-10-18T18:07:38.580336Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="60.58%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1212 }"
[INFO] [stdout] 2026-10-18T18:07:38.582700Z  INFO librtbit::session: deleted torrent id=0
[INFO] [stdout] 2026-10-18T18:07:38.582715Z  INFO librtbit::tests::e2e: deleted handle
[INFO] [stdout] 2026-10-18T18:07:38.587705Z  INFO librtbit::session: added torrent name="rtbit_e2eVqmRi0"
[INFO] [stdout] 2026-10-18T18:07:38.588223Z  INFO librtbit::tests::e2e: re-added handle
[INFO] [stdout] 2026-10-18T18:07:38.588015Z  INFO librtbit::torrent_state::initializing: Doing initial checksum validation, this might take a while...
[INFO] [stdout] 2026-10-18T18:07:38.680622Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="75.53%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1503 }"
[INFO] [stdout] 2026-10-18T18:07:38.781527Z  INFO stats_printer: librtbit::tests::e2e: progress_percent="92.17%" peers="AggregatePeerStats { queued: 0, connecting: 0, live: 32, live_tcp: 0, live_utp: 32, live_socks: 0, seen: 32, dead: 0, not_needed: 0, steals: 1723 }"
[INFO] [stdout] 2026-10-18T18:07:38.828251Z  INFO librtbit::torrent_state::live: torrent finished downloading id=0 info_hash=d7ed1257211ecde168f3d5b804958f18fe6a36b9
[INFO] [stdout] 2026-10-18T18:07:38.828641Z  INFO librtbit::tests::e2e: handle is completed
[INFO] [stdout] 2026-10-18T18:07:38.831254Z  INFO librtbit::session: deleted torrent id=0
[INFO] [stdout] 2026-10-18T18:07:38.831274Z  INFO librtbit::tests::e2e: deleted handle
[INFO] [stdout] 2026-10-18T18:07:38.833147Z  INFO librtbit::session: added torrent name="rtbit_e2eiMuMbX"
[INFO] [stdout] 2026-10-18T18:07:38.833168Z  INFO librtbit::tests::e2e: re-added handle
[INFO] [stdout] 2026-10-18T18:07:38.843351Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=1
[INFO] [stdout] 2026-10-18T18:07:38.860446Z  INFO librtbit::torrent_state::initializing: Initial check results: have 61.0Mi, needed 0, total selected 61.0Mi torrent=0
[INFO] [stdout] 2026-10-18T18:07:38.919206Z  INFO librtbit::session: deleted torrent id=0
[INFO] [stdout] 2026-10-18T18:07:38.928122Z  INFO librtbit::tests::e2e: all good
[INFO] [stdout] 2026-10-18T18:07:38.950773Z  INFO librtbit::session: deleted torrent id=1
[INFO] [stdout] 2026-10-18T18:07:38.950855Z  INFO librtbit::tests::e2e: all good
[INFO] [stdout] 2026-10-18T18:07:38.952327Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.956276Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.957987Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.958961Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.959896Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.960881Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.961968Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.963124Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.965535Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.966723Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.969049Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.979909Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.982155Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.983076Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.984154Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.985340Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.986475Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.993001Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] 2026-10-18T18:07:38.994169Z  WARN librtbit::session::network: error accepting: error accepting uTP: dispatcher dead
[INFO] [stdout] test tests::e2e::test_e2e_download_tcp ... ok
[INFO] [stdout] test tests::e2e::test_e2e_download_utp ... ok
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout] 
[INFO] [stdout] ---- ip_ranges::tests::test_list_from_plaintext_file stdout ----
[INFO] [stdout] Error: Read-only file system (os error 30)
[INFO] [stdout] 
[INFO] [stdout] Stack backtrace:
[INFO] [stdout]    0: <anyhow::Error as core::convert::From<core::io::error::Error>>::from
[INFO] [stdout]    1: librtbit::ip_ranges::tests::test_list_from_plaintext_file::{closure#0}
[INFO] [stdout]    2: <tokio::runtime::scheduler::current_thread::Context>::enter::<core::task::poll::Poll<core::result::Result<(), anyhow::Error>>, <tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = core::result::Result<(), anyhow::Error>>>>>::{closure#0}::{closure#0}>
[INFO] [stdout]    3: <tokio::runtime::context::scoped::Scoped<tokio::runtime::scheduler::Context>>::set::<<tokio::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = core::result::Result<(), anyhow::Error>>>>>::{closure#0}, core::option::Option<core::result::Result<(), anyhow::Error>>>::{closure#0}, (alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core>, core::option::Option<core::result::Result<(), anyhow::Error>>)>
[INFO] [stdout]    4: <tokio::runtime::scheduler::current_thread::CoreGuard>::block_on::<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = core::result::Result<(), anyhow::Error>>>>>
[INFO] [stdout]    5: tokio::runtime::context::runtime::enter_runtime::<<tokio::runtime::scheduler::current_thread::CurrentThread>::block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output = core::result::Result<(), anyhow::Error>>>>::{closure#0}, core::result::Result<(), anyhow::Error>>
[INFO] [stdout]    6: <tokio::runtime::runtime::Runtime>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = core::result::Result<(), anyhow::Error>>>>
[INFO] [stdout]    7: librtbit::ip_ranges::tests::test_list_from_plaintext_file
[INFO] [stdout]    8: <librtbit::ip_ranges::tests::test_list_from_plaintext_file::{closure#0} as core::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]    9: test::__rust_begin_short_backtrace::<core::result::Result<(), alloc::string::String>, fn() -> core::result::Result<(), alloc::string::String>>
[INFO] [stdout]   10: test::run_test::{closure#0}
[INFO] [stdout]   11: std::sys::backtrace::__rust_begin_short_backtrace::<test::run_test::{closure#1}, ()>
[INFO] [stdout]   12: <std::thread::lifecycle::spawn_unchecked<test::run_test::{closure#1}, ()>::{closure#1} as core::ops::function::FnOnce<()>>::call_once::{shim:vtable#0}
[INFO] [stdout]   13: <std::sys::thread::unix::Thread>::new::thread_start
[INFO] [stdout]   14: <unknown>
[INFO] [stdout]   15: clone
[INFO] [stdout] 
[INFO] [stdout] ---- session::tests::test_magnet_resolution_timeout stdout ----
[INFO] [stdout] 
[INFO] [stdout] thread 'session::tests::test_magnet_resolution_timeout' (4902) panicked at src/session/mod.rs:1471:9:
[INFO] [stdout] error message should mention timeout, got: input address stream exhausted, no way to discover torrent metainfo
[INFO] [stdout] stack backtrace:
[INFO] [stdout]    0:     0x5c5459dbffa1 - <<std[70759c8f55707aa4]::sys::backtrace::BacktraceLock>::print::DisplayBacktrace as core[df12db4294e9bfd3]::fmt::Display>::fmt
[INFO] [stdout]    1:     0x5c5459dd912a - core[df12db4294e9bfd3]::fmt::write
[INFO] [stdout]    2:     0x5c5459dc597c - <alloc[2182bb758b4b3781]::vec::Vec<u8> as core[df12db4294e9bfd3]::io::write::Write>::write_fmt
[INFO] [stdout]    3:     0x5c5459d95d36 - std[70759c8f55707aa4]::panicking::default_hook::{closure#0}
[INFO] [stdout]    4:     0x5c5459db5219 - std[70759c8f55707aa4]::panicking::default_hook
[INFO] [stdout]    5:     0x5c5459a441e0 - test[9d35eded1c95d3be]::test_main_inner::<test[9d35eded1c95d3be]::test_main_static::{closure#0}>::{closure#0}
[INFO] [stdout]    6:     0x5c5459db5542 - std[70759c8f55707aa4]::panicking::panic_with_hook
[INFO] [stdout]    7:     0x5c5459d95de2 - std[70759c8f55707aa4]::panicking::panic_handler::{closure#0}
[INFO] [stdout]    8:     0x5c5459d8df59 - std[70759c8f55707aa4]::sys::backtrace::__rust_end_short_backtrace::<std[70759c8f55707aa4]::panicking::panic_handler::{closure#0}, !>
[INFO] [stdout]    9:     0x5c5459d96f5d - __rustc[8fa7c3cbc660c2b3]::rust_begin_unwind
[INFO] [stdout]   10:     0x5c5459dd990c - core[df12db4294e9bfd3]::panicking::panic_fmt
[INFO] [stdout]   11:     0x5c545987e769 - librtbit[4d1dfcd599f24283]::session::tests::test_magnet_resolution_timeout::{closure#0}
[INFO] [stdout]   12:     0x5c545989c6ed - tokio[14a6022bb245f368]::runtime::context::runtime::enter_runtime::<<tokio[14a6022bb245f368]::runtime::scheduler::multi_thread::MultiThread>::block_on<core[df12db4294e9bfd3]::pin::Pin<&mut dyn core[df12db4294e9bfd3]::future::future::Future<Output = ()>>>::{closure#0}, ()>
[INFO] [stdout]   13:     0x5c54598e0a9a - <tokio[14a6022bb245f368]::runtime::runtime::Runtime>::block_on::<core[df12db4294e9bfd3]::pin::Pin<&mut dyn core[df12db4294e9bfd3]::future::future::Future<Output = ()>>>
[INFO] [stdout]   14:     0x5c545988324b - librtbit[4d1dfcd599f24283]::session::tests::test_magnet_resolution_timeout
[INFO] [stdout]   15:     0x5c5459a0ceb9 - <librtbit[4d1dfcd599f24283]::session::tests::test_magnet_resolution_timeout::{closure#0} as core[df12db4294e9bfd3]::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]   16:     0x5c5459a374cb - test[9d35eded1c95d3be]::__rust_begin_short_backtrace::<core[df12db4294e9bfd3]::result::Result<(), alloc[2182bb758b4b3781]::string::String>, fn() -> core[df12db4294e9bfd3]::result::Result<(), alloc[2182bb758b4b3781]::string::String>>
[INFO] [stdout]   17:     0x5c5459a44b35 - test[9d35eded1c95d3be]::run_test::{closure#0}
[INFO] [stdout]   18:     0x5c5459a3e3f4 - std[70759c8f55707aa4]::sys::backtrace::__rust_begin_short_backtrace::<test[9d35eded1c95d3be]::run_test::{closure#1}, ()>
[INFO] [stdout]   19:     0x5c5459a47c92 - <std[70759c8f55707aa4]::thread::lifecycle::spawn_unchecked<test[9d35eded1c95d3be]::run_test::{closure#1}, ()>::{closure#1} as core[df12db4294e9bfd3]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0}
[INFO] [stdout]   20:     0x5c5459dbe859 - <std[70759c8f55707aa4]::sys::thread::unix::Thread>::new::thread_start
[INFO] [stdout]   21:     0x7366787d5dfa - <unknown>
[INFO] [stdout]   22:     0x7366788693d4 - clone
[INFO] [stdout]   23:                0x0 - <unknown>
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout]     ip_ranges::tests::test_list_from_plaintext_file
[INFO] [stdout]     session::tests::test_magnet_resolution_timeout
[INFO] [stdout] 
[INFO] [stdout] test result: FAILED. 112 passed; 2 failed; 5 ignored; 0 measured; 0 filtered out; finished in 8.96s
[INFO] [stdout] 
[INFO] [stderr] error: test failed, to rerun pass `--lib`
[INFO] running `Command { std: "docker" "inspect" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d", kill_on_drop: false }`
[INFO] [stdout] a68943f8bde1cb9cbc203ee53a2101639a82b1a76bf9e503e7af1117c0308b6d
