adding ability to record logs for debug purposes

This commit is contained in:
orangecoding
2026-06-09 15:42:25 +02:00
parent 6c7d655277
commit 6bef907416
20 changed files with 2229 additions and 7 deletions

View File

@@ -0,0 +1,129 @@
/*
* Copyright (c) 2026 by Christian Kellner.
* Licensed under Apache-2.0 with Commons Clause and Attribution/Naming Clause
*/
import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
import path from 'node:path';
describe('services/debug/debugBundleService.js', () => {
let svc;
let storedLogs;
let addedZipEntries;
beforeEach(async () => {
storedLogs = [];
addedZipEntries = [];
/**
* Minimal AdmZip stand-in that records the in-memory entry names + payloads so we
* can assert what made it into the bundle without spinning up real zip parsing.
*/
class MockAdmZip {
constructor() {
this.entries = [];
}
addFile(name, buf) {
this.entries.push({ entryName: name, data: buf });
addedZipEntries.push({ entryName: name, content: buf.toString('utf-8') });
}
toBuffer() {
return Buffer.from(JSON.stringify(this.entries.map((e) => e.entryName)));
}
}
globalThis.__TEST_ADM_ZIP__ = MockAdmZip;
const ROOT = path.resolve('.');
const storagePath = path.join(ROOT, 'lib', 'services', 'debug', 'debugLogStorage.js');
const utilsPath = path.join(ROOT, 'lib', 'utils.js');
const storageMock = {
getAllDebugLogs: () => storedLogs,
};
const utilsMock = { getPackageVersion: async () => '22.5.0' };
vi.resetModules();
vi.doMock(storagePath, () => storageMock);
vi.doMock(utilsPath, () => utilsMock);
svc = await import(path.join(ROOT, 'lib', 'services', 'debug', 'debugBundleService.js'));
});
afterEach(() => {
delete globalThis.__TEST_ADM_ZIP__;
});
describe('renderLogsTxt', () => {
it('returns an empty string when there are no rows', () => {
expect(svc.renderLogsTxt()).toBe('');
});
it('formats each row as [date] LEVEL: message and keeps order', () => {
storedLogs.push({ id: 1, ts: 1717855200000, level: 'info', message: 'first line' });
storedLogs.push({ id: 2, ts: 1717855201000, level: 'warn', message: 'second line' });
const out = svc.renderLogsTxt();
expect(out).toMatch(/\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\] INFO: first line/);
expect(out).toMatch(/\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\] WARN: second line/);
expect(out.indexOf('first line')).toBeLessThan(out.indexOf('second line'));
expect(out.endsWith('\n')).toBe(true);
});
});
describe('buildSystemInfo', () => {
it('contains Fredy version, Node version and OS platform', async () => {
const sys = await svc.buildSystemInfo({ settings: null });
expect(sys).toMatch(/Fredy version:\s+22\.5\.0/);
expect(sys).toContain(`Node.js version: ${process.version}`);
expect(sys).toContain(`Platform: ${process.platform}`);
});
it('redacts proxy URL credentials', async () => {
const sys = await svc.buildSystemInfo({
settings: { proxyUrl: 'http://secret:hunter2@proxy.example:8080', port: 9998 },
});
expect(sys).not.toContain('hunter2');
expect(sys).not.toContain('secret');
expect(sys).toContain('proxy.example');
expect(sys).toContain('port: 9998');
});
it('strips session secrets from sanitized settings output', async () => {
const sys = await svc.buildSystemInfo({
settings: { session_secret: 'top-secret', sessionSecret: 'other-secret', port: 9998 },
});
expect(sys).not.toContain('top-secret');
expect(sys).not.toContain('other-secret');
});
});
describe('buildDebugBundleFileName', () => {
it('matches YYYY-MM-DD-FredyDebug-<version>.zip', async () => {
const name = await svc.buildDebugBundleFileName();
expect(name).toMatch(/^\d{4}-\d{2}-\d{2}-FredyDebug-22\.5\.0\.zip$/);
});
});
describe('buildDebugBundleZip', () => {
it('always emits both logs.txt and sys.txt entries', async () => {
storedLogs.push({ id: 1, ts: 1717855200000, level: 'info', message: 'recorded line' });
await svc.buildDebugBundleZip({ settings: { port: 9998 } });
const names = addedZipEntries.map((e) => e.entryName).sort();
expect(names).toEqual(['logs.txt', 'sys.txt']);
const logs = addedZipEntries.find((e) => e.entryName === 'logs.txt');
const sys = addedZipEntries.find((e) => e.entryName === 'sys.txt');
expect(logs.content).toContain('recorded line');
expect(sys.content).toMatch(/Fredy version:\s+22\.5\.0/);
expect(sys.content).toContain('port: 9998');
});
it('includes a placeholder message when no logs are stored', async () => {
await svc.buildDebugBundleZip({ settings: null });
const logs = addedZipEntries.find((e) => e.entryName === 'logs.txt');
expect(logs.content).toMatch(/no debug log entries/i);
});
});
});

