[INFO] fetching crate critpath-core 0.1.0...
[INFO] testing critpath-core-0.1.0 against 1.99.0-beta.8+cargoflags=--release for beta-release-1.100-2
[INFO] extracting crate critpath-core 0.1.0 into /workspace/builds/worker-5-tc1/source
[INFO] started tweaking crates.io crate critpath-core 0.1.0
[INFO] removed 0 missing examples
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate critpath-core 0.1.0
[INFO] tweaked toml for crates.io crate critpath-core 0.1.0 written to /workspace/builds/worker-5-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate critpath-core 0.1.0 on toolchain 1.99.0-beta.8
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.99.0-beta.8" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate crates.io crate critpath-core 0.1.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" "+1.99.0-beta.8" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,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" "-m" "1610612736" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:77db811e55d90add9212f6832c23229e3de5f1c1f9905e8cb07319ea15df73ac" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] 5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8
[INFO] running `Command { std: "docker" "start" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-w" "/opt/rustwide/workdir" "--user" "0:0" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "build" "--frozen" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling critpath-core v0.1.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 1.63s
[INFO] running `Command { std: "docker" "inspect" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "test" "--frozen" "--no-run" "--message-format=json" "--release", kill_on_drop: false }`
[INFO] [stderr]    Compiling critpath-core v0.1.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 10.12s
[INFO] running `Command { std: "docker" "inspect" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "exec" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-w" "/opt/rustwide/workdir" "--user" "0:0" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "test" "--frozen" "--release", kill_on_drop: false }`
[INFO] [stderr]     Finished `release` profile [optimized] target(s) in 0.01s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/release/deps/critpath_core-e450959478d0ea85)
[INFO] [stderr]      Running tests/analysis.rs (/opt/rustwide/target/release/deps/analysis-39cfc16d0f83c540)
[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] [stdout] 
[INFO] [stdout] running 21 tests
[INFO] [stdout] test every_step_of_the_critical_path_is_a_constraint_the_model_states ... ok
[INFO] [stdout] test i11_single_unit_critical_path_is_its_own_weight ... ok
[INFO] [stdout] test a_unit_is_never_told_to_finish_before_it_can ... ok
[INFO] [stdout] test a_unit_with_no_dependents_carries_slack_up_to_the_critical_path ... ok
[INFO] [stdout] test closure_rule_reproduces_the_measured_fixture ... ok
[INFO] [stdout] test a_closure_requirement_overrides_the_kind_of_an_incoming_edge ... ok
[INFO] [stdout] test i12_empty_graph_has_no_critical_path ... ok
[INFO] [stdout] test earliest_times_match_a_naive_reference_on_every_shape ... ok
[INFO] [stdout] test i13_reclassifying_a_full_edge_as_metadata_cannot_lengthen_the_path ... ok
[INFO] [stdout] test i15_fan_out_is_the_source_plus_the_largest_sink ... ok
[INFO] [stdout] test i17_a_closure_requirement_reaches_past_the_direct_dependencies ... ok
[INFO] [stdout] test i18_the_closure_recurrence_equals_the_enumerated_closure ... ok
[INFO] [stdout] test i16_setting_a_closure_requirement_can_only_delay ... ok
[INFO] [stdout] test slack_can_actually_be_taken ... ok
[INFO] [stdout] test i9_slack_is_zero_on_a_critical_path_and_positive_beside_it ... ok
[INFO] [stdout] test i1_repeated_analysis_of_the_same_graph_agrees_exactly ... ok
[INFO] [stdout] test i15_chain_of_full_edges_is_n_times_the_weight ... ok
[INFO] [stdout] test metadata_edges_credit_pipelining_where_full_edges_would_not ... ok
[INFO] [stdout] test slack_is_tight_against_a_delayed_start ... ok
[INFO] [stdout] test ties_for_the_longest_path_resolve_to_the_lowest_identifier ... ok
[INFO] [stderr]      Running tests/graph.rs (/opt/rustwide/target/release/deps/graph-7aba3d9ca5b59773)
[INFO] [stdout] test i14_increasing_a_weight_cannot_shorten_the_path ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 21 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 18 tests
[INFO] [stdout] test a_cycle_is_rejected_and_the_cycle_is_reported ... ok
[INFO] [stdout] test a_duplicate_edge_keeps_the_stronger_constraint_whichever_order_it_arrives ... ok
[INFO] [stdout] test an_identifier_from_another_graph_is_not_detected ... ok
[INFO] [stdout] test a_unit_depending_on_itself_is_rejected ... ok
[INFO] [stdout] test graph_can_cross_thread_boundaries ... ok
[INFO] [stdout] test error_messages_name_the_units_involved ... ok
[INFO] [stdout] test metadata_edge_from_a_unit_that_emits_no_metadata_is_rejected ... ok
[INFO] [stdout] test a_cycle_is_reported_even_when_part_of_the_graph_is_acyclic ... ok
[INFO] [stderr]      Running tests/oracle.rs (/opt/rustwide/target/release/deps/oracle-071d83442dcc8538)
[INFO] [stdout] test topological_order_places_every_dependency_before_its_dependent ... ok
[INFO] [stdout] test total_work_is_the_sum_of_unit_weights ... ok
[INFO] [stdout] test units_iterates_every_unit_once_in_id_order ... ok
[INFO] [stdout] test an_index_past_the_end_reads_as_absent_rather_than_panicking ... ok
[INFO] [stdout] test empty_graph_is_valid_and_weighs_nothing ... ok
[INFO] [stdout] test chain_records_dependencies_and_dependents_in_both_directions ... ok
[INFO] [stdout] test metadata_emitted_after_the_unit_finishes_is_rejected ... ok
[INFO] [stdout] test an_edge_naming_a_unit_that_does_not_exist_is_rejected ... ok
[INFO] [stdout] test single_unit_graph_reports_its_own_weight ... ok
[INFO] [stdout] test unit_ids_follow_insertion_order_so_adapters_control_the_canonical_order ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 18 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 11 tests
[INFO] [stdout] test the_longest_path_policy_has_the_anomaly_too ... ok
[INFO] [stdout] test an_extra_executor_can_lengthen_the_simulated_build ... ok
[INFO] [stdout] test the_oracle_and_the_code_agree_on_degenerate_graphs ... ok
[INFO] [stdout] test analysis_and_simulation_are_deterministic ... ok
[INFO] [stdout] test earliest_times_match_the_relaxation_oracle ... ok
[INFO] [stdout] test the_critical_path_is_a_real_path ... ok
[INFO] [stdout] test an_extra_executor_costs_time_rarely_but_measurably ... ok
[INFO] [stdout] test unlimited_executors_reach_the_critical_path ... ok
[INFO] [stdout] test simulated_makespan_is_never_below_the_bounds ... ok
[INFO] [stdout] test schedules_respect_precedence_capacity_and_non_preemption ... ok
[INFO] [stdout] test simulated_makespan_is_never_below_the_exhaustive_optimum ... ok
[INFO] [stderr]      Running tests/properties.rs (/opt/rustwide/target/release/deps/properties-0514db33c45d46f3)
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.84s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 26 tests
[INFO] [stdout] test i15_chains_and_fans_match_their_closed_forms ... ok
[INFO] [stdout] test i11_a_lone_unit_is_the_whole_build ... ok
[INFO] [stdout] test i12_an_empty_graph_answers_zero_rather_than_failing ... ok
[INFO] [stdout] test i13_turning_full_edges_into_metadata_edges_never_lengthens_the_critical_path ... ok
[INFO] [stdout] test i17_a_closure_requirement_reaches_past_the_neighbours ... ok
[INFO] [stdout] test corpus_is_non_trivial ... ok
[INFO] [stdout] test i8_another_executor_can_make_the_build_longer ... ok
[INFO] [stdout] test removing_an_edge_can_lengthen_the_simulated_makespan ... ok
[INFO] [stdout] test i9_slack_is_never_negative_and_is_zero_along_the_critical_path ... ok
[INFO] [stdout] test i3_no_more_than_j_units_are_running_at_any_instant ... ok
[INFO] [stdout] test saturating_weights_degrade_without_panicking ... ok
[INFO] [stdout] test i7_with_an_executor_per_unit_the_makespan_is_the_critical_path ... ok
[INFO] [stdout] test every_applied_transformation_yields_a_valid_graph ... ok
[INFO] [stdout] test a_split_adds_no_work_beyond_the_overhead_it_charges ... ok
[INFO] [stdout] test i18_the_closure_recurrence_agrees_with_an_enumerated_closure ... ok
[INFO] [stdout] test i8_another_executor_almost_always_helps ... ok
[INFO] [stdout] test i14_making_a_unit_slower_never_shortens_the_critical_path ... ok
[INFO] [stdout] test i2_no_unit_starts_before_the_edges_into_it_release_it ... ok
[INFO] [stdout] test i10_the_critical_path_does_not_move_with_the_executor_count ... ok
[INFO] [stdout] test i1_the_same_graph_yields_identical_answers_whatever_order_it_was_assembled_in ... ok
[INFO] [stdout] test removing_units_never_lengthens_the_critical_path ... ok
[INFO] [stdout] test i4_every_unit_occupies_exactly_its_own_duration ... ok
[INFO] [stdout] test i5_no_schedule_finishes_before_the_critical_path ... ok
[INFO] [stdout] test i6_no_schedule_finishes_before_the_work_can_be_done ... ok
[INFO] [stdout] test i16_a_closure_requirement_only_ever_delays ... ok
[INFO] [stdout] test removing_an_edge_never_lengthens_the_critical_path ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 26 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.49s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/schedule.rs (/opt/rustwide/target/release/deps/schedule-f2ec8a545dd7a901)
[INFO] [stdout] 
[INFO] [stdout] running 14 tests
[INFO] [stdout] test i11_a_single_unit_takes_its_own_time_on_any_number_of_executors ... ok
[INFO] [stdout] test i2_and_i4_the_schedule_respects_every_constraint_it_was_given ... ok
[INFO] [stdout] test i12_empty_graph_schedules_to_nothing ... ok
[INFO] [stdout] test the_lower_bound_needs_only_the_analysis_it_came_from ... ok
[INFO] [stdout] test i8_more_executors_never_lengthen_these_schedules ... ok
[INFO] [stdout] test i5_and_i6_every_schedule_meets_both_bounds ... ok
[INFO] [stdout] test a_metadata_release_in_the_future_leaves_an_executor_idle ... ok
[INFO] [stdout] test i3_never_more_units_running_than_executors ... ok
[INFO] [stdout] test cargo_like_ordering_counts_transitive_dependents_not_direct_ones ... ok
[INFO] [stdout] test the_two_policies_can_differ_by_a_third_of_the_build ... ok
[INFO] [stdout] test i1_repeated_simulation_of_the_same_graph_agrees_exactly ... ok
[INFO] [stdout] test i7_enough_executors_reach_the_critical_path_exactly ... ok
[INFO] [stdout] test the_area_bound_rounds_up_and_the_lower_bound_takes_whichever_term_dominates ... ok
[INFO] [stdout] test more_executors_can_lengthen_a_schedule ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 14 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/transform.rs (/opt/rustwide/target/release/deps/transform-2e31d4381e58fa13)
[INFO] [stdout] 
[INFO] [stdout] running 24 tests
[INFO] [stdout] test removing_an_edge_deletes_that_edge_and_nothing_else ... ok
[INFO] [stdout] test removing_no_units_changes_nothing ... ok
[INFO] [stdout] test an_optimistic_split_attaches_every_dependent_to_the_part_that_finishes_first ... ok
[INFO] [stdout] test removing_a_unit_from_another_graph_is_an_error ... ok
[INFO] [stdout] test pessimistic_split_halves_the_weight_and_feeds_every_dependent ... ok
[INFO] [stdout] test removing_a_unit_also_removes_what_only_it_dragged_in ... ok
[INFO] [stdout] test removing_an_absent_edge_is_an_error ... ok
[INFO] [stdout] test removing_every_unit_yields_an_empty_graph ... ok
[INFO] [stdout] test splitting_a_zero_weight_unit_yields_two_units_of_overhead ... ok
[INFO] [stdout] test splitting_off_more_than_the_whole_unit_is_refused ... ok
[INFO] [stdout] test the_mapping_can_be_read_without_matching_on_it ... ok
[INFO] [stdout] test an_optimistic_split_leaves_the_edges_it_does_not_touch_alone ... ok
[INFO] [stdout] test roots_are_the_units_nothing_depends_on ... ok
[INFO] [stdout] test roots_of_an_empty_graph_are_empty ... ok
[INFO] [stdout] test split_by_one_third_rounds_to_nearest_and_costs_only_the_overhead ... ok
[INFO] [stdout] test split_clamps_metadata_to_the_part_that_carries_it ... ok
[INFO] [stdout] test removing_the_same_unit_twice_is_not_an_error ... ok
[INFO] [stdout] test removing_the_root_removes_everything_it_kept_alive ... ok
[INFO] [stdout] test the_same_transform_applied_twice_gives_identical_graphs ... ok
[INFO] [stdout] test splitting_a_build_script_is_refused ... ok
[INFO] [stdout] test splitting_a_unit_from_another_graph_is_refused ... ok
[INFO] [stdout] test splitting_a_unit_with_no_dependents_is_the_same_under_both_assumptions ... ok
[INFO] [stdout] test the_mapping_relates_every_surviving_unit_to_its_original ... ok
[INFO] [stdout] test optimistic_split_gives_each_dependent_exactly_one_part ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 24 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests critpath_core
[INFO] [stdout] 
[INFO] [stdout] running 7 tests
[INFO] [stdout] test src/millis.rs - millis::Millis (line 15) ... ok
[INFO] [stdout] test src/transform.rs - transform::apply (line 362) ... ok
[INFO] [stdout] test src/graph.rs - graph::BuildGraph (line 158) ... ok
[INFO] [stdout] test src/transform.rs - transform::roots (line 309) ... ok
[INFO] [stdout] test src/analysis.rs - analysis::Analysis (line 16) ... ok
[INFO] [stdout] test src/schedule.rs - schedule::area_bound (line 244) ... ok
[INFO] [stdout] test src/schedule.rs - schedule::simulate (line 103) ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.73s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8", kill_on_drop: false }`
[INFO] [stdout] 5734b53557f7e3a4c3bc2c082ca2939846e490cfebc8e5af37c2d52bf3bd75a8
