Implement logging utility

This commit is contained in:
Nissa Seru 2025-02-08 09:30:42 -05:00
parent 910bdf19d5
commit f403a336dc
9 changed files with 1019 additions and 1 deletions

View file

@ -10,6 +10,13 @@
- Prefer fixing the underlying issue over disabling the lint rule
- Document any approved lint rule disabling with a comment explaining the reason
3. Logging Guidelines:
- Always instrument code changes using the logger exported from `src\utils\logging\index.ts`.
- This will facilitate efficient debugging without impacting production (as the logger no-ops outside of a test environment.)
- Logs can be found in `logs\app.log`
- Logfile is overwritten on each run to keep it to a manageable volume.
# Adding a New Setting
To add a new setting that persists its state, follow the steps in cline_docs/settings.md
To add a new setting that persists its state, follow the steps in cline_docs/settings.md

4
.gitignore vendored
View file

@ -22,3 +22,7 @@ docs/_site/
# Dotenv
.env.integration
#Logging
logs

View file

@ -0,0 +1,151 @@
/**
* @fileoverview Implementation of the compact logging system's main logger class
*/
import { ILogger, LogMeta, CompactLogEntry, LogLevel } from "./types"
import { CompactTransport } from "./CompactTransport"
/**
* Main logger implementation providing compact, efficient logging capabilities
* @implements {ILogger}
*/
export class CompactLogger implements ILogger {
private transport: CompactTransport
private parentMeta: LogMeta | undefined
/**
* Creates a new CompactLogger instance
* @param transport - Optional custom transport instance
* @param parentMeta - Optional parent metadata for hierarchical logging
*/
constructor(transport?: CompactTransport, parentMeta?: LogMeta) {
this.transport = transport ?? new CompactTransport()
this.parentMeta = parentMeta
}
/**
* Logs a debug level message
* @param message - The message to log
* @param meta - Optional metadata to include
*/
debug(message: string, meta?: LogMeta): void {
this.log("debug", message, this.combineMeta(meta))
}
/**
* Logs an info level message
* @param message - The message to log
* @param meta - Optional metadata to include
*/
info(message: string, meta?: LogMeta): void {
this.log("info", message, this.combineMeta(meta))
}
/**
* Logs a warning level message
* @param message - The message to log
* @param meta - Optional metadata to include
*/
warn(message: string, meta?: LogMeta): void {
this.log("warn", message, this.combineMeta(meta))
}
/**
* Logs an error level message
* @param message - The error message or Error object
* @param meta - Optional metadata to include
*/
error(message: string | Error, meta?: LogMeta): void {
this.handleErrorLog("error", message, meta)
}
/**
* Logs a fatal level message
* @param message - The error message or Error object
* @param meta - Optional metadata to include
*/
fatal(message: string | Error, meta?: LogMeta): void {
this.handleErrorLog("fatal", message, meta)
}
/**
* Creates a child logger inheriting this logger's metadata
* @param meta - Additional metadata for the child logger
* @returns A new logger instance with combined metadata
*/
child(meta: LogMeta): ILogger {
const combinedMeta = this.parentMeta ? { ...this.parentMeta, ...meta } : meta
return new CompactLogger(this.transport, combinedMeta)
}
/**
* Closes the logger and its transport
*/
close(): void {
this.transport.close()
}
/**
* Handles logging of error and fatal messages with special error object processing
* @private
* @param level - The log level (error or fatal)
* @param message - The message or Error object to log
* @param meta - Optional metadata to include
*/
private handleErrorLog(level: "error" | "fatal", message: string | Error, meta?: LogMeta): void {
if (message instanceof Error) {
const errorMeta: LogMeta = {
ctx: meta?.ctx ?? level,
id: meta?.id,
error: {
name: message.name,
message: message.message,
stack: message.stack,
},
...meta,
}
this.log(level, message.message, this.combineMeta(errorMeta))
} else {
this.log(level, message, this.combineMeta(meta))
}
}
/**
* Combines parent and current metadata with proper context handling
* @private
* @param meta - The current metadata to combine with parent metadata
* @returns Combined metadata or undefined if no metadata exists
*/
private combineMeta(meta?: LogMeta): LogMeta | undefined {
if (!this.parentMeta) {
return meta
}
if (!meta) {
return this.parentMeta
}
return {
...this.parentMeta,
...meta,
ctx: meta.ctx || this.parentMeta.ctx,
}
}
/**
* Core logging function that processes and writes log entries
* @private
* @param level - The log level
* @param message - The message to log
* @param meta - Optional metadata to include
*/
private log(level: LogLevel, message: string, meta?: LogMeta): void {
const entry: CompactLogEntry = {
t: Date.now(),
l: level,
m: message,
c: meta?.ctx,
d: meta ? (({ ctx, ...rest }) => (Object.keys(rest).length > 0 ? rest : undefined))(meta) : undefined,
}
this.transport.write(entry)
}
}

