[INFO] fetching crate timer-lib 0.4.0...
[INFO] testing timer-lib-0.4.0 against master#562dee4820c458d823175268e41601d4c060588a for pr-154210-2
[INFO] extracting crate timer-lib 0.4.0 into /workspace/builds/worker-4-tc1/source
[INFO] started tweaking crates.io crate timer-lib 0.4.0
[INFO] removed 0 missing examples
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate timer-lib 0.4.0
[INFO] tweaked toml for crates.io crate timer-lib 0.4.0 written to /workspace/builds/worker-4-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate timer-lib 0.4.0 on toolchain 562dee4820c458d823175268e41601d4c060588a
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+562dee4820c458d823175268e41601d4c060588a" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate crates.io crate timer-lib 0.4.0 already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+562dee4820c458d823175268e41601d4c060588a" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded tokio v1.43.1
[INFO] [stderr]   Downloaded syn v2.0.89
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+562dee4820c458d823175268e41601d4c060588a" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 7953ae04e158bf34d30774a47ac2241e93e47757e6a6f63bf0c7630d65aaf4c0
[INFO] running `Command { std: "docker" "start" "-a" "7953ae04e158bf34d30774a47ac2241e93e47757e6a6f63bf0c7630d65aaf4c0", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "7953ae04e158bf34d30774a47ac2241e93e47757e6a6f63bf0c7630d65aaf4c0", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "7953ae04e158bf34d30774a47ac2241e93e47757e6a6f63bf0c7630d65aaf4c0", kill_on_drop: false }`
[INFO] [stdout] 7953ae04e158bf34d30774a47ac2241e93e47757e6a6f63bf0c7630d65aaf4c0
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+562dee4820c458d823175268e41601d4c060588a" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 5131196e51cd6731fb0effe7f6f903e236d6c13008607763f7f3b5a900a03bc6
[INFO] running `Command { std: "docker" "start" "-a" "5131196e51cd6731fb0effe7f6f903e236d6c13008607763f7f3b5a900a03bc6", kill_on_drop: false }`
[INFO] [stderr]    Compiling pin-project-lite v0.2.15
[INFO] [stderr]    Compiling syn v2.0.89
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling async-trait v0.1.83
[INFO] [stderr]    Compiling tokio v1.43.1
[INFO] [stderr]    Compiling timer-lib v0.4.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 10.41s
[INFO] running `Command { std: "docker" "inspect" "5131196e51cd6731fb0effe7f6f903e236d6c13008607763f7f3b5a900a03bc6", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "5131196e51cd6731fb0effe7f6f903e236d6c13008607763f7f3b5a900a03bc6", kill_on_drop: false }`
[INFO] [stdout] 5131196e51cd6731fb0effe7f6f903e236d6c13008607763f7f3b5a900a03bc6
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+562dee4820c458d823175268e41601d4c060588a" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] fa417f15d0dd6d1746ecdd7e13be3e998720305590eaac624fd9f6954269838e
[INFO] running `Command { std: "docker" "start" "-a" "fa417f15d0dd6d1746ecdd7e13be3e998720305590eaac624fd9f6954269838e", kill_on_drop: false }`
[INFO] [stderr]    Compiling zerocopy v0.8.27
[INFO] [stderr]    Compiling autocfg v1.4.0
[INFO] [stderr]    Compiling futures-sink v0.3.31
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling futures-core v0.3.31
[INFO] [stderr]    Compiling zerocopy-derive v0.8.27
[INFO] [stderr]    Compiling serde_derive v1.0.228
[INFO] [stderr]    Compiling futures-task v0.3.31
[INFO] [stderr]    Compiling memchr v2.7.4
[INFO] [stderr]    Compiling futures-util v0.3.31
[INFO] [stderr]    Compiling futures-channel v0.3.31
[INFO] [stderr]    Compiling clap_builder v4.5.60
[INFO] [stderr]    Compiling tokio v1.43.1
[INFO] [stderr]    Compiling num-traits v0.2.19
[INFO] [stderr]    Compiling serde_json v1.0.149
[INFO] [stderr]    Compiling futures-io v0.3.31
[INFO] [stderr]    Compiling criterion-plot v0.5.0
[INFO] [stderr]    Compiling plotters v0.3.7
[INFO] [stderr]    Compiling is-terminal v0.4.17
[INFO] [stderr]    Compiling futures v0.3.31
[INFO] [stderr]    Compiling clap v4.5.60
[INFO] [stderr]    Compiling serde v1.0.228
[INFO] [stderr]    Compiling timer-lib v0.4.0 (/opt/rustwide/workdir)
[INFO] [stderr]    Compiling half v2.7.1
[INFO] [stderr]    Compiling ciborium-ll v0.2.2
[INFO] [stderr]    Compiling ciborium v0.2.2
[INFO] [stderr]    Compiling tinytemplate v1.2.1
[INFO] [stderr]    Compiling criterion v0.5.1
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 55.00s
[INFO] running `Command { std: "docker" "inspect" "fa417f15d0dd6d1746ecdd7e13be3e998720305590eaac624fd9f6954269838e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "fa417f15d0dd6d1746ecdd7e13be3e998720305590eaac624fd9f6954269838e", kill_on_drop: false }`
[INFO] [stdout] fa417f15d0dd6d1746ecdd7e13be3e998720305590eaac624fd9f6954269838e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/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=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+562dee4820c458d823175268e41601d4c060588a" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] e43e11d893025796d690884f7ad062b7678b7da30327cfb8b3eec73568b105d8
[INFO] running `Command { std: "docker" "start" "-a" "e43e11d893025796d690884f7ad062b7678b7da30327cfb8b3eec73568b105d8", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.17s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timer_lib-f194953ae47e6596)
[INFO] [stdout] 
[INFO] [stdout] running 23 tests
[INFO] [stdout] test errors::tests::error_helpers_expose_stable_queries ... ok
[INFO] [stdout] test errors::tests::error_messages_are_stable_and_descriptive ... ok
[INFO] [stdout] test registry::tests::registry_start_helpers_are_easy_to_use ... ok
[INFO] [stdout] test registry::tests::registry_can_pause_and_resume_tracked_timers ... ok
[INFO] [stdout] test timer::tests::builder_starts_recurring_timers_with_less_boilerplate ... ok
[INFO] [stdout] test timer::tests::callback_timeout_counts_as_a_failed_execution ... ok
[INFO] [stdout] test registry::tests::registry_supports_direct_timer_controls ... ok
[INFO] [stdout] test timer::tests::completion_subscription_is_lossless ... ok
[INFO] [stdout] test timer::tests::builder_initial_delay_controls_the_first_recurring_tick ... ok
[INFO] [stdout] test timer::tests::event_helpers_wait_for_pause_resume_and_stop ... ok
[INFO] [stdout] test timer::tests::event_suppression_can_be_enabled_from_the_builder ... ok
[INFO] [stdout] test timer::tests::events_are_emitted_for_key_lifecycle_changes ... ok
[INFO] [stdout] test timer::tests::fixed_rate_and_fixed_delay_schedules_diverge_under_slow_callbacks ... ok
[INFO] [stdout] test timer::tests::one_shot_timer_returns_completed_outcome ... ok
[INFO] [stdout] test timer::tests::paused_builder_start_waits_for_resume ... ok
[INFO] [stdout] test timer::tests::recurring_timers_can_delay_the_first_tick ... ok
[INFO] [stdout] test timer::tests::stop_is_graceful_and_cancel_is_immediate ... ok
[INFO] [stdout] test timer::tests::timer_starts_stopped ... ok
[INFO] [stdout] test timer::tests::replacing_a_run_records_replaced_outcome ... ok
[INFO] [stdout] test timer::tests::retry_policy_retries_failed_callbacks_before_succeeding ... ok
[INFO] [stdout] test timer::tests::event_helpers_wait_for_cancelled_outcomes ... ok
[INFO] [stdout] test timer::tests::interval_adjustments_apply_to_future_ticks ... ok
[INFO] [stdout] test timer::tests::completion_wait_advances_to_the_next_unseen_outcome ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 23 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.04s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/public_api.rs (/opt/rustwide/target/debug/deps/public_api-f91c7941b5b578e8)
[INFO] [stdout] 
[INFO] [stdout] running 15 tests
[INFO] [stdout] test builder_api_is_simple_to_use ... ok
[INFO] [stdout] test lifecycle_wait_helpers_are_consumable_from_the_public_api ... ok
[INFO] [stdout] test callback_timeout_is_available_from_the_public_api ... ok
[INFO] [stdout] test recurring_initial_delay_is_available_from_the_public_api ... ok
[INFO] [stdout] test registry_ergonomics_cover_common_bulk_operations ... ok
[INFO] [stdout] test completion_api_is_simple_to_consume ... ok
[INFO] [stdout] test registry_spawn_helpers_reduce_boilerplate ... ok
[INFO] [stdout] test start_at_is_available_from_the_public_api ... ok
[INFO] [stdout] test timer_closure_api_is_simple_to_use ... ok
[INFO] [stdout] test timer_events_are_consumable_from_the_public_api ... ok
[INFO] [stdout] test retry_policy_is_available_from_the_public_api ... ok
[INFO] [stdout] test labels_and_registry_snapshots_are_available_from_the_public_api ... ok
[INFO] [stdout] test jitter_and_retry_backoff_are_available_from_the_public_api ... ok
[INFO] [stdout] test recurring_schedule_is_the_public_configuration_entry_point ... ok
[INFO] [stdout] test registry_pause_and_resume_helpers_are_available_from_the_public_api ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.03s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/stress.rs (/opt/rustwide/target/debug/deps/stress-b68dd1eee49200aa)
[INFO] [stdout] 
[INFO] [stdout] running 3 tests
[INFO] [stdout] test concurrent_joiners_see_the_same_completed_outcome ... ok
[INFO] [stdout] test many_timers_complete_under_registry_load ... ok
[INFO] [stderr]      Running tests/weird.rs (/opt/rustwide/target/debug/deps/weird-e57f3acfe428a7d8)
[INFO] [stdout] test registry_cancel_all_stops_many_recurring_timers_concurrently ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.14s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 6 tests
[INFO] [stderr]    Doc-tests timer_lib
[INFO] [stdout] test join_is_idempotent_after_cancel ... ok
[INFO] [stdout] test callback_can_request_stop_on_itself_without_deadlocking ... ok
[INFO] [stdout] test removed_timer_keeps_running_after_leaving_registry ... ok
[INFO] [stdout] test callback_cannot_restart_its_own_timer_inline ... ok
[INFO] [stdout] test concurrent_stop_cancel_and_join_do_not_deadlock ... ok
[INFO] [stdout] test lagged_event_subscriber_can_still_observe_finished ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 6 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] test src/lib.rs - (line 41) ... ok
[INFO] [stdout] test src/lib.rs - (line 63) ... ok
[INFO] [stdout] test src/lib.rs - (line 19) ... ok
[INFO] [stdout] test src/lib.rs - (line 86) ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 2.52s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "e43e11d893025796d690884f7ad062b7678b7da30327cfb8b3eec73568b105d8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "e43e11d893025796d690884f7ad062b7678b7da30327cfb8b3eec73568b105d8", kill_on_drop: false }`
[INFO] [stdout] e43e11d893025796d690884f7ad062b7678b7da30327cfb8b3eec73568b105d8