[INFO] fetching crate kad 0.6.0...
[INFO] testing kad-0.6.0 against 1.54.0 for beta-1.55-1
[INFO] extracting crate kad 0.6.0 into /workspace/builds/worker-4/source
[INFO] validating manifest of crates.io crate kad 0.6.0 on toolchain 1.54.0
[INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1.54.0" "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-4/source/Cargo.toml
[INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1.54.0" "generate-lockfile" "--manifest-path" "Cargo.toml" "-Zno-index-update", kill_on_drop: false }`
[INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+1.54.0" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/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" "+1.54.0" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] ecd38e3e00fadcadac2235ea0e1b659d41396aa5cba09df589317d9d9cd083e9
[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" "ecd38e3e00fadcadac2235ea0e1b659d41396aa5cba09df589317d9d9cd083e9", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "ecd38e3e00fadcadac2235ea0e1b659d41396aa5cba09df589317d9d9cd083e9", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "ecd38e3e00fadcadac2235ea0e1b659d41396aa5cba09df589317d9d9cd083e9", kill_on_drop: false }`
[INFO] [stdout] ecd38e3e00fadcadac2235ea0e1b659d41396aa5cba09df589317d9d9cd083e9
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/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" "+1.54.0" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] eb71aeb845b2c38385de7fb6ac90992963519703411317ae40396f0e1692834a
[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" "eb71aeb845b2c38385de7fb6ac90992963519703411317ae40396f0e1692834a", 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-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 8.12s
[INFO] running `Command { std: "docker" "inspect" "eb71aeb845b2c38385de7fb6ac90992963519703411317ae40396f0e1692834a", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "eb71aeb845b2c38385de7fb6ac90992963519703411317ae40396f0e1692834a", kill_on_drop: false }`
[INFO] [stdout] eb71aeb845b2c38385de7fb6ac90992963519703411317ae40396f0e1692834a
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/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" "+1.54.0" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] aece6c2660858c27f3e9addb80adc9f35c8794ebfd53451056384ad376332c5b
[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" "aece6c2660858c27f3e9addb80adc9f35c8794ebfd53451056384ad376332c5b", kill_on_drop: false }`
[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 derive_builder 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 17.76s
[INFO] running `Command { std: "docker" "inspect" "aece6c2660858c27f3e9addb80adc9f35c8794ebfd53451056384ad376332c5b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "aece6c2660858c27f3e9addb80adc9f35c8794ebfd53451056384ad376332c5b", kill_on_drop: false }`
[INFO] [stdout] aece6c2660858c27f3e9addb80adc9f35c8794ebfd53451056384ad376332c5b
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4/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" "+1.54.0" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] ce3129b9540a240a2237da7897d80e4f199f88a697fe05f9d9a8ea11d5347a31
[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" "ce3129b9540a240a2237da7897d80e4f199f88a697fe05f9d9a8ea11d5347a31", kill_on_drop: false }`
[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: 10 warnings emitted
[INFO] [stderr] 
[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: 4 warnings emitted
[INFO] [stderr] 
[INFO] [stderr]     Finished test [unoptimized + debuginfo] target(s) in 0.10s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests (/opt/rustwide/target/debug/deps/kad-8cfbf8b9e392f141)
[INFO] [stdout] running 11 tests
[INFO] [stdout] 06:07:54 [INFO] Start connect
[INFO] [stdout] 06:07:54 [INFO] Search round 0
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Initiating operation Connect (25906)  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:54 [DEBUG] (2) kad::dht: Op 25906 tx: FindNode([8]) to: Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Op 25906 tx: FindNode([8]) to: Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Operation 25906 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Receive response id: 25906 (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:54 [DEBUG] (2) kad::dht: Operation 25906, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: update node: (Entry { id: [3], info: 200, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Receive response id: 25906 (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:54 [DEBUG] (2) kad::dht: Operation 25906, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: update node: (Entry { id: [2], info: 300, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [INFO] Search round 1
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Operation 25906, all responses received, re-starting search
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Operation 25906 search iteration 1
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Operation 25906 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:54 [DEBUG] (2) kad::dht: Operation 25906 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Receive response id: 25906 (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:54 [DEBUG] (2) kad::dht: Operation 25906, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Receive response id: 25906 (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:54 [DEBUG] (2) kad::dht: Operation 25906, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Operation 25906 search complete!
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Operation 25906 entering done state
[INFO] [stdout] test dht::tests::test_receive_common ... ok
[INFO] [stdout] test dht::tests::test_receive_find_values ... ok
[INFO] [stdout] test table::kbucket::test::test_k_bucket_update ... ok
[INFO] [stdout] 06:07:54 [DEBUG] (2) kad::dht: Operating 25906 done
[INFO] [stdout] test table::knodetable::test::test_k_node_table ... ok
[INFO] [stdout] test dht::tests::test_receive_ping ... ok
[INFO] [stdout] 06:07:54 [INFO] Expecting completion
[INFO] [stdout] 06:07:54 [INFO] Start store
[INFO] [stdout] test dht::connect::tests::test_connect ... ok
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Registering operation id: 1297
[INFO] [stdout] 06:07:54 [INFO] Search round 0
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Initiating operation Store (1297)  sending FindNode([12]) request to [Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 198286869 }), state: Ok, frozen: false }, Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 198278469 }), state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Op 1297 tx: FindNode([12]) to: Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 198286869 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Op 1297 tx: FindNode([12]) to: Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 198278469 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Receive response id: 1297 (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:54 [DEBUG] (5) kad::dht: Operation 1297, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: update node: (Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 198286869 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Receive response id: 1297 (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:54 [DEBUG] (5) kad::dht: Operation 1297, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: update node: (Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 198278469 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [INFO] Search round 1
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297, all responses received, re-starting search
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297 search iteration 1
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297 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:54 [DEBUG] (5) kad::dht: Operation 1297 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Receive response id: 1297 (NodesFound([12], [])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297, adding entries to map: []
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Receive response id: 1297 (NodesFound([12], [])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297, adding entries to map: []
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [INFO] Store round
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297 search complete!
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297 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:54 [DEBUG] (5) kad::dht: Receive response id: 1297 (ValuesFound([12], [500])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297, adding data to map: [500]
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Receive response id: 1297 (ValuesFound([12], [500])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297, adding data to map: [500]
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297 entering done state
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operating 1297 done
[INFO] [stdout] 06:07:54 [DEBUG] (5) kad::dht: Operation 1297 stored at 2 peers
[INFO] [stdout] 06:07:54 [INFO] Expecting store completion
[INFO] [stdout] test dht::store::tests::test_store ... ok
[INFO] [stdout] 06:07:54 [DEBUG] (10) kad::dht: Stored 1 values for id: [2]
[INFO] [stdout] 06:07:54 [INFO] Start locate
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Registering operation id: 15976
[INFO] [stdout] 06:07:54 [INFO] Search round 0
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Initiating operation FindValues (15976)  sending FindValue([12]) request to [Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 204607129 }), state: Ok, frozen: false }, Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 204595728 }), state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Op 15976 tx: FindValue([12]) to: Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 204607129 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Op 15976 tx: FindValue([12]) to: Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 204595728 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Receive response id: 15976 (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:54 [DEBUG] (4) kad::dht: Operation 15976, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: update node: (Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 204595728 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Receive response id: 15976 (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:54 [DEBUG] (4) kad::dht: Operation 15976, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: update node: (Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 204607129 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [INFO] Search round 1
[INFO] [stdout] test dht::tests::test_receive_store ... ok
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976, all responses received, re-starting search
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976 search iteration 1
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976 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:54 [DEBUG] (4) kad::dht: Operation 15976 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Receive response id: 15976 (ValuesFound([12], [500])) from: Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976, adding data to map: [500]
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Receive response id: 15976 (ValuesFound([12], [500])) from: Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976, adding data to map: [500]
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976 search complete!
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976 entering done state
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operating 15976 done
[INFO] [stdout] 06:07:54 [DEBUG] (4) kad::dht: Operation 15976 values found: [500, 500]
[INFO] [stdout] 06:07:54 [INFO] Expecting search completion
[INFO] [stdout] 06:07:54 [INFO] Start locate
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Registering operation id: 8150
[INFO] [stdout] 06:07:54 [INFO] Search round 0
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Initiating operation FindNode (8150)  sending FindNode([9]) request to [Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 213841599 }), state: Ok, frozen: false }, Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 213857201 }), state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Op 8150 tx: FindNode([9]) to: Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 213841599 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Op 8150 tx: FindNode([9]) to: Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 213857201 }), state: Ok, frozen: false }
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Operation 8150 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Receive response id: 8150 (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:54 [DEBUG] (3) kad::dht: Operation 8150, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: update node: (Entry { id: [2], info: 300, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 213857201 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Receive response id: 8150 (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:54 [DEBUG] (3) kad::dht: Operation 8150, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: update node: (Entry { id: [3], info: 200, seen: Some(Instant { tv_sec: 6710490, tv_nsec: 213841599 }), state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [INFO] Search round 1
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Operation 8150, all responses received, re-starting search
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Operation 8150 search iteration 1
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Operation 8150 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:54 [DEBUG] (3) kad::dht: Operation 8150 entering searching state
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Receive response id: 8150 (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:54 [DEBUG] (3) kad::dht: Operation 8150, adding entries to map: [Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: update node: (Entry { id: [9], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Receive response id: 8150 (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:54 [DEBUG] (3) kad::dht: Operation 8150, adding entries to map: [Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }]
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: update node: (Entry { id: [10], info: 400, seen: None, state: Ok, frozen: false }, Complete)
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Operation 8150 search complete!
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Operation 8150 entering done state
[INFO] [stdout] 06:07:54 [DEBUG] (3) kad::dht: Operating 8150 done
[INFO] [stdout] 06:07:54 [INFO] Expecting completion
[INFO] [stdout] test dht::tests::test_receive_find_nodes ... ok
[INFO] [stdout] test dht::search::tests::test_search ... ok
[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.03s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/main.rs (/opt/rustwide/target/debug/deps/main-9f18766028439683)
[INFO] [stderr]    Doc-tests kad
[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] [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" "ce3129b9540a240a2237da7897d80e4f199f88a697fe05f9d9a8ea11d5347a31", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "ce3129b9540a240a2237da7897d80e4f199f88a697fe05f9d9a8ea11d5347a31", kill_on_drop: false }`
[INFO] [stdout] ce3129b9540a240a2237da7897d80e4f199f88a697fe05f9d9a8ea11d5347a31