View file

@ -0,0 +1,122 @@
/**
* @fileoverview Implementation of the compact logging transport system with file output capabilities
*/
import { writeFileSync, mkdirSync } from "fs"
import { dirname } from "path"
import { CompactTransportConfig, ICompactTransport, CompactLogEntry, LogLevel, LOG_LEVELS } from "./types"
/**
* Default configuration for the transport
*/
const DEFAULT_CONFIG: CompactTransportConfig = {
level: "debug",
fileOutput: {
enabled: true,
path: "./logs/app.log",
},
}
/**
* Determines if a log entry should be processed based on configured minimum level
* @param configLevel - The minimum log level from configuration
* @param entryLevel - The level of the current log entry
* @returns Whether the entry should be processed
*/
function isLevelEnabled(configLevel: LogLevel, entryLevel: string): boolean {
const configIdx = LOG_LEVELS.indexOf(configLevel)
const entryIdx = LOG_LEVELS.indexOf(entryLevel as LogLevel)
return entryIdx >= configIdx
}
/**
* Implements the compact logging transport with file output support
* @implements {ICompactTransport}
*/
export class CompactTransport implements ICompactTransport {
private sessionStart: number
private lastTimestamp: number
private filePath?: string
private initialized: boolean = false
/**
* Creates a new CompactTransport instance
* @param config - Optional transport configuration
*/
constructor(readonly config: CompactTransportConfig = DEFAULT_CONFIG) {
this.sessionStart = Date.now()
this.lastTimestamp = this.sessionStart
if (config.fileOutput?.enabled) {
this.filePath = config.fileOutput.path
}
}
/**
* Ensures the log file is initialized with proper directory structure and session start marker
* @private
* @throws {Error} If file initialization fails
*/
private ensureInitialized(): void {
if (this.initialized || !this.filePath) return
try {
mkdirSync(dirname(this.filePath), { recursive: true })
writeFileSync(this.filePath, "", { flag: "w" })
const sessionStart = {
t: 0,
l: "info",
m: "Log session started",
d: { timestamp: new Date(this.sessionStart).toISOString() },
}
writeFileSync(this.filePath, JSON.stringify(sessionStart) + "\n", { flag: "w" })
this.initialized = true
} catch (err) {
throw new Error(`Failed to initialize log file: ${(err as Error).message}`)
}
}
/**
* Writes a log entry to configured outputs (console and/or file)
* @param entry - The log entry to write
*/
write(entry: CompactLogEntry): void {
const deltaT = entry.t - this.lastTimestamp
this.lastTimestamp = entry.t
const compact = {
...entry,
t: deltaT,
}
const output = JSON.stringify(compact) + "\n"
// Write to console if level is enabled
if (this.config.level && isLevelEnabled(this.config.level, entry.l)) {
process.stdout.write(output)
}
// Write to file if enabled
if (this.filePath) {
this.ensureInitialized()
writeFileSync(this.filePath, output, { flag: "a" })
}
}
/**
* Closes the transport and writes session end marker
*/
close(): void {
if (this.filePath && this.initialized) {
const sessionEnd = {
t: Date.now() - this.lastTimestamp,
l: "info",
m: "Log session ended",
d: { timestamp: new Date().toISOString() },
}
writeFileSync(this.filePath, JSON.stringify(sessionEnd) + "\n", { flag: "a" })
}
}
}

