diff --git a/.vscode/launch.json b/.vscode/launch.json index d3a1a95287c..fdd6e922d69 100644 --- a/.vscode/launch.json +++ b/.vscode/launch.json @@ -36,7 +36,7 @@ "name": "Run Quarto test", "request": "launch", "type": "node", - "program": "smoke/smoke-all.test.ts", // test script here + "program": "smoke/logging/log-level-direct.test.ts", // test script here "args": [], // args to the script here, like in command line smoke/smoke-all.test.t -- .\docs\smoke-all\2023\01\19\2107.qmd "cwd": "${workspaceFolder}/tests", "runtimeExecutable": "${workspaceFolder}/package/dist/bin/tools/deno", diff --git a/src/core/log.ts b/src/core/log.ts index a0b376da497..7c6199930e1 100644 --- a/src/core/log.ts +++ b/src/core/log.ts @@ -23,12 +23,13 @@ import { execProcess } from "./process.ts"; import { pandocBinaryPath } from "./resources.ts"; import { Block, pandoc } from "./pandoc/json.ts"; -export type LogLevel = "DEBUG" | "INFO" | "WARN" | "ERROR"; +export type LogLevel = "DEBUG" | "INFO" | "WARN" | "ERROR" | "CRITICAL"; +export type LogFormat = "plain" | "json-stream"; export interface LogOptions { log?: string; level?: string; - format?: "plain" | "json-stream"; + format?: LogFormat; quiet?: boolean; newline?: true; } @@ -55,7 +56,7 @@ export function appendLogOptions(cmd: Command): Command { }, ).option( "--log-level ", - "Log level (info, warning, error, critical)", + "Log level (debug, info, warning, error, critical)", { global: true, }, @@ -265,7 +266,7 @@ export class LogFileHandler extends FileHandler { interface LogFileHandlerOptions { filename: string; mode?: "a" | "w" | "x"; - format?: "plain" | "json-stream"; + format?: LogFormat; } export function flushLoggers(handlers: Record) { @@ -460,7 +461,9 @@ const levelMap: Record< debug: "DEBUG", info: "INFO", warning: "WARN", + warn: "WARN", error: "ERROR", + critical: "CRITICAL", }; export async function logPandocJson( diff --git a/tests/docs/logging/error-filter.lua b/tests/docs/logging/error-filter.lua new file mode 100644 index 00000000000..cf0a8d97e5d --- /dev/null +++ b/tests/docs/logging/error-filter.lua @@ -0,0 +1,8 @@ +-- error-filter.lua +-- This filter purposely generates an error for testing error logging + +function Pandoc(doc) + -- Generate an error + internal_error("This is a deliberate error from error-filter.lua for testing purposes") + return doc +end diff --git a/tests/docs/logging/lua-error.qmd b/tests/docs/logging/lua-error.qmd new file mode 100644 index 00000000000..177dd474b37 --- /dev/null +++ b/tests/docs/logging/lua-error.qmd @@ -0,0 +1,10 @@ +--- +title: "Lua Error Test" +format: html +filters: + - error-filter.lua +--- + +## Test Content + +This document will trigger a Lua filter error because the error-filter.lua purposely generates an error. diff --git a/tests/smoke/logging/log-level-and-formats.test.ts b/tests/smoke/logging/log-level-and-formats.test.ts new file mode 100644 index 00000000000..9c2bbf703d0 --- /dev/null +++ b/tests/smoke/logging/log-level-and-formats.test.ts @@ -0,0 +1,364 @@ +/* +* log-level-direct.test.ts +* +* Copyright (C) 2020-2025 Posit Software, PBC +* +*/ + +import { basename, extname } from "../../../src/deno_ral/path.ts"; +import { execProcess } from "../../../src/core/process.ts"; +import { md5HashSync } from "../../../src/core/hash.ts"; +import { safeRemoveIfExists } from "../../../src/core/path.ts"; +import { quartoDevCmd, outputForInput } from "../../utils.ts"; +import { assert } from "testing/asserts"; +import { LogFormat } from "../../../src/core/log.ts"; +import { existsSync } from "../../../src/deno_ral/fs.ts"; +import { readExecuteOutput } from "../../test.ts"; + +// Simple minimal document for testing +const testDoc = "docs/minimal.qmd"; +const testDocWithError = "docs/logging/lua-error.qmd"; + +// NOTE: We intentionally do NOT test environment variables (QUARTO_LOG, QUARTO_LOG_LEVEL, QUARTO_LOG_FORMAT) +// because they can interfere with other tests running concurrently in the Deno environment. +// Instead, we focus on testing the CLI arguments which are isolated to each test. + +// Those tests are not using testQuartoCmd because they are testing the log level directly +// and custom helpers in tests() are modifying the logging configuration. +// This is why we use Deno.test directly here. + +function testLogDirectly(options: { + testName: string, + level: string, + format?: LogFormat, + logFile?: string, + fileToRender?: string, + quiet?: boolean, + expectedOutputs?: { + // To test log output for document with errors + shouldSucceed?: boolean + // For plain format, we can check for specific text in the output + shouldContain?: string[], + shouldNotContain?: string[], + // For JSON format, we can also check for specific log levels + shouldContainLevel?: string[], + shouldNotContainLevel?: string[], + } +}) { + Deno.test({ + name: options.testName, + fn: async () => { + // Generate a unique log file path if one was provided + // This is to avoid conflicts when running multiple tests in parallel + let logFile = options.logFile; + if (logFile) { + const testNameHash = md5HashSync(options.testName); + const extension = extname(logFile); + const baseName = basename(logFile, extension); + logFile = `${baseName}-${testNameHash}${extension}`; + } + + try { + // Build command args + const args = ["render"]; + + // Add file path (default to testDoc if not specified) + if (!options.fileToRender) { + options.fileToRender = testDoc; + } + args.push(options.fileToRender); + + // Add log level + args.push("--log-level", options.level); + + // Add format if specified + if (options.format) { + args.push("--log-format", options.format); + } + + if (logFile) { + args.push("--log", logFile); + } + + // Add quiet if specified + if (options.quiet) { + args.push("--quiet"); + } + + // Execute quarto directly + const process = await execProcess({ + cmd: quartoDevCmd(), + args: args, + stdout: "piped", + stderr: "piped" + }); + + // Get stdout/stderr with fallback to empty string + const stdout = process.stdout || ""; + const stderr = process.stderr || ""; + const allOutput = stdout + stderr; + + // Check success/failure expectation + if (options.expectedOutputs?.shouldSucceed !== undefined) { + assert( + process.success === options.expectedOutputs.shouldSucceed, + options.expectedOutputs.shouldSucceed + ? `Process unexpectedly failed: ${stderr}` + : `Process unexpectedly succeeded (expected failure)` + ); + } + + // Check for expected content + if (options.expectedOutputs?.shouldContain) { + for (const text of options.expectedOutputs.shouldContain) { + assert( + allOutput.includes(text), + `Output should contain '${text}' but didn't.\nOutput: ${allOutput}` + ); + } + } + + // Check for unwanted content + if (options.expectedOutputs?.shouldNotContain) { + for (const text of options.expectedOutputs.shouldNotContain) { + assert( + !allOutput.includes(text), + `Output shouldn't contain '${text}' but did.\nOutput: ${allOutput}` + ); + } + } + + // For quiet mode, verify no output + if (options.quiet) { + assert( + stdout.trim() === "", + `Expected no stdout with --quiet option, but found: ${stdout}` + ); + } + + + // If JSON format is specified, verify the output is valid JSON + if (logFile && options.format === "json-stream") { + assert(existsSync(logFile), "Log file should exist"); + let foundValidJson = false; + try { + const outputs = readExecuteOutput(logFile); + foundValidJson = true; + outputs.filter((out) => out.msg !== "" && options.expectedOutputs?.shouldNotContainLevel?.includes(out.levelName)).forEach( + (out) => { + assert(false, `JSON output should not contain level ${out.levelName}, but found: ${out.msg}`); + } + ); + outputs.filter((out) => out.msg !== "" && options.expectedOutputs?.shouldContainLevel?.includes(out.levelName)).forEach( + (out) => { + let json = undefined; + try { + json = JSON.parse(out.msg); + } catch { + assert(false, "Error parsing JSON returned by quarto meta"); + } + assert( + Object.keys(json).length > 0, + "JSON returned by quarto meta seems invalid", + ); + } + ); + + } catch (e) {} + assert(foundValidJson, "JSON format should produce valid JSON output"); + } + } finally { + // Clean up log file if it exists + if (logFile) { + safeRemoveIfExists(logFile); + } + // Clean up any rendered output files + if (options.fileToRender) { + const output = outputForInput(options.fileToRender, 'html'); + safeRemoveIfExists(output.outputPath); + safeRemoveIfExists(output.supportPath); + } + } + } + }); +}; + +// This will always be shown in debug output as we'll show pandoc call +const debugHintText = "pandoc --verbose --trace"; +// This will be shown in info output +const infoHintText = function(testDoc: string) { + return `Output created: ${basename(testDoc, extname(testDoc))}.html`; +}; + +testLogDirectly({ + testName: "Plain format - DEBUG level should show all log messages", + level: "debug", + format: "plain", + fileToRender: testDoc, + expectedOutputs: { + shouldContain: [debugHintText, infoHintText(testDoc)], + shouldSucceed: true + } +}); + +testLogDirectly({ + testName: "Plain format - INFO level should not show DEBUG messages", + level: "info", + format: "plain", + fileToRender: testDoc, + expectedOutputs: { + shouldContain: [infoHintText(testDoc)], + shouldNotContain: [debugHintText], + shouldSucceed: true + } +}); + +testLogDirectly({ + testName: "Plain format - WARN level should not show INFO or DEBUG messages", + level: "warn", + format: "plain", + fileToRender: testDocWithError, + expectedOutputs: { + shouldContain: ["WARN:", "ERROR:"], + shouldNotContain: [debugHintText, infoHintText(testDocWithError)], + shouldSucceed: false + } +}); + +testLogDirectly({ + testName: "Plain format - ERROR level should only show ERROR messages", + level: "error", + format: "plain", + fileToRender: testDocWithError, + expectedOutputs: { + shouldContain: ["ERROR:"], + shouldNotContain: [debugHintText, infoHintText(testDocWithError), "WARN:"], + shouldSucceed: false + } +}); + +testLogDirectly({ + testName: "Json-Stream format - should produce parseable JSON in a log file with INFO level", + level: "info", + format: "json-stream", + logFile: "test-log.json", + expectedOutputs: { + shouldSucceed: true, + shouldContainLevel: ["INFO"], + shouldNotContainLevel: ["DEBUG"] + } +}); + +testLogDirectly({ + testName: "Json-Stream format - should produce parseable JSON in a log file with DEBUG level", + level: "debug", + format: "json-stream", + logFile: "test-log.json", + expectedOutputs: { + shouldSucceed: true, + shouldContainLevel: ["DEBUG", "INFO"], + } +}); + +testLogDirectly({ + testName: "Json-Stream format - should produce parseable JSON in a log file with WARN level", + level: "warn", + format: "json-stream", + logFile: "test-log.json", + fileToRender: testDocWithError, + expectedOutputs: { + shouldSucceed: false, + shouldContainLevel: ["WARN", "ERROR"], + shouldNotContainLevel: ["INFO", "DEBUG"], + } +}); + +testLogDirectly({ + testName: "Json-Stream format - should produce parseable JSON in a log file with ERROR level", + level: "error", + format: "json-stream", + logFile: "test-log.json", + fileToRender: testDocWithError, + expectedOutputs: { + shouldSucceed: false, + shouldContainLevel: ["ERROR"], + shouldNotContainLevel: ["DEBUG", "INFO", "WARN"] + } +}); + + +// 6. Testing quiet mode +testLogDirectly({ + testName: "Quiet mode should suppress all console output", + level: "debug", + format: "plain", + quiet: true, + expectedOutputs: { + shouldSucceed: true + } +}); + +testLogDirectly({ + testName: "Quiet mode should not suppress all output in JSON log file", + level: "debug", + format: "json-stream", + logFile: "test-log.json", + quiet: true, + expectedOutputs: { + shouldSucceed: true, + shouldContainLevel: ["DEBUG", "INFO"], + } +}); + +// 7. Testing quiet mode with errors +testLogDirectly({ + testName: "Plain format - Quiet mode should suppress output even with errors", + level: "debug", + format: "plain", + quiet: true, + fileToRender: testDocWithError, + expectedOutputs: { + shouldSucceed: false + } +}); + +testLogDirectly({ + testName: "Json-Stream - Quiet mode should not suppress output even with errors", + level: "debug", + format: "json-stream", + logFile: "test-log.json", + quiet: true, + fileToRender: testDocWithError, + expectedOutputs: { + shouldSucceed: false, + shouldContainLevel: ["DEBUG", "INFO", "WARN", "ERROR"] + } +}); + + +testLogDirectly({ + testName: "Log level should be case-insensitive (INFO vs info)", + level: "INFO", + format: "plain", + fileToRender: testDoc, + expectedOutputs: { + shouldContain: [infoHintText(testDoc)], + shouldNotContain: [debugHintText], + shouldSucceed: true + } +}); + +testLogDirectly({ + testName: "WARNING should be equivalent to WARN level", + level: "WARNING", + format: "plain", + fileToRender: testDocWithError, + expectedOutputs: { + shouldContain: ["WARN:", "ERROR:"], + shouldNotContain: [debugHintText, infoHintText(testDocWithError)], + shouldSucceed: false + } +}); + + + diff --git a/tests/test.ts b/tests/test.ts index e4d67ae894c..6390aea40e3 100644 --- a/tests/test.ts +++ b/tests/test.ts @@ -9,7 +9,7 @@ import { AssertionError, fail } from "testing/asserts"; import { warning } from "../src/deno_ral/log.ts"; import { initDenoDom } from "../src/core/deno-dom.ts"; -import { cleanupLogger, initializeLogger, flushLoggers, logError } from "../src/core/log.ts"; +import { cleanupLogger, initializeLogger, flushLoggers, logError, LogLevel, LogFormat } from "../src/core/log.ts"; import { quarto } from "../src/quarto.ts"; import { join } from "../src/deno_ral/path.ts"; import * as colors from "fmt/colors"; @@ -18,6 +18,17 @@ import { relative, fromFileUrl } from "../src/deno_ral/path.ts"; import { quartoConfig } from "../src/core/quarto.ts"; import { isWindows } from "../src/deno_ral/platform.ts"; + +export interface TestLogConfig { + // Path to log file + log?: string; + + // Log level + level?: LogLevel; + + // Log format + format?: LogFormat; +} export interface TestDescriptor { // The name of the test name: string; @@ -33,6 +44,9 @@ export interface TestDescriptor { // type of test type: "smoke" | "unit"; + + // Optional logging configuration + logConfig?: TestLogConfig; } export interface TestContext { @@ -105,7 +119,8 @@ export function testQuartoCmd( args: string[], verify: Verify[], context?: TestContext, - name?: string + name?: string, + logConfig?: TestLogConfig, ) { if (name === undefined) { name = `quarto ${cmd} ${args.join(" ")}`; @@ -124,6 +139,7 @@ export function testQuartoCmd( verify, context: context || {}, type: "smoke", + logConfig, // Pass log config to test }); } @@ -201,9 +217,9 @@ export function test(test: TestDescriptor) { // Capture the output const log = Deno.makeTempFileSync({ suffix: ".json" }); const handlers = await initializeLogger({ - log: log, - level: "INFO", - format: "json-stream", + log: test.logConfig?.log || log, + level: test.logConfig?.level || "INFO", + format: test.logConfig?.format || "json-stream", quiet: true, }); @@ -330,7 +346,7 @@ export function test(test: TestDescriptor) { Deno.test(args); } -function readExecuteOutput(log: string) { +export function readExecuteOutput(log: string) { const jsonStream = Deno.readTextFileSync(log); const lines = jsonStream.split("\n").filter((line) => !!line); return lines.map((line) => {