diff --git a/scripts/test/tophat_diagnostics_test.rb b/scripts/test/tophat_diagnostics_test.rb new file mode 100644 index 000000000..a87e4c582 --- /dev/null +++ b/scripts/test/tophat_diagnostics_test.rb @@ -0,0 +1,116 @@ +# frozen_string_literal: true + +require "minitest/autorun" +require "time" +require_relative "../tophat/diagnostics" + +class TophatDiagnosticsTest < Minitest::Test + THREE_OK_THEN_404 = <<~LOG + 2026-08-07 10:15:30.111111-0700 0x2a3 Info 0x0 1111 0 TophatBitriseExtension: task_1 received response, status 200 + 2026-08-07 10:15:30.222222-0700 0x2a3 Info 0x0 1111 0 TophatBitriseExtension: task_2 received response, status 200 + 2026-08-07 10:15:30.333333-0700 0x2a3 Info 0x0 1111 0 TophatBitriseExtension: task_3 received response, status 200 + 2026-08-07 10:15:31.444444-0700 0x2a3 Info 0x0 1111 0 TophatBitriseExtension: task_4 received response, status 404 + LOG + + ONLY_OK = <<~LOG + 2026-08-07 10:15:30.111111-0700 0x2a3 Info 0x0 1111 0 TophatBitriseExtension: task_1 received response, status 200 + 2026-08-07 10:15:30.222222-0700 0x2a3 Info 0x0 1111 0 TophatBitriseExtension: task_2 received response, status 200 + LOG + + TWO_DIFFERENT_NON_2XX = <<~LOG + 2026-08-07 10:15:30.111111-0700 0x2a3 Info 0x0 1111 0 Tophat: task_1 received response, status 401 + 2026-08-07 10:15:31.222222-0700 0x2a3 Info 0x0 1111 0 TophatBitriseExtension: task_2 received response, status 404 + LOG + + NO_PROCESS_NAME_LINE = "some tool: task_1 received response, status 500\n" + + def test_parse_log_output_returns_empty_array_for_nil + assert_equal [], TophatDiagnostics.parse_log_output(nil) + end + + def test_parse_log_output_returns_empty_array_for_empty_string + assert_equal [], TophatDiagnostics.parse_log_output("") + end + + def test_parse_log_output_returns_empty_array_when_only_2xx_statuses_present + assert_equal [], TophatDiagnostics.parse_log_output(ONLY_OK) + end + + def test_parse_log_output_extracts_single_non_2xx_finding_with_process_and_status + findings = TophatDiagnostics.parse_log_output(THREE_OK_THEN_404) + assert_equal 1, findings.length + assert_equal 404, findings.first.status + assert_equal "TophatBitriseExtension", findings.first.process + end + + def test_parse_log_output_extracts_multiple_non_2xx_findings_in_order + findings = TophatDiagnostics.parse_log_output(TWO_DIFFERENT_NON_2XX) + assert_equal [401, 404], findings.map(&:status) + end + + def test_parse_log_output_ignores_2xx_lines_interleaved_with_non_2xx + findings = TophatDiagnostics.parse_log_output(THREE_OK_THEN_404) + assert_equal [404], findings.map(&:status) + end + + def test_parse_log_output_returns_empty_array_for_malformed_log_text + assert_equal [], TophatDiagnostics.parse_log_output("this log line has nothing useful in it\n") + end + + def test_parse_log_output_falls_back_to_tophat_when_process_name_absent_from_line + findings = TophatDiagnostics.parse_log_output(NO_PROCESS_NAME_LINE) + assert_equal "Tophat", findings.first.process + end + + def test_most_recent_finding_returns_last_of_multiple + findings = TophatDiagnostics.parse_log_output(TWO_DIFFERENT_NON_2XX) + assert_equal 404, TophatDiagnostics.most_recent_finding(findings).status + end + + def test_most_recent_finding_returns_nil_for_empty_array + assert_nil TophatDiagnostics.most_recent_finding([]) + end + + def test_format_diagnostic_message_for_404_uses_specific_hint_and_emoji + finding = TophatDiagnostics.parse_log_output(THREE_OK_THEN_404).first + message = TophatDiagnostics.format_diagnostic_message(finding) + assert message.start_with?("🔴 Diagnostics: Tophat's Bitrise helper received HTTP 404") + assert_includes message, "artifact expired" + end + + def test_format_diagnostic_message_for_unmapped_status_uses_generic_hint + finding = TophatDiagnostics::Finding.new(status: 500, process: "Tophat", line: "irrelevant") + message = TophatDiagnostics.format_diagnostic_message(finding) + assert_includes message, TophatDiagnostics::DEFAULT_HINT + refute_includes message, "artifact expired" + end + + def test_log_show_argv_includes_predicate_and_formatted_start_time + start_time = Time.new(2026, 8, 7, 10, 0, 0, "-07:00") + argv = TophatDiagnostics.log_show_argv(start_time: start_time) + assert_equal ["--predicate", %(process CONTAINS "Tophat")], argv[2, 2] + assert_equal ["--start", "2026-08-07 10:00:00-0700"], argv[4, 2] + end + + def test_log_show_argv_joins_multiple_process_names_with_or + start_time = Time.new(2026, 8, 7, 10, 0, 0, "-07:00") + argv = TophatDiagnostics.log_show_argv(start_time: start_time, processes: ["Tophat", "OtherProc"]) + assert_equal %(process CONTAINS "Tophat" OR process CONTAINS "OtherProc"), argv[3] + end + + def test_capture_returns_stdout_for_a_successful_command + assert_equal "hello\n", TophatDiagnostics.capture(["/bin/echo", "hello"]) + end + + def test_capture_returns_nil_for_missing_binary + assert_nil TophatDiagnostics.capture(["/no/such/binary-xyz"]) + end + + def test_capture_returns_nil_on_nonzero_exit + assert_nil TophatDiagnostics.capture(["/usr/bin/false"]) + end + + def test_capture_returns_nil_on_timeout + assert_nil TophatDiagnostics.capture(["/bin/sleep", "2"], timeout_seconds: 0.2) + end +end diff --git a/scripts/tophat/dev_tophat b/scripts/tophat/dev_tophat index 25648aa3a..755c7489c 100755 --- a/scripts/tophat/dev_tophat +++ b/scripts/tophat/dev_tophat @@ -6,6 +6,7 @@ require_relative "common" require_relative "bitrise_client" require_relative "bitrise_auth" require_relative "build_state" +require_relative "diagnostics" WAIT_POLL_SECONDS = 30 WAIT_TIMEOUT_SECONDS = 1800 @@ -240,10 +241,16 @@ def reverify_head!(client, option, pr) abort_with("The build finished but produced no HEAD artifact for #{option.fetch("label")}. Check the Bitrise build logs.") end -def ensure_installable(option, manifest, pr, wait:) +def ensure_installable(option, manifest, pr, wait:, force_rebuild:) app_slug = manifest.fetch("app_slug") client = BitriseClient.new(token: BitriseAuth.resolve_token(app_slug), app_slug: app_slug, retries: BITRISE_API_RETRIES) + if force_rebuild + puts "==> Forcing a fresh Bitrise build for #{option.fetch("label")}." + await_head_build(client, option, pr) { trigger_head_builds(client, option, pr) } + return + end + puts "==> Checking Bitrise: #{option.fetch("label")} @ HEAD #{TophatBuildState.short_sha(pr.fetch("sha"))}…" evaluations = verify_bitrise_state(client, option, pr) state = TophatBuildState.combine(evaluations) @@ -369,14 +376,25 @@ def run_tophat_install(config_path, stream: true) [output, status] end -def install_with_tophat(config_path, app_slug) - output, status = run_tophat_install(config_path, stream: false) +def report_install_diagnostics(attempt_started_at, verbose:) + raw_log = TophatDiagnostics.capture_raw_log(start_time: attempt_started_at) + puts raw_log if verbose && raw_log + finding = TophatDiagnostics.most_recent_finding(TophatDiagnostics.parse_log_output(raw_log)) + puts TophatDiagnostics.format_diagnostic_message(finding) if finding +rescue StandardError + nil +end + +def install_with_tophat(config_path, app_slug, verbose: false) + attempt_started_at = Time.now - 5 + output, status = run_tophat_install(config_path, stream: verbose) if status.success? - print output + print output unless verbose return true end unless bitrise_auth_error?(output) - print output + print output unless verbose + report_install_diagnostics(attempt_started_at, verbose: verbose) return false end @@ -420,6 +438,8 @@ def print_help(manifest) built at the PR's HEAD commit. If it was not, it shows what CI currently has and lets you trigger a HEAD build and wait (~6 min), wait for a HEAD build that is already running, or knowingly install the current (older) build. + Pass --force-rebuild to skip this check and always trigger a fresh HEAD + build and wait for it, even if a build already looks ready. Arguments: Optional pull request number or GitHub pull request URL. @@ -432,8 +452,14 @@ def print_help(manifest) --wait Non-interactively ensure the HEAD build: wait for a HEAD build that is already running, or trigger one and wait, then install. Skips the menu. + --force-rebuild Always trigger a fresh Bitrise build and wait for it before + installing, even if the HEAD build already looks ready. + Useful when the last install failed with a stale or + missing artifact. --clear-token Remove dev tophat's saved Bitrise token from your keychain (does not change Tophat's own token) and exit. + --verbose Stream tophatctl's install output live, print the generated + config, and show the raw diagnostic log on failure. -h, --help Show this help. Available targets (pass as the argument): @@ -445,6 +471,7 @@ def print_help(manifest) dev tophat 382 react-native-ios dev tophat 382 s dev tophat --wait 382 + dev tophat --force-rebuild 382 dev tophat https://github.com/Shopify/checkout-kit/pull/382 Environment: @@ -471,6 +498,8 @@ def main end wait_flag = extract_flag("--wait") + force_rebuild_flag = extract_flag("--force-rebuild") + verbose_flag = extract_flag("--verbose") CheckoutKitTophat.require_tophat! @@ -478,7 +507,9 @@ def main pr = pr_metadata(pr_number) options = CheckoutKitTophat.install_options(manifest) option = select_option(options, ARGV[1]) - ensure_installable(option, manifest, pr, wait: wait_flag) unless skip_artifact_check? + unless skip_artifact_check? + ensure_installable(option, manifest, pr, wait: wait_flag, force_rebuild: force_rebuild_flag) + end device = select_device(option.fetch("platform")) recipe = recipe_for(option.fetch("target"), device) @@ -488,15 +519,15 @@ def main puts " Device: #{device.fetch("name")} #{device.fetch("runtimeVersion")} (#{device.fetch("type")})" puts " Artifact: #{recipe.fetch("artifact_name")}" - if ENV["TOPHAT_DRY_RUN"] == "1" + if verbose_flag || ENV["TOPHAT_DRY_RUN"] == "1" puts JSON.pretty_generate(config) - exit 0 + exit 0 if ENV["TOPHAT_DRY_RUN"] == "1" end Tempfile.create(["tophat-install", ".json"]) do |file| file.write(JSON.generate(config)) file.flush - install_with_tophat(file.path, manifest.fetch("app_slug")) || abort_with("Tophat install failed.") + install_with_tophat(file.path, manifest.fetch("app_slug"), verbose: verbose_flag) || abort_with("Tophat install failed.") puts "✅ Installed #{option.fetch("label")} to #{device.fetch("name")}." end end diff --git a/scripts/tophat/diagnostics.rb b/scripts/tophat/diagnostics.rb new file mode 100644 index 000000000..3acd3fb47 --- /dev/null +++ b/scripts/tophat/diagnostics.rb @@ -0,0 +1,86 @@ +# frozen_string_literal: true + +require "open3" +require "time" + +# Pure parsing of macOS unified log text for Tophat's Bitrise helper HTTP +# activity, plus a generic timeout-guarded shell-out used to fetch that text. +# tophatctl itself has no verbose/debug flag, so this is the only visibility +# into why an install actually failed. +module TophatDiagnostics + module_function + + LOG_SHOW_BIN = "/usr/bin/log" + PROCESS_NAMES = ["Tophat"].freeze + KNOWN_PROCESS_LABELS = ["TophatBitriseExtension", "Tophat"].freeze + STATUS_LINE_PATTERN = /received response,\s*status\s+(\d{3})\b/i + LOG_TIMEOUT_SECONDS = 8 + + STATUS_HINTS = { + 404 => "This usually means the artifact expired or no longer matches. Run\n dev tophat --force-rebuild to trigger a fresh build and retry." + }.freeze + DEFAULT_HINT = "Try re-running dev tophat; if it persists, check the Bitrise build/artifact directly." + + Finding = Struct.new(:status, :process, :line, keyword_init: true) + + def parse_log_output(text) + return [] if text.nil? || text.strip.empty? + + text.each_line.filter_map do |line| + match = STATUS_LINE_PATTERN.match(line) + next unless match + + status = match[1].to_i + next if (200..299).cover?(status) + + process = KNOWN_PROCESS_LABELS.find { |name| line.include?(name) } || "Tophat" + Finding.new(status: status, process: process, line: line.strip) + end + end + + def most_recent_finding(findings) + findings.last + end + + def log_show_argv(start_time:, processes: PROCESS_NAMES, style: "compact") + predicate = processes.map { |name| %(process CONTAINS "#{name}") }.join(" OR ") + [LOG_SHOW_BIN, "show", "--predicate", predicate, "--start", format_start_time(start_time), "--style", style] + end + + def format_start_time(time) + time.strftime("%Y-%m-%d %H:%M:%S%z") + end + + def format_diagnostic_message(finding) + hint = STATUS_HINTS.fetch(finding.status, DEFAULT_HINT) + "🔴 Diagnostics: Tophat's Bitrise helper received HTTP #{finding.status} while installing.\n #{hint}" + end + + def capture_raw_log(start_time:, timeout_seconds: LOG_TIMEOUT_SECONDS) + capture(log_show_argv(start_time: start_time), timeout_seconds: timeout_seconds) + end + + def capture(argv, timeout_seconds: LOG_TIMEOUT_SECONDS) + output = +"" + Open3.popen2e(*argv) do |stdin, out, wait_thread| + stdin.close + reader = Thread.new { out.each_line { |line| output << line } } + unless wait_thread.join(timeout_seconds) + kill(wait_thread.pid) + reader.kill + return nil + end + reader.join + return nil unless wait_thread.value.success? + end + output + rescue Errno::ENOENT, Errno::EACCES, SystemCallError + nil + end + + def kill(pid) + Process.kill("TERM", pid) + rescue Errno::ESRCH + nil + end +end