View file

@ -0,0 +1,338 @@
// __tests__/CompactLogger.test.ts
import { describe, expect, test, beforeEach, afterEach } from "@jest/globals"
import { CompactLogger } from "../CompactLogger"
import { MockTransport } from "./MockTransport"
import { LogLevel } from "../types"
describe("CompactLogger", () => {
let transport: MockTransport
let logger: CompactLogger
beforeEach(() => {
transport = new MockTransport()
logger = new CompactLogger(transport)
})
afterEach(() => {
transport.clear()
})
describe("Log Levels", () => {
const levels: LogLevel[] = ["debug", "info", "warn", "error", "fatal"]
levels.forEach((level) => {
test(`${level} level logs correctly`, () => {
const message = `test ${level} message`
;(logger[level] as (message: string) => void)(message)
expect(transport.entries.length).toBe(1)
expect(transport.entries[0]).toMatchObject({
l: level,
m: message,
})
expect(transport.entries[0].t).toBeGreaterThan(0)
})
})
})
describe("Metadata Handling", () => {
test("logs with simple metadata", () => {
const meta = { ctx: "test", userId: "123" }
logger.info("test message", meta)
expect(transport.entries[0]).toMatchObject({
m: "test message",
c: "test",
d: { userId: "123" },
})
})
test("handles undefined metadata", () => {
logger.info("test message")
expect(transport.entries[0]).toMatchObject({
m: "test message",
})
expect(transport.entries[0].d).toBeUndefined()
})
test("strips empty metadata", () => {
logger.info("test message", { ctx: "test" })
expect(transport.entries[0]).toMatchObject({
m: "test message",
c: "test",
})
expect(transport.entries[0].d).toBeUndefined()
})
})
describe("Error Handling", () => {
test("handles Error objects in error level", () => {
const error = new Error("test error")
logger.error(error)
expect(transport.entries[0]).toMatchObject({
l: "error",
m: "test error",
c: "error",
d: {
error: {
name: "Error",
message: "test error",
stack: error.stack,
},
},
})
})
test("handles Error objects in fatal level", () => {
const error = new Error("test fatal")
logger.fatal(error)
expect(transport.entries[0]).toMatchObject({
l: "fatal",
m: "test fatal",
c: "fatal",
d: {
error: {
name: "Error",
message: "test fatal",
stack: error.stack,
},
},
})
})
test("handles Error objects with custom metadata", () => {
const error = new Error("test error")
const meta = { ctx: "custom", userId: "123" }
logger.error(error, meta)
expect(transport.entries[0]).toMatchObject({
l: "error",
m: "test error",
c: "custom",
d: {
userId: "123",
error: {
name: "Error",
message: "test error",
stack: error.stack,
},
},
})
})
})
describe("Child Loggers", () => {
test("creates child logger with inherited metadata", () => {
const parentMeta = { ctx: "parent", traceId: "123" }
const childMeta = { ctx: "child", userId: "456" }
const parentLogger = new CompactLogger(transport, parentMeta)
const childLogger = parentLogger.child(childMeta)
childLogger.info("test message")
expect(transport.entries[0]).toMatchObject({
m: "test message",
c: "child",
d: {
traceId: "123",
userId: "456",
},
})
})
test("child logger respects parent context when not overridden", () => {
const parentLogger = new CompactLogger(transport, { ctx: "parent" })
const childLogger = parentLogger.child({ userId: "123" })
childLogger.info("test message")
expect(transport.entries[0]).toMatchObject({
m: "test message",
c: "parent",
d: { userId: "123" },
})
})
})
describe("Lifecycle", () => {
test("closes transport on logger close", () => {
logger.close()
expect(transport.closed).toBe(true)
})
})
describe("Timestamp Handling", () => {
beforeEach(() => {
jest.useFakeTimers()
})
afterEach(() => {
jest.useRealTimers()
})
test("generates increasing timestamps", () => {
const now = Date.now()
jest.setSystemTime(now)
logger.info("first")
jest.setSystemTime(now + 10)
logger.info("second")
expect(transport.entries[0].t).toBeLessThan(transport.entries[1].t)
})
})
describe("Message Handling", () => {
test("handles empty string messages", () => {
logger.info("")
expect(transport.entries[0]).toMatchObject({
m: "",
l: "info",
})
})
})
describe("Metadata Edge Cases", () => {
test("handles metadata with undefined values", () => {
const meta = {
ctx: "test",
someField: undefined,
validField: "value",
}
logger.info("test", meta)
expect(transport.entries[0].d).toMatchObject({
someField: undefined,
validField: "value",
})
})
test("handles metadata with null values", () => {
logger.info("test", { ctx: "test", nullField: null })
expect(transport.entries[0].d).toMatchObject({ nullField: null })
})
test("maintains metadata value types", () => {
const meta = {
str: "string",
num: 123,
bool: true,
arr: [1, 2, 3],
obj: { nested: true },
}
logger.info("test", meta)
expect(transport.entries[0].d).toStrictEqual(meta)
})
})
describe("Child Logger Edge Cases", () => {
test("deeply nested child loggers maintain correct metadata inheritance", () => {
const root = new CompactLogger(transport, { ctx: "root", rootVal: 1 })
const child1 = root.child({ level1: "a" })
const child2 = child1.child({ level2: "b" })
const child3 = child2.child({ ctx: "leaf" })
child3.info("test")
expect(transport.entries[0]).toMatchObject({
c: "leaf",
d: {
rootVal: 1,
level1: "a",
level2: "b",
},
})
})
test("child logger with empty metadata inherits parent metadata unchanged", () => {
const parent = new CompactLogger(transport, { ctx: "parent", data: "value" })
const child = parent.child({})
child.info("test")
expect(transport.entries[0]).toMatchObject({
c: "parent",
d: { data: "value" },
})
})
})
describe("Error Handling Edge Cases", () => {
test("handles custom error types", () => {
class CustomError extends Error {
constructor(
message: string,
public code: string,
) {
super(message)
this.name = "CustomError"
}
}
const error = new CustomError("custom error", "ERR_CUSTOM")
logger.error(error)
expect(transport.entries[0]).toMatchObject({
m: "custom error",
d: {
error: {
name: "CustomError",
message: "custom error",
stack: error.stack,
},
},
})
})
test("handles errors without stack traces", () => {
const error = new Error("test")
delete error.stack
logger.error(error)
expect(transport.entries[0].d).toMatchObject({
error: {
name: "Error",
message: "test",
stack: undefined,
},
})
})
})
describe("Timestamp Generation", () => {
beforeEach(() => {
jest.useFakeTimers()
})
afterEach(() => {
jest.useRealTimers()
})
test("uses current timestamp for entries", () => {
const baseTime = 1000000000000
jest.setSystemTime(baseTime)
logger.info("test")
expect(transport.entries[0].t).toBe(baseTime)
})
test("timestamps reflect time progression", () => {
const baseTime = 1000000000000
jest.setSystemTime(baseTime)
logger.info("first")
jest.setSystemTime(baseTime + 100)
logger.info("second")
expect(transport.entries).toHaveLength(2)
expect(transport.entries[0].t).toBe(baseTime)
expect(transport.entries[1].t).toBe(baseTime + 100)
})
})
})

