diff --git a/tests/cli/test_machines_commands.py b/tests/cli/test_machines_commands.py index bb8b83a6..7733e966 100644 --- a/tests/cli/test_machines_commands.py +++ b/tests/cli/test_machines_commands.py @@ -130,7 +130,7 @@ def test_successful_destroy_does_not_warn_when_instance_is_already_gone( assert exit_info.value.code == 0 assert destroy_instance.call_count == 1 captured = capsys.readouterr() - assert "Instance 123 destroyed successfully on attempt 1." in captured.out + assert "Temporary test instance 123 destroyed." in captured.out assert "WARNING: failed to destroy test instance 123" not in captured.out @@ -193,7 +193,9 @@ def test_ignore_requirements_warns_on_success(self, parse_argv, monkeypatch, cap assert "Requirement checks are skipped as a pass/fail gate" in out assert "does not qualify this machine for verification" in out assert out.count("does not qualify this machine for verification") >= 2 - assert "Test passed." in out + assert "Self-test summary" in out + assert "Status: passed" in out + assert "Result: self-test completed successfully." in out def test_ignore_requirements_warning_in_raw_summary(self, parse_argv, monkeypatch, capsys): from vastai.cli.commands import machines @@ -406,7 +408,7 @@ def test_no_offer_non_raw_renders_once_without_stale_placeholders( search = Mock(side_effect=[[], [broader_offer]]) monkeypatch.setattr("vastai.cli.commands.machines.offers_api.search_offers", search) - args = parse_argv(["self-test", "machine", "42"]) + args = parse_argv(["self-test", "machine", "42", "--log-level", "debug"]) with pytest.raises(SystemExit) as exc_info: args.func(args) @@ -428,7 +430,7 @@ def test_preflight_outputs_actual_required_once( search = Mock(return_value=[bad_offer]) monkeypatch.setattr("vastai.cli.commands.machines.offers_api.search_offers", search) - args = parse_argv(["self-test", "machine", "42"]) + args = parse_argv(["self-test", "machine", "42", "--log-level", "debug"]) with pytest.raises(SystemExit) as exc_info: args.func(args) @@ -442,6 +444,49 @@ def test_preflight_outputs_actual_required_once( assert "--filter" not in captured.out assert search.call_count == 1 + def test_default_info_preflight_failure_is_compact( + self, parse_argv, patch_get_client, monkeypatch, capsys + ): + bad_offer = _self_test_offer(cuda_max_good=11.7, reliability=0.9) + search = Mock(return_value=[bad_offer]) + monkeypatch.setattr("vastai.cli.commands.machines.offers_api.search_offers", search) + + args = parse_argv(["self-test", "machine", "42"]) + with pytest.raises(SystemExit) as exc_info: + args.func(args) + + captured = capsys.readouterr() + assert exc_info.value.code == 1 + assert "Starting self-test for machine 42." in captured.out + assert "Preflight failed." in captured.out + assert "Self-test summary" in captured.out + assert "Status: failed" in captured.out + assert "Failed checks: CUDA version, Reliability" in captured.out + assert "Reason: 2 preflight requirement check(s) failed." in captured.out + assert "Preflight diagnostics for machine 42 failed:" not in captured.out + assert "actual: 11.7 CUDA" not in captured.out + assert "purpose:" not in captured.out + + def test_warning_log_level_keeps_summary_but_suppresses_info_lifecycle( + self, parse_argv, patch_get_client, monkeypatch, capsys + ): + bad_offer = _self_test_offer(cuda_max_good=11.7, reliability=0.9) + search = Mock(return_value=[bad_offer]) + monkeypatch.setattr("vastai.cli.commands.machines.offers_api.search_offers", search) + + args = parse_argv(["self-test", "machine", "42", "--log-level", "warning"]) + with pytest.raises(SystemExit) as exc_info: + args.func(args) + + captured = capsys.readouterr() + assert exc_info.value.code == 1 + assert "Starting self-test for machine 42." not in captured.out + assert "Preflight failed." not in captured.out + assert "Self-test summary" in captured.out + assert "Status: failed" in captured.out + assert "Failed checks: CUDA version, Reliability" in captured.out + assert "actual: 11.7 CUDA" not in captured.out + def test_selected_offer_is_reused_for_rental( self, parse_argv, patch_get_client, monkeypatch ): @@ -470,7 +515,7 @@ def test_preflight_normalizes_api_gpu_ram_units( search = Mock(return_value=[bad_offer]) monkeypatch.setattr("vastai.cli.commands.machines.offers_api.search_offers", search) - args = parse_argv(["self-test", "machine", "42"]) + args = parse_argv(["self-test", "machine", "42", "--log-level", "debug"]) with pytest.raises(SystemExit) as exc_info: args.func(args) @@ -600,7 +645,7 @@ def test_preflight_direct_port_overage_renders_advisory( Mock(return_value=[offer]), ) - args = parse_argv(["self-test", "machine", "42"]) + args = parse_argv(["self-test", "machine", "42", "--log-level", "debug"]) with pytest.raises(SystemExit) as exc_info: args.func(args) @@ -763,6 +808,48 @@ def test_env_test_image_overrides_default_mapping( assert create.call_args.kwargs["image"] == "vastai/test:p3-env" assert create.call_args.kwargs["runtype"] == "ssh_direc ssh_proxy" + @pytest.mark.parametrize( + "argv,env_level,expected_level,expected_source", + [ + (["self-test", "machine", "42", "--raw"], None, "info", "default"), + (["self-test", "machine", "42", "--log-level", "debug", "--raw"], None, "debug", "argument"), + (["self-test", "machine", "42", "--debugging", "--raw"], None, "debug", "debugging"), + (["self-test", "machine", "42", "--raw"], "debug", "debug", "VAST_LOG_LEVEL"), + (["self-test", "machine", "42", "--raw"], "not-a-level", "info", "default_invalid_VAST_LOG_LEVEL"), + ], + ) + def test_self_test_log_level_resolution( + self, + parse_argv, + patch_get_client, + monkeypatch, + argv, + env_level, + expected_level, + expected_source, + ): + offer = _self_test_offer() + if env_level is None: + monkeypatch.delenv("VAST_LOG_LEVEL", raising=False) + else: + monkeypatch.setenv("VAST_LOG_LEVEL", env_level) + monkeypatch.setattr( + "vastai.cli.commands.machines.offers_api.search_offers", + Mock(return_value=[offer]), + ) + monkeypatch.setattr( + "vastai.cli.commands.machines.instances_api.create_instance", + Mock(side_effect=RuntimeError("stop before live rental")), + ) + + args = parse_argv(argv) + result = args.func(args) + + assert result["diagnostics"]["log_level"] == { + "level": expected_level, + "source": expected_source, + } + def test_default_cuda_mapping_still_selects_official_image( self, parse_argv, patch_get_client, monkeypatch ): @@ -919,15 +1006,16 @@ def test_cleanup_404_after_destroy_is_not_reported_as_leak( monkeypatch.setattr("vastai.cli.commands.machines.instances_api.show_instance", show) monkeypatch.setattr("vastai.cli.commands.machines.instances_api.destroy_instance", destroy) - args = parse_argv(["self-test", "machine", "42"]) + args = parse_argv(["self-test", "machine", "42", "--log-level", "debug"]) with pytest.raises(SystemExit) as exc_info: args.func(args) captured = capsys.readouterr() assert exc_info.value.code == 1 - assert "Runtime failure diagnostics:" in captured.out - assert "- code: daemon_startup_failed" in captured.out - assert "- remediation: Inspect docker daemon, OCI runtime, and container startup logs." in captured.out + assert "Runtime failure diagnostics" in captured.out + assert " code: daemon_startup_failed" in captured.out + assert " Remediation:" in captured.out + assert " Inspect docker daemon, OCI runtime, and container startup logs." in captured.out assert "WARNING: failed to destroy test instance" not in captured.out assert "api_key=secret" not in captured.out destroy.assert_called_once() @@ -947,7 +1035,7 @@ def test_create_instance_error_redacts_api_key( ) monkeypatch.setattr("vastai.cli.commands.machines.instances_api.create_instance", create) - args = parse_argv(["self-test", "machine", "42"]) + args = parse_argv(["self-test", "machine", "42", "--log-level", "debug"]) with pytest.raises(SystemExit) as exc_info: args.func(args) @@ -1080,15 +1168,16 @@ def test_progress_endpoint_failure_prints_external_port( Mock(side_effect=requests.exceptions.ConnectTimeout("timed out")), ) - args = parse_argv(["self-test", "machine", "42"]) + args = parse_argv(["self-test", "machine", "42", "--log-level", "debug"]) with pytest.raises(SystemExit) as exc_info: args.func(args) captured = capsys.readouterr() assert exc_info.value.code == 1 assert "External port tested: 45000" in captured.out - assert "- external port tested: 45000" in captured.out - assert "- mapped container ports: 22/tcp, 5000/tcp" in captured.out + assert " Connection attempt:" in captured.out + assert " external port tested: 45000" in captured.out + assert " mapped container ports: 22/tcp, 5000/tcp" in captured.out def test_progress_endpoint_lost_after_success_records_different_failure( self, parse_argv, patch_get_client, monkeypatch diff --git a/tests/cli/test_runtime_diagnostics.py b/tests/cli/test_runtime_diagnostics.py index aa9e4e69..6c2cf1fe 100644 --- a/tests/cli/test_runtime_diagnostics.py +++ b/tests/cli/test_runtime_diagnostics.py @@ -171,6 +171,88 @@ def test_status_msg_classifies_generic_daemon_startup_failure(): assert result["underlying_error"] == status_msg +def test_status_msg_classifies_startup_wrapper_build_line(): + status_msg = ( + "#6 [3/6] RUN export DEBIAN_FRONTEND=noninteractive; " + "apt-get update || echo 'V220614a: error during apt-get update!';" + ) + + result = diag.classify_status_msg(status_msg) + + assert result["code"] == diag.DAEMON_STARTUP_FAILED + assert result["stage"] == diag.STAGE_STARTUP + assert result["underlying_error"] == status_msg + + +def test_startup_daemon_log_evidence_distinguishes_apt_success_from_cdi_failure(): + daemon_log = "\n".join( + [ + "#6 [3/6] RUN export DEBIAN_FRONTEND=noninteractive; apt-get update || echo 'V220614a: error during apt-get update!';", + "#6 2.268 Fetched 49.3 MB in 2s (26.6 MB/s)", + "#6 DONE 3.3s", + "Successfully loaded vastai/test:self-test-v2-cuda-11.8", + "Error response from daemon: failed to inject CDI devices: unresolvable CDI devices D.host/gpu=0, D.host/gpu=1, D.host/gpu=2, D.host/gpu=3: unknown", + ] + ) + + evidence = diag.summarize_startup_daemon_log(daemon_log) + + assert evidence["apt_update"]["status"] == "completed" + assert evidence["apt_update"]["error_marker_printed"] is False + assert evidence["cdi_gpu_device_injection"]["gpu_ids"] == ["0", "1", "2", "3"] + assert "completed successfully" in evidence["findings"][0] + + +def test_startup_failure_refinement_prints_host_runtime_cause_for_cdi(): + diagnostic = diag.classify_status_msg( + "#6 [3/6] RUN export DEBIAN_FRONTEND=noninteractive; apt-get update || echo 'V220614a: error during apt-get update!';" + ) + daemon_log = "\n".join( + [ + "#6 [3/6] RUN export DEBIAN_FRONTEND=noninteractive; apt-get update || echo 'V220614a: error during apt-get update!';", + "#6 DONE 3.3s", + "Error response from daemon: failed to inject CDI devices: unresolvable CDI devices D.host/gpu=0: unknown", + ] + ) + + refined = diag.refine_startup_failure_with_daemon_log(diagnostic, daemon_log) + + assert refined["code"] == diag.DAEMON_STARTUP_FAILED + assert refined["summary"] == "Docker/NVIDIA runtime failed before the self-test container could start." + assert "NVIDIA container runtime/CDI" in refined["remediation"] + assert refined["startup_evidence"]["apt_update"]["status"] == "completed" + assert refined["startup_evidence"]["cdi_gpu_device_injection"]["gpu_ids"] == ["0"] + + +def test_startup_failure_refinement_uses_status_message_when_daemon_log_lacks_cdi(): + diagnostic = diag.classify_status_msg( + "Error response from daemon: failed to create task for container: failed to inject CDI devices: " + "unresolvable CDI devices D.host/gpu=0, D.host/gpu=1: unknown" + ) + daemon_log = "container setup log did not include the final status error" + + refined = diag.refine_startup_failure_with_daemon_log(diagnostic, daemon_log) + + assert refined["summary"] == "Docker/NVIDIA runtime failed before the self-test container could start." + assert refined["startup_evidence"]["cdi_gpu_device_injection"]["gpu_ids"] == ["0", "1"] + assert refined["startup_evidence"]["sources"] == ["instance/daemon.log", "instance status message"] + + +def test_startup_daemon_log_evidence_detects_actual_apt_update_marker_output(): + daemon_log = "\n".join( + [ + "#6 [3/6] RUN export DEBIAN_FRONTEND=noninteractive; apt-get update || echo 'V220614a: error during apt-get update!';", + "#6 2.100 V220614a: error during apt-get update!", + "#6 DONE 2.2s", + ] + ) + + evidence = diag.summarize_startup_daemon_log(daemon_log) + + assert evidence["apt_update"]["status"] == "failed" + assert evidence["apt_update"]["error_marker_printed"] is True + + def test_status_msg_classifies_other_errors_as_status_error(): result = diag.classify_status_msg("Error: host reported an unknown fault") diff --git a/tests/cli/test_self_test_support_bundle.py b/tests/cli/test_self_test_support_bundle.py index 4295acd5..acdf739f 100644 --- a/tests/cli/test_self_test_support_bundle.py +++ b/tests/cli/test_self_test_support_bundle.py @@ -105,9 +105,9 @@ def fake_bundle(**kwargs): captured = capsys.readouterr() assert exc_info.value.code == 1 - assert "Self-test diagnostic bundle saved to:" in captured.out - assert "self-test-result.json" in captured.out - assert "Review this tarball before sharing it with support." in captured.out + assert f"Support bundle: {tmp_path / 'vast_selftest_42_20260602T100000Z.tar.gz'}" in captured.out + assert "self-test-result.json" not in captured.out + assert "Next: inspect the support bundle or rerun with --log-level debug" in captured.out def test_self_test_bundle_creation_error_preserves_original_failure( @@ -144,11 +144,11 @@ def test_self_test_bundle_creation_error_preserves_original_failure( captured = capsys.readouterr() assert exc_info.value.code == 1 assert "WARNING: failed to create self-test diagnostic bundle: disk full" in captured.out - assert "Test failed: 8 preflight requirement check(s) failed." in captured.out + assert "Reason: 8 preflight requirement check(s) failed." in captured.out def test_self_test_runtime_failure_bundle_includes_instance_logs( - parse_argv, patch_get_client, monkeypatch, tmp_path + parse_argv, patch_get_client, monkeypatch, tmp_path, capsys ): from vastai.cli.commands import machines @@ -198,7 +198,10 @@ def fake_show_instance(client, id): "id": id, "actual_status": "created", "intended_status": "running", - "status_msg": "docker_build() error writing dockerfile", + "status_msg": ( + "#6 [3/6] RUN export DEBIAN_FRONTEND=noninteractive; " + "apt-get update || echo 'V220614a: error during apt-get update!';" + ), "label": "vast-self-test-machine-42", } @@ -207,7 +210,16 @@ def fake_logs(client, instance_id, tail=None, filter=None, daemon_logs=False): assert instance_id == 123 assert tail == machines.INSTANCE_LOG_TAIL_LINES assert filter is None - return "daemon startup failure" if daemon_logs else "container startup failure" + if daemon_logs: + return "\n".join( + [ + "#6 [3/6] RUN export DEBIAN_FRONTEND=noninteractive; apt-get update || echo 'V220614a: error during apt-get update!';", + "#6 2.268 Fetched 49.3 MB in 2s (26.6 MB/s)", + "#6 DONE 3.3s", + "Error response from daemon: failed to inject CDI devices: unresolvable CDI devices D.host/gpu=0, D.host/gpu=1: unknown", + ] + ) + return "container startup failure" def fake_destroy_instance(client, id): assert client is patch_get_client @@ -222,18 +234,37 @@ def fake_destroy_instance(client, id): monkeypatch.setattr(machines.instances_api, "logs", fake_logs) monkeypatch.setattr(machines.instances_api, "destroy_instance", fake_destroy_instance) - args = parse_argv(["self-test", "machine", "42", "--support-bundle-dir", str(tmp_path)]) + args = parse_argv([ + "self-test", + "machine", + "42", + "--support-bundle-dir", + str(tmp_path), + "--log-level", + "debug", + ]) with pytest.raises(SystemExit) as exc_info: args.func(args) assert exc_info.value.code == 1 + captured = capsys.readouterr() assert 123 in destroyed assert created["include_local_host_artifacts"] is False assert created["result"]["failure_code"] == "daemon_startup_failed" + assert created["result"]["failure"]["summary"] == "Docker/NVIDIA runtime failed before the self-test container could start." + assert created["result"]["failure"]["startup_evidence"]["apt_update"]["status"] == "completed" assert created["extra_files"]["instance/container.log"] == "container startup failure" - assert created["extra_files"]["instance/daemon.log"] == "daemon startup failure" + assert "failed to inject CDI devices" in created["extra_files"]["instance/daemon.log"] assert '"label": "vast-self-test-machine-42"' in created["extra_files"]["instance/show-instance.json"] assert created["extra_errors"] == [] + assert "Runtime failure diagnostics" in captured.out + assert " Result:" in captured.out + assert " What happened:" in captured.out + assert "Vast startup wrapper apt-get update completed successfully." in captured.out + assert "Docker/NVIDIA runtime failed to inject CDI GPU devices for GPUs 0, 1." in captured.out + assert " Where to read next:" in captured.out + assert "instance/daemon.log in the diagnostic bundle" in captured.out + assert "Reason: Docker/NVIDIA runtime failed before the self-test container could start." in captured.out def test_dump_logs_command_creates_cli_visible_bundle(parse_argv, monkeypatch, tmp_path): diff --git a/vastai/cli/commands/machines.py b/vastai/cli/commands/machines.py index dd2f1752..0af11e95 100644 --- a/vastai/cli/commands/machines.py +++ b/vastai/cli/commands/machines.py @@ -4,6 +4,7 @@ import os import sys import time +import textwrap import warnings import argparse from contextlib import redirect_stdout, redirect_stderr @@ -52,6 +53,7 @@ make_progress_endpoint_diagnostic, make_failure, redact_secret_text, + refine_startup_failure_with_daemon_log, ) from vastai.cli.self_test.support_bundle import ( create_support_bundle, @@ -63,6 +65,14 @@ parser = _get_parser() SELF_TEST_INSTANCE_LABEL_PREFIX = "vast-self-test-machine" INSTANCE_LOG_TAIL_LINES = 1000 +SELF_TEST_LOG_LEVELS = ("critical", "error", "warning", "info", "debug") +SELF_TEST_LOG_LEVEL_PRIORITY = { + "debug": 10, + "info": 20, + "warning": 30, + "error": 40, + "critical": 50, +} # --------------------------------------------------------------------------- @@ -609,6 +619,22 @@ def collect_instance_log_artifacts(client, instance_id): return files, errors +def resolve_self_test_log_level(args): + """Resolve self-test log level from CLI args, legacy flag, and env.""" + arg_level = getattr(args, "log_level", None) + if arg_level: + return arg_level.lower(), "argument" + if getattr(args, "debugging", False): + return "debug", "debugging" + env_level = os.environ.get("VAST_LOG_LEVEL") + if env_level: + normalized = env_level.strip().lower() + if normalized in SELF_TEST_LOG_LEVELS: + return normalized, "VAST_LOG_LEVEL" + return "info", "default_invalid_VAST_LOG_LEVEL" + return "info", "default" + + @parser.command( argument("machine_id", help="Machine ID", type=str), argument("--instance-id", help="Instance ID to pull Vast instance logs from", type=int), @@ -699,11 +725,16 @@ def dump_logs(args): @parser.command( argument("machine_id", help="Machine ID", type=str), argument("--debugging", action="store_true", help="Enable debugging output"), + argument( + "--log-level", + choices=SELF_TEST_LOG_LEVELS, + help="Set self-test log level (default: VAST_LOG_LEVEL or info; info is compact, debug shows live diagnostics)", + ), argument("--ignore-requirements", action="store_true", help="Ignore the minimum system requirements and run the self test regardless"), argument("--test-image", help="Use a custom self-test image for testing custom self-test images. Overrides VAST_SELF_TEST_IMAGE and CUDA mapping.", type=str), argument("--support-bundle-dir", help="Directory for failure diagnostic bundles (default: /tmp)", type=str), argument("--no-support-bundle", action="store_true", help="Do not create a diagnostic tarball when the self-test fails"), - usage="vastai self-test machine [--debugging] [--ignore-requirements] [--test-image IMAGE]", + usage="vastai self-test machine [--debugging] [--log-level LEVEL] [--ignore-requirements] [--test-image IMAGE]", help="[Host] Perform a self-test on the specified machine", epilog=deindent(""" This command tests if a machine meets specific requirements and @@ -733,12 +764,21 @@ def self_test__machine(args): if not hasattr(args, 'debugging'): args.debugging = False + if not hasattr(args, 'log_level'): + args.log_level = None if not hasattr(args, 'test_image'): args.test_image = None if not hasattr(args, 'support_bundle_dir'): args.support_bundle_dir = None if not hasattr(args, 'no_support_bundle'): args.no_support_bundle = False + + log_level, log_level_source = resolve_self_test_log_level(args) + args.debugging = args.debugging or log_level == "debug" + result["diagnostics"]["log_level"] = { + "level": log_level, + "source": log_level_source, + } if getattr(args, "ignore_requirements", False): result["warning"] = ignore_requirements_warning result["diagnostics"]["requirements_ignored"] = True @@ -746,7 +786,30 @@ def self_test__machine(args): def output_line(*args_to_print): return " ".join(str(item) for item in args_to_print) + def should_print(level): + return ( + not args.raw + and SELF_TEST_LOG_LEVEL_PRIORITY[level] >= SELF_TEST_LOG_LEVEL_PRIORITY[log_level] + ) + + def emit(level, *args_to_print): + cli_output.append(output_line(*args_to_print)) + if should_print(level): + print(*args_to_print) + def progress_print(*args_to_print): + emit("debug", *args_to_print) + + def info_print(*args_to_print): + emit("info", *args_to_print) + + def warning_print(*args_to_print): + emit("warning", *args_to_print) + + def error_print(*args_to_print): + emit("error", *args_to_print) + + def summary_print(*args_to_print): cli_output.append(output_line(*args_to_print)) if not args.raw: print(*args_to_print) @@ -771,6 +834,13 @@ def collect_instance_logs(inst_id): "files": sorted(instance_log_files.keys()), "collection_errors": instance_log_errors, } + runtime_failure = result.get("diagnostics", {}).get("runtime_failure") + refined_failure = refine_startup_failure_with_daemon_log( + runtime_failure, + instance_log_files.get("instance/daemon.log"), + ) + if refined_failure != runtime_failure: + set_runtime_failure(refined_failure, result.get("reason")) def ensure_support_bundle(): if result.get("success"): @@ -797,7 +867,7 @@ def ensure_support_bundle(): except Exception as e: error = redact_secret_text(e) or "" result["diagnostics"]["support_bundle_error"] = error - progress_print(f"WARNING: failed to create self-test diagnostic bundle: {error}") + warning_print(f"WARNING: failed to create self-test diagnostic bundle: {error}") return None result["diagnostics"]["support_bundle"] = bundle return bundle @@ -807,16 +877,17 @@ def finish_failure(): ensure_support_bundle() return result if result.get("warning"): - print(result["warning"]) + warning_print(result["warning"]) render_runtime_failure() bundle = ensure_support_bundle() - if bundle: - for line in format_bundle_summary(bundle): - print(line) - print(f"Test failed: {result['reason']}") + render_final_summary(bundle=bundle) sys.exit(1) def set_runtime_failure(diagnostic, fallback_reason=None): + diagnostic = refine_startup_failure_with_daemon_log( + diagnostic, + instance_log_files.get("instance/daemon.log"), + ) result["failure"] = diagnostic result["failure_code"] = diagnostic["code"] result["stage"] = diagnostic.get("stage") or result.get("stage") @@ -826,23 +897,103 @@ def set_runtime_failure(diagnostic, fallback_reason=None): def safe_error(error): return redact_secret_text(error) or "" + def failure_display_reason(): + diagnostic = result.get("diagnostics", {}).get("runtime_failure") + if diagnostic and diagnostic.get("summary"): + return diagnostic["summary"] + return result["reason"] + + def render_bundle_summary(bundle): + if not bundle: + return + if log_level == "debug": + for line in format_bundle_summary(bundle): + summary_print(line) + return + summary_print(f"Support bundle: {bundle.get('path')}") + errors = bundle.get("collection_errors") or [] + if errors: + summary_print(f"Bundle collection warnings: {len(errors)} artifact(s) could not be collected.") + + def render_final_summary(bundle=None): + success = bool(result.get("success")) + summary_print("") + summary_print("Self-test summary") + summary_print(f"Status: {'passed' if success else 'failed'}") + summary_print(f"Machine: {args.machine_id}") + if result.get("stage") and not success: + summary_print(f"Failed stage: {result['stage']}") + if result.get("warning"): + summary_print(f"Warning: {result['warning']}") + failed = failed_checks(result.get("checks") or []) + if failed: + summary_print("Failed checks: " + ", ".join(check["title"] for check in failed)) + if success: + if result.get("diagnostics", {}).get("preflight_failure"): + summary_print("Result: runtime checks passed, but requirement checks were ignored.") + summary_print("Next: resolve the failed requirement checks before relying on this for verification.") + else: + summary_print("Result: self-test completed successfully.") + return + summary_print(f"Reason: {failure_display_reason()}") + render_bundle_summary(bundle) + if bundle: + summary_print("Next: inspect the support bundle or rerun with --log-level debug for live details.") + else: + summary_print("Next: rerun with --log-level debug for detailed diagnostics.") + def render_runtime_failure(): diagnostic = result.get("diagnostics", {}).get("runtime_failure") if not diagnostic: return - progress_print("Runtime failure diagnostics:") - progress_print(f"- code: {diagnostic.get('code')}") + + def print_wrapped_lines(text, indent=4, width=100): + prefix = " " * indent + for raw_line in str(text).splitlines() or [""]: + if not raw_line: + progress_print("") + continue + wrapped = textwrap.wrap( + raw_line, + width=width, + initial_indent=prefix, + subsequent_indent=prefix, + break_long_words=True, + break_on_hyphens=False, + ) + for line in wrapped or [prefix + raw_line]: + progress_print(line) + + progress_print("") + progress_print("Runtime failure diagnostics") + progress_print("") + progress_print(" Result:") + progress_print(f" code: {diagnostic.get('code')}") if diagnostic.get("summary"): - progress_print(f"- summary: {diagnostic['summary']}") + progress_print(f" summary: {diagnostic['summary']}") + + evidence = diagnostic.get("startup_evidence") or {} + findings = evidence.get("findings") if isinstance(evidence, dict) else [] + if findings: + progress_print("") + progress_print(" What happened:") + for finding in findings: + progress_print(f" - {finding}") + if diagnostic.get("underlying_error"): - progress_print(f"- underlying error: {diagnostic['underlying_error']}") + progress_print("") + progress_print(" Underlying error:") + print_wrapped_lines(diagnostic["underlying_error"], indent=4) + endpoint = diagnostic.get("progress_endpoint") or result.get("diagnostics", {}).get("progress_endpoint") if endpoint: + progress_print("") + progress_print(" Connection attempt:") if endpoint.get("url"): - progress_print(f"- tried: {endpoint['url']}") + progress_print(f" tried: {endpoint['url']}") external_port = endpoint.get("external_port") or endpoint.get("host_port") if external_port: - progress_print(f"- external port tested: {external_port}") + progress_print(f" external port tested: {external_port}") last_bits = [] if endpoint.get("last_status_code") is not None: last_bits.append(f"HTTP {endpoint['last_status_code']}") @@ -851,17 +1002,29 @@ def render_runtime_failure(): if endpoint.get("last_error"): last_bits.append(str(endpoint["last_error"])) if last_bits: - progress_print(f"- last result: {' - '.join(last_bits)}") + progress_print(f" last result: {' - '.join(last_bits)}") if endpoint.get("mapped_ports"): - progress_print(f"- mapped container ports: {', '.join(endpoint['mapped_ports'])}") + progress_print(f" mapped container ports: {', '.join(endpoint['mapped_ports'])}") + if diagnostic.get("remediation"): - progress_print(f"- remediation: {diagnostic['remediation']}") + progress_print("") + progress_print(" Remediation:") + progress_print(f" {diagnostic['remediation']}") + steps = diagnostic.get("suggested_steps") or [] if steps: - progress_print("- suggested steps:") + progress_print("") + progress_print(" Suggested steps:") for step in steps: - progress_print(f" - {step}") + progress_print(f" - {step}") + + if findings: + progress_print("") + progress_print(" Where to read next:") + progress_print(" - instance/daemon.log in the diagnostic bundle for startup/build details.") + progress_print(" - instance/show-instance.json in the diagnostic bundle for the raw instance status.") + info_print(f"Starting self-test for machine {args.machine_id}.") client = get_client(args) try: @@ -988,6 +1151,7 @@ def selected_offer_for_self_test(machine_id): result["failure_code"] = failure["code"] result["stage"] = "select_offer" result["reason"] = failure["summary"] + info_print("Preflight failed.") render_preflight_failure(args.machine_id, result["checks"], failure, progress_print) return finish_failure() @@ -998,6 +1162,7 @@ def selected_offer_for_self_test(machine_id): if unmet_checks: failure = requirement_failure(checks) result["diagnostics"]["preflight_failure"] = failure + info_print("Preflight failed.") render_preflight_failure(args.machine_id, checks, failure, progress_print) render_preflight_advisories(args.machine_id, checks, progress_print) if not args.ignore_requirements: @@ -1006,12 +1171,13 @@ def selected_offer_for_self_test(machine_id): result["stage"] = "preflight_requirements" result["reason"] = failure["summary"] return finish_failure() - progress_print("Continuing despite unmet requirements because --ignore-requirements is set.") + warning_print("Continuing despite unmet requirements because --ignore-requirements is set.") else: + info_print("Preflight passed.") progress_print(f"Machine ID {args.machine_id} meets all the requirements.") render_preflight_advisories(args.machine_id, checks, progress_print) if args.ignore_requirements: - progress_print(ignore_requirements_warning) + warning_print(ignore_requirements_warning) # ----- CUDA version to docker image mapping ----- def cuda_map_to_image(cuda_version, compute_cap=None): @@ -1113,6 +1279,7 @@ def image_for(version): "label": self_test_label, } + info_print("Creating temporary test instance...") progress_print(f"Starting test with {docker_image} ({image_reason})") rj = instances_api.create_instance( client, @@ -1139,7 +1306,7 @@ def image_for(version): debug_print("Captured instance_info from create_instance:", rj) except Exception as e: error = safe_error(e) - progress_print(f"Error creating instance: {error}") + error_print(f"Error creating instance: {error}") set_runtime_failure( make_failure( INSTANCE_CREATE_FAILED, @@ -1195,19 +1362,15 @@ def destroy_instance_silent(inst_id, collect_logs=False): instances_api.destroy_instance(client, id=inst_id) else: instances_api.destroy_instance(client, id=inst_id) - if not args.raw: - print(f"Instance {inst_id} destroyed successfully on attempt {attempt}.") + info_print(f"Temporary test instance {inst_id} destroyed.") return {"success": True} except Exception as e: - if not args.raw: - print(f"Error destroying instance {inst_id}: {safe_error(e)}") + warning_print(f"WARNING: error destroying test instance {inst_id}: {safe_error(e)}") if attempt < max_retries: - if not args.raw: - print(f"Retrying in 10 seconds... (Attempt {attempt}/{max_retries})") + progress_print(f"Retrying destroy in 10 seconds... (Attempt {attempt}/{max_retries})") time.sleep(10) else: - if not args.raw: - print(f"Failed to destroy instance {inst_id} after {max_retries} attempts.") + warning_print(f"WARNING: failed to destroy test instance {inst_id} after {max_retries} attempts.") return {"success": False, "error": "Max retries exceeded"} # ----- wait for instance to start ----- @@ -1551,6 +1714,7 @@ def is_instance(iid): delay = "15" result["phase"] = "test" result["stage"] = "run_machinetester" + info_print("Running self-test...") success, reason, runtime_diagnostic = run_machinetester( ip_address, port, instance_id, args.machine_id, delay, mapped_ports=all_ports, ) @@ -1569,7 +1733,7 @@ def is_instance(iid): "Interrupted by user (Ctrl+C)", ) result["error"] = result["reason"] - progress_print("\nInterrupted — cleaning up test instance...") + warning_print("\nInterrupted - cleaning up test instance...") except Exception as e: error = safe_error(e) result["success"] = False @@ -1597,12 +1761,12 @@ def is_instance(iid): if info and status not in ('destroyed', 'terminated', 'offline'): if not result.get("success"): collect_instance_logs(instance_id) - progress_print(f"Destroying test instance {instance_id} (status: {status})...") + info_print(f"Cleaning up temporary test instance {instance_id} (status: {status})...") instances_api.destroy_instance(client, id=instance_id) - progress_print(f"Test instance {instance_id} destroyed.") + info_print(f"Temporary test instance {instance_id} destroyed.") except KeyboardInterrupt: - progress_print( - f"\nSecond interrupt during cleanup — instance {instance_id} may still be running.\n" + warning_print( + f"\nSecond interrupt during cleanup - instance {instance_id} may still be running.\n" f" Destroy it manually: vastai destroy instance {instance_id}" ) raise @@ -1610,12 +1774,12 @@ def is_instance(iid): if e.response is not None and e.response.status_code == 404: debug_print(f"Test instance {instance_id} already gone during cleanup.") else: - progress_print( + warning_print( f"WARNING: failed to destroy test instance {instance_id}: {safe_error(e)}\n" f" Destroy it manually: vastai destroy instance {instance_id}" ) except Exception as e: - progress_print( + warning_print( f"WARNING: failed to destroy test instance {instance_id}: {safe_error(e)}\n" f" Destroy it manually: vastai destroy instance {instance_id}" ) @@ -1626,19 +1790,11 @@ def is_instance(iid): return result else: if result.get("warning"): - print(result["warning"]) + warning_print(result["warning"]) if result["success"]: - if result.get("diagnostics", {}).get("preflight_failure"): - print("Runtime checks passed, but minimum requirement checks were ignored.") - print("This run does not qualify the machine for verification.") - else: - print("Test completed successfully.") + render_final_summary() sys.exit(0) - else: - render_runtime_failure() - bundle = ensure_support_bundle() - if bundle: - for line in format_bundle_summary(bundle): - print(line) - print(f"Test failed: {result['reason']}") - sys.exit(1) + render_runtime_failure() + bundle = ensure_support_bundle() + render_final_summary(bundle=bundle) + sys.exit(1) diff --git a/vastai/cli/self_test/runtime_diagnostics.py b/vastai/cli/self_test/runtime_diagnostics.py index 604b4210..d2b9b78f 100644 --- a/vastai/cli/self_test/runtime_diagnostics.py +++ b/vastai/cli/self_test/runtime_diagnostics.py @@ -253,6 +253,20 @@ class FailureCatalogEntry: r"docker|exited|exec format error|permission denied|mount|entrypoint", re.IGNORECASE, ) +_STARTUP_WRAPPER_RE = re.compile( + r"V220614a|apt-get update|dockerfile|buildkit|\brun export DEBIAN_FRONTEND\b", + re.IGNORECASE, +) +_APT_UPDATE_STEP_RE = re.compile( + r"(?P#\d+).*?\[[^\]]+\]\s+RUN\b.*?apt-get update\b.*?V220614a", + re.IGNORECASE, +) +_APT_UPDATE_ERROR_OUTPUT_RE = re.compile( + r"#\d+\s+\d+(?:\.\d+)?\s+V220614a:\s+error during apt-get update", + re.IGNORECASE, +) +_CDI_DEVICE_RE = re.compile(r"failed to inject CDI devices.*?(?:unresolvable CDI devices\s+)?(?P[^\n]+)", re.IGNORECASE) +_GPU_ID_RE = re.compile(r"gpu=(\d+)") _API_KEY_RE = re.compile(r"([?&]api_key=)[^&\s]+") @@ -426,6 +440,132 @@ def parse_legacy_progress(text: str) -> list[dict[str, object]]: return LegacyProgressParser().parse(text) +def _unique_sorted_gpu_ids(text: str) -> list[str]: + return sorted(set(_GPU_ID_RE.findall(text)), key=lambda value: int(value)) + + +def summarize_startup_daemon_log(startup_text: str | None) -> dict[str, object] | None: + """Extract high-signal startup findings from daemon logs or status text.""" + if not startup_text: + return None + + findings: list[str] = [] + evidence: dict[str, object] = { + "source": "startup logs/status", + "findings": findings, + } + + apt_step = _APT_UPDATE_STEP_RE.search(startup_text) + if apt_step: + step_id = apt_step.group("step") + step_lines = [line for line in startup_text.splitlines() if step_id in line] + apt_update = { + "command_seen": True, + "step": step_id, + "fetched_packages": any("Fetched " in line for line in step_lines), + "completed": any(f"{step_id} DONE" in line for line in step_lines), + "error_marker_printed": any( + _APT_UPDATE_ERROR_OUTPUT_RE.search(line) for line in step_lines + ), + } + if apt_update["error_marker_printed"]: + apt_update["status"] = "failed" + findings.append("Vast startup wrapper apt-get update printed the V220614a failure marker.") + elif apt_update["completed"]: + apt_update["status"] = "completed" + findings.append("Vast startup wrapper apt-get update completed successfully.") + else: + apt_update["status"] = "unknown" + findings.append( + "Vast startup wrapper apt-get update was the visible build step, " + "but the daemon log does not show whether it completed." + ) + evidence["apt_update"] = apt_update + + cdi_match = _CDI_DEVICE_RE.search(startup_text) + if cdi_match: + gpu_ids = _unique_sorted_gpu_ids(cdi_match.group("devices")) + cdi_evidence = { + "failed": True, + "gpu_ids": gpu_ids, + } + evidence["cdi_gpu_device_injection"] = cdi_evidence + if gpu_ids: + findings.append( + "Docker/NVIDIA runtime failed to inject CDI GPU devices for GPUs " + f"{', '.join(gpu_ids)}." + ) + else: + findings.append("Docker/NVIDIA runtime failed to inject CDI GPU devices.") + findings.append("The self-test runtime did not start; this happened before the test scripts ran.") + findings.append("This is probably host daemon/NVIDIA runtime state, not a self-test image failure.") + + if not findings: + return None + return evidence + + +def refine_startup_failure_with_daemon_log( + diagnostic: dict[str, object] | None, + daemon_log: str | None, +) -> dict[str, object] | None: + """Attach startup evidence and refine common startup failure wording.""" + if not diagnostic: + return diagnostic + + diagnostic_text = "\n".join( + str(diagnostic.get(key) or "") + for key in ("underlying_error", "error", "details") + if diagnostic.get(key) + ) + startup_text = "\n".join(text for text in (daemon_log, diagnostic_text) if text) + evidence = summarize_startup_daemon_log(startup_text) + if not evidence: + return diagnostic + evidence["sources"] = [ + source + for source, text in ( + ("instance/daemon.log", daemon_log), + ("instance status message", diagnostic_text), + ) + if text + ] + + refined = dict(diagnostic) + refined["startup_evidence"] = evidence + + cdi = evidence.get("cdi_gpu_device_injection") + apt_update = evidence.get("apt_update") + if isinstance(cdi, dict) and cdi.get("failed"): + refined["code"] = DAEMON_STARTUP_FAILED + refined["summary"] = "Docker/NVIDIA runtime failed before the self-test container could start." + refined["remediation"] = ( + "Check the host NVIDIA container runtime/CDI device configuration and daemon health." + ) + refined["suggested_steps"] = [ + "Check docker/kaalia daemon logs on the host.", + "Run nvidia-smi and verify all GPUs are visible to the container runtime.", + "Restart or repair the NVIDIA container runtime/CDI configuration before retrying self-test.", + ] + elif isinstance(apt_update, dict) and apt_update.get("status") == "failed": + refined["code"] = DAEMON_STARTUP_FAILED + refined["summary"] = "The Vast startup wrapper failed while updating packages." + refined["remediation"] = ( + "Check host outbound networking, DNS, apt repository reachability, and Docker build logs." + ) + refined["suggested_steps"] = [ + "Retry once to rule out a transient repository/network failure.", + "Check host DNS and outbound HTTPS access from Docker builds.", + "Inspect the daemon log in the diagnostic bundle for apt errors.", + ] + elif isinstance(apt_update, dict): + refined["code"] = DAEMON_STARTUP_FAILED + refined["summary"] = "The instance failed during Vast startup wrapper build/startup." + refined["remediation"] = "Inspect the daemon log in the diagnostic bundle for the real startup error." + + return refined + + def classify_status_msg(status_msg: str | None) -> dict[str, object] | None: """Classify startup/status messages reported while the instance starts.""" if not status_msg: @@ -438,7 +578,7 @@ def classify_status_msg(status_msg: str | None) -> dict[str, object] | None: code = INSTANCE_STATUS_ERROR if _DOCKER_PULL_RE.search(msg): code = DOCKER_PULL_FAILED - elif _STARTUP_RE.search(msg): + elif _STARTUP_RE.search(msg) or _STARTUP_WRAPPER_RE.search(msg): code = DAEMON_STARTUP_FAILED return make_failure( @@ -492,5 +632,7 @@ def classify_status_msg(status_msg: str | None) -> dict[str, object] | None: "make_progress_endpoint_diagnostic", "parse_legacy_progress", "redact_secret_text", + "refine_startup_failure_with_daemon_log", "stage_from_progress_line", + "summarize_startup_daemon_log", ]