[INFO] fetching crate kad 0.6.0...
[INFO] testing kad-0.6.0 against beta-2021-08-01 for beta-1.55-1
[INFO] extracting crate kad 0.6.0 into /workspace/builds/worker-3/source
[INFO] validating manifest of crates.io crate kad 0.6.0 on toolchain beta-2021-08-01
[INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+beta-2021-08-01" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] started tweaking crates.io crate kad 0.6.0
[INFO] finished tweaking crates.io crate kad 0.6.0
[INFO] tweaked toml for crates.io crate kad 0.6.0 written to /workspace/builds/worker-3/source/Cargo.toml
[INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+beta-2021-08-01" "generate-lockfile" "--manifest-path" "Cargo.toml" "-Zno-index-update", kill_on_drop: false }`
[INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+beta-2021-08-01" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded simplelog v0.8.0
[INFO] [stderr]   Downloaded rr-mux v0.10.1
[INFO] [stderr]   Downloaded futures-timer v0.1.1
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/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:34b6a614d2c27851fe6cbf88fbd1137609cefab8b10d0615aaeb6fd47975d74e" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2021-08-01" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stderr] WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mounted. Memory limited without swap.
[INFO] [stdout] 3ba363a2108d05144c91a9f69371654d30fd6afeff7041c9e0f151ca22f27bb4
[INFO] running `Command { std: "docker" "start" "-a" "3ba363a2108d05144c91a9f69371654d30fd6afeff7041c9e0f151ca22f27bb4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "3ba363a2108d05144c91a9f69371654d30fd6afeff7041c9e0f151ca22f27bb4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3ba363a2108d05144c91a9f69371654d30fd6afeff7041c9e0f151ca22f27bb4", kill_on_drop: false }`
[INFO] [stdout] 3ba363a2108d05144c91a9f69371654d30fd6afeff7041c9e0f151ca22f27bb4
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/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:34b6a614d2c27851fe6cbf88fbd1137609cefab8b10d0615aaeb6fd47975d74e" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2021-08-01" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 4bfdca67489cdacc10e938e429d93573a284573d61f8cbe4eed4e64301608af7
[INFO] [stderr] WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mounted. Memory limited without swap.
[INFO] running `Command { std: "docker" "start" "-a" "4bfdca67489cdacc10e938e429d93573a284573d61f8cbe4eed4e64301608af7", kill_on_drop: false }`
[INFO] [stderr]    Compiling log v0.4.14
[INFO] [stderr]    Compiling num-bigint v0.2.6
[INFO] [stderr]    Compiling num-complex v0.2.4
[INFO] [stderr]    Compiling futures-timer v0.1.1
[INFO] [stderr]    Compiling futures-channel v0.3.16
[INFO] [stderr]    Compiling futures-util v0.3.16
[INFO] [stderr]    Compiling num-rational v0.2.4
[INFO] [stderr]    Compiling num v0.2.1
[INFO] [stderr]    Compiling futures-executor v0.3.16
[INFO] [stderr]    Compiling futures v0.3.16
[INFO] [stderr]    Compiling kad v0.6.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 9.14s
[INFO] running `Command { std: "docker" "inspect" "4bfdca67489cdacc10e938e429d93573a284573d61f8cbe4eed4e64301608af7", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "4bfdca67489cdacc10e938e429d93573a284573d61f8cbe4eed4e64301608af7", kill_on_drop: false }`
[INFO] [stdout] 4bfdca67489cdacc10e938e429d93573a284573d61f8cbe4eed4e64301608af7
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/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:34b6a614d2c27851fe6cbf88fbd1137609cefab8b10d0615aaeb6fd47975d74e" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2021-08-01" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 84f4fc726e5c0247df71dba14305b9c211c9ea13865d8c5b9f313232e5ee2ec7
[INFO] [stderr] WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mounted. Memory limited without swap.
[INFO] running `Command { std: "docker" "start" "-a" "84f4fc726e5c0247df71dba14305b9c211c9ea13865d8c5b9f313232e5ee2ec7", kill_on_drop: false }`
[INFO] [stderr]    Compiling derive_builder v0.9.0
[INFO] [stderr]    Compiling darling_core v0.10.2
[INFO] [stderr]    Compiling async-attributes v1.1.2
[INFO] [stderr]    Compiling chrono v0.4.19
[INFO] [stderr]    Compiling polling v2.1.0
[INFO] [stderr]    Compiling kv-log-macro v1.0.7
[INFO] [stderr]    Compiling async-io v1.6.0
[INFO] [stderr]    Compiling async-global-executor v2.0.2
[INFO] [stderr]    Compiling simplelog v0.8.0
[INFO] [stderr]    Compiling async-std v1.9.0
[INFO] [stderr]    Compiling darling_macro v0.10.2
[INFO] [stderr]    Compiling darling v0.10.2
[INFO] [stderr]    Compiling derive_builder_core v0.9.0
[INFO] [stderr]    Compiling rr-mux v0.10.1
[INFO] [stderr]    Compiling kad v0.6.0 (/opt/rustwide/workdir)
[INFO] [stdout] warning: unused import: `std::marker::PhantomData`
[INFO] [stdout]   --> tests/main.rs:10:5
[INFO] [stdout]    |
[INFO] [stdout] 10 | use std::marker::PhantomData;
[INFO] [stdout]    |     ^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(unused_imports)]` on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `kad::mock::MockSync`
[INFO] [stdout]   --> tests/main.rs:17:5
[INFO] [stdout]    |
[INFO] [stdout] 17 | use kad::mock::MockSync;
[INFO] [stdout]    |     ^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `kad::store::HashMapStore`
[INFO] [stdout]   --> tests/main.rs:18:5
[INFO] [stdout]    |
[INFO] [stdout] 18 | use kad::store::HashMapStore;
[INFO] [stdout]    |     ^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `kad::table::KNodeTable`
[INFO] [stdout]   --> tests/main.rs:19:5
[INFO] [stdout]    |
[INFO] [stdout] 19 | use kad::table::KNodeTable;
[INFO] [stdout]    |     ^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `futures::executor::block_on`
[INFO] [stdout]   --> tests/main.rs:24:5
[INFO] [stdout]    |
[INFO] [stdout] 24 | use futures::executor::block_on;
[INFO] [stdout]    |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused variable: `sink_rx`
[INFO] [stdout]   --> tests/main.rs:50:27
[INFO] [stdout]    |
[INFO] [stdout] 50 |             let (sink_tx, sink_rx) = mpsc::channel(10);
[INFO] [stdout]    |                           ^^^^^^^ help: if this is intentional, prefix it with an underscore: `_sink_rx`
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(unused_variables)]` on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct is never constructed: `MockPeer`
[INFO] [stdout]   --> tests/main.rs:26:8
[INFO] [stdout]    |
[INFO] [stdout] 26 | struct MockPeer<Id: Debug, Info: Debug, Data: Debug> {
[INFO] [stdout]    |        ^^^^^^^^
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(dead_code)]` on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: type alias is never used: `PeerMap`
[INFO] [stdout]   --> tests/main.rs:30:1
[INFO] [stdout]    |
[INFO] [stdout] 30 | type PeerMap<Id, Info, Data> = HashMap<Id, MockPeer<Id, Info, Data>>;
[INFO] [stdout]    | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: struct is never constructed: `MockNetwork`
[INFO] [stdout]   --> tests/main.rs:32:8
[INFO] [stdout]    |
[INFO] [stdout] 32 | struct MockNetwork<Id: Debug, Info: Debug, Data: Debug> {
[INFO] [stdout]    |        ^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: associated function is never used: `new`
[INFO] [stdout]   --> tests/main.rs:42:12
[INFO] [stdout]    |
[INFO] [stdout] 42 |     pub fn new(config: Config, nodes: &[Entry<Id, Info>]) -> MockNetwork<Id, Info, Data> {
[INFO] [stdout]    |            ^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `std::time::Duration`
[INFO] [stdout]    --> src/dht/mod.rs:730:9
[INFO] [stdout]     |
[INFO] [stdout] 730 |     use std::time::Duration;
[INFO] [stdout]     |         ^^^^^^^^^^^^^^^^^^^
[INFO] [stdout]     |
[INFO] [stdout]     = note: `#[warn(unused_imports)]` on by default
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `futures::executor::block_on`
[INFO] [stdout]    --> src/dht/mod.rs:734:9
[INFO] [stdout]     |
[INFO] [stdout] 734 |     use futures::executor::block_on;
[INFO] [stdout]     |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `HashMapStore`
[INFO] [stdout]    --> src/dht/mod.rs:737:35
[INFO] [stdout]     |
[INFO] [stdout] 737 |     use crate::store::{Datastore, HashMapStore};
[INFO] [stdout]     |                                   ^^^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: unused import: `KNodeTable`
[INFO] [stdout]    --> src/dht/mod.rs:738:24
[INFO] [stdout]     |
[INFO] [stdout] 738 |     use crate::table::{KNodeTable, NodeTable};
[INFO] [stdout]     |                        ^^^^^^^^^^
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: 10 warnings emitted
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: 4 warnings emitted
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished test [unoptimized + debuginfo] target(s) in 16.60s
[INFO] running `Command { std: "docker" "inspect" "84f4fc726e5c0247df71dba14305b9c211c9ea13865d8c5b9f313232e5ee2ec7", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "84f4fc726e5c0247df71dba14305b9c211c9ea13865d8c5b9f313232e5ee2ec7", kill_on_drop: false }`
[INFO] [stdout] 84f4fc726e5c0247df71dba14305b9c211c9ea13865d8c5b9f313232e5ee2ec7
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-3/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:34b6a614d2c27851fe6cbf88fbd1137609cefab8b10d0615aaeb6fd47975d74e" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2021-08-01" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 31d7323ae9dde2f9a1d40dfd902031531a8b1f9ed586004fa42750b968ffe329
[INFO] [stderr] WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mounted. Memory limited without swap.
[INFO] running `Command { std: "docker" "start" "-a" "31d7323ae9dde2f9a1d40dfd902031531a8b1f9ed586004fa42750b968ffe329", kill_on_drop: false }`
[INFO] [stderr] warning: unused import: `std::time::Duration`
[INFO] [stderr]    --> src/dht/mod.rs:730:9
[INFO] [stderr]     |
[INFO] [stderr] 730 |     use std::time::Duration;
[INFO] [stderr]     |         ^^^^^^^^^^^^^^^^^^^
[INFO] [stderr]     |
[INFO] [stderr]     = note: `#[warn(unused_imports)]` on by default
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `futures::executor::block_on`
[INFO] [stderr]    --> src/dht/mod.rs:734:9
[INFO] [stderr]     |
[INFO] [stderr] 734 |     use futures::executor::block_on;
[INFO] [stderr]     |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `HashMapStore`
[INFO] [stderr]    --> src/dht/mod.rs:737:35
[INFO] [stderr]     |
[INFO] [stderr] 737 |     use crate::store::{Datastore, HashMapStore};
[INFO] [stderr]     |                                   ^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `KNodeTable`
[INFO] [stderr]    --> src/dht/mod.rs:738:24
[INFO] [stderr]     |
[INFO] [stderr] 738 |     use crate::table::{KNodeTable, NodeTable};
[INFO] [stderr]     |                        ^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `std::marker::PhantomData`
[INFO] [stderr]   --> tests/main.rs:10:5
[INFO] [stderr]    |
[INFO] [stderr] 10 | use std::marker::PhantomData;
[INFO] [stderr]    |     ^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr]    |
[INFO] [stderr]    = note: `#[warn(unused_imports)]` on by default
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `kad::mock::MockSync`
[INFO] [stderr]   --> tests/main.rs:17:5
[INFO] [stderr]    |
[INFO] [stderr] 17 | use kad::mock::MockSync;
[INFO] [stderr]    |     ^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `kad::store::HashMapStore`
[INFO] [stderr]   --> tests/main.rs:18:5
[INFO] [stderr]    |
[INFO] [stderr] 18 | use kad::store::HashMapStore;
[INFO] [stderr]    |     ^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `kad::table::KNodeTable`
[INFO] [stderr]   --> tests/main.rs:19:5
[INFO] [stderr]    |
[INFO] [stderr] 19 | use kad::table::KNodeTable;
[INFO] [stderr]    |     ^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused import: `futures::executor::block_on`
[INFO] [stderr]   --> tests/main.rs:24:5
[INFO] [stderr]    |
[INFO] [stderr] 24 | use futures::executor::block_on;
[INFO] [stderr]    |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: unused variable: `sink_rx`
[INFO] [stderr]   --> tests/main.rs:50:27
[INFO] [stderr]    |
[INFO] [stderr] 50 |             let (sink_tx, sink_rx) = mpsc::channel(10);
[INFO] [stderr]    |                           ^^^^^^^ help: if this is intentional, prefix it with an underscore: `_sink_rx`
[INFO] [stderr]    |
[INFO] [stderr]    = note: `#[warn(unused_variables)]` on by default
[INFO] [stderr] 
[INFO] [stderr] warning: struct is never constructed: `MockPeer`
[INFO] [stderr]   --> tests/main.rs:26:8
[INFO] [stderr]    |
[INFO] [stderr] 26 | struct MockPeer<Id: Debug, Info: Debug, Data: Debug> {
[INFO] [stderr]    |        ^^^^^^^^
[INFO] [stderr]    |
[INFO] [stderr]    = note: `#[warn(dead_code)]` on by default
[INFO] [stderr] 
[INFO] [stderr] warning: type alias is never used: `PeerMap`
[INFO] [stderr]   --> tests/main.rs:30:1
[INFO] [stderr]    |
[INFO] [stderr] 30 | type PeerMap<Id, Info, Data> = HashMap<Id, MockPeer<Id, Info, Data>>;
[INFO] [stderr]    | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: struct is never constructed: `MockNetwork`
[INFO] [stderr]   --> tests/main.rs:32:8
[INFO] [stderr]    |
[INFO] [stderr] 32 | struct MockNetwork<Id: Debug, Info: Debug, Data: Debug> {
[INFO] [stderr]    |        ^^^^^^^^^^^
[INFO] [stderr] 
[INFO] [stderr] warning: associated function is never used: `new`
[INFO] [stderr]   --> tests/main.rs:42:12
[INFO] [stderr]    |
[INFO] [stderr] 42 |     pub fn new(config: Config, nodes: &[Entry<Id, Info>]) -> MockNetwork<Id, Info, Data> {
[INFO] [stderr]    |            ^^^
[INFO] [stderr] 
[INFO] [stderr] warning: `kad` (lib test) generated 4 warnings
[INFO] [stderr] warning: `kad` (test "main") generated 10 warnings
[INFO] [stderr]     Finished test [unoptimized + debuginfo] target(s) in 0.10s
[INFO] [stderr]      Running unittests (/opt/rustwide/target/debug/deps/kad-8aa164d690b5fd8a)
[INFO] [stdout] 
[INFO] [stdout] running 11 tests
[INFO] [stdout] test dht::tests::test_receive_store ... ok
[INFO] [stdout] test dht::tests::test_receive_common ... ok
[INFO] [stdout] test table::kbucket::test::test_k_bucket_update ... ok
[INFO] [stdout] test table::knodetable::test::test_k_node_table ... ok
[INFO] [stdout] 06:07:49 [INFO] Start connect
[INFO] [stdout] 06:07:49 [INFO] Start store
[INFO] [stdout] 06:07:49 [INFO] Search round 0
[INFO] [stdout] 06:07:49 [INFO] Start locate
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Registering operation id: 35460
[INFO] [stdout] 06:07:49 [INFO] Start locate
[INFO] [stdout] 06:07:49 [INFO] Search round 0
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Registering operation id: 20699
[INFO] [stdout] 06:07:49 [INFO] Search round 0
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Initiating operation Connect (56188)  sending FindNode([8]) request to [Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }, Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Op 56188 tx: FindNode([8]) to: Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Op 56188 tx: FindNode([8]) to: Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Receive response id: 56188 (NodesFound([8], [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: update node: (Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Receive response id: 56188 (NodesFound([8], [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: update node: (Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [INFO] Search round 1
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188, all responses received, re-starting search
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188 search iteration 1
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188 issuing search request: FindNode([8]) to: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Receive response id: 56188 (NodesFound([8], [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (8) kad::dht: No values found, returning closer nodes for id: [201]
[INFO] [stdout] 06:07:49 [DEBUG] (8) kad::dht: Found 1 values for id: [201]
[INFO] [stdout] test dht::tests::test_receive_find_values ... ok
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Receive response id: 56188 (NodesFound([8], [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188 search complete!
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operation 56188 entering done state
[INFO] [stdout] 06:07:49 [DEBUG] (2) kad::dht: Operating 56188 done
[INFO] [stdout] 06:07:49 [INFO] Expecting completion
[INFO] [stdout] test dht::connect::tests::test_connect ... ok
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Initiating operation Store (35460)  sending FindNode([12]) request to [Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 28573368 }), state: Ok, frozen: false }, Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 28564467 }), state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Op 35460 tx: FindNode([12]) to: Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 28573368 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Op 35460 tx: FindNode([12]) to: Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 28564467 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Receive response id: 35460 (NodesFound([12], [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: update node: (Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 28573368 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Receive response id: 35460 (NodesFound([12], [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: update node: (Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 28564467 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [INFO] Search round 1
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460, all responses received, re-starting search
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 search iteration 1
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 issuing search request: FindNode([12]) to: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Receive response id: 35460 (NodesFound([12], [])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460, adding entries to map: []
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Receive response id: 35460 (NodesFound([12], [])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460, adding entries to map: []
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [INFO] Store round
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 search complete!
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 issuing request: Store([12], [500]) to: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Receive response id: 35460 (ValuesFound([12], [500])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460, adding data to map: [500]
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Receive response id: 35460 (ValuesFound([12], [500])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460, adding data to map: [500]
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 entering done state
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operating 35460 done
[INFO] [stdout] 06:07:49 [DEBUG] (5) kad::dht: Operation 35460 stored at 2 peers
[INFO] [stdout] 06:07:49 [INFO] Expecting store completion
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Initiating operation FindValues (20699)  sending FindValue([12]) request to [Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29014500 }), state: Ok, frozen: false }, Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29003299 }), state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Op 20699 tx: FindValue([12]) to: Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29014500 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Op 20699 tx: FindValue([12]) to: Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29003299 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Receive response id: 20699 (NodesFound([12], [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: update node: (Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29003299 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Receive response id: 20699 (NodesFound([12], [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: update node: (Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29014500 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [INFO] Search round 1
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699, all responses received, re-starting search
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699 search iteration 1
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699 issuing search request: FindValue([12]) to: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Receive response id: 20699 (ValuesFound([12], [500])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699, adding data to map: [500]
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Receive response id: 20699 (ValuesFound([12], [500])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699, adding data to map: [500]
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699 search complete!
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699 entering done state
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operating 20699 done
[INFO] [stdout] 06:07:49 [DEBUG] (4) kad::dht: Operation 20699 values found: [500, 500]
[INFO] [stdout] 06:07:49 [INFO] Expecting search completion
[INFO] [stdout] test dht::store::tests::test_store ... ok
[INFO] [stdout] test dht::search::tests::test_search ... ok
[INFO] [stdout] test dht::tests::test_receive_find_nodes ... ok
[INFO] [stdout] test dht::tests::test_receive_ping ... ok
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Registering operation id: 60544
[INFO] [stdout] 06:07:49 [INFO] Search round 0
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Initiating operation FindNode (60544)  sending FindNode([9]) request to [Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29657447 }), state: Ok, frozen: false }, Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29665547 }), state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Op 60544 tx: FindNode([9]) to: Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29657447 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Op 60544 tx: FindNode([9]) to: Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29665547 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Receive response id: 60544 (NodesFound([9], [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: update node: (Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29665547 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Receive response id: 60544 (NodesFound([9], [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: update node: (Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710485, tv_nsec: 29657447 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [INFO] Search round 1
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544, all responses received, re-starting search
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544 search iteration 1
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544 issuing search request: FindNode([9]) to: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544 entering searching state
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Receive response id: 60544 (NodesFound([9], [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Receive response id: 60544 (NodesFound([9], [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544 search complete!
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operation 60544 entering done state
[INFO] [stdout] 06:07:49 [DEBUG] (3) kad::dht: Operating 60544 done
[INFO] [stdout] 06:07:49 [INFO] Expecting completion
[INFO] [stdout] test dht::locate::tests::test_lookup ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/main.rs (/opt/rustwide/target/debug/deps/main-58fc17795fd3da7a)
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests kad
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 0 tests
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "31d7323ae9dde2f9a1d40dfd902031531a8b1f9ed586004fa42750b968ffe329", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "31d7323ae9dde2f9a1d40dfd902031531a8b1f9ed586004fa42750b968ffe329", kill_on_drop: false }`
[INFO] [stdout] 31d7323ae9dde2f9a1d40dfd902031531a8b1f9ed586004fa42750b968ffe329
