[INFO] fetching crate subms 0.9.4...
[INFO] testing subms-0.9.4 against 1.99.0-beta.8 for beta-1.100-2
[INFO] extracting crate subms 0.9.4 into /workspace/builds/worker-1-tc1/source
[INFO] started tweaking crates.io crate subms 0.9.4
[INFO] removed 0 missing examples
[INFO] finished tweaking crates.io crate subms 0.9.4
[INFO] tweaked toml for crates.io crate subms 0.9.4 written to /workspace/builds/worker-1-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate subms 0.9.4 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 subms 0.9.4 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-1-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-1-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:3111399a4047eeb3a02b7a90e478d715f38a8c6669b5c4b49d30a17385265909" "sleep" "infinity", kill_on_drop: false }`
[INFO] [stdout] 94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b
[INFO] running `Command { std: "docker" "start" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b", 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" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b" "/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" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b", 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" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling subms v0.9.4 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 1.46s
[INFO] running `Command { std: "docker" "inspect" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b", 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" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stderr]    Compiling subms v0.9.4 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 3.35s
[INFO] running `Command { std: "docker" "inspect" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b", 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" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b" "/opt/rustwide/cargo-home/bin/cargo" "+1.99.0-beta.8" "test" "--frozen", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.02s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/subms-22dd9bfc86607662)
[INFO] [stdout] 
[INFO] [stdout] running 172 tests
[INFO] [stdout] test bench::tests::benchmark_threads_sample_cap_onto_harness ... ok
[INFO] [stdout] test bench::tests::assert_p99_under_errors_when_above_limit ... ok
[INFO] [stdout] test bench::tests::cpu_json_emits_object_or_null ... ok
[INFO] [stdout] test bench::tests::diff_summary_computes_per_metric_deltas ... ok
[INFO] [stdout] test bench::tests::diff_summary_does_not_flag_when_all_improved ... ok
[INFO] [stdout] test bench::tests::format_ns_uses_three_unit_tiers ... ok
[INFO] [stdout] test bench::tests::diff_summary_flags_regression_above_threshold ... ok
[INFO] [stdout] test bench::tests::assert_p99_under_passes_when_below_limit ... ok
[INFO] [stdout] test bench::tests::assert_p99_under_errors_when_stage_missing ... ok
[INFO] [stdout] test bench::tests::print_summary_produces_aligned_table ... ok
[INFO] [stdout] test bench::tests::print_diff_emits_table_with_verdict_column ... ok
[INFO] [stdout] test bench::tests::print_sweep_pivots_by_stage_and_labels_rows ... ok
[INFO] [stdout] test bench::tests::run_bench_drives_recipe_through_harness ... ok
[INFO] [stdout] test bench::tests::percentile_known_distribution ... ok
[INFO] [stdout] test bench::tests::diff_to_json_emits_expected_keys ... ok
[INFO] [stdout] test bench::tests::run_sweep_runs_recipe_once_per_params_set ... ok
[INFO] [stdout] test bench::tests::downsample_respects_cap ... ok
[INFO] [stdout] test bench::tests::percentile_single_value ... ok
[INFO] [stdout] test bench::tests::summarize_windowed_p99_monotonic_for_monotonic_input ... ok
[INFO] [stdout] test bench::tests::summarize_windowed_splits_into_correct_number_of_buckets ... ok
[INFO] [stdout] test bench::tests::summarize_populates_cdf_buckets_64_long ... ok
[INFO] [stdout] test bench::tests::summary_to_json_emits_cdf_buckets_ns_field ... ok
[INFO] [stdout] test bench::tests::percentile_empty_is_zero ... ok
[INFO] [stdout] test bench::tests::summarize_lean_drops_samples ... ok
[INFO] [stdout] test bench::tests::summarize_populates_jitter_score_in_unit_interval ... ok
[INFO] [stdout] test bench::tests::sweep_to_json_emits_array ... ok
[INFO] [stdout] test bench::tests::summarize_sweep_bundles_existing_summaries ... ok
[INFO] [stdout] test bench_config::tests::absent_cpu_pin_defaults_single_even_with_other_keys ... ok
[INFO] [stdout] test bench_config::tests::cpu_pin_wire_tokens_round_trip ... ok
[INFO] [stdout] test bench::tests::summarize_windowed_zero_window_treated_as_one ... ok
[INFO] [stdout] test bench::tests::summarize_windowed_empty_harness_returns_empty_vec ... ok
[INFO] [stdout] test bench_config::tests::legacy_boolean_cpu_pin_still_reads ... ok
[INFO] [stdout] test bench::tests::summarize_populates_percentiles_and_samples ... ok
[INFO] [stdout] test bench_config::tests::default_impl_matches_new ... ok
[INFO] [stdout] test bench::tests::summary_to_json_emits_stddev_ns_field ... ok
[INFO] [stdout] test bench_config::tests::load_str_reads_typed_fields ... ok
[INFO] [stdout] test bench_config::tests::load_missing_then_save_creates_file_and_dirs ... ok
[INFO] [stdout] test bench_config::tests::malformed_input_yields_empty_never_panics ... ok
[INFO] [stdout] test bench_loops::tests::keyed_op_is_deterministic_under_same_seed ... ok
[INFO] [stdout] test bench_loops::tests::indexed_op_passes_sequential_indices ... ok
[INFO] [stdout] test env::tests::app_env_as_str_and_display_match ... ok
[INFO] [stdout] test bench_config::tests::merge_preserves_foreign_fields ... ok
[INFO] [stdout] test bench_config::tests::new_defaults_cpu_pin_single ... ok
[INFO] [stdout] test bench_config::tests::setters_are_idempotent_and_positional ... ok
[INFO] [stdout] test env::tests::app_env_from_env_reads_app_env_var ... ok
[INFO] [stdout] test bench_config::tests::wrong_typed_values_fall_back_to_default ... ok
[INFO] [stdout] test env::tests::app_env_default_is_local ... ok
[INFO] [stdout] test env::tests::app_env_parses_canonical_lowercase ... ok
[INFO] [stdout] test env::tests::app_env_parses_synonyms ... ok
[INFO] [stdout] test env::tests::app_env_unknown_falls_back_to_local ... ok
[INFO] [stdout] test bench_loops::tests::templated_op_substitutes_index ... ok
[INFO] [stdout] test env::tests::app_env_parses_mixed_case ... ok
[INFO] [stdout] test env::tests::app_region_default_is_unknown ... ok
[INFO] [stdout] test env::tests::app_region_parses_canonical ... ok
[INFO] [stdout] test env::tests::app_region_from_env_reads_app_region_var ... ok
[INFO] [stdout] test env::tests::app_region_parses_mixed_case ... ok
[INFO] [stdout] test env::tests::app_region_parses_synonyms ... ok
[INFO] [stdout] test env::tests::env_bool_parses_falsy_variants ... ok
[INFO] [stdout] test env::tests::env_bool_parses_truthy_variants ... ok
[INFO] [stdout] test env::tests::env_i64_falls_back_on_unparseable ... ok
[INFO] [stdout] test env::tests::env_i64_parses_signed_int ... ok
[INFO] [stdout] test env::tests::env_or_falls_back_when_unset ... ok
[INFO] [stdout] test env::tests::env_or_uses_value_when_set ... ok
[INFO] [stdout] test env::tests::env_str_returns_none_for_unset ... ok
[INFO] [stdout] test env::tests::app_env_trims_whitespace ... ok
[INFO] [stdout] test env::tests::env_str_reads_set_value ... ok
[INFO] [stdout] test env::tests::app_region_as_str_and_display_match ... ok
[INFO] [stdout] test env::tests::env_str_treats_empty_as_absent ... ok
[INFO] [stdout] test feature::tests::a_clearly_superlinear_sweep_is_still_structural ... ok
[INFO] [stdout] test feature::tests::a_feature_costing_about_the_guard_is_indeterminate_not_a_coin_toss ... ok
[INFO] [stdout] test feature::tests::a_feature_faster_than_base_is_not_reported_as_within_the_delta ... ok
[INFO] [stdout] test feature::tests::a_feature_just_above_base_still_reads_as_within_the_delta ... ok
[INFO] [stdout] test feature::tests::a_feature_the_run_did_not_touch_keeps_its_own_provenance ... ok
[INFO] [stdout] test feature::tests::a_feature_written_this_run_carries_this_runs_provenance ... ok
[INFO] [stdout] test feature::tests::a_flat_op_above_the_claim_line_is_reported_not_claimed ... ok
[INFO] [stdout] test env::tests::env_u64_and_f64_smoke ... ok
[INFO] [stdout] test feature::tests::a_mixed_feature_rolls_up_to_its_most_restrictive_stage ... ok
[INFO] [stdout] test feature::tests::a_carried_over_feature_in_a_v2_manifest_reports_no_provenance ... ok
[INFO] [stdout] test feature::tests::a_pre_v2_manifest_falls_back_to_the_file_level_stamp ... ok
[INFO] [stdout] test feature::tests::a_reference_passed_with_local_is_ignored ... ok
[INFO] [stdout] test feature::tests::an_empty_fleet_reference_is_not_recorded ... ok
[INFO] [stdout] test feature::tests::an_empty_stage_set_rolls_up_to_auxiliary ... ok
[INFO] [stdout] test feature::tests::an_override_still_wins_over_the_claim_line_and_the_band ... ok
[INFO] [stdout] test feature::tests::an_unknown_source_token_reads_as_local ... ok
[INFO] [stdout] test feature::tests::auxiliary_stages_never_drag_a_hot_feature_down ... ok
[INFO] [stdout] test feature::tests::classifies_flat_above_base_as_hot_path ... ok
[INFO] [stdout] test feature::tests::classifies_linear_growth_as_structural ... ok
[INFO] [stdout] test env::tests::app_region_unknown_falls_back_to_unknown ... ok
[INFO] [stdout] test feature::tests::degenerate_features_preserves_other_top_level_keys ... ok
[INFO] [stdout] test env::tests::env_bool_falls_back_on_garbage ... ok
[INFO] [stdout] test bench::tests::summary_to_json_emits_jitter_score_field ... ok
[INFO] [stdout] test bench_loops::tests::keyed_op_records_count_samples ... ok
[INFO] [stdout] test feature::tests::env_provenance_defaults_to_local_when_unset ... ok
[INFO] [stdout] test feature::tests::exactly_base_stays_auxiliary_and_is_never_indeterminate ... ok
[INFO] [stdout] test feature::tests::fleet_stamp_records_source_and_instance ... ok
[INFO] [stdout] test feature::tests::local_stamp_clears_a_stale_fleet_reference ... ok
[INFO] [stdout] test feature::tests::env_provenance_reads_the_instance_id ... ok
[INFO] [stdout] test feature::tests::load_missing_then_save_creates_the_file_and_dirs ... ok
[INFO] [stdout] test feature::tests::a_sweep_straddling_the_structural_guard_is_indeterminate ... ok
[INFO] [stdout] test feature::tests::an_all_hot_feature_still_rolls_up_hot ... ok
[INFO] [stdout] test feature::tests::every_category_round_trips_through_its_wire_value ... ok
[INFO] [stdout] test feature::tests::no_workload_is_auxiliary ... ok
[INFO] [stdout] test feature::tests::log_n_growth_stays_hot_path ... ok
[INFO] [stdout] test feature::tests::only_the_target_feature_changes ... ok
[INFO] [stdout] test feature::tests::override_wins ... ok
[INFO] [stdout] test feature::tests::re_running_a_feature_locally_clears_its_fleet_reference ... ok
[INFO] [stdout] test feature::tests::malformed_input_never_crashes_and_stays_writable ... ok
[INFO] [stdout] test feature::tests::one_indeterminate_stage_makes_the_feature_indeterminate ... ok
[INFO] [stdout] test feature::tests::merge_preserves_deep_third_party_structures ... ok
[INFO] [stdout] test feature::tests::reclassify_keeps_custom_fields_drops_p99 ... ok
[INFO] [stdout] test feature::tests::repeated_merges_are_lossless ... ok
[INFO] [stdout] test feature::tests::restamping_keeps_the_key_in_place ... ok
[INFO] [stdout] test feature::tests::round_trips_number_precision ... ok
[INFO] [stdout] test feature::tests::sample_features_classify_correctly ... ok
[INFO] [stdout] test feature::tests::set_feature_stages_writes_per_stage_detail_and_the_rollup ... ok
[INFO] [stdout] test feature::tests::stamp_round_trips_through_load_str_and_preserves_other_fields ... ok
[INFO] [stdout] test feature::tests::structural_feature_drops_p99 ... ok
[INFO] [stdout] test feature::tests::the_claim_line_does_not_swallow_a_genuine_sub_ms_hot_path ... ok
[INFO] [stdout] test growth::tests::bounded_gates_on_peak_bytes ... ok
[INFO] [stdout] test growth::tests::json_bytes_match_the_cross_port_fixture ... ok
[INFO] [stdout] test growth::tests::plateau_holds_when_flat_and_breaches_when_climbing ... ok
[INFO] [stdout] test feature::tests::unstamped_manifest_reads_as_local ... ok
[INFO] [stdout] test params::tests::bench_params_from_map_ignores_garbage_values ... ok
[INFO] [stdout] test growth::tests::amplification_bounded_breaches_when_disk_grows_but_live_flat ... ok
[INFO] [stdout] test growth::tests::amplification_bounded_holds_when_disk_tracks_live ... ok
[INFO] [stdout] test params::tests::bench_params_from_map_reads_overrides ... ok
[INFO] [stdout] test growth::tests::json_has_verdict_and_rounds ... ok
[INFO] [stdout] test params::tests::bench_params_from_map_uses_defaults_when_missing ... ok
[INFO] [stdout] test feature::tests::merge_preserves_unknown_fields ... ok
[INFO] [stdout] test params::tests::parse_bool_accepts_falsy ... ok
[INFO] [stdout] test feature::tests::no_delta_from_base_is_auxiliary ... ok
[INFO] [stdout] test params::tests::parse_bool_accepts_truthy ... ok
[INFO] [stdout] test params::tests::parse_bool_unknown_falls_back ... ok
[INFO] [stdout] test params::tests::parse_bool_missing_falls_back ... ok
[INFO] [stdout] test params::tests::parse_u64_missing ... ok
[INFO] [stdout] test params::tests::parse_u64_present ... ok
[INFO] [stdout] test params::tests::parse_usize_missing ... ok
[INFO] [stdout] test params::tests::parse_usize_invalid_falls_back ... ok
[INFO] [stdout] test params::tests::parse_string_missing ... ok
[INFO] [stdout] test params::tests::parse_string_present ... ok
[INFO] [stdout] test params::tests::parse_u64_invalid_falls_back ... ok
[INFO] [stdout] test recipe::tests::bench_params_default_is_sensible ... ok
[INFO] [stdout] test recipe::tests::lcg_reexport_works ... ok
[INFO] [stdout] test tests::observer_fires_on_record_and_time ... ok
[INFO] [stdout] test params::tests::parse_usize_present ... ok
[INFO] [stdout] test tests::observer_default_noop_does_not_change_behaviour ... ok
[INFO] [stdout] test tests::observer_fires_on_warm_then_time_only_for_measured_pass ... ok
[INFO] [stdout] test tests::observer_fires_on_summarize_exactly_once ... ok
[INFO] [stdout] test recipe::tests::benchmark_produces_expected_json_shape ... ok
[INFO] [stdout] test tests::round_trip_smoke ... ok
[INFO] [stdout] test tests::set_observer_updates_already_created_stages ... ok
[INFO] [stdout] test tests::observer_records_carry_declared_stage_kind ... ok
[INFO] [stdout] test tests::warm_then_time_records_measured_only ... ok
[INFO] [stdout] test feature::tests::set_feature_is_idempotent ... ok
[INFO] [stdout] test timer::tests::measure_ns_propagates_closure_return_value ... ok
[INFO] [stdout] test timer::tests::lap_is_alias_of_mark ... ok
[INFO] [stdout] test tests::percentiles_make_sense ... ok
[INFO] [stdout] test timer::tests::measure_ns_returns_zero_or_positive_for_noop ... ok
[INFO] [stdout] test timer::tests::print_emits_header_and_checkpoints ... ok
[INFO] [stdout] test timer::tests::reset_clears_checkpoints ... ok
[INFO] [stdout] test timer::tests::nanos_now_returns_positive_increasing ... ok
[INFO] [stdout] test timer::tests::measure_ns_returns_elapsed_and_runs_closure ... ok
[INFO] [stdout] test util::tests::lcg_bounded_zero_is_safe ... ok
[INFO] [stdout] test timer::tests::autostart_and_mark_captures_increasing_since_start ... ok
[INFO] [stdout] test util::tests::lcg_bounded_stays_in_range ... ok
[INFO] [stdout] test tests::paced_stage_folds_queue_delay_into_latency ... ok
[INFO] [stdout] test util::tests::lcg_is_deterministic ... ok
[INFO] [stdout] test util::tests::lcg_seed_zero_has_full_entropy ... ok
[INFO] [stdout] test timer::tests::tick_and_elapsed_ns_capture_positive_interval ... ok
[INFO] [stdout] test timer::tests::tick_is_reusable_for_multiple_reads ... ok
[INFO] [stdout] test timer::tests::stop_marks_is_stop_and_freezes_elapsed ... ok
[INFO] [stdout] test util::tests::lcg_adjacent_seeds_do_not_alias ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 172 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.09s
[INFO] [stdout] 
[INFO] [stderr]    Doc-tests subms
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[INFO] [stdout] test src/lib.rs - SubMsStage::with_pacing (line 202) ... ignored
[INFO] [stdout] test src/bench_loops.rs - bench_loops (line 13) - compile ... ok
[INFO] [stdout] test src/feature.rs - feature (line 16) ... ok
[INFO] [stdout] test src/timer.rs - timer (line 5) ... ok
[INFO] [stdout] test src/lib.rs - (line 16) ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.06s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 0.80s; merged doctests compilation took 0.73s
[INFO] running `Command { std: "docker" "inspect" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b", kill_on_drop: false }`
[INFO] [stdout] 94c3d49ebd7e9eddef82b2cecad9bb0d605302af53f153e879c3149749240a1b