View File

@@ -0,0 +1,278 @@
/*
* Copyright (c) 2026 by Christian Kellner.
* Licensed under Apache-2.0 with Commons Clause and Attribution/Naming Clause
*/
import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
import path from 'node:path';
import Database from 'better-sqlite3';
/**
* Wire up an in-memory better-sqlite3 instance plus a stubbed settings module so the
* storage module under test can exercise real SQL while the rest of the dependency
* graph stays inert.
*/
async function bootstrap() {
const db = new Database(':memory:');
db.exec(`
CREATE TABLE debug_logs (
id INTEGER PRIMARY KEY AUTOINCREMENT,
ts INTEGER NOT NULL,
level TEXT NOT NULL,
message TEXT NOT NULL,
byte_size INTEGER NOT NULL
);
`);
const settings = { debug_logging_enabled: false, debug_logging_ever_enabled: false };
const ROOT = path.resolve('.');
const sqlitePath = path.join(ROOT, 'lib', 'services', 'storage', 'SqliteConnection.js');
const settingsPath = path.join(ROOT, 'lib', 'services', 'storage', 'settingsStorage.js');
const sqliteMock = {
default: {
getConnection: () => db,
execute: (sql, params = {}) => db.prepare(sql).run(params),
query: (sql, params = {}) => db.prepare(sql).all(params),
},
};
const settingsMock = {
getSettings: async () => ({ ...settings }),
upsertSettings: (entries) => {
const map = Array.isArray(entries) ? Object.fromEntries(entries) : entries;
for (const [k, v] of Object.entries(map)) {
settings[k] = v;
}
},
};
vi.resetModules();
vi.doMock(sqlitePath, () => sqliteMock);
vi.doMock(settingsPath, () => settingsMock);
const storage = await import(path.join(ROOT, 'lib', 'services', 'debug', 'debugLogStorage.js'));
storage._resetForTests();
return { storage, db, settings };
}
describe('services/debug/debugLogStorage.js', () => {
let ctx;
beforeEach(async () => {
ctx = await bootstrap();
});
afterEach(() => {
try {
ctx.db.close();
} catch {
// ignore
}
});
it('isEnabled is false before enableDebugLogging is called', async () => {
expect(ctx.storage.isEnabled()).toBe(false);
});
it('enableDebugLogging flips the cached flag and persists ever-enabled', async () => {
await ctx.storage.enableDebugLogging();
expect(ctx.storage.isEnabled()).toBe(true);
expect(ctx.settings.debug_logging_enabled).toBe(true);
expect(ctx.settings.debug_logging_ever_enabled).toBe(true);
});
it('reloadEnabledFromSettings picks up persisted state after restart', async () => {
ctx.settings.debug_logging_enabled = true;
const enabled = await ctx.storage.reloadEnabledFromSettings();
expect(enabled).toBe(true);
expect(ctx.storage.isEnabled()).toBe(true);
});
it('appendLogEntry writes only while enabled', async () => {
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'before-enable' });
expect(ctx.db.prepare('SELECT COUNT(*) AS c FROM debug_logs').get().c).toBe(0);
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 2, level: 'warn', message: 'after-enable' });
expect(ctx.db.prepare('SELECT COUNT(*) AS c FROM debug_logs').get().c).toBe(1);
const row = ctx.db.prepare('SELECT level, message, byte_size FROM debug_logs').get();
expect(row.level).toBe('warn');
expect(row.message).toBe('after-enable');
expect(row.byte_size).toBe(Buffer.byteLength('after-enable', 'utf-8'));
});
it('disableDebugLogging stops writes but keeps existing rows', async () => {
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'keep-me' });
await ctx.storage.disableDebugLogging();
ctx.storage.appendLogEntry({ ts: 2, level: 'info', message: 'never-written' });
const rows = ctx.db.prepare('SELECT message FROM debug_logs ORDER BY id').all();
expect(rows).toHaveLength(1);
expect(rows[0].message).toBe('keep-me');
});
it('enableDebugLogging clears previous logs only when asked', async () => {
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'pre-existing' });
await ctx.storage.disableDebugLogging();
await ctx.storage.enableDebugLogging({ clearPrevious: false });
expect(ctx.db.prepare('SELECT COUNT(*) AS c FROM debug_logs').get().c).toBe(1);
await ctx.storage.disableDebugLogging();
await ctx.storage.enableDebugLogging({ clearPrevious: true });
expect(ctx.db.prepare('SELECT COUNT(*) AS c FROM debug_logs').get().c).toBe(0);
});
it('hasAnyLogs / wasEverEnabled report correctly', async () => {
expect(ctx.storage.hasAnyLogs()).toBe(false);
expect(await ctx.storage.wasEverEnabled()).toBe(false);
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'hi' });
expect(ctx.storage.hasAnyLogs()).toBe(true);
expect(await ctx.storage.wasEverEnabled()).toBe(true);
});
it('getCurrentSize reflects the on-disk byte total', async () => {
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'hello' }); // 5 bytes
ctx.storage.appendLogEntry({ ts: 2, level: 'info', message: 'world!' }); // 6 bytes
expect(await ctx.storage.getCurrentSize()).toBe(11);
});
it('rolling buffer drops oldest rows once the cap is exceeded', async () => {
await ctx.storage.enableDebugLogging();
const cap = ctx.storage.getMaxSize();
// Insert one row whose payload exceeds the entire cap. trimToFit must drop the
// oldest row(s) until the live size falls back under the cap. With a single
// oversized row, the only outcome is "table empty".
const giantText = 'X'.repeat(cap + 1024);
ctx.storage.appendLogEntry({ ts: 10, level: 'info', message: giantText });
const remaining = await ctx.storage.getCurrentSize();
expect(remaining).toBeLessThanOrEqual(cap);
expect(remaining).toBe(0);
expect(ctx.db.prepare('SELECT COUNT(*) AS c FROM debug_logs').get().c).toBe(0);
});
it('rolling buffer keeps newer rows when only the oldest need to go', async () => {
await ctx.storage.enableDebugLogging();
const cap = ctx.storage.getMaxSize();
// Push the size just over the cap with one big row, then a smaller "newer" row
// that should survive the trim because it is not at the head of the queue.
const bigText = 'A'.repeat(cap - 10); // ~5 MiB - 10 bytes
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: bigText });
// At this point we are just under the cap. Pushing one more row will tip us over.
ctx.storage.appendLogEntry({ ts: 2, level: 'warn', message: 'tip-over message which keeps us above cap' });
const remainingRows = ctx.db.prepare('SELECT message FROM debug_logs ORDER BY id ASC').all();
// The oldest (big) row must be gone; the newer one survives.
expect(remainingRows).toHaveLength(1);
expect(remainingRows[0].message).toContain('tip-over');
const remainingSize = await ctx.storage.getCurrentSize();
expect(remainingSize).toBeLessThanOrEqual(cap);
// And the cache must match what SQLite reports, verifies no drift after trim.
const dbSize = ctx.db.prepare('SELECT COALESCE(SUM(byte_size),0) AS s FROM debug_logs').get().s;
expect(remainingSize).toBe(dbSize);
});
it('cachedSize stays consistent across enable → append → disable → re-enable(clear) cycles', async () => {
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'one' });
ctx.storage.appendLogEntry({ ts: 2, level: 'info', message: 'two' });
const sizeAfterFirst = await ctx.storage.getCurrentSize();
await ctx.storage.disableDebugLogging();
expect(await ctx.storage.getCurrentSize()).toBe(sizeAfterFirst);
await ctx.storage.enableDebugLogging({ clearPrevious: true });
expect(await ctx.storage.getCurrentSize()).toBe(0);
ctx.storage.appendLogEntry({ ts: 3, level: 'info', message: 'fresh' });
const dbSize = ctx.db.prepare('SELECT COALESCE(SUM(byte_size),0) AS s FROM debug_logs').get().s;
expect(await ctx.storage.getCurrentSize()).toBe(dbSize);
});
it('clearAllDebugLogs empties the table and resets cached size', async () => {
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'foo' });
ctx.storage.appendLogEntry({ ts: 2, level: 'info', message: 'bar' });
expect(await ctx.storage.getCurrentSize()).toBeGreaterThan(0);
ctx.storage.clearAllDebugLogs();
expect(ctx.db.prepare('SELECT COUNT(*) AS c FROM debug_logs').get().c).toBe(0);
expect(await ctx.storage.getCurrentSize()).toBe(0);
});
it('getAllDebugLogs returns rows ordered chronologically', async () => {
await ctx.storage.enableDebugLogging();
ctx.storage.appendLogEntry({ ts: 1, level: 'info', message: 'first' });
ctx.storage.appendLogEntry({ ts: 2, level: 'warn', message: 'second' });
ctx.storage.appendLogEntry({ ts: 3, level: 'error', message: 'third' });
const rows = ctx.storage.getAllDebugLogs();
expect(rows.map((r) => r.message)).toEqual(['first', 'second', 'third']);
expect(rows.map((r) => r.level)).toEqual(['info', 'warn', 'error']);
});
describe('logger sink wiring', () => {
let logger;
let consoleSpies;
beforeEach(async () => {
// Storage imports the same logger module; vi.resetModules() ensured both share
// the same fresh instance for this test. Spies silence console output so the
// vitest report stays clean while we exercise real logger.info() calls.
logger = (await import(path.resolve('lib/services/logger.js'))).default;
consoleSpies = {
debug: vi.spyOn(console, 'debug').mockImplementation(() => {}),
info: vi.spyOn(console, 'info').mockImplementation(() => {}),
warn: vi.spyOn(console, 'warn').mockImplementation(() => {}),
error: vi.spyOn(console, 'error').mockImplementation(() => {}),
};
});
afterEach(() => {
// Detach sink between tests to prevent cross-test pollution from the shared
// logger module instance.
logger.setDebugLogSink(null);
for (const spy of Object.values(consoleSpies)) spy.mockRestore();
});
it('routes logger calls into debug_logs once enabled', async () => {
await ctx.storage.enableDebugLogging();
logger.info('captured-via-logger');
const rows = ctx.db.prepare('SELECT level, message FROM debug_logs').all();
expect(rows).toHaveLength(1);
expect(rows[0].level).toBe('info');
expect(rows[0].message).toContain('captured-via-logger');
});
it('detaches the sink on disable so logger calls no longer hit the DB', async () => {
await ctx.storage.enableDebugLogging();
await ctx.storage.disableDebugLogging();
logger.info('not-captured');
expect(ctx.db.prepare('SELECT COUNT(*) AS c FROM debug_logs').get().c).toBe(0);
});
it('restores the sink on reloadEnabledFromSettings when persisted state is on', async () => {
ctx.settings.debug_logging_enabled = true;
await ctx.storage.reloadEnabledFromSettings();
logger.warn('captured-after-restart');
const rows = ctx.db.prepare('SELECT level, message FROM debug_logs').all();
expect(rows).toHaveLength(1);
expect(rows[0].level).toBe('warn');
expect(rows[0].message).toContain('captured-after-restart');
});
});
});