View file

@ -0,0 +1,220 @@
// __tests__/CompactTransport.test.ts
import { describe, expect, test, beforeEach, afterEach } from "@jest/globals"
import { CompactTransport } from "../CompactTransport"
import fs from "fs"
import path from "path"
describe("CompactTransport", () => {
const testDir = "./test-logs"
const testLogPath = path.join(testDir, "test.log")
let transport: CompactTransport
const originalWrite = process.stdout.write
const cleanupTestLogs = () => {
const rmDirRecursive = (dirPath: string) => {
if (fs.existsSync(dirPath)) {
fs.readdirSync(dirPath).forEach((file) => {
const curPath = path.join(dirPath, file)
if (fs.lstatSync(curPath).isDirectory()) {
// Recursive call for directories
rmDirRecursive(curPath)
} else {
// Delete file
fs.unlinkSync(curPath)
}
})
// Remove directory after it's empty
fs.rmdirSync(dirPath)
}
}
try {
rmDirRecursive(testDir)
} catch (err) {
console.error("Cleanup error:", err)
}
}
beforeEach(() => {
process.stdout.write = () => true
cleanupTestLogs()
fs.mkdirSync(testDir, { recursive: true })
transport = new CompactTransport({
level: "fatal",
fileOutput: {
enabled: true,
path: testLogPath,
},
})
})
afterEach(() => {
process.stdout.write = originalWrite
transport.close()
cleanupTestLogs()
})
describe("File Handling", () => {
test("creates new log file on initialization", () => {
const entry = {
t: Date.now(),
l: "info",
m: "test message",
}
transport.write(entry)
const fileContent = fs.readFileSync(testLogPath, "utf-8")
const lines = fileContent.trim().split("\n")
expect(lines.length).toBe(2)
expect(JSON.parse(lines[0])).toMatchObject({
l: "info",
m: "Log session started",
})
expect(JSON.parse(lines[1])).toMatchObject({
l: "info",
m: "test message",
})
})
test("appends entries after initialization", () => {
transport.write({
t: Date.now(),
l: "info",
m: "first",
})
transport.write({
t: Date.now(),
l: "info",
m: "second",
})
const fileContent = fs.readFileSync(testLogPath, "utf-8")
const lines = fileContent.trim().split("\n")
expect(lines.length).toBe(3)
expect(JSON.parse(lines[1])).toMatchObject({ m: "first" })
expect(JSON.parse(lines[2])).toMatchObject({ m: "second" })
})
test("writes session end marker on close", () => {
transport.write({
t: Date.now(),
l: "info",
m: "test",
})
transport.close()
const fileContent = fs.readFileSync(testLogPath, "utf-8")
const lines = fileContent.trim().split("\n")
const lastLine = JSON.parse(lines[lines.length - 1])
expect(lastLine).toMatchObject({
l: "info",
m: "Log session ended",
})
})
})
describe("File System Edge Cases", () => {
test("handles file path with deep directories", () => {
const deepDir = path.join(testDir, "deep/nested/path")
const deepPath = path.join(deepDir, "test.log")
const deepTransport = new CompactTransport({
fileOutput: { enabled: true, path: deepPath },
})
try {
deepTransport.write({
t: Date.now(),
l: "info",
m: "test",
})
expect(fs.existsSync(deepPath)).toBeTruthy()
} finally {
deepTransport.close()
// Clean up the deep directory structure
const rmDirRecursive = (dirPath: string) => {
if (fs.existsSync(dirPath)) {
fs.readdirSync(dirPath).forEach((file) => {
const curPath = path.join(dirPath, file)
if (fs.lstatSync(curPath).isDirectory()) {
rmDirRecursive(curPath)
} else {
fs.unlinkSync(curPath)
}
})
fs.rmdirSync(dirPath)
}
}
rmDirRecursive(path.join(testDir, "deep"))
}
})
test("handles concurrent writes", async () => {
const entries = Array(100)
.fill(null)
.map((_, i) => ({
t: Date.now(),
l: "info",
m: `test ${i}`,
}))
await Promise.all(entries.map((entry) => Promise.resolve(transport.write(entry))))
const fileContent = fs.readFileSync(testLogPath, "utf-8")
const lines = fileContent.trim().split("\n")
// +1 for session start line
expect(lines.length).toBe(entries.length + 1)
})
})
describe("Delta Timestamp Conversion", () => {
let output: string[] = []
beforeEach(() => {
output = []
jest.useFakeTimers()
const baseTime = 1000000000000
jest.setSystemTime(baseTime) // Set time before transport creation
process.stdout.write = (str: string): boolean => {
output.push(str)
return true
}
})
afterEach(() => {
jest.useRealTimers()
})
test("converts absolute timestamps to deltas", () => {
const baseTime = Date.now() // Use current fake time
const transport = new CompactTransport({
level: "info",
fileOutput: { enabled: false, path: "null" },
})
transport.write({
t: baseTime,
l: "info",
m: "first",
})
transport.write({
t: baseTime + 100,
l: "info",
m: "second",
})
const entries = output.map((str) => JSON.parse(str))
expect(entries[0].t).toBe(0) // First entry should have 0 delta from transport creation
expect(entries[1].t).toBe(100) // Delta from previous entry
})
})
})

