diff --git a/src/helpers/logger.mts b/src/helpers/logger.mts index 72e41ba8..1e29bf9c 100644 --- a/src/helpers/logger.mts +++ b/src/helpers/logger.mts @@ -1,21 +1,10 @@ -import type { Get } from "type-fest"; - import type { TContext } from "./context.mts"; import type { TBlackHole } from "./utilities.mts"; -// eslint-disable-next-line @typescript-eslint/no-empty-object-type -export interface ReplacementLogger { - // intentionally left empty - // for use with declaration merging -} - -export type GetLogger = - Get extends object ? Get : ILogger; - export type LogStreamTarget = (message: string, data: object) => TBlackHole; export type DigitalAlchemyLogger = { - addTarget: (logger: GetLogger | LogStreamTarget) => void; + addTarget: (logger: LogStreamTarget) => void; /** * Create a new logger instance for a given context */ @@ -23,10 +12,7 @@ export type DigitalAlchemyLogger = { /** * Retrieve a reference to the base logger used to emit from */ - getBaseLogger: () => Record< - keyof GetLogger, - (context: TContext, ...data: Parameters) => void - >; + getBaseLogger: () => ILogger; getPrettyFormat: () => boolean; /** * exposed for testing @@ -37,7 +23,7 @@ export type DigitalAlchemyLogger = { * * Note: Extension still handles LOG_LEVEL logic */ - setBaseLogger: (base: GetLogger) => GetLogger; + setBaseLogger: (base: ILogger) => ILogger; /** * Set the enabled/disabled state of the message pretty formatting logic */ @@ -45,36 +31,51 @@ export type DigitalAlchemyLogger = { /** * Logger instance of last resort */ - systemLogger: GetLogger; + systemLogger: ILogger; /** * exposed for testing */ updateShouldLog: () => void; }; +export interface ExtraLoggerArgs { + string: string; + boolean: boolean; + number: number; +} + +export type LoggerArgs = ExtraLoggerArgs[keyof ExtraLoggerArgs]; + export type TLoggerFunction = - | ((message: string, ...arguments_: unknown[]) => void) - | ((object: object, message?: string, ...arguments_: unknown[]) => void); + | ((message: string, ...arguments_: LoggerArgs[]) => void) + | ((object: object, message?: string, ...arguments_: LoggerArgs[]) => void); + +// export type InternalRewriteLoggerFn = ( +// context: TContext, +// ...data: Parameters +// ) => void; + +// export type InternalRewriteLogger = Record; export interface ILogger { debug(...arguments_: Parameters): void; - debug(message: string, ...arguments_: unknown[]): void; - debug(object: object, message?: string, ...arguments_: unknown[]): void; + debug(message: string, ...arguments_: LoggerArgs[]): void; + debug(object: object, message?: string, ...arguments_: LoggerArgs[]): void; error(...arguments_: Parameters): void; - error(message: string, ...arguments_: unknown[]): void; - error(object: object, message?: string, ...arguments_: unknown[]): void; + error(message: string, ...arguments_: LoggerArgs[]): void; + error(object: object, message?: string, ...arguments_: LoggerArgs[]): void; fatal(...arguments_: Parameters): void; - fatal(message: string, ...arguments_: unknown[]): void; - fatal(object: object, message?: string, ...arguments_: unknown[]): void; + fatal(message: string, ...arguments_: LoggerArgs[]): void; + fatal(object: object, message?: string, ...arguments_: LoggerArgs[]): void; info(...arguments_: Parameters): void; - info(message: string, ...arguments_: unknown[]): void; - info(object: object, message?: string, ...arguments_: unknown[]): void; + info(message: string, ...arguments_: LoggerArgs[]): void; + info(object: object, message?: string, ...arguments_: LoggerArgs[]): void; trace(...arguments_: Parameters): void; - trace(message: string, ...arguments_: unknown[]): void; - trace(object: object, message?: string, ...arguments_: unknown[]): void; + trace(message: string, ...arguments_: LoggerArgs[]): void; + trace(object: object, message?: string, ...arguments_: LoggerArgs[]): void; warn(...arguments_: Parameters): void; - warn(message: string, ...arguments_: unknown[]): void; - warn(object: object, message?: string, ...arguments_: unknown[]): void; + warn(message: string, ...arguments_: LoggerArgs[]): void; + warn(object: object, message?: string, ...arguments_: LoggerArgs[]): void; } export type TConfigLogLevel = keyof ILogger | "silent"; diff --git a/src/helpers/wiring.mts b/src/helpers/wiring.mts index c050f426..95725f96 100644 --- a/src/helpers/wiring.mts +++ b/src/helpers/wiring.mts @@ -19,7 +19,7 @@ import type { TContext } from "./context.mts"; import type { CronExpression, ScheduleRemove } from "./cron.mts"; import { BootstrapException } from "./errors.mts"; import type { TLifecycleBase } from "./lifecycle.mts"; -import type { GetLogger, TConfigLogLevel } from "./logger.mts"; +import type { ILogger, TConfigLogLevel } from "./logger.mts"; import type { TBlackHole } from "./utilities.mts"; export type TServiceReturn = void | OBJECT; @@ -150,7 +150,7 @@ export interface AsyncLogData { /** * thread local child logger */ - logger?: GetLogger; + logger?: ILogger; } export interface AsyncLocalData { @@ -196,7 +196,7 @@ export type TServiceParams = { /** * context aware logger instance */ - logger: GetLogger; + logger: ILogger; /** * run commands on intervals & schedules * @@ -363,7 +363,7 @@ export type BootstrapOptions = { /** * use this logger, instead of the baked in one. Maybe you want some custom transports or something? Put your customized thing here */ - customLogger?: GetLogger; + customLogger?: ILogger; /** * fine tine the built in logger @@ -482,7 +482,7 @@ export type ApplicationDefinition< C extends OptionalModuleConfiguration, > = ApplicationConfigurationOptions & Wire & { - logger: GetLogger; + logger: ILogger; type: "application"; booted: boolean; bootstrap: (options?: BootstrapOptions) => Promise; @@ -493,7 +493,7 @@ export type TLibrary = LibraryDefinition( app: ApplicationDefinition, - logger: GetLogger, + logger: ILogger, ) { if (is.empty(app.libraries)) { return []; diff --git a/src/services/configuration.service.mts b/src/services/configuration.service.mts index 4a2aa633..a66e5b6f 100644 --- a/src/services/configuration.service.mts +++ b/src/services/configuration.service.mts @@ -41,7 +41,10 @@ export function Configuration({ // modern problems require modern solutions let logger: ILogger; - lifecycle.onPreInit(() => (logger = internal.boilerplate.logger.context(context))); + lifecycle.onPreInit( + () => (logger = internal.boilerplate.logger.context(context)), + Number.NEGATIVE_INFINITY, + ); const configDefinitions: KnownConfigs = new Map(); const configuration: PartialConfiguration = {}; const loaded = new Set(); diff --git a/src/services/logger.service.mts b/src/services/logger.service.mts index dbcb5558..a432dd40 100644 --- a/src/services/logger.service.mts +++ b/src/services/logger.service.mts @@ -1,12 +1,12 @@ /* eslint-disable sonarjs/slow-regex */ import chalk from "chalk"; import dayjs from "dayjs"; +import fs from "fs"; import { format, inspect } from "util"; import type { DigitalAlchemyLogger, FlatServiceNames, - GetLogger, ILogger, LoadedModuleNames, LogStreamTarget, @@ -26,19 +26,21 @@ const LOG_LEVEL_PRIORITY = { trace: 10, warn: 40, }; +export const VALID_LOG_LEVELS = Object.keys( + LOG_LEVEL_PRIORITY, +) as (keyof typeof LOG_LEVEL_PRIORITY)[]; + const DECIMALS = 2; const LOG_LEVELS = Object.keys(LOG_LEVEL_PRIORITY) as TConfigLogLevel[]; -let logger = {} as Record< - keyof ILogger, - (context: TContext, ...data: Parameters) => void ->; +let logger = {} as ILogger; const MAX_CUTOFF = 2000; const frontDash = " - "; const SYMBOL_START = 1; const SYMBOL_END = -1; const LEVEL_MAX = 7; +const SKIP_FIRST_PARAM = 1; export async function Logger({ lifecycle, @@ -50,7 +52,7 @@ export async function Logger({ const { is } = internal.utils; let lastMessage = performance.now(); let logCounter = START; - const extraTargets = new Set(); + const extraTargets = new Set(); internal.boot.options ??= {}; const { loggerOptions = {} } = internal.boot.options; @@ -66,6 +68,24 @@ export async function Logger({ // if this is enabled while outputting to docker logs, the output becomes much harder to read inspect.defaultOptions.colors = prettyFormat; + // #MARK: normalizeParameters + function normalizeParameters( + context: TContext, + ...params: Parameters + ): Parameters { + if (is.object(params[FIRST])) { + // First param is an object - ensure it has context (create new object to avoid mutation) + const firstParam = params[FIRST] as { context?: TContext } & Record; + if (!firstParam.context) { + const remainingParams = params.slice(SKIP_FIRST_PARAM); + return [{ ...firstParam, context }, ...remainingParams] as Parameters; + } + return params; + } + // First param is not an object - create one with context and shift everything over + return [{ context }, ...params] as Parameters; + } + // #MARK: mergeData function mergeData(data: T): [T, ILogger] { let out = { ...data, ...loggerOptions.mergeData }; @@ -89,6 +109,32 @@ export async function Logger({ return [out, logger]; } + // #MARK: printMessage + function printMessage(key: keyof ILogger, message: string) { + switch (key) { + case "warn": { + globalThis.console.warn(message); + return; + } + case "debug": { + globalThis.console.debug(message); + return; + } + case "error": { + globalThis.console.error(message); + return; + } + case "fatal": { + // Synchronous write for fatal logs to ensure they are flushed before process exit + fs.writeSync(process.stdout.fd, `${message}\n`); + return; + } + default: { + globalThis.console.log(message); + } + } + } + // #MARK: prettyFormatMessage function prettyFormatMessage(message: string): string { if (!message) { @@ -119,7 +165,13 @@ export async function Logger({ if (is.empty(internal.boot.options?.customLogger)) { // #MARK: formatter [...METHOD_COLORS.keys()].forEach(key => { - logger[key] = (context: TContext, ...parameters: Parameters) => { + logger[key] = (...parameters: Parameters) => { + // Extract context from first param if it's an object, otherwise use default + const firstParam = parameters[FIRST]; + const contextValue: TContext = + (is.object(firstParam) && (firstParam as { context?: TContext }).context) || + ("digital-alchemy:system-logger" as TContext); + const [data, child] = mergeData( is.object(parameters[FIRST]) ? (parameters.shift() as { @@ -139,7 +191,7 @@ export async function Logger({ // used with cloud logging (graylog, datadog, etc) const rawData = { ...data, - context: data.context || context, + context: data.context || contextValue, level: key, timestamp: Date.now(), } as Record; @@ -171,11 +223,12 @@ export async function Logger({ // stream targets, just take all messages and do the exact same thing with them // ex: send to http endpoint if (is.function(target)) { - target(msg, rawData); + (target as LogStreamTarget)(msg, rawData); return; } - // something that conforms to the basic logger interface - (target as GetLogger)[key](msg, rawData); + if (is.object(target)) { + (target as ILogger)[key](rawData, msg); + } }); // minor performance tuning option: @@ -186,7 +239,7 @@ export async function Logger({ // #MARK: pretty logs const level = `[${key.toUpperCase()}]`.padStart(LEVEL_MAX, " "); - const highlighted = chalk.bold[METHOD_COLORS.get(key)](`[${data.context || context}]`); + const highlighted = chalk.bold[METHOD_COLORS.get(key)](`[${data.context || contextValue}]`); const timestamp = chalk.white(`[${dayjs().format(timestampFormat)}]`); let message = `${ms}${timestamp} ${level}${highlighted}`; @@ -210,7 +263,7 @@ export async function Logger({ "\n" + inspect(extra, { compact: false, - depth: 10, + depth: config.boilerplate.INSPECT_DEPTH, numericSeparator: true, sorted: true, }) @@ -224,25 +277,7 @@ export async function Logger({ return; } - // #MARK: globalThis.console - switch (key) { - case "warn": { - globalThis.console.warn(message); - return; - } - case "debug": { - globalThis.console.debug(message); - return; - } - case "error": - case "fatal": { - globalThis.console.error(message); - return; - } - default: { - globalThis.console.log(message); - } - } + printMessage(key, message); }; }); } else { @@ -283,18 +318,18 @@ export async function Logger({ return { debug: (...params: Parameters) => - shouldILog.debug && logger.debug(context as TContext, ...params), + shouldILog.debug && logger.debug(...normalizeParameters(context as TContext, ...params)), error: (...params: Parameters) => - shouldILog.error && logger.error(context as TContext, ...params), + shouldILog.error && logger.error(...normalizeParameters(context as TContext, ...params)), fatal: (...params: Parameters) => - shouldILog.fatal && logger.fatal(context as TContext, ...params), + shouldILog.fatal && logger.fatal(...normalizeParameters(context as TContext, ...params)), info: (...params: Parameters) => - shouldILog.info && logger.info(context as TContext, ...params), + shouldILog.info && logger.info(...normalizeParameters(context as TContext, ...params)), trace: (...params: Parameters) => - shouldILog.trace && logger.trace(context as TContext, ...params), + shouldILog.trace && logger.trace(...normalizeParameters(context as TContext, ...params)), warn: (...params: Parameters) => - shouldILog.warn && logger.warn(context as TContext, ...params), - } as GetLogger; + shouldILog.warn && logger.warn(...normalizeParameters(context as TContext, ...params)), + } as ILogger; } // #MARK updateShouldLog: @@ -306,15 +341,24 @@ export async function Logger({ } // #MARK: lifecycle - lifecycle.onPostConfig(() => internal.boilerplate.logger.updateShouldLog()); + lifecycle.onPostConfig(() => { + internal.boilerplate.logger.updateShouldLog(); + inspect.defaultOptions.depth = config.boilerplate.INSPECT_DEPTH; + }); + + lifecycle.onShutdownComplete(() => { + extraTargets.forEach(i => extraTargets.delete(i)); + }, Number.POSITIVE_INFINITY); + internal.boilerplate.configuration.onUpdate( () => internal.boilerplate.logger.updateShouldLog(), "boilerplate", "LOG_LEVEL", ); - function addTarget(target: GetLogger | LogStreamTarget) { + function addTarget(target: ILogger | LogStreamTarget) { extraTargets.add(target); + return internal.removeFn(() => extraTargets.delete(target)); } // #MARK: return object diff --git a/src/services/wiring.service.mts b/src/services/wiring.service.mts index e8660957..efe0c01e 100644 --- a/src/services/wiring.service.mts +++ b/src/services/wiring.service.mts @@ -27,6 +27,7 @@ import { eachSeries, NONE, SINGLE, + VALID_LOG_LEVELS, WIRE_PROJECT, wireOrder, WIRING_CONTEXT, @@ -77,6 +78,15 @@ function createBoilerplate() { type: "string", }, + /** + * Affects the node global inspectDepth for console.log, as well as the internal logger + */ + INSPECT_DEPTH: { + default: 10, + description: "Object depth to print in logs", + type: "number", + }, + /** * > by default true when: * @@ -120,7 +130,8 @@ function createBoilerplate() { * * ### `fatal` * - * Produce a log at the highest importance level, not common + * Produce a log at the highest importance level, not common. + * Prints logs sync to console (getting ahead of the probable exit as the next step) * * ### `silent` * @@ -129,7 +140,7 @@ function createBoilerplate() { LOG_LEVEL: { default: "trace", description: "Minimum log level to process", - enum: ["silent", "trace", "info", "warn", "debug", "error", "fatal"], + enum: VALID_LOG_LEVELS, type: "string", } satisfies StringConfig as StringConfig, diff --git a/testing/logger.spec.mts b/testing/logger.spec.mts index 813ef249..70280c83 100644 --- a/testing/logger.spec.mts +++ b/testing/logger.spec.mts @@ -1,5 +1,6 @@ import chalk from "chalk"; import dayjs from "dayjs"; +import fs from "fs"; import type { ApplicationDefinition, @@ -305,16 +306,16 @@ describe("Logger", () => { }); }); - it("fatal uses error", async () => { - const spy = vi.spyOn(globalThis.console, "error").mockImplementation(() => {}); + it("fatal writes to stdout", async () => { + const spy = vi.spyOn(fs, "writeSync").mockImplementation(() => 0); vi.spyOn(globalThis.console, "debug").mockImplementation(() => {}); vi.spyOn(globalThis.console, "log").mockImplementation(() => {}); await TestRunner() .emitLogs() .run(({ logger }) => { - vi.clearAllMocks(); + spy.mockClear(); logger.fatal(`test`); - expect(spy).toHaveBeenCalled(); + expect(spy).toHaveBeenCalledWith(process.stdout.fd, expect.stringContaining("test")); }); }); diff --git a/testing/wiring.spec.mts b/testing/wiring.spec.mts index 94d518fe..1507bf7d 100644 --- a/testing/wiring.spec.mts +++ b/testing/wiring.spec.mts @@ -590,8 +590,8 @@ describe("Bootstrap", () => { showExtraBootStats: true, }); expect(spy).toHaveBeenCalledWith( - "boilerplate:wiring", expect.objectContaining({ + context: "boilerplate:wiring", Bootstrap: expect.any(String), Configure: expect.any(String), PostConfig: expect.any(String), @@ -617,16 +617,16 @@ describe("Bootstrap", () => { customLogger: mockLogger, }); expect(spy).toHaveBeenCalledWith( - "boilerplate:wiring", expect.objectContaining({ + context: "boilerplate:wiring", Total: expect.any(String), }), "[%s] application bootstrapped", "app", ); expect(spy).not.toHaveBeenCalledWith( - "boilerplate:wiring", expect.objectContaining({ + context: "boilerplate:wiring", Ready: expect.any(String), }), "[%s] application bootstrapped",