View File

@@ -0,0 +1,250 @@
/*
* Copyright (c) 2026 by Christian Kellner.
* Licensed under Apache-2.0 with Commons Clause and Attribution/Naming Clause
*/
import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
import path from 'node:path';
import Fastify from 'fastify';
describe('api/routes/debugRouter.js', () => {
let app;
let state;
beforeEach(async () => {
state = {
enabled: false,
hasLogs: false,
everEnabled: false,
size: 0,
max: 5 * 1024 * 1024,
};
const ROOT = path.resolve('.');
const storagePath = path.join(ROOT, 'lib', 'services', 'debug', 'debugLogStorage.js');
const bundlePath = path.join(ROOT, 'lib', 'services', 'debug', 'debugBundleService.js');
const settingsStoragePath = path.join(ROOT, 'lib', 'services', 'storage', 'settingsStorage.js');
const storageMock = {
isEnabled: () => state.enabled,
enableDebugLogging: async ({ clearPrevious = false } = {}) => {
state.enabled = true;
state.everEnabled = true;
if (clearPrevious) {
state.hasLogs = false;
state.size = 0;
}
},
disableDebugLogging: async () => {
state.enabled = false;
},
getCurrentSize: async () => state.size,
getMaxSize: () => state.max,
hasAnyLogs: () => state.hasLogs,
wasEverEnabled: async () => state.everEnabled,
clearAllDebugLogs: () => {
state.hasLogs = false;
state.size = 0;
},
};
const bundleMock = {
buildDebugBundleFileName: async () => '2026-06-08-FredyDebug-22.5.0.zip',
buildDebugBundleZip: async () => Buffer.from('FAKEZIP'),
};
const settingsMock = {
getSettings: async () => ({ port: 9998 }),
};
vi.resetModules();
vi.doMock(storagePath, () => storageMock);
vi.doMock(bundlePath, () => bundleMock);
vi.doMock(settingsStoragePath, () => settingsMock);
const mod = await import(path.join(ROOT, 'lib', 'api', 'routes', 'debugRouter.js'));
const plugin = mod.default;
app = Fastify({ logger: false });
await app.register(plugin, { prefix: '/api/admin/debug' });
await app.register(
async (sub) => {
mod.registerDebugPublicProbe(sub);
},
{ prefix: '/api/debug' },
);
await app.ready();
});
afterEach(async () => {
if (app) await app.close();
});
it('GET /status returns the current snapshot', async () => {
const res = await app.inject({ method: 'GET', url: '/api/admin/debug/status' });
expect(res.statusCode).toBe(200);
expect(res.json()).toEqual({
enabled: false,
size: 0,
max: state.max,
hasLogs: false,
everEnabled: false,
});
});
it('POST /enable flips the feature on and returns updated status', async () => {
const res = await app.inject({
method: 'POST',
url: '/api/admin/debug/enable',
payload: {},
});
expect(res.statusCode).toBe(200);
const json = res.json();
expect(json.enabled).toBe(true);
expect(json.everEnabled).toBe(true);
});
it('POST /enable with clearPrevious=true wipes existing logs first', async () => {
state.hasLogs = true;
state.size = 1234;
state.everEnabled = true;
const res = await app.inject({
method: 'POST',
url: '/api/admin/debug/enable',
payload: { clearPrevious: true },
});
expect(res.statusCode).toBe(200);
const json = res.json();
expect(json.enabled).toBe(true);
expect(json.hasLogs).toBe(false);
expect(json.size).toBe(0);
});
it('POST /disable turns the feature off without losing existing logs', async () => {
state.enabled = true;
state.hasLogs = true;
state.everEnabled = true;
state.size = 99;
const res = await app.inject({ method: 'POST', url: '/api/admin/debug/disable' });
expect(res.statusCode).toBe(200);
const json = res.json();
expect(json.enabled).toBe(false);
expect(json.hasLogs).toBe(true);
expect(json.size).toBe(99);
});
it('GET /download returns 409 when the feature was never enabled', async () => {
const res = await app.inject({ method: 'GET', url: '/api/admin/debug/download' });
expect(res.statusCode).toBe(409);
expect(res.json().error).toMatch(/never produced any data/i);
});
it('GET /download returns 409 when ever-enabled but no logs are stored', async () => {
state.everEnabled = true;
state.hasLogs = false;
const res = await app.inject({ method: 'GET', url: '/api/admin/debug/download' });
expect(res.statusCode).toBe(409);
});
it('GET /download streams a zip with the expected headers when logs exist', async () => {
state.everEnabled = true;
state.hasLogs = true;
const res = await app.inject({ method: 'GET', url: '/api/admin/debug/download' });
expect(res.statusCode).toBe(200);
expect(res.headers['content-type']).toBe('application/zip');
expect(res.headers['content-disposition']).toContain('FredyDebug');
expect(res.rawPayload.toString('utf-8')).toBe('FAKEZIP');
});
it('DELETE /logs wipes stored logs without touching the enabled flag', async () => {
state.enabled = true;
state.hasLogs = true;
state.everEnabled = true;
state.size = 1234;
const res = await app.inject({ method: 'DELETE', url: '/api/admin/debug/logs' });
expect(res.statusCode).toBe(200);
const json = res.json();
expect(json.enabled).toBe(true);
expect(json.hasLogs).toBe(false);
expect(json.size).toBe(0);
// everEnabled must stay true so the download button does not change semantics.
expect(json.everEnabled).toBe(true);
});
it('GET /api/debug/active returns only the enabled boolean (no other settings)', async () => {
state.enabled = false;
let res = await app.inject({ method: 'GET', url: '/api/debug/active' });
expect(res.statusCode).toBe(200);
expect(res.json()).toEqual({ enabled: false });
state.enabled = true;
res = await app.inject({ method: 'GET', url: '/api/debug/active' });
expect(res.statusCode).toBe(200);
expect(res.json()).toEqual({ enabled: true });
});
});
describe('api/routes/debugRouter.js - admin-only enforcement', () => {
let app;
beforeEach(async () => {
const ROOT = path.resolve('.');
const storagePath = path.join(ROOT, 'lib', 'services', 'debug', 'debugLogStorage.js');
const bundlePath = path.join(ROOT, 'lib', 'services', 'debug', 'debugBundleService.js');
const settingsStoragePath = path.join(ROOT, 'lib', 'services', 'storage', 'settingsStorage.js');
vi.resetModules();
vi.doMock(storagePath, () => ({
isEnabled: () => false,
enableDebugLogging: async () => {},
disableDebugLogging: async () => {},
getCurrentSize: async () => 0,
getMaxSize: () => 5 * 1024 * 1024,
hasAnyLogs: () => false,
wasEverEnabled: async () => false,
clearAllDebugLogs: () => {},
}));
vi.doMock(bundlePath, () => ({
buildDebugBundleFileName: async () => 'x.zip',
buildDebugBundleZip: async () => Buffer.from(''),
}));
vi.doMock(settingsStoragePath, () => ({
getSettings: async () => ({}),
}));
const plugin = (await import(path.join(ROOT, 'lib', 'api', 'routes', 'debugRouter.js'))).default;
app = Fastify({ logger: false });
await app.register(
async (sub) => {
// Same wiring shape as lib/api/api.js: apply adminHook before the plugin.
sub.addHook('preHandler', async (request, reply) => {
reply.code(401).send();
});
sub.register(plugin, { prefix: '/api/admin/debug' });
},
{ prefix: '/' },
);
await app.ready();
});
afterEach(async () => {
if (app) await app.close();
});
it('rejects non-admin callers with 401 on every endpoint', async () => {
for (const route of [
['GET', '/api/admin/debug/status'],
['POST', '/api/admin/debug/enable'],
['POST', '/api/admin/debug/disable'],
['GET', '/api/admin/debug/download'],
['DELETE', '/api/admin/debug/logs'],
]) {
const [method, url] = route;
const res = await app.inject({ method, url, payload: method === 'POST' ? {} : undefined });
expect(res.statusCode, `${method} ${url}`).toBe(401);
}
});
});

