diff --git a/README.md b/README.md index 039e355d..58b30ac2 100644 --- a/README.md +++ b/README.md @@ -201,6 +201,45 @@ You can set the logging level through multiple sources (in order of priority): This is useful for setting a default logging level for all package manager commands in your terminal session or CI/CD environment. +## File Logging + +You can mirror Aikido Safe Chain output to a log file using the `--safe-chain-log-file` flag or the `SAFE_CHAIN_LOG_FILE` environment variable. File logging is disabled by default and enabled when a path is set. The file format (`--safe-chain-log-file-format`) and verbosity (`--safe-chain-log-file-verbosity`) are controlled independently from the terminal output. + +### Configuration Options + +Set through any of these (in order of priority): + +1. **CLI Argument** (highest priority): + + ```shell + npm install express \ + --safe-chain-log-file=~/safe-chain.log \ + --safe-chain-log-file-format=plain \ + --safe-chain-log-file-verbosity=normal + ``` + +2. **Environment Variable**: + + ```shell + export SAFE_CHAIN_LOG_FILE=~/safe-chain.log + export SAFE_CHAIN_LOG_FILE_FORMAT=plain + export SAFE_CHAIN_LOG_FILE_VERBOSITY=normal + ``` + +3. **Config File** (`~/.safe-chain/config.json`): + + ```json + { + "logFile": "~/safe-chain.log", + "logFileFormat": "plain", + "logFileVerbosity": "normal" + } + ``` + +`logFileFormat` — `json` (default) or `plain`. + +`logFileVerbosity` — `silent`, `normal`, or `verbose` (default). Independent from `--safe-chain-logging`. + ## Minimum Package Age You can configure how long packages must exist before Safe Chain allows their installation. By default, packages must be at least 48 hours old before they can be installed. diff --git a/packages/safe-chain/src/config/cliArguments.js b/packages/safe-chain/src/config/cliArguments.js index 918761ca..05d6a1ad 100644 --- a/packages/safe-chain/src/config/cliArguments.js +++ b/packages/safe-chain/src/config/cliArguments.js @@ -1,13 +1,16 @@ import { ui } from "../environment/userInteraction.js"; /** - * @type {{loggingLevel: string | undefined, skipMinimumPackageAge: boolean | undefined, minimumPackageAgeHours: string | undefined, malwareListBaseUrl: string | undefined}} + * @type {{loggingLevel: string | undefined, skipMinimumPackageAge: boolean | undefined, minimumPackageAgeHours: string | undefined, malwareListBaseUrl: string | undefined, logFile: string | undefined, logFileFormat: string | undefined, logFileVerbosity: string | undefined}} */ const state = { loggingLevel: undefined, skipMinimumPackageAge: undefined, minimumPackageAgeHours: undefined, malwareListBaseUrl: undefined, + logFile: undefined, + logFileFormat: undefined, + logFileVerbosity: undefined, }; const SAFE_CHAIN_ARG_PREFIX = "--safe-chain-"; @@ -22,6 +25,9 @@ export function initializeCliArguments(args) { state.skipMinimumPackageAge = undefined; state.minimumPackageAgeHours = undefined; state.malwareListBaseUrl = undefined; + state.logFile = undefined; + state.logFileFormat = undefined; + state.logFileVerbosity = undefined; const safeChainArgs = []; const remainingArgs = []; @@ -38,6 +44,9 @@ export function initializeCliArguments(args) { setSkipMinimumPackageAge(safeChainArgs); setMinimumPackageAgeHours(safeChainArgs); setMalwareListBaseUrl(safeChainArgs); + setLogFile(safeChainArgs); + setLogFileFormat(safeChainArgs); + setLogFileVerbosity(safeChainArgs); checkDeprecatedPythonFlag(args); return remainingArgs; } @@ -132,6 +141,66 @@ export function getMalwareListBaseUrl() { return state.malwareListBaseUrl; } +/** + * @param {string[]} args + * @returns {void} + */ +function setLogFile(args) { + const argName = SAFE_CHAIN_ARG_PREFIX + "log-file="; + + const value = getLastArgEqualsValue(args, argName); + if (value) { + state.logFile = value; + } +} + +/** + * @returns {string | undefined} + */ +export function getLogFile() { + return state.logFile; +} + +/** + * @param {string[]} args + * @returns {void} + */ +function setLogFileFormat(args) { + const argName = SAFE_CHAIN_ARG_PREFIX + "log-file-format="; + + const value = getLastArgEqualsValue(args, argName); + if (value) { + state.logFileFormat = value.toLowerCase(); + } +} + +/** + * @returns {string | undefined} + */ +export function getLogFileFormat() { + return state.logFileFormat; +} + +/** + * @param {string[]} args + * @returns {void} + */ +function setLogFileVerbosity(args) { + const argName = SAFE_CHAIN_ARG_PREFIX + "log-file-verbosity="; + + const value = getLastArgEqualsValue(args, argName); + if (value) { + state.logFileVerbosity = value.toLowerCase(); + } +} + +/** + * @returns {string | undefined} + */ +export function getLogFileVerbosity() { + return state.logFileVerbosity; +} + /** * @param {string[]} args * @param {string} flagName diff --git a/packages/safe-chain/src/config/cliArguments.spec.js b/packages/safe-chain/src/config/cliArguments.spec.js index 8b505be2..329d7d51 100644 --- a/packages/safe-chain/src/config/cliArguments.spec.js +++ b/packages/safe-chain/src/config/cliArguments.spec.js @@ -5,6 +5,9 @@ import { getLoggingLevel, getSkipMinimumPackageAge, getMinimumPackageAgeHours, + getLogFile, + getLogFileFormat, + getLogFileVerbosity, } from "./cliArguments.js"; import { ui } from "../environment/userInteraction.js"; @@ -308,4 +311,140 @@ describe("initializeCliArguments", () => { ui.writeWarning = originalWriteWarning; } }); + + it("should not set logFile when no log-file argument is passed", () => { + initializeCliArguments(["install", "express"]); + + assert.strictEqual(getLogFile(), undefined); + }); + + it("should parse log-file value and set state", () => { + const args = ["--safe-chain-log-file=/tmp/safe-chain.log", "install"]; + const result = initializeCliArguments(args); + + assert.deepEqual(result, ["install"]); + assert.strictEqual(getLogFile(), "/tmp/safe-chain.log"); + }); + + it("should use the last log-file argument when multiple are provided", () => { + const args = [ + "--safe-chain-log-file=/tmp/first.log", + "--safe-chain-log-file=/tmp/second.log", + "install", + ]; + initializeCliArguments(args); + + assert.strictEqual(getLogFile(), "/tmp/second.log"); + }); + + it("should handle log-file with other safe-chain arguments", () => { + const args = [ + "--safe-chain-logging=verbose", + "--safe-chain-log-file=/tmp/test.log", + "install", + "lodash", + ]; + const result = initializeCliArguments(args); + + assert.deepEqual(result, ["install", "lodash"]); + assert.strictEqual(getLoggingLevel(), "verbose"); + assert.strictEqual(getLogFile(), "/tmp/test.log"); + }); + + it("should reset logFile between calls", () => { + initializeCliArguments(["--safe-chain-log-file=/tmp/test.log", "install"]); + assert.strictEqual(getLogFile(), "/tmp/test.log"); + + initializeCliArguments(["install"]); + assert.strictEqual(getLogFile(), undefined); + }); + + it("should not set logFileFormat when no log-file-format argument is passed", () => { + initializeCliArguments(["install", "express"]); + + assert.strictEqual(getLogFileFormat(), undefined); + }); + + it("should parse log-file-format=json and set state", () => { + const args = ["--safe-chain-log-file-format=json", "install"]; + const result = initializeCliArguments(args); + + assert.deepEqual(result, ["install"]); + assert.strictEqual(getLogFileFormat(), "json"); + }); + + it("should parse log-file-format=plain and set state", () => { + const args = ["--safe-chain-log-file-format=plain", "install"]; + initializeCliArguments(args); + + assert.strictEqual(getLogFileFormat(), "plain"); + }); + + it("should handle log-file-format case-insensitively", () => { + initializeCliArguments(["--safe-chain-log-file-format=JSON", "install"]); + + assert.strictEqual(getLogFileFormat(), "json"); + }); + + it("should use the last log-file-format argument when multiple are provided", () => { + const args = [ + "--safe-chain-log-file-format=plain", + "--safe-chain-log-file-format=json", + "install", + ]; + initializeCliArguments(args); + + assert.strictEqual(getLogFileFormat(), "json"); + }); + + it("should reset logFileFormat between calls", () => { + initializeCliArguments(["--safe-chain-log-file-format=json", "install"]); + assert.strictEqual(getLogFileFormat(), "json"); + + initializeCliArguments(["install"]); + assert.strictEqual(getLogFileFormat(), undefined); + }); + + it("should handle log-file and log-file-format together", () => { + const args = [ + "--safe-chain-log-file=/tmp/out.log", + "--safe-chain-log-file-format=json", + "install", + ]; + const result = initializeCliArguments(args); + + assert.deepEqual(result, ["install"]); + assert.strictEqual(getLogFile(), "/tmp/out.log"); + assert.strictEqual(getLogFileFormat(), "json"); + }); + + it("should not set logFileVerbosity when no log-file-verbosity argument is passed", () => { + initializeCliArguments(["install"]); + + assert.strictEqual(getLogFileVerbosity(), undefined); + }); + + it("should parse log-file-verbosity values and lowercase them", () => { + initializeCliArguments(["--safe-chain-log-file-verbosity=Verbose", "install"]); + + assert.strictEqual(getLogFileVerbosity(), "verbose"); + }); + + it("should reset logFileVerbosity between calls", () => { + initializeCliArguments(["--safe-chain-log-file-verbosity=silent"]); + assert.strictEqual(getLogFileVerbosity(), "silent"); + + initializeCliArguments(["install"]); + assert.strictEqual(getLogFileVerbosity(), undefined); + }); + + it("should use the last log-file-verbosity argument when multiple are provided", () => { + initializeCliArguments([ + "--safe-chain-log-file-verbosity=normal", + "--safe-chain-log-file-verbosity=silent", + "install", + ]); + + assert.strictEqual(getLogFileVerbosity(), "silent"); + }); }); diff --git a/packages/safe-chain/src/config/configFile.js b/packages/safe-chain/src/config/configFile.js index d3401303..902d3107 100644 --- a/packages/safe-chain/src/config/configFile.js +++ b/packages/safe-chain/src/config/configFile.js @@ -12,6 +12,9 @@ import { getSafeChainBaseDir } from "./safeChainDir.js"; * @property {unknown | Number} scanTimeout * @property {unknown | Number} minimumPackageAgeHours * @property {unknown | string} malwareListBaseUrl + * @property {unknown | string} logFile + * @property {unknown | string} logFileFormat + * @property {unknown | string} logFileVerbosity * @property {unknown | SafeChainRegistryConfiguration} npm * @property {unknown | SafeChainRegistryConfiguration} pip * @@ -98,6 +101,42 @@ export function getMalwareListBaseUrl() { return undefined; } +/** + * Gets the log file path from the config file + * @returns {string | undefined} + */ +export function getLogFile() { + const config = readConfigFile(); + if (config.logFile && typeof config.logFile === "string") { + return config.logFile; + } + return undefined; +} + +/** + * Gets the log file format from the config file + * @returns {string | undefined} + */ +export function getLogFileFormat() { + const config = readConfigFile(); + if (config.logFileFormat && typeof config.logFileFormat === "string") { + return config.logFileFormat; + } + return undefined; +} + +/** + * Gets the log file verbosity from the config file + * @returns {string | undefined} + */ +export function getLogFileVerbosity() { + const config = readConfigFile(); + if (config.logFileVerbosity && typeof config.logFileVerbosity === "string") { + return config.logFileVerbosity; + } + return undefined; +} + /** * Gets the custom npm registries from the config file (format parsing only, no validation) * @returns {string[]} @@ -229,6 +268,9 @@ function readConfigFile() { scanTimeout: undefined, minimumPackageAgeHours: undefined, malwareListBaseUrl: undefined, + logFile: undefined, + logFileFormat: undefined, + logFileVerbosity: undefined, npm: { customRegistries: undefined, }, diff --git a/packages/safe-chain/src/config/configFile.spec.js b/packages/safe-chain/src/config/configFile.spec.js index 8b36ff26..42bdd9ef 100644 --- a/packages/safe-chain/src/config/configFile.spec.js +++ b/packages/safe-chain/src/config/configFile.spec.js @@ -347,6 +347,132 @@ for (const { packageManager, getCustomRegistries } of [ }); } +describe("getLogFile", async () => { + const { getLogFile } = await import("./configFile.js"); + + afterEach(() => { + mockFiles.clear(); + }); + + it("should return undefined when config file doesn't exist", () => { + assert.strictEqual(getLogFile(), undefined); + }); + + it("should return undefined when logFile is not set", () => { + setConfigContent(JSON.stringify({ scanTimeout: 5000 })); + + assert.strictEqual(getLogFile(), undefined); + }); + + it("should return log file path from config", () => { + setConfigContent(JSON.stringify({ logFile: "/tmp/safe-chain.log" })); + + assert.strictEqual(getLogFile(), "/tmp/safe-chain.log"); + }); + + it("should return undefined for non-string logFile values", () => { + setConfigContent(JSON.stringify({ logFile: 123 })); + + assert.strictEqual(getLogFile(), undefined); + }); + + it("should return undefined for empty string logFile", () => { + setConfigContent(JSON.stringify({ logFile: "" })); + + assert.strictEqual(getLogFile(), undefined); + }); + + it("should handle malformed JSON and return undefined", () => { + setConfigContent("{ invalid json"); + + assert.strictEqual(getLogFile(), undefined); + }); +}); + +describe("getLogFileFormat", async () => { + const { getLogFileFormat } = await import("./configFile.js"); + + afterEach(() => { + mockFiles.clear(); + }); + + it("should return undefined when config file doesn't exist", () => { + assert.strictEqual(getLogFileFormat(), undefined); + }); + + it("should return undefined when logFileFormat is not set", () => { + setConfigContent(JSON.stringify({ scanTimeout: 5000 })); + + assert.strictEqual(getLogFileFormat(), undefined); + }); + + it("should return log format from config", () => { + setConfigContent(JSON.stringify({ logFileFormat: "json" })); + + assert.strictEqual(getLogFileFormat(), "json"); + }); + + it("should return plain format from config", () => { + setConfigContent(JSON.stringify({ logFileFormat: "plain" })); + + assert.strictEqual(getLogFileFormat(), "plain"); + }); + + it("should return undefined for non-string logFileFormat values", () => { + setConfigContent(JSON.stringify({ logFileFormat: 42 })); + + assert.strictEqual(getLogFileFormat(), undefined); + }); + + it("should return undefined for empty string logFileFormat", () => { + setConfigContent(JSON.stringify({ logFileFormat: "" })); + + assert.strictEqual(getLogFileFormat(), undefined); + }); + + it("should handle malformed JSON and return undefined", () => { + setConfigContent("{ invalid json"); + + assert.strictEqual(getLogFileFormat(), undefined); + }); +}); + +describe("getLogFileVerbosity", async () => { + const { getLogFileVerbosity } = await import("./configFile.js"); + + afterEach(() => { + mockFiles.clear(); + }); + + it("should return undefined when config file doesn't exist", () => { + assert.strictEqual(getLogFileVerbosity(), undefined); + }); + + it("should return undefined when logFileVerbosity is not set", () => { + setConfigContent(JSON.stringify({ scanTimeout: 5000 })); + + assert.strictEqual(getLogFileVerbosity(), undefined); + }); + + it("should return verbosity from config", () => { + setConfigContent(JSON.stringify({ logFileVerbosity: "normal" })); + + assert.strictEqual(getLogFileVerbosity(), "normal"); + }); + + it("should return undefined for non-string values", () => { + setConfigContent(JSON.stringify({ logFileVerbosity: 42 })); + + assert.strictEqual(getLogFileVerbosity(), undefined); + }); + + it("should return undefined for empty string", () => { + setConfigContent(JSON.stringify({ logFileVerbosity: "" })); + + assert.strictEqual(getLogFileVerbosity(), undefined); + }); +}); + describe("config file location fallback", async () => { const { getScanTimeout } = await import("./configFile.js"); diff --git a/packages/safe-chain/src/config/environmentVariables.js b/packages/safe-chain/src/config/environmentVariables.js index 932eff76..d4ad8186 100644 --- a/packages/safe-chain/src/config/environmentVariables.js +++ b/packages/safe-chain/src/config/environmentVariables.js @@ -55,3 +55,30 @@ export function getMinimumPackageAgeExclusions() { export function getMalwareListBaseUrl() { return process.env.SAFE_CHAIN_MALWARE_LIST_BASE_URL; } + +/** + * Gets the log file path from environment variable + * When set, all output (including verbose) is written to this file + * @returns {string | undefined} + */ +export function getLogFile() { + return process.env.SAFE_CHAIN_LOG_FILE; +} + +/** + * Gets the log file format from environment variable + * Valid values: "plain", "json" + * @returns {string | undefined} + */ +export function getLogFileFormat() { + return process.env.SAFE_CHAIN_LOG_FILE_FORMAT; +} + +/** + * Gets the log file verbosity from environment variable + * Valid values: "silent", "normal", "verbose". Default is "verbose". + * @returns {string | undefined} + */ +export function getLogFileVerbosity() { + return process.env.SAFE_CHAIN_LOG_FILE_VERBOSITY; +} diff --git a/packages/safe-chain/src/config/settings.js b/packages/safe-chain/src/config/settings.js index d04411e6..5a81fa0a 100644 --- a/packages/safe-chain/src/config/settings.js +++ b/packages/safe-chain/src/config/settings.js @@ -1,3 +1,5 @@ +import os from "os"; +import path from "path"; import * as cliArguments from "./cliArguments.js"; import * as configFile from "./configFile.js"; import * as environmentVariables from "./environmentVariables.js"; @@ -10,7 +12,7 @@ export const LOGGING_VERBOSE = "verbose"; export function getLoggingLevel() { // Priority 1: CLI argument const cliLevel = cliArguments.getLoggingLevel(); - if (cliLevel === LOGGING_SILENT || cliLevel === LOGGING_VERBOSE) { + if (isValidVerbosity(cliLevel)) { return cliLevel; } if (cliLevel) { @@ -20,13 +22,133 @@ export function getLoggingLevel() { // Priority 2: Environment variable const envLevel = environmentVariables.getLoggingLevel()?.toLowerCase(); - if (envLevel === LOGGING_SILENT || envLevel === LOGGING_VERBOSE) { + if (isValidVerbosity(envLevel)) { return envLevel; } return LOGGING_NORMAL; } +/** + * Gets the log file path with priority: CLI argument > environment variable > config file > undefined + * @returns {string | undefined} + */ +export function getLogFile() { + // Priority 1: CLI argument + const cliValue = cliArguments.getLogFile(); + if (cliValue) { + return expandTilde(cliValue); + } + + // Priority 2: Environment variable + const envValue = environmentVariables.getLogFile(); + if (envValue) { + return expandTilde(envValue); + } + + // Priority 3: Config file + const configValue = configFile.getLogFile(); + if (configValue) { + return expandTilde(configValue); + } + + return undefined; +} + +/** + * Expands a leading "~/" or bare "~" to the user's home directory. Shells + * don't expand tilde after "=" (e.g. --safe-chain-log-file=~/foo.log) and + * env vars are never shell-expanded, so we do it here. + * + * @param {string} filePath + * @returns {string} + */ +function expandTilde(filePath) { + if (filePath === "~") return os.homedir(); + if (filePath.startsWith("~/")) return path.join(os.homedir(), filePath.slice(2)); + return filePath; +} + +export const LOG_FILE_FORMAT_PLAIN = "plain"; +export const LOG_FILE_FORMAT_JSON = "json"; + +/** + * Gets the log file format with priority: CLI argument > environment variable > config file > "json" + * @returns {string} + */ +export function getLogFileFormat() { + // Priority 1: CLI argument + const cliValue = cliArguments.getLogFileFormat(); + if (cliValue === LOG_FILE_FORMAT_PLAIN || cliValue === LOG_FILE_FORMAT_JSON) { + return cliValue; + } + if (cliValue) { + // CLI arg was set but invalid, default to json. Mirrors getLoggingLevel. + return LOG_FILE_FORMAT_JSON; + } + + // Priority 2: Environment variable + const envValue = environmentVariables.getLogFileFormat()?.toLowerCase(); + if (envValue === LOG_FILE_FORMAT_PLAIN || envValue === LOG_FILE_FORMAT_JSON) { + return envValue; + } + + // Priority 3: Config file + const configValue = configFile.getLogFileFormat()?.toLowerCase(); + if (configValue === LOG_FILE_FORMAT_PLAIN || configValue === LOG_FILE_FORMAT_JSON) { + return configValue; + } + + return LOG_FILE_FORMAT_JSON; +} + +/** + * Gets the log file verbosity with priority: CLI argument > environment + * variable > config file > LOGGING_VERBOSE. Default is verbose because the + * file is meant to be the diagnostic record; users opt down explicitly. + * Reuses the LOGGING_* enum since the levels mean the same thing as for + * console output. + * + * @returns {string} + */ +export function getLogFileVerbosity() { + // Priority 1: CLI argument + const cliValue = cliArguments.getLogFileVerbosity(); + if (isValidVerbosity(cliValue)) { + return cliValue; + } + if (cliValue) { + // CLI arg was set but invalid, default to verbose. Mirrors getLoggingLevel. + return LOGGING_VERBOSE; + } + + // Priority 2: Environment variable + const envValue = environmentVariables.getLogFileVerbosity()?.toLowerCase(); + if (isValidVerbosity(envValue)) { + return envValue; + } + + // Priority 3: Config file + const configValue = configFile.getLogFileVerbosity()?.toLowerCase(); + if (isValidVerbosity(configValue)) { + return configValue; + } + + return LOGGING_VERBOSE; +} + +/** + * @param {string | undefined} value + * @returns {value is "silent" | "normal" | "verbose"} + */ +function isValidVerbosity(value) { + return ( + value === LOGGING_SILENT || + value === LOGGING_NORMAL || + value === LOGGING_VERBOSE + ); +} + export const ECOSYSTEM_JS = "js"; export const ECOSYSTEM_PY = "py"; diff --git a/packages/safe-chain/src/config/settings.spec.js b/packages/safe-chain/src/config/settings.spec.js index 48108c4e..a62b6bb1 100644 --- a/packages/safe-chain/src/config/settings.spec.js +++ b/packages/safe-chain/src/config/settings.spec.js @@ -23,6 +23,11 @@ const { LOGGING_SILENT, LOGGING_NORMAL, LOGGING_VERBOSE, + getLogFile, + getLogFileFormat, + getLogFileVerbosity, + LOG_FILE_FORMAT_PLAIN, + LOG_FILE_FORMAT_JSON, } = await import("./settings.js"); const { initializeCliArguments } = await import("./cliArguments.js"); @@ -645,3 +650,270 @@ describe("getMalwareListBaseUrl", () => { assert.strictEqual(url, "https://cli-mirror.com"); }); }); + +describe("getLogFile", () => { + let originalEnv; + const envVarName = "SAFE_CHAIN_LOG_FILE"; + + beforeEach(() => { + originalEnv = process.env[envVarName]; + delete process.env[envVarName]; + initializeCliArguments([]); + }); + + afterEach(() => { + if (originalEnv !== undefined) { + process.env[envVarName] = originalEnv; + } else { + delete process.env[envVarName]; + } + configFileContent = undefined; + }); + + it("should return undefined when nothing is configured", () => { + assert.strictEqual(getLogFile(), undefined); + }); + + it("should return CLI argument value with highest priority", () => { + initializeCliArguments(["--safe-chain-log-file=/tmp/cli.log"]); + + assert.strictEqual(getLogFile(), "/tmp/cli.log"); + }); + + it("should return environment variable when no CLI argument", () => { + process.env[envVarName] = "/tmp/env.log"; + + assert.strictEqual(getLogFile(), "/tmp/env.log"); + }); + + it("should return config file value when no CLI or env", () => { + configFileContent = JSON.stringify({ logFile: "/tmp/config.log" }); + + assert.strictEqual(getLogFile(), "/tmp/config.log"); + }); + + it("should prioritize CLI over environment variable", () => { + process.env[envVarName] = "/tmp/env.log"; + initializeCliArguments(["--safe-chain-log-file=/tmp/cli.log"]); + + assert.strictEqual(getLogFile(), "/tmp/cli.log"); + }); + + it("should prioritize environment variable over config file", () => { + process.env[envVarName] = "/tmp/env.log"; + configFileContent = JSON.stringify({ logFile: "/tmp/config.log" }); + + assert.strictEqual(getLogFile(), "/tmp/env.log"); + }); + + it("should prioritize CLI over config file", () => { + initializeCliArguments(["--safe-chain-log-file=/tmp/cli.log"]); + configFileContent = JSON.stringify({ logFile: "/tmp/config.log" }); + + assert.strictEqual(getLogFile(), "/tmp/cli.log"); + }); + + it("should expand a leading ~/ to the user's home directory", async () => { + const os = await import("os"); + const path = await import("path"); + process.env[envVarName] = "~/safe-chain.log"; + + // Shells don't expand ~ after `=` and never expand env vars, so the + // logger has to do it. + assert.strictEqual( + getLogFile(), + path.join(os.default.homedir(), "safe-chain.log") + ); + }); + + it("should expand a bare ~ to the user's home directory", async () => { + const os = await import("os"); + process.env[envVarName] = "~"; + + assert.strictEqual(getLogFile(), os.default.homedir()); + }); + + it("should leave non-tilde paths untouched", () => { + process.env[envVarName] = "/var/log/safe-chain.log"; + + assert.strictEqual(getLogFile(), "/var/log/safe-chain.log"); + }); + + it("should not expand mid-path ~ characters", () => { + process.env[envVarName] = "/tmp/~weird/path.log"; + + assert.strictEqual(getLogFile(), "/tmp/~weird/path.log"); + }); +}); + +describe("getLogFileFormat", () => { + let originalEnv; + const envVarName = "SAFE_CHAIN_LOG_FILE_FORMAT"; + + beforeEach(() => { + originalEnv = process.env[envVarName]; + delete process.env[envVarName]; + initializeCliArguments([]); + }); + + afterEach(() => { + if (originalEnv !== undefined) { + process.env[envVarName] = originalEnv; + } else { + delete process.env[envVarName]; + } + configFileContent = undefined; + }); + + it("should return json by default when nothing is configured", () => { + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should return json from CLI argument", () => { + initializeCliArguments(["--safe-chain-log-file-format=json"]); + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should return plain from CLI argument", () => { + initializeCliArguments(["--safe-chain-log-file-format=plain"]); + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_PLAIN); + }); + + it("should return json from environment variable", () => { + process.env[envVarName] = "json"; + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should handle uppercase environment variable values", () => { + process.env[envVarName] = "JSON"; + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should fall back to default for invalid environment variable values", () => { + process.env[envVarName] = "xml"; + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should return json from config file", () => { + configFileContent = JSON.stringify({ logFileFormat: "json" }); + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should prioritize CLI over environment variable", () => { + process.env[envVarName] = "json"; + initializeCliArguments(["--safe-chain-log-file-format=plain"]); + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_PLAIN); + }); + + it("should prioritize environment variable over config file", () => { + process.env[envVarName] = "json"; + configFileContent = JSON.stringify({ logFileFormat: "plain" }); + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should prioritize CLI over config file", () => { + initializeCliArguments(["--safe-chain-log-file-format=json"]); + configFileContent = JSON.stringify({ logFileFormat: "plain" }); + + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); + + it("should fall back to default for invalid CLI value even if env var is set", () => { + process.env[envVarName] = "plain"; + initializeCliArguments(["--safe-chain-log-file-format=xml"]); + + // Set-but-invalid CLI short-circuits to default (mirrors getLoggingLevel). + // An explicit CLI override should not silently fall through to env. + assert.strictEqual(getLogFileFormat(), LOG_FILE_FORMAT_JSON); + }); +}); + +describe("getLogFileVerbosity", () => { + let originalEnv; + const envVarName = "SAFE_CHAIN_LOG_FILE_VERBOSITY"; + + beforeEach(() => { + originalEnv = process.env[envVarName]; + delete process.env[envVarName]; + initializeCliArguments([]); + }); + + afterEach(() => { + if (originalEnv !== undefined) { + process.env[envVarName] = originalEnv; + } else { + delete process.env[envVarName]; + } + configFileContent = undefined; + }); + + it("should default to verbose (maximum) when nothing is configured", () => { + assert.strictEqual(getLogFileVerbosity(), LOGGING_VERBOSE); + }); + + it("should accept verbose, normal, and silent from CLI", () => { + initializeCliArguments(["--safe-chain-log-file-verbosity=silent"]); + assert.strictEqual(getLogFileVerbosity(), LOGGING_SILENT); + + initializeCliArguments(["--safe-chain-log-file-verbosity=normal"]); + assert.strictEqual(getLogFileVerbosity(), LOGGING_NORMAL); + + initializeCliArguments(["--safe-chain-log-file-verbosity=verbose"]); + assert.strictEqual(getLogFileVerbosity(), LOGGING_VERBOSE); + }); + + it("should read from environment variable", () => { + process.env[envVarName] = "silent"; + + assert.strictEqual(getLogFileVerbosity(), LOGGING_SILENT); + }); + + it("should handle uppercase environment variable values", () => { + process.env[envVarName] = "NORMAL"; + + assert.strictEqual(getLogFileVerbosity(), LOGGING_NORMAL); + }); + + it("should read from config file", () => { + configFileContent = JSON.stringify({ logFileVerbosity: "normal" }); + + assert.strictEqual(getLogFileVerbosity(), LOGGING_NORMAL); + }); + + it("should prioritize CLI over environment variable", () => { + process.env[envVarName] = "silent"; + initializeCliArguments(["--safe-chain-log-file-verbosity=verbose"]); + + assert.strictEqual(getLogFileVerbosity(), LOGGING_VERBOSE); + }); + + it("should prioritize environment variable over config file", () => { + process.env[envVarName] = "silent"; + configFileContent = JSON.stringify({ logFileVerbosity: "normal" }); + + assert.strictEqual(getLogFileVerbosity(), LOGGING_SILENT); + }); + + it("should fall back to default when env value is invalid", () => { + process.env[envVarName] = "loud"; + + assert.strictEqual(getLogFileVerbosity(), LOGGING_VERBOSE); + }); + + it("should fall back to default when CLI value is invalid even if env is set", () => { + process.env[envVarName] = "silent"; + initializeCliArguments(["--safe-chain-log-file-verbosity=loud"]); + + // Mirrors getLoggingLevel: an explicit but invalid CLI override goes to + // default rather than silently falling through to env. + assert.strictEqual(getLogFileVerbosity(), LOGGING_VERBOSE); + }); +}); diff --git a/packages/safe-chain/src/environment/fileLogger.js b/packages/safe-chain/src/environment/fileLogger.js new file mode 100644 index 00000000..f63b26ce --- /dev/null +++ b/packages/safe-chain/src/environment/fileLogger.js @@ -0,0 +1,242 @@ +import fs from "fs"; +import path from "path"; +import { + getLogFileFormat, + getLogFileVerbosity, + LOG_FILE_FORMAT_JSON, + LOGGING_SILENT, + LOGGING_VERBOSE, +} from "../config/settings.js"; + +/** + * @type {{ + * stream: fs.WriteStream | null, + * filePath: string, + * command: string, + * format: string, + * verbosity: string, + * warn: ((msg: string) => void) | null, + * }} + */ +const state = { + stream: null, + filePath: "", + command: "", + // Placeholder; initializeFileLogger resolves the real value via + // getLogFileFormat() before the first write. Must be a literal, not + // LOG_FILE_FORMAT_JSON: settings.js -> ui -> fileLogger.js is a real + // import cycle and the constant is in the temporal dead zone when this + // module body runs from the settings -> ui chain. + format: "json", + // Same TDZ concern as `format`: literal placeholder, real value resolved + // in initializeFileLogger. + verbosity: "verbose", + // One-shot. reportFailureOnce consumes it on first failure so subsequent + // failures (sync or async) stay silent. The caller must be a sink that + // does NOT re-enter writeToLogFile, otherwise the cycle returns. + warn: null, +}; + +/** + * Opens a write stream in append mode and writes a session-start entry. + * Idempotent: calls while logging is active are ignored. If the file path + * is not writable, logs a warning and stays inactive. + * + * @param {string} filePath + * @param {(msg: string) => void} warnFn console-only warning sink. Must not + * re-enter writeToLogFile (use ui.writeWarningToConsole, not ui.writeWarning) + * to keep failure reporting cycle-free. + */ +export function initializeFileLogger(filePath, warnFn) { + if (state.stream) return; + + // Set the warn sink before the try block so reportFailureOnce can be + // used in the catch. That keeps the failure path uniform (sync init, + // sync write, async stream error all go through the same helper, which + // nulls state.stream defensively). + state.warn = warnFn; + + try { + fs.mkdirSync(path.dirname(filePath), { recursive: true }); + state.stream = fs.createWriteStream(filePath, { flags: "a" }); + } catch (/** @type {any} */ err) { + reportFailureOnce(`Failed to open log file ${filePath}: ${err.message}`); + return; + } + + state.filePath = filePath; + state.format = getLogFileFormat(); + state.verbosity = getLogFileVerbosity(); + state.command = process.argv.slice(2).join(" "); + + state.stream.on("error", (err) => { + reportFailureOnce(`Failed to write to log file: ${err.message}`); + }); + + writeToLogFile("info", "Log started, command:", state.command); +} + +export function isFileLoggingActive() { + return state.stream !== null; +} + +/** + * Writes a log entry to the file. No-op when not active. Accepts the same + * trailing-params shape as console.log. + * + * @param {"info" | "warning" | "error" | "verbose"} level + * @param {string} message + * @param {...any} params + */ +export function writeToLogFile(level, message, ...params) { + if (!state.stream) return; + if (!shouldWriteLevel(level)) return; + try { + state.stream.write(formatLine(level, message, params)); + } catch (/** @type {any} */ err) { + reportFailureOnce(`Failed to write to log file: ${err?.message ?? err}`); + } +} + +/** + * @param {string} level + * @returns {boolean} + */ +function shouldWriteLevel(level) { + if (state.verbosity === LOGGING_VERBOSE) return true; + if (state.verbosity === LOGGING_SILENT) return level === "error"; + // LOGGING_NORMAL: drop verbose, keep info/warning/error. + return level !== "verbose"; +} + +/** + * Disables further file logging and surfaces the failure to the user once. + * Idempotent: state.warn is consumed on first call, so additional failures + * (sync or async, same session) are silent. + * + * @param {string} message + */ +function reportFailureOnce(message) { + state.stream = null; + const warn = state.warn; + state.warn = null; + if (warn) warn(message); +} + +/** + * Closes the file logger asynchronously, flushing buffered writes. Safe to + * call when inactive or multiple times. Only the first call writes the + * session-end entry. + * + * @returns {Promise} + */ +export function closeFileLogger() { + if (!state.stream) return Promise.resolve(); + const closing = state.stream; + state.stream = null; + state.warn = null; + if (shouldWriteLevel("info")) { + try { + closing.write(formatLine("info", "Log ended, command:", [state.command])); + } catch { + // best-effort: stream is being closed anyway + } + } + return new Promise((resolve) => { + try { + closing.end(resolve); + } catch { + resolve(); + } + }); +} + +/** + * Closes the file logger synchronously, for signal handlers and crash paths + * (uncaughtException, unhandledRejection) that call process.exit() right + * after. + * + * stream.end() only QUEUES a flush; if the process exits before the event + * loop ticks, the session-end write never reaches disk. We use + * fs.appendFileSync for the session-end entry instead so the most + * diagnostically useful line in the log actually lands. Earlier writes + * still buffered in the stream may be lost on crash paths — there is no + * sync flush API for WriteStream — but the session-end + command remains. + */ +export function closeFileLoggerSync() { + if (!state.stream) return; + const closing = state.stream; + state.stream = null; + state.warn = null; + if (shouldWriteLevel("info")) { + try { + fs.appendFileSync( + state.filePath, + formatLine("info", "Log ended, command:", [state.command]) + ); + } catch { + // best-effort: file may have become unwritable + } + } + try { + closing.end(); + } catch { + // best-effort: stream is being closed anyway + } +} + +/** + * Formats a log entry as a single newline-terminated line, either as NDJSON + * or as bracketed plain text: `[timestamp] [level] message param1 param2 ...` + * + * @param {string} level + * @param {string} message + * @param {any[]} params - console.log-style trailing args + * @returns {string} + */ +function formatLine(level, message, params) { + const timestamp = new Date().toISOString(); + + const fullMessage = + params.length === 0 + ? message + : `${message} ${params.map(formatParam).join(" ")}`; + + if (state.format === LOG_FILE_FORMAT_JSON) { + return JSON.stringify({ timestamp, level, message: fullMessage }) + "\n"; + } + + // Escape CR/LF in plain mode so a message containing a newline can't forge + // a separate log entry. JSON mode is already safe via JSON.stringify. + return `[${timestamp}] [${level}] ${escapeNewlines(fullMessage)}\n`; +} + +/** + * @param {string} value + * @returns {string} + */ +function escapeNewlines(value) { + return value.replace(/\r/g, "\\r").replace(/\n/g, "\\n"); +} + +/** + * Stringifies a log param: Errors keep their stack, strings pass through, + * everything else becomes JSON (falling back to String() for values that + * JSON.stringify rejects, like circular references or BigInt). + * + * @param {any} value + * @returns {string} + */ +function formatParam(value) { + if (value instanceof Error) { + return value.stack || value.message; + } + if (typeof value === "string") { + return value; + } + try { + return JSON.stringify(value); + } catch { + return String(value); + } +} diff --git a/packages/safe-chain/src/environment/fileLogger.spec.js b/packages/safe-chain/src/environment/fileLogger.spec.js new file mode 100644 index 00000000..b9c6bbed --- /dev/null +++ b/packages/safe-chain/src/environment/fileLogger.spec.js @@ -0,0 +1,458 @@ +import { describe, it, beforeEach, afterEach, mock } from "node:test"; +import assert from "node:assert"; + +let writtenData = []; +let mockStreamError = null; +let currentFormat = "json"; + +const mockWriteStream = { + write: (data) => { + writtenData.push(data); + return true; + }, + end: (cb) => { + if (cb) cb(); + }, + on: (event, handler) => { + if (event === "error" && mockStreamError) { + handler(mockStreamError); + } + }, +}; + +mock.module("fs", { + namedExports: { + existsSync: () => true, + createWriteStream: () => mockWriteStream, + mkdirSync: () => { }, + readFileSync: () => "", + writeFileSync: () => { }, + appendFileSync: (_path, data) => { + // closeFileLoggerSync writes the session-end entry via appendFileSync + // (so it actually lands on process.exit). Mirror it into writtenData + // so existing assertions about session-end content still apply. + writtenData.push(data); + }, + }, +}); + +let currentVerbosity = "verbose"; + +mock.module("../config/settings.js", { + namedExports: { + LOG_FILE_FORMAT_PLAIN: "plain", + LOG_FILE_FORMAT_JSON: "json", + getLogFileFormat: () => currentFormat, + LOGGING_SILENT: "silent", + LOGGING_NORMAL: "normal", + LOGGING_VERBOSE: "verbose", + getLogFileVerbosity: () => currentVerbosity, + }, +}); + +const { + initializeFileLogger, + isFileLoggingActive, + writeToLogFile, + closeFileLogger, + closeFileLoggerSync, +} = await import("./fileLogger.js"); + +function initAndReset() { + initializeFileLogger("/tmp/test.log", () => { }); + writtenData = []; +} + +describe("fileLogger - plain format", () => { + beforeEach(() => { + writtenData = []; + mockStreamError = null; + currentFormat = "plain"; + currentVerbosity = "verbose"; + }); + + afterEach(() => { + closeFileLoggerSync(); + }); + + it("should not be active before initialization", () => { + assert.strictEqual(isFileLoggingActive(), false); + }); + + it("should be active after initialization", () => { + initializeFileLogger("/tmp/test.log", () => { }); + assert.strictEqual(isFileLoggingActive(), true); + }); + + it("should write a plain-text session start entry on init", () => { + initializeFileLogger("/tmp/test.log", () => { }); + + assert.strictEqual(writtenData.length, 1); + assert.ok(writtenData[0].includes("[info]")); + assert.ok(writtenData[0].includes("Log started, command:")); + }); + + it("should write plain-text log entries with timestamp and level", () => { + initAndReset(); + + writeToLogFile("warning", "something happened"); + + assert.strictEqual(writtenData.length, 1); + assert.ok(writtenData[0].includes("[warning]")); + assert.ok(writtenData[0].includes("something happened")); + assert.ok(writtenData[0].endsWith("\n")); + }); + + it("should write plain-text log entries for all levels", () => { + initAndReset(); + + writeToLogFile("info", "info msg"); + writeToLogFile("verbose", "verbose msg"); + writeToLogFile("error", "error msg"); + writeToLogFile("warning", "warning msg"); + + assert.strictEqual(writtenData.length, 4); + assert.ok(writtenData[0].includes("[info]")); + assert.ok(writtenData[1].includes("[verbose]")); + assert.ok(writtenData[2].includes("[error]")); + assert.ok(writtenData[3].includes("[warning]")); + }); + + it("should preserve ANSI codes in messages", () => { + initAndReset(); + + writeToLogFile("info", "\x1b[31mred error\x1b[0m"); + + assert.ok(writtenData[0].includes("\x1b[31m")); + assert.ok(writtenData[0].includes("red error")); + }); + + it("should append params after the message in plain format", () => { + initAndReset(); + + writeToLogFile("info", "hello", "world", { k: "v" }); + + assert.ok(writtenData[0].includes("hello")); + assert.ok(writtenData[0].includes("world")); + assert.ok(writtenData[0].includes('{"k":"v"}')); + }); + + it("should escape CR/LF in plain-format messages to prevent log injection", () => { + initAndReset(); + + writeToLogFile("info", "evil\n[ts] [info] forged", "param\rline"); + + // Each call should produce exactly one line. A naive implementation + // would emit two newline-separated lines and let the second masquerade + // as an independent log entry. + assert.strictEqual(writtenData.length, 1); + const line = writtenData[0]; + assert.strictEqual((line.match(/\n/g) || []).length, 1); + assert.ok(line.endsWith("\n")); + assert.ok(line.includes("evil\\n[ts] [info] forged")); + assert.ok(line.includes("param\\rline")); + }); + + it("should not be active after sync close", () => { + initializeFileLogger("/tmp/test.log", () => { }); + assert.strictEqual(isFileLoggingActive(), true); + + closeFileLoggerSync(); + + assert.strictEqual(isFileLoggingActive(), false); + }); + + it("should not be active after async close", async () => { + initializeFileLogger("/tmp/test.log", () => { }); + assert.strictEqual(isFileLoggingActive(), true); + + await closeFileLogger(); + + assert.strictEqual(isFileLoggingActive(), false); + }); + + it("should write a log-ended-with-command entry on async close", async () => { + initAndReset(); + + await closeFileLogger(); + + assert.strictEqual(writtenData.length, 1); + assert.ok(writtenData[0].includes("Log ended, command:")); + }); + + it("should write a log-ended-with-command entry on sync close", () => { + initAndReset(); + + closeFileLoggerSync(); + + assert.strictEqual(writtenData.length, 1); + assert.ok(writtenData[0].includes("Log ended, command:")); + }); + + it("should write the session-end entry via appendFileSync on sync close", () => { + // stream.end() only queues a flush; on process.exit() in a signal / + // crash handler the queued write is lost. The session-end entry has + // to bypass the stream and write directly to disk synchronously. + initAndReset(); + + const streamWrites = []; + const originalWrite = mockWriteStream.write; + mockWriteStream.write = (data) => { + streamWrites.push(data); + return true; + }; + + try { + closeFileLoggerSync(); + } finally { + mockWriteStream.write = originalWrite; + } + + assert.strictEqual( + streamWrites.length, + 0, + "session-end must not go through stream.write" + ); + assert.strictEqual(writtenData.length, 1); + assert.ok(writtenData[0].includes("Log ended, command:")); + }); + + it("should not write when not initialized", () => { + writeToLogFile("info", "should be ignored"); + + assert.strictEqual(writtenData.length, 0); + }); + + it("initialize should be idempotent", () => { + initializeFileLogger("/tmp/test.log", () => { }); + const after_first = writtenData.length; + + initializeFileLogger("/tmp/test.log", () => { }); + + assert.strictEqual(writtenData.length, after_first); + }); +}); + +describe("fileLogger - json format", () => { + beforeEach(() => { + writtenData = []; + mockStreamError = null; + currentFormat = "json"; + currentVerbosity = "verbose"; + }); + + afterEach(() => { + closeFileLoggerSync(); + }); + + it("should write JSON session start entry on init", () => { + initializeFileLogger("/tmp/test.log", () => { }); + + assert.strictEqual(writtenData.length, 1); + const entry = JSON.parse(writtenData[0]); + assert.strictEqual(entry.level, "info"); + assert.ok(!("source" in entry)); + assert.ok(entry.message.includes("Log started, command:")); + assert.ok(entry.timestamp); + assert.ok(!("params" in entry)); + }); + + it("should write structured JSON log entries", () => { + initAndReset(); + + writeToLogFile("warning", "something happened"); + + assert.strictEqual(writtenData.length, 1); + const entry = JSON.parse(writtenData[0]); + assert.strictEqual(entry.level, "warning"); + assert.ok(!("source" in entry)); + assert.strictEqual(entry.message, "something happened"); + assert.ok(entry.timestamp); + assert.ok(!("params" in entry)); + }); + + it("should preserve ANSI codes in JSON message field", () => { + initAndReset(); + + writeToLogFile("error", "\x1b[31mred error\x1b[0m"); + + const entry = JSON.parse(writtenData[0]); + assert.strictEqual(entry.message, "\x1b[31mred error\x1b[0m"); + }); + + it("should append params to the message when extra args are passed", () => { + initAndReset(); + + writeToLogFile("info", "hello", "world", { k: "v" }, 42); + + const entry = JSON.parse(writtenData[0]); + assert.strictEqual(entry.message, 'hello world {"k":"v"} 42'); + assert.ok(!("params" in entry)); + }); + + it("should write a JSON log-ended-with-command entry on async close", async () => { + initAndReset(); + + await closeFileLogger(); + + assert.strictEqual(writtenData.length, 1); + const entry = JSON.parse(writtenData[0]); + assert.strictEqual(entry.level, "info"); + assert.ok(entry.message.includes("Log ended, command:")); + }); + + it("should produce valid NDJSON (each line parseable)", () => { + initAndReset(); + + writeToLogFile("info", "first"); + writeToLogFile("error", "second"); + writeToLogFile("verbose", "third"); + + for (const data of writtenData) { + assert.ok(data.endsWith("\n"), "Each entry should end with newline"); + const parsed = JSON.parse(data); + assert.ok(parsed.timestamp); + assert.ok(parsed.level); + assert.ok(!("source" in parsed)); + } + }); +}); + +describe("fileLogger - error handling", () => { + beforeEach(() => { + writtenData = []; + mockStreamError = null; + currentFormat = "json"; + currentVerbosity = "verbose"; + }); + + afterEach(() => { + closeFileLoggerSync(); + }); + + it("should call warnFn and remain inactive on stream error during init", () => { + mockStreamError = new Error("disk full"); + const warnings = []; + + initializeFileLogger("/tmp/test.log", (msg) => warnings.push(msg)); + + assert.strictEqual(isFileLoggingActive(), false); + assert.ok(warnings.some((w) => w.includes("disk full"))); + }); + + it("should call warnFn once when a mid-session write throws", () => { + const warnings = []; + initializeFileLogger("/tmp/test.log", (msg) => warnings.push(msg)); + writtenData = []; + + const originalWrite = mockWriteStream.write; + mockWriteStream.write = () => { + throw new Error("disk full mid-session"); + }; + + try { + writeToLogFile("info", "first"); + writeToLogFile("info", "second"); // already inactive, should not re-warn + } finally { + mockWriteStream.write = originalWrite; + } + + assert.strictEqual(isFileLoggingActive(), false); + assert.strictEqual( + warnings.filter((w) => w.includes("disk full mid-session")).length, + 1 + ); + }); + + it("should handle closeFileLoggerSync when not initialized", () => { + closeFileLoggerSync(); + assert.strictEqual(isFileLoggingActive(), false); + }); + + it("should handle closeFileLogger when not initialized", async () => { + await closeFileLogger(); + assert.strictEqual(isFileLoggingActive(), false); + }); + + it("should be a no-op when closeFileLogger is called twice", async () => { + initAndReset(); + + await closeFileLogger(); + const after_first = writtenData.length; + await closeFileLogger(); + + assert.strictEqual(writtenData.length, after_first); + assert.strictEqual(isFileLoggingActive(), false); + }); +}); + +describe("fileLogger - verbosity filter", () => { + beforeEach(() => { + writtenData = []; + mockStreamError = null; + currentFormat = "json"; + currentVerbosity = "verbose"; + }); + + afterEach(() => { + closeFileLoggerSync(); + }); + + it("verbose verbosity writes every level", () => { + currentVerbosity = "verbose"; + initAndReset(); + + writeToLogFile("info", "i"); + writeToLogFile("warning", "w"); + writeToLogFile("error", "e"); + writeToLogFile("verbose", "v"); + + assert.strictEqual(writtenData.length, 4); + }); + + it("normal verbosity drops verbose entries", () => { + currentVerbosity = "normal"; + initAndReset(); + + writeToLogFile("info", "i"); + writeToLogFile("warning", "w"); + writeToLogFile("error", "e"); + writeToLogFile("verbose", "v"); + + assert.strictEqual(writtenData.length, 3); + const levels = writtenData.map((d) => JSON.parse(d).level); + assert.deepEqual(levels, ["info", "warning", "error"]); + }); + + it("silent verbosity records only error entries", async () => { + // The file is still created so errors have somewhere to land — silent + // mirrors console silent semantics (errors always surface) rather than + // disabling file logging entirely. + currentVerbosity = "silent"; + initializeFileLogger("/tmp/test.log", () => { }); + writtenData = []; + + writeToLogFile("info", "i"); + writeToLogFile("warning", "w"); + writeToLogFile("verbose", "v"); + writeToLogFile("error", "boom"); + + assert.strictEqual(writtenData.length, 1); + const entry = JSON.parse(writtenData[0]); + assert.strictEqual(entry.level, "error"); + assert.strictEqual(entry.message, "boom"); + }); + + it("silent verbosity skips the session-start and session-end entries", async () => { + currentVerbosity = "silent"; + initializeFileLogger("/tmp/test.log", () => { }); + + // Session-start (info-level) is filtered out. + assert.strictEqual(writtenData.length, 0); + + await closeFileLogger(); + + // Session-end (info-level) is also filtered out. + assert.strictEqual(writtenData.length, 0); + }); +}); diff --git a/packages/safe-chain/src/environment/userInteraction.js b/packages/safe-chain/src/environment/userInteraction.js index 9115b582..d3ec29c7 100644 --- a/packages/safe-chain/src/environment/userInteraction.js +++ b/packages/safe-chain/src/environment/userInteraction.js @@ -6,6 +6,7 @@ import { LOGGING_SILENT, LOGGING_VERBOSE, } from "../config/settings.js"; +import { writeToLogFile } from "./fileLogger.js"; /** * @type {{ bufferOutput: boolean, bufferedMessages:(() => void)[]}} @@ -26,7 +27,7 @@ function isVerboseMode() { function emptyLine() { if (isSilentMode()) return; - writeInformation(""); + writeOrBuffer(() => console.log("")); } /** @@ -35,6 +36,8 @@ function emptyLine() { * @returns {void} */ function writeInformation(message, ...optionalParams) { + writeToLogFile("info", message, ...optionalParams); + if (isSilentMode()) return; writeOrBuffer(() => console.log(message, ...optionalParams)); @@ -46,6 +49,19 @@ function writeInformation(message, ...optionalParams) { * @returns {void} */ function writeWarning(message, ...optionalParams) { + writeToLogFile("warning", message, ...optionalParams); + writeWarningToConsole(message, ...optionalParams); +} + +/** + * Console-only warning. Used by fileLogger to surface its own failures + * without re-entering writeToLogFile and creating a runtime cycle. + * + * @param {string} message + * @param {...any} optionalParams + * @returns {void} + */ +function writeWarningToConsole(message, ...optionalParams) { if (isSilentMode()) return; if (!isCi()) { @@ -60,6 +76,8 @@ function writeWarning(message, ...optionalParams) { * @returns {void} */ function writeError(message, ...optionalParams) { + writeToLogFile("error", message, ...optionalParams); + if (!isCi()) { message = chalk.red(message); } @@ -68,6 +86,8 @@ function writeError(message, ...optionalParams) { function writeExitWithoutInstallingMaliciousPackages() { let message = "Safe-chain: Exiting without installing malicious packages."; + writeToLogFile("error", message); + if (!isCi()) { message = chalk.red(message); } @@ -80,6 +100,8 @@ function writeExitWithoutInstallingMaliciousPackages() { * @returns {void} */ function writeVerbose(message, ...optionalParams) { + writeToLogFile("verbose", message, ...optionalParams); + if (!isVerboseMode()) return; writeOrBuffer(() => console.log(message, ...optionalParams)); @@ -114,6 +136,7 @@ export const ui = { writeVerbose, writeInformation, writeWarning, + writeWarningToConsole, writeError, writeExitWithoutInstallingMaliciousPackages, emptyLine, diff --git a/packages/safe-chain/src/main.js b/packages/safe-chain/src/main.js index 74f8a257..f94ca4a0 100644 --- a/packages/safe-chain/src/main.js +++ b/packages/safe-chain/src/main.js @@ -4,9 +4,15 @@ import { scanCommand, shouldScanCommand } from "./scanning/index.js"; import { ui } from "./environment/userInteraction.js"; import { getPackageManager } from "./packagemanager/currentPackageManager.js"; import { initializeCliArguments } from "./config/cliArguments.js"; +import { getLogFile } from "./config/settings.js"; import { createSafeChainProxy } from "./registryProxy/registryProxy.js"; import chalk from "chalk"; import { getAuditStats } from "./scanning/audit/index.js"; +import { + initializeFileLogger, + closeFileLogger, + closeFileLoggerSync, +} from "./environment/fileLogger.js"; /** * @param {string[]} args @@ -28,6 +34,7 @@ export async function main(args) { ui.writeError(`Safe-chain: Uncaught exception: ${error.message}`); ui.writeVerbose(`Stack trace: ${error.stack}`); ui.writeBufferedLogsAndStopBuffering(); + closeFileLoggerSync(); process.exit(1); }); @@ -37,6 +44,7 @@ export async function main(args) { ui.writeVerbose(`Stack trace: ${reason.stack}`); } ui.writeBufferedLogsAndStopBuffering(); + closeFileLoggerSync(); process.exit(1); }); @@ -44,6 +52,14 @@ export async function main(args) { // This parses all the --safe-chain arguments and removes them from the args array args = initializeCliArguments(args); + const logFile = getLogFile(); + if (logFile) { + // Use the console-only warning sink: ui.writeWarning would re-enter + // writeToLogFile, creating a cycle whenever the logger needs to + // report its own failure. + initializeFileLogger(logFile, ui.writeWarningToConsole); + } + if (shouldScanCommand(args)) { const commandScanResult = await scanCommand(args); @@ -105,12 +121,16 @@ export async function main(args) { // to be awaited in the bin files and return the correct exit code return 1; } finally { - await proxy.stopServer(); + // Both must run even if one throws. Losing the session-end entry + // because stopServer() rejected (or vice versa) defeats the point of + // having a log on failure paths. + await Promise.allSettled([proxy.stopServer(), closeFileLogger()]); } } function handleProcessTermination() { ui.writeBufferedLogsAndStopBuffering(); + closeFileLoggerSync(); } /** @param {string[]} args */ diff --git a/packages/safe-chain/src/registryProxy/interceptors/npm/npmInterceptor.packageDownload.spec.js b/packages/safe-chain/src/registryProxy/interceptors/npm/npmInterceptor.packageDownload.spec.js index 769b6e15..f4a80971 100644 --- a/packages/safe-chain/src/registryProxy/interceptors/npm/npmInterceptor.packageDownload.spec.js +++ b/packages/safe-chain/src/registryProxy/interceptors/npm/npmInterceptor.packageDownload.spec.js @@ -23,6 +23,8 @@ mock.module("../../../config/settings.js", { LOGGING_VERBOSE: "verbose", ECOSYSTEM_JS: "js", ECOSYSTEM_PY: "py", + LOG_FILE_FORMAT_JSON: "json", + LOG_FILE_FORMAT_PLAIN: "plain", getLoggingLevel: () => "normal", getEcoSystem: () => "js", setEcoSystem: () => {}, @@ -30,6 +32,9 @@ mock.module("../../../config/settings.js", { getNpmCustomRegistries: () => customRegistries, getMinimumPackageAgeExclusions: () => [], skipMinimumPackageAge: () => skipMinimumPackageAgeSetting, + getLogFileFormat: () => "json", + getLogFileVerbosity: () => "verbose", + getLogFile: () => undefined, }, }); mock.module("../../../scanning/newPackagesListCache.js", { diff --git a/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.customRegistries.spec.js b/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.customRegistries.spec.js index 5904f05a..9236407b 100644 --- a/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.customRegistries.spec.js +++ b/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.customRegistries.spec.js @@ -16,7 +16,12 @@ describe("pipInterceptor custom registries", async () => { getPipCustomRegistries: () => customRegistries, LOGGING_SILENT: "silent", LOGGING_VERBOSE: "verbose", + LOG_FILE_FORMAT_JSON: "json", + LOG_FILE_FORMAT_PLAIN: "plain", skipMinimumPackageAge: () => false, + getLogFileFormat: () => "json", + getLogFileVerbosity: () => "verbose", + getLogFile: () => undefined, }, }); diff --git a/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.minPackageAge.spec.js b/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.minPackageAge.spec.js index f311df74..43b701c0 100644 --- a/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.minPackageAge.spec.js +++ b/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.minPackageAge.spec.js @@ -36,7 +36,12 @@ describe("pipInterceptor minimum package age", async () => { getPipCustomRegistries: () => [], LOGGING_SILENT: "silent", LOGGING_VERBOSE: "verbose", + LOG_FILE_FORMAT_JSON: "json", + LOG_FILE_FORMAT_PLAIN: "plain", skipMinimumPackageAge: () => skipMinimumPackageAgeSetting, + getLogFileFormat: () => "json", + getLogFileVerbosity: () => "verbose", + getLogFile: () => undefined, }, }); diff --git a/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.packageDownload.spec.js b/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.packageDownload.spec.js index f4a54a42..30163b1b 100644 --- a/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.packageDownload.spec.js +++ b/packages/safe-chain/src/registryProxy/interceptors/pip/pipInterceptor.packageDownload.spec.js @@ -32,7 +32,12 @@ describe("pipInterceptor", async () => { getPipCustomRegistries: () => [], LOGGING_SILENT: "silent", LOGGING_VERBOSE: "verbose", + LOG_FILE_FORMAT_JSON: "json", + LOG_FILE_FORMAT_PLAIN: "plain", skipMinimumPackageAge: () => false, + getLogFileFormat: () => "json", + getLogFileVerbosity: () => "verbose", + getLogFile: () => undefined, }, });