Nov 18 16:16:30.167 INFO testing desync-0.2.3 against try#2e026d6e5d7621634147ad4c8074f1d964dbb1be for pr-55982
Nov 18 16:16:30.167 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-55982/worker-6/try#2e026d6e5d7621634147ad4c8074f1d964dbb1be:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-6/pr-55982/try#2e026d6e5d7621634147ad4c8074f1d964dbb1be:/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 +2e026d6e5d7621634147ad4c8074f1d964dbb1be-alt build --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 18 16:16:30.439 INFO [stdout] 89b1d9630d916027628e72eb81e9b2b9c89134b322b1336c9515700bf247ff87
Nov 18 16:16:30.443 INFO running `"docker" "start" "-a" "89b1d9630d916027628e72eb81e9b2b9c89134b322b1336c9515700bf247ff87"`
Nov 18 16:16:30.934 INFO [stderr] usermod: no changes
Nov 18 16:16:30.980 INFO [stderr]    Compiling desync v0.2.3 (/source)
Nov 18 16:16:32.843 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 1.89s
Nov 18 16:16:32.847 INFO [stderr] su: No module specific data is present
Nov 18 16:16:33.285 INFO running `"docker" "inspect" "89b1d9630d916027628e72eb81e9b2b9c89134b322b1336c9515700bf247ff87"`
Nov 18 16:16:33.458 INFO running `"docker" "rm" "-f" "89b1d9630d916027628e72eb81e9b2b9c89134b322b1336c9515700bf247ff87"`
Nov 18 16:16:33.641 INFO [stdout] 89b1d9630d916027628e72eb81e9b2b9c89134b322b1336c9515700bf247ff87
Nov 18 16:16:33.647 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-55982/worker-6/try#2e026d6e5d7621634147ad4c8074f1d964dbb1be:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-6/pr-55982/try#2e026d6e5d7621634147ad4c8074f1d964dbb1be:/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 +2e026d6e5d7621634147ad4c8074f1d964dbb1be-alt test --frozen --no-run" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 18 16:16:34.090 INFO [stdout] 5dbb3dd0f2953d5089c4da4dae8bc8fd067503ff772e819dcdcf03c9e231eb91
Nov 18 16:16:34.099 INFO running `"docker" "start" "-a" "5dbb3dd0f2953d5089c4da4dae8bc8fd067503ff772e819dcdcf03c9e231eb91"`
Nov 18 16:16:35.092 INFO [stderr] usermod: no changes
Nov 18 16:16:35.175 INFO [stderr]    Compiling desync v0.2.3 (/source)
Nov 18 16:16:48.001 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 12.88s
Nov 18 16:16:48.006 INFO [stderr] su: No module specific data is present
Nov 18 16:16:48.425 INFO running `"docker" "inspect" "5dbb3dd0f2953d5089c4da4dae8bc8fd067503ff772e819dcdcf03c9e231eb91"`
Nov 18 16:16:48.565 INFO running `"docker" "rm" "-f" "5dbb3dd0f2953d5089c4da4dae8bc8fd067503ff772e819dcdcf03c9e231eb91"`
Nov 18 16:16:48.755 INFO [stdout] 5dbb3dd0f2953d5089c4da4dae8bc8fd067503ff772e819dcdcf03c9e231eb91
Nov 18 16:16:48.759 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-55982/worker-6/try#2e026d6e5d7621634147ad4c8074f1d964dbb1be:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-6/pr-55982/try#2e026d6e5d7621634147ad4c8074f1d964dbb1be:/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 +2e026d6e5d7621634147ad4c8074f1d964dbb1be-alt test --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 18 16:16:49.001 INFO [stdout] e61e7d5a5d94f38e7e8906243dbc76f36fc4e08840cf39cb9dffc368acbd9cc9
Nov 18 16:16:49.003 INFO running `"docker" "start" "-a" "e61e7d5a5d94f38e7e8906243dbc76f36fc4e08840cf39cb9dffc368acbd9cc9"`
Nov 18 16:16:49.549 INFO [stderr] usermod: no changes
Nov 18 16:16:49.576 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 0.01s
Nov 18 16:16:49.577 INFO [stderr]      Running /target/debug/deps/desync-38f26bb9f58e5916
Nov 18 16:16:49.579 INFO [stdout] 
Nov 18 16:16:49.581 INFO [stdout] running 0 tests
Nov 18 16:16:49.581 INFO [stdout] 
Nov 18 16:16:49.581 INFO [stdout] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 18 16:16:49.581 INFO [stdout] 
Nov 18 16:16:49.581 INFO [stderr]      Running /target/debug/deps/desync-42450a2dbc598297
Nov 18 16:16:49.584 INFO [stdout] 
Nov 18 16:16:49.584 INFO [stdout] running 27 tests
Nov 18 16:16:49.588 INFO [stdout] test retrieve_data_synchronously ... ok
Nov 18 16:16:49.588 INFO [stdout] test retrieve_data_into_local_var ... ok
Nov 18 16:16:49.596 INFO [stdout] test scheduler::async::schedule_async ... ok
Nov 18 16:16:49.599 INFO [stdout] test scheduler::async::schedule_after_queue_released ... ok
Nov 18 16:16:49.703 INFO [stdout] test scheduler::async::will_schedule_separate_queues_in_parallel ... ok
Nov 18 16:16:49.711 INFO [stdout] test scheduler::future::wait_for_future ... ok
Nov 18 16:16:49.711 INFO [stdout] test scheduler::async::will_schedule_in_order ... ok
Nov 18 16:16:49.723 INFO [stdout] test scheduler::suspend::safe_to_drop_suspended_queue ... ok
Nov 18 16:16:49.727 INFO [stdout] test scheduler::future::future_waits_for_us ... ok
Nov 18 16:16:49.727 INFO [stdout] test scheduler::future::schedule_future ... ok
Nov 18 16:16:49.727 INFO [stdout] test scheduler::sync::schedule_sync ... ok
Nov 18 16:16:49.727 INFO [stdout] test scheduler::sync::reschedule_after_immediate_sync ... ok
Nov 18 16:16:49.791 INFO [stdout] test dropping_while_running_isnt_obviously_bad ... ok
Nov 18 16:16:49.792 INFO [stdout] test scheduler::sync::sync_has_synchronous_lifetime ... ok
Nov 18 16:16:49.831 INFO [stdout] test scheduler::sync::schedule_sync_after_async ... ok
Nov 18 16:16:49.834 INFO [stdout] test scheduler::sync::sync_drains_with_no_threads ... ok
Nov 18 16:16:49.835 INFO [stdout] test scheduler::suspend::suspend_queue_with_local_drain ... ok
Nov 18 16:16:49.836 INFO [stderr] thread 'desync jobs thread' panicked at 'assertion failed: core.state == QueueState::Running', src/scheduler.rs:179:13
Nov 18 16:16:49.836 INFO [stderr] stack backtrace:
Nov 18 16:16:49.867 INFO [stdout] test scheduler::thread_management::will_despawn_extra_threads ... ok
Nov 18 16:16:49.871 INFO [stderr]    0:     0x5653bac535a3 - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::h26df0f6fdb27c709
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
Nov 18 16:16:49.891 INFO [stderr]    1:     0x5653bac4ddf8 - std::sys_common::backtrace::_print::h84c40fecda6d638e
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/sys_common/backtrace.rs:71
Nov 18 16:16:49.891 INFO [stderr]    2:     0x5653bac52514 - std::panicking::default_hook::{{closure}}::h77e370c0567fc0a7
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/sys_common/backtrace.rs:59
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/panicking.rs:211
Nov 18 16:16:49.891 INFO [stderr]    3:     0x5653bac5227d - std::panicking::default_hook::hb9a45c11a33bbcb2
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/panicking.rs:227
Nov 18 16:16:49.891 INFO [stderr]    4:     0x5653bac52c20 - std::panicking::rust_panic_with_hook::ha8d95048d940f754
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/panicking.rs:476
Nov 18 16:16:49.891 INFO [stderr]    5:     0x5653bac32487 - std::panicking::begin_panic::h04ab197dc1f674c9
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/panicking.rs:410
Nov 18 16:16:49.891 INFO [stderr]    6:     0x5653bac1782f - desync::scheduler::JobQueue::dequeue::hbac7d4b642b5e3a0
Nov 18 16:16:49.891 INFO [stderr]                                at src/scheduler.rs:179
Nov 18 16:16:49.891 INFO [stderr]    7:     0x5653bac179cc - desync::scheduler::JobQueue::drain::h3ea16388e7cd9b7c
Nov 18 16:16:49.891 INFO [stderr]                                at src/scheduler.rs:193
Nov 18 16:16:49.891 INFO [stderr]    8:     0x5653bac1940a - desync::scheduler::Scheduler::schedule_thread::{{closure}}::h6b34359c64a70f6b
Nov 18 16:16:49.891 INFO [stderr]                                at src/scheduler.rs:381
Nov 18 16:16:49.891 INFO [stderr]    9:     0x5653bac18ef0 - desync::scheduler::Scheduler::schedule_dormant::{{closure}}::h49dee250d4729fe6
Nov 18 16:16:49.891 INFO [stderr]                                at src/scheduler.rs:338
Nov 18 16:16:49.891 INFO [stderr]   10:     0x5653bac0e5cc - <desync::job::Job<TFn> as desync::job::ScheduledJob>::run::h59ca97230a830b84
Nov 18 16:16:49.891 INFO [stderr]                                at src/job.rs:31
Nov 18 16:16:49.891 INFO [stderr]   11:     0x5653bac0eb40 - desync::scheduler_thread::SchedulerThread::new::{{closure}}::hfa3172cbea70e5da
Nov 18 16:16:49.891 INFO [stderr]                                at src/scheduler_thread.rs:28
Nov 18 16:16:49.891 INFO [stderr]   12:     0x5653bac0daea - std::sys_common::backtrace::__rust_begin_short_backtrace::hf61678d3718038db
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/sys_common/backtrace.rs:136
Nov 18 16:16:49.891 INFO [stderr]   13:     0x5653bac0a72d - std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}::h1717fac45744c12e
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/thread/mod.rs:477
Nov 18 16:16:49.891 INFO [stderr]   14:     0x5653bac0da0d - <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h08f55bf7fb894606
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/panic.rs:319
Nov 18 16:16:49.891 INFO [stderr]   15:     0x5653bac0dcc4 - std::panicking::try::do_call::h405b4ded8a39a79d
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/panicking.rs:310
Nov 18 16:16:49.891 INFO [stderr]   16:     0x5653bac614e9 - __rust_maybe_catch_panic
Nov 18 16:16:49.891 INFO [stderr]                                at libpanic_unwind/lib.rs:102
Nov 18 16:16:49.891 INFO [stderr]   17:     0x5653bac0dbe5 - std::panicking::try::h5a98bc3c379b7db7
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/panicking.rs:289
Nov 18 16:16:49.891 INFO [stderr]   18:     0x5653bac0db6d - std::panic::catch_unwind::h6f15fb815399b731
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/panic.rs:398
Nov 18 16:16:49.891 INFO [stderr]   19:     0x5653bac0a524 - std::thread::Builder::spawn_unchecked::{{closure}}::hc91308aba76475f1
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/libstd/thread/mod.rs:476
Nov 18 16:16:49.891 INFO [stderr]   20:     0x5653bac0c5c9 - <F as alloc::boxed::FnBox<A>>::call_box::hda69c564b722b303
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/liballoc/boxed.rs:673
Nov 18 16:16:49.891 INFO [stderr]   21:     0x5653bac5532d - std::sys::unix::thread::Thread::new::thread_start::h8526625243d2f13b
Nov 18 16:16:49.891 INFO [stderr]                                at /rustc/2e026d6e5d7621634147ad4c8074f1d964dbb1be/src/liballoc/boxed.rs:683
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/sys_common/thread.rs:24
Nov 18 16:16:49.891 INFO [stderr]                                at libstd/sys/unix/thread.rs:90
Nov 18 16:16:49.891 INFO [stderr]   22:     0x7fe9cc2c76b9 - start_thread
Nov 18 16:16:49.891 INFO [stderr]   23:     0x7fe9cbde741c - clone
Nov 18 16:16:49.891 INFO [stderr]   24:                0x0 - <unknown>
Nov 18 16:16:49.935 INFO [stdout] test update_data_asynchronously ... ok
Nov 18 16:16:49.938 INFO [stdout] test update_data_with_future ... ok
Nov 18 16:16:50.036 INFO [stdout] test wait_for_future ... ok
Nov 18 16:16:52.320 INFO [stdout] test update_data_asynchronously_1000_times ... ok
Nov 18 16:16:52.485 INFO [stdout] test update_data_with_future_1000_times ... ok
Nov 18 16:16:52.494 INFO [stdout] test scheduler::async::async_only_runs_once ... ok
Nov 18 16:16:52.647 INFO [stdout] test scheduler::async::async_runs_in_order_1000_iter ... ok
Nov 18 16:16:52.704 INFO [stdout] test scheduler::suspend::resume_before_suspend ... ok
Nov 18 16:16:53.695 INFO [stdout] test scheduler::suspend::suspend_queue ... ok
Nov 18 16:16:53.695 INFO [stdout] 
Nov 18 16:16:53.695 INFO [stdout] test result: ok. 27 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 18 16:16:53.695 INFO [stdout] 
Nov 18 16:16:53.701 INFO [stderr]      Running /target/debug/deps/pipe-e40d1eb3d494a6e9
Nov 18 16:16:53.704 INFO [stdout] 
Nov 18 16:16:53.704 INFO [stdout] running 5 tests
Nov 18 16:16:53.724 INFO [stdout] test pipe_through_stream_closes ... ok
Nov 18 16:16:53.724 INFO [stdout] test pipe_through ... ok
Nov 18 16:16:53.735 INFO [stdout] test pipe_in_simple_stream ... ok
Nov 18 16:16:53.736 INFO [stdout] test pipe_in_mpsc_receiver ... ok
Nov 18 16:16:53.751 INFO [stdout] test pipe_through_produces_backpressure ... ok
Nov 18 16:16:53.752 INFO [stdout] 
Nov 18 16:16:53.752 INFO [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 18 16:16:53.752 INFO [stdout] 
Nov 18 16:16:53.754 INFO [stderr]    Doc-tests desync
Nov 18 16:16:54.703 INFO [stdout] 
Nov 18 16:16:54.703 INFO [stdout] running 9 tests
Nov 18 16:17:01.051 INFO [stdout] test src/lib.rs -  (line 60) ... ok
Nov 18 16:17:02.591 INFO [stdout] test src/lib.rs -  (line 37) ... ok
Nov 18 16:17:03.291 INFO [stdout] test src/scheduler.rs - scheduler (line 33) ... ok
Nov 18 16:17:03.987 INFO [stdout] test src/pipe.rs - pipe::pipe (line 164) ... ok
Nov 18 16:17:04.209 INFO [stdout] test src/lib.rs -  (line 11) ... ok
Nov 18 16:17:04.435 INFO [stdout] test src/scheduler.rs - scheduler (line 19) ... ok
Nov 18 16:17:05.111 INFO [stdout] test src/pipe.rs - pipe (line 20) ... ok
Nov 18 16:17:05.139 INFO [stdout] test src/lib.rs -  (line 20) ... ok
Nov 18 16:17:05.828 INFO [stdout] test src/scheduler.rs - scheduler (line 9) ... ok
Nov 18 16:17:05.828 INFO [stdout] 
Nov 18 16:17:05.828 INFO [stdout] test result: ok. 9 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 18 16:17:05.828 INFO [stdout] 
Nov 18 16:17:05.854 INFO [stderr] su: No module specific data is present
Nov 18 16:17:06.192 INFO running `"docker" "inspect" "e61e7d5a5d94f38e7e8906243dbc76f36fc4e08840cf39cb9dffc368acbd9cc9"`
Nov 18 16:17:06.337 INFO running `"docker" "rm" "-f" "e61e7d5a5d94f38e7e8906243dbc76f36fc4e08840cf39cb9dffc368acbd9cc9"`
Nov 18 16:17:06.481 INFO [stdout] e61e7d5a5d94f38e7e8906243dbc76f36fc4e08840cf39cb9dffc368acbd9cc9