[INFO] fetching crate libjuice-rs 0.1.0... [INFO] testing libjuice-rs-0.1.0 against 1.60.0 for beta-1.61-1 [INFO] extracting crate libjuice-rs 0.1.0 into /workspace/builds/worker-5/source [INFO] validating manifest of crates.io crate libjuice-rs 0.1.0 on toolchain 1.60.0 [INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1.60.0" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }` [INFO] started tweaking crates.io crate libjuice-rs 0.1.0 [INFO] finished tweaking crates.io crate libjuice-rs 0.1.0 [INFO] tweaked toml for crates.io crate libjuice-rs 0.1.0 written to /workspace/builds/worker-5/source/Cargo.toml [INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1.60.0" "generate-lockfile" "--manifest-path" "Cargo.toml" "-Zno-index-update", kill_on_drop: false }` [INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1.60.0" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Downloading crates ... [INFO] [stderr] Downloaded libjuice-sys v0.9.7 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1.60.0" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 521d02bf5f0aabb84ae1162daec6c54d0c45da62b17abe4cdbca0ea5ea7a89c4 [INFO] running `Command { std: "docker" "start" "-a" "521d02bf5f0aabb84ae1162daec6c54d0c45da62b17abe4cdbca0ea5ea7a89c4", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "521d02bf5f0aabb84ae1162daec6c54d0c45da62b17abe4cdbca0ea5ea7a89c4", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "521d02bf5f0aabb84ae1162daec6c54d0c45da62b17abe4cdbca0ea5ea7a89c4", kill_on_drop: false }` [INFO] [stdout] 521d02bf5f0aabb84ae1162daec6c54d0c45da62b17abe4cdbca0ea5ea7a89c4 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1.60.0" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] b341dabc23a5edb1d73ceb8e52d12fbc1114037aff62c12fb121de65b346e0c7 [INFO] running `Command { std: "docker" "start" "-a" "b341dabc23a5edb1d73ceb8e52d12fbc1114037aff62c12fb121de65b346e0c7", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Compiling cmake v0.1.48 [INFO] [stderr] Compiling libjuice-sys v0.9.7 [INFO] [stderr] Compiling libjuice-rs v0.1.0 (/opt/rustwide/workdir) [INFO] [stderr] Finished dev [unoptimized + debuginfo] target(s) in 5.89s [INFO] running `Command { std: "docker" "inspect" "b341dabc23a5edb1d73ceb8e52d12fbc1114037aff62c12fb121de65b346e0c7", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "b341dabc23a5edb1d73ceb8e52d12fbc1114037aff62c12fb121de65b346e0c7", kill_on_drop: false }` [INFO] [stdout] b341dabc23a5edb1d73ceb8e52d12fbc1114037aff62c12fb121de65b346e0c7 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1.60.0" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 01d69eba33a557c0d68fcc7248904dffa0a4cb64fa4e0c27c50038d77f9caa51 [INFO] running `Command { std: "docker" "start" "-a" "01d69eba33a557c0d68fcc7248904dffa0a4cb64fa4e0c27c50038d77f9caa51", kill_on_drop: false }` [INFO] [stderr] Compiling libc v0.2.123 [INFO] [stderr] Compiling regex-syntax v0.6.25 [INFO] [stderr] Compiling libjuice-rs v0.1.0 (/opt/rustwide/workdir) [INFO] [stderr] Compiling regex v1.5.5 [INFO] [stderr] Compiling atty v0.2.14 [INFO] [stderr] Compiling env_logger v0.9.0 [INFO] [stderr] Finished test [unoptimized + debuginfo] target(s) in 5.89s [INFO] running `Command { std: "docker" "inspect" "01d69eba33a557c0d68fcc7248904dffa0a4cb64fa4e0c27c50038d77f9caa51", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "01d69eba33a557c0d68fcc7248904dffa0a4cb64fa4e0c27c50038d77f9caa51", kill_on_drop: false }` [INFO] [stdout] 01d69eba33a557c0d68fcc7248904dffa0a4cb64fa4e0c27c50038d77f9caa51 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:b0c94ce3c1162fcb8e57cac5b65ec2f72eabb1eebea4fcc35e269e823f681646" "/opt/rustwide/cargo-home/bin/cargo" "+1.60.0" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] b64765f5b9cfecd60a0c1c30555ce8bc19b7135df0e6e3b99b983d8f37a34e67 [INFO] running `Command { std: "docker" "start" "-a" "b64765f5b9cfecd60a0c1c30555ce8bc19b7135df0e6e3b99b983d8f37a34e67", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Finished test [unoptimized + debuginfo] target(s) in 0.09s [INFO] [stderr] Running unittests (/opt/rustwide/target/debug/deps/libjuice_rs-13935df5e5259e5c) [INFO] [stdout] [INFO] [stdout] running 3 tests [INFO] [stdout] test agent::tests::build ... ok [INFO] [stderr] [2022-04-13T18:04:23.492227Z INFO libjuice_rs::log] agent.c:780: Changing state to connecting [INFO] [stderr] [2022-04-13T18:04:23.492264Z DEBUG libjuice_rs::agent::tests] State changed to: Connecting [INFO] [stderr] [2022-04-13T18:04:23.492278Z DEBUG libjuice_rs::log] server.c:422: Leaving server thread [INFO] [stdout] test server::tests::build ... ok [INFO] [stderr] [2022-04-13T18:04:23.492874Z WARN libjuice_rs::log] addr.c:274: Address resolution failed for stun.l.google.com:19302 [INFO] [stderr] [2022-04-13T18:04:23.492906Z ERROR libjuice_rs::log] agent.c:615: STUN server address resolution failed [INFO] [stderr] [2022-04-13T18:04:23.492915Z INFO libjuice_rs::log] agent.c:2321: Candidate gathering done [INFO] [stderr] [2022-04-13T18:04:23.492924Z DEBUG libjuice_rs::agent::tests] Gathering finished [INFO] [stderr] [2022-04-13T18:04:23.493039Z DEBUG libjuice_rs::log] agent.c:662: Leaving agent thread [INFO] [stderr] [2022-04-13T18:04:23.493063Z INFO libjuice_rs::log] agent.c:780: Changing state to disconnected [INFO] [stderr] [2022-04-13T18:04:23.493072Z DEBUG libjuice_rs::agent::tests] State changed to: Disconnected [INFO] [stdout] test agent::tests::gather ... ok [INFO] [stdout] [INFO] [stdout] test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s [INFO] [stdout] [INFO] [stderr] Running tests/connectivity.rs (/opt/rustwide/target/debug/deps/connectivity-24fe20b77b95abf0) [INFO] [stdout] [INFO] [stdout] running 2 tests [INFO] [stderr] [2022-04-13T18:04:23.495565Z INFO libjuice_rs::log] agent.c:780: Changing state to connecting [INFO] [stderr] [2022-04-13T18:04:23.495633Z INFO connectivity] first changed state to: Connecting [INFO] [stderr] [2022-04-13T18:04:23.495899Z INFO libjuice_rs::log] agent.c:780: Changing state to connecting [INFO] [stderr] [2022-04-13T18:04:23.496164Z INFO connectivity] first changed state to: Connecting [INFO] [stderr] [2022-04-13T18:04:23.496231Z INFO libjuice_rs::log] agent.c:780: Changing state to connecting [INFO] [stderr] [2022-04-13T18:04:23.496274Z INFO connectivity] second changed state to: Connecting [INFO] [stderr] [2022-04-13T18:04:23.496282Z WARN libjuice_rs::log] addr.c:274: Address resolution failed for stun.l.google.com:19302 [INFO] [stderr] [2022-04-13T18:04:23.496315Z ERROR libjuice_rs::log] agent.c:615: STUN server address resolution failed [INFO] [stderr] [2022-04-13T18:04:23.496338Z INFO libjuice_rs::log] agent.c:2321: Candidate gathering done [INFO] [stderr] [2022-04-13T18:04:23.496362Z INFO connectivity] first agent finished gathering [INFO] [stderr] [2022-04-13T18:04:23.496397Z WARN libjuice_rs::log] addr.c:274: Address resolution failed for stun.l.google.com:19302 [INFO] [stderr] [2022-04-13T18:04:23.496427Z ERROR libjuice_rs::log] agent.c:615: STUN server address resolution failed [INFO] [stderr] [2022-04-13T18:04:23.496446Z INFO libjuice_rs::log] agent.c:2321: Candidate gathering done [INFO] [stderr] [2022-04-13T18:04:23.496466Z INFO connectivity] first agent finished gathering [INFO] [stderr] [2022-04-13T18:04:23.496505Z INFO libjuice_rs::log] agent.c:780: Changing state to connecting [INFO] [stderr] [2022-04-13T18:04:23.496578Z INFO connectivity] second changed state to: Connecting [INFO] [stderr] [2022-04-13T18:04:23.496587Z WARN libjuice_rs::log] addr.c:274: Address resolution failed for stun.l.google.com:19302 [INFO] [stderr] [2022-04-13T18:04:23.496612Z ERROR libjuice_rs::log] agent.c:615: STUN server address resolution failed [INFO] [stderr] [2022-04-13T18:04:23.496634Z INFO libjuice_rs::log] agent.c:2321: Candidate gathering done [INFO] [stderr] [2022-04-13T18:04:23.496657Z INFO connectivity] second agent finished gathering [INFO] [stderr] [2022-04-13T18:04:23.496666Z WARN libjuice_rs::log] addr.c:274: Address resolution failed for stun.l.google.com:19302 [INFO] [stderr] [2022-04-13T18:04:23.496683Z ERROR libjuice_rs::log] agent.c:615: STUN server address resolution failed [INFO] [stderr] [2022-04-13T18:04:23.496700Z INFO libjuice_rs::log] agent.c:2321: Candidate gathering done [INFO] [stderr] [2022-04-13T18:04:23.496709Z INFO connectivity] second agent finished gathering [INFO] [stderr] [2022-04-13T18:04:23.496745Z DEBUG libjuice_rs::log] agent.c:806: STUN entry 0: Sending request to 127.0.0.1:42609 (5 retransmissions left) [INFO] [stderr] [2022-04-13T18:04:23.496764Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.496880Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:56608 [INFO] [stderr] [2022-04-13T18:04:23.496931Z DEBUG libjuice_rs::log] agent.c:2151: Obtained a new remote reflexive candidate, priority=1853882367 [INFO] [stderr] [2022-04-13T18:04:23.496949Z DEBUG libjuice_rs::log] agent.c:2410: STUN entry 0 pair matching incoming address [INFO] [stderr] [2022-04-13T18:04:23.496963Z DEBUG libjuice_rs::log] agent.c:1248: Received STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.496973Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding response [INFO] [stderr] [2022-04-13T18:04:23.497025Z DEBUG libjuice_rs::log] agent.c:806: STUN entry 0: Sending request to 127.0.0.1:56608 (5 retransmissions left) [INFO] [stderr] [2022-04-13T18:04:23.497054Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.497086Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:42609 [INFO] [stderr] [2022-04-13T18:04:23.497129Z DEBUG libjuice_rs::log] agent.c:2151: Obtained a new remote reflexive candidate, priority=0 [INFO] [stderr] [2022-04-13T18:04:23.497146Z DEBUG libjuice_rs::log] agent.c:1329: Received STUN Binding success response from peer [INFO] [stderr] [2022-04-13T18:04:23.497159Z DEBUG libjuice_rs::log] agent.c:2115: Gathered reflexive candidate: a=candidate:1 1 UDP 1853882367 127.0.0.1 56608 typ prflx [INFO] [stderr] [2022-04-13T18:04:23.497175Z DEBUG libjuice_rs::log] agent.c:1381: Candidate pair check succeeded [INFO] [stderr] [2022-04-13T18:04:23.497185Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:42609 [INFO] [stderr] [2022-04-13T18:04:23.497217Z DEBUG libjuice_rs::log] agent.c:2410: STUN entry 0 pair matching incoming address [INFO] [stderr] [2022-04-13T18:04:23.497231Z DEBUG libjuice_rs::log] agent.c:1248: Received STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.497238Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding response [INFO] [stderr] [2022-04-13T18:04:23.497283Z DEBUG libjuice_rs::log] agent.c:806: STUN entry 1: Sending request to 127.0.0.1:42609 (5 retransmissions left) [INFO] [stderr] [2022-04-13T18:04:23.497309Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.497337Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:56608 [INFO] [stderr] [2022-04-13T18:04:23.497375Z DEBUG libjuice_rs::log] agent.c:946: New selected pair [INFO] [stderr] [2022-04-13T18:04:23.497402Z INFO libjuice_rs::log] agent.c:780: Changing state to connected [INFO] [stderr] [2022-04-13T18:04:23.497425Z INFO connectivity] second changed state to: Connected [INFO] [stderr] [2022-04-13T18:04:23.497429Z DEBUG libjuice_rs::log] agent.c:1329: Received STUN Binding success response from peer [INFO] [stderr] [2022-04-13T18:04:23.497445Z DEBUG libjuice_rs::log] agent.c:2115: Gathered reflexive candidate: a=candidate:2 1 UDP 1853882111 127.0.0.1 42609 typ prflx [INFO] [stderr] [2022-04-13T18:04:23.497462Z DEBUG libjuice_rs::log] agent.c:1381: Candidate pair check succeeded [INFO] [stderr] [2022-04-13T18:04:23.497473Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:56608 [INFO] [stderr] [2022-04-13T18:04:23.497505Z DEBUG libjuice_rs::log] agent.c:2410: STUN entry 0 pair matching incoming address [INFO] [stderr] [2022-04-13T18:04:23.497519Z DEBUG libjuice_rs::log] agent.c:1248: Received STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.497527Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding response [INFO] [stderr] [2022-04-13T18:04:23.497564Z DEBUG libjuice_rs::log] agent.c:946: New selected pair [INFO] [stderr] [2022-04-13T18:04:23.497601Z INFO libjuice_rs::log] agent.c:780: Changing state to connected [INFO] [stderr] [2022-04-13T18:04:23.497624Z INFO connectivity] first changed state to: Connected [INFO] [stderr] [2022-04-13T18:04:23.497629Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:42609 [INFO] [stderr] [2022-04-13T18:04:23.497673Z DEBUG libjuice_rs::log] agent.c:1018: Requesting pair nomination (controlling) [INFO] [stderr] [2022-04-13T18:04:23.497703Z DEBUG libjuice_rs::log] agent.c:806: STUN entry 0: Sending request to 127.0.0.1:56608 (5 retransmissions left) [INFO] [stderr] [2022-04-13T18:04:23.497725Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.497752Z DEBUG libjuice_rs::log] agent.c:1329: Received STUN Binding success response from peer [INFO] [stderr] [2022-04-13T18:04:23.497777Z DEBUG libjuice_rs::log] agent.c:1381: Candidate pair check succeeded [INFO] [stderr] [2022-04-13T18:04:23.497788Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:42609 [INFO] [stderr] [2022-04-13T18:04:23.497820Z DEBUG libjuice_rs::log] agent.c:2410: STUN entry 0 pair matching incoming address [INFO] [stderr] [2022-04-13T18:04:23.497834Z DEBUG libjuice_rs::log] agent.c:1248: Received STUN Binding request [INFO] [stderr] [2022-04-13T18:04:23.497842Z DEBUG libjuice_rs::log] agent.c:1312: Got a nominated pair (controlled) [INFO] [stderr] [2022-04-13T18:04:23.497850Z DEBUG libjuice_rs::log] agent.c:1470: Sending STUN Binding response [INFO] [stderr] [2022-04-13T18:04:23.497890Z INFO libjuice_rs::log] agent.c:780: Changing state to completed [INFO] [stderr] [2022-04-13T18:04:23.497915Z INFO connectivity] second changed state to: Completed [INFO] [stderr] [2022-04-13T18:04:23.497921Z DEBUG libjuice_rs::log] agent.c:706: Received STUN datagram from 127.0.0.1:56608 [INFO] [stderr] [2022-04-13T18:04:23.497964Z DEBUG libjuice_rs::log] agent.c:1329: Received STUN Binding success response from peer [INFO] [stderr] [2022-04-13T18:04:23.497979Z DEBUG libjuice_rs::log] agent.c:1393: Got a nominated pair (controlling) [INFO] [stderr] [2022-04-13T18:04:23.497994Z INFO libjuice_rs::log] agent.c:780: Changing state to completed [INFO] [stderr] [2022-04-13T18:04:23.498008Z INFO connectivity] first changed state to: Completed [INFO] [stderr] [2022-04-13T18:04:25.497411Z DEBUG libjuice_rs::log] agent.c:725: Received non-STUN datagram from 127.0.0.1:42609 [INFO] [stderr] [2022-04-13T18:04:25.497489Z DEBUG libjuice_rs::log] agent.c:2377: STUN selected entry matching incoming address [INFO] [stderr] [2022-04-13T18:04:25.497501Z DEBUG libjuice_rs::log] agent.c:735: Received application datagram [INFO] [stderr] [2022-04-13T18:04:25.497524Z DEBUG connectivity] second received [104, 101, 108, 108, 111] [INFO] [stderr] [2022-04-13T18:04:25.497659Z DEBUG libjuice_rs::log] agent.c:725: Received non-STUN datagram from 127.0.0.1:56608 [INFO] [stderr] [2022-04-13T18:04:25.497680Z DEBUG libjuice_rs::log] agent.c:2377: STUN selected entry matching incoming address [INFO] [stderr] [2022-04-13T18:04:25.497690Z DEBUG libjuice_rs::log] agent.c:735: Received application datagram [INFO] [stderr] [2022-04-13T18:04:25.497701Z DEBUG connectivity] first received [119, 111, 114, 108, 100] [INFO] [stderr] [2022-04-13T18:04:25.497845Z DEBUG libjuice_rs::log] agent.c:662: Leaving agent thread [INFO] [stderr] [2022-04-13T18:04:25.497860Z INFO libjuice_rs::log] agent.c:780: Changing state to disconnected [INFO] [stderr] [2022-04-13T18:04:25.497874Z INFO connectivity] second changed state to: Disconnected [INFO] [stderr] [2022-04-13T18:04:25.503455Z DEBUG libjuice_rs::log] agent.c:662: Leaving agent thread [INFO] [stderr] [2022-04-13T18:04:25.503487Z INFO libjuice_rs::log] agent.c:780: Changing state to disconnected [INFO] [stderr] [2022-04-13T18:04:25.503501Z INFO connectivity] first changed state to: Disconnected [INFO] [stdout] test connectivity_trickle ... ok [INFO] [stdout] test connectivity_no_trickle ... FAILED [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] [INFO] [stdout] ---- connectivity_no_trickle stdout ---- [INFO] [stdout] [2022-04-13T18:04:23.495051Z DEBUG libjuice_rs::log] ice.c:152: Created local description: ufrag="l7bJ", pwd="kyVzV2vgdR7q3XJ6f3e5qX" [INFO] [stdout] [2022-04-13T18:04:23.495182Z DEBUG libjuice_rs::log] ice.c:152: Created local description: ufrag="41xi", pwd="Uix+8cRvAJbrJsrHvEMD6h" [INFO] [stdout] [2022-04-13T18:04:23.495302Z INFO libjuice_rs::log] agent.c:780: Changing state to gathering [INFO] [stdout] [2022-04-13T18:04:23.495329Z INFO connectivity] first changed state to: Gathering [INFO] [stdout] [2022-04-13T18:04:23.495423Z WARN libjuice_rs::log] agent.c:232: No local host candidates gathered [INFO] [stdout] [2022-04-13T18:04:23.495442Z DEBUG libjuice_rs::log] agent.c:273: Assuming controlling mode [INFO] [stdout] [2022-04-13T18:04:23.495663Z DEBUG libjuice_rs::log] udp.c:159: UDP socket bound to any:5004 [INFO] [stdout] [2022-04-13T18:04:23.495677Z INFO libjuice_rs::log] agent.c:780: Changing state to gathering [INFO] [stdout] [2022-04-13T18:04:23.495685Z INFO connectivity] second changed state to: Gathering [INFO] [stdout] [2022-04-13T18:04:23.495728Z WARN libjuice_rs::log] agent.c:232: No local host candidates gathered [INFO] [stdout] [2022-04-13T18:04:23.495736Z DEBUG libjuice_rs::log] agent.c:273: Assuming controlling mode [INFO] [stdout] [2022-04-13T18:04:23.496713Z DEBUG libjuice_rs::log] ice.c:128: Parsed remote description: ufrag="l7bJ", pwd="kyVzV2vgdR7q3XJ6f3e5qX", candidates=0 [INFO] [stdout] [2022-04-13T18:04:23.496726Z DEBUG libjuice_rs::log] agent.c:326: Unfreezing 0 existing candidate pairs [INFO] [stdout] [2022-04-13T18:04:23.496733Z DEBUG libjuice_rs::log] agent.c:330: Adding 0 candidates from remote description [INFO] [stdout] [2022-04-13T18:04:23.496792Z DEBUG libjuice_rs::log] ice.c:128: Parsed remote description: ufrag="41xi", pwd="Uix+8cRvAJbrJsrHvEMD6h", candidates=0 [INFO] [stdout] [2022-04-13T18:04:23.496804Z DEBUG libjuice_rs::log] agent.c:326: Unfreezing 0 existing candidate pairs [INFO] [stdout] [2022-04-13T18:04:23.496811Z DEBUG libjuice_rs::log] agent.c:330: Adding 0 candidates from remote description [INFO] [stdout] thread 'connectivity_no_trickle' panicked at 'assertion failed: `(left == right)` [INFO] [stdout] left: `Connecting`, [INFO] [stdout] right: `Completed`', tests/connectivity.rs:65:5 [INFO] [stdout] stack backtrace: [INFO] [stdout] 0: 0x563b5dd22a3d - std::backtrace_rs::backtrace::libunwind::trace::hee598835bc88d35b [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5 [INFO] [stdout] 1: 0x563b5dd22a3d - std::backtrace_rs::backtrace::trace_unsynchronized::h9cdc730ba5cf5d72 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 [INFO] [stdout] 2: 0x563b5dd22a3d - std::sys_common::backtrace::_print_fmt::h75aeaf7ed30e43fa [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5 [INFO] [stdout] 3: 0x563b5dd22a3d - ::fmt::h606862f787600875 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22 [INFO] [stdout] 4: 0x563b5dd4838c - core::fmt::write::he803f0f418caf762 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17 [INFO] [stdout] 5: 0x563b5dd1c4f8 - std::io::Write::write_fmt::hbe7c1a63616291e2 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15 [INFO] [stdout] 6: 0x563b5dd24fa7 - std::sys_common::backtrace::_print::h64d038cf8ac3e13e [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5 [INFO] [stdout] 7: 0x563b5dd24fa7 - std::sys_common::backtrace::print::h359300b4a7fccf65 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9 [INFO] [stdout] 8: 0x563b5dd24fa7 - std::panicking::default_hook::{{closure}}::hf51be35e2f510149 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22 [INFO] [stdout] 9: 0x563b5dd24cdc - std::panicking::default_hook::h03ca0f22e1d2d25e [INFO] [stderr] [2022-04-13T18:04:25.513707Z DEBUG libjuice_rs::log] agent.c:662: Leaving agent thread [INFO] [stderr] [2022-04-13T18:04:25.513746Z INFO libjuice_rs::log] agent.c:780: Changing state to disconnected [INFO] [stderr] [2022-04-13T18:04:25.513768Z INFO connectivity] second changed state to: Disconnected [INFO] [stderr] [2022-04-13T18:04:25.513916Z DEBUG libjuice_rs::log] agent.c:662: Leaving agent thread [INFO] [stderr] [2022-04-13T18:04:25.513933Z INFO libjuice_rs::log] agent.c:780: Changing state to disconnected [INFO] [stderr] [2022-04-13T18:04:25.513948Z INFO connectivity] first changed state to: Disconnected [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:311:9 [INFO] [stdout] 10: 0x563b5dd256f9 - std::panicking::rust_panic_with_hook::h3b7380e99b825b63 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17 [INFO] [stdout] 11: 0x563b5dd253e7 - std::panicking::begin_panic_handler::{{closure}}::h8e849d0710154ce0 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13 [INFO] [stdout] 12: 0x563b5dd22f04 - std::sys_common::backtrace::__rust_end_short_backtrace::hedcdaddbd4c46cc5 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18 [INFO] [stdout] 13: 0x563b5dd250f9 - rust_begin_unwind [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5 [INFO] [stdout] 14: 0x563b5dac1983 - core::panicking::panic_fmt::he1bbc7336d49a357 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14 [INFO] [stdout] 15: 0x563b5dd46f48 - core::panicking::assert_failed_inner::hbaac70a629215a04 [INFO] [stdout] 16: 0x563b5dad89aa - core::panicking::assert_failed::h3fb26fdc8a92c563 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:182:5 [INFO] [stdout] 17: 0x563b5dacabc6 - connectivity::connectivity_no_trickle::h9f2c6f4ca0314784 [INFO] [stdout] at /opt/rustwide/workdir/tests/connectivity.rs:65:5 [INFO] [stdout] 18: 0x563b5daca30a - connectivity::connectivity_no_trickle::{{closure}}::h13ff6c1c5c7875dc [INFO] [stdout] at /opt/rustwide/workdir/tests/connectivity.rs:11:1 [INFO] [stdout] 19: 0x563b5dad102e - core::ops::function::FnOnce::call_once::hf7dff486d40a01ee [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5 [INFO] [stdout] 20: 0x563b5dccd4e3 - core::ops::function::FnOnce::call_once::h2a47b4b927cb6ca5 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5 [INFO] [stdout] 21: 0x563b5dccd4e3 - test::__rust_begin_short_backtrace::h594ef8055a183b9b [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/test/src/lib.rs:575:5 [INFO] [stdout] 22: 0x563b5dccc1c4 - as core::ops::function::FnOnce>::call_once::hb40cbb8bc3e1be15 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/alloc/src/boxed.rs:1853:9 [INFO] [stdout] 23: 0x563b5dccc1c4 - as core::ops::function::FnOnce<()>>::call_once::ha4f2bd3b806745a0 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panic/unwind_safe.rs:271:9 [INFO] [stdout] 24: 0x563b5dccc1c4 - std::panicking::try::do_call::h92af9f8bc77a5987 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40 [INFO] [stdout] 25: 0x563b5dccc1c4 - std::panicking::try::h9df49eeae42572b7 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19 [INFO] [stdout] 26: 0x563b5dccc1c4 - std::panic::catch_unwind::h101dbadc82bbe0fd [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14 [INFO] [stdout] 27: 0x563b5dccc1c4 - test::run_test_in_process::h2ad7bffb068e750a [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/test/src/lib.rs:598:18 [INFO] [stdout] 28: 0x563b5dccc1c4 - test::run_test::run_test_inner::{{closure}}::h384faf46554c5acb [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/test/src/lib.rs:492:39 [INFO] [stdout] 29: 0x563b5dcd5ae1 - test::run_test::run_test_inner::{{closure}}::h17cfe94835a46685 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/test/src/lib.rs:519:37 [INFO] [stdout] 30: 0x563b5dcd5ae1 - std::sys_common::backtrace::__rust_begin_short_backtrace::h82709e5086312627 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:122:18 [INFO] [stdout] 31: 0x563b5dca215f - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::hdfea66a201b39571 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/mod.rs:498:17 [INFO] [stdout] 32: 0x563b5dca215f - as core::ops::function::FnOnce<()>>::call_once::h4912df03598e67fa [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panic/unwind_safe.rs:271:9 [INFO] [stdout] 33: 0x563b5dca215f - std::panicking::try::do_call::h6d5dc1045d0eade8 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40 [INFO] [stdout] 34: 0x563b5dca215f - std::panicking::try::hbc897fc717ec6571 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19 [INFO] [stdout] 35: 0x563b5dca215f - std::panic::catch_unwind::h27f1e958c91391ad [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14 [INFO] [stdout] 36: 0x563b5dca215f - std::thread::Builder::spawn_unchecked_::{{closure}}::h1b42e48537edc3c0 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/mod.rs:497:30 [INFO] [stdout] 37: 0x563b5dca215f - core::ops::function::FnOnce::call_once{{vtable.shim}}::h9137b3d6d2a88354 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5 [INFO] [stdout] 38: 0x563b5dd2b443 - as core::ops::function::FnOnce>::call_once::hf70ac038171e3e1a [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/alloc/src/boxed.rs:1853:9 [INFO] [stdout] 39: 0x563b5dd2b443 - as core::ops::function::FnOnce>::call_once::he6690128792365ad [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/alloc/src/boxed.rs:1853:9 [INFO] [stdout] 40: 0x563b5dd2b443 - std::sys::unix::thread::Thread::new::thread_start::ha07928d93d5a5ec9 [INFO] [stdout] at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys/unix/thread.rs:108:17 [INFO] [stdout] 41: 0x7f340bda7609 - start_thread [INFO] [stdout] 42: 0x7f340c030163 - clone [INFO] [stdout] 43: 0x0 - [INFO] [stdout] [2022-04-13T18:04:25.513607Z DEBUG libjuice_rs::log] agent.c:189: Waiting for agent thread [INFO] [stdout] [2022-04-13T18:04:25.513837Z DEBUG libjuice_rs::log] agent.c:151: Destroying agent [INFO] [stdout] [2022-04-13T18:04:25.513876Z DEBUG libjuice_rs::log] agent.c:189: Waiting for agent thread [INFO] [stdout] [2022-04-13T18:04:25.514014Z DEBUG libjuice_rs::log] agent.c:151: Destroying agent [INFO] [stdout] [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] connectivity_no_trickle [INFO] [stdout] [INFO] [stdout] test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 2.02s [INFO] [stdout] [INFO] [stderr] error: test failed, to rerun pass '--test connectivity' [INFO] running `Command { std: "docker" "inspect" "b64765f5b9cfecd60a0c1c30555ce8bc19b7135df0e6e3b99b983d8f37a34e67", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "b64765f5b9cfecd60a0c1c30555ce8bc19b7135df0e6e3b99b983d8f37a34e67", kill_on_drop: false }` [INFO] [stdout] b64765f5b9cfecd60a0c1c30555ce8bc19b7135df0e6e3b99b983d8f37a34e67