From 5c8e98c85f65a7b0ae0829988fbb5c8f193ea488 Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Mon, 15 Apr 2024 14:38:32 +0100 Subject: [PATCH 01/10] refactor: abstracted common logging functionality --- .../logging/__tests__/logger.test.ts | 24 +++++------- src/common/logging/index.ts | 3 ++ src/{plugin => common}/logging/log-level.ts | 0 src/{plugin => common}/logging/log-target.ts | 0 src/{plugin => common}/logging/logger.ts | 10 +++-- src/plugin/__tests__/connection.test.ts | 5 ++- src/plugin/__tests__/i18n.test.ts | 4 +- src/plugin/__tests__/index.test.ts | 2 +- src/plugin/logging/__mocks__/index.ts | 4 +- .../logging/__tests__/file-target.test.ts | 2 +- src/plugin/logging/__tests__/index.test.ts | 37 ++++++++++--------- src/plugin/logging/file-target.ts | 3 +- src/plugin/logging/index.ts | 7 ++-- 13 files changed, 52 insertions(+), 49 deletions(-) rename src/{plugin => common}/logging/__tests__/logger.test.ts (96%) create mode 100644 src/common/logging/index.ts rename src/{plugin => common}/logging/log-level.ts (100%) rename src/{plugin => common}/logging/log-target.ts (100%) rename src/{plugin => common}/logging/logger.ts (96%) diff --git a/src/plugin/logging/__tests__/logger.test.ts b/src/common/logging/__tests__/logger.test.ts similarity index 96% rename from src/plugin/logging/__tests__/logger.test.ts rename to src/common/logging/__tests__/logger.test.ts index 4a9afe59..ab49ab72 100644 --- a/src/plugin/logging/__tests__/logger.test.ts +++ b/src/common/logging/__tests__/logger.test.ts @@ -1,19 +1,15 @@ -import * as utils from "../../common/utils"; import { LogLevel } from "../log-level"; import { LogEntry, LogTarget } from "../log-target"; import { Logger, LoggerOptions } from "../logger"; -jest.mock("../../common/utils"); - describe("Logger", () => { - afterEach(() => jest.resetAllMocks()); - /** * Asserts the {@link Logger} clones options on construction. */ it("Clones options on construction", () => { // Arrange. const options: LoggerOptions = { + isDebugMode: false, level: LogLevel.ERROR, target: { write: jest.fn() } }; @@ -40,10 +36,9 @@ describe("Logger", () => { describe("Formats with unscoped log entires", () => { it.each([[undefined], [""], [" "]])("When scope is '%s'", (scope) => { // Arrange. - jest.spyOn(utils, "isDebugMode").mockReturnValue(true); - const target = { write: jest.fn() }; const logger = new Logger({ + isDebugMode: true, level: LogLevel.TRACE, scope, target @@ -123,10 +118,9 @@ describe("Logger", () => { } ])("When scopes are $scopes", ({ scopes, expectedPrefix }) => { // Arrange. - jest.spyOn(utils, "isDebugMode").mockReturnValue(true); - const target = { write: jest.fn() }; const parent = new Logger({ + isDebugMode: true, level: LogLevel.TRACE, target }); @@ -247,10 +241,9 @@ describe("Logger", () => { */ function verify(act: (logger: Logger) => void, expectLog: boolean) { // Arrange. - jest.spyOn(utils, "isDebugMode").mockReturnValue(true); - const target = { write: jest.fn() }; const logger = new Logger({ + isDebugMode: true, level, target }); @@ -270,6 +263,7 @@ describe("Logger", () => { it("Inherited by scoped loggers", () => { // Arrange. const parent = new Logger({ + isDebugMode: false, level: LogLevel.ERROR, target: { write: jest.fn() } }); @@ -294,6 +288,7 @@ describe("Logger", () => { it("Inherited from parents with defined log-level", () => { // Arrange. const parent = new Logger({ + isDebugMode: false, level: LogLevel.ERROR, target: { write: jest.fn() } }); @@ -317,6 +312,7 @@ describe("Logger", () => { it("Defaults when set to undefined", () => { // Arrange. const parent = new Logger({ + isDebugMode: false, level: LogLevel.ERROR, target: { write: jest.fn() } }); @@ -409,9 +405,8 @@ describe("Logger", () => { describe("Construction", () => { it.each(testCases)("$name when isDebugMode is $isDebugMode", ({ level, expected, isDebugMode }) => { // Arrange. - jest.spyOn(utils, "isDebugMode").mockReturnValue(isDebugMode); - const options: LoggerOptions = { + isDebugMode, level, target: { write: jest.fn() } }; @@ -440,9 +435,8 @@ describe("Logger", () => { describe("setLevel", () => { it.each(testCases)("$name when isDebugMode is $isDebugMode", ({ level, expected, isDebugMode }) => { // Arrange. - jest.spyOn(utils, "isDebugMode").mockReturnValue(isDebugMode); - const options: LoggerOptions = { + isDebugMode, level: LogLevel.ERROR, target: { write: jest.fn() } }; diff --git a/src/common/logging/index.ts b/src/common/logging/index.ts new file mode 100644 index 00000000..52c43633 --- /dev/null +++ b/src/common/logging/index.ts @@ -0,0 +1,3 @@ +export * from "./log-level"; +export * from "./log-target"; +export * from "./logger"; diff --git a/src/plugin/logging/log-level.ts b/src/common/logging/log-level.ts similarity index 100% rename from src/plugin/logging/log-level.ts rename to src/common/logging/log-level.ts diff --git a/src/plugin/logging/log-target.ts b/src/common/logging/log-target.ts similarity index 100% rename from src/plugin/logging/log-target.ts rename to src/common/logging/log-target.ts diff --git a/src/plugin/logging/logger.ts b/src/common/logging/logger.ts similarity index 96% rename from src/plugin/logging/logger.ts rename to src/common/logging/logger.ts index 09750bf9..897a13f4 100644 --- a/src/plugin/logging/logger.ts +++ b/src/common/logging/logger.ts @@ -1,4 +1,3 @@ -import { isDebugMode } from "../common/utils"; import { LogLevel } from "./log-level"; import type { LogTarget } from "./log-target"; @@ -100,7 +99,7 @@ export class Logger { * @returns This instance for chaining. */ public setLevel(level?: LogLevel): this { - if ((level === LogLevel.DEBUG || level === LogLevel.TRACE) && !isDebugMode()) { + if ((level === LogLevel.DEBUG || level === LogLevel.TRACE) && !this.options.isDebugMode) { this._level = LogLevel.INFO; this.warn(`Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.`); } else { @@ -155,7 +154,12 @@ export class Logger { */ export type LoggerOptions = { /** - * Minimum log-level required for a log message to be written. + * Indicates whether the current context is running in debug mode. + */ + isDebugMode: boolean; + + /** + * Determines the minimum level of logs that can be written. */ level: LogLevel | (() => LogLevel); diff --git a/src/plugin/__tests__/connection.test.ts b/src/plugin/__tests__/connection.test.ts index b79e1516..b440afb3 100644 --- a/src/plugin/__tests__/connection.test.ts +++ b/src/plugin/__tests__/connection.test.ts @@ -3,9 +3,8 @@ import type { RegistrationInfo } from ".."; import type { ApplicationDidLaunch, DidReceiveGlobalSettings, OpenUrl } from "../../api"; import type { Settings } from "../../api/__mocks__/events"; import { registrationInfo } from "../../api/registration/__mocks__"; +import { LogLevel, Logger } from "../../common/logging"; import { type connection as Connection } from "../connection"; -import { LogLevel } from "../logging/log-level"; -import { Logger } from "../logging/logger"; jest.mock("ws"); jest.mock("../logging"); @@ -25,6 +24,7 @@ describe("connection", () => { // Re-import the connection to ensure a fresh state. beforeEach(async () => { connectionLogger = new Logger({ + isDebugMode: false, level: LogLevel.TRACE, target: { write: jest.fn() } }); @@ -299,6 +299,7 @@ describe("connection", () => { it("logs arguments", () => { // Arrange const scopedLogger = new Logger({ + isDebugMode: false, level: LogLevel.TRACE, target: { write: jest.fn() } }); diff --git a/src/plugin/__tests__/i18n.test.ts b/src/plugin/__tests__/i18n.test.ts index 409aaa62..0bbe1900 100644 --- a/src/plugin/__tests__/i18n.test.ts +++ b/src/plugin/__tests__/i18n.test.ts @@ -1,9 +1,8 @@ import fs, { Dirent } from "node:fs"; import path from "node:path"; +import { LogLevel, Logger } from "../../common/logging"; import { I18nProvider } from "../i18n"; import { logger } from "../logging"; -import { LogLevel } from "../logging/log-level"; -import { Logger } from "../logging/logger"; jest.mock("../logging"); @@ -31,6 +30,7 @@ describe("I18nProvider", () => { beforeEach(() => { scopedLogger = new Logger({ + isDebugMode: false, level: LogLevel.TRACE, target: { write: jest.fn } }); diff --git a/src/plugin/__tests__/index.test.ts b/src/plugin/__tests__/index.test.ts index 3bd34cf0..c910ca26 100644 --- a/src/plugin/__tests__/index.test.ts +++ b/src/plugin/__tests__/index.test.ts @@ -1,12 +1,12 @@ import { BarSubType, DeviceType, Target } from "../../api"; import { EventEmitter } from "../../common/event-emitter"; +import { LogLevel } from "../../common/logging"; import { Action } from "../actions/action"; import { SingletonAction } from "../actions/singleton-action"; import { connection } from "../connection"; import { I18nProvider } from "../i18n"; import streamDeckAsDefaultExport, { streamDeck } from "../index"; import { logger } from "../logging"; -import { LogLevel } from "../logging/log-level"; jest.mock("../logging"); jest.mock("../manifest"); diff --git a/src/plugin/logging/__mocks__/index.ts b/src/plugin/logging/__mocks__/index.ts index 8f5724e3..740298c9 100644 --- a/src/plugin/logging/__mocks__/index.ts +++ b/src/plugin/logging/__mocks__/index.ts @@ -1,7 +1,7 @@ -import { LogLevel } from "../log-level"; -import { Logger, type LoggerOptions } from "../logger"; +import { LogLevel, Logger, type LoggerOptions } from "../../../common/logging"; const options: LoggerOptions = { + isDebugMode: false, level: LogLevel.TRACE, target: { write: jest.fn() } }; diff --git a/src/plugin/logging/__tests__/file-target.test.ts b/src/plugin/logging/__tests__/file-target.test.ts index 3d14047e..5e5f894e 100644 --- a/src/plugin/logging/__tests__/file-target.test.ts +++ b/src/plugin/logging/__tests__/file-target.test.ts @@ -2,8 +2,8 @@ import fs, { Dirent } from "node:fs"; import { EOL } from "node:os"; import path from "node:path"; +import { LogLevel } from "../../../common/logging"; import { FileTarget, FileTargetOptions } from "../file-target"; -import { LogLevel } from "../log-level"; jest.mock("node:fs"); diff --git a/src/plugin/logging/__tests__/index.test.ts b/src/plugin/logging/__tests__/index.test.ts index ec9c23dc..e023c9bd 100644 --- a/src/plugin/logging/__tests__/index.test.ts +++ b/src/plugin/logging/__tests__/index.test.ts @@ -1,25 +1,26 @@ import path from "node:path"; -import * as utils from "../../common/utils"; +import { LogLevel, type LoggerOptions } from "../../../common/logging"; import { type FileTargetOptions } from "../file-target"; -import { LogLevel } from "../log-level"; -import { type LoggerOptions } from "../logger"; - -jest.mock("../../common/utils", () => { - return { - get: jest.fn(), - getPluginUUID: jest.fn().mockReturnValue("com.elgato.test"), - isDebugMode: jest.fn() - } satisfies typeof import("../../common/utils"); -}); jest.mock("../file-target"); -jest.mock("../logger"); +jest.mock("../../../common/logging"); +jest.mock("../../common/utils"); describe("createLogger", () => { const mockedCwd = path.join("stream-deck", "tests"); + let utils: typeof import("../../common/utils"); + + beforeEach(async () => { + jest.spyOn(process, "cwd").mockReturnValue(mockedCwd); - beforeEach(() => jest.spyOn(process, "cwd").mockReturnValue(mockedCwd)); - afterEach(() => jest.resetModules()); + utils = await require("../../common/utils"); + jest.spyOn(utils, "getPluginUUID").mockReturnValue("com.elgato.test"); + }); + + afterEach(() => { + jest.resetModules(); + jest.resetAllMocks(); + }); describe("default log level", () => { /** @@ -29,7 +30,7 @@ describe("createLogger", () => { // Arrange. jest.spyOn(utils, "isDebugMode").mockReturnValue(true); const spyOnFileTarget = jest.spyOn(await require("../file-target"), "FileTarget"); - const { Logger } = await require("../logger"); + const { Logger } = await require("../../../common/logging"); // Act. await require("../index"); @@ -37,6 +38,7 @@ describe("createLogger", () => { // Assert. expect(spyOnFileTarget).toHaveBeenCalledTimes(1); expect(Logger).toHaveBeenCalledWith<[LoggerOptions]>({ + isDebugMode: true, level: LogLevel.DEBUG, target: spyOnFileTarget.mock.instances[0] }); @@ -49,13 +51,14 @@ describe("createLogger", () => { // Arrange. jest.spyOn(utils, "isDebugMode").mockReturnValue(false); const spyOnFileTarget = jest.spyOn(await require("../file-target"), "FileTarget"); - const { Logger } = await require("../logger"); + const { Logger } = await require("../../../common/logging"); // Act. await require("../index"); // Assert. expect(Logger).toHaveBeenCalledWith<[LoggerOptions]>({ + isDebugMode: false, level: LogLevel.INFO, target: spyOnFileTarget.mock.instances[0] }); @@ -103,7 +106,7 @@ describe("createLogger", () => { }); /** - * Asserts the exports of "../logger". + * Asserts the exports of "./index". */ describe("exports", () => { test("LogLevel", async () => { diff --git a/src/plugin/logging/file-target.ts b/src/plugin/logging/file-target.ts index 0a61d4d1..78e617dd 100644 --- a/src/plugin/logging/file-target.ts +++ b/src/plugin/logging/file-target.ts @@ -2,8 +2,7 @@ import fs, { Dirent } from "node:fs"; import { EOL } from "node:os"; import path from "node:path"; -import { LogLevel } from "./log-level"; -import type { LogEntry, LogTarget } from "./log-target"; +import { LogLevel, type LogEntry, type LogTarget } from "../../common/logging"; /** * Provides a {@link LogTarget} capable of logging to a local file system. diff --git a/src/plugin/logging/index.ts b/src/plugin/logging/index.ts index 35197d5e..c62c9def 100644 --- a/src/plugin/logging/index.ts +++ b/src/plugin/logging/index.ts @@ -1,13 +1,11 @@ import path from "node:path"; import { cwd } from "node:process"; +import { LogLevel, Logger } from "../../common/logging"; import { getPluginUUID, isDebugMode } from "../common/utils"; import { FileTarget } from "./file-target"; -import { LogLevel } from "./log-level"; -import { Logger } from "./logger"; -export { LogLevel } from "./log-level"; -export { Logger } from "./logger"; +export { LogLevel, Logger } from "../../common/logging"; // Log all entires to a log file. const target = new FileTarget({ @@ -22,6 +20,7 @@ const target = new FileTarget({ * @returns The default {@link Logger}. */ export const logger = new Logger({ + isDebugMode: isDebugMode(), level: isDebugMode() ? LogLevel.DEBUG : LogLevel.INFO, target }); From 5262443c8bac2a3cc1948db68bc5a7772697edb0 Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Mon, 15 Apr 2024 17:27:18 +0100 Subject: [PATCH 02/10] feat: decouple message formatter from file target --- src/common/logging/__tests__/logger.test.ts | 151 ++++++---------- src/common/logging/index.ts | 4 +- src/common/logging/{log-level.ts => level.ts} | 0 src/common/logging/log-target.ts | 32 ---- src/common/logging/logger.ts | 64 +++---- src/common/logging/target.ts | 44 +++++ .../logging/__tests__/file-target.test.ts | 162 ++++++------------ src/plugin/logging/__tests__/index.test.ts | 2 + .../__tests__/node-util-formatter.test.ts | 135 +++++++++++++++ src/plugin/logging/file-target.ts | 26 ++- src/plugin/logging/index.ts | 2 + src/plugin/logging/node-util-formatter.ts | 43 +++++ 12 files changed, 367 insertions(+), 298 deletions(-) rename src/common/logging/{log-level.ts => level.ts} (100%) delete mode 100644 src/common/logging/log-target.ts create mode 100644 src/common/logging/target.ts create mode 100644 src/plugin/logging/__tests__/node-util-formatter.test.ts create mode 100644 src/plugin/logging/node-util-formatter.ts diff --git a/src/common/logging/__tests__/logger.test.ts b/src/common/logging/__tests__/logger.test.ts index ab49ab72..0b05845f 100644 --- a/src/common/logging/__tests__/logger.test.ts +++ b/src/common/logging/__tests__/logger.test.ts @@ -1,6 +1,6 @@ -import { LogLevel } from "../log-level"; -import { LogEntry, LogTarget } from "../log-target"; +import { LogLevel } from "../level"; import { Logger, LoggerOptions } from "../logger"; +import { LogEntry, LogTarget } from "../target"; describe("Logger", () => { /** @@ -25,98 +25,38 @@ describe("Logger", () => { expect(options.level).toBe(LogLevel.ERROR); expect(options.target.write).toHaveBeenCalledTimes(1); expect(options.target.write).toHaveBeenCalledWith<[LogEntry]>({ + data: ["Hello world"], level: LogLevel.INFO, - message: "Hello world" + scope: "" }); }); /** - * Asserts {@link Logger} correctly formats an empty name when writing messages. + * Asserts {@link Logger} correctly supplies all log entry data. */ - describe("Formats with unscoped log entires", () => { - it.each([[undefined], [""], [" "]])("When scope is '%s'", (scope) => { - // Arrange. - const target = { write: jest.fn() }; - const logger = new Logger({ - isDebugMode: true, - level: LogLevel.TRACE, - scope, - target - }); - - // Act. - logger.error("Log error", new Error("error")); - logger.warn("Log warn", new Error("warn")); - logger.info("Log info", new Error("info")); - logger.debug("Log debug", new Error("debug")); - logger.trace("Log trace", new Error("trace")); - - // Assert. - expect(target.write).toHaveBeenCalledTimes(5); - expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(1, { - level: LogLevel.ERROR, - message: "Log error", - error: expect.objectContaining({ - message: "error" - }) - }); - - expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(2, { - level: LogLevel.WARN, - message: "Log warn", - error: expect.objectContaining({ - message: "warn" - }) - }); - - expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(3, { - level: LogLevel.INFO, - message: "Log info", - error: expect.objectContaining({ - message: "info" - }) - }); - - expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(4, { - level: LogLevel.DEBUG, - message: "Log debug", - error: expect.objectContaining({ - message: "debug" - }) - }); - - expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(5, { - level: LogLevel.TRACE, - message: "Log trace", - error: expect.objectContaining({ - message: "trace" - }) - }); - }); - }); - - /** - * Asserts {@link Logger} correctly formats scoped entries. - */ - describe("Formats scoped log entries", () => { + describe("Supplies all log entry data", () => { it.each([ + { + scopes: [], + scope: "" + }, { scopes: ["Foo "], - expectedPrefix: "Foo: " + scope: "Foo" }, { scopes: ["Foo", " "], - expectedPrefix: "Foo: " + scope: "Foo" }, { scopes: [" Hello", "World"], - expectedPrefix: "Hello->World: " + scope: "Hello->World" }, { scopes: ["One", " Two ", "Three"], - expectedPrefix: "One->Two->Three: " + scope: "One->Two->Three" } - ])("When scopes are $scopes", ({ scopes, expectedPrefix }) => { + ])("When scopes are $scopes", ({ scopes, scope }) => { // Arrange. const target = { write: jest.fn() }; const parent = new Logger({ @@ -138,42 +78,57 @@ describe("Logger", () => { expect(target.write).toHaveBeenCalledTimes(5); expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(1, { level: LogLevel.ERROR, - message: `${expectedPrefix}Log error`, - error: expect.objectContaining({ - message: "error" - }) + data: [ + "Log error", + expect.objectContaining({ + message: "error" + }) + ], + scope }); expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(2, { level: LogLevel.WARN, - message: `${expectedPrefix}Log warn`, - error: expect.objectContaining({ - message: "warn" - }) + data: [ + "Log warn", + expect.objectContaining({ + message: "warn" + }) + ], + scope }); expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(3, { level: LogLevel.INFO, - message: `${expectedPrefix}Log info`, - error: expect.objectContaining({ - message: "info" - }) + data: [ + "Log info", + expect.objectContaining({ + message: "info" + }) + ], + scope }); expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(4, { level: LogLevel.DEBUG, - message: `${expectedPrefix}Log debug`, - error: expect.objectContaining({ - message: "debug" - }) + data: [ + "Log debug", + expect.objectContaining({ + message: "debug" + }) + ], + scope }); expect(target.write).toHaveBeenNthCalledWith<[LogEntry]>(5, { level: LogLevel.TRACE, - message: `${expectedPrefix}Log trace`, - error: expect.objectContaining({ - message: "trace" - }) + data: [ + "Log trace", + expect.objectContaining({ + message: "trace" + }) + ], + scope }); }); }); @@ -423,7 +378,8 @@ describe("Logger", () => { expect(options.target.write).toHaveBeenCalledTimes(1); expect(options.target.write).toHaveBeenCalledWith<[LogEntry]>({ level: LogLevel.WARN, - message: `Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.` + data: [`Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.`], + scope: "" }); } }); @@ -455,7 +411,8 @@ describe("Logger", () => { expect(options.target.write).toHaveBeenCalledTimes(1); expect(options.target.write).toHaveBeenCalledWith<[LogEntry]>({ level: LogLevel.WARN, - message: `Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.` + data: [`Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.`], + scope: "" }); } }); diff --git a/src/common/logging/index.ts b/src/common/logging/index.ts index 52c43633..7a06f253 100644 --- a/src/common/logging/index.ts +++ b/src/common/logging/index.ts @@ -1,3 +1,3 @@ -export * from "./log-level"; -export * from "./log-target"; +export * from "./level"; export * from "./logger"; +export * from "./target"; diff --git a/src/common/logging/log-level.ts b/src/common/logging/level.ts similarity index 100% rename from src/common/logging/log-level.ts rename to src/common/logging/level.ts diff --git a/src/common/logging/log-target.ts b/src/common/logging/log-target.ts deleted file mode 100644 index 6961ca35..00000000 --- a/src/common/logging/log-target.ts +++ /dev/null @@ -1,32 +0,0 @@ -import { LogLevel } from "./log-level"; - -/** - * A log target capable of capturing a log entry, e.g. to the file system, console, etc. - */ -export type LogTarget = { - /** - * Writes the specified {@link entry} to the log target. - * @param entry The log entry to write. - */ - write(entry: LogEntry): void; -}; - -/** - * Defines a log entry to be logged to a {@link LogTarget}. - */ -export type LogEntry = { - /** - * Log level that indicates the severity of the log being written. - */ - level: LogLevel; - - /** - * Message associated with the log entry, aka the log. - */ - message: string; - - /** - * Optional error provided to be written as part of the log. - */ - error?: Error | unknown; -}; diff --git a/src/common/logging/logger.ts b/src/common/logging/logger.ts index 897a13f4..568d5a26 100644 --- a/src/common/logging/logger.ts +++ b/src/common/logging/logger.ts @@ -1,5 +1,5 @@ -import { LogLevel } from "./log-level"; -import type { LogTarget } from "./log-target"; +import { LogLevel } from "./level"; +import type { LogEntryData, LogTarget } from "./target"; /** * Logger capable of forwarding messages to a {@link LogTarget}. @@ -26,7 +26,7 @@ export class Logger { */ constructor(opts: LoggerOptions) { this.options = { ...opts }; - this.scope = this.options.scope === undefined || this.options.scope.trim() === "" ? "" : `${this.options.scope}: `; + this.scope = this.options.scope === undefined || this.options.scope.trim() === "" ? "" : this.options.scope; if (typeof this.options.level !== "function") { this.setLevel(this.options.level); @@ -64,33 +64,30 @@ export class Logger { } /** - * Writes a debug log {@link message}. - * @param message Message to write to the log. - * @param error Optional error to log with the {@link message}. + * Writes the arguments as a debug log entry. + * @param data Message or data to log. * @returns This instance for chaining. */ - public debug(message: string, error?: Error | unknown): this { - return this.log(LogLevel.DEBUG, message, error); + public debug(...data: LogEntryData): this { + return this.log(LogLevel.DEBUG, ...data); } /** - * Writes an error log {@link message}. - * @param message Message to write to the log. - * @param error Optional error to log with the {@link message}. + * Writes the arguments as error log entry. + * @param data Message or data to log. * @returns This instance for chaining. */ - public error(message: string, error?: Error | unknown): this { - return this.log(LogLevel.ERROR, message, error); + public error(...data: LogEntryData): this { + return this.log(LogLevel.ERROR, ...data); } /** - * Writes an info log {@link message}. - * @param message Message to write to the log. - * @param error Optional error to log with the {@link message}. + * Writes the arguments as an info log entry. + * @param data Message or data to log. * @returns This instance for chaining. */ - public info(message: string, error?: Error | unknown): this { - return this.log(LogLevel.INFO, message, error); + public info(...data: LogEntryData): this { + return this.log(LogLevel.INFO, ...data); } /** @@ -110,39 +107,32 @@ export class Logger { } /** - * Write a trace log {@link message}. - * @param message Message to write to the log. - * @param error Optional error to log with the {@link message}. + * Writes the arguments as a trace log entry. + * @param data Message or data to log. * @returns This instance for chaining. */ - public trace(message: string, error?: Error | unknown): this { - return this.log(LogLevel.TRACE, message, error); + public trace(...data: LogEntryData): this { + return this.log(LogLevel.TRACE, ...data); } /** - * Writes a warning log {@link message}. - * @param message Message to write to the log. - * @param error Optional error to log with the {@link message}. + * Writes the arguments as a warning log entry. + * @param data Message or data to log. * @returns This instance for chaining. */ - public warn(message: string, error?: Error | unknown): this { - return this.log(LogLevel.WARN, message, error); + public warn(...data: LogEntryData): this { + return this.log(LogLevel.WARN, ...data); } /** - * Writes a log {@link message} with the specified {@link level}. + * Writes a log entry. * @param level Log level of the message, printed as part of the overall log message. - * @param message Message to write to the log. - * @param error Optional error to log with the {@link message}. + * @param data Message or data to log. * @returns This instance for chaining. */ - private log(level: LogLevel, message: string, error?: Error | unknown): this { + private log(level: LogLevel, ...data: LogEntryData): this { if (level <= this.level) { - this.options.target.write({ - level, - message: `${this.scope}${message}`, - error - }); + this.options.target.write({ data, level, scope: this.scope }); } return this; diff --git a/src/common/logging/target.ts b/src/common/logging/target.ts new file mode 100644 index 00000000..750c564d --- /dev/null +++ b/src/common/logging/target.ts @@ -0,0 +1,44 @@ +import { LogLevel } from "./level"; + +/** + * A log target capable of capturing a log entry, e.g. to the file system, console, etc. + */ +export type LogTarget = { + /** + * Writes the specified log entry to the target. + * @param entry The log entry to write. + */ + write(entry: LogEntry): void; +}; + +/** + * Defines a log entry to be logged to a {@link LogTarget}. + */ +export type LogEntry = { + /** + * Data to log. + */ + data: unknown[] | [string, ...unknown[]]; + + /** + * Log level that indicates the severity of the log being written. + */ + level: LogLevel; + + /** + * Scope of the log entry. + */ + scope: string; +}; + +/** + * Data to log. + */ +export type LogEntryData = unknown[] | [string, ...unknown[]]; + +/** + * Formats the specified entry. + * @param entry Log entry to format. + * @returns The formatted log entry as a `string`. + */ +export type LogEntryFormatter = (entry: LogEntry) => string; diff --git a/src/plugin/logging/__tests__/file-target.test.ts b/src/plugin/logging/__tests__/file-target.test.ts index 5e5f894e..bb671b5e 100644 --- a/src/plugin/logging/__tests__/file-target.test.ts +++ b/src/plugin/logging/__tests__/file-target.test.ts @@ -1,5 +1,4 @@ import fs, { Dirent } from "node:fs"; -import { EOL } from "node:os"; import path from "node:path"; import { LogLevel } from "../../../common/logging"; @@ -8,108 +7,46 @@ import { FileTarget, FileTargetOptions } from "../file-target"; jest.mock("node:fs"); describe("FileTarget", () => { - const mockedDate = new Date(2000, 11, 25, 10, 30, 0, 123); - const mockedFileDescriptor = 13; - - beforeEach(() => jest.useFakeTimers().setSystemTime(mockedDate)); afterEach(() => jest.resetAllMocks()); - describe("Writing to file", () => { - const testCases = [ - { - name: "ERROR", - level: LogLevel.ERROR, - expectedMessage: `2000-12-25T10:30:00.123Z ERROR Hello world${EOL}` - }, - { - name: "WARN", - level: LogLevel.WARN, - expectedMessage: `2000-12-25T10:30:00.123Z WARN Hello world${EOL}` - }, - { - name: "INFO", - level: LogLevel.INFO, - expectedMessage: `2000-12-25T10:30:00.123Z INFO Hello world${EOL}` - }, - { - name: "DEBUG", - level: LogLevel.DEBUG, - expectedMessage: `2000-12-25T10:30:00.123Z DEBUG Hello world${EOL}` - }, - { - name: "TRACE", - level: LogLevel.TRACE, - expectedMessage: `2000-12-25T10:30:00.123Z TRACE Hello world${EOL}` - } - ]; - - /** - * Asserts {@link FileTarget.write} writes the formatted log message to the file. - */ - it.each(testCases)("$name message", async ({ level, expectedMessage }) => { - // Arrange. - jest.spyOn(fs, "existsSync").mockReturnValue(false); - jest.spyOn(fs, "openSync").mockReturnValue(mockedFileDescriptor); - - const options: FileTargetOptions = { - dest: path.join("home", "test", "logs"), - fileName: "com.elgato.test", - maxFileCount: 1, - maxSize: 1024 * 10 * 10 - }; - const fileTarget = new FileTarget(options); - - // Act. - fileTarget.write({ - level, - message: "Hello world" - }); - - // Assert. - expect(fs.openSync).toHaveBeenCalledTimes(1); - expect(fs.openSync).toHaveBeenNthCalledWith(1, path.join(options.dest, "com.elgato.test.0.log"), "a"); - expect(fs.writeSync).toHaveBeenCalledTimes(1); - expect(fs.writeSync).toHaveBeenCalledWith(mockedFileDescriptor, expectedMessage); - expect(fs.closeSync).toHaveBeenCalledTimes(1); - expect(fs.closeSync).toHaveBeenCalledWith(mockedFileDescriptor); - }); - - /** - * Asserts {@link FileTarget.write} writes the formatted log message, including the error, to the file. - */ - it.each(testCases)("$name message, with error", async ({ level, expectedMessage }) => { - // Arrange. - jest.spyOn(fs, "existsSync").mockReturnValue(false); - jest.spyOn(fs, "openSync").mockReturnValue(mockedFileDescriptor); - - const options: FileTargetOptions = { - dest: path.join("home", "tests", "logs"), - fileName: "com.elgato.test", - maxFileCount: 1, - maxSize: 1024 * 10 * 10 - }; - - const fileTarget = new FileTarget(options); - - const error = new Error("Hello world, this is a test"); - - // Act. - fileTarget.write({ - level, - message: "Hello world", - error - }); - - // Assert. - expect(fs.openSync).toHaveBeenCalledTimes(1); - expect(fs.openSync).toHaveBeenNthCalledWith(1, path.join(options.dest, "com.elgato.test.0.log"), "a"); - expect(fs.writeSync).toHaveBeenCalledTimes(3); - expect(fs.writeSync).toHaveBeenNthCalledWith(1, mockedFileDescriptor, expectedMessage); - expect(fs.writeSync).toHaveBeenNthCalledWith(2, mockedFileDescriptor, `Hello world, this is a test${EOL}`); - expect(fs.writeSync).toHaveBeenNthCalledWith(3, mockedFileDescriptor, `${(error).stack}${EOL}`); - expect(fs.closeSync).toHaveBeenCalledTimes(1); - expect(fs.closeSync).toHaveBeenCalledWith(mockedFileDescriptor); - }); + /** + * Asserts {@link FileTarget.write} writes the formatted log message to the file. + */ + it("writes the formatted message", async () => { + // Arrange. + const mockedFileDescriptor = 13; + + jest.spyOn(fs, "existsSync").mockReturnValue(false); + jest.spyOn(fs, "openSync").mockReturnValue(mockedFileDescriptor); + const format = jest.fn().mockReturnValue("Hello world"); + + const options: FileTargetOptions = { + dest: path.join("home", "test", "logs"), + fileName: "com.elgato.test", + format, + maxFileCount: 1, + maxSize: 1024 * 10 * 10 + }; + const fileTarget = new FileTarget(options); + + // Act. + const entry = { + level: LogLevel.INFO, + data: ["Hello world"], + scope: "Test->Logger" + }; + + fileTarget.write(entry); + + // Assert. + expect(format).toHaveBeenCalledTimes(1); + expect(format).toHaveBeenCalledWith(entry); + expect(fs.openSync).toHaveBeenCalledTimes(1); + expect(fs.openSync).toHaveBeenNthCalledWith(1, path.join(options.dest, "com.elgato.test.0.log"), "a"); + expect(fs.writeSync).toHaveBeenCalledTimes(1); + expect(fs.writeSync).toHaveBeenCalledWith(mockedFileDescriptor, "Hello world"); + expect(fs.closeSync).toHaveBeenCalledTimes(1); + expect(fs.closeSync).toHaveBeenCalledWith(mockedFileDescriptor); }); describe("Re-indexing", () => { @@ -133,6 +70,7 @@ describe("FileTarget", () => { const options: FileTargetOptions = { dest: path.join("home", "test", "logs"), fileName: "com.elgato.test", + format: jest.fn(), maxFileCount: 3, maxSize: 100 }; @@ -164,27 +102,23 @@ describe("FileTarget", () => { const options: FileTargetOptions = { dest: path.join("home", "test", "logs"), fileName: "com.elgato.test", + format: jest.fn().mockReturnValue("x".repeat(10)), maxFileCount: 3, - maxSize: 50 + maxSize: 29 }; const fileTarget = new FileTarget(options); // Act. - fileTarget.write({ + const entry = { level: LogLevel.ERROR, - message: "Hello world (1)" - }); - - fileTarget.write({ - level: LogLevel.ERROR, - message: "Hello world (2)" - }); + data: [], + scope: "" + }; - fileTarget.write({ - level: LogLevel.ERROR, - message: "Hello world (3)" - }); + fileTarget.write(entry); + fileTarget.write(entry); + fileTarget.write(entry); expect(fs.rmSync).toHaveBeenCalledTimes(1); expect(fs.rmSync).toHaveBeenLastCalledWith(path.join(options.dest, "com.elgato.test.2.log")); diff --git a/src/plugin/logging/__tests__/index.test.ts b/src/plugin/logging/__tests__/index.test.ts index e023c9bd..007d5579 100644 --- a/src/plugin/logging/__tests__/index.test.ts +++ b/src/plugin/logging/__tests__/index.test.ts @@ -72,6 +72,7 @@ describe("createLogger", () => { // Arrange. jest.spyOn(utils, "isDebugMode").mockReturnValue(false); const { FileTarget } = await require("../file-target"); + const { format } = await require("../node-util-formatter"); // Act. await require("../index"); @@ -80,6 +81,7 @@ describe("createLogger", () => { expect(FileTarget).toHaveBeenLastCalledWith<[FileTargetOptions]>({ dest: path.join(mockedCwd, "logs"), fileName: "com.elgato.test", + format, maxFileCount: 10, maxSize: 50 * 1024 * 1024 }); diff --git a/src/plugin/logging/__tests__/node-util-formatter.test.ts b/src/plugin/logging/__tests__/node-util-formatter.test.ts new file mode 100644 index 00000000..3d94e67a --- /dev/null +++ b/src/plugin/logging/__tests__/node-util-formatter.test.ts @@ -0,0 +1,135 @@ +import { EOL } from "node:os"; +import { LogLevel } from "../../../common/logging"; +import { format } from "../node-util-formatter"; + +describe("format", () => { + const mockedDate = new Date(2000, 11, 25, 10, 30, 0, 123); + const mockedDateString = "2000-12-25T10:30:00.123Z"; + + beforeEach(() => jest.useFakeTimers().setSystemTime(mockedDate)); + + describe("aggregating data", () => { + /** + * Asserts {@link format} aggregates the data. + */ + it("without error", () => { + // Arrange, act. + const actual = format({ + data: ["Hello", "World", { foo: "bar" }, true], + level: LogLevel.INFO, + scope: "Test" + }); + + // Assert. + expect(actual).toEqual(`${mockedDateString} INFO Test: Hello World { foo: 'bar' } true${EOL}`); + }); + + /** + * Asserts {@link format} aggregates data when one of the parameters is an error. + */ + it("with error", () => { + // Arrange, act. + const err = new Error("I am the error"); + const actual = format({ + data: ["Encountered an error", err, true], + level: LogLevel.INFO, + scope: "" + }); + + expect(actual).toEqual(`${mockedDateString} INFO Encountered an error ${EOL}${err.stack} ${EOL}true${EOL}`); + }); + }); + + describe("log each level", () => { + /** + * Asserts {@link format} for each log-level, without a scope. + */ + describe("without scope", () => { + const testCases = [ + { + name: "ERROR", + level: LogLevel.ERROR, + expected: `${mockedDateString} ERROR Hello world${EOL}` + }, + { + name: "WARN", + level: LogLevel.WARN, + expected: `${mockedDateString} WARN Hello world${EOL}` + }, + { + name: "INFO", + level: LogLevel.INFO, + expected: `${mockedDateString} INFO Hello world${EOL}` + }, + { + name: "DEBUG", + level: LogLevel.DEBUG, + expected: `${mockedDateString} DEBUG Hello world${EOL}` + }, + { + name: "TRACE", + level: LogLevel.TRACE, + expected: `${mockedDateString} TRACE Hello world${EOL}` + } + ]; + + it.each(testCases)("$name message", ({ level, expected }) => { + // Arrange, act. + const actual = format({ + data: ["Hello world"], + level, + scope: "" + }); + + // Assert. + expect(actual).toEqual(expected); + }); + }); + + /** + * Asserts {@link format} for each log-level, with a scope. + */ + describe("with scope", () => { + const scope = "Test->Logger"; + const testCases = [ + { + name: "ERROR", + level: LogLevel.ERROR, + expected: `${mockedDateString} ERROR ${scope}: Hello world${EOL}` + }, + { + name: "WARN", + level: LogLevel.WARN, + expected: `${mockedDateString} WARN ${scope}: Hello world${EOL}` + }, + { + name: "INFO", + level: LogLevel.INFO, + expected: `${mockedDateString} INFO ${scope}: Hello world${EOL}` + }, + { + name: "DEBUG", + level: LogLevel.DEBUG, + expected: `${mockedDateString} DEBUG ${scope}: Hello world${EOL}` + }, + { + name: "TRACE", + level: LogLevel.TRACE, + expected: `${mockedDateString} TRACE ${scope}: Hello world${EOL}` + } + ]; + + it.each(testCases)("$name message", ({ level, expected }) => { + // Arrange, act. + const actual = format({ + data: ["Hello world"], + level, + scope + }); + + // Assert. + expect(actual).toEqual(expected); + }); + }); + }); +}); diff --git a/src/plugin/logging/file-target.ts b/src/plugin/logging/file-target.ts index 78e617dd..a7e20af8 100644 --- a/src/plugin/logging/file-target.ts +++ b/src/plugin/logging/file-target.ts @@ -1,8 +1,7 @@ import fs, { Dirent } from "node:fs"; -import { EOL } from "node:os"; import path from "node:path"; -import { LogLevel, type LogEntry, type LogTarget } from "../../common/logging"; +import { type LogEntry, type LogEntryFormatter, type LogTarget } from "../../common/logging"; /** * Provides a {@link LogTarget} capable of logging to a local file system. @@ -30,23 +29,13 @@ export class FileTarget implements LogTarget { /** * @inheritdoc */ - public write({ level, message, error }: LogEntry): void { + public write(entry: LogEntry): void { const fd = fs.openSync(this.filePath, "a"); - const write = (message: string): void => { - fs.writeSync(fd, message); - this.size += message.length; - }; try { - write(`${new Date().toISOString()} ${LogLevel[level].padEnd(5)} ${message}${EOL}`); - if (error !== undefined) { - if (error instanceof Object && "message" in error && error.message && error.message !== "") { - write(`${error.message}${EOL}`); - } - if (error instanceof Object && "stack" in error && error.stack) { - write(`${error.stack}${EOL}`); - } - } + const msg = this.options.format(entry); + fs.writeSync(fd, msg); + this.size += msg.length; } finally { fs.closeSync(fd); } @@ -150,6 +139,11 @@ export type FileTargetOptions = { */ fileName: string; + /** + * Formatter responsible for formatting the log entry. + */ + format: LogEntryFormatter; + /** * Maximum number of files that can be created as part of the target before old logs should be truncated and removed. */ diff --git a/src/plugin/logging/index.ts b/src/plugin/logging/index.ts index c62c9def..d7deff89 100644 --- a/src/plugin/logging/index.ts +++ b/src/plugin/logging/index.ts @@ -4,6 +4,7 @@ import { cwd } from "node:process"; import { LogLevel, Logger } from "../../common/logging"; import { getPluginUUID, isDebugMode } from "../common/utils"; import { FileTarget } from "./file-target"; +import { format } from "./node-util-formatter"; export { LogLevel, Logger } from "../../common/logging"; @@ -11,6 +12,7 @@ export { LogLevel, Logger } from "../../common/logging"; const target = new FileTarget({ dest: path.join(cwd(), "logs"), fileName: getPluginUUID(), + format, maxFileCount: 10, maxSize: 50 * 1024 * 1024 }); diff --git a/src/plugin/logging/node-util-formatter.ts b/src/plugin/logging/node-util-formatter.ts new file mode 100644 index 00000000..793f0d37 --- /dev/null +++ b/src/plugin/logging/node-util-formatter.ts @@ -0,0 +1,43 @@ +import { EOL } from "node:os"; +import { inspect } from "node:util"; +import { LogLevel, type LogEntry } from "../../common/logging"; + +/** + * Formats the specified entry, stringify'ing data using `node:inspect`. + * @param entry Log entry to format. + * @returns The formatted log entry as a `string`. + */ +export function format(entry: LogEntry): string { + const { data, level, scope } = entry; + + let msg = `${new Date().toISOString()} ${LogLevel[level].padEnd(5)} `; + if (scope) { + msg += `${scope}: `; + } + + return `${msg}${toString(data)}${EOL}`; +} + +/** + * Stringifies the provided data parameters that make up the log entry. + * @param data Data parameters. + * @returns The data represented as a single `string`. + */ +function toString(data: unknown[]): string { + let result = ""; + let previousWasError = false; + + for (const value of data) { + if (typeof value === "object" && value instanceof Error) { + result += EOL; + previousWasError = true; + } else if (previousWasError) { + result += EOL; + previousWasError = false; + } + + result += `${typeof value === "object" ? inspect(value, false, null, false) : value} `; + } + + return result.trimEnd(); +} From ae71606d8f40a5fba0e23d17e0519628094ceb6c Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Mon, 15 Apr 2024 17:36:23 +0100 Subject: [PATCH 03/10] feat: update logger to allow multiple targets --- src/common/logging/__tests__/logger.test.ts | 63 +++++++++++++++------ src/common/logging/logger.ts | 6 +- src/plugin/__tests__/connection.test.ts | 4 +- src/plugin/__tests__/i18n.test.ts | 2 +- src/plugin/logging/__mocks__/index.ts | 2 +- src/plugin/logging/__tests__/index.test.ts | 4 +- src/plugin/logging/index.ts | 4 +- 7 files changed, 58 insertions(+), 27 deletions(-) diff --git a/src/common/logging/__tests__/logger.test.ts b/src/common/logging/__tests__/logger.test.ts index 0b05845f..5f28c116 100644 --- a/src/common/logging/__tests__/logger.test.ts +++ b/src/common/logging/__tests__/logger.test.ts @@ -11,7 +11,7 @@ describe("Logger", () => { const options: LoggerOptions = { isDebugMode: false, level: LogLevel.ERROR, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }; const logger = new Logger(options); @@ -23,14 +23,45 @@ describe("Logger", () => { // Assert expect(logger.level).toBe(LogLevel.INFO); expect(options.level).toBe(LogLevel.ERROR); - expect(options.target.write).toHaveBeenCalledTimes(1); - expect(options.target.write).toHaveBeenCalledWith<[LogEntry]>({ + expect(options.targets[0].write).toHaveBeenCalledTimes(1); + expect(options.targets[0].write).toHaveBeenCalledWith<[LogEntry]>({ data: ["Hello world"], level: LogLevel.INFO, scope: "" }); }); + /** + * Asserts {@link Logger.write} logs to all targets + */ + it("writes to all targets", () => { + // Arrange. + const options: LoggerOptions = { + isDebugMode: false, + level: LogLevel.INFO, + targets: [{ write: jest.fn() }, { write: jest.fn() }, { write: jest.fn() }] + }; + + const logger = new Logger(options); + + // Act. + logger.info("Hello world"); + + // Assert + const entry: LogEntry = { + data: ["Hello world"], + level: LogLevel.INFO, + scope: "" + }; + + expect(options.targets[0].write).toBeCalledTimes(1); + expect(options.targets[0].write).toHaveBeenCalledWith(entry); + expect(options.targets[1].write).toBeCalledTimes(1); + expect(options.targets[1].write).toHaveBeenCalledWith(entry); + expect(options.targets[2].write).toBeCalledTimes(1); + expect(options.targets[2].write).toHaveBeenCalledWith(entry); + }); + /** * Asserts {@link Logger} correctly supplies all log entry data. */ @@ -62,7 +93,7 @@ describe("Logger", () => { const parent = new Logger({ isDebugMode: true, level: LogLevel.TRACE, - target + targets: [target] }); const logger = scopes.reduce((prev, current) => prev.createScope(current), parent); @@ -200,7 +231,7 @@ describe("Logger", () => { const logger = new Logger({ isDebugMode: true, level, - target + targets: [target] }); // Act. @@ -220,7 +251,7 @@ describe("Logger", () => { const parent = new Logger({ isDebugMode: false, level: LogLevel.ERROR, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }); // Act. @@ -245,7 +276,7 @@ describe("Logger", () => { const parent = new Logger({ isDebugMode: false, level: LogLevel.ERROR, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }); // Act. @@ -269,7 +300,7 @@ describe("Logger", () => { const parent = new Logger({ isDebugMode: false, level: LogLevel.ERROR, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }); // Act (1). @@ -363,7 +394,7 @@ describe("Logger", () => { const options: LoggerOptions = { isDebugMode, level, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }; // Act. @@ -373,10 +404,10 @@ describe("Logger", () => { expect(logger.level).toBe(expected); if (level === expected) { - expect(options.target.write).toHaveBeenCalledTimes(0); + expect(options.targets[0].write).toHaveBeenCalledTimes(0); } else { - expect(options.target.write).toHaveBeenCalledTimes(1); - expect(options.target.write).toHaveBeenCalledWith<[LogEntry]>({ + expect(options.targets[0].write).toHaveBeenCalledTimes(1); + expect(options.targets[0].write).toHaveBeenCalledWith<[LogEntry]>({ level: LogLevel.WARN, data: [`Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.`], scope: "" @@ -394,7 +425,7 @@ describe("Logger", () => { const options: LoggerOptions = { isDebugMode, level: LogLevel.ERROR, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }; const logger = new Logger(options); @@ -406,10 +437,10 @@ describe("Logger", () => { expect(logger.level).toBe(expected); if (level === expected) { - expect(options.target.write).toHaveBeenCalledTimes(0); + expect(options.targets[0].write).toHaveBeenCalledTimes(0); } else { - expect(options.target.write).toHaveBeenCalledTimes(1); - expect(options.target.write).toHaveBeenCalledWith<[LogEntry]>({ + expect(options.targets[0].write).toHaveBeenCalledTimes(1); + expect(options.targets[0].write).toHaveBeenCalledWith<[LogEntry]>({ level: LogLevel.WARN, data: [`Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.`], scope: "" diff --git a/src/common/logging/logger.ts b/src/common/logging/logger.ts index 568d5a26..bd653915 100644 --- a/src/common/logging/logger.ts +++ b/src/common/logging/logger.ts @@ -132,7 +132,7 @@ export class Logger { */ private log(level: LogLevel, ...data: LogEntryData): this { if (level <= this.level) { - this.options.target.write({ data, level, scope: this.scope }); + this.options.targets.forEach((t) => t.write({ data, level, scope: this.scope })); } return this; @@ -159,7 +159,7 @@ export type LoggerOptions = { scope?: string; /** - * Log target that defines where log messages will be written. + * Log targets where logs will be written to. */ - target: LogTarget; + targets: LogTarget[]; }; diff --git a/src/plugin/__tests__/connection.test.ts b/src/plugin/__tests__/connection.test.ts index b440afb3..4d34f166 100644 --- a/src/plugin/__tests__/connection.test.ts +++ b/src/plugin/__tests__/connection.test.ts @@ -26,7 +26,7 @@ describe("connection", () => { connectionLogger = new Logger({ isDebugMode: false, level: LogLevel.TRACE, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }); ({ logger } = await require("../logging")); @@ -301,7 +301,7 @@ describe("connection", () => { const scopedLogger = new Logger({ isDebugMode: false, level: LogLevel.TRACE, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }); jest.spyOn(logger, "createScope").mockReturnValueOnce(scopedLogger); diff --git a/src/plugin/__tests__/i18n.test.ts b/src/plugin/__tests__/i18n.test.ts index 0bbe1900..5345222b 100644 --- a/src/plugin/__tests__/i18n.test.ts +++ b/src/plugin/__tests__/i18n.test.ts @@ -32,7 +32,7 @@ describe("I18nProvider", () => { scopedLogger = new Logger({ isDebugMode: false, level: LogLevel.TRACE, - target: { write: jest.fn } + targets: [{ write: jest.fn }] }); jest.spyOn(logger, "createScope").mockReturnValue(scopedLogger); diff --git a/src/plugin/logging/__mocks__/index.ts b/src/plugin/logging/__mocks__/index.ts index 740298c9..377a2d84 100644 --- a/src/plugin/logging/__mocks__/index.ts +++ b/src/plugin/logging/__mocks__/index.ts @@ -3,7 +3,7 @@ import { LogLevel, Logger, type LoggerOptions } from "../../../common/logging"; const options: LoggerOptions = { isDebugMode: false, level: LogLevel.TRACE, - target: { write: jest.fn() } + targets: [{ write: jest.fn() }] }; export { LogLevel, Logger }; diff --git a/src/plugin/logging/__tests__/index.test.ts b/src/plugin/logging/__tests__/index.test.ts index 007d5579..b0f511e6 100644 --- a/src/plugin/logging/__tests__/index.test.ts +++ b/src/plugin/logging/__tests__/index.test.ts @@ -40,7 +40,7 @@ describe("createLogger", () => { expect(Logger).toHaveBeenCalledWith<[LoggerOptions]>({ isDebugMode: true, level: LogLevel.DEBUG, - target: spyOnFileTarget.mock.instances[0] + targets: [spyOnFileTarget.mock.instances[0]] }); }); @@ -60,7 +60,7 @@ describe("createLogger", () => { expect(Logger).toHaveBeenCalledWith<[LoggerOptions]>({ isDebugMode: false, level: LogLevel.INFO, - target: spyOnFileTarget.mock.instances[0] + targets: [spyOnFileTarget.mock.instances[0]] }); }); }); diff --git a/src/plugin/logging/index.ts b/src/plugin/logging/index.ts index d7deff89..421243b9 100644 --- a/src/plugin/logging/index.ts +++ b/src/plugin/logging/index.ts @@ -9,7 +9,7 @@ import { format } from "./node-util-formatter"; export { LogLevel, Logger } from "../../common/logging"; // Log all entires to a log file. -const target = new FileTarget({ +const fileTarget = new FileTarget({ dest: path.join(cwd(), "logs"), fileName: getPluginUUID(), format, @@ -24,7 +24,7 @@ const target = new FileTarget({ export const logger = new Logger({ isDebugMode: isDebugMode(), level: isDebugMode() ? LogLevel.DEBUG : LogLevel.INFO, - target + targets: [fileTarget] }); process.once("uncaughtException", (err) => logger.error("Process encountered uncaught exception", err)); From 7bbe3b97ad24449f8057b82995acfb306c00cc4b Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Mon, 15 Apr 2024 18:40:07 +0100 Subject: [PATCH 04/10] feat: add console logger target --- .../logging/__tests__/console-target.ts | 68 +++++++++++++++++++ src/common/logging/console-target.ts | 25 +++++++ src/plugin/logging/__tests__/index.test.ts | 3 +- src/plugin/logging/index.ts | 11 ++- 4 files changed, 104 insertions(+), 3 deletions(-) create mode 100644 src/common/logging/__tests__/console-target.ts create mode 100644 src/common/logging/console-target.ts diff --git a/src/common/logging/__tests__/console-target.ts b/src/common/logging/__tests__/console-target.ts new file mode 100644 index 00000000..ba7f9e95 --- /dev/null +++ b/src/common/logging/__tests__/console-target.ts @@ -0,0 +1,68 @@ +import { ConsoleTarget } from "../console-target"; +import { LogLevel } from "../level"; + +describe("ConsoleTarget", () => { + /** + * Asserts {@link ConsoleTarget.write} logs to the error console. + */ + it("Error writes to error", () => { + // Arrange. + const target = new ConsoleTarget(); + const spyOnConsoleError = jest.spyOn(console, "error"); + + // Act. + target.write({ + data: ["Hello world"], + level: LogLevel.ERROR, + scope: "Test" + }); + + // Assert. + expect(spyOnConsoleError).toHaveBeenCalledTimes(1); + expect(spyOnConsoleError).toHaveBeenCalledWith("Hello world"); + }); + + /** + * Asserts {@link ConsoleTarget.write} logs to the warn console. + */ + it("Warn writes to warn", () => { + // Arrange. + const target = new ConsoleTarget(); + const spyOnConsoleWarn = jest.spyOn(console, "warn"); + + // Act. + target.write({ + data: ["Hello world"], + level: LogLevel.WARN, + scope: "Test" + }); + + // Assert. + expect(spyOnConsoleWarn).toHaveBeenCalledTimes(1); + expect(spyOnConsoleWarn).toHaveBeenCalledWith("Hello world"); + }); + + /** + * Asserts {@link ConsoleTarget.write} logs to the error console. + */ + it.each([ + { name: "Info", level: LogLevel.INFO }, + { name: "Debug", level: LogLevel.DEBUG }, + { name: "Trace", level: LogLevel.TRACE } + ])("$name writes to log", ({ level }) => { + // Arrange. + const target = new ConsoleTarget(); + const spyOnConsoleLog = jest.spyOn(console, "log"); + + // Act. + target.write({ + data: ["Hello world"], + level, + scope: "Test" + }); + + // Assert. + expect(spyOnConsoleLog).toHaveBeenCalledTimes(1); + expect(spyOnConsoleLog).toHaveBeenCalledWith("Hello world"); + }); +}); diff --git a/src/common/logging/console-target.ts b/src/common/logging/console-target.ts new file mode 100644 index 00000000..c31a9a1f --- /dev/null +++ b/src/common/logging/console-target.ts @@ -0,0 +1,25 @@ +import { LogLevel } from "."; +import type { LogEntry, LogTarget } from "./target"; + +/** + * Provides a {@link LogTarget} that logs to the console. + */ +export class ConsoleTarget implements LogTarget { + /** + * @inheritdoc + */ + public write(entry: LogEntry): void { + switch (entry.level) { + case LogLevel.ERROR: + console.error(...entry.data); + break; + + case LogLevel.WARN: + console.warn(...entry.data); + break; + + default: + console.log(...entry.data); + } + } +} diff --git a/src/plugin/logging/__tests__/index.test.ts b/src/plugin/logging/__tests__/index.test.ts index b0f511e6..5048b7ef 100644 --- a/src/plugin/logging/__tests__/index.test.ts +++ b/src/plugin/logging/__tests__/index.test.ts @@ -1,5 +1,6 @@ import path from "node:path"; import { LogLevel, type LoggerOptions } from "../../../common/logging"; +import { ConsoleTarget } from "../../../common/logging/console-target"; import { type FileTargetOptions } from "../file-target"; jest.mock("../file-target"); @@ -40,7 +41,7 @@ describe("createLogger", () => { expect(Logger).toHaveBeenCalledWith<[LoggerOptions]>({ isDebugMode: true, level: LogLevel.DEBUG, - targets: [spyOnFileTarget.mock.instances[0]] + targets: [expect.any(ConsoleTarget), spyOnFileTarget.mock.instances[0]] }); }); diff --git a/src/plugin/logging/index.ts b/src/plugin/logging/index.ts index 421243b9..586983c8 100644 --- a/src/plugin/logging/index.ts +++ b/src/plugin/logging/index.ts @@ -1,7 +1,8 @@ import path from "node:path"; import { cwd } from "node:process"; -import { LogLevel, Logger } from "../../common/logging"; +import { LogLevel, Logger, type LogTarget } from "../../common/logging"; +import { ConsoleTarget } from "../../common/logging/console-target"; import { getPluginUUID, isDebugMode } from "../common/utils"; import { FileTarget } from "./file-target"; import { format } from "./node-util-formatter"; @@ -17,6 +18,12 @@ const fileTarget = new FileTarget({ maxSize: 50 * 1024 * 1024 }); +// Construct the log targets. +const targets: LogTarget[] = [fileTarget]; +if (isDebugMode()) { + targets.splice(0, 0, new ConsoleTarget()); +} + /** * The default {@link Logger} for the current plugin based on its environment. * @returns The default {@link Logger}. @@ -24,7 +31,7 @@ const fileTarget = new FileTarget({ export const logger = new Logger({ isDebugMode: isDebugMode(), level: isDebugMode() ? LogLevel.DEBUG : LogLevel.INFO, - targets: [fileTarget] + targets }); process.once("uncaughtException", (err) => logger.error("Process encountered uncaught exception", err)); From 62aaefcc725de5096b83a823123574b709148459 Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Tue, 16 Apr 2024 14:02:10 +0100 Subject: [PATCH 05/10] feat: update string format to be cross compatible (node and browser) --- .../logging/__tests__/console-target.ts | 6 +- src/common/logging/__tests__/format.test.ts | 174 ++++++++++++++++++ src/common/logging/format.ts | 74 ++++++++ src/common/logging/index.ts | 1 + src/common/logging/target.ts | 7 - .../logging/__tests__/file-target.test.ts | 2 +- src/plugin/logging/__tests__/index.test.ts | 6 +- .../__tests__/node-util-formatter.test.ts | 135 -------------- src/plugin/logging/file-target.ts | 2 +- src/plugin/logging/index.ts | 5 +- src/plugin/logging/node-util-formatter.ts | 43 ----- 11 files changed, 259 insertions(+), 196 deletions(-) create mode 100644 src/common/logging/__tests__/format.test.ts create mode 100644 src/common/logging/format.ts delete mode 100644 src/plugin/logging/__tests__/node-util-formatter.test.ts delete mode 100644 src/plugin/logging/node-util-formatter.ts diff --git a/src/common/logging/__tests__/console-target.ts b/src/common/logging/__tests__/console-target.ts index ba7f9e95..f5af6efd 100644 --- a/src/common/logging/__tests__/console-target.ts +++ b/src/common/logging/__tests__/console-target.ts @@ -8,7 +8,7 @@ describe("ConsoleTarget", () => { it("Error writes to error", () => { // Arrange. const target = new ConsoleTarget(); - const spyOnConsoleError = jest.spyOn(console, "error"); + const spyOnConsoleError = jest.spyOn(console, "error").mockImplementationOnce(() => jest.fn()); // Act. target.write({ @@ -28,7 +28,7 @@ describe("ConsoleTarget", () => { it("Warn writes to warn", () => { // Arrange. const target = new ConsoleTarget(); - const spyOnConsoleWarn = jest.spyOn(console, "warn"); + const spyOnConsoleWarn = jest.spyOn(console, "warn").mockImplementationOnce(() => jest.fn()); // Act. target.write({ @@ -52,7 +52,7 @@ describe("ConsoleTarget", () => { ])("$name writes to log", ({ level }) => { // Arrange. const target = new ConsoleTarget(); - const spyOnConsoleLog = jest.spyOn(console, "log"); + const spyOnConsoleLog = jest.spyOn(console, "log").mockImplementationOnce(() => jest.fn()); // Act. target.write({ diff --git a/src/common/logging/__tests__/format.test.ts b/src/common/logging/__tests__/format.test.ts new file mode 100644 index 00000000..e64ee6a6 --- /dev/null +++ b/src/common/logging/__tests__/format.test.ts @@ -0,0 +1,174 @@ +import { LogLevel } from "../../../common/logging"; +import { stringFormatter } from "../format"; + +describe("stringFormatter", () => { + describe("data only", () => { + /** + * Asserts {@link stringFormatter} aggregates the data. + */ + test("without error", () => { + // Arrange, act. + const format = stringFormatter({ dataOnly: true }); + const actual = format({ + data: ["Hello", "World", { foo: "bar" }, true], + level: LogLevel.INFO, + scope: "Test" + }); + + // Assert. + expect(actual).toEqual(`Hello World {"foo":"bar"} true`); + }); + + /** + * Asserts {@link stringFormatter} aggregates data when one of the parameters is an error. + */ + test("with error", () => { + // Arrange, act. + const err = new Error("I am the error"); + const format = stringFormatter({ dataOnly: true }); + const actual = format({ + data: ["Encountered an error", err, true], + level: LogLevel.INFO, + scope: "" + }); + + expect(actual).toEqual(`Encountered an error \n${err.stack}\ntrue`); + }); + }); + + describe("full", () => { + const mockedDate = new Date(2000, 11, 25, 10, 30, 0, 123); + const mockedDateString = "2000-12-25T10:30:00.123Z"; + + beforeEach(() => jest.useFakeTimers().setSystemTime(mockedDate)); + + describe("aggregating data", () => { + /** + * Asserts {@link stringFormatter} aggregates the data. + */ + it("without error", () => { + // Arrange, act. + const format = stringFormatter(); + const actual = format({ + data: ["Hello", "World", { foo: "bar" }, true], + level: LogLevel.INFO, + scope: "Test" + }); + + // Assert. + expect(actual).toEqual(`${mockedDateString} INFO Test: Hello World {"foo":"bar"} true`); + }); + + /** + * Asserts {@link stringFormatter} aggregates data when one of the parameters is an error. + */ + it("with error", () => { + // Arrange, act. + const err = new Error("I am the error"); + const format = stringFormatter(); + const actual = format({ + data: ["Encountered an error", err, true], + level: LogLevel.INFO, + scope: "" + }); + + expect(actual).toEqual(`${mockedDateString} INFO Encountered an error \n${err.stack}\ntrue`); + }); + }); + + describe("log each level", () => { + /** + * Asserts {@link stringFormatter} for each log-level, without a scope. + */ + describe("without scope", () => { + const testCases = [ + { + name: "ERROR", + level: LogLevel.ERROR, + expected: `${mockedDateString} ERROR Hello world` + }, + { + name: "WARN", + level: LogLevel.WARN, + expected: `${mockedDateString} WARN Hello world` + }, + { + name: "INFO", + level: LogLevel.INFO, + expected: `${mockedDateString} INFO Hello world` + }, + { + name: "DEBUG", + level: LogLevel.DEBUG, + expected: `${mockedDateString} DEBUG Hello world` + }, + { + name: "TRACE", + level: LogLevel.TRACE, + expected: `${mockedDateString} TRACE Hello world` + } + ]; + + it.each(testCases)("$name message", ({ level, expected }) => { + // Arrange, act. + const format = stringFormatter(); + const actual = format({ + data: ["Hello world"], + level, + scope: "" + }); + + // Assert. + expect(actual).toEqual(expected); + }); + }); + + /** + * Asserts {@link stringFormatter} for each log-level, with a scope. + */ + describe("with scope", () => { + const scope = "Test->Logger"; + const testCases = [ + { + name: "ERROR", + level: LogLevel.ERROR, + expected: `${mockedDateString} ERROR ${scope}: Hello world` + }, + { + name: "WARN", + level: LogLevel.WARN, + expected: `${mockedDateString} WARN ${scope}: Hello world` + }, + { + name: "INFO", + level: LogLevel.INFO, + expected: `${mockedDateString} INFO ${scope}: Hello world` + }, + { + name: "DEBUG", + level: LogLevel.DEBUG, + expected: `${mockedDateString} DEBUG ${scope}: Hello world` + }, + { + name: "TRACE", + level: LogLevel.TRACE, + expected: `${mockedDateString} TRACE ${scope}: Hello world` + } + ]; + + it.each(testCases)("$name message", ({ level, expected }) => { + // Arrange, act. + const format = stringFormatter(); + const actual = format({ + data: ["Hello world"], + level, + scope + }); + + // Assert. + expect(actual).toEqual(expected); + }); + }); + }); + }); +}); diff --git a/src/common/logging/format.ts b/src/common/logging/format.ts new file mode 100644 index 00000000..9d50e38f --- /dev/null +++ b/src/common/logging/format.ts @@ -0,0 +1,74 @@ +import { LogLevel, type LogEntry } from "../../common/logging"; + +// Remove any dependencies on node. +const EOL = "\n"; + +/** + * Formats the specified entry. + * @param entry Log entry to format. + * @returns The formatted log entry as a `string`. + */ +export type LogEntryFormatter = (entry: LogEntry) => string; + +/** + * Creates a new string log entry formatter. + * @param opts Options that defines the type for the formatter. + * @returns The string {@link LogEntryFormatter}. + */ +export function stringFormatter(opts?: StringFormatOptions): LogEntryFormatter { + if (opts?.dataOnly) { + return ({ data }) => `${reduce(data)}`; + } else { + return (entry: LogEntry) => { + const { data, level, scope } = entry; + + let prefix = `${new Date().toISOString()} ${LogLevel[level].padEnd(5)} `; + if (scope) { + prefix += `${scope}: `; + } + + return `${prefix}${reduce(data)}`; + }; + } +} + +/** + * Options associated with {@link stringFormatter}. + */ +type StringFormatOptions = { + /** + * Indicates whether the entry should only log the {@link LogEntry.data}. + */ + dataOnly?: boolean; +}; + +/** + * Stringifies the provided data parameters that make up the log entry. + * @param data Data parameters. + * @returns The data represented as a single `string`. + */ +function reduce(data: unknown[]): string { + let result = ""; + let previousWasError = false; + + for (const value of data) { + // When the value is an error, write the stack. + if (typeof value === "object" && value instanceof Error) { + result += `${EOL}${value.stack}`; + previousWasError = true; + + continue; + } + + // When the previous was an error, write a new line. + if (previousWasError) { + result += EOL; + previousWasError = false; + } + + result += typeof value === "object" ? JSON.stringify(value) : value; + result += " "; + } + + return result.trimEnd(); +} diff --git a/src/common/logging/index.ts b/src/common/logging/index.ts index 7a06f253..75ab4ddc 100644 --- a/src/common/logging/index.ts +++ b/src/common/logging/index.ts @@ -1,3 +1,4 @@ +export * from "./format"; export * from "./level"; export * from "./logger"; export * from "./target"; diff --git a/src/common/logging/target.ts b/src/common/logging/target.ts index 750c564d..ca180005 100644 --- a/src/common/logging/target.ts +++ b/src/common/logging/target.ts @@ -35,10 +35,3 @@ export type LogEntry = { * Data to log. */ export type LogEntryData = unknown[] | [string, ...unknown[]]; - -/** - * Formats the specified entry. - * @param entry Log entry to format. - * @returns The formatted log entry as a `string`. - */ -export type LogEntryFormatter = (entry: LogEntry) => string; diff --git a/src/plugin/logging/__tests__/file-target.test.ts b/src/plugin/logging/__tests__/file-target.test.ts index bb671b5e..425c91a8 100644 --- a/src/plugin/logging/__tests__/file-target.test.ts +++ b/src/plugin/logging/__tests__/file-target.test.ts @@ -44,7 +44,7 @@ describe("FileTarget", () => { expect(fs.openSync).toHaveBeenCalledTimes(1); expect(fs.openSync).toHaveBeenNthCalledWith(1, path.join(options.dest, "com.elgato.test.0.log"), "a"); expect(fs.writeSync).toHaveBeenCalledTimes(1); - expect(fs.writeSync).toHaveBeenCalledWith(mockedFileDescriptor, "Hello world"); + expect(fs.writeSync).toHaveBeenCalledWith(mockedFileDescriptor, "Hello world\n"); expect(fs.closeSync).toHaveBeenCalledTimes(1); expect(fs.closeSync).toHaveBeenCalledWith(mockedFileDescriptor); }); diff --git a/src/plugin/logging/__tests__/index.test.ts b/src/plugin/logging/__tests__/index.test.ts index 5048b7ef..2e83da33 100644 --- a/src/plugin/logging/__tests__/index.test.ts +++ b/src/plugin/logging/__tests__/index.test.ts @@ -72,8 +72,8 @@ describe("createLogger", () => { it("initializes the file target from the cwd", async () => { // Arrange. jest.spyOn(utils, "isDebugMode").mockReturnValue(false); - const { FileTarget } = await require("../file-target"); - const { format } = await require("../node-util-formatter"); + const { FileTarget } = (await require("../file-target")) as typeof import("../file-target"); + const { stringFormatter } = (await require("../../../common/logging")) as typeof import("../../../common/logging"); // Act. await require("../index"); @@ -82,7 +82,7 @@ describe("createLogger", () => { expect(FileTarget).toHaveBeenLastCalledWith<[FileTargetOptions]>({ dest: path.join(mockedCwd, "logs"), fileName: "com.elgato.test", - format, + format: stringFormatter(), maxFileCount: 10, maxSize: 50 * 1024 * 1024 }); diff --git a/src/plugin/logging/__tests__/node-util-formatter.test.ts b/src/plugin/logging/__tests__/node-util-formatter.test.ts deleted file mode 100644 index 3d94e67a..00000000 --- a/src/plugin/logging/__tests__/node-util-formatter.test.ts +++ /dev/null @@ -1,135 +0,0 @@ -import { EOL } from "node:os"; -import { LogLevel } from "../../../common/logging"; -import { format } from "../node-util-formatter"; - -describe("format", () => { - const mockedDate = new Date(2000, 11, 25, 10, 30, 0, 123); - const mockedDateString = "2000-12-25T10:30:00.123Z"; - - beforeEach(() => jest.useFakeTimers().setSystemTime(mockedDate)); - - describe("aggregating data", () => { - /** - * Asserts {@link format} aggregates the data. - */ - it("without error", () => { - // Arrange, act. - const actual = format({ - data: ["Hello", "World", { foo: "bar" }, true], - level: LogLevel.INFO, - scope: "Test" - }); - - // Assert. - expect(actual).toEqual(`${mockedDateString} INFO Test: Hello World { foo: 'bar' } true${EOL}`); - }); - - /** - * Asserts {@link format} aggregates data when one of the parameters is an error. - */ - it("with error", () => { - // Arrange, act. - const err = new Error("I am the error"); - const actual = format({ - data: ["Encountered an error", err, true], - level: LogLevel.INFO, - scope: "" - }); - - expect(actual).toEqual(`${mockedDateString} INFO Encountered an error ${EOL}${err.stack} ${EOL}true${EOL}`); - }); - }); - - describe("log each level", () => { - /** - * Asserts {@link format} for each log-level, without a scope. - */ - describe("without scope", () => { - const testCases = [ - { - name: "ERROR", - level: LogLevel.ERROR, - expected: `${mockedDateString} ERROR Hello world${EOL}` - }, - { - name: "WARN", - level: LogLevel.WARN, - expected: `${mockedDateString} WARN Hello world${EOL}` - }, - { - name: "INFO", - level: LogLevel.INFO, - expected: `${mockedDateString} INFO Hello world${EOL}` - }, - { - name: "DEBUG", - level: LogLevel.DEBUG, - expected: `${mockedDateString} DEBUG Hello world${EOL}` - }, - { - name: "TRACE", - level: LogLevel.TRACE, - expected: `${mockedDateString} TRACE Hello world${EOL}` - } - ]; - - it.each(testCases)("$name message", ({ level, expected }) => { - // Arrange, act. - const actual = format({ - data: ["Hello world"], - level, - scope: "" - }); - - // Assert. - expect(actual).toEqual(expected); - }); - }); - - /** - * Asserts {@link format} for each log-level, with a scope. - */ - describe("with scope", () => { - const scope = "Test->Logger"; - const testCases = [ - { - name: "ERROR", - level: LogLevel.ERROR, - expected: `${mockedDateString} ERROR ${scope}: Hello world${EOL}` - }, - { - name: "WARN", - level: LogLevel.WARN, - expected: `${mockedDateString} WARN ${scope}: Hello world${EOL}` - }, - { - name: "INFO", - level: LogLevel.INFO, - expected: `${mockedDateString} INFO ${scope}: Hello world${EOL}` - }, - { - name: "DEBUG", - level: LogLevel.DEBUG, - expected: `${mockedDateString} DEBUG ${scope}: Hello world${EOL}` - }, - { - name: "TRACE", - level: LogLevel.TRACE, - expected: `${mockedDateString} TRACE ${scope}: Hello world${EOL}` - } - ]; - - it.each(testCases)("$name message", ({ level, expected }) => { - // Arrange, act. - const actual = format({ - data: ["Hello world"], - level, - scope - }); - - // Assert. - expect(actual).toEqual(expected); - }); - }); - }); -}); diff --git a/src/plugin/logging/file-target.ts b/src/plugin/logging/file-target.ts index a7e20af8..a3bf2d9f 100644 --- a/src/plugin/logging/file-target.ts +++ b/src/plugin/logging/file-target.ts @@ -34,7 +34,7 @@ export class FileTarget implements LogTarget { try { const msg = this.options.format(entry); - fs.writeSync(fd, msg); + fs.writeSync(fd, msg + "\n"); this.size += msg.length; } finally { fs.closeSync(fd); diff --git a/src/plugin/logging/index.ts b/src/plugin/logging/index.ts index 586983c8..68ca0d37 100644 --- a/src/plugin/logging/index.ts +++ b/src/plugin/logging/index.ts @@ -1,11 +1,10 @@ import path from "node:path"; import { cwd } from "node:process"; -import { LogLevel, Logger, type LogTarget } from "../../common/logging"; +import { LogLevel, Logger, stringFormatter, type LogTarget } from "../../common/logging"; import { ConsoleTarget } from "../../common/logging/console-target"; import { getPluginUUID, isDebugMode } from "../common/utils"; import { FileTarget } from "./file-target"; -import { format } from "./node-util-formatter"; export { LogLevel, Logger } from "../../common/logging"; @@ -13,7 +12,7 @@ export { LogLevel, Logger } from "../../common/logging"; const fileTarget = new FileTarget({ dest: path.join(cwd(), "logs"), fileName: getPluginUUID(), - format, + format: stringFormatter(), maxFileCount: 10, maxSize: 50 * 1024 * 1024 }); diff --git a/src/plugin/logging/node-util-formatter.ts b/src/plugin/logging/node-util-formatter.ts deleted file mode 100644 index 793f0d37..00000000 --- a/src/plugin/logging/node-util-formatter.ts +++ /dev/null @@ -1,43 +0,0 @@ -import { EOL } from "node:os"; -import { inspect } from "node:util"; -import { LogLevel, type LogEntry } from "../../common/logging"; - -/** - * Formats the specified entry, stringify'ing data using `node:inspect`. - * @param entry Log entry to format. - * @returns The formatted log entry as a `string`. - */ -export function format(entry: LogEntry): string { - const { data, level, scope } = entry; - - let msg = `${new Date().toISOString()} ${LogLevel[level].padEnd(5)} `; - if (scope) { - msg += `${scope}: `; - } - - return `${msg}${toString(data)}${EOL}`; -} - -/** - * Stringifies the provided data parameters that make up the log entry. - * @param data Data parameters. - * @returns The data represented as a single `string`. - */ -function toString(data: unknown[]): string { - let result = ""; - let previousWasError = false; - - for (const value of data) { - if (typeof value === "object" && value instanceof Error) { - result += EOL; - previousWasError = true; - } else if (previousWasError) { - result += EOL; - previousWasError = false; - } - - result += `${typeof value === "object" ? inspect(value, false, null, false) : value} `; - } - - return result.trimEnd(); -} From f775d17945c2e71bbb8575352af3e622fcf6860c Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Tue, 16 Apr 2024 18:27:55 +0100 Subject: [PATCH 06/10] fix: message responder not awaiting routed handler --- src/common/messaging/gateway.ts | 2 +- src/plugin/ui/__tests__/router.test.ts | 7 +++++-- src/ui/__tests__/plugin.test.ts | 7 +++++-- 3 files changed, 11 insertions(+), 5 deletions(-) diff --git a/src/common/messaging/gateway.ts b/src/common/messaging/gateway.ts index 06533c4e..3fb71de4 100644 --- a/src/common/messaging/gateway.ts +++ b/src/common/messaging/gateway.ts @@ -116,7 +116,7 @@ export class MessageGateway extends EventEmitter) => { if (options?.filter && options.filter(ev.request.action)) { - ev.routed(); + await ev.routed(); try { // Invoke the handler; when data was returned, propagate it as part of the response (if there wasn't already a response). diff --git a/src/plugin/ui/__tests__/router.test.ts b/src/plugin/ui/__tests__/router.test.ts index b5f3a37c..087d3a35 100644 --- a/src/plugin/ui/__tests__/router.test.ts +++ b/src/plugin/ui/__tests__/router.test.ts @@ -2,6 +2,7 @@ import { Action, MessageRequest, type MessageRequestOptions } from "../.."; import type { DidReceivePropertyInspectorMessage, SendToPropertyInspector } from "../../../api"; import type { RawMessageRequest } from "../../../common/messaging/message"; import { MessageResponder } from "../../../common/messaging/responder"; +import { PromiseCompletionSource } from "../../../common/promises"; import { connection } from "../../connection"; import { PropertyInspector } from "../property-inspector"; import { getCurrentUI, router } from "../router"; @@ -96,7 +97,7 @@ describe("router", () => { /** * Asserts {@link router} processed messages when the {@link connection} emits `sendToPlugin`. */ - it("processes", () => { + it("processes", async () => { // Arrange. const spyOnProcess = jest.spyOn(router, "process"); const ev = { @@ -114,11 +115,13 @@ describe("router", () => { } } satisfies DidReceivePropertyInspectorMessage; - const listener = jest.fn(); + const awaiter = new PromiseCompletionSource(); + const listener = jest.fn().mockImplementation(() => awaiter.setResult(true)); const disposable = router.route("/test", listener); // Act. connection.emit("sendToPlugin", ev); + await awaiter.promise; // Assert. expect(spyOnProcess).toBeCalledTimes(1); diff --git a/src/ui/__tests__/plugin.test.ts b/src/ui/__tests__/plugin.test.ts index 270ef34d..ebe5df72 100644 --- a/src/ui/__tests__/plugin.test.ts +++ b/src/ui/__tests__/plugin.test.ts @@ -7,6 +7,7 @@ import type { DidReceivePluginMessage, SendToPlugin } from "../../api"; import { actionInfo } from "../../api/registration/__mocks__"; import type { RawMessageRequest } from "../../common/messaging/message"; import { MessageResponder } from "../../common/messaging/responder"; +import { PromiseCompletionSource } from "../../common/promises"; import { connection } from "../connection"; import { plugin, router, type PluginController } from "../plugin"; import { getSettings, setSettings } from "../settings"; @@ -154,9 +155,10 @@ describe("plugin", () => { /** * Asserts {@link router} routes the request with a construct action. */ - it("receives request", () => { + it("receives request", async () => { // Arrange. - const listener = jest.fn(); + const awaiter = new PromiseCompletionSource(); + const listener = jest.fn().mockImplementation(() => awaiter.setResult(true)); const ev = { action: actionInfo.action, context: uuid, @@ -175,6 +177,7 @@ describe("plugin", () => { // Act. const disposable = plugin.registerRoute("/receive", listener); connection.emit("sendToPropertyInspector", ev); + await awaiter.promise; // Assert. expect(listener).toHaveBeenCalledTimes(1); From 4efb19b8b7dd6be321bda969c958848f810b22d8 Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Tue, 16 Apr 2024 18:28:15 +0100 Subject: [PATCH 07/10] fix: circular dependencies --- src/common/logging/format.ts | 3 ++- src/common/logging/logger.ts | 23 +++++++++++------------ 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/src/common/logging/format.ts b/src/common/logging/format.ts index 9d50e38f..ba137aa8 100644 --- a/src/common/logging/format.ts +++ b/src/common/logging/format.ts @@ -1,4 +1,5 @@ -import { LogLevel, type LogEntry } from "../../common/logging"; +import { LogLevel } from "./level"; +import { type LogEntry } from "./target"; // Remove any dependencies on node. const EOL = "\n"; diff --git a/src/common/logging/logger.ts b/src/common/logging/logger.ts index bd653915..e0687f3e 100644 --- a/src/common/logging/logger.ts +++ b/src/common/logging/logger.ts @@ -1,5 +1,5 @@ import { LogLevel } from "./level"; -import type { LogEntryData, LogTarget } from "./target"; +import type { LogEntry, LogEntryData, LogTarget } from "./target"; /** * Logger capable of forwarding messages to a {@link LogTarget}. @@ -69,7 +69,7 @@ export class Logger { * @returns This instance for chaining. */ public debug(...data: LogEntryData): this { - return this.log(LogLevel.DEBUG, ...data); + return this.write({ level: LogLevel.DEBUG, data, scope: this.scope }); } /** @@ -78,7 +78,7 @@ export class Logger { * @returns This instance for chaining. */ public error(...data: LogEntryData): this { - return this.log(LogLevel.ERROR, ...data); + return this.write({ level: LogLevel.ERROR, data, scope: this.scope }); } /** @@ -87,7 +87,7 @@ export class Logger { * @returns This instance for chaining. */ public info(...data: LogEntryData): this { - return this.log(LogLevel.INFO, ...data); + return this.write({ level: LogLevel.INFO, data, scope: this.scope }); } /** @@ -112,7 +112,7 @@ export class Logger { * @returns This instance for chaining. */ public trace(...data: LogEntryData): this { - return this.log(LogLevel.TRACE, ...data); + return this.write({ level: LogLevel.TRACE, data, scope: this.scope }); } /** @@ -121,18 +121,17 @@ export class Logger { * @returns This instance for chaining. */ public warn(...data: LogEntryData): this { - return this.log(LogLevel.WARN, ...data); + return this.write({ level: LogLevel.WARN, data, scope: this.scope }); } /** - * Writes a log entry. - * @param level Log level of the message, printed as part of the overall log message. - * @param data Message or data to log. + * Writes the log entry. + * @param entry Log entry to write. * @returns This instance for chaining. */ - private log(level: LogLevel, ...data: LogEntryData): this { - if (level <= this.level) { - this.options.targets.forEach((t) => t.write({ data, level, scope: this.scope })); + public write(entry: LogEntry): this { + if (entry.level <= this.level) { + this.options.targets.forEach((t) => t.write(entry)); } return this; From f73d33f7fc6812b83deadb5325ce50fa454382f7 Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Tue, 16 Apr 2024 20:05:06 +0100 Subject: [PATCH 08/10] feat: add logger to ui --- src/common/logging/index.ts | 1 + src/common/logging/routing.ts | 61 +++++++++++++++++++++++++++++++++++ src/plugin/index.ts | 3 ++ src/plugin/logging/index.ts | 3 +- src/ui/index.ts | 20 ++++++++---- src/ui/logging.ts | 12 +++++++ 6 files changed, 91 insertions(+), 9 deletions(-) create mode 100644 src/common/logging/routing.ts create mode 100644 src/ui/logging.ts diff --git a/src/common/logging/index.ts b/src/common/logging/index.ts index 75ab4ddc..81905729 100644 --- a/src/common/logging/index.ts +++ b/src/common/logging/index.ts @@ -1,4 +1,5 @@ export * from "./format"; export * from "./level"; export * from "./logger"; +export * from "./routing"; export * from "./target"; diff --git a/src/common/logging/routing.ts b/src/common/logging/routing.ts new file mode 100644 index 00000000..ff1dbd82 --- /dev/null +++ b/src/common/logging/routing.ts @@ -0,0 +1,61 @@ +import type { MessageGateway } from "../messaging"; +import { stringFormatter } from "./format"; +import type { Logger } from "./logger"; +import type { LogEntry, LogTarget } from "./target"; + +export const LOGGING_WRITE_ROUTE = "#internal:logger.write"; + +/** + * Creates a log target that that sends the log entry to the router. + * @param router Router to which log entries should be sent to. + * @returns The log target, attached to the router. + */ +export function createRoutedLogTarget(router: MessageGateway): LogTarget { + const format = stringFormatter({ dataOnly: true }); + + return { + write: (entry: LogEntry): void => { + router.fetch({ + body: { + level: entry.level, + message: format(entry), + scope: entry.scope + } satisfies JsonSafeLogEntry, + path: LOGGING_WRITE_ROUTE, + unidirectional: true + }); + } + }; +} + +/** + * Registers a route handler on the router, propagating any log entries to the specified logger for writing. + * @param router Router to receive inbound log entries on. + * @param logger Logger responsible for logging log entries. + */ +export function registerCreateLogEntryRoute(router: MessageGateway, logger: Logger): void { + router.route(LOGGING_WRITE_ROUTE, (req, res) => { + if (req.body === undefined) { + return res.fail(); + } + + const { level, message, scope } = req.body; + if (level === undefined || typeof level !== "number") { + logger.warn(`Unknown log entry level received from property inspector: ${level}`); + return res.fail(); + } + + logger.write({ level, data: [message], scope }); + return res.success(); + }); +} + +/** + * Defines a JSON safe {@link LogEntry}. + */ +export type JsonSafeLogEntry = Omit & { + /** + * The log message. + */ + message: string; +}; diff --git a/src/plugin/index.ts b/src/plugin/index.ts index c5c36bdf..bebbcc2f 100644 --- a/src/plugin/index.ts +++ b/src/plugin/index.ts @@ -30,6 +30,7 @@ export * from "./events"; export { LogLevel } from "./logging"; export { route, type MessageRequest, type PropertyInspector } from "./ui"; +import { registerCreateLogEntryRoute } from "../common/logging"; import * as actions from "./actions"; import { connection } from "./connection"; import { devices } from "./devices"; @@ -39,6 +40,7 @@ import * as profiles from "./profiles"; import * as settings from "./settings"; import * as system from "./system"; import { ui, type UIController } from "./ui"; +import { router } from "./ui/router"; let i18n: I18nProvider | undefined; @@ -132,4 +134,5 @@ export const streamDeck = { } }; +registerCreateLogEntryRoute(router, logger); export default streamDeck; diff --git a/src/plugin/logging/index.ts b/src/plugin/logging/index.ts index 68ca0d37..c14d2d86 100644 --- a/src/plugin/logging/index.ts +++ b/src/plugin/logging/index.ts @@ -24,8 +24,7 @@ if (isDebugMode()) { } /** - * The default {@link Logger} for the current plugin based on its environment. - * @returns The default {@link Logger}. + * Logger responsible for capturing log messages. */ export const logger = new Logger({ isDebugMode: isDebugMode(), diff --git a/src/ui/index.ts b/src/ui/index.ts index 7cd70d3e..0cb595e1 100644 --- a/src/ui/index.ts +++ b/src/ui/index.ts @@ -1,6 +1,7 @@ import { type ActionInfo, type RegistrationInfo } from "../api"; import type { IDisposable } from "../common/disposable"; import { connection } from "./connection"; +import { logger } from "./logging"; import { plugin } from "./plugin"; import * as settings from "./settings"; import * as system from "./system"; @@ -13,13 +14,9 @@ export { type MessageHandler, type MessageRequest } from "./plugin"; const streamDeck = { /** - * Occurs when the UI connects to the Stream Deck. - * @param listener Event handler function. - * @returns A disposable that removes the listener when disposed. + * Logger responsible for capturing log messages. */ - onDidConnect: (listener: (info: RegistrationInfo, actionInfo: ActionInfo) => void): IDisposable => { - return connection.disposableOn("connected", listener); - }, + logger, /** * Provides interaction with the plugin. @@ -34,7 +31,16 @@ const streamDeck = { /** * Provides events and methods for interacting with the system. */ - system + system, + + /** + * Occurs when the UI connects to the Stream Deck. + * @param listener Event handler function. + * @returns A disposable that removes the listener when disposed. + */ + onDidConnect: (listener: (info: RegistrationInfo, actionInfo: ActionInfo) => void): IDisposable => { + return connection.disposableOn("connected", listener); + } }; export default streamDeck; diff --git a/src/ui/logging.ts b/src/ui/logging.ts new file mode 100644 index 00000000..fa687668 --- /dev/null +++ b/src/ui/logging.ts @@ -0,0 +1,12 @@ +import { LogLevel, Logger, createRoutedLogTarget } from "../common/logging"; +import { ConsoleTarget } from "../common/logging/console-target"; +import { router } from "./plugin"; + +/** + * Logger responsible for capturing log messages. + */ +export const logger = new Logger({ + isDebugMode: true, + level: LogLevel.TRACE, + targets: [new ConsoleTarget(), createRoutedLogTarget(router)] +}); From 7b415779a4cb3d5ba0b38c1fb60dc9f5b390dc32 Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Wed, 17 Apr 2024 15:20:47 +0100 Subject: [PATCH 09/10] test: ui logger registration --- ...nsole-target.ts => console-target.test.ts} | 0 src/common/logging/__tests__/logger.test.ts | 66 ++++----- src/common/logging/__tests__/routing.test.ts | 131 ++++++++++++++++++ src/common/logging/index.ts | 1 + src/common/logging/routing.ts | 3 +- src/plugin/__tests__/index.test.ts | 2 + src/ui/__tests__/logging.test.ts | 26 ++++ src/ui/logging.ts | 3 +- 8 files changed, 195 insertions(+), 37 deletions(-) rename src/common/logging/__tests__/{console-target.ts => console-target.test.ts} (100%) create mode 100644 src/common/logging/__tests__/routing.test.ts create mode 100644 src/ui/__tests__/logging.test.ts diff --git a/src/common/logging/__tests__/console-target.ts b/src/common/logging/__tests__/console-target.test.ts similarity index 100% rename from src/common/logging/__tests__/console-target.ts rename to src/common/logging/__tests__/console-target.test.ts diff --git a/src/common/logging/__tests__/logger.test.ts b/src/common/logging/__tests__/logger.test.ts index 5f28c116..42e5cb0e 100644 --- a/src/common/logging/__tests__/logger.test.ts +++ b/src/common/logging/__tests__/logger.test.ts @@ -6,7 +6,7 @@ describe("Logger", () => { /** * Asserts the {@link Logger} clones options on construction. */ - it("Clones options on construction", () => { + it("clones options on construction", () => { // Arrange. const options: LoggerOptions = { isDebugMode: false, @@ -65,7 +65,7 @@ describe("Logger", () => { /** * Asserts {@link Logger} correctly supplies all log entry data. */ - describe("Supplies all log entry data", () => { + describe("supplies all log entry data", () => { it.each([ { scopes: [], @@ -167,57 +167,57 @@ describe("Logger", () => { /** * Asserts {@link Logger} only writes messages to the {@link LogTarget} when the log-level is allowed. */ - describe("Checks the log level before forwarding to target", () => { + describe("checks the log level before forwarding to target", () => { let level: LogLevel; describe("ERROR", () => { beforeAll(() => (level = LogLevel.ERROR)); - it("Does log ERROR", () => verify((logger) => logger.error("error"), true)); - it("Does not log WARN", () => verify((logger) => logger.warn("warn"), false)); - it("Does not log INFO", () => verify((logger) => logger.info("info"), false)); - it("Does not log DEBUG", () => verify((logger) => logger.debug("debug"), false)); - it("Does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); + it("does log ERROR", () => verify((logger) => logger.error("error"), true)); + it("does not log WARN", () => verify((logger) => logger.warn("warn"), false)); + it("does not log INFO", () => verify((logger) => logger.info("info"), false)); + it("does not log DEBUG", () => verify((logger) => logger.debug("debug"), false)); + it("does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); }); describe("WARN", () => { beforeAll(() => (level = LogLevel.WARN)); - it("Does log ERROR", () => verify((logger) => logger.error("error"), true)); - it("Does log WARN", () => verify((logger) => logger.warn("warn"), true)); - it("Does not log INFO", () => verify((logger) => logger.info("info"), false)); - it("Does not log DEBUG", () => verify((logger) => logger.debug("debug"), false)); - it("Does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); + it("does log ERROR", () => verify((logger) => logger.error("error"), true)); + it("does log WARN", () => verify((logger) => logger.warn("warn"), true)); + it("does not log INFO", () => verify((logger) => logger.info("info"), false)); + it("does not log DEBUG", () => verify((logger) => logger.debug("debug"), false)); + it("does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); }); describe("INFO", () => { beforeAll(() => (level = LogLevel.INFO)); - it("Does log ERROR", () => verify((logger) => logger.error("error"), true)); - it("Does log WARN", () => verify((logger) => logger.warn("warn"), true)); - it("Does log INFO", () => verify((logger) => logger.info("info"), true)); - it("Does not log DEBUG", () => verify((logger) => logger.debug("debug"), false)); - it("Does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); + it("does log ERROR", () => verify((logger) => logger.error("error"), true)); + it("does log WARN", () => verify((logger) => logger.warn("warn"), true)); + it("does log INFO", () => verify((logger) => logger.info("info"), true)); + it("does not log DEBUG", () => verify((logger) => logger.debug("debug"), false)); + it("does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); }); describe("DEBUG", () => { beforeAll(() => (level = LogLevel.DEBUG)); - it("Does log ERROR", () => verify((logger) => logger.error("error"), true)); - it("Does log WARN", () => verify((logger) => logger.warn("warn"), true)); - it("Does log INFO", () => verify((logger) => logger.info("info"), true)); - it("Does log DEBUG", () => verify((logger) => logger.debug("debug"), true)); - it("Does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); + it("does log ERROR", () => verify((logger) => logger.error("error"), true)); + it("does log WARN", () => verify((logger) => logger.warn("warn"), true)); + it("does log INFO", () => verify((logger) => logger.info("info"), true)); + it("does log DEBUG", () => verify((logger) => logger.debug("debug"), true)); + it("does not log TRACE", () => verify((logger) => logger.trace("trace"), false)); }); describe("TRACE", () => { beforeAll(() => (level = LogLevel.TRACE)); - it("Does log ERROR", () => verify((logger) => logger.error("error"), true)); - it("Does log WARN", () => verify((logger) => logger.warn("warn"), true)); - it("Does log INFO", () => verify((logger) => logger.info("info"), true)); - it("Does log DEBUG", () => verify((logger) => logger.debug("debug"), true)); - it("Does log TRACE", () => verify((logger) => logger.trace("trace"), true)); + it("does log ERROR", () => verify((logger) => logger.error("error"), true)); + it("does log WARN", () => verify((logger) => logger.warn("warn"), true)); + it("does log INFO", () => verify((logger) => logger.info("info"), true)); + it("does log DEBUG", () => verify((logger) => logger.debug("debug"), true)); + it("does log TRACE", () => verify((logger) => logger.trace("trace"), true)); }); /** @@ -246,7 +246,7 @@ describe("Logger", () => { /** * Asserts scoped {@link Logger} inherit the {@link LogLevel} of their parent. */ - it("Inherited by scoped loggers", () => { + it("inherited by scoped loggers", () => { // Arrange. const parent = new Logger({ isDebugMode: false, @@ -271,7 +271,7 @@ describe("Logger", () => { /** * Asserts scoped {@link Logger} inherit the {@link LogLevel} of their earliest parent that has an explicit {@link LogLevel} defined. */ - it("Inherited from parents with defined log-level", () => { + it("inherited from parents with defined log-level", () => { // Arrange. const parent = new Logger({ isDebugMode: false, @@ -295,7 +295,7 @@ describe("Logger", () => { /** * Asserts scoped {@link Logger} inherit the {@link LogLevel}, from their parent, when resetting the {@link LogLevel}. */ - it("Defaults when set to undefined", () => { + it("defaults when set to undefined", () => { // Arrange. const parent = new Logger({ isDebugMode: false, @@ -321,7 +321,7 @@ describe("Logger", () => { /** * Asserts validating the {@link LogLevel} can be set based on the environment. */ - describe("Log-level validation", () => { + describe("log-level validation", () => { const testCases = [ { isDebugMode: false, @@ -388,7 +388,7 @@ describe("Logger", () => { /** * Asserts the {@link Logger} validates the {@link LogLevel} on construction. */ - describe("Construction", () => { + describe("construction", () => { it.each(testCases)("$name when isDebugMode is $isDebugMode", ({ level, expected, isDebugMode }) => { // Arrange. const options: LoggerOptions = { diff --git a/src/common/logging/__tests__/routing.test.ts b/src/common/logging/__tests__/routing.test.ts new file mode 100644 index 00000000..554ad99d --- /dev/null +++ b/src/common/logging/__tests__/routing.test.ts @@ -0,0 +1,131 @@ +import type { LogEntry } from ".."; +import { MessageGateway, MessageResponder, type MessageRequestOptions } from "../../messaging"; +import { LogLevel } from "../level"; +import { Logger } from "../logger"; + +import { LOGGING_WRITE_ROUTE, createRoutedLogTarget, registerCreateLogEntryRoute, type JsonSafeLogEntry } from "../routing"; + +jest.mock("../../messaging"); + +describe("createRoutedLogTarget", () => { + it("sends log entry to router", () => { + // Arrange. + const router = new MessageGateway(jest.fn(), jest.fn()); + const target = createRoutedLogTarget(router); + + // Act. + target.write({ + data: ["Hello", "world"], + level: LogLevel.INFO, + scope: "Test" + }); + + // Assert. + expect(router.fetch).toHaveBeenCalledTimes(1); + expect(router.fetch).toHaveBeenCalledWith<[MessageRequestOptions]>({ + body: { + level: LogLevel.INFO, + message: "Hello world", + scope: "Test" + } satisfies JsonSafeLogEntry, + path: LOGGING_WRITE_ROUTE, + unidirectional: true + }); + }); +}); + +describe("registerCreateLogEntryRoute", () => { + describe("incomplete request", () => { + test("body is undefined", () => { + // Arrange. + const router = new MessageGateway(jest.fn(), jest.fn()); + const spyOnRoute = jest.spyOn(router, "route"); + const responder = new MessageResponder(null!, jest.fn()); + + // Act. + registerCreateLogEntryRoute(router, null!); + spyOnRoute.mock.calls[0][1]( + { + action: jest.fn(), + path: LOGGING_WRITE_ROUTE, + unidirectional: true, + body: undefined + }, + responder + ); + + // Assert. + expect(spyOnRoute).toHaveBeenCalledTimes(1); + expect(spyOnRoute).toHaveBeenCalledWith(LOGGING_WRITE_ROUTE, expect.any(Function)); + expect(responder.fail).toHaveBeenCalledTimes(1); + }); + + test("level is undefined", () => { + // Arrange. + const router = new MessageGateway(jest.fn(), jest.fn()); + const spyOnRoute = jest.spyOn(router, "route"); + const responder = new MessageResponder(null!, jest.fn()); + + // Act. + registerCreateLogEntryRoute(router, null!); + spyOnRoute.mock.calls[0][1]( + { + action: jest.fn(), + path: LOGGING_WRITE_ROUTE, + unidirectional: true, + body: { + level: undefined + } + }, + responder + ); + + // Assert. + expect(spyOnRoute).toHaveBeenCalledTimes(1); + expect(spyOnRoute).toHaveBeenCalledWith(LOGGING_WRITE_ROUTE, expect.any(Function)); + expect(responder.fail).toHaveBeenCalledTimes(1); + }); + }); + + it("should write to logger", () => { + // Arrange. + const router = new MessageGateway(jest.fn(), jest.fn()); + const spyOnRoute = jest.spyOn(router, "route"); + const responder = new MessageResponder(null!, jest.fn()); + + const logger = new Logger({ + level: LogLevel.INFO, + isDebugMode: true, + targets: [{ write: jest.fn() }] + }); + + const spyOnWrite = jest.spyOn(logger, "write"); + + // Act. + registerCreateLogEntryRoute(router, logger); + spyOnRoute.mock.calls[0][1]( + { + action: jest.fn(), + path: LOGGING_WRITE_ROUTE, + unidirectional: true, + body: { + level: LogLevel.WARN, + message: "Hello world", + scope: "Test" + } satisfies JsonSafeLogEntry + }, + responder + ); + + // Assert. + expect(spyOnRoute).toHaveBeenCalledTimes(1); + expect(spyOnRoute).toHaveBeenCalledWith(LOGGING_WRITE_ROUTE, expect.any(Function)); + expect(spyOnWrite).toHaveBeenCalledTimes(1); + expect(spyOnWrite).toHaveBeenCalledWith<[LogEntry]>({ + data: ["Hello world"], + level: LogLevel.WARN, + scope: "Test" + }); + expect(responder.success).toHaveBeenCalledTimes(1); + }); +}); diff --git a/src/common/logging/index.ts b/src/common/logging/index.ts index 81905729..1e2067fd 100644 --- a/src/common/logging/index.ts +++ b/src/common/logging/index.ts @@ -1,3 +1,4 @@ +export * from "./console-target"; export * from "./format"; export * from "./level"; export * from "./logger"; diff --git a/src/common/logging/routing.ts b/src/common/logging/routing.ts index ff1dbd82..c42d3e2c 100644 --- a/src/common/logging/routing.ts +++ b/src/common/logging/routing.ts @@ -40,8 +40,7 @@ export function registerCreateLogEntryRoute(router: MessageGateway, log } const { level, message, scope } = req.body; - if (level === undefined || typeof level !== "number") { - logger.warn(`Unknown log entry level received from property inspector: ${level}`); + if (level === undefined) { return res.fail(); } diff --git a/src/plugin/__tests__/index.test.ts b/src/plugin/__tests__/index.test.ts index c910ca26..53fbe81c 100644 --- a/src/plugin/__tests__/index.test.ts +++ b/src/plugin/__tests__/index.test.ts @@ -29,6 +29,7 @@ describe("index", () => { // Arrange. const actions = await require("../actions"); const { devices } = await require("../devices"); + const { getManifest } = await require("../manifest"); const profiles = await require("../profiles"); const settings = await require("../settings"); const system = await require("../system"); @@ -37,6 +38,7 @@ describe("index", () => { // Act, assert. expect(streamDeck.actions).toBe(actions); expect(streamDeck.devices).toBe(devices); + expect(streamDeck.manifest).toBe(getManifest()); expect(streamDeck.profiles).toBe(profiles); expect(streamDeck.settings).toBe(settings); expect(streamDeck.system).toBe(system); diff --git a/src/ui/__tests__/logging.test.ts b/src/ui/__tests__/logging.test.ts new file mode 100644 index 00000000..bfc57564 --- /dev/null +++ b/src/ui/__tests__/logging.test.ts @@ -0,0 +1,26 @@ +/** + * @jest-environment jsdom + */ + +import * as LoggingModule from "../../common/logging"; +import { router } from "../plugin"; + +jest.mock("../../common/logging"); +jest.mock("../plugin"); + +describe("Logging", () => { + it("constructs a logger", async () => { + // Arrange, act. + const spyOnLogger = jest.spyOn(LoggingModule, "Logger"); + const { logger } = (await require("../logging")) as typeof import("../logging"); + + // Assert. + expect(logger).toBe(spyOnLogger.mock.instances[0]); + expect(spyOnLogger).toHaveBeenCalledTimes(1); + expect(spyOnLogger).toHaveBeenCalledWith<[LoggingModule.LoggerOptions]>({ + isDebugMode: true, + level: LoggingModule.LogLevel.TRACE, + targets: [expect.any(LoggingModule.ConsoleTarget), LoggingModule.createRoutedLogTarget(router)] + }); + }); +}); diff --git a/src/ui/logging.ts b/src/ui/logging.ts index fa687668..70782e3f 100644 --- a/src/ui/logging.ts +++ b/src/ui/logging.ts @@ -1,5 +1,4 @@ -import { LogLevel, Logger, createRoutedLogTarget } from "../common/logging"; -import { ConsoleTarget } from "../common/logging/console-target"; +import { ConsoleTarget, LogLevel, Logger, createRoutedLogTarget } from "../common/logging"; import { router } from "./plugin"; /** From 61149acdaef2c8a83a310280d8b2b8b7cd8cab4f Mon Sep 17 00:00:00 2001 From: Richard Herman Date: Wed, 17 Apr 2024 15:47:52 +0100 Subject: [PATCH 10/10] refactor: remove isDebugMode from logger in favour of minimumLevel --- src/common/logging/__tests__/logger.test.ts | 37 +++++++++----------- src/common/logging/__tests__/routing.test.ts | 1 - src/common/logging/console-target.ts | 2 +- src/common/logging/logger.ts | 14 ++++---- src/plugin/__tests__/connection.test.ts | 2 -- src/plugin/__tests__/i18n.test.ts | 1 - src/plugin/logging/__mocks__/index.ts | 1 - src/plugin/logging/__tests__/index.test.ts | 4 +-- src/plugin/logging/index.ts | 2 +- src/ui/__tests__/logging.test.ts | 3 +- src/ui/logging.ts | 3 +- 11 files changed, 29 insertions(+), 41 deletions(-) diff --git a/src/common/logging/__tests__/logger.test.ts b/src/common/logging/__tests__/logger.test.ts index 42e5cb0e..6766a810 100644 --- a/src/common/logging/__tests__/logger.test.ts +++ b/src/common/logging/__tests__/logger.test.ts @@ -9,7 +9,6 @@ describe("Logger", () => { it("clones options on construction", () => { // Arrange. const options: LoggerOptions = { - isDebugMode: false, level: LogLevel.ERROR, targets: [{ write: jest.fn() }] }; @@ -37,7 +36,6 @@ describe("Logger", () => { it("writes to all targets", () => { // Arrange. const options: LoggerOptions = { - isDebugMode: false, level: LogLevel.INFO, targets: [{ write: jest.fn() }, { write: jest.fn() }, { write: jest.fn() }] }; @@ -91,8 +89,8 @@ describe("Logger", () => { // Arrange. const target = { write: jest.fn() }; const parent = new Logger({ - isDebugMode: true, level: LogLevel.TRACE, + minimumLevel: LogLevel.TRACE, targets: [target] }); @@ -229,8 +227,8 @@ describe("Logger", () => { // Arrange. const target = { write: jest.fn() }; const logger = new Logger({ - isDebugMode: true, level, + minimumLevel: LogLevel.TRACE, targets: [target] }); @@ -249,7 +247,6 @@ describe("Logger", () => { it("inherited by scoped loggers", () => { // Arrange. const parent = new Logger({ - isDebugMode: false, level: LogLevel.ERROR, targets: [{ write: jest.fn() }] }); @@ -274,7 +271,6 @@ describe("Logger", () => { it("inherited from parents with defined log-level", () => { // Arrange. const parent = new Logger({ - isDebugMode: false, level: LogLevel.ERROR, targets: [{ write: jest.fn() }] }); @@ -298,7 +294,6 @@ describe("Logger", () => { it("defaults when set to undefined", () => { // Arrange. const parent = new Logger({ - isDebugMode: false, level: LogLevel.ERROR, targets: [{ write: jest.fn() }] }); @@ -324,61 +319,61 @@ describe("Logger", () => { describe("log-level validation", () => { const testCases = [ { - isDebugMode: false, + minimumLevel: LogLevel.INFO, name: "Can be ERROR", level: LogLevel.ERROR, expected: LogLevel.ERROR }, { - isDebugMode: true, + minimumLevel: LogLevel.TRACE, name: "Can be ERROR", level: LogLevel.ERROR, expected: LogLevel.ERROR }, { - isDebugMode: false, + minimumLevel: LogLevel.INFO, name: "Can be WARN", level: LogLevel.WARN, expected: LogLevel.WARN }, { - isDebugMode: true, + minimumLevel: LogLevel.TRACE, name: "Can be WARN", level: LogLevel.WARN, expected: LogLevel.WARN }, { - isDebugMode: false, + minimumLevel: LogLevel.INFO, name: "Can be INFO", level: LogLevel.INFO, expected: LogLevel.INFO }, { - isDebugMode: true, + minimumLevel: LogLevel.TRACE, name: "Can be INFO", level: LogLevel.INFO, expected: LogLevel.INFO }, { - isDebugMode: false, + minimumLevel: LogLevel.INFO, name: "Cannot be DEBUG", level: LogLevel.DEBUG, expected: LogLevel.INFO }, { - isDebugMode: true, + minimumLevel: LogLevel.TRACE, name: "Can be DEBUG", level: LogLevel.DEBUG, expected: LogLevel.DEBUG }, { - isDebugMode: false, + minimumLevel: LogLevel.INFO, name: "Cannot be TRACE", level: LogLevel.TRACE, expected: LogLevel.INFO }, { - isDebugMode: true, + minimumLevel: LogLevel.TRACE, name: "Can be TRACE", level: LogLevel.TRACE, expected: LogLevel.TRACE @@ -389,11 +384,11 @@ describe("Logger", () => { * Asserts the {@link Logger} validates the {@link LogLevel} on construction. */ describe("construction", () => { - it.each(testCases)("$name when isDebugMode is $isDebugMode", ({ level, expected, isDebugMode }) => { + it.each(testCases)("$name when minimumLevel is $minimumLevel", ({ level, expected, minimumLevel }) => { // Arrange. const options: LoggerOptions = { - isDebugMode, level, + minimumLevel: minimumLevel as LogLevel.INFO | LogLevel.TRACE, targets: [{ write: jest.fn() }] }; @@ -420,11 +415,11 @@ describe("Logger", () => { * Asserts {@link Logger.setLogLevel} validates teh {@link LogLevel}. */ describe("setLevel", () => { - it.each(testCases)("$name when isDebugMode is $isDebugMode", ({ level, expected, isDebugMode }) => { + it.each(testCases)("$name when minimumLevel is $minimumLevel", ({ level, expected, minimumLevel }) => { // Arrange. const options: LoggerOptions = { - isDebugMode, level: LogLevel.ERROR, + minimumLevel: minimumLevel as LogLevel.INFO | LogLevel.TRACE, targets: [{ write: jest.fn() }] }; diff --git a/src/common/logging/__tests__/routing.test.ts b/src/common/logging/__tests__/routing.test.ts index 554ad99d..f96bdfe6 100644 --- a/src/common/logging/__tests__/routing.test.ts +++ b/src/common/logging/__tests__/routing.test.ts @@ -95,7 +95,6 @@ describe("registerCreateLogEntryRoute", () => { const logger = new Logger({ level: LogLevel.INFO, - isDebugMode: true, targets: [{ write: jest.fn() }] }); diff --git a/src/common/logging/console-target.ts b/src/common/logging/console-target.ts index c31a9a1f..e88928ff 100644 --- a/src/common/logging/console-target.ts +++ b/src/common/logging/console-target.ts @@ -1,4 +1,4 @@ -import { LogLevel } from "."; +import { LogLevel } from "./level"; import type { LogEntry, LogTarget } from "./target"; /** diff --git a/src/common/logging/logger.ts b/src/common/logging/logger.ts index e0687f3e..c31759e3 100644 --- a/src/common/logging/logger.ts +++ b/src/common/logging/logger.ts @@ -13,7 +13,7 @@ export class Logger { /** * Options that define the loggers behavior. */ - private readonly options: LoggerOptions; + private readonly options: LoggerOptions & Required>; /** * Scope associated with this {@link Logger}. @@ -25,7 +25,7 @@ export class Logger { * @param opts Options that define the loggers behavior. */ constructor(opts: LoggerOptions) { - this.options = { ...opts }; + this.options = { minimumLevel: LogLevel.TRACE, ...opts }; this.scope = this.options.scope === undefined || this.options.scope.trim() === "" ? "" : this.options.scope; if (typeof this.options.level !== "function") { @@ -96,7 +96,7 @@ export class Logger { * @returns This instance for chaining. */ public setLevel(level?: LogLevel): this { - if ((level === LogLevel.DEBUG || level === LogLevel.TRACE) && !this.options.isDebugMode) { + if (level !== undefined && level > this.options.minimumLevel) { this._level = LogLevel.INFO; this.warn(`Log level cannot be set to ${LogLevel[level]} whilst not in debug mode.`); } else { @@ -143,14 +143,14 @@ export class Logger { */ export type LoggerOptions = { /** - * Indicates whether the current context is running in debug mode. + * Determines the minimum level of logs that can be written. */ - isDebugMode: boolean; + level: LogLevel | (() => LogLevel); /** - * Determines the minimum level of logs that can be written. + * Minimum level the logger can be set to. */ - level: LogLevel | (() => LogLevel); + minimumLevel?: LogLevel.INFO | LogLevel.TRACE; /** * Optional value that defines the scope of the logger. diff --git a/src/plugin/__tests__/connection.test.ts b/src/plugin/__tests__/connection.test.ts index 4d34f166..5390f689 100644 --- a/src/plugin/__tests__/connection.test.ts +++ b/src/plugin/__tests__/connection.test.ts @@ -24,7 +24,6 @@ describe("connection", () => { // Re-import the connection to ensure a fresh state. beforeEach(async () => { connectionLogger = new Logger({ - isDebugMode: false, level: LogLevel.TRACE, targets: [{ write: jest.fn() }] }); @@ -299,7 +298,6 @@ describe("connection", () => { it("logs arguments", () => { // Arrange const scopedLogger = new Logger({ - isDebugMode: false, level: LogLevel.TRACE, targets: [{ write: jest.fn() }] }); diff --git a/src/plugin/__tests__/i18n.test.ts b/src/plugin/__tests__/i18n.test.ts index 5345222b..fa87d5e7 100644 --- a/src/plugin/__tests__/i18n.test.ts +++ b/src/plugin/__tests__/i18n.test.ts @@ -30,7 +30,6 @@ describe("I18nProvider", () => { beforeEach(() => { scopedLogger = new Logger({ - isDebugMode: false, level: LogLevel.TRACE, targets: [{ write: jest.fn }] }); diff --git a/src/plugin/logging/__mocks__/index.ts b/src/plugin/logging/__mocks__/index.ts index 377a2d84..5660b1d5 100644 --- a/src/plugin/logging/__mocks__/index.ts +++ b/src/plugin/logging/__mocks__/index.ts @@ -1,7 +1,6 @@ import { LogLevel, Logger, type LoggerOptions } from "../../../common/logging"; const options: LoggerOptions = { - isDebugMode: false, level: LogLevel.TRACE, targets: [{ write: jest.fn() }] }; diff --git a/src/plugin/logging/__tests__/index.test.ts b/src/plugin/logging/__tests__/index.test.ts index 2e83da33..eff0459f 100644 --- a/src/plugin/logging/__tests__/index.test.ts +++ b/src/plugin/logging/__tests__/index.test.ts @@ -39,8 +39,8 @@ describe("createLogger", () => { // Assert. expect(spyOnFileTarget).toHaveBeenCalledTimes(1); expect(Logger).toHaveBeenCalledWith<[LoggerOptions]>({ - isDebugMode: true, level: LogLevel.DEBUG, + minimumLevel: LogLevel.TRACE, targets: [expect.any(ConsoleTarget), spyOnFileTarget.mock.instances[0]] }); }); @@ -59,8 +59,8 @@ describe("createLogger", () => { // Assert. expect(Logger).toHaveBeenCalledWith<[LoggerOptions]>({ - isDebugMode: false, level: LogLevel.INFO, + minimumLevel: LogLevel.INFO, targets: [spyOnFileTarget.mock.instances[0]] }); }); diff --git a/src/plugin/logging/index.ts b/src/plugin/logging/index.ts index c14d2d86..9b5d68f3 100644 --- a/src/plugin/logging/index.ts +++ b/src/plugin/logging/index.ts @@ -27,8 +27,8 @@ if (isDebugMode()) { * Logger responsible for capturing log messages. */ export const logger = new Logger({ - isDebugMode: isDebugMode(), level: isDebugMode() ? LogLevel.DEBUG : LogLevel.INFO, + minimumLevel: isDebugMode() ? LogLevel.TRACE : LogLevel.INFO, targets }); diff --git a/src/ui/__tests__/logging.test.ts b/src/ui/__tests__/logging.test.ts index bfc57564..84293f55 100644 --- a/src/ui/__tests__/logging.test.ts +++ b/src/ui/__tests__/logging.test.ts @@ -18,8 +18,7 @@ describe("Logging", () => { expect(logger).toBe(spyOnLogger.mock.instances[0]); expect(spyOnLogger).toHaveBeenCalledTimes(1); expect(spyOnLogger).toHaveBeenCalledWith<[LoggingModule.LoggerOptions]>({ - isDebugMode: true, - level: LoggingModule.LogLevel.TRACE, + level: LoggingModule.LogLevel.DEBUG, targets: [expect.any(LoggingModule.ConsoleTarget), LoggingModule.createRoutedLogTarget(router)] }); }); diff --git a/src/ui/logging.ts b/src/ui/logging.ts index 70782e3f..81f3b789 100644 --- a/src/ui/logging.ts +++ b/src/ui/logging.ts @@ -5,7 +5,6 @@ import { router } from "./plugin"; * Logger responsible for capturing log messages. */ export const logger = new Logger({ - isDebugMode: true, - level: LogLevel.TRACE, + level: LogLevel.DEBUG, targets: [new ConsoleTarget(), createRoutedLogTarget(router)] });