[INFO] cloning repository https://github.com/kafji/tp-kvs
[INFO] running `Command { std: "git" "-c" "credential.helper=" "-c" "credential.helper=/workspace/cargo-home/bin/git-credential-null" "clone" "--bare" "https://github.com/kafji/tp-kvs" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fkafji%2Ftp-kvs", kill_on_drop: false }`
[INFO] [stderr] Cloning into bare repository '/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fkafji%2Ftp-kvs'...
[INFO] running `Command { std: "git" "rev-parse" "HEAD", kill_on_drop: false }`
[INFO] [stdout] 9b6ff72b524b5e9ce4bfe3b1e1ab2199a84aa065
[INFO] testing kafji/tp-kvs against beta-2021-08-01 for beta-1.55-1
[INFO] running `Command { std: "git" "clone" "/workspace/cache/git-repos/https%3A%2F%2Fgithub.com%2Fkafji%2Ftp-kvs" "/workspace/builds/worker-7/source", kill_on_drop: false }`
[INFO] [stderr] Cloning into '/workspace/builds/worker-7/source'...
[INFO] [stderr] done.
[INFO] validating manifest of git repo https://github.com/kafji/tp-kvs 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 git repo https://github.com/kafji/tp-kvs
[INFO] finished tweaking git repo https://github.com/kafji/tp-kvs
[INFO] tweaked toml for git repo https://github.com/kafji/tp-kvs written to /workspace/builds/worker-7/source/Cargo.toml
[INFO] crate git repo https://github.com/kafji/tp-kvs already has a lockfile, it will not be regenerated
[INFO] running `Command { std: "/workspace/cargo-home/bin/cargo" "+beta-2021-08-01" "fetch" "--manifest-path" "Cargo.toml", 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] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/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] [stdout] 008922ebf0a722d3be18c782fbfa09753a69f2b3a94077db87ecbbb5479ff111
[INFO] running `Command { std: "docker" "start" "-a" "008922ebf0a722d3be18c782fbfa09753a69f2b3a94077db87ecbbb5479ff111", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "008922ebf0a722d3be18c782fbfa09753a69f2b3a94077db87ecbbb5479ff111", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "008922ebf0a722d3be18c782fbfa09753a69f2b3a94077db87ecbbb5479ff111", kill_on_drop: false }`
[INFO] [stdout] 008922ebf0a722d3be18c782fbfa09753a69f2b3a94077db87ecbbb5479ff111
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/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] 2a0de1f688092958bbc34ba1f0456e5ab7be730f32d290ba90b6b7eaf3ea0c8c
[INFO] running `Command { std: "docker" "start" "-a" "2a0de1f688092958bbc34ba1f0456e5ab7be730f32d290ba90b6b7eaf3ea0c8c", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.24
[INFO] [stderr]    Compiling libc v0.2.80
[INFO] [stderr]    Compiling syn v1.0.48
[INFO] [stderr]    Compiling version_check v0.9.2
[INFO] [stderr]    Compiling ident_case v1.0.1
[INFO] [stderr]    Compiling slog v2.5.2
[INFO] [stderr]    Compiling serde_derive v1.0.117
[INFO] [stderr]    Compiling const_fn v0.4.3
[INFO] [stderr]    Compiling strsim v0.9.3
[INFO] [stderr]    Compiling smallvec v1.4.2
[INFO] [stderr]    Compiling serde v1.0.117
[INFO] [stderr]    Compiling log v0.4.11
[INFO] [stderr]    Compiling unicode-segmentation v1.6.0
[INFO] [stderr]    Compiling crc32fast v1.2.1
[INFO] [stderr]    Compiling adler v0.2.3
[INFO] [stderr]    Compiling gimli v0.23.0
[INFO] [stderr]    Compiling anyhow v1.0.34
[INFO] [stderr]    Compiling hashbrown v0.9.1
[INFO] [stderr]    Compiling rustc-demangle v0.1.18
[INFO] [stderr]    Compiling object v0.22.0
[INFO] [stderr]    Compiling derive_builder v0.9.0
[INFO] [stderr]    Compiling os_str_bytes v2.3.2
[INFO] [stderr]    Compiling termcolor v1.1.0
[INFO] [stderr]    Compiling strsim v0.10.0
[INFO] [stderr]    Compiling once_cell v1.4.1
[INFO] [stderr]    Compiling num-traits v0.2.14
[INFO] [stderr]    Compiling crossbeam-utils v0.7.2
[INFO] [stderr]    Compiling miniz_oxide v0.4.3
[INFO] [stderr]    Compiling crossbeam-utils v0.8.0
[INFO] [stderr]    Compiling memoffset v0.5.6
[INFO] [stderr]    Compiling indexmap v1.6.0
[INFO] [stderr]    Compiling instant v0.1.8
[INFO] [stderr]    Compiling thread_local v1.0.1
[INFO] [stderr]    Compiling lock_api v0.4.1
[INFO] [stderr]    Compiling textwrap v0.12.1
[INFO] [stderr]    Compiling fxhash v0.2.1
[INFO] [stderr]    Compiling heck v0.3.1
[INFO] [stderr]    Compiling proc-macro-error-attr v1.0.4
[INFO] [stderr]    Compiling proc-macro-error v1.0.4
[INFO] [stderr]    Compiling quote v1.0.7
[INFO] [stderr]    Compiling addr2line v0.14.0
[INFO] [stderr]    Compiling dirs-sys v0.3.5
[INFO] [stderr]    Compiling time v0.1.44
[INFO] [stderr]    Compiling atty v0.2.14
[INFO] [stderr]    Compiling parking_lot_core v0.8.0
[INFO] [stderr]    Compiling fs2 v0.4.3
[INFO] [stderr]    Compiling nix v0.19.0
[INFO] [stderr]    Compiling dirs v2.0.2
[INFO] [stderr]    Compiling parking_lot v0.11.0
[INFO] [stderr]    Compiling num-integer v0.1.44
[INFO] [stderr]    Compiling term v0.6.1
[INFO] [stderr]    Compiling crossbeam-channel v0.4.4
[INFO] [stderr]    Compiling backtrace v0.3.54
[INFO] [stderr]    Compiling chrono v0.4.19
[INFO] [stderr]    Compiling crossbeam-epoch v0.9.0
[INFO] [stderr]    Compiling slog-async v2.5.0
[INFO] [stderr]    Compiling sled v0.34.5
[INFO] [stderr]    Compiling slog-term v2.6.0
[INFO] [stderr]    Compiling darling_core v0.10.2
[INFO] [stderr]    Compiling thiserror-impl v1.0.22
[INFO] [stderr]    Compiling clap_derive v3.0.0-beta.2
[INFO] [stderr]    Compiling num-derive v0.3.3
[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 thiserror v1.0.22
[INFO] [stderr]    Compiling clap v3.0.0-beta.2
[INFO] [stderr]    Compiling bincode v1.3.1
[INFO] [stderr]    Compiling exercises v0.0.1 (/opt/rustwide/workdir/exercises)
[INFO] [stderr]    Compiling kvs v0.0.1 (/opt/rustwide/workdir/kvs)
[INFO] [stdout] warning: panic message is not a string literal
[INFO] [stdout]   --> exercises/src/bin/redis_protocol.rs:59:25
[INFO] [stdout]    |
[INFO] [stdout] 59 |         other => panic!(format!("unexpected arg `{}`", other)),
[INFO] [stdout]    |                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(non_fmt_panics)]` on by default
[INFO] [stdout]    = note: this usage of panic!() is deprecated; it will be a hard error in Rust 2021
[INFO] [stdout]    = note: for more information, see <https://doc.rust-lang.org/nightly/edition-guide/rust-2021/panic-macro-consistency.html>
[INFO] [stdout]    = note: the panic!() macro supports formatting, so there's no need for the format!() macro here
[INFO] [stdout] help: remove the `format!(..)` macro call
[INFO] [stdout]    |
[INFO] [stdout] 59 |         other => panic!("unexpected arg `{}`", other),
[INFO] [stdout]    |                        --                          --
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: panic message is not a string literal
[INFO] [stdout]     --> exercises/src/bin/redis_protocol.rs:1063:28
[INFO] [stdout]      |
[INFO] [stdout] 1063 |                       panic!(format!(
[INFO] [stdout]      |  ____________________________^
[INFO] [stdout] 1064 | |                         "unknown type, first byte is `{}`",
[INFO] [stdout] 1065 | |                         first_byte as char
[INFO] [stdout] 1066 | |                     ))
[INFO] [stdout]      | |_____________________^
[INFO] [stdout]      |
[INFO] [stdout]      = note: this usage of panic!() is deprecated; it will be a hard error in Rust 2021
[INFO] [stdout]      = note: for more information, see <https://doc.rust-lang.org/nightly/edition-guide/rust-2021/panic-macro-consistency.html>
[INFO] [stdout]      = note: the panic!() macro supports formatting, so there's no need for the format!() macro here
[INFO] [stdout] help: remove the `format!(..)` macro call
[INFO] [stdout]      |
[INFO] [stdout] 1063 |                     panic!(
[INFO] [stdout] 1064 |                         "unknown type, first byte is `{}`",
[INFO] [stdout] 1065 |                         first_byte as char
[INFO] [stdout] 1066 |                     )
[INFO] [stdout]      |
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: 2 warnings emitted
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 35.06s
[INFO] running `Command { std: "docker" "inspect" "2a0de1f688092958bbc34ba1f0456e5ab7be730f32d290ba90b6b7eaf3ea0c8c", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "2a0de1f688092958bbc34ba1f0456e5ab7be730f32d290ba90b6b7eaf3ea0c8c", kill_on_drop: false }`
[INFO] [stdout] 2a0de1f688092958bbc34ba1f0456e5ab7be730f32d290ba90b6b7eaf3ea0c8c
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/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] 3e9f8a1cca4c582ddd6f9396950dcaed0f09c0f2accc8916440064c5f44c43cb
[INFO] running `Command { std: "docker" "start" "-a" "3e9f8a1cca4c582ddd6f9396950dcaed0f09c0f2accc8916440064c5f44c43cb", kill_on_drop: false }`
[INFO] [stderr]    Compiling getrandom v0.1.15
[INFO] [stderr]    Compiling regex-syntax v0.6.21
[INFO] [stderr]    Compiling predicates-core v1.0.0
[INFO] [stderr]    Compiling doc-comment v0.3.3
[INFO] [stderr]    Compiling remove_dir_all v0.5.3
[INFO] [stderr]    Compiling static_assertions v1.1.0
[INFO] [stderr]    Compiling wait-timeout v0.2.0
[INFO] [stderr]    Compiling float-cmp v0.8.0
[INFO] [stderr]    Compiling quickcheck_macros v0.9.1
[INFO] [stderr]    Compiling exercises v0.0.1 (/opt/rustwide/workdir/exercises)
[INFO] [stderr]    Compiling predicates-tree v1.0.0
[INFO] [stdout] warning: panic message is not a string literal
[INFO] [stdout]   --> exercises/src/bin/redis_protocol.rs:59:25
[INFO] [stdout]    |
[INFO] [stdout] 59 |         other => panic!(format!("unexpected arg `{}`", other)),
[INFO] [stdout]    |                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stdout]    |
[INFO] [stdout]    = note: `#[warn(non_fmt_panics)]` on by default
[INFO] [stdout]    = note: this usage of panic!() is deprecated; it will be a hard error in Rust 2021
[INFO] [stdout]    = note: for more information, see <https://doc.rust-lang.org/nightly/edition-guide/rust-2021/panic-macro-consistency.html>
[INFO] [stdout]    = note: the panic!() macro supports formatting, so there's no need for the format!() macro here
[INFO] [stdout] help: remove the `format!(..)` macro call
[INFO] [stdout]    |
[INFO] [stdout] 59 |         other => panic!("unexpected arg `{}`", other),
[INFO] [stdout]    |                        --                          --
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] warning: panic message is not a string literal
[INFO] [stdout]     --> exercises/src/bin/redis_protocol.rs:1063:28
[INFO] [stdout]      |
[INFO] [stdout] 1063 |                       panic!(format!(
[INFO] [stdout]      |  ____________________________^
[INFO] [stdout] 1064 | |                         "unknown type, first byte is `{}`",
[INFO] [stdout] 1065 | |                         first_byte as char
[INFO] [stdout] 1066 | |                     ))
[INFO] [stdout]      | |_____________________^
[INFO] [stdout]      |
[INFO] [stdout]      = note: this usage of panic!() is deprecated; it will be a hard error in Rust 2021
[INFO] [stdout]      = note: for more information, see <https://doc.rust-lang.org/nightly/edition-guide/rust-2021/panic-macro-consistency.html>
[INFO] [stdout]      = note: the panic!() macro supports formatting, so there's no need for the format!() macro here
[INFO] [stdout] help: remove the `format!(..)` macro call
[INFO] [stdout]      |
[INFO] [stdout] 1063 |                     panic!(
[INFO] [stdout] 1064 |                         "unknown type, first byte is `{}`",
[INFO] [stdout] 1065 |                         first_byte as char
[INFO] [stdout] 1066 |                     )
[INFO] [stdout]      |
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]    Compiling rand_core v0.5.1
[INFO] [stderr]    Compiling rand_chacha v0.2.2
[INFO] [stderr]    Compiling rand v0.7.3
[INFO] [stdout] warning: 2 warnings emitted
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stderr]    Compiling tempfile v3.1.0
[INFO] [stderr]    Compiling regex v1.4.2
[INFO] [stderr]    Compiling predicates v1.0.5
[INFO] [stderr]    Compiling env_logger v0.7.1
[INFO] [stderr]    Compiling quickcheck v0.9.2
[INFO] [stderr]    Compiling assert_cmd v1.0.1
[INFO] [stderr]    Compiling kvs v0.0.1 (/opt/rustwide/workdir/kvs)
[INFO] [stderr]     Finished test [unoptimized + debuginfo] target(s) in 12.49s
[INFO] running `Command { std: "docker" "inspect" "3e9f8a1cca4c582ddd6f9396950dcaed0f09c0f2accc8916440064c5f44c43cb", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3e9f8a1cca4c582ddd6f9396950dcaed0f09c0f2accc8916440064c5f44c43cb", kill_on_drop: false }`
[INFO] [stdout] 3e9f8a1cca4c582ddd6f9396950dcaed0f09c0f2accc8916440064c5f44c43cb
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-7/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] b8fc5c8b7afd3f91bf9e5d19e04e3720f28d6eaadf49a61206f711270ef797c2
[INFO] running `Command { std: "docker" "start" "-a" "b8fc5c8b7afd3f91bf9e5d19e04e3720f28d6eaadf49a61206f711270ef797c2", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr] warning: panic message is not a string literal
[INFO] [stderr]   --> exercises/src/bin/redis_protocol.rs:59:25
[INFO] [stderr]    |
[INFO] [stderr] 59 |         other => panic!(format!("unexpected arg `{}`", other)),
[INFO] [stderr]    |                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[INFO] [stderr]    |
[INFO] [stderr]    = note: `#[warn(non_fmt_panics)]` on by default
[INFO] [stderr]    = note: this usage of panic!() is deprecated; it will be a hard error in Rust 2021
[INFO] [stderr]    = note: for more information, see <https://doc.rust-lang.org/nightly/edition-guide/rust-2021/panic-macro-consistency.html>
[INFO] [stderr]    = note: the panic!() macro supports formatting, so there's no need for the format!() macro here
[INFO] [stderr] help: remove the `format!(..)` macro call
[INFO] [stderr]    |
[INFO] [stderr] 59 |         other => panic!("unexpected arg `{}`", other),
[INFO] [stderr]    |                        --                          --
[INFO] [stderr] 
[INFO] [stderr] warning: panic message is not a string literal
[INFO] [stderr]     --> exercises/src/bin/redis_protocol.rs:1063:28
[INFO] [stderr]      |
[INFO] [stderr] 1063 |                       panic!(format!(
[INFO] [stderr]      |  ____________________________^
[INFO] [stderr] 1064 | |                         "unknown type, first byte is `{}`",
[INFO] [stderr] 1065 | |                         first_byte as char
[INFO] [stderr] 1066 | |                     ))
[INFO] [stderr]      | |_____________________^
[INFO] [stderr]      |
[INFO] [stderr]      = note: this usage of panic!() is deprecated; it will be a hard error in Rust 2021
[INFO] [stderr]      = note: for more information, see <https://doc.rust-lang.org/nightly/edition-guide/rust-2021/panic-macro-consistency.html>
[INFO] [stderr]      = note: the panic!() macro supports formatting, so there's no need for the format!() macro here
[INFO] [stderr] help: remove the `format!(..)` macro call
[INFO] [stderr]      |
[INFO] [stderr] 1063 |                     panic!(
[INFO] [stderr] 1064 |                         "unknown type, first byte is `{}`",
[INFO] [stderr] 1065 |                         first_byte as char
[INFO] [stderr] 1066 |                     )
[INFO] [stderr]      |
[INFO] [stderr] 
[INFO] [stderr] warning: `exercises` (bin "redis_protocol" test) generated 2 warnings
[INFO] [stderr]     Finished test [unoptimized + debuginfo] target(s) in 1.59s
[INFO] [stderr]      Running unittests (/opt/rustwide/target/debug/deps/redis_protocol-2af6f70b68ade218)
[INFO] [stdout] 
[INFO] [stdout] running 12 tests
[INFO] [stdout] test client::test_request_ping_with_arg ... ok
[INFO] [stdout] test client::test_request_ping_without_arg ... ok
[INFO] [stdout] test deserialize::tests::test_deserialize_array_homogenous ... ok
[INFO] [stdout] test deserialize::tests::test_deserialize_bulk_string ... ok
[INFO] [stdout] test deserialize::tests::test_deserialize_error ... ok
[INFO] [stdout] test deserialize::tests::test_deserialize_integer ... ok
[INFO] [stdout] test deserialize::tests::test_deserialize_simple_string ... ok
[INFO] [stdout] test server::test_respond_ping_with_arg ... ok
[INFO] [stdout] test server::test_respond_ping_without_arg ... ok
[INFO] [stdout] test server::test_server_ping_with_argument ... ok
[INFO] [stdout] test server::test_server_shutdown ... ok
[INFO] [stdout] test server::test_server_ping_without_argument ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.11s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests (/opt/rustwide/target/debug/deps/kvs-e20d4bcec42e725d)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test protocol::response::tests::prop_ser_de_is_identical ... ok
[INFO] [stdout] test store::test_kvstore_impls ... ok
[INFO] [stdout] test store::index::tests::test_build_index ... ok
[INFO] [stdout] test store::command::tests::test_ser_de ... ok
[INFO] [stdout] test server::server::tests::test_can_be_shutdown ... ok
[INFO] [stdout] test protocol::request::tests::prop_ser_de_is_identical ... ok
[INFO] [stdout] test server::server::tests::test_handle_requests ... ok
[INFO] [stderr]      Running unittests (/opt/rustwide/target/debug/deps/kvs-b055c57978cee54a)
[INFO] [stdout] test store::compaction::tests::test_compact ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 8 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.03s
[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] [stderr]      Running unittests (/opt/rustwide/target/debug/deps/kvs_client-f9b1851b4f248891)
[INFO] [stdout] 
[INFO] [stderr]      Running unittests (/opt/rustwide/target/debug/deps/kvs_server-26f6c69d8afc1516)
[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] [stderr]      Running tests/cli.rs (/opt/rustwide/target/debug/deps/cli-41a3726fdac647b3)
[INFO] [stdout] 
[INFO] [stdout] running 11 tests
[INFO] [stdout] test cli_wrong_engine ... ignored
[INFO] [stderr] Aug 08 09:24:49.483 INFO starting, engine: kvs, address: 127.0.0.1:4004
[INFO] [stderr] Aug 08 09:24:49.485 INFO starting, engine: sled, address: 127.0.0.1:4005
[INFO] [stderr] Aug 08 09:24:49.485 DEBG binding TCP listener
[INFO] [stderr] Aug 08 09:24:49.485 DEBG creating signal eventfd
[INFO] [stderr] Aug 08 09:24:49.485 INFO start listening
[INFO] [stderr] Aug 08 09:24:49.485 DEBG epoll create
[INFO] [stderr] Aug 08 09:24:49.486 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:49.486 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stdout] test client_cli_invalid_subcommand ... ok
[INFO] [stdout] test client_cli_version ... ok
[INFO] [stdout] test client_cli_no_args ... ok
[INFO] [stdout] test server_cli_version ... ok
[INFO] [stdout] test client_cli_invalid_rm ... ok
[INFO] [stdout] test client_cli_invalid_get ... ok
[INFO] [stdout] test client_cli_invalid_set ... ok
[INFO] [stderr] Aug 08 09:24:49.677 DEBG binding TCP listener
[INFO] [stderr] Aug 08 09:24:49.677 DEBG creating signal eventfd
[INFO] [stderr] Aug 08 09:24:49.677 INFO start listening
[INFO] [stderr] Aug 08 09:24:49.677 DEBG epoll create
[INFO] [stderr] Aug 08 09:24:49.677 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:49.677 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stdout] test cli_log_configuration ... ok
[INFO] [stderr] Aug 08 09:24:50.485 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.485 INFO connected, peer: 127.0.0.1:51000, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.485 INFO received request, request: Set { key: "key1", value: "value1" }, peer: 127.0.0.1:51000, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.486 INFO sending response, response: Success(None), peer: 127.0.0.1:51000, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.486 DEBG received eof, peer: 127.0.0.1:51000, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.486 INFO closing connection, peer: 127.0.0.1:51000, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.487 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.487 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.487 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.487 INFO connected, peer: 127.0.0.1:57780, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.487 INFO received request, request: Set { key: "key1", value: "value1" }, peer: 127.0.0.1:57780, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.491 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.491 INFO connected, peer: 127.0.0.1:51004, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.491 INFO received request, request: Get { key: "key1" }, peer: 127.0.0.1:51004, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.492 DEBG GET request, peer: 127.0.0.1:51004, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.492 INFO sending response, response: Success(Some("value1")), peer: 127.0.0.1:51004, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.492 DEBG received eof, peer: 127.0.0.1:51004, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.492 INFO closing connection, peer: 127.0.0.1:51004, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.492 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.492 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.501 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.501 INFO connected, peer: 127.0.0.1:51006, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.501 INFO received request, request: Set { key: "key1", value: "value2" }, peer: 127.0.0.1:51006, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.502 INFO sending response, response: Success(None), peer: 127.0.0.1:51006, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.503 DEBG received eof, peer: 127.0.0.1:51006, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.503 INFO closing connection, peer: 127.0.0.1:51006, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.503 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.503 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.506 INFO sending response, response: Success(None), peer: 127.0.0.1:57780, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.506 DEBG received eof, peer: 127.0.0.1:57780, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.506 INFO closing connection, peer: 127.0.0.1:57780, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.506 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.506 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.512 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 INFO connected, peer: 127.0.0.1:51008, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 INFO received request, request: Get { key: "key1" }, peer: 127.0.0.1:51008, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 DEBG GET request, peer: 127.0.0.1:51008, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 INFO sending response, response: Success(Some("value2")), peer: 127.0.0.1:51008, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 DEBG received eof, peer: 127.0.0.1:51008, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 INFO closing connection, peer: 127.0.0.1:51008, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.513 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.514 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.514 INFO connected, peer: 127.0.0.1:57788, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.515 INFO received request, request: Get { key: "key1" }, peer: 127.0.0.1:57788, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.515 DEBG GET request, peer: 127.0.0.1:57788, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.515 INFO sending response, response: Success(Some("value1")), peer: 127.0.0.1:57788, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.515 DEBG received eof, peer: 127.0.0.1:57788, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.515 INFO closing connection, peer: 127.0.0.1:57788, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.515 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.515 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.517 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.517 INFO connected, peer: 127.0.0.1:51012, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.518 INFO received request, request: Get { key: "key2" }, peer: 127.0.0.1:51012, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.518 DEBG GET request, peer: 127.0.0.1:51012, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.518 INFO sending response, response: Success(None), peer: 127.0.0.1:51012, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.518 DEBG received eof, peer: 127.0.0.1:51012, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.518 INFO closing connection, peer: 127.0.0.1:51012, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.518 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.518 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.520 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.520 INFO connected, peer: 127.0.0.1:57792, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.520 INFO received request, request: Set { key: "key1", value: "value2" }, peer: 127.0.0.1:57792, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 INFO connected, peer: 127.0.0.1:51016, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 INFO received request, request: Rm { key: "key2" }, peer: 127.0.0.1:51016, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 DEBG entry not found, key: key2, peer: 127.0.0.1:51016, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 INFO sending response, response: Failure("Key not found"), peer: 127.0.0.1:51016, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 DEBG received eof, peer: 127.0.0.1:51016, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 INFO closing connection, peer: 127.0.0.1:51016, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.523 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.524 INFO sending response, response: Success(None), peer: 127.0.0.1:57792, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.525 DEBG received eof, peer: 127.0.0.1:57792, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.525 INFO closing connection, peer: 127.0.0.1:57792, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.525 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.525 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.529 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.530 INFO connected, peer: 127.0.0.1:51018, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.530 INFO received request, request: Set { key: "key2", value: "value3" }, peer: 127.0.0.1:51018, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.530 INFO sending response, response: Success(None), peer: 127.0.0.1:51018, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.531 DEBG received eof, peer: 127.0.0.1:51018, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.531 INFO closing connection, peer: 127.0.0.1:51018, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.531 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.531 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.539 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.539 INFO connected, peer: 127.0.0.1:57798, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.539 INFO received request, request: Get { key: "key1" }, peer: 127.0.0.1:57798, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.539 DEBG GET request, peer: 127.0.0.1:57798, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.539 INFO sending response, response: Success(Some("value2")), peer: 127.0.0.1:57798, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.539 DEBG received eof, peer: 127.0.0.1:57798, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.540 INFO closing connection, peer: 127.0.0.1:57798, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.540 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.540 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.556 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.556 INFO connected, peer: 127.0.0.1:51024, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.556 INFO received request, request: Rm { key: "key1" }, peer: 127.0.0.1:51024, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.556 DEBG entry removed, key: key1, peer: 127.0.0.1:51024, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.556 INFO sending response, response: Success(None), peer: 127.0.0.1:51024, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.564 DEBG received eof, peer: 127.0.0.1:51024, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.564 INFO closing connection, peer: 127.0.0.1:51024, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.564 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.564 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.566 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.566 INFO connected, peer: 127.0.0.1:57804, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.566 INFO received request, request: Get { key: "key2" }, peer: 127.0.0.1:57804, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.566 DEBG GET request, peer: 127.0.0.1:57804, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.566 INFO sending response, response: Success(None), peer: 127.0.0.1:57804, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.567 DEBG received eof, peer: 127.0.0.1:57804, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.567 INFO closing connection, peer: 127.0.0.1:57804, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.567 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.567 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.582 INFO starting, engine: sled, address: 127.0.0.1:4005
[INFO] [stderr] Aug 08 09:24:50.582 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 INFO connected, peer: 127.0.0.1:57806, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 INFO received request, request: Rm { key: "key2" }, peer: 127.0.0.1:57806, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 DEBG entry not found, key: key2, peer: 127.0.0.1:57806, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 INFO sending response, response: Failure("Key not found"), peer: 127.0.0.1:57806, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 DEBG received eof, peer: 127.0.0.1:57806, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 INFO closing connection, peer: 127.0.0.1:57806, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.583 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.588 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.589 INFO connected, peer: 127.0.0.1:57808, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.589 INFO received request, request: Set { key: "key2", value: "value3" }, peer: 127.0.0.1:57808, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.595 INFO sending response, response: Success(None), peer: 127.0.0.1:57808, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.595 DEBG received eof, peer: 127.0.0.1:57808, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.595 INFO closing connection, peer: 127.0.0.1:57808, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.595 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.595 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.601 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.601 INFO connected, peer: 127.0.0.1:57810, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.601 INFO received request, request: Rm { key: "key1" }, peer: 127.0.0.1:57810, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.601 DEBG entry removed, key: key1, peer: 127.0.0.1:57810, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.601 INFO sending response, response: Success(None), peer: 127.0.0.1:57810, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.601 DEBG received eof, peer: 127.0.0.1:57810, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.601 INFO closing connection, peer: 127.0.0.1:57810, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.602 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.602 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.611 INFO starting, engine: kvs, address: 127.0.0.1:4004
[INFO] [stderr] Aug 08 09:24:50.611 DEBG binding TCP listener
[INFO] [stderr] Aug 08 09:24:50.611 DEBG creating signal eventfd
[INFO] [stderr] Aug 08 09:24:50.611 INFO start listening
[INFO] [stderr] Aug 08 09:24:50.611 DEBG epoll create
[INFO] [stderr] Aug 08 09:24:50.611 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.611 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.887 DEBG binding TCP listener
[INFO] [stderr] Aug 08 09:24:50.887 DEBG creating signal eventfd
[INFO] [stderr] Aug 08 09:24:50.887 INFO start listening
[INFO] [stderr] Aug 08 09:24:50.888 DEBG epoll create
[INFO] [stderr] Aug 08 09:24:50.888 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:50.888 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.580 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.580 INFO connected, peer: 127.0.0.1:51038, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.580 INFO received request, request: Get { key: "key2" }, peer: 127.0.0.1:51038, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.580 DEBG GET request, peer: 127.0.0.1:51038, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.581 INFO sending response, response: Success(Some("value3")), peer: 127.0.0.1:51038, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.581 DEBG received eof, peer: 127.0.0.1:51038, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.581 INFO closing connection, peer: 127.0.0.1:51038, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.581 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.581 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.585 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.585 INFO connected, peer: 127.0.0.1:51040, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.585 INFO received request, request: Get { key: "key1" }, peer: 127.0.0.1:51040, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.585 DEBG GET request, peer: 127.0.0.1:51040, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.586 INFO sending response, response: Success(None), peer: 127.0.0.1:51040, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.586 DEBG received eof, peer: 127.0.0.1:51040, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.586 INFO closing connection, peer: 127.0.0.1:51040, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.586 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.586 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stdout] test cli_access_server_sled_engine ... ok
[INFO] [stderr] Aug 08 09:24:51.609 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.609 INFO connected, peer: 127.0.0.1:57820, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.609 INFO received request, request: Get { key: "key2" }, peer: 127.0.0.1:57820, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.609 DEBG GET request, peer: 127.0.0.1:57820, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.610 INFO sending response, response: Success(Some("value3")), peer: 127.0.0.1:57820, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.610 DEBG received eof, peer: 127.0.0.1:57820, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.610 INFO closing connection, peer: 127.0.0.1:57820, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.610 INFO waiting for incoming connection, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.610 DEBG epoll wait, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.614 DEBG incoming connection received, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.614 INFO connected, peer: 127.0.0.1:57822, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.614 INFO received request, request: Get { key: "key1" }, peer: 127.0.0.1:57822, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.614 DEBG GET request, peer: 127.0.0.1:57822, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stderr] Aug 08 09:24:51.614 INFO sending response, response: Success(None), peer: 127.0.0.1:57822, epoll_timeout: -1, epoll_maxevents: 2
[INFO] [stdout] test cli_access_server_kvs_engine ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 2.14s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/kv_store.rs (/opt/rustwide/target/debug/deps/kv_store-59171413350ecdae)
[INFO] [stdout] 
[INFO] [stdout] running 6 tests
[INFO] [stdout] test remove_non_existent_key ... ok
[INFO] [stdout] test get_non_existent_value ... ok
[INFO] [stdout] test remove_key ... ok
[INFO] [stdout] test get_stored_value ... ok
[INFO] [stdout] test overwrite_value ... ok
[INFO] [stdout] test compaction has been running for over 60 seconds
[INFO] [stdout] test compaction ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 6 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 201.86s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/tests.rs (/opt/rustwide/target/debug/deps/tests-cbe25ef66ce74408)
[INFO] [stdout] 
[INFO] [stdout] running 17 tests
[INFO] [stdout] test cli_get_non_existent_key ... ok
[INFO] [stdout] test cli_no_args ... ok
[INFO] [stdout] test cli_invalid_subcommand ... ok
[INFO] [stdout] test cli_rm_non_existent_key ... ok
[INFO] [stdout] test remove_non_existent_key ... ok
[INFO] [stdout] test cli_invalid_get ... ok
[INFO] [stdout] test cli_invalid_rm ... ok
[INFO] [stdout] test cli_version ... ok
[INFO] [stdout] test cli_get_stored ... ok
[INFO] [stdout] test cli_invalid_set ... ok
[INFO] [stdout] test cli_set ... ok
[INFO] [stdout] test remove_key ... ok
[INFO] [stdout] test get_non_existent_value ... ok
[INFO] [stdout] test get_stored_value ... ok
[INFO] [stdout] test cli_rm_stored ... ok
[INFO] [stdout] test overwrite_value ... ok
[INFO] [stdout] test compaction has been running for over 60 seconds
[ERROR] error running command: no output for 300 seconds
[INFO] running `Command { std: "docker" "inspect" "b8fc5c8b7afd3f91bf9e5d19e04e3720f28d6eaadf49a61206f711270ef797c2", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "b8fc5c8b7afd3f91bf9e5d19e04e3720f28d6eaadf49a61206f711270ef797c2", kill_on_drop: false }`
[INFO] [stdout] b8fc5c8b7afd3f91bf9e5d19e04e3720f28d6eaadf49a61206f711270ef797c2
