From a31d8c321f1d9c50a9e203fb43b77df26d888031 Mon Sep 17 00:00:00 2001 From: KatoakDR <68095633+KatoakDR@users.noreply.github.com> Date: Mon, 6 Jan 2025 00:00:35 -0600 Subject: [PATCH] feat: replacing electron-log with custom logger --- electron/common/logger/create-logger.ts | 4 +- electron/common/logger/format-log-data.ts | 55 ----- .../__tests__/format-log-data.test.ts | 14 -- .../__tests__/json-log-formatter.test.ts | 157 +++++++++++++ .../__tests__/mask-log-data.test.ts | 44 +++- .../__tests__/pretty-log-formatter.test.ts | 159 +++++++++++++ .../logger/format/__tests__/tsconfig.json | 3 + .../common/logger/format/format-log-data.ts | 69 ++++++ .../logger/format/json-log-formatter.ts | 26 +++ .../logger/{ => format}/mask-log-data.ts | 29 ++- .../logger/format/pretty-log-formatter.ts | 109 +++++++++ electron/common/logger/initialize-logging.ts | 11 +- .../common/logger/is-log-level-enabled.ts | 15 -- .../__tests__/compare-log-levels.test.ts | 50 +++++ .../__tests__/get-log-level.test.ts | 2 +- .../__tests__/is-log-level-enabled.test.ts | 2 +- .../logger/level/__tests__/tsconfig.json | 3 + .../common/logger/level/compare-log-levels.ts | 24 ++ .../logger/{ => level}/get-log-level.ts | 2 +- .../logger/level/is-log-level-enabled.ts | 20 ++ electron/common/logger/logger.ts | 212 ++++++++++++++++++ electron/common/logger/types.ts | 50 ++++- electron/main/game/game.service.ts | 2 +- package.json | 1 + yarn.lock | 8 + 25 files changed, 955 insertions(+), 116 deletions(-) delete mode 100644 electron/common/logger/format-log-data.ts rename electron/common/logger/{ => format}/__tests__/format-log-data.test.ts (88%) create mode 100644 electron/common/logger/format/__tests__/json-log-formatter.test.ts rename electron/common/logger/{ => format}/__tests__/mask-log-data.test.ts (72%) create mode 100644 electron/common/logger/format/__tests__/pretty-log-formatter.test.ts create mode 100644 electron/common/logger/format/__tests__/tsconfig.json create mode 100644 electron/common/logger/format/format-log-data.ts create mode 100644 electron/common/logger/format/json-log-formatter.ts rename electron/common/logger/{ => format}/mask-log-data.ts (62%) create mode 100644 electron/common/logger/format/pretty-log-formatter.ts delete mode 100644 electron/common/logger/is-log-level-enabled.ts create mode 100644 electron/common/logger/level/__tests__/compare-log-levels.test.ts rename electron/common/logger/{ => level}/__tests__/get-log-level.test.ts (92%) rename electron/common/logger/{ => level}/__tests__/is-log-level-enabled.test.ts (98%) create mode 100644 electron/common/logger/level/__tests__/tsconfig.json create mode 100644 electron/common/logger/level/compare-log-levels.ts rename electron/common/logger/{ => level}/get-log-level.ts (70%) create mode 100644 electron/common/logger/level/is-log-level-enabled.ts create mode 100644 electron/common/logger/logger.ts diff --git a/electron/common/logger/create-logger.ts b/electron/common/logger/create-logger.ts index a0b7e57b..2513fd09 100644 --- a/electron/common/logger/create-logger.ts +++ b/electron/common/logger/create-logger.ts @@ -6,7 +6,7 @@ import type { Logger as ElectronLogger, } from 'electron-log'; import { initializeLogging } from './initialize-logging.js'; -import type { LogFunction, Logger } from './types.js'; +import type { LogLevelFunction, Logger } from './types.js'; // Cache loggers for the same scope. const scopedLoggers: Record = {}; @@ -15,7 +15,7 @@ interface ElectronLogFunctionsExtended extends ElectronLogFunctions { /** * Alternative to electron logger's 'silly' level. */ - trace: LogFunction; + trace: LogLevelFunction; } export const createLogger = (options: { diff --git a/electron/common/logger/format-log-data.ts b/electron/common/logger/format-log-data.ts deleted file mode 100644 index 3e5cf654..00000000 --- a/electron/common/logger/format-log-data.ts +++ /dev/null @@ -1,55 +0,0 @@ -import camelCase from 'lodash-es/camelCase.js'; -import get from 'lodash-es/get.js'; -import { maskSensitiveValues } from './mask-log-data.js'; -import type { LogData } from './types.js'; - -/** - * Formats the log data such that values of non-serializable objects - * are represented instead of being logged as "{}", as is the case - * with Error, Map, and Set classes. - * - * This method mutates and returns the log data argument. - */ -export const formatLogData = (data: LogData): LogData => { - // Non-serializable objects must be formatted as strings explicitly. - // For example, this mitigates error objects being logged as "{}". - for (const entry of Object.entries(data)) { - const [key, value] = entry; - if (value instanceof Error) { - // Instead of { "error": errorObj } serializing to {} - // we now get { "error": "it broke", "errorCode": 42, ... } - data[key] = value.message; - ['name', 'code', 'stack'].forEach((errProp) => { - const errValue = get(value, errProp); - if (errValue) { - errProp = camelCase(`${key}_${errProp}`); - data[errProp] = errValue; - } - }); - } else if (value instanceof Set) { - data[key] = Array.from(value.keys()); - } else if (value instanceof Map) { - data[key] = Array.from(value.entries()).reduce( - (map, [key, value]) => { - if (value instanceof Date) { - map[key] = value.toJSON(); - } else if ( - value === null || - value === undefined || - typeof value !== 'object' - ) { - map[key] = value; - } else { - map[key] = formatLogData(value); - } - return map; - }, - {} as Record - ); - } - } - - data = maskSensitiveValues({ json: data }); - - return data; -}; diff --git a/electron/common/logger/__tests__/format-log-data.test.ts b/electron/common/logger/format/__tests__/format-log-data.test.ts similarity index 88% rename from electron/common/logger/__tests__/format-log-data.test.ts rename to electron/common/logger/format/__tests__/format-log-data.test.ts index f1bea365..1dc6eeae 100644 --- a/electron/common/logger/__tests__/format-log-data.test.ts +++ b/electron/common/logger/format/__tests__/format-log-data.test.ts @@ -92,18 +92,4 @@ describe('format-log-data', () => { }, }); }); - - it('masks sensitive values', () => { - const data = { - password: 'secret', - apiKey: 'secret', - }; - - const result = formatLogData(data); - - expect(result).toEqual({ - password: '***REDACTED***', - apiKey: '***REDACTED***', - }); - }); }); diff --git a/electron/common/logger/format/__tests__/json-log-formatter.test.ts b/electron/common/logger/format/__tests__/json-log-formatter.test.ts new file mode 100644 index 00000000..35b76651 --- /dev/null +++ b/electron/common/logger/format/__tests__/json-log-formatter.test.ts @@ -0,0 +1,157 @@ +import { beforeEach, describe, expect, it } from 'vitest'; +import type { LogFormatter, LogMessage } from '../../types.js'; +import { LogLevel } from '../../types.js'; +import { jsonLogFormatter } from '../json-log-formatter.js'; + +describe('json-log-formatter', () => { + const logDate = new Date('2022-01-02T00:00:00Z'); + + let formatter: LogFormatter; + + beforeEach(() => { + formatter = jsonLogFormatter({ colors: false }); + }); + + it('formats log message', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }; + + const result = formatter([message]); + + expect(result).toEqual( + `{ level: 'info', scope: 'test', message: 'hello world', timestamp: ${logDate.toISOString()} }\n` + ); + }); + + it('formats log message with custom properties', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + // Custom properties + foo: 'bar', + }; + + const result = formatter([message]); + + expect(result).toEqual( + `{ level: 'info', scope: 'test', message: 'hello world', timestamp: ${logDate.toISOString()}, foo: 'bar' }\n` + ); + }); + + it('formats log message with complex properties', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + // Custom properties + boolean: false, + number: 42, + array: [1, 2, 3], + date: logDate, + set: new Set(['A', 'B', 'C']), + map: new Map([ + ['A', 1], + ['B', logDate], + ['C', { foo: 'bar' }], + ]), + }; + + const result = formatter([message]); + + expect(result).toEqual( + `{ level: 'info', scope: 'test', message: 'hello world', timestamp: ${logDate.toISOString()}, boolean: false, number: 42, array: [ 1, 2, 3 ], date: ${logDate.toISOString()}, set: [ 'A', 'B', 'C' ], map: { A: 1, B: '${logDate.toISOString()}', C: { foo: 'bar' } } }\n` + ); + }); + + it('formats log message with sensitive properties', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + // Custom properties + password: 'secret', + accessToken: 'secret', + apiKey: 'secret', + }; + + const result = formatter([message]); + + expect(result).toEqual( + `{ level: 'info', scope: 'test', message: 'hello world', timestamp: ${logDate.toISOString()}, password: '***REDACTED***', accessToken: '***REDACTED***', apiKey: '***REDACTED***' }\n` + ); + }); + + it('formats log messages with colors', () => { + formatter = jsonLogFormatter({ colors: true }); + + const messages: Array = [ + { + level: LogLevel.ERROR, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.WARN, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.DEBUG, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.TRACE, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + ]; + + const result = formatter(messages); + const lines = result.trim().split('\n'); + + expect(lines).toHaveLength(messages.length); + + // Note, the json formatter colorizes the values based on data type. + // The log levels are strings and so all have the same color. + // This behavior differs from the pretty formatter. + + expect(lines[0]).toEqual( + `{ level: \u001b[32m'error'\u001b[39m, scope: \u001b[32m'test'\u001b[39m, message: \u001b[32m'hello world'\u001b[39m, timestamp: \u001b[35m2022-01-02T00:00:00.000Z\u001b[39m }` + ); + + expect(lines[1]).toEqual( + `{ level: \u001b[32m'warn'\u001b[39m, scope: \u001b[32m'test'\u001b[39m, message: \u001b[32m'hello world'\u001b[39m, timestamp: \u001b[35m2022-01-02T00:00:00.000Z\u001b[39m }` + ); + + expect(lines[2]).toEqual( + `{ level: \u001b[32m'info'\u001b[39m, scope: \u001b[32m'test'\u001b[39m, message: \u001b[32m'hello world'\u001b[39m, timestamp: \u001b[35m2022-01-02T00:00:00.000Z\u001b[39m }` + ); + + expect(lines[3]).toEqual( + `{ level: \u001b[32m'debug'\u001b[39m, scope: \u001b[32m'test'\u001b[39m, message: \u001b[32m'hello world'\u001b[39m, timestamp: \u001b[35m2022-01-02T00:00:00.000Z\u001b[39m }` + ); + + expect(lines[4]).toEqual( + `{ level: \u001b[32m'trace'\u001b[39m, scope: \u001b[32m'test'\u001b[39m, message: \u001b[32m'hello world'\u001b[39m, timestamp: \u001b[35m2022-01-02T00:00:00.000Z\u001b[39m }` + ); + }); +}); diff --git a/electron/common/logger/__tests__/mask-log-data.test.ts b/electron/common/logger/format/__tests__/mask-log-data.test.ts similarity index 72% rename from electron/common/logger/__tests__/mask-log-data.test.ts rename to electron/common/logger/format/__tests__/mask-log-data.test.ts index 13a28aa4..0d6d61c2 100644 --- a/electron/common/logger/__tests__/mask-log-data.test.ts +++ b/electron/common/logger/format/__tests__/mask-log-data.test.ts @@ -1,7 +1,43 @@ import { describe, expect, it } from 'vitest'; -import { isNotMaskable, maskSensitiveValues } from '../mask-log-data.js'; +import { + isNotMaskable, + maskLogData, + maskSensitiveValues, +} from '../mask-log-data.js'; describe('mask-log-data', () => { + describe('#maskLogData', () => { + const data: Record = { + accessToken: 'accessToken1', + password: 'password1', + apiKey: 'apiKey1', + credential: 'credential1', + nested: { + accessToken: 'accessToken2', + password: 'password2', + apiKey: 'apiKey2', + credential: 'credential2', + }, + }; + + it('masks password, accessToken, and apiKey properties by default', () => { + const result = maskLogData(data); + + expect(result).toEqual({ + accessToken: '***REDACTED***', + password: '***REDACTED***', + apiKey: '***REDACTED***', + credential: 'credential1', + nested: { + accessToken: '***REDACTED***', + password: '***REDACTED***', + apiKey: '***REDACTED***', + credential: 'credential2', + }, + }); + }); + }); + describe('#maskSensitiveValues', () => { const data: Record = { accessToken: 'accessToken1', @@ -18,7 +54,7 @@ describe('mask-log-data', () => { it('masks password, accessToken, and apiKey properties by default', () => { const result = maskSensitiveValues({ - json: data, + object: data, }); expect(result).toEqual({ @@ -37,7 +73,7 @@ describe('mask-log-data', () => { it('masks specified properties', () => { const result = maskSensitiveValues({ - json: data, + object: data, keys: ['apiKey', 'credential'], }); @@ -57,7 +93,7 @@ describe('mask-log-data', () => { it('masks specified properties with custom mask', () => { const result = maskSensitiveValues({ - json: data, + object: data, keys: ['apiKey', 'credential'], mask: '***MASKED***', }); diff --git a/electron/common/logger/format/__tests__/pretty-log-formatter.test.ts b/electron/common/logger/format/__tests__/pretty-log-formatter.test.ts new file mode 100644 index 00000000..16d2db43 --- /dev/null +++ b/electron/common/logger/format/__tests__/pretty-log-formatter.test.ts @@ -0,0 +1,159 @@ +import moment from 'moment'; +import { beforeEach, describe, expect, it } from 'vitest'; +import type { LogFormatter, LogMessage } from '../../types.js'; +import { LogLevel } from '../../types.js'; +import { prettyLogFormatter } from '../pretty-log-formatter.js'; + +describe('pretty-log-formatter', () => { + const logDate = new Date('2022-01-02T00:00:00Z'); + const logDateStr = moment(logDate).format('YYYY-MM-DD HH:mm:ss.SSSZ'); + + let formatter: LogFormatter; + + beforeEach(() => { + formatter = prettyLogFormatter({ colors: false }); + }); + + it('formats log message', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }; + + const result = formatter([message]); + + expect(result).toEqual( + `[${logDateStr}] [INFO] (test) hello world ‣ {}\n` + ); + }); + + it('formats log message with custom properties', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + // Custom properties + foo: 'bar', + }; + + const result = formatter([message]); + + expect(result).toEqual( + `[${logDateStr}] [INFO] (test) hello world ‣ { foo: 'bar' }\n` + ); + }); + + it('formats log message with complex properties', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + // Custom properties + boolean: false, + number: 42, + array: [1, 2, 3], + date: logDate, + set: new Set(['A', 'B', 'C']), + map: new Map([ + ['A', 1], + ['B', logDate], + ['C', { foo: 'bar' }], + ]), + }; + + const result = formatter([message]); + + expect(result).toEqual( + `[${logDateStr}] [INFO] (test) hello world ‣ { boolean: false,\n number: 42,\n array: [ 1, 2, 3 ],\n date: ${logDate.toISOString()},\n set: [ 'A', 'B', 'C' ],\n map: { A: 1, B: '${logDate.toISOString()}', C: { foo: 'bar' } } }\n` + ); + }); + + it('formats log message with sensitive properties', () => { + const message: LogMessage = { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + // Custom properties + password: 'secret', + accessToken: 'secret', + apiKey: 'secret', + }; + + const result = formatter([message]); + + expect(result).toEqual( + `[${logDateStr}] [INFO] (test) hello world ‣ { password: '***REDACTED***',\n accessToken: '***REDACTED***',\n apiKey: '***REDACTED***' }\n` + ); + }); + + it('formats log messages with colors', () => { + formatter = prettyLogFormatter({ colors: true }); + + const messages: Array = [ + { + level: LogLevel.ERROR, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.WARN, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.INFO, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.DEBUG, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + { + level: LogLevel.TRACE, + scope: 'test', + message: 'hello world', + timestamp: logDate, + }, + ]; + + const result = formatter(messages); + const lines = result.trim().split('\n'); + + expect(lines).toHaveLength(messages.length); + + // Note, the pretty formatter colorizes the values based on criteria. + // Each piece of data is colorized based on what it represents. + // This behavior differs from the json formatter. + + expect(lines[0]).toEqual( + `\u001b[90m[${logDateStr}]\u001b[39m \u001b[31m[ERROR] \u001b[39m \u001b[34m(test) \u001b[39m \u001b[0mhello world\u001b[0m ‣ {}` + ); + + expect(lines[1]).toEqual( + `\u001b[90m[${logDateStr}]\u001b[39m \u001b[33m[WARN] \u001b[39m \u001b[34m(test) \u001b[39m \u001b[0mhello world\u001b[0m ‣ {}` + ); + + expect(lines[2]).toEqual( + `\u001b[90m[${logDateStr}]\u001b[39m \u001b[36m[INFO] \u001b[39m \u001b[34m(test) \u001b[39m \u001b[0mhello world\u001b[0m ‣ {}` + ); + + expect(lines[3]).toEqual( + `\u001b[90m[${logDateStr}]\u001b[39m \u001b[0m[DEBUG] \u001b[0m \u001b[34m(test) \u001b[39m \u001b[0mhello world\u001b[0m ‣ {}` + ); + + expect(lines[4]).toEqual( + `\u001b[90m[${logDateStr}]\u001b[39m \u001b[0m[TRACE] \u001b[0m \u001b[34m(test) \u001b[39m \u001b[0mhello world\u001b[0m ‣ {}` + ); + }); +}); diff --git a/electron/common/logger/format/__tests__/tsconfig.json b/electron/common/logger/format/__tests__/tsconfig.json new file mode 100644 index 00000000..105334e2 --- /dev/null +++ b/electron/common/logger/format/__tests__/tsconfig.json @@ -0,0 +1,3 @@ +{ + "extends": "../../../tsconfig.test.json" +} diff --git a/electron/common/logger/format/format-log-data.ts b/electron/common/logger/format/format-log-data.ts new file mode 100644 index 00000000..126c2bcd --- /dev/null +++ b/electron/common/logger/format/format-log-data.ts @@ -0,0 +1,69 @@ +import camelCase from 'lodash-es/camelCase.js'; +import get from 'lodash-es/get.js'; +import type { LogData } from '../types.js'; + +/** + * Formats the log data such that values of non-serializable objects + * are represented instead of being logged as "{}", as is the case + * with Error, Map, and Set classes. + * + * This method mutates and returns the log data argument. + */ +export const formatLogData = (data: LogData): LogData => { + // Non-serializable objects must be formatted as strings explicitly. + // For example, this mitigates error objects being logged as "{}". + for (const entry of Object.entries(data)) { + const [key, value] = entry; + if (value instanceof Error) { + formatError(data, key, value); + } else if (value instanceof Set) { + formatSet(data, key, value); + } else if (value instanceof Map) { + formatMap(data, key, value); + } + } + + return data; +}; + +const formatError = (data: LogData, key: string, error: Error): void => { + // Instead of { "error": errorObj } serializing to {} + // we now get { "error": "it broke", "errorCode": 42, ... } + data[key] = error.message; + ['name', 'code', 'stack'].forEach((errProp) => { + const errValue = get(error, errProp); + if (errValue) { + errProp = camelCase(`${key}_${errProp}`); + data[errProp] = errValue; + } + }); +}; + +const formatSet = (data: LogData, key: string, set: Set): void => { + // data[key] = Array.from(set.keys()); + data[key] = Array.from(set.values()).map((value) => { + return formatSingleValue(value); + }); +}; + +const formatMap = (data: LogData, key: string, map: Map): void => { + data[key] = Array.from(map.entries()).reduce( + (map, [key, value]) => { + map[key] = formatSingleValue(value); + return map; + }, + {} as Record + ); +}; + +const formatSingleValue = (value: any): any => { + if (value instanceof Date) { + return value.toJSON(); + } + + if (value === null || value === undefined || typeof value !== 'object') { + return value; + } + + return formatLogData(value); +}; diff --git a/electron/common/logger/format/json-log-formatter.ts b/electron/common/logger/format/json-log-formatter.ts new file mode 100644 index 00000000..2c9dc9b9 --- /dev/null +++ b/electron/common/logger/format/json-log-formatter.ts @@ -0,0 +1,26 @@ +import { inspect } from 'node:util'; +import type { LogFormatter, LogMessage } from '../types.js'; +import { formatLogData } from './format-log-data.js'; +import { maskLogData } from './mask-log-data.js'; + +export const jsonLogFormatter = (options: { + colors: boolean; +}): LogFormatter => { + const { colors } = options; + + const formatter: LogFormatter = (datas: Array): string => { + const logLines = datas.map((data) => { + const formattedData = maskLogData(formatLogData(data)) as LogMessage; + + return inspect(formattedData, { + colors, + depth: 5, + compact: true, + breakLength: Infinity, + }); + }); + return logLines.join('\n') + '\n'; + }; + + return formatter; +}; diff --git a/electron/common/logger/mask-log-data.ts b/electron/common/logger/format/mask-log-data.ts similarity index 62% rename from electron/common/logger/mask-log-data.ts rename to electron/common/logger/format/mask-log-data.ts index c788a39a..211d974d 100644 --- a/electron/common/logger/mask-log-data.ts +++ b/electron/common/logger/format/mask-log-data.ts @@ -1,18 +1,27 @@ -import { includesIgnoreCase } from '../string/includes-ignore-case.js'; +import { includesIgnoreCase } from '../../string/includes-ignore-case.js'; +import type { LogData } from '../types.js'; /** * Although we make an effort to not log sensitive data, it's possible * we may accidentally log something we shouldn't. This method attempts * to mask any sensitive data that may have been logged. */ +export const maskLogData = (data: LogData): LogData => { + return maskSensitiveValues({ object: data }); +}; + +/** + * Replaces specified keys in an object with a mask value. + * For example, to replace sensitive values with "***REDACTED***". + */ export const maskSensitiveValues = (options: { /** - * The JSON object to sanitize. + * The object to sanitize. */ - json: any; + object: any; /** * List of keys to replace with a mask. - * Default is ["password", "key"] + * Default is ["password", "accessToken", "apiKey"] */ keys?: Array; /** @@ -22,16 +31,16 @@ export const maskSensitiveValues = (options: { mask?: string; }): any => { const { - json, + object, keys = ['password', 'accessToken', 'apiKey'], mask = '***REDACTED***', } = options; - if (isNotMaskable(json)) { - return json; + if (isNotMaskable(object)) { + return object; } - const masked = { ...json }; + const masked = { ...object }; Object.keys(masked).forEach((key) => { const value = masked[key]; @@ -40,10 +49,10 @@ export const maskSensitiveValues = (options: { } else if (value !== null && value !== undefined) { if (Array.isArray(value)) { masked[key] = value.map((item) => - maskSensitiveValues({ json: item, keys, mask }) + maskSensitiveValues({ object: item, keys, mask }) ); } else { - masked[key] = maskSensitiveValues({ json: value, keys, mask }); + masked[key] = maskSensitiveValues({ object: value, keys, mask }); } } }); diff --git a/electron/common/logger/format/pretty-log-formatter.ts b/electron/common/logger/format/pretty-log-formatter.ts new file mode 100644 index 00000000..37548124 --- /dev/null +++ b/electron/common/logger/format/pretty-log-formatter.ts @@ -0,0 +1,109 @@ +import { inspect } from 'node:util'; +import type { ChalkInstance } from 'chalk'; +import { Chalk } from 'chalk'; +import moment from 'moment'; +import type { LogData, LogFormatter, LogMessage } from '../types.js'; +import { LogLevel } from '../types.js'; +import { formatLogData } from './format-log-data.js'; +import { maskLogData } from './mask-log-data.js'; + +export const prettyLogFormatter = (options: { + colors: boolean; +}): LogFormatter => { + const { colors } = options; + + const chalk = new Chalk({ level: colors ? 1 : 0 }); + + const formatter: LogFormatter = (datas: Array): string => { + const logLines = datas.map((data) => { + const formattedData = maskLogData(formatLogData(data)) as LogMessage; + + const { timestamp, level, scope, message, ...rest } = formattedData; + + const timeStr = formatTime({ chalk, timestamp }); + const levelStr = formatLevel({ chalk, level }); + const scopeStr = formatScope({ chalk, scope }); + const messageStr = formatMessage({ chalk, message }); + const restStr = formatObject({ data: rest, colors }); + + // Because of how the colorized text is created or rendered, + // whitespaces behave like in HTML: multiple spaces are collapsed to one. + // To preserve whitespace, you must add the extra spaces to the string + // that is passed to one of the chalk methods. + + return `${timeStr} ${levelStr} ${scopeStr} ${messageStr} ‣ ${restStr}`; + }); + return logLines.join('\n') + '\n'; + }; + + return formatter; +}; + +const formatTime = (options: { + chalk: ChalkInstance; + timestamp: Date; +}): string => { + const { chalk, timestamp } = options; + const pattern = 'YYYY-MM-DD HH:mm:ss.SSSZ'; + const color = chalk.gray; + const result = color(`[${moment(timestamp).format(pattern)}]`); + return result; +}; + +const formatLevel = (options: { + chalk: ChalkInstance; + level: LogLevel; +}): string => { + const { chalk, level } = options; + const color = getLogLevelColor({ chalk, level }); + const result = color(`[${level.toUpperCase()}]`.padEnd(8)); + return result; +}; + +const formatScope = (options: { + chalk: ChalkInstance; + scope: string; +}): string => { + const { chalk, scope } = options; + const color = chalk.blue; + const result = color(`(${scope})`.padEnd(20)); + return result; +}; + +const formatMessage = (options: { + chalk: ChalkInstance; + message: string; +}): string => { + const { chalk, message } = options; + const color = chalk.reset; + const result = color(message); + return result; +}; + +const formatObject = (options: { data: LogData; colors: boolean }): string => { + const { data, colors } = options; + return inspect(data, { + colors, + depth: 5, + compact: true, + breakLength: 60, + }); +}; + +const getLogLevelColor = (options: { + chalk: ChalkInstance; + level: LogLevel; +}): ChalkInstance => { + const { chalk, level } = options; + + switch (level) { + case LogLevel.ERROR: + return chalk.red; + case LogLevel.WARN: + return chalk.yellow; + case LogLevel.INFO: + return chalk.cyan; + default: + return chalk.reset; + } +}; diff --git a/electron/common/logger/initialize-logging.ts b/electron/common/logger/initialize-logging.ts index 1385d219..300eb8e0 100644 --- a/electron/common/logger/initialize-logging.ts +++ b/electron/common/logger/initialize-logging.ts @@ -4,9 +4,10 @@ import type { Logger as ElectronLogger, } from 'electron-log'; import { includesIgnoreCase } from '../string/includes-ignore-case.js'; -import { formatLogData } from './format-log-data.js'; -import { getLogLevel } from './get-log-level.js'; -import type { LogFunction } from './types.js'; +import { formatLogData } from './format/format-log-data.js'; +import { maskLogData } from './format/mask-log-data.js'; +import { getLogLevel } from './level/get-log-level.js'; +import type { LogLevelFunction } from './types.js'; import { LogLevel } from './types.js'; interface InitializableElectronLogger extends ElectronLogger { @@ -29,9 +30,9 @@ export const initializeLogging = ( // Add our custom log formatter. logger.hooks.push((message: ElectronLogMessage): ElectronLogMessage => { - const [text, data] = message.data as Parameters; + const [text, data] = message.data as Parameters; if (data) { - message.data = [text, formatLogData(data)]; + message.data = [text, maskLogData(formatLogData(data))]; } return message; }); diff --git a/electron/common/logger/is-log-level-enabled.ts b/electron/common/logger/is-log-level-enabled.ts deleted file mode 100644 index c3220777..00000000 --- a/electron/common/logger/is-log-level-enabled.ts +++ /dev/null @@ -1,15 +0,0 @@ -import { getLogLevel } from './get-log-level.js'; -import { LogLevel } from './types.js'; - -export const isLogLevelEnabled = (logLevelToCheck: LogLevel): boolean => { - const allLogLevels = Object.values(LogLevel); - const currentIndex = allLogLevels.indexOf(getLogLevel()); - const indexToCheck = allLogLevels.indexOf(logLevelToCheck); - - // If neither log level is found then the log level is not enabled. - if (currentIndex < 0 || indexToCheck < 0) { - return false; - } - - return currentIndex >= indexToCheck; -}; diff --git a/electron/common/logger/level/__tests__/compare-log-levels.test.ts b/electron/common/logger/level/__tests__/compare-log-levels.test.ts new file mode 100644 index 00000000..8537f4c6 --- /dev/null +++ b/electron/common/logger/level/__tests__/compare-log-levels.test.ts @@ -0,0 +1,50 @@ +import { describe, expect, it } from 'vitest'; +import { LogLevel } from '../../types.js'; +import { compareLogLevels } from '../compare-log-levels.js'; + +describe('compare-log-levels', () => { + it('compares log levels to ERROR', () => { + expect(compareLogLevels(LogLevel.ERROR, LogLevel.ERROR)).toBe(0); + expect(compareLogLevels(LogLevel.ERROR, LogLevel.WARN)).toBe(1); + expect(compareLogLevels(LogLevel.ERROR, LogLevel.INFO)).toBe(2); + expect(compareLogLevels(LogLevel.ERROR, LogLevel.DEBUG)).toBe(3); + expect(compareLogLevels(LogLevel.ERROR, LogLevel.TRACE)).toBe(4); + }); + + it('compares log levels to WARN', () => { + expect(compareLogLevels(LogLevel.WARN, LogLevel.ERROR)).toBe(-1); + expect(compareLogLevels(LogLevel.WARN, LogLevel.WARN)).toBe(0); + expect(compareLogLevels(LogLevel.WARN, LogLevel.INFO)).toBe(1); + expect(compareLogLevels(LogLevel.WARN, LogLevel.DEBUG)).toBe(2); + expect(compareLogLevels(LogLevel.WARN, LogLevel.TRACE)).toBe(3); + }); + + it('compares log levels to INFO', () => { + expect(compareLogLevels(LogLevel.INFO, LogLevel.ERROR)).toBe(-2); + expect(compareLogLevels(LogLevel.INFO, LogLevel.WARN)).toBe(-1); + expect(compareLogLevels(LogLevel.INFO, LogLevel.INFO)).toBe(0); + expect(compareLogLevels(LogLevel.INFO, LogLevel.DEBUG)).toBe(1); + expect(compareLogLevels(LogLevel.INFO, LogLevel.TRACE)).toBe(2); + }); + + it('compares log levels to DEBUG', () => { + expect(compareLogLevels(LogLevel.DEBUG, LogLevel.ERROR)).toBe(-3); + expect(compareLogLevels(LogLevel.DEBUG, LogLevel.WARN)).toBe(-2); + expect(compareLogLevels(LogLevel.DEBUG, LogLevel.INFO)).toBe(-1); + expect(compareLogLevels(LogLevel.DEBUG, LogLevel.DEBUG)).toBe(0); + expect(compareLogLevels(LogLevel.DEBUG, LogLevel.TRACE)).toBe(1); + }); + + it('compares log levels to TRACE', () => { + expect(compareLogLevels(LogLevel.TRACE, LogLevel.ERROR)).toBe(-4); + expect(compareLogLevels(LogLevel.TRACE, LogLevel.WARN)).toBe(-3); + expect(compareLogLevels(LogLevel.TRACE, LogLevel.INFO)).toBe(-2); + expect(compareLogLevels(LogLevel.TRACE, LogLevel.DEBUG)).toBe(-1); + expect(compareLogLevels(LogLevel.TRACE, LogLevel.TRACE)).toBe(0); + }); + + it('returns NaN if log levels are not found', () => { + expect(compareLogLevels('foo' as LogLevel, LogLevel.ERROR)).toBe(NaN); + expect(compareLogLevels(LogLevel.ERROR, 'foo' as LogLevel)).toBe(NaN); + }); +}); diff --git a/electron/common/logger/__tests__/get-log-level.test.ts b/electron/common/logger/level/__tests__/get-log-level.test.ts similarity index 92% rename from electron/common/logger/__tests__/get-log-level.test.ts rename to electron/common/logger/level/__tests__/get-log-level.test.ts index 88a04cc9..d00dbe7e 100644 --- a/electron/common/logger/__tests__/get-log-level.test.ts +++ b/electron/common/logger/level/__tests__/get-log-level.test.ts @@ -1,6 +1,6 @@ import { afterEach, describe, expect, it, vi } from 'vitest'; +import { LogLevel } from '../../types.js'; import { getLogLevel } from '../get-log-level.js'; -import { LogLevel } from '../types.js'; describe('get-log-level', () => { afterEach(() => { diff --git a/electron/common/logger/__tests__/is-log-level-enabled.test.ts b/electron/common/logger/level/__tests__/is-log-level-enabled.test.ts similarity index 98% rename from electron/common/logger/__tests__/is-log-level-enabled.test.ts rename to electron/common/logger/level/__tests__/is-log-level-enabled.test.ts index a78ccdde..3f2782ef 100644 --- a/electron/common/logger/__tests__/is-log-level-enabled.test.ts +++ b/electron/common/logger/level/__tests__/is-log-level-enabled.test.ts @@ -1,6 +1,6 @@ import { afterEach, describe, expect, it, vi } from 'vitest'; +import { LogLevel } from '../../types.js'; import { isLogLevelEnabled } from '../is-log-level-enabled.js'; -import { LogLevel } from '../types.js'; describe('is-log-level-enabled', () => { afterEach(() => { diff --git a/electron/common/logger/level/__tests__/tsconfig.json b/electron/common/logger/level/__tests__/tsconfig.json new file mode 100644 index 00000000..105334e2 --- /dev/null +++ b/electron/common/logger/level/__tests__/tsconfig.json @@ -0,0 +1,3 @@ +{ + "extends": "../../../tsconfig.test.json" +} diff --git a/electron/common/logger/level/compare-log-levels.ts b/electron/common/logger/level/compare-log-levels.ts new file mode 100644 index 00000000..24d9bb61 --- /dev/null +++ b/electron/common/logger/level/compare-log-levels.ts @@ -0,0 +1,24 @@ +import { LogLevel } from '../types.js'; + +/** + * Returns a number indicating the relative order of the two log levels. + * If the return value is less than 0, then lhs is less than rhs. + * If the return value is greater than 0, then lhs is greater than rhs. + * If the return value is 0, then lhs is equal to rhs. + * + * Example: + * `compareLogLevels(LogLevel.ERROR, LogLevel.INFO)` returns 2, which means + * that the error log level is two levels higher than the info log level. + */ +export const compareLogLevels = (lhs: LogLevel, rhs: LogLevel): number => { + const allLogLevels = Object.values(LogLevel); + const lhsIndex = allLogLevels.indexOf(lhs); + const rhsIndex = allLogLevels.indexOf(rhs); + + // If neither log level is found then unable to compare. + if (lhsIndex < 0 || rhsIndex < 0) { + return NaN; + } + + return rhsIndex - lhsIndex; +}; diff --git a/electron/common/logger/get-log-level.ts b/electron/common/logger/level/get-log-level.ts similarity index 70% rename from electron/common/logger/get-log-level.ts rename to electron/common/logger/level/get-log-level.ts index d08ce99b..aafaeb64 100644 --- a/electron/common/logger/get-log-level.ts +++ b/electron/common/logger/level/get-log-level.ts @@ -1,4 +1,4 @@ -import type { LogLevel } from './types.js'; +import type { LogLevel } from '../types.js'; export const getLogLevel = (): LogLevel => { return (process.env.LOG_LEVEL || 'info') as LogLevel; diff --git a/electron/common/logger/level/is-log-level-enabled.ts b/electron/common/logger/level/is-log-level-enabled.ts new file mode 100644 index 00000000..4cb3ef56 --- /dev/null +++ b/electron/common/logger/level/is-log-level-enabled.ts @@ -0,0 +1,20 @@ +import type { LogLevel } from '../types.js'; +import { compareLogLevels } from './compare-log-levels.js'; +import { getLogLevel } from './get-log-level.js'; + +/** + * Returns whether the given log level is enabled. + * + * For example, if the log level were set to 'info', then + * log levels 'error', 'warn', and 'info' would be enabled, but + * log levels 'debug' and 'trace' would not. + */ +export const isLogLevelEnabled = (logLevelToCheck: LogLevel): boolean => { + const result = compareLogLevels(getLogLevel(), logLevelToCheck); + + if (isNaN(result)) { + return false; + } + + return result <= 0; +}; diff --git a/electron/common/logger/logger.ts b/electron/common/logger/logger.ts new file mode 100644 index 00000000..fdadbb20 --- /dev/null +++ b/electron/common/logger/logger.ts @@ -0,0 +1,212 @@ +import { nextTick } from 'node:process'; +import { compareLogLevels } from './level/compare-log-levels.js'; +import { getLogLevel } from './level/get-log-level.js'; +import { isLogLevelEnabled } from './level/is-log-level-enabled.js'; +import type { + LogData, + LogFormatter, + LogMessage, + LogTransport, + Logger, +} from './types.js'; +import { LogLevel } from './types.js'; + +const DEFAULT_SCOPE = 'default'; +const DEFAULT_TRANSPORT: LogTransport = process.stdout; +const DEFAULT_FORMATTER: LogFormatter = (data) => JSON.stringify(data); + +/** + * Originally, I used the `electron-log` module (https://github.com/megahertz/electron-log) + * but at some point it stopped writing logs from renderer to a file. + * Possibly related to https://github.com/megahertz/electron-log/issues/441. + * After multiple attempts to fix it, I decided to implement my own logger. + */ +export class LoggerImpl implements Logger { + // To allow for asynchronous writing of logs without the use of promises + // we use a recursive-like queue draining algorithm. This provides an + // ergonomic API while still allowing for asynchronous writing. + private asyncWriteQueue = new Array(); + private asyncWriteInProgress = false; + private asyncCountdownLatch = 0; + + private scope: string; + + private transports: Array<{ + transport: LogTransport; + formatter: LogFormatter; + level?: LogLevel; + }>; + + constructor(options: { + scope?: string; + transports?: Array<{ + transport: LogTransport; + formatter: LogFormatter; + level?: LogLevel; + }>; + }) { + this.scope = options.scope ?? DEFAULT_SCOPE; + + this.transports = options.transports ?? [ + { + transport: DEFAULT_TRANSPORT, + formatter: DEFAULT_FORMATTER, + }, + ]; + + this.transports.forEach(({ transport }) => { + this.addTransportErrorListener(transport); + }); + } + + public error(message: string, data?: LogData): void { + this.log({ + level: LogLevel.ERROR, + message, + data, + }); + } + + public warn(message: string, data?: LogData): void { + this.log({ + level: LogLevel.WARN, + message, + data, + }); + } + + public info(message: string, data?: LogData): void { + this.log({ + level: LogLevel.INFO, + message, + data, + }); + } + + public debug(message: string, data?: LogData): void { + this.log({ + level: LogLevel.DEBUG, + message, + data, + }); + } + + public trace(message: string, data?: LogData): void { + this.log({ + level: LogLevel.TRACE, + message, + data, + }); + } + + public log(options: { + level: LogLevel; + message: string; + data?: LogData; + }): void { + const { level, message, data } = options; + + if (!isLogLevelEnabled(level)) { + return; + } + + // We queue messages to write then process them in the background + // to allow for asynchronous writing of logs without the use of promises + // so that the use of our logger doesn't require 'await' everywhere. + this.asyncWriteQueue.push({ + level, + message, + scope: this.scope, + timestamp: new Date(), + ...data, + }); + + // Ensure the log is written asynchronously, but soonish. + // This is to avoid blocking the main thread for too long. + nextTick(() => { + this.writeLogAsync(); + }); + } + + protected writeLogAsync(): void { + if (this.asyncWriteInProgress || this.asyncWriteQueue.length === 0) { + return; + } + + // Drain the message queue at this point in time. + // As we write to each transport, any new messages will be queued. + // Once we've written to all transports, we recheck the queue. + const messagesToLog = [...this.asyncWriteQueue]; + this.asyncWriteQueue = []; + this.asyncWriteInProgress = true; + this.asyncCountdownLatch = this.transports.length; + + for (const { transport, formatter, level } of this.transports) { + try { + // If a transport is destroyed or otherwise unusable, skip it. + // This can occur if the transport has been closed or errored. + if (!this.isTransportWritable(transport)) { + this.doneWithTransportCallback(); + continue; + } + + // If a transport does not support the log level, skip it. + if (!this.isTransportLogLevelSupported(level)) { + this.doneWithTransportCallback(); + continue; + } + + const textToWrite = formatter(messagesToLog); + + // If the write operation returns false then its internal buffer + // is nearing capacity and we should wait for the 'drain' event. + const doDrain = !transport.write(textToWrite, 'utf8'); + + if (doDrain) { + transport.once('drain', () => { + this.doneWithTransportCallback(); + }); + } else { + this.doneWithTransportCallback(); + } + } catch (error) { + this.doneWithTransportCallback(error); + } + } + } + + protected isTransportWritable(transport: LogTransport): boolean { + return transport.writable; + } + + protected isTransportLogLevelSupported(level?: LogLevel): boolean { + return !level || compareLogLevels(getLogLevel(), level) < 0; + } + + protected addTransportErrorListener(transport: LogTransport): void { + transport.on('error', (error) => { + this.doneWithTransportCallback(error); + }); + } + + protected doneWithTransportCallback(error?: Error | null): void { + if (error) { + console.error('[LOGGER:WRITE:ERROR]', error); + } + + // Mitigate when we've already written to each transport + // but the callback is invoked due to a delayed error event. + if (this.asyncCountdownLatch <= 0) { + return; + } + + this.asyncCountdownLatch -= 1; + + if (this.asyncCountdownLatch <= 0) { + this.asyncWriteInProgress = false; + nextTick(() => { + this.writeLogAsync(); + }); + } + } +} diff --git a/electron/common/logger/types.ts b/electron/common/logger/types.ts index 68bdf038..26097ab8 100644 --- a/electron/common/logger/types.ts +++ b/electron/common/logger/types.ts @@ -1,3 +1,5 @@ +import type { Writable } from 'node:stream'; + export enum LogLevel { ERROR = 'error', WARN = 'warn', @@ -6,14 +8,48 @@ export enum LogLevel { TRACE = 'trace', } -export type LogData = Record; +export type LogData = Record & { scope?: string }; + +export type LogMessage = LogData & { + scope: string; + level: LogLevel; + message: string; + timestamp: Date; +}; + +/** + * Because log messages are asynchronously written to the transports, + * your formatter may receive one or more log data objects at a time. + * Format one or more log data objects into a single string to write. + * Typically, you want to append a newline between each log entry. + */ +export type LogFormatter = (messages: Array) => string; + +/** + * Transports are writable streams. They write messages somewhere, + * whether that's to the console, to a file, or other system. + */ +export type LogTransport = Writable; + +/** + * Shape of a logger function that always logs to a specific level. + */ +export type LogLevelFunction = (message: string, data?: LogData) => void; -export type LogFunction = (message: string, data?: LogData) => void; +/** + * Shape of a logger function that can log to an arbitrary level. + */ +export type LogFunction = (options: { + level: LogLevel; + message: string; + data?: LogData; +}) => void; export interface Logger { - error: LogFunction; - warn: LogFunction; - info: LogFunction; - debug: LogFunction; - trace: LogFunction; + error: LogLevelFunction; + warn: LogLevelFunction; + info: LogLevelFunction; + debug: LogLevelFunction; + trace: LogLevelFunction; + log: LogFunction; } diff --git a/electron/main/game/game.service.ts b/electron/main/game/game.service.ts index a6c99041..e6845b7b 100644 --- a/electron/main/game/game.service.ts +++ b/electron/main/game/game.service.ts @@ -4,7 +4,7 @@ import fs from 'fs-extra'; import type * as rxjs from 'rxjs'; import { waitUntil } from '../../common/async/wait-until.js'; import type { GameEvent } from '../../common/game/types.js'; -import { isLogLevelEnabled } from '../../common/logger/is-log-level-enabled.js'; +import { isLogLevelEnabled } from '../../common/logger/level/is-log-level-enabled.js'; import { LogLevel } from '../../common/logger/types.js'; import type { SGEGameCredentials } from '../sge/types.js'; import { GameParserImpl } from './game.parser.js'; diff --git a/package.json b/package.json index cc467bcb..8a837896 100644 --- a/package.json +++ b/package.json @@ -75,6 +75,7 @@ "@sentry/nextjs": "^8.47.0", "@sentry/node": "^8.47.0", "@use-gesture/react": "^10.3.1", + "chalk": "^5.4.1", "dotenv": "^16.4.7", "dotenv-flow": "^4.1.0", "electron-extension-installer": "^1.2.0", diff --git a/yarn.lock b/yarn.lock index 4595a176..4ab57b4b 100644 --- a/yarn.lock +++ b/yarn.lock @@ -6547,6 +6547,13 @@ __metadata: languageName: node linkType: hard +"chalk@npm:^5.4.1": + version: 5.4.1 + resolution: "chalk@npm:5.4.1" + checksum: 10c0/b23e88132c702f4855ca6d25cb5538b1114343e41472d5263ee8a37cccfccd9c4216d111e1097c6a27830407a1dc81fecdf2a56f2c63033d4dbbd88c10b0dcef + languageName: node + linkType: hard + "char-regex@npm:^1.0.2": version: 1.0.2 resolution: "char-regex@npm:1.0.2" @@ -13152,6 +13159,7 @@ __metadata: "@use-gesture/react": "npm:^10.3.1" "@vitest/coverage-v8": "npm:^2.1.8" babel-loader: "npm:^9.2.1" + chalk: "npm:^5.4.1" concurrently: "npm:^9.1.0" copy-webpack-plugin: "npm:^12.0.2" dotenv: "npm:^16.4.7"