View file

@ -0,0 +1,34 @@
// __tests__/MockTransport.ts
import { CompactTransport } from "../CompactTransport"
import type { CompactLogEntry, CompactTransportConfig } from "../types"
const TEST_CONFIG: CompactTransportConfig = {
level: "fatal",
fileOutput: {
enabled: false,
path: "",
},
}
export class MockTransport extends CompactTransport {
public entries: CompactLogEntry[] = []
public closed = false
constructor() {
super(TEST_CONFIG)
}
override async write(entry: CompactLogEntry): Promise<void> {
this.entries.push(entry)
}
override async close(): Promise<void> {
this.closed = true
await super.close()
}
clear(): void {
this.entries = []
this.closed = false
}
}

View file

@ -0,0 +1,25 @@
/**
* @fileoverview Main entry point for the compact logging system
* Provides a default logger instance with Jest environment detection
*/
import { CompactLogger } from "./CompactLogger"
/**
* No-operation logger implementation for test environments
*/
const noopLogger = {
debug: () => {},
info: () => {},
warn: () => {},
error: () => {},
fatal: () => {},
child: () => noopLogger,
close: () => {},
}
/**
* Default logger instance
* Uses CompactLogger for normal operation, switches to noop logger in Jest test environment
*/
export const logger = process.env.JEST_WORKER_ID !== undefined ? new CompactLogger() : noopLogger

