Merge pull request #13807 from quarto-dev/gha/improve-logging

GHA TESTS - Improve logging to group in the right place and reduce log in CI in non debug mode

Author: cderv

.github/workflows/test-smokes.yml

@@ -264,18 +264,19 @@ jobs:
         env:
           # Useful as TinyTeX latest release is checked in run-test.sh
           GH_TOKEN: ${{ secrets.GITHUB_TOKEN }}
-          QUARTO_LOG_LEVEL: DEBUG
         run: |
           haserror=0
           failed_tests=()
           readarray -t my_array < <(echo '${{ inputs.buckets }}' | jq -rc '.[]')
           for file in "${my_array[@]}"; do
+            echo "::group::Testing ${file}"
             echo ">>> ./run-tests.sh ${file}"
             # Run tests without -e so we don't exit on first failure
             set +e
             shopt -s globstar && ./run-tests.sh "$file"
             status=$?
             set -e
+            echo "::endgroup::"
             if [ $status -ne 0 ]; then
               echo "::error title=Test Bucket Failed::Test bucket ${file} failed with exit code ${status}"
               echo ">>> Error found in test file: ${file}"
@@ -305,9 +306,11 @@ jobs:
           $haserror=$false
           $failed_tests=@()
           foreach ($file in ('${{ inputs.buckets }}' | ConvertFrom-Json)) {
+            Write-Host "::group::Testing ${file}"
             Write-Host ">>> ./run-tests.ps1 ${file}"
             ./run-tests.ps1 $file
             $status=$LASTEXITCODE
+            Write-Host "::endgroup::"
             if ($status -ne 0) {
               Write-Host "::error title=Test Bucket Failed::Test bucket ${file} failed with exit code ${status}"
               Write-Host ">>> Error found in test file: ${file}"

src/core/log.ts

@@ -22,6 +22,7 @@ import { onCleanup } from "./cleanup.ts";
 import { execProcess } from "./process.ts";
 import { pandocBinaryPath } from "./resources.ts";
 import { Block, pandoc } from "./pandoc/json.ts";
+import { isGitHubActions, isVerboseMode } from "../tools/github.ts";
 
 export type LogLevel = "DEBUG" | "INFO" | "WARN" | "ERROR" | "CRITICAL";
 export type LogFormat = "plain" | "json-stream";
@@ -99,8 +100,17 @@ export function logOptions(args: Args) {
   if (logOptions.log) {
     ensureDirSync(dirname(logOptions.log));
   }
-  logOptions.level = args.ll || args["log-level"] ||
-    Deno.env.get("QUARTO_LOG_LEVEL");
+
+  // Determine log level with priority: explicit args > QUARTO_LOG_LEVEL > GitHub Actions debug mode
+  let level = args.ll || args["log-level"] || Deno.env.get("QUARTO_LOG_LEVEL");
+
+  // Enable DEBUG logging when GitHub Actions debug mode is on (RUNNER_DEBUG=1)
+  // Can be overridden by explicit --log-level or QUARTO_LOG_LEVEL
+  if (!level && isGitHubActions() && isVerboseMode()) {
+    level = "DEBUG";
+  }
+
+  logOptions.level = level;
   logOptions.quiet = args.q || args.quiet;
   logOptions.format = parseFormat(
     args.lf || args["log-format"] || Deno.env.get("QUARTO_LOG_FORMAT"),

src/tools/github.ts

@@ -61,7 +61,10 @@ export function error(
   message: string,
   properties?: AnnotationProperties,
 ): void {
-  if (!isGitHubActions()) return;
+  if (!isGitHubActions()) {
+    console.log(message);
+    return;
+  }
   const props = properties ? formatProperties(properties) : "";
   console.log(`::error${props}::${escapeData(message)}`);
 }
@@ -70,7 +73,10 @@ export function warning(
   message: string,
   properties?: AnnotationProperties,
 ): void {
-  if (!isGitHubActions()) return;
+  if (!isGitHubActions()) {
+    console.log(message);
+    return;
+  }
   const props = properties ? formatProperties(properties) : "";
   console.log(`::warning${props}::${escapeData(message)}`);
 }
@@ -79,7 +85,10 @@ export function notice(
   message: string,
   properties?: AnnotationProperties,
 ): void {
-  if (!isGitHubActions()) return;
+  if (!isGitHubActions()) {
+    console.log(message);
+    return;
+  }
   const props = properties ? formatProperties(properties) : "";
   console.log(`::notice${props}::${escapeData(message)}`);
 }
@@ -96,6 +105,10 @@ export function endGroup(): void {
 }
 
 export function withGroup<T>(title: string, fn: () => T): T {
+  if (!isGitHubActions()) {
+    console.log(title);
+    return fn();
+  }
   startGroup(title);
   try {
     return fn();
@@ -108,6 +121,10 @@ export async function withGroupAsync<T>(
   title: string,
   fn: () => Promise<T>,
 ): Promise<T> {
+  if (!isGitHubActions()) {
+    console.log(title);
+    return await fn();
+  }
   startGroup(title);
   try {
     return await fn();

tests/integration/playwright-tests.test.ts

@@ -16,7 +16,7 @@ import { execProcess } from "../../src/core/process.ts";
 import { quartoDevCmd } from "../utils.ts";
 import { fail } from "testing/asserts";
 import { isWindows } from "../../src/deno_ral/platform.ts";
-import { join } from "../../src/deno_ral/path.ts";
+import { join, relative } from "../../src/deno_ral/path.ts";
 import { existsSync } from "../../src/deno_ral/fs.ts";
 import * as gha from "../../src/tools/github.ts";
 
@@ -37,7 +37,6 @@ await initState();
 const multiplexServerPath = "integration/playwright/multiplex-server";
 const multiplexNodeModules = join(multiplexServerPath, "node_modules");
 if (!existsSync(multiplexNodeModules)) {
-  console.log("Installing multiplex server dependencies...");
   await execProcess({
     cmd: isWindows ? "npm.cmd" : "npm",
     args: ["install", "--loglevel=error"],
@@ -48,44 +47,66 @@ if (!existsSync(multiplexNodeModules)) {
 
 // const promises = [];
 const fileNames: string[] = [];
-const extraOpts = [
-  {
-    pathSuffix: "docs/playwright/embed-resources/issue-11860/main.qmd",
-    options: ["--output-dir=inner"],
-  }
-]
 
-for (const { path: fileName } of globOutput) {
-  const input = fileName;
-  const options: string[] = [];
-  for (const extraOpt of extraOpts) {
-    if (fileName.endsWith(extraOpt.pathSuffix)) {
-      options.push(...extraOpt.options);
+// To avoid re-rendering, see QUARTO_PLAYWRIGHT_SKIP_RENDER env var
+if (Deno.env.get("QUARTO_PLAYWRIGHT_TESTS_SKIP_RENDER") === "true") {
+  console.log("Skipping render of test documents.");
+} else {
+  const extraOpts = [
+    {
+      pathSuffix: "docs/playwright/embed-resources/issue-11860/main.qmd",
+      options: ["--output-dir=inner"],
     }
-  }
+  ]
 
-  // sigh, we have a race condition somewhere in
-  // mediabag inspection if we don't wait all renders
-  // individually. This is very slow..
-  await execProcess({
-    cmd: quartoDevCmd(),
-    args: ["render", input, ...options],
-  });
-  fileNames.push(fileName);
+  for (const { path: fileName } of globOutput) {
+    const input = relative(Deno.cwd(), fileName);
+    const options: string[] = [];
+    for (const extraOpt of extraOpts) {
+      if (fileName.endsWith(extraOpt.pathSuffix)) {
+        options.push(...extraOpt.options);
+      }
+    }
+
+    // sigh, we have a race condition somewhere in
+    // mediabag inspection if we don't wait all renders
+    // individually. This is very slow..
+    console.log(`Rendering ${input}...`);
+    const result = await execProcess({
+      cmd: quartoDevCmd(),
+      args: ["render", input, ...options],
+      stdout: "piped",
+      stderr: "piped",
+    });
+
+    if (!result.success) {
+      gha.error(`Failed to render ${input}`)
+      if (result.stdout) console.log(result.stdout);
+      if (result.stderr) console.error(result.stderr);
+      throw new Error(`Render failed with code ${result.code}`);
+    }
+
+    fileNames.push(fileName);
+  }
 }
 
 Deno.test({
   name: "Playwright tests are passing", 
   // currently we run playwright tests only on Linux
-  ignore: isWindows,
+  ignore: gha.isGitHubActions() && isWindows,
   fn: async () => {
     try {
       // run playwright
       const res = await execProcess({
-        cmd: isWindows ? "npx.cmd" : "npx", 
+        cmd: isWindows ? "npx.cmd" : "npx",
         args: ["playwright", "test", "--ignore-snapshots"],
         cwd: "integration/playwright",
-      });
+      },
+      undefined, // stdin
+      undefined, // mergeOutput
+      undefined, // stderrFilter
+      true       // respectStreams - write directly to stderr/stdout
+      );
       if (!res.success) {
         if (gha.isGitHubActions() && Deno.env.get("GITHUB_REPOSITORY") && Deno.env.get("GITHUB_RUN_ID")) {
           const runUrl = `https://github.com/${Deno.env.get("GITHUB_REPOSITORY")}/actions/runs/${Deno.env.get("GITHUB_RUN_ID")}`;
@@ -99,11 +120,15 @@ Deno.test({
         }
         fail("Failed tests with playwright. Look at playwright report for more details.")
       }
-      
+
     } finally {
-      for (const fileName of fileNames) {
-        cleanoutput(fileName, "html");
-      }
+      // skip cleanoutput if requested
+      if (Deno.env.get("QUARTO_PLAYWRIGHT_TESTS_SKIP_CLEANOUTPUT") === "true" || Deno.env.get("QUARTO_PLAYWRIGHT_TESTS_SKIP_RENDER") === "true") {
+        console.log("Skipping cleanoutput of test documents.");
+      } else 
+        for (const fileName of fileNames) {
+          cleanoutput(fileName, "html");
+        }
     }
   }
 });

tests/integration/playwright/playwright.config.ts

@@ -101,6 +101,7 @@ export default defineConfig({
       url: 'http://127.0.0.1:8080',
       reuseExistingServer: !isCI,
       cwd: '../../docs/playwright',
+      stderr: 'ignore',  // Suppress verbose HTTP request logs
     },
     {
       // Socket.IO multiplex server for RevealJS
@@ -109,6 +110,7 @@ export default defineConfig({
       reuseExistingServer: !isCI,
       cwd: './multiplex-server',
       timeout: 10000,
+      stderr: 'ignore',  // Suppress verbose logs
     }
   ],
 });

tests/run-tests.sh

@@ -117,14 +117,12 @@ else
     TESTS_TO_RUN=""
     if [[ ! -z "$*" ]]; then
       for file in "$*"; do
-        echo $file
         filename=$(basename "$file")
         # smoke-all.test.ts works with .qmd, .md and .ipynb but  will ignored file starting with _
         if [[ $filename =~ ^[^_].*[.]qmd$ ]] || [[ $filename =~ ^[^_].*[.]ipynb$ ]] || [[ $filename =~ ^[^_].*[.]md$ ]]; then
           SMOKE_ALL_FILES="${SMOKE_ALL_FILES} ${file}"
         elif [[ $file =~ .*[.]ts$ ]]; then
           TESTS_TO_RUN="${TESTS_TO_RUN} ${file}"
-          echo $TESTS_TO_RUN
         else
           echo "#### WARNING"
           echo "Only .ts, or .qmd, .md and .ipynb passed to smoke-all.test.ts are accepted (file starting with _ are ignored)."