Nov 02 16:27:45.687 INFO testing graphannis-0.9.0 against beta-2018-10-30 for beta-1.31-1
Nov 02 16:27:45.689 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/beta-1.31-1/worker-0/beta-2018-10-30:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-0/beta-1.31-1/beta-2018-10-30:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +beta-2018-10-30 build --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 02 16:27:46.168 INFO blam! 55c2d5cd63c67047a80195f476cdc7fd8a70685733909e528fbd85e6d237a982
Nov 02 16:27:46.171 INFO running `"docker" "start" "-a" "55c2d5cd63c67047a80195f476cdc7fd8a70685733909e528fbd85e6d237a982"`
Nov 02 16:27:47.871 INFO kablam! usermod: no changes
Nov 02 16:27:48.257 INFO kablam!    Compiling graphannis-malloc_size_of v0.0.1
Nov 02 16:27:48.265 INFO kablam!    Compiling new_debug_unreachable v1.0.1
Nov 02 16:27:48.265 INFO kablam!    Compiling multimap v0.4.0
Nov 02 16:27:48.271 INFO kablam!    Compiling atty v0.1.2
Nov 02 16:27:48.271 INFO kablam!    Compiling strum_macros v0.10.0
Nov 02 16:27:48.271 INFO kablam!    Compiling graphannis-malloc_size_of_derive v0.0.1
Nov 02 16:27:51.129 INFO kablam!    Compiling string_cache v0.7.3
Nov 02 16:27:54.635 INFO kablam!    Compiling lalrpop-snap v0.15.2
Nov 02 16:29:04.889 INFO kablam!    Compiling lalrpop v0.15.2
Nov 02 16:29:52.483 INFO kablam!    Compiling graphannis v0.9.0 (/source)
Nov 02 16:30:31.075 INFO kablam!     Finished dev [unoptimized + debuginfo] target(s) in 2m 43s
Nov 02 16:30:31.082 INFO kablam! su: No module specific data is present
Nov 02 16:30:31.575 INFO running `"docker" "rm" "-f" "55c2d5cd63c67047a80195f476cdc7fd8a70685733909e528fbd85e6d237a982"`
Nov 02 16:30:31.740 INFO blam! 55c2d5cd63c67047a80195f476cdc7fd8a70685733909e528fbd85e6d237a982
Nov 02 16:30:31.742 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/beta-1.31-1/worker-0/beta-2018-10-30:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-0/beta-1.31-1/beta-2018-10-30:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +beta-2018-10-30 test --frozen --no-run" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 02 16:30:32.053 INFO blam! 98b4bf5614dbab83de50200e27d4666b833431bcfaa9964af35d7d1eb6904a77
Nov 02 16:30:32.058 INFO running `"docker" "start" "-a" "98b4bf5614dbab83de50200e27d4666b833431bcfaa9964af35d7d1eb6904a77"`
Nov 02 16:30:33.019 INFO kablam! usermod: no changes
Nov 02 16:30:33.339 INFO kablam!    Compiling graphannis v0.9.0 (/source)
Nov 02 16:31:00.289 INFO kablam!     Finished dev [unoptimized + debuginfo] target(s) in 27.23s
Nov 02 16:31:00.305 INFO kablam! su: No module specific data is present
Nov 02 16:31:00.888 INFO running `"docker" "rm" "-f" "98b4bf5614dbab83de50200e27d4666b833431bcfaa9964af35d7d1eb6904a77"`
Nov 02 16:31:01.065 INFO blam! 98b4bf5614dbab83de50200e27d4666b833431bcfaa9964af35d7d1eb6904a77
Nov 02 16:31:01.067 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/beta-1.31-1/worker-0/beta-2018-10-30:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-0/beta-1.31-1/beta-2018-10-30:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +beta-2018-10-30 test --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 02 16:31:01.263 INFO blam! dc918686e797f1ca0cb749b83510b830e1d2cfe722776360b998780ac8ef1b30
Nov 02 16:31:01.267 INFO running `"docker" "start" "-a" "dc918686e797f1ca0cb749b83510b830e1d2cfe722776360b998780ac8ef1b30"`
Nov 02 16:31:01.668 INFO kablam! usermod: no changes
Nov 02 16:31:01.919 INFO kablam!     Finished dev [unoptimized + debuginfo] target(s) in 0.23s
Nov 02 16:31:01.935 INFO kablam!      Running /target/debug/deps/graphannis-ef5c3ed6f0c4c6bb
Nov 02 16:31:01.940 INFO blam! 
Nov 02 16:31:01.941 INFO blam! running 10 tests
Nov 02 16:31:01.959 INFO blam! test graphdb::tests::create_writeable_gs ... ok
Nov 02 16:31:01.960 INFO blam! test annostorage::tests::get_all_for_node ... ok
Nov 02 16:31:01.960 INFO blam! test annostorage::tests::remove ... ok
Nov 02 16:31:01.961 INFO blam! test annostorage::tests::insert_same_anno ... ok
Nov 02 16:31:01.961 INFO blam! test stringstorage::tests::insert_and_get ... ok
Nov 02 16:31:01.961 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:321] applying event AddNode { node_name: "test", node_type: "node" }
Nov 02 16:31:01.961 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:526] memory updates completed
Nov 02 16:31:01.961 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:529] output location for persisting updates is "/tmp/annis_test.Mn9Zl5BiiVY1/testcorpus"
Nov 02 16:31:01.962 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:538] writing WAL update log to "/tmp/annis_test.Mn9Zl5BiiVY1/testcorpus/current/update_log.bin"
Nov 02 16:31:01.962 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 1
Nov 02 16:31:01.962 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.962 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 2 to stack with new size 1
Nov 02 16:31:01.962 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 3 to stack with new size 2
Nov 02 16:31:01.963 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 1
Nov 02 16:31:01.963 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 3
Nov 02 16:31:01.963 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.963 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 4 to stack with new size 2
Nov 02 16:31:01.963 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 5 to stack with new size 3
Nov 02 16:31:01.963 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 3
Nov 02 16:31:01.964 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 5
Nov 02 16:31:01.964 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.964 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 6 to stack with new size 3
Nov 02 16:31:01.964 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 7 to stack with new size 4
Nov 02 16:31:01.964 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 5
Nov 02 16:31:01.964 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 7
Nov 02 16:31:01.965 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.965 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 7
Nov 02 16:31:01.965 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 6
Nov 02 16:31:01.965 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 7 from path
Nov 02 16:31:01.965 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.965 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 6
Nov 02 16:31:01.965 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 4
Nov 02 16:31:01.966 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 5 from path
Nov 02 16:31:01.966 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 6 from path
Nov 02 16:31:01.966 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.966 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 4
Nov 02 16:31:01.966 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 2
Nov 02 16:31:01.966 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 3 from path
Nov 02 16:31:01.967 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 4 from path
Nov 02 16:31:01.967 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.967 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 4 to stack with new size 1
Nov 02 16:31:01.968 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 2
Nov 02 16:31:01.970 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 4
Nov 02 16:31:01.970 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.970 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 4
Nov 02 16:31:01.970 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 3
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 4 to stack with new size 1
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 5 to stack with new size 2
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 3
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 5
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 6 to stack with new size 2
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 7 to stack with new size 3
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 5
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 7
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 7
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:543] finished writing WAL update log
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1387] Waiting for background thread to finish (1 worker(s) left)...
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 6
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 7 from path
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 6
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 4
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 5 from path
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 6 from path
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 4
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 1
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 2 to stack with new size 1
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 3 to stack with new size 2
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 1
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 3
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 4 to stack with new size 2
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 5 to stack with new size 3
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 3
Nov 02 16:31:01.971 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 5
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 6 to stack with new size 3
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 7 to stack with new size 4
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 5
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 7
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 7
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 6
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 7 from path
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 6
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 4
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 5 from path
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 6 from path
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 4
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 2
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 3 from path
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:77] truncating 4 from path
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:109] adding 4 to stack with new size 1
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 2
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 4
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result true for node 4
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:72] enter node 7
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:92] removing from stack
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::dfs: [src/dfs.rs:113] enter_node finished with result false for node 7
Nov 02 16:31:01.972 INFO blam! test stringstorage::tests::serialization ... ok
Nov 02 16:31:01.972 INFO blam! test stringstorage::tests::insert_clear_insert_get ... ok
Nov 02 16:31:01.972 INFO blam! test graphstorage::adjacencylist::tests::simple_dag_find_all ... ok
Nov 02 16:31:01.972 INFO blam! 16:31:01 [INFO] Using cache with size 3353.85 MiB
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:515] applying updates
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:321] applying event AddNode { node_name: "test", node_type: "node" }
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:526] memory updates completed
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:529] output location for persisting updates is "/tmp/annis_test.slNirVMLt01a/testcorpus"
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:538] writing WAL update log to "/tmp/annis_test.slNirVMLt01a/testcorpus/current/update_log.bin"
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:543] finished writing WAL update log
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1387] Waiting for background thread to finish (1 worker(s) left)...
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1359] Starting background thread to sync WAL updates
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1366] Finished background thread to sync WAL updates
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1395] Unlocked CorpusStorage lock file
Nov 02 16:31:01.972 INFO blam! 16:31:01 [INFO] Using cache with size 3353.56 MiB
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:515] applying updates
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:321] applying event AddNode { node_name: "test", node_type: "node" }
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:526] memory updates completed
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:529] output location for persisting updates is "/tmp/annis_test.slNirVMLt01a/testcorpus"
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:538] writing WAL update log to "/tmp/annis_test.slNirVMLt01a/testcorpus/current/update_log.bin"
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::graphdb: [src/graphdb.rs:543] finished writing WAL update log
Nov 02 16:31:01.972 INFO blam! 16:31:01 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1387] Waiting for background thread to finish (1 worker(s) left)...
Nov 02 16:31:01.977 INFO blam! 16:31:01 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1359] Starting background thread to sync WAL updates
Nov 02 16:31:02.113 INFO kablam! 16:31:01 [ERROR] Can't sync changes in background thread: Error(IO(Os { code: 2, kind: NotFound, message: "No such file or directory" }), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
Nov 02 16:31:02.113 INFO kablam!    0:     0x559ad6abaa06 - backtrace::backtrace::libunwind::trace::hc561409b688814b6
Nov 02 16:31:02.113 INFO kablam!                         at /cargo-home/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.9/src/backtrace/libunwind.rs:53
Nov 02 16:31:02.114 INFO kablam!                          - backtrace::backtrace::trace::h8dba8a3e72707af9
Nov 02 16:31:02.116 INFO blam! 16:31:02 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1359] Starting background thread to sync WAL updates
Nov 02 16:31:02.116 INFO kablam!                         at /cargo-home/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.9/src/backtrace/mod.rs:42
Nov 02 16:31:02.116 INFO blam! 16:31:02 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1395] Unlocked CorpusStorage lock file
Nov 02 16:31:02.116 INFO kablam!    1:     0x559ad6ab50c3 - backtrace::capture::Backtrace::new_unresolved::h5b95b42aa0b46afa
Nov 02 16:31:02.116 INFO kablam!                         at /cargo-home/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.9/src/capture.rs:88
Nov 02 16:31:02.116 INFO kablam!    2:     0x559ad6ab3ca6 - error_chain::backtrace::imp::InternalBacktrace::new::h57017c541f65f711
Nov 02 16:31:02.116 INFO kablam!                         at /cargo-home/registry/src/github.com-1ecc6299db9ec823/error-chain-0.12.0/src/backtrace.rs:56
Nov 02 16:31:02.116 INFO kablam!    3:     0x559ad6ab2352 - <error_chain::State as core::default::Default>::default::hccb7667b59ce0e5a
Nov 02 16:31:02.116 INFO kablam!                         at /cargo-home/registry/src/github.com-1ecc6299db9ec823/error-chain-0.12.0/src/lib.rs:666
Nov 02 16:31:02.116 INFO kablam!    4:     0x559ad699676f - graphannis::errors::Error::from_kind::hb6d88ba0ca094441
Nov 02 16:31:02.116 INFO kablam!                         at /source/<::error_chain::error_chain::impl_error_chain_processed macros>:53
Nov 02 16:31:02.116 INFO kablam!    5:     0x559ad6996a9f - <graphannis::errors::Error as core::convert::From<std::io::error::Error>>::from::hb2a74890b1a0780b
Nov 02 16:31:02.116 INFO kablam!                         at src/errors.rs:5
Nov 02 16:31:02.116 INFO kablam!    6:     0x559ad69526c5 - graphannis::graphdb::GraphDB::background_sync_wal_updates::h901b8628dcf1ef39
Nov 02 16:31:02.116 INFO kablam!                         at src/graphdb.rs:570
Nov 02 16:31:02.116 INFO kablam!    7:     0x559ad66fa245 - graphannis::api::corpusstorage::CorpusStorage::apply_update::{{closure}}::h3ccd5ba08b1f03c7
Nov 02 16:31:02.116 INFO kablam!                         at src/api/corpusstorage.rs:1363
Nov 02 16:31:02.116 INFO kablam!    8:     0x559ad66e4eda - std::sys_common::backtrace::__rust_begin_short_backtrace::h45946f13789aacfe
Nov 02 16:31:02.116 INFO kablam!                         at libstd/sys_common/backtrace.rs:136
Nov 02 16:31:02.116 INFO kablam!    9:     0x559ad6919f8c - std::thread::Builder::spawn::{{closure}}::{{closure}}::hb5e73c72aa77e21e
Nov 02 16:31:02.116 INFO kablam!                         at libstd/thread/mod.rs:409
Nov 02 16:31:02.116 INFO kablam!   10:     0x559ad672ae1c - <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h6a1280333006d79b
Nov 02 16:31:02.116 INFO kablam!                         at libstd/panic.rs:313
Nov 02 16:31:02.116 INFO kablam!   11:     0x559ad6742d6f - std::panicking::try::do_call::hd9a4cbd5b783d0fc
Nov 02 16:31:02.116 INFO kablam!                         at libstd/panicking.rs:310
Nov 02 16:31:02.116 INFO kablam!   12:     0x559ad6b01989 - __rust_maybe_catch_panic
Nov 02 16:31:02.116 INFO kablam!                         at libpanic_unwind/lib.rs:102
Nov 02 16:31:02.116 INFO kablam!   13:     0x559ad6742c92 - std::panicking::try::h7d145b5d6f17ae38
Nov 02 16:31:02.116 INFO kablam!                         at libstd/panicking.rs:289
Nov 02 16:31:02.116 INFO kablam!   14:     0x559ad6742c1c - std::panic::catch_unwind::hcf8f02ea39b567f8
Nov 02 16:31:02.116 INFO kablam!                         at libstd/panic.rs:392
Nov 02 16:31:02.116 INFO kablam!   15:     0x559ad6919d90 - std::thread::Builder::spawn::{{closure}}::hae7bb809a6598a23
Nov 02 16:31:02.116 INFO kablam!                         at libstd/thread/mod.rs:408
Nov 02 16:31:02.116 INFO kablam!   16:     0x559ad69286a6 - <F as alloc::boxed::FnBox<A>>::call_box::hef67663349893e54
Nov 02 16:31:02.116 INFO kablam!                         at liballoc/boxed.rs:672
Nov 02 16:31:02.116 INFO kablam!   17:     0x559ad6aef22d - <alloc::boxed::Box<(dyn alloc::boxed::FnBox<A, Output=R> + 'a)> as core::ops::function::FnOnce<A>>::call_once::h2e69ee95a52cd9a2
Nov 02 16:31:02.116 INFO kablam!                         at liballoc/boxed.rs:682
Nov 02 16:31:02.116 INFO kablam!                          - std::sys_common::thread::start_thread::had0c80d121669d29
Nov 02 16:31:02.116 INFO kablam!                         at libstd/sys_common/thread.rs:24
Nov 02 16:31:02.116 INFO kablam!   18:     0x559ad6ae3915 - std::sys::unix::thread::Thread::new::thread_start::h4a5b66a70d76f47f
Nov 02 16:31:02.116 INFO kablam!                         at libstd/sys/unix/thread.rs:90
Nov 02 16:31:02.116 INFO kablam!   19:     0x7f01a1d1f6b9 - start_thread
Nov 02 16:31:02.116 INFO kablam!   20:     0x7f01a183f41c - clone
Nov 02 16:31:02.116 INFO kablam!   21:                0x0 - <unknown>) } })
Nov 02 16:31:02.117 INFO blam! 16:31:02 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1366] Finished background thread to sync WAL updates
Nov 02 16:31:02.127 INFO blam! test api::corpusstorage::tests::delete ... ok
Nov 02 16:31:02.127 INFO kablam!      Running /target/debug/deps/loadtest-1920e49e45f42d40
Nov 02 16:31:02.127 INFO blam! 16:31:02 [TRACE] graphannis::api::corpusstorage: [src/api/corpusstorage.rs:1395] Unlocked CorpusStorage lock file
Nov 02 16:31:02.127 INFO blam! test api::corpusstorage::tests::load_cs_twice ... ok
Nov 02 16:31:02.127 INFO blam! 
Nov 02 16:31:02.127 INFO blam! test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 02 16:31:02.127 INFO blam! 
Nov 02 16:31:02.127 INFO blam! 
Nov 02 16:31:02.127 INFO blam! running 7 tests
Nov 02 16:31:02.127 INFO blam! test count_annos ... ok
Nov 02 16:31:02.127 INFO blam! test edges ... ok
Nov 02 16:31:02.127 INFO blam! test parallel_index_join ... ok
Nov 02 16:31:02.127 INFO blam! test node_annos ... ok
Nov 02 16:31:02.127 INFO blam! test index_join ... ok
Nov 02 16:31:02.127 INFO blam! test parallel_nested_loop_join ... ok
Nov 02 16:31:02.127 INFO blam! test nested_loop_join ... ok
Nov 02 16:31:02.127 INFO blam! 
Nov 02 16:31:02.128 INFO blam! test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 02 16:31:02.128 INFO blam! 
Nov 02 16:31:02.131 INFO kablam!      Running /target/debug/deps/searchtest-301550c374d5dfaf
Nov 02 16:31:02.145 INFO blam! 
Nov 02 16:31:02.145 INFO blam! running 6 tests
Nov 02 16:31:02.145 INFO blam! test all_from_folder ... ignored
Nov 02 16:31:02.145 INFO blam! test count_gum ... ignored
Nov 02 16:31:02.145 INFO blam! test count_parlament ... ignored
Nov 02 16:31:02.145 INFO blam! test count_pcc2 ... ignored
Nov 02 16:31:02.145 INFO blam! test count_ridges ... ignored
Nov 02 16:31:02.145 INFO blam! test count_tiger ... ignored
Nov 02 16:31:02.145 INFO blam! 
Nov 02 16:31:02.145 INFO blam! test result: ok. 0 passed; 0 failed; 6 ignored; 0 measured; 0 filtered out
Nov 02 16:31:02.145 INFO blam! 
Nov 02 16:31:02.148 INFO kablam!      Running /target/debug/deps/searchtest_parallel-37e42e6693c220b5
Nov 02 16:31:02.159 INFO kablam!    Doc-tests graphannis
Nov 02 16:31:02.159 INFO blam! 
Nov 02 16:31:02.159 INFO blam! running 6 tests
Nov 02 16:31:02.159 INFO blam! test all_from_folder ... ignored
Nov 02 16:31:02.159 INFO blam! test count_gum ... ignored
Nov 02 16:31:02.159 INFO blam! test count_parlament ... ignored
Nov 02 16:31:02.159 INFO blam! test count_pcc2 ... ignored
Nov 02 16:31:02.159 INFO blam! test count_ridges ... ignored
Nov 02 16:31:02.159 INFO blam! test count_tiger ... ignored
Nov 02 16:31:02.159 INFO blam! 
Nov 02 16:31:02.159 INFO blam! test result: ok. 0 passed; 0 failed; 6 ignored; 0 measured; 0 filtered out
Nov 02 16:31:02.159 INFO blam! 
Nov 02 16:31:07.719 INFO blam! 
Nov 02 16:31:07.719 INFO blam! running 1 test
Nov 02 16:31:18.036 INFO blam! test src/util/mod.rs - util::extract_node_path (line 75) ... ok
Nov 02 16:31:18.036 INFO blam! 
Nov 02 16:31:18.036 INFO blam! test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 02 16:31:18.036 INFO blam! 
Nov 02 16:31:18.055 INFO kablam! su: No module specific data is present
Nov 02 16:31:18.403 INFO running `"docker" "rm" "-f" "dc918686e797f1ca0cb749b83510b830e1d2cfe722776360b998780ac8ef1b30"`
Nov 02 16:31:18.491 INFO blam! dc918686e797f1ca0cb749b83510b830e1d2cfe722776360b998780ac8ef1b30