117
src/utils/logging/types.ts Normal file
View file

@ -0,0 +1,117 @@
/**
* @fileoverview Core type definitions for the compact logging system
*/
/**
* Represents a compact log entry format optimized for storage and transmission
*/
export interface CompactLogEntry {
/** Delta timestamp from last entry in milliseconds */
t: number
/** Log level identifier */
l: string
/** Log message content */
m: string
/** Optional context identifier */
c?: string
/** Optional structured data payload */
d?: unknown
}
/** Available log levels in ascending order of severity */
export const LOG_LEVELS = ["debug", "info", "warn", "error", "fatal"] as const
/** Type representing valid log levels */
export type LogLevel = (typeof LOG_LEVELS)[number]
/**
* Metadata structure for log entries
*/
export interface LogMeta {
/** Optional context identifier */
ctx?: string
/** Additional arbitrary metadata fields */
[key: string]: unknown
}
/**
* Configuration options for CompactTransport
*/
export interface CompactTransportConfig {
/** Minimum log level to process */
level?: LogLevel
/** File output configuration */
fileOutput?: {
/** Whether file output is enabled */
enabled: boolean
/** Path to the log file */
path: string
}
}
/**
* Interface for log transport implementations
*/
export interface ICompactTransport {
/**
* Writes a log entry to the transport
* @param entry - The log entry to write
*/
write(entry: CompactLogEntry): void
/**
* Closes the transport and performs cleanup
*/
close(): void
}
/**
* Interface for logger implementations
*/
export interface ILogger {
/**
* Logs a debug message
* @param message - The message to log
* @param meta - Optional metadata
*/
debug(message: string, meta?: LogMeta): void
/**
* Logs an info message
* @param message - The message to log
* @param meta - Optional metadata
*/
info(message: string, meta?: LogMeta): void
/**
* Logs a warning message
* @param message - The message to log
* @param meta - Optional metadata
*/
warn(message: string, meta?: LogMeta): void
/**
* Logs an error message
* @param message - The message or error to log
* @param meta - Optional metadata
*/
error(message: string | Error, meta?: LogMeta): void
/**
* Logs a fatal error message
* @param message - The message or error to log
* @param meta - Optional metadata
*/
fatal(message: string | Error, meta?: LogMeta): void
/**
* Creates a child logger with inherited metadata
* @param meta - Metadata to merge with parent's metadata
* @returns A new logger instance with combined metadata
*/
child(meta: LogMeta): ILogger
/**
* Closes the logger and its transport
*/
close(): void
}