View File

@@ -0,0 +1,89 @@
/*
* Copyright (c) 2026 by Christian Kellner.
* Licensed under Apache-2.0 with Commons Clause and Attribution/Naming Clause
*/
import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
import path from 'node:path';
describe('services/logger.js - debug log sink', () => {
let logger;
let setDebugLogSink;
let consoleSpies;
beforeEach(async () => {
vi.resetModules();
const mod = await import(path.resolve('lib/services/logger.js'));
logger = mod.default;
setDebugLogSink = mod.setDebugLogSink;
// Silence console output so test runner stdout stays readable while still
// letting us inspect what the logger emitted if a test wants to.
consoleSpies = {
debug: vi.spyOn(console, 'debug').mockImplementation(() => {}),
info: vi.spyOn(console, 'info').mockImplementation(() => {}),
warn: vi.spyOn(console, 'warn').mockImplementation(() => {}),
error: vi.spyOn(console, 'error').mockImplementation(() => {}),
};
});
afterEach(() => {
setDebugLogSink(null);
for (const spy of Object.values(consoleSpies)) spy.mockRestore();
});
it('is a no-op for the sink when none is registered', () => {
// Just make sure nothing throws.
expect(() => logger.info('hello')).not.toThrow();
expect(() => logger.error(new Error('boom'))).not.toThrow();
});
it('forwards every log level (including debug) to the registered sink', () => {
const captured = [];
setDebugLogSink((entry) => captured.push(entry));
logger.debug('debug-line');
logger.info('info-line');
logger.warn('warn-line');
logger.error('error-line');
expect(captured).toHaveLength(4);
expect(captured.map((c) => c.level)).toEqual(['debug', 'info', 'warn', 'error']);
expect(captured[0].message).toContain('debug-line');
expect(captured[1].message).toContain('info-line');
expect(captured[2].message).toContain('warn-line');
expect(captured[3].message).toContain('error-line');
for (const c of captured) {
expect(typeof c.ts).toBe('number');
}
});
it('serializes Error stacks for the sink instead of "[object Object]"', () => {
const captured = [];
setDebugLogSink((entry) => captured.push(entry));
logger.error(new Error('boom'));
expect(captured).toHaveLength(1);
expect(captured[0].message).toContain('Error: boom');
});
it('stops forwarding once the sink is unregistered', () => {
const captured = [];
setDebugLogSink((entry) => captured.push(entry));
logger.info('one');
setDebugLogSink(null);
logger.info('two');
expect(captured).toHaveLength(1);
expect(captured[0].message).toContain('one');
});
it('does not break the caller when the sink throws', () => {
setDebugLogSink(() => {
throw new Error('sink exploded');
});
expect(() => logger.info('still works')).not.toThrow();
expect(consoleSpies.info).toHaveBeenCalled();
});
});