diff --git a/actions/setup/js/copilot_driver.cjs b/actions/setup/js/copilot_driver.cjs index 9fd8894cbc..48cf9992aa 100644 --- a/actions/setup/js/copilot_driver.cjs +++ b/actions/setup/js/copilot_driver.cjs @@ -25,6 +25,7 @@ "use strict"; const { spawn } = require("child_process"); +const fs = require("fs"); // Maximum number of retry attempts after the initial run const MAX_RETRIES = 3; @@ -67,6 +68,29 @@ function sleep(ms) { return new Promise(resolve => setTimeout(resolve, ms)); } +/** + * Check whether a command path is accessible and executable, logging the result. + * Returns true if the command is usable, false otherwise. + * @param {string} command - Absolute or relative path to the executable + * @returns {Promise} + */ +async function checkCommandAccessible(command) { + try { + await fs.promises.access(command, fs.constants.F_OK); + } catch { + log(`pre-flight: command not found: ${command} (F_OK check failed — binary does not exist at this path)`); + return false; + } + try { + await fs.promises.access(command, fs.constants.X_OK); + log(`pre-flight: command is accessible and executable: ${command}`); + return true; + } catch { + log(`pre-flight: command exists but is not executable: ${command} (X_OK check failed — permission denied)`); + return false; + } +} + /** * Format elapsed milliseconds as a human-readable string (e.g. "3m 12s"). * @param {number} ms @@ -148,7 +172,11 @@ function runProcess(command, args, attempt) { child.on("error", err => { const durationMs = Date.now() - startTime; - log(`attempt ${attempt + 1}: failed to start process '${command}': ${err.message}`); + // prettier-ignore + const errno = /** @type {NodeJS.ErrnoException} */ (err); + const errCode = errno.code ?? "unknown"; + const errSyscall = errno.syscall ?? "unknown"; + log(`attempt ${attempt + 1}: failed to start process '${command}': ${err.message}` + ` (code=${errCode} syscall=${errSyscall})`); resolve({ exitCode: 1, output: collectedOutput, @@ -170,7 +198,9 @@ async function main() { process.exit(1); } - log(`starting: command=${command} maxRetries=${MAX_RETRIES} initialDelayMs=${INITIAL_DELAY_MS} backoffMultiplier=${BACKOFF_MULTIPLIER} maxDelayMs=${MAX_DELAY_MS}`); + log(`starting: command=${command} maxRetries=${MAX_RETRIES} initialDelayMs=${INITIAL_DELAY_MS}` + ` backoffMultiplier=${BACKOFF_MULTIPLIER} maxDelayMs=${MAX_DELAY_MS}` + ` nodeVersion=${process.version} platform=${process.platform}`); + + await checkCommandAccessible(command); let delay = INITIAL_DELAY_MS; let lastExitCode = 1; @@ -212,7 +242,7 @@ async function main() { if (attempt >= MAX_RETRIES) { log(`all ${MAX_RETRIES} retries exhausted — giving up (exitCode=${lastExitCode})`); } else { - log(`attempt ${attempt + 1}: no output produced — not retrying (process may have failed to start)`); + log(`attempt ${attempt + 1}: no output produced — not retrying` + ` (possible causes: binary not found, permission denied, auth failure, or silent startup crash)`); } // Non-retryable error or retries exhausted — propagate exit code diff --git a/actions/setup/js/copilot_driver.test.cjs b/actions/setup/js/copilot_driver.test.cjs index d01e0626a8..f3d296b583 100644 --- a/actions/setup/js/copilot_driver.test.cjs +++ b/actions/setup/js/copilot_driver.test.cjs @@ -153,4 +153,35 @@ describe("copilot_driver.cjs", () => { expect(logLine).toMatch(/^\[copilot-driver\] \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}/); }); }); + + describe("startup log includes node version and platform", () => { + it("starting log line contains nodeVersion and platform fields", () => { + const command = "/usr/local/bin/copilot"; + const startingLine = `starting: command=${command} maxRetries=3 initialDelayMs=5000` + ` backoffMultiplier=2 maxDelayMs=60000` + ` nodeVersion=${process.version} platform=${process.platform}`; + expect(startingLine).toContain("nodeVersion="); + expect(startingLine).toContain("platform="); + expect(startingLine).toMatch(/nodeVersion=v\d+\.\d+/); + }); + }); + + describe("no-output failure message", () => { + it("includes actionable possible causes", () => { + const msg = `attempt 1: no output produced — not retrying` + ` (possible causes: binary not found, permission denied, auth failure, or silent startup crash)`; + expect(msg).toContain("binary not found"); + expect(msg).toContain("permission denied"); + expect(msg).toContain("auth failure"); + expect(msg).toContain("silent startup crash"); + }); + }); + + describe("error event message", () => { + it("includes code and syscall fields", () => { + const errMessage = "spawn /usr/local/bin/copilot ENOENT"; + const errCode = "ENOENT"; + const errSyscall = "spawn"; + const logMsg = `attempt 1: failed to start process '/usr/local/bin/copilot': ${errMessage}` + ` (code=${errCode} syscall=${errSyscall})`; + expect(logMsg).toContain("code=ENOENT"); + expect(logMsg).toContain("syscall=spawn"); + }); + }); }); diff --git a/pkg/cli/audit.go b/pkg/cli/audit.go index abacfc0ca7..d90aa99f9a 100644 --- a/pkg/cli/audit.go +++ b/pkg/cli/audit.go @@ -636,6 +636,7 @@ func auditJobRun(runID int64, jobID int64, stepNumber int, owner, repo, hostname // extractStepOutput extracts the output of a specific step from job logs func extractStepOutput(jobLog string, stepNumber int) (string, error) { + auditLog.Printf("Extracting output for step %d from job logs (%d bytes)", stepNumber, len(jobLog)) lines := strings.Split(jobLog, "\n") var stepOutput []string inStep := false @@ -662,14 +663,17 @@ func extractStepOutput(jobLog string, stepNumber int) (string, error) { } if len(stepOutput) == 0 { + auditLog.Printf("Step %d not found in job logs (scanned %d lines)", stepNumber, len(lines)) return "", fmt.Errorf("step %d not found in job logs", stepNumber) } + auditLog.Printf("Extracted %d lines for step %d", len(stepOutput), stepNumber) return strings.Join(stepOutput, "\n"), nil } // findFirstFailingStep finds the first step that failed in the job logs func findFirstFailingStep(jobLog string) (int, string) { + auditLog.Printf("Searching for first failing step in job logs (%d bytes)", len(jobLog)) lines := strings.Split(jobLog, "\n") var stepOutput []string inStep := false @@ -700,9 +704,11 @@ func findFirstFailingStep(jobLog string) (int, string) { } if foundFailure && len(stepOutput) > 0 { + auditLog.Printf("Found failing step %d with %d lines of output", currentStep, len(stepOutput)) return currentStep, strings.Join(stepOutput, "\n") } + auditLog.Print("No failing step found in job logs") return 0, "" } diff --git a/pkg/cli/deps_security.go b/pkg/cli/deps_security.go index a71cb491b6..71304dd2c1 100644 --- a/pkg/cli/deps_security.go +++ b/pkg/cli/deps_security.go @@ -134,6 +134,7 @@ func querySecurityAdvisories(depVersions map[string]string, verbose bool) ([]Sec // GitHub Security Advisory API endpoint url := "https://api.github.com/advisories?ecosystem=go&per_page=100" + depsSecurityLog.Printf("Querying GitHub Security Advisory API: url=%s, dep_count=%d", url, len(depVersions)) client := &http.Client{Timeout: 30 * time.Second} req, err := http.NewRequest(http.MethodGet, url, nil) if err != nil { @@ -190,6 +191,7 @@ func querySecurityAdvisories(depVersions map[string]string, verbose bool) ([]Sec adv.PatchedVers = []string{vuln.FirstPatchedVersion} } + depsSecurityLog.Printf("Advisory matched dependency: package=%s, version=%s, severity=%s, id=%s", vuln.Package.Name, currentVersion, apiAdv.Severity, apiAdv.GHSAID) matchingAdvisories = append(matchingAdvisories, adv) if verbose { diff --git a/pkg/cli/firewall_policy.go b/pkg/cli/firewall_policy.go index ad10cb0c9c..f2210807c2 100644 --- a/pkg/cli/firewall_policy.go +++ b/pkg/cli/firewall_policy.go @@ -271,6 +271,7 @@ func findMatchingRule(entry AuditLogEntry, rules []PolicyRule) *PolicyRule { if isEntryAllowed(entry) { expectedAction = "allow" } + firewallPolicyLog.Printf("Finding matching rule for host=%s, expected_action=%s, rules=%d", entry.Host, expectedAction, len(rules)) for i := range rules { rule := &rules[i] @@ -283,6 +284,7 @@ func findMatchingRule(entry AuditLogEntry, rules []PolicyRule) *PolicyRule { // aclName "all" is a catch-all rule (typically the default deny) if rule.ACLName == "all" { if rule.Action == expectedAction { + firewallPolicyLog.Printf("Matched catch-all rule (action=%s) for host=%s", rule.Action, entry.Host) return rule } continue @@ -291,10 +293,12 @@ func findMatchingRule(entry AuditLogEntry, rules []PolicyRule) *PolicyRule { // Domain match if domainMatchesRule(entry.Host, *rule) { if rule.Action == expectedAction { + firewallPolicyLog.Printf("Matched rule %s (action=%s) for host=%s", rule.ACLName, rule.Action, entry.Host) return rule } } } + firewallPolicyLog.Printf("No matching rule found for host=%s", entry.Host) return nil } diff --git a/pkg/cli/mcp_safe_update_cache.go b/pkg/cli/mcp_safe_update_cache.go index 856830bb48..a776f985cb 100644 --- a/pkg/cli/mcp_safe_update_cache.go +++ b/pkg/cli/mcp_safe_update_cache.go @@ -59,6 +59,7 @@ func CollectLockFileManifests(workflowsDir string) map[string]*workflow.GHAWMani // WritePriorManifestFile serialises the manifest cache to a temporary JSON file and // returns its path. The caller is responsible for removing the file when done. func WritePriorManifestFile(cache map[string]*workflow.GHAWManifest) (string, error) { + mcpLog.Printf("Writing prior manifest cache to temp file: %d entries", len(cache)) data, err := json.Marshal(cache) if err != nil { return "", fmt.Errorf("marshal manifest cache: %w", err) @@ -75,5 +76,6 @@ func WritePriorManifestFile(cache map[string]*workflow.GHAWManifest) (string, er return "", fmt.Errorf("write manifest cache file: %w", err) } + mcpLog.Printf("Prior manifest cache written to: %s (%d bytes)", f.Name(), len(data)) return f.Name(), nil } diff --git a/pkg/cli/workflows.go b/pkg/cli/workflows.go index 4fc716008d..0efdb3e66e 100644 --- a/pkg/cli/workflows.go +++ b/pkg/cli/workflows.go @@ -242,8 +242,11 @@ func suggestWorkflowNames(target string) []string { // Normalize target: strip .md extension and get basename if it's a path normalizedTarget := strings.TrimSuffix(filepath.Base(target), ".md") + workflowsLog.Printf("Suggesting workflow names for %q (available: %d)", normalizedTarget, len(availableNames)) // Use the existing FindClosestMatches function from parser package - return parser.FindClosestMatches(normalizedTarget, availableNames, 3) + suggestions := parser.FindClosestMatches(normalizedTarget, availableNames, 3) + workflowsLog.Printf("Found %d suggestion(s) for %q: %v", len(suggestions), normalizedTarget, suggestions) + return suggestions } // isWorkflowFile returns true if the file should be treated as a workflow file. @@ -266,6 +269,8 @@ func getMarkdownWorkflowFiles(workflowDir string) ([]string, error) { workflowsDir = getWorkflowsDir() } + workflowsLog.Printf("Scanning for markdown workflow files in: %s", workflowsDir) + if _, err := os.Stat(workflowsDir); os.IsNotExist(err) { return nil, fmt.Errorf("no %s directory found", workflowsDir) } @@ -279,6 +284,7 @@ func getMarkdownWorkflowFiles(workflowDir string) ([]string, error) { // Filter out README.md files mdFiles = filterWorkflowFiles(mdFiles) + workflowsLog.Printf("Found %d markdown workflow file(s) in %s", len(mdFiles), workflowsDir) return mdFiles, nil }