test(utils): define lean logger contract
(cherry picked from commit 4ded69a293827e0dfbc3333f3da2944c97d71016)
This commit is contained in:
usr-bin-roygbiv
@@ -0,0 +1,15 @@
|
||||
import * as fs from "node:fs";
|
||||
import { logger as rootLogger } from "../../src/index";
|
||||
import * as directLogger from "../../src/logger";
|
||||
|
||||
const outputPath = process.argv[2];
|
||||
if (!outputPath) throw new Error("expected output path");
|
||||
|
||||
const keys = Object.keys(directLogger).sort();
|
||||
const identities = keys.every(key => {
|
||||
const direct = directLogger as Record<string, unknown>;
|
||||
const root = rootLogger as Record<string, unknown>;
|
||||
return direct[key] === root[key];
|
||||
});
|
||||
|
||||
fs.writeFileSync(outputPath, JSON.stringify({ identities, keys }));
|
||||
@@ -0,0 +1,9 @@
|
||||
import * as fs from "node:fs";
|
||||
import * as winston from "winston";
|
||||
import { snapshotLoggerRuntime } from "./logger-cache-snapshot";
|
||||
|
||||
const outputPath = process.argv[2];
|
||||
if (!outputPath) throw new Error("expected output path");
|
||||
|
||||
void winston;
|
||||
fs.writeFileSync(outputPath, JSON.stringify(snapshotLoggerRuntime()));
|
||||
@@ -0,0 +1,29 @@
|
||||
import * as fs from "node:fs";
|
||||
import * as logger from "../../src/logger";
|
||||
import { snapshotLoggerRuntime } from "./logger-cache-snapshot";
|
||||
|
||||
const scenario = process.argv[2];
|
||||
const outputPath = process.argv[3];
|
||||
const logsDir = process.argv[4];
|
||||
|
||||
if (!scenario || !outputPath) throw new Error("expected scenario and output path");
|
||||
|
||||
switch (scenario) {
|
||||
case "import":
|
||||
break;
|
||||
case "console":
|
||||
logger.setTransports({ console: true, file: false });
|
||||
logger.info("logger-cache-console");
|
||||
logger.setTransports({ console: false, file: false });
|
||||
break;
|
||||
case "file":
|
||||
if (!logsDir) throw new Error("file scenario requires logs directory");
|
||||
logger.setTransports({ console: false, file: logsDir });
|
||||
logger.info("logger-cache-file");
|
||||
logger.setTransports({ console: false, file: false });
|
||||
break;
|
||||
default:
|
||||
throw new Error(`unknown scenario: ${scenario}`);
|
||||
}
|
||||
|
||||
fs.writeFileSync(outputPath, JSON.stringify(snapshotLoggerRuntime()));
|
||||
@@ -0,0 +1,39 @@
|
||||
import * as fs from "node:fs";
|
||||
import * as nodeModule from "node:module";
|
||||
|
||||
interface ModuleConstructorWithCache {
|
||||
readonly _cache: Record<string, object>;
|
||||
}
|
||||
|
||||
export interface CacheFamily {
|
||||
readonly modules: number;
|
||||
readonly bytes: number;
|
||||
readonly paths: string[];
|
||||
}
|
||||
|
||||
export interface LoggerCacheSnapshot {
|
||||
readonly winston: CacheFamily;
|
||||
readonly fileStreamRotator: CacheFamily;
|
||||
readonly moment: CacheFamily;
|
||||
}
|
||||
|
||||
const moduleCache = (nodeModule.Module as unknown as ModuleConstructorWithCache)._cache;
|
||||
|
||||
function snapshotFamily(segment: string): CacheFamily {
|
||||
const paths = Object.keys(moduleCache)
|
||||
.filter(modulePath => modulePath.replaceAll("\\", "/").includes(segment))
|
||||
.sort();
|
||||
return {
|
||||
modules: paths.length,
|
||||
bytes: paths.reduce((total, modulePath) => total + fs.statSync(modulePath).size, 0),
|
||||
paths,
|
||||
};
|
||||
}
|
||||
|
||||
export function snapshotLoggerRuntime(): LoggerCacheSnapshot {
|
||||
return {
|
||||
winston: snapshotFamily("/node_modules/winston/"),
|
||||
fileStreamRotator: snapshotFamily("/node_modules/file-stream-rotator/"),
|
||||
moment: snapshotFamily("/node_modules/moment/"),
|
||||
};
|
||||
}
|
||||
@@ -0,0 +1,226 @@
|
||||
import * as fs from "node:fs";
|
||||
import * as path from "node:path";
|
||||
import * as logger from "../../src/logger";
|
||||
|
||||
const scenario = process.argv[2];
|
||||
const primaryDir = process.argv[3];
|
||||
const secondaryDir = process.argv[4];
|
||||
const resultPath = process.argv[5];
|
||||
|
||||
if (!scenario || !primaryDir || !secondaryDir || !resultPath) {
|
||||
throw new Error("expected scenario, primary directory, secondary directory, and result path");
|
||||
}
|
||||
|
||||
function disableTransports(): void {
|
||||
logger.setTransports({ console: false, file: false });
|
||||
}
|
||||
|
||||
function writeResult(value: unknown): void {
|
||||
fs.writeFileSync(resultPath, JSON.stringify(value));
|
||||
}
|
||||
|
||||
switch (scenario) {
|
||||
case "matrix": {
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
logger.error("level-error", { ordinal: 1 });
|
||||
logger.warn("level-warn", { ordinal: 2 });
|
||||
logger.info("level-info", { ordinal: 3 });
|
||||
logger.debug("level-debug", { ordinal: 4 });
|
||||
|
||||
const hidden = Symbol("hidden");
|
||||
const context: Record<string, unknown> & { [hidden]?: unknown } = {
|
||||
stringValue: "text",
|
||||
numberValue: 7,
|
||||
booleanValue: false,
|
||||
nullValue: null,
|
||||
nested: { alpha: "a", values: [1, undefined, () => "omitted", Number.NaN] },
|
||||
undefinedValue: undefined,
|
||||
functionValue: () => "omitted",
|
||||
infinity: Number.POSITIVE_INFINITY,
|
||||
nan: Number.NaN,
|
||||
};
|
||||
context[hidden] = "omitted";
|
||||
logger.info("context-matrix", context);
|
||||
logger.warn("reserved-primary", {
|
||||
before: "first",
|
||||
message: "metadata-message",
|
||||
level: "context-level",
|
||||
timestamp: "context-timestamp",
|
||||
after: "last",
|
||||
});
|
||||
logger.debug("reserved-falsy", { message: "", after: true });
|
||||
|
||||
const cause = new Error("downstream");
|
||||
cause.stack = "CAUSE_STACK";
|
||||
const error = new Error("upstream", { cause }) as Error & { code: string; detail: { retry: boolean } };
|
||||
error.name = "CustomError";
|
||||
error.stack = "OUTER_STACK";
|
||||
error.code = "E_FIXTURE";
|
||||
error.detail = { retry: false };
|
||||
logger.error("error-matrix", { error });
|
||||
disableTransports();
|
||||
break;
|
||||
}
|
||||
case "format-tokens": {
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
for (const token of ["s", "c", "d", "j", "i", "f", "o", "O", "%"]) {
|
||||
logger.info(`token-%${token}`, { value: 7 });
|
||||
}
|
||||
logger.info("non-token-%q", { value: 7 });
|
||||
interface TokenCircularContext extends Record<string, unknown> {
|
||||
self?: TokenCircularContext;
|
||||
}
|
||||
const circular: TokenCircularContext = { kind: "circular" };
|
||||
circular.self = circular;
|
||||
logger.info("circular-%s", circular);
|
||||
logger.info("bigint-%d", { value: 1n });
|
||||
disableTransports();
|
||||
break;
|
||||
}
|
||||
case "serialization-failures": {
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
interface CircularContext extends Record<string, unknown> {
|
||||
self?: CircularContext;
|
||||
}
|
||||
const circular: CircularContext = { kind: "circular" };
|
||||
circular.self = circular;
|
||||
const bigintContext: Record<string, unknown> = { value: 1n };
|
||||
const expectedContexts: Record<string, unknown>[] = [circular, bigintContext];
|
||||
const events: Array<{ level: logger.LogLevel; message: string; sameContext: boolean; timestamp: string }> = [];
|
||||
const dispose = logger.registerLogSink(event => {
|
||||
const expected = expectedContexts[events.length];
|
||||
events.push({
|
||||
level: event.level,
|
||||
message: event.message,
|
||||
sameContext: event.context === expected,
|
||||
timestamp: event.timestamp.toISOString(),
|
||||
});
|
||||
});
|
||||
logger.info("circular-drop", circular);
|
||||
logger.error("bigint-drop", bigintContext);
|
||||
dispose();
|
||||
disableTransports();
|
||||
writeResult({ events });
|
||||
break;
|
||||
}
|
||||
case "default-file":
|
||||
logger.info("mode-default", { mode: "default" });
|
||||
disableTransports();
|
||||
break;
|
||||
case "file-only":
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
logger.info("mode-file", { mode: "file" });
|
||||
disableTransports();
|
||||
break;
|
||||
case "console-only":
|
||||
logger.setTransports({ console: true, file: false });
|
||||
logger.info("mode-console", { mode: "console" });
|
||||
disableTransports();
|
||||
break;
|
||||
case "both":
|
||||
logger.setTransports({ console: true, file: primaryDir });
|
||||
logger.info("mode-both", { mode: "both" });
|
||||
disableTransports();
|
||||
break;
|
||||
case "disabled-reenable": {
|
||||
const contexts: Record<string, unknown>[] = [];
|
||||
const disabledContext = { mode: "disabled" };
|
||||
const dispose = logger.registerLogSink(event => {
|
||||
if (event.context) contexts.push(event.context);
|
||||
});
|
||||
const setReturn = logger.setTransports({ console: false, file: false });
|
||||
const logReturn = logger.warn("mode-disabled", disabledContext);
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
logger.warn("mode-reenabled", { mode: "file" });
|
||||
const disposeReturn = dispose();
|
||||
disableTransports();
|
||||
writeResult({
|
||||
disabledSinkSameContext: contexts[0] === disabledContext,
|
||||
sinkCount: contexts.length,
|
||||
returnsUndefined: setReturn === undefined && logReturn === undefined && disposeReturn === undefined,
|
||||
});
|
||||
break;
|
||||
}
|
||||
case "reconfigure":
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
logger.info("directory-a", { destination: "a" });
|
||||
logger.setTransports({ console: false, file: secondaryDir });
|
||||
logger.info("directory-b", { destination: "b" });
|
||||
disableTransports();
|
||||
break;
|
||||
case "reconfigure-failure": {
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
logger.info("before-failed-reconfigure");
|
||||
const blockerPath = path.join(secondaryDir, "not-a-directory");
|
||||
fs.writeFileSync(blockerPath, "blocked");
|
||||
let reconfigureThrew = false;
|
||||
try {
|
||||
logger.setTransports({ console: false, file: path.join(blockerPath, "child") });
|
||||
} catch {
|
||||
reconfigureThrew = true;
|
||||
}
|
||||
const sinkContext = { after: "failure" };
|
||||
let sinkSameContext = false;
|
||||
let sinkCount = 0;
|
||||
const dispose = logger.registerLogSink(event => {
|
||||
sinkCount++;
|
||||
sinkSameContext = event.context === sinkContext;
|
||||
});
|
||||
logger.info("after-failed-reconfigure", sinkContext);
|
||||
dispose();
|
||||
await Bun.sleep(20);
|
||||
writeResult({ reconfigureThrew, sinkCount, sinkSameContext });
|
||||
break;
|
||||
}
|
||||
case "burst-close":
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
for (let index = 0; index < 1_000; index++) logger.info("burst-close", { index });
|
||||
disableTransports();
|
||||
break;
|
||||
case "burst-natural":
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
for (let index = 0; index < 1_000; index++) logger.info("burst-natural", { index });
|
||||
break;
|
||||
case "sink-order": {
|
||||
logger.setTransports({ console: true, file: false });
|
||||
const sinkContext = { identity: "same" };
|
||||
const dispose = logger.registerLogSink(event => {
|
||||
process.stdout.write(`SINK:${event.context === sinkContext}\n`);
|
||||
throw new Error("sink failure must be isolated");
|
||||
});
|
||||
logger.info("sink-first", sinkContext);
|
||||
dispose();
|
||||
logger.info("sink-disposed");
|
||||
disableTransports();
|
||||
break;
|
||||
}
|
||||
case "date-retention": {
|
||||
const dates = [
|
||||
"2026-01-02T03:04:05.006Z",
|
||||
"2026-01-03T03:04:05.006Z",
|
||||
"2026-01-04T03:04:05.006Z",
|
||||
"2026-01-05T03:04:05.006Z",
|
||||
"2026-01-06T03:04:05.006Z",
|
||||
"2026-01-07T03:04:05.006Z",
|
||||
];
|
||||
process.env.OMP_LOGGER_TEST_NOW = dates[0];
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
for (const [index, date] of dates.entries()) {
|
||||
process.env.OMP_LOGGER_TEST_NOW = date;
|
||||
logger.info(`date-${index + 1}`);
|
||||
await Bun.sleep(10);
|
||||
}
|
||||
disableTransports();
|
||||
break;
|
||||
}
|
||||
case "size-rotation":
|
||||
logger.setTransports({ console: false, file: primaryDir });
|
||||
logger.info("size-nine-mib", { payload: "x".repeat(9 * 1024 * 1024) });
|
||||
logger.info("size-half-mib", { payload: "y".repeat(512 * 1024) });
|
||||
logger.info("size-crosses-ten-mib", { payload: "z".repeat(1024 * 1024) });
|
||||
logger.info("rotation-trigger");
|
||||
disableTransports();
|
||||
break;
|
||||
default:
|
||||
throw new Error(`unknown scenario: ${scenario}`);
|
||||
}
|
||||
@@ -0,0 +1,21 @@
|
||||
const NativeDate = globalThis.Date;
|
||||
|
||||
function fixtureNow(): number {
|
||||
const value = process.env.OMP_LOGGER_TEST_NOW;
|
||||
if (!value) throw new Error("OMP_LOGGER_TEST_NOW is required");
|
||||
const parsed = NativeDate.parse(value);
|
||||
if (!Number.isFinite(parsed)) throw new Error(`invalid OMP_LOGGER_TEST_NOW: ${value}`);
|
||||
return parsed;
|
||||
}
|
||||
|
||||
class FixedDate extends NativeDate {
|
||||
constructor(value?: string | number) {
|
||||
super(value === undefined ? fixtureNow() : value);
|
||||
}
|
||||
|
||||
static now(): number {
|
||||
return fixtureNow();
|
||||
}
|
||||
}
|
||||
|
||||
globalThis.Date = FixedDate as DateConstructor;
|
||||
@@ -0,0 +1,358 @@
|
||||
import { afterEach, describe, expect, test } from "bun:test";
|
||||
import * as crypto from "node:crypto";
|
||||
import * as fs from "node:fs/promises";
|
||||
import * as os from "node:os";
|
||||
import * as path from "node:path";
|
||||
|
||||
const fixtureDir = path.join(import.meta.dir, "fixtures");
|
||||
const probePath = path.join(fixtureDir, "logger-contract-probe.ts");
|
||||
const preloadPath = path.join(fixtureDir, "logger-fixed-date-preload.ts");
|
||||
const apiProbePath = path.join(fixtureDir, "logger-api-probe.ts");
|
||||
const fixedNow = "2026-01-02T03:04:05.006Z";
|
||||
const fixedTimestamp = "2026-01-01T22:04:05.006-05:00";
|
||||
const roots: string[] = [];
|
||||
|
||||
interface ScenarioResult {
|
||||
readonly pid: number;
|
||||
readonly root: string;
|
||||
readonly primaryDir: string;
|
||||
readonly secondaryDir: string;
|
||||
readonly resultPath: string;
|
||||
readonly stdout: string;
|
||||
readonly stderr: string;
|
||||
}
|
||||
|
||||
interface AuditFile {
|
||||
readonly keep: { readonly days: boolean; readonly amount: number };
|
||||
readonly auditLog: string;
|
||||
readonly files: Array<{ readonly date: number; readonly name: string; readonly hash: string }>;
|
||||
readonly hashType: string;
|
||||
}
|
||||
|
||||
afterEach(async () => {
|
||||
await Promise.all(roots.splice(0).map(root => fs.rm(root, { recursive: true, force: true })));
|
||||
});
|
||||
|
||||
async function runScenario(scenario: string): Promise<ScenarioResult> {
|
||||
const root = await fs.mkdtemp(path.join(os.tmpdir(), "omp-logger-contract-"));
|
||||
roots.push(root);
|
||||
const primaryDir = path.join(root, "primary");
|
||||
const secondaryDir = path.join(root, "secondary");
|
||||
const resultPath = path.join(root, "result.json");
|
||||
await Promise.all([fs.mkdir(primaryDir), fs.mkdir(secondaryDir)]);
|
||||
const proc = Bun.spawn(
|
||||
[process.execPath, "--preload", preloadPath, probePath, scenario, primaryDir, secondaryDir, resultPath],
|
||||
{
|
||||
cwd: path.resolve(import.meta.dir, "../../.."),
|
||||
env: {
|
||||
...process.env,
|
||||
HOME: primaryDir,
|
||||
PI_CONFIG_DIR: ".omp",
|
||||
OMP_PROFILE: "",
|
||||
PI_PROFILE: "",
|
||||
XDG_DATA_HOME: "",
|
||||
XDG_STATE_HOME: "",
|
||||
XDG_CACHE_HOME: "",
|
||||
OMP_LOGGER_TEST_NOW: fixedNow,
|
||||
TZ: "Etc/GMT+5",
|
||||
},
|
||||
stdout: "pipe",
|
||||
stderr: "pipe",
|
||||
},
|
||||
);
|
||||
const [stdout, stderr, exitCode] = await Promise.all([
|
||||
new Response(proc.stdout).text(),
|
||||
new Response(proc.stderr).text(),
|
||||
proc.exited,
|
||||
]);
|
||||
expect(exitCode, stderr).toBe(0);
|
||||
return { pid: proc.pid, root, primaryDir, secondaryDir, resultPath, stdout, stderr };
|
||||
}
|
||||
|
||||
async function logFileNames(directory: string): Promise<string[]> {
|
||||
return (await fs.readdir(directory)).filter(name => /^omp\.\d{4}-\d{2}-\d{2}\.\d+\.log(?:\.\d+)?$/.test(name)).sort();
|
||||
}
|
||||
|
||||
async function readSingleLog(directory: string): Promise<{ name: string; text: string }> {
|
||||
const names = await logFileNames(directory);
|
||||
expect(names).toHaveLength(1);
|
||||
const name = names[0];
|
||||
if (!name) throw new Error("expected one log file");
|
||||
return { name, text: await fs.readFile(path.join(directory, name), "utf8") };
|
||||
}
|
||||
|
||||
function expectedLine(
|
||||
pid: number,
|
||||
level: "error" | "warn" | "info" | "debug",
|
||||
message: string,
|
||||
context: Record<string, unknown> = {},
|
||||
timestamp = fixedTimestamp,
|
||||
): string {
|
||||
return `${JSON.stringify({ timestamp, level, pid, message, ...context })}${os.EOL}`;
|
||||
}
|
||||
|
||||
describe("central logger byte contract", () => {
|
||||
test("pins levels, metadata normalization, key order, timestamp, errors, pid, and EOL", async () => {
|
||||
const result = await runScenario("matrix");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
const log = await readSingleLog(result.primaryDir);
|
||||
expect(log.name).toBe(`omp.2026-01-01.${result.pid}.log`);
|
||||
const expected = [
|
||||
expectedLine(result.pid, "error", "level-error", { ordinal: 1 }),
|
||||
expectedLine(result.pid, "warn", "level-warn", { ordinal: 2 }),
|
||||
expectedLine(result.pid, "info", "level-info", { ordinal: 3 }),
|
||||
expectedLine(result.pid, "debug", "level-debug", { ordinal: 4 }),
|
||||
expectedLine(result.pid, "info", "context-matrix", {
|
||||
stringValue: "text",
|
||||
numberValue: 7,
|
||||
booleanValue: false,
|
||||
nullValue: null,
|
||||
nested: { alpha: "a", values: [1, null, null, null] },
|
||||
infinity: null,
|
||||
nan: null,
|
||||
}),
|
||||
expectedLine(result.pid, "warn", "reserved-primary metadata-message", { before: "first", after: "last" }),
|
||||
expectedLine(result.pid, "debug", "reserved-falsy", { after: true }),
|
||||
expectedLine(result.pid, "error", "error-matrix", {
|
||||
error: {
|
||||
name: "CustomError",
|
||||
message: "upstream",
|
||||
stack: "OUTER_STACK",
|
||||
code: "E_FIXTURE",
|
||||
detail: { retry: false },
|
||||
cause: { name: "Error", message: "downstream", stack: "CAUSE_STACK" },
|
||||
},
|
||||
}),
|
||||
].join("");
|
||||
expect(log.text).toBe(expected);
|
||||
expect(log.text.endsWith(os.EOL)).toBe(true);
|
||||
expect(await fs.readFile(path.join(result.primaryDir, `.omp.${result.pid}-audit.json`), "utf8")).not.toBe("");
|
||||
});
|
||||
|
||||
test("treats Winston format tokens as a splat branch and omits context", async () => {
|
||||
const result = await runScenario("format-tokens");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
const tokenMessages = ["token-%s", "token-%c", "token-%d", "token-%j", "token-%i", "token-%f", "token-%o", "token-%O", "token-%%"];
|
||||
const expected = [
|
||||
...tokenMessages.map(message => expectedLine(result.pid, "info", message)),
|
||||
expectedLine(result.pid, "info", "non-token-%q", { value: 7 }),
|
||||
expectedLine(result.pid, "info", "circular-%s"),
|
||||
expectedLine(result.pid, "info", "bigint-%d"),
|
||||
].join("");
|
||||
expect((await readSingleLog(result.primaryDir)).text).toBe(expected);
|
||||
});
|
||||
|
||||
test("drops native JSON failures locally but sends original contexts to sinks", async () => {
|
||||
const result = await runScenario("serialization-failures");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
const log = await readSingleLog(result.primaryDir);
|
||||
expect(log.text).toBe("");
|
||||
const payload = JSON.parse(await fs.readFile(result.resultPath, "utf8")) as {
|
||||
events: Array<{ level: string; message: string; sameContext: boolean; timestamp: string }>;
|
||||
};
|
||||
expect(payload.events).toEqual([
|
||||
{ level: "info", message: "circular-drop", sameContext: true, timestamp: fixedNow },
|
||||
{ level: "error", message: "bigint-drop", sameContext: true, timestamp: fixedNow },
|
||||
]);
|
||||
});
|
||||
});
|
||||
|
||||
describe("central logger transport lifecycle", () => {
|
||||
test("defaults to file-only without touching stdout or stderr", async () => {
|
||||
const result = await runScenario("default-file");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
const defaultLogsDir = path.join(result.primaryDir, ".omp", "logs");
|
||||
const log = await readSingleLog(defaultLogsDir);
|
||||
expect(log.text).toBe(expectedLine(result.pid, "info", "mode-default", { mode: "default" }));
|
||||
});
|
||||
|
||||
test("emits file-only, console-only, and dual modes exactly once", async () => {
|
||||
const fileOnly = await runScenario("file-only");
|
||||
const fileLine = expectedLine(fileOnly.pid, "info", "mode-file", { mode: "file" });
|
||||
expect(fileOnly.stdout).toBe("");
|
||||
expect(fileOnly.stderr).toBe("");
|
||||
expect((await readSingleLog(fileOnly.primaryDir)).text).toBe(fileLine);
|
||||
|
||||
const consoleOnly = await runScenario("console-only");
|
||||
const consoleLine = expectedLine(consoleOnly.pid, "info", "mode-console", { mode: "console" });
|
||||
expect(consoleOnly.stdout).toBe(consoleLine);
|
||||
expect(consoleOnly.stderr).toBe("");
|
||||
expect(await logFileNames(consoleOnly.primaryDir)).toEqual([]);
|
||||
|
||||
const both = await runScenario("both");
|
||||
const bothLine = expectedLine(both.pid, "info", "mode-both", { mode: "both" });
|
||||
expect(both.stdout).toBe(bothLine);
|
||||
expect(both.stderr).toBe("");
|
||||
expect((await readSingleLog(both.primaryDir)).text).toBe(bothLine);
|
||||
});
|
||||
|
||||
test("keeps disabled mode silent, sends sinks, preserves void returns, and re-enables", async () => {
|
||||
const result = await runScenario("disabled-reenable");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
expect((await readSingleLog(result.primaryDir)).text).toBe(
|
||||
expectedLine(result.pid, "warn", "mode-reenabled", { mode: "file" }),
|
||||
);
|
||||
const payload = JSON.parse(await fs.readFile(result.resultPath, "utf8")) as {
|
||||
disabledSinkSameContext: boolean;
|
||||
sinkCount: number;
|
||||
returnsUndefined: boolean;
|
||||
};
|
||||
expect(payload).toEqual({ disabledSinkSameContext: true, sinkCount: 2, returnsUndefined: true });
|
||||
});
|
||||
|
||||
test("closes A before reconfiguring to B and never cross-writes", async () => {
|
||||
const result = await runScenario("reconfigure");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
expect((await readSingleLog(result.primaryDir)).text).toBe(
|
||||
expectedLine(result.pid, "info", "directory-a", { destination: "a" }),
|
||||
);
|
||||
expect((await readSingleLog(result.secondaryDir)).text).toBe(
|
||||
expectedLine(result.pid, "info", "directory-b", { destination: "b" }),
|
||||
);
|
||||
});
|
||||
|
||||
test("invalidates closed transports when warm replacement construction fails", async () => {
|
||||
const result = await runScenario("reconfigure-failure");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
expect((await readSingleLog(result.primaryDir)).text).toBe(
|
||||
expectedLine(result.pid, "info", "before-failed-reconfigure"),
|
||||
);
|
||||
expect(await logFileNames(result.secondaryDir)).toEqual([]);
|
||||
const payload = JSON.parse(await fs.readFile(result.resultPath, "utf8")) as {
|
||||
reconfigureThrew: boolean;
|
||||
sinkCount: number;
|
||||
sinkSameContext: boolean;
|
||||
};
|
||||
expect(payload).toEqual({ reconfigureThrew: true, sinkCount: 1, sinkSameContext: true });
|
||||
});
|
||||
|
||||
test("preserves burst order and drains on close and natural child exit", async () => {
|
||||
for (const scenario of ["burst-close", "burst-natural"] as const) {
|
||||
const result = await runScenario(scenario);
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
const text = (await readSingleLog(result.primaryDir)).text;
|
||||
expect(text.endsWith(os.EOL)).toBe(true);
|
||||
const lines = text.split(os.EOL);
|
||||
expect(lines.pop()).toBe("");
|
||||
expect(lines).toHaveLength(1_000);
|
||||
for (const [index, line] of lines.entries()) {
|
||||
const entry = JSON.parse(line) as { message: string; index: number };
|
||||
expect(entry).toMatchObject({ message: scenario, index });
|
||||
}
|
||||
}
|
||||
});
|
||||
|
||||
test("runs local console output before sinks and isolates throwing or disposed sinks", async () => {
|
||||
const result = await runScenario("sink-order");
|
||||
const first = expectedLine(result.pid, "info", "sink-first", { identity: "same" });
|
||||
const second = expectedLine(result.pid, "info", "sink-disposed");
|
||||
expect(result.stdout).toBe(`${first}SINK:true\n${second}`);
|
||||
expect(result.stderr).toBe("");
|
||||
});
|
||||
});
|
||||
|
||||
describe("DailyRotateFile option and retention contract", () => {
|
||||
test("uses local-day names, a PID audit, SHA-256, and retains exactly five rotations", async () => {
|
||||
const result = await runScenario("date-retention");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
const expectedNames = [2, 3, 4, 5, 6].map(day => `omp.2026-01-0${day}.${result.pid}.log`);
|
||||
expect(await logFileNames(result.primaryDir)).toEqual(expectedNames);
|
||||
for (const [offset, name] of expectedNames.entries()) {
|
||||
const day = offset + 2;
|
||||
const timestamp = `2026-01-0${day}T22:04:05.006-05:00`;
|
||||
expect(await fs.readFile(path.join(result.primaryDir, name), "utf8")).toBe(
|
||||
expectedLine(result.pid, "info", `date-${day}`, {}, timestamp),
|
||||
);
|
||||
}
|
||||
|
||||
const auditPath = path.join(result.primaryDir, `.omp.${result.pid}-audit.json`);
|
||||
const audit = JSON.parse(await fs.readFile(auditPath, "utf8")) as AuditFile;
|
||||
expect(audit.keep).toEqual({ days: false, amount: 5 });
|
||||
expect(audit.auditLog).toBe(auditPath);
|
||||
expect(audit.hashType).toBe("sha256");
|
||||
expect(audit.files.map(file => file.name)).toEqual(expectedNames.map(name => path.join(result.primaryDir, name)));
|
||||
for (const file of audit.files) {
|
||||
const hash = crypto.createHash("sha256").update(`${file.name}LOG_FILE${file.date}`).digest("hex");
|
||||
expect(file.hash).toBe(hash);
|
||||
expect(file.hash).toMatch(/^[0-9a-f]{64}$/);
|
||||
}
|
||||
});
|
||||
|
||||
test("crosses 10 MiB before rolling the following record to suffix .1", async () => {
|
||||
const result = await runScenario("size-rotation");
|
||||
expect(result.stdout).toBe("");
|
||||
expect(result.stderr).toBe("");
|
||||
const baseName = `omp.2026-01-01.${result.pid}.log`;
|
||||
const rotatedName = `${baseName}.1`;
|
||||
expect(await logFileNames(result.primaryDir)).toEqual([baseName, rotatedName]);
|
||||
const basePath = path.join(result.primaryDir, baseName);
|
||||
const baseStat = await fs.stat(basePath);
|
||||
const recordSize = (message: string, payloadSize: number): number =>
|
||||
`{"timestamp":"${fixedTimestamp}","level":"info","pid":${result.pid},"message":"${message}","payload":"`.length +
|
||||
payloadSize +
|
||||
`"}${os.EOL}`.length;
|
||||
const expectedBytes =
|
||||
recordSize("size-nine-mib", 9 * 1024 * 1024) +
|
||||
recordSize("size-half-mib", 512 * 1024) +
|
||||
recordSize("size-crosses-ten-mib", 1024 * 1024);
|
||||
expect(baseStat.size).toBe(expectedBytes);
|
||||
expect(baseStat.size).toBeGreaterThan(10 * 1024 * 1024);
|
||||
expect(await fs.readFile(path.join(result.primaryDir, rotatedName), "utf8")).toBe(
|
||||
expectedLine(result.pid, "info", "rotation-trigger"),
|
||||
);
|
||||
const audit = JSON.parse(
|
||||
await fs.readFile(path.join(result.primaryDir, `.omp.${result.pid}-audit.json`), "utf8"),
|
||||
) as AuditFile;
|
||||
expect(audit.keep).toEqual({ days: false, amount: 5 });
|
||||
expect(audit.files.map(file => path.basename(file.name))).toEqual([baseName, rotatedName]);
|
||||
});
|
||||
});
|
||||
|
||||
test("root and direct source entry points expose identical public logger functions", async () => {
|
||||
const root = await fs.mkdtemp(path.join(os.tmpdir(), "omp-logger-api-"));
|
||||
roots.push(root);
|
||||
const outputPath = path.join(root, "result.json");
|
||||
const proc = Bun.spawn([process.execPath, apiProbePath, outputPath], {
|
||||
cwd: path.resolve(import.meta.dir, "../../.."),
|
||||
stdout: "pipe",
|
||||
stderr: "pipe",
|
||||
});
|
||||
const [stdout, stderr, exitCode] = await Promise.all([
|
||||
new Response(proc.stdout).text(),
|
||||
new Response(proc.stderr).text(),
|
||||
proc.exited,
|
||||
]);
|
||||
expect(exitCode, stderr).toBe(0);
|
||||
expect(stdout).toBe("");
|
||||
expect(stderr).toBe("");
|
||||
const payload = JSON.parse(await fs.readFile(outputPath, "utf8")) as { identities: boolean; keys: string[] };
|
||||
expect(payload).toEqual({
|
||||
identities: true,
|
||||
keys: [
|
||||
"debug",
|
||||
"endTiming",
|
||||
"error",
|
||||
"info",
|
||||
"openSpanPath",
|
||||
"printTimings",
|
||||
"recordModuleLoadSpan",
|
||||
"registerLogSink",
|
||||
"setTransports",
|
||||
"shouldExitAfterTimings",
|
||||
"startTiming",
|
||||
"startupMarker",
|
||||
"time",
|
||||
"timingModeIncludes",
|
||||
"warn",
|
||||
],
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,100 @@
|
||||
import { afterEach, describe, expect, test } from "bun:test";
|
||||
import * as fs from "node:fs/promises";
|
||||
import * as os from "node:os";
|
||||
import * as path from "node:path";
|
||||
import type { LoggerCacheSnapshot } from "./fixtures/logger-cache-snapshot";
|
||||
|
||||
const fixtureDir = path.join(import.meta.dir, "fixtures");
|
||||
const probePath = path.join(fixtureDir, "logger-cache-probe.ts");
|
||||
const positiveControlPath = path.join(fixtureDir, "logger-cache-positive-control.ts");
|
||||
const roots: string[] = [];
|
||||
|
||||
interface ProbeResult {
|
||||
readonly snapshot: LoggerCacheSnapshot;
|
||||
readonly stdout: string;
|
||||
readonly stderr: string;
|
||||
}
|
||||
|
||||
afterEach(async () => {
|
||||
await Promise.all(roots.splice(0).map(root => fs.rm(root, { recursive: true, force: true })));
|
||||
});
|
||||
|
||||
async function makeRoot(prefix: string): Promise<string> {
|
||||
const root = await fs.mkdtemp(path.join(os.tmpdir(), prefix));
|
||||
roots.push(root);
|
||||
return root;
|
||||
}
|
||||
|
||||
async function runProbe(scenario: "import" | "console" | "file"): Promise<ProbeResult> {
|
||||
const root = await makeRoot("omp-logger-cache-");
|
||||
const outputPath = path.join(root, "result.json");
|
||||
const logsDir = path.join(root, "logs");
|
||||
await fs.mkdir(logsDir);
|
||||
const proc = Bun.spawn([process.execPath, probePath, scenario, outputPath, logsDir], {
|
||||
cwd: path.resolve(import.meta.dir, "../../.."),
|
||||
env: { ...process.env, TZ: "Etc/GMT+5" },
|
||||
stdout: "pipe",
|
||||
stderr: "pipe",
|
||||
});
|
||||
const [stdout, stderr, exitCode] = await Promise.all([
|
||||
new Response(proc.stdout).text(),
|
||||
new Response(proc.stderr).text(),
|
||||
proc.exited,
|
||||
]);
|
||||
expect(exitCode, stderr).toBe(0);
|
||||
return {
|
||||
snapshot: JSON.parse(await fs.readFile(outputPath, "utf8")) as LoggerCacheSnapshot,
|
||||
stdout,
|
||||
stderr,
|
||||
};
|
||||
}
|
||||
|
||||
async function runPositiveControl(): Promise<LoggerCacheSnapshot> {
|
||||
const root = await makeRoot("omp-logger-cache-control-");
|
||||
const outputPath = path.join(root, "result.json");
|
||||
const proc = Bun.spawn([process.execPath, positiveControlPath, outputPath], {
|
||||
cwd: path.resolve(import.meta.dir, "../../.."),
|
||||
stdout: "pipe",
|
||||
stderr: "pipe",
|
||||
});
|
||||
const stderr = new Response(proc.stderr).text();
|
||||
expect(await proc.exited, await stderr).toBe(0);
|
||||
return JSON.parse(await fs.readFile(outputPath, "utf8")) as LoggerCacheSnapshot;
|
||||
}
|
||||
|
||||
describe("central logger runtime closure", () => {
|
||||
test("detector observes the direct Winston positive control", async () => {
|
||||
const { winston } = await runPositiveControl();
|
||||
expect(winston.modules, JSON.stringify(winston)).toBeGreaterThan(0);
|
||||
expect(winston.bytes, JSON.stringify(winston)).toBeGreaterThan(0);
|
||||
});
|
||||
|
||||
for (const scenario of ["import", "console", "file"] as const) {
|
||||
test(`${scenario} evaluates zero Winston runtime modules`, async () => {
|
||||
const { snapshot } = await runProbe(scenario);
|
||||
expect(
|
||||
{ modules: snapshot.winston.modules, bytes: snapshot.winston.bytes },
|
||||
JSON.stringify(snapshot.winston),
|
||||
).toEqual({ modules: 0, bytes: 0 });
|
||||
});
|
||||
}
|
||||
|
||||
test("rotation engine stays lazy until a file transport is constructed", async () => {
|
||||
const imported = await runProbe("import");
|
||||
const consoled = await runProbe("console");
|
||||
for (const result of [imported, consoled]) {
|
||||
expect(result.snapshot.fileStreamRotator.modules, JSON.stringify(result.snapshot)).toBe(0);
|
||||
expect(result.snapshot.moment.modules, JSON.stringify(result.snapshot)).toBe(0);
|
||||
}
|
||||
expect(imported.stdout).toBe("");
|
||||
expect(imported.stderr).toBe("");
|
||||
expect(consoled.stdout.endsWith(`${os.EOL}`)).toBe(true);
|
||||
expect(consoled.stderr).toBe("");
|
||||
|
||||
const filed = await runProbe("file");
|
||||
expect(filed.snapshot.fileStreamRotator.modules, JSON.stringify(filed.snapshot)).toBeGreaterThan(0);
|
||||
expect(filed.snapshot.moment.modules, JSON.stringify(filed.snapshot)).toBeGreaterThan(0);
|
||||
expect(filed.stdout).toBe("");
|
||||
expect(filed.stderr).toBe("");
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user