[INFO] fetching crate tracing 0.1.3...
[INFO] extracting crate tracing 0.1.3 into work/ex/beta-1.37-6/sources/1.36.0/reg/tracing/0.1.3
[INFO] extracting crate tracing 0.1.3 into work/ex/beta-1.37-6/sources/beta-2019-07-23/reg/tracing/0.1.3
[INFO] validating manifest of tracing-0.1.3 on toolchain 1.36.0
[INFO] running `"/mnt/big/crater/work/local/cargo-home/bin/cargo" "+1.36.0" "read-manifest" "--manifest-path" "Cargo.toml"`
[INFO] validating manifest of tracing-0.1.3 on toolchain beta-2019-07-23
[INFO] running `"/mnt/big/crater/work/local/cargo-home/bin/cargo" "+beta-2019-07-23" "read-manifest" "--manifest-path" "Cargo.toml"`
[INFO] started frobbing tracing-0.1.3
[INFO] finished frobbing tracing-0.1.3
[INFO] frobbed toml for tracing-0.1.3 written to work/ex/beta-1.37-6/sources/1.36.0/reg/tracing/0.1.3/Cargo.toml
[INFO] started frobbing tracing-0.1.3
[INFO] finished frobbing tracing-0.1.3
[INFO] frobbed toml for tracing-0.1.3 written to work/ex/beta-1.37-6/sources/beta-2019-07-23/reg/tracing/0.1.3/Cargo.toml
[INFO] running `"/mnt/big/crater/work/local/cargo-home/bin/cargo" "+1.36.0" "generate-lockfile" "--manifest-path" "Cargo.toml" "-Zno-index-update"`
[INFO] [stderr]     Blocking waiting for file lock on package cache lock
[INFO] running `"/mnt/big/crater/work/local/cargo-home/bin/cargo" "+beta-2019-07-23" "generate-lockfile" "--manifest-path" "Cargo.toml" "-Zno-index-update"`
[INFO] running `"/mnt/big/crater/work/local/cargo-home/bin/cargo" "+1.36.0" "fetch" "--locked" "--manifest-path" "Cargo.toml"`
[INFO] [stderr]     Blocking waiting for file lock on package cache lock
[INFO] running `"/mnt/big/crater/work/local/cargo-home/bin/cargo" "+beta-2019-07-23" "fetch" "--locked" "--manifest-path" "Cargo.toml"`
[INFO] testing tracing-0.1.3 against 1.36.0 for beta-1.37-6
[INFO] running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/beta-1.37-6/worker-2/1.36.0:/opt/crater/target:rw,Z" "-v" "/mnt/big/crater/work/ex/beta-1.37-6/sources/1.36.0/reg/tracing/0.1.3:/opt/crater/workdir:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/opt/crater/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/opt/crater/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/opt/crater/workdir" "-e" "MAP_USER_ID=1000" "-e" "CARGO_TARGET_DIR=/opt/crater/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/crater/cargo-home" "-e" "RUSTUP_HOME=/opt/crater/rustup-home" "-w" "/opt/crater/workdir" "-m" "1536M" "--network" "none" "rustops/crates-build-env" "/opt/crater/cargo-home/bin/cargo" "+1.36.0" "build" "--frozen"`
[INFO] [stdout] a268abb183ab25af3f19423cbdcbedbf0abcd50229a29091a1c7356d67c02c38
[INFO] running `"docker" "start" "-a" "a268abb183ab25af3f19423cbdcbedbf0abcd50229a29091a1c7356d67c02c38"`
[INFO] [stderr]    Compiling tracing-core v0.1.2
[INFO] [stderr]    Compiling tracing v0.1.3 (/opt/crater/workdir)
[INFO] [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 1.72s
[INFO] running `"docker" "inspect" "a268abb183ab25af3f19423cbdcbedbf0abcd50229a29091a1c7356d67c02c38"`
[INFO] running `"docker" "rm" "-f" "a268abb183ab25af3f19423cbdcbedbf0abcd50229a29091a1c7356d67c02c38"`
[INFO] [stdout] a268abb183ab25af3f19423cbdcbedbf0abcd50229a29091a1c7356d67c02c38
[INFO] running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/beta-1.37-6/worker-2/1.36.0:/opt/crater/target:rw,Z" "-v" "/mnt/big/crater/work/ex/beta-1.37-6/sources/1.36.0/reg/tracing/0.1.3:/opt/crater/workdir:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/opt/crater/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/opt/crater/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/opt/crater/workdir" "-e" "MAP_USER_ID=1000" "-e" "CARGO_TARGET_DIR=/opt/crater/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/crater/cargo-home" "-e" "RUSTUP_HOME=/opt/crater/rustup-home" "-w" "/opt/crater/workdir" "-m" "1536M" "--network" "none" "rustops/crates-build-env" "/opt/crater/cargo-home/bin/cargo" "+1.36.0" "test" "--frozen" "--no-run"`
[INFO] [stdout] 7daf730ced198e723336e7e67695f5d02be34fc3ba8f84db131e2ef650b25e80
[INFO] running `"docker" "start" "-a" "7daf730ced198e723336e7e67695f5d02be34fc3ba8f84db131e2ef650b25e80"`
[INFO] [stderr]    Compiling same-file v1.0.5
[INFO] [stderr]    Compiling either v1.5.2
[INFO] [stderr]    Compiling quick-error v1.2.2
[INFO] [stderr]    Compiling cast v0.2.2
[INFO] [stderr]    Compiling byteorder v1.3.2
[INFO] [stderr]    Compiling memchr v2.2.1
[INFO] [stderr]    Compiling clap v2.33.0
[INFO] [stderr]    Compiling crossbeam-deque v0.6.3
[INFO] [stderr]    Compiling humantime v1.2.0
[INFO] [stderr]    Compiling itertools v0.8.0
[INFO] [stderr]    Compiling regex-automata v0.1.8
[INFO] [stderr]    Compiling rand_xoshiro v0.1.0
[INFO] [stderr]    Compiling rayon-core v1.5.0
[INFO] [stderr]    Compiling walkdir v2.2.9
[INFO] [stderr]    Compiling csv-core v0.1.6
[INFO] [stderr]    Compiling bstr v0.2.6
[INFO] [stderr]    Compiling rayon v1.1.0
[INFO] [stderr]    Compiling csv v1.1.1
[INFO] [stderr]    Compiling criterion v0.2.11
[INFO] [stderr]    Compiling tracing v0.1.3 (/opt/crater/workdir)
[INFO] [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 43.92s
[INFO] running `"docker" "inspect" "7daf730ced198e723336e7e67695f5d02be34fc3ba8f84db131e2ef650b25e80"`
[INFO] running `"docker" "rm" "-f" "7daf730ced198e723336e7e67695f5d02be34fc3ba8f84db131e2ef650b25e80"`
[INFO] [stdout] 7daf730ced198e723336e7e67695f5d02be34fc3ba8f84db131e2ef650b25e80
[INFO] running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/beta-1.37-6/worker-2/1.36.0:/opt/crater/target:rw,Z" "-v" "/mnt/big/crater/work/ex/beta-1.37-6/sources/1.36.0/reg/tracing/0.1.3:/opt/crater/workdir:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/opt/crater/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/opt/crater/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/opt/crater/workdir" "-e" "MAP_USER_ID=1000" "-e" "CARGO_TARGET_DIR=/opt/crater/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/crater/cargo-home" "-e" "RUSTUP_HOME=/opt/crater/rustup-home" "-w" "/opt/crater/workdir" "-m" "1536M" "--network" "none" "rustops/crates-build-env" "/opt/crater/cargo-home/bin/cargo" "+1.36.0" "test" "--frozen"`
[INFO] [stdout] 86625e4724598ed84d33efd4bc2e832e8334be83e1c57019c86576005ef60909
[INFO] running `"docker" "start" "-a" "86625e4724598ed84d33efd4bc2e832e8334be83e1c57019c86576005ef60909"`
[INFO] [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 0.05s
[INFO] [stderr]      Running /opt/crater/target/debug/deps/tracing-0ab1bcf0a44048ac
[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
[INFO] [stdout] 
[INFO] [stderr]      Running /opt/crater/target/debug/deps/event-0438483196e270e0
[INFO] [stdout] 
[INFO] [stdout] running 12 tests
[INFO] [stdout] test event_without_message ... ok
[INFO] [stdout] test dotted_field_name ... ok
[INFO] [stdout] test event_with_message ... ok
[INFO] [stdout] test debug_shorthand ... ok
[INFO] [stdout] test explicit_child ... ok
[INFO] [stdout] test both_shorthands ... ok
[INFO] [stdout] test borrowed_field ... ok
[INFO] [stdout] test move_field_out_of_struct ... ok
[INFO] [stdout] test moved_field ... ok
[INFO] [stdout] test one_with_everything ... ok
[INFO] [stdout] test explicit_child_at_levels ... ok
[INFO] [stdout] test display_shorthand ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stderr]      Running /opt/crater/target/debug/deps/filter_caching_is_lexically_scoped-de872dcaf3e52254
[INFO] [stdout] 
[INFO] [stdout] running 1 test
[INFO] [stdout] test filter_caching_is_lexically_scoped ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stderr]      Running /opt/crater/target/debug/deps/filters_are_not_reevaluated_for_the_same_span-07d7827753277ed5
[INFO] [stdout] 
[INFO] [stdout] running 1 test
[INFO] [stdout] test filters_are_not_reevaluated_for_the_same_span ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stderr]      Running /opt/crater/target/debug/deps/filters_are_reevaluated_for_different_call_sites-64922ece4b124118
[INFO] [stdout] 
[INFO] [stderr]      Running /opt/crater/target/debug/deps/macro_imports-846bac9618595123
[INFO] [stdout] running 1 test
[INFO] [stdout] test filters_are_reevaluated_for_different_call_sites ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test prefixed_span_macros ... ok
[INFO] [stderr]      Running /opt/crater/target/debug/deps/macros-1a60b6dadc936688
[INFO] [stdout] test prefixed_event_macros ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 38 tests
[INFO] [stdout] test debug_span ... ok
[INFO] [stdout] test callsite_macro_api ... ok
[INFO] [stdout] test debug ... ok
[INFO] [stdout] test debug_span_with_parent ... ok
[INFO] [stdout] test debug_span_root ... ok
[INFO] [stdout] test debug_root ... ok
[INFO] [stdout] test debug_with_parent ... ok
[INFO] [stdout] test error_root ... ok
[INFO] [stdout] test error_span ... ok
[INFO] [stdout] test error_span_root ... ok
[INFO] [stdout] test field_shorthand_only ... ok
[INFO] [stdout] test error ... ok
[INFO] [stdout] test event_with_parent ... ok
[INFO] [stdout] test info ... ok
[INFO] [stdout] test info_root ... ok
[INFO] [stdout] test error_span_with_parent ... ok
[INFO] [stdout] test info_span ... ok
[INFO] [stdout] test info_span_root ... ok
[INFO] [stdout] test span ... ok
[INFO] [stdout] test info_span_with_parent ... ok
[INFO] [stdout] test info_with_parent ... ok
[INFO] [stdout] test trace_span ... ok
[INFO] [stdout] test trace_root ... ok
[INFO] [stdout] test trace ... ok
[INFO] [stdout] test span_with_parent ... ok
[INFO] [stdout] test trace_span_root ... ok
[INFO] [stdout] test trace_span_with_parent ... ok
[INFO] [stdout] test trace_with_parent ... ok
[INFO] [stdout] test event ... ok
[INFO] [stdout] test event_root ... ok
[INFO] [stdout] test error_with_parent ... ok
[INFO] [stdout] test warn_span_root ... ok
[INFO] [stdout] test warn_span_with_parent ... ok
[INFO] [stdout] test warn_span ... ok
[INFO] [stdout] test span_root ... ok
[INFO] [stdout] test warn_with_parent ... ok
[INFO] [stdout] test warn ... ok
[INFO] [stdout] test warn_root ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 38 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stderr]      Running /opt/crater/target/debug/deps/span-00df7d436be2aa76
[INFO] [stdout] 
[INFO] [stdout] running 31 tests
[INFO] [stdout] test cloning_a_span_calls_clone_span ... ok
[INFO] [stdout] test both_shorthands ... ok
[INFO] [stdout] test clone_and_drop_span_always_go_to_the_subscriber_that_tagged_the_span ... ok
[INFO] [stdout] test borrowed_field ... ok
[INFO] [stdout] test dotted_field_name ... ok
[INFO] [stdout] test debug_shorthand ... ok
[INFO] [stdout] test drop_span_when_exiting_dispatchers_context ... ok
[INFO] [stdout] test display_shorthand ... ok
[INFO] [stdout] test dropping_a_span_calls_drop_span ... ok
[INFO] [stdout] test contextual_root ... ok
[INFO] [stdout] test explicit_child_at_levels ... ok
[INFO] [stdout] test enter ... ok
[INFO] [stdout] test contextual_child ... ok
[INFO] [stdout] test event_outside_of_span ... ok
[INFO] [stdout] test explicit_root_span_is_root ... ok
[INFO] [stdout] test explicit_child_regardless_of_ctx ... ok
[INFO] [stdout] test explicit_child ... ok
[INFO] [stdout] test handles_to_different_spans_are_not_equal ... ok
[INFO] [stdout] test moved_field ... ok
[INFO] [stdout] test new_span_after_event ... ok
[INFO] [stdout] test new_span_with_target_and_log_level ... ok
[INFO] [stdout] test record_new_value_for_field ... ok
[INFO] [stdout] test span_closes_after_event ... ok
[INFO] [stdout] enter: foo; id=Id(1);
[INFO] [stdout] exit: foo; id=Id(1);
[INFO] [stdout] drop_span: foo; id=Id(1); refs=1;
[INFO] [stdout] test spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads ... ok
[INFO] [stdout] test spans_always_go_to_the_subscriber_that_tagged_them ... ok
[INFO] [stdout] test handles_to_the_same_span_are_equal ... ok
[INFO] [stdout] test move_field_out_of_struct ... ok
[INFO] [stdout] test handles_to_different_spans_with_the_same_metadata_are_not_equal ... ok
[INFO] [stdout] test record_new_values_for_fields ... ok
[INFO] [stdout] test span_closes_when_exited ... ok
[INFO] [stdout] test explicit_root_span_is_root_regardless_of_ctx ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 31 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stderr]      Running /opt/crater/target/debug/deps/subscriber-8609f2978c5a1390
[INFO] [stdout] 
[INFO] [stdout] running 1 test
[INFO] [stdout] test event_macros_dont_infinite_loop ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests tracing
[INFO] [stdout] 
[INFO] [stdout] running 56 tests
[INFO] [stdout] test src/lib.rs -  (line 126) ... ok
[INFO] [stdout] test src/lib.rs -  (line 136) ... ok
[INFO] [stdout] test src/lib.rs -  (line 233) ... ok
[INFO] [stdout] test src/lib.rs -  (line 270) ... ok
[INFO] [stdout] test src/lib.rs -  (line 176) ... ok
[INFO] [stdout] test src/lib.rs -  (line 42) ... ok
[INFO] [stdout] test src/lib.rs -  (line 158) ... ok
[INFO] [stdout] test src/lib.rs -  (line 70) ... ok
[INFO] [stdout] test src/macros.rs - debug (line 1268) ... ok
[INFO] [stdout] test src/macros.rs - debug_span (line 452) ... ok
[INFO] [stdout] test src/macros.rs - error_span (line 688) ... ok
[INFO] [stdout] test src/macros.rs - debug_span (line 462) ... ok
[INFO] [stdout] test src/macros.rs - error_span (line 698) ... ok
[INFO] [stdout] test src/macros.rs - error (line 1879) ... ok
[INFO] [stdout] test src/macros.rs - event (line 796) ... ok
[INFO] [stdout] test src/macros.rs - event (line 760) ... ok
[INFO] [stdout] test src/macros.rs - event (line 815) ... ok
[INFO] [stdout] test src/macros.rs - event (line 833) ... ok
[INFO] [stdout] test src/macros.rs - info_span (line 531) ... ok
[INFO] [stdout] test src/macros.rs - info_span (line 541) ... ok
[INFO] [stdout] test src/macros.rs - info (line 1468) ... ok
[INFO] [stdout] test src/macros.rs - span (line 101) ... ok
[INFO] [stdout] test src/macros.rs - span (line 166) ... ok
[INFO] [stdout] test src/macros.rs - span (line 124) ... ok
[INFO] [stdout] test src/macros.rs - span (line 146) ... ok
[INFO] [stdout] test src/macros.rs - span (line 200) ... ok
[INFO] [stdout] test src/macros.rs - span (line 189) ... ok
[INFO] [stdout] test src/macros.rs - span (line 219) ... ok
[INFO] [stdout] test src/macros.rs - span (line 22) ... ok
[INFO] [stdout] test src/macros.rs - span (line 34) ... ok
[INFO] [stdout] test src/macros.rs - span (line 234) ... ok
[INFO] [stdout] test src/macros.rs - span (line 7) ... ok
[INFO] [stdout] test src/macros.rs - span (line 66) ... ok
[INFO] [stdout] test src/macros.rs - event (line 787) ... ok
[INFO] [stdout] test src/macros.rs - span (line 51) ... ok
[INFO] [stdout] test src/macros.rs - trace (line 1069) ... ok
[INFO] [stdout] test src/macros.rs - trace_span (line 373) ... ok
[INFO] [stdout] test src/macros.rs - trace_span (line 383) ... ok
[INFO] [stdout] test src/macros.rs - span (line 80) ... ok
[INFO] [stdout] test src/span.rs - span (line 196) ... ok
[INFO] [stdout] test src/macros.rs - warn_span (line 610) ... ok
[INFO] [stdout] test src/span.rs - span (line 126) ... ok
[INFO] [stdout] test src/macros.rs - warn_span (line 620) ... ok
[INFO] [stdout] test src/span.rs - span (line 238) ... ok
[INFO] [stdout] test src/macros.rs - warn (line 1675) ... ok
[INFO] [stdout] test src/span.rs - span (line 150) ... ok
[INFO] [stdout] test src/span.rs - span (line 275) ... ok
[INFO] [stdout] test src/span.rs - span (line 290) ... ok
[INFO] [stdout] test src/span.rs - span (line 32) ... ok
[INFO] [stdout] test src/span.rs - span::Span::enter (line 539) ... ok
[INFO] [stdout] test src/span.rs - span (line 93) ... ok
[INFO] [stdout] test src/span.rs - span::Span::enter (line 521) ... ok
[INFO] [stdout] test src/span.rs - span::Span::in_scope (line 611) ... ok
[INFO] [stdout] test src/span.rs - span::Span::enter (line 563) ... ok
[INFO] [stdout] test src/span.rs - span (line 73) ... ok
[INFO] [stdout] test src/span.rs - span::Span::in_scope (line 628) ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 56 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
[INFO] [stdout] 
[INFO] running `"docker" "inspect" "86625e4724598ed84d33efd4bc2e832e8334be83e1c57019c86576005ef60909"`
[INFO] running `"docker" "rm" "-f" "86625e4724598ed84d33efd4bc2e832e8334be83e1c57019c86576005ef60909"`
[INFO] [stdout] 86625e4724598ed84d33efd4bc2e832e8334be83e1c57019c86576005ef60909