feat(logging): support logger instances

justinmk3 · justinmk3 · commit 2864cca0c5b2 · 2024-11-06T14:42:57.000-08:00
Problem:
`getLogger('foo')` returns a global singleton, so the "current topic"
only is stored until the next `getLogger` call.

Solution:
Modify `getLogger('foo')` to return a wrapper which stores its topic.
This allows modules to declare their own module-local shared logger:

    const logger = getLogger('foo')
diff --git a/packages/core/src/shared/logger/logger.ts b/packages/core/src/shared/logger/logger.ts
@@ -4,6 +4,7 @@
  */
 
 import * as vscode from 'vscode'
+import { ToolkitLogger, TopicLogger } from './toolkitLogger'
 
 export type LogTopic = 'crashReport' | 'notifications' | 'test' | 'unknown'
 
@@ -36,10 +37,6 @@ export abstract class BaseLogger implements Logger {
     logFile?: vscode.Uri
     topic: LogTopic = 'unknown'
 
-    setTopic(topic: LogTopic = 'unknown') {
-        this.topic = topic
-    }
-
     debug(message: string | Error, ...meta: any[]): number {
         return this.sendToLog('debug', message, ...meta)
     }
@@ -131,17 +128,15 @@ export function getLogger(topic?: LogTopic): Logger {
     if (!logger) {
         return new ConsoleLogger()
     }
-    ;(logger as BaseLogger).setTopic?.(topic)
-    return logger
+    return new TopicLogger(topic ?? 'unknown', logger as ToolkitLogger)
 }
 
 export function getDebugConsoleLogger(topic?: LogTopic): Logger {
     const logger = toolkitLoggers['debugConsole']
     if (!logger) {
         return new ConsoleLogger()
     }
-    ;(logger as BaseLogger).setTopic?.(topic)
-    return logger
+    return new TopicLogger(topic ?? 'unknown', logger as ToolkitLogger)
 }
 
 // jscpd:ignore-start
diff --git a/packages/core/src/shared/logger/toolkitLogger.ts b/packages/core/src/shared/logger/toolkitLogger.ts
@@ -6,7 +6,7 @@
 import { normalize } from 'path'
 import * as vscode from 'vscode'
 import winston from 'winston'
-import { BaseLogger, LogLevel, compareLogLevel } from './logger'
+import { BaseLogger, LogLevel, LogTopic, compareLogLevel } from './logger'
 import { OutputChannelTransport } from './outputChannelTransport'
 import { isSourceMappingAvailable } from '../vscode/env'
 import { formatError, ToolkitError, UnknownError } from '../errors'
@@ -21,12 +21,26 @@ class ErrorLog {
     ) {}
 }
 
+/* Format the message with topic header */
+function prependTopic(topic: string, message: string | Error): string | ErrorLog {
+    if (typeof message === 'string') {
+        // TODO: remove this after all calls are migrated and topic is a required param.
+        if (topic === 'unknown') {
+            return message
+        }
+        return `${topic}: ` + message
+    } else if (message instanceof Error) {
+        return new ErrorLog(topic, message)
+    }
+    return message
+}
+
 // Need to limit how many logs are actually tracked
 // LRU cache would work well, currently it just dumps the least recently added log
 const logmapSize: number = 1000
+
 export class ToolkitLogger extends BaseLogger implements vscode.Disposable {
     private readonly logger: winston.Logger
-    /* topic is used for header in log messages, default is 'Unknown' */
     private disposed: boolean = false
     private idCounter: number = 0
     private logMap: { [logID: number]: { [filePath: string]: string } } = {}
@@ -111,20 +125,6 @@ export class ToolkitLogger extends BaseLogger implements vscode.Disposable {
               })
     }
 
-    /* Format the message with topic header */
-    private addTopicToMessage(message: string | Error): string | ErrorLog {
-        if (typeof message === 'string') {
-            // TODO: remove this after all calls are migrated and topic is a required param.
-            if (this.topic === 'unknown') {
-                return message
-            }
-            return `${this.topic}: ` + message
-        } else if (message instanceof Error) {
-            return new ErrorLog(this.topic, message)
-        }
-        return message
-    }
-
     private mapError(level: LogLevel, err: Error): Error | string {
         // Use ToolkitError.trace even if we have source mapping (see below), because:
         // 1. it is what users will see, we want visibility into that when debugging
@@ -141,17 +141,16 @@ export class ToolkitLogger extends BaseLogger implements vscode.Disposable {
     }
 
     override sendToLog(level: LogLevel, message: string | Error, ...meta: any[]): number {
-        const messageWithTopic = this.addTopicToMessage(message)
         if (this.disposed) {
             throw new Error('Cannot write to disposed logger')
         }
 
         meta = meta.map((o) => (o instanceof Error ? this.mapError(level, o) : o))
 
-        if (messageWithTopic instanceof ErrorLog) {
-            this.logger.log(level, '%O', messageWithTopic, ...meta, { logID: this.idCounter })
+        if (message instanceof Error) {
+            this.logger.log(level, '%O', message, ...meta, { logID: this.idCounter })
         } else {
-            this.logger.log(level, messageWithTopic, ...meta, { logID: this.idCounter })
+            this.logger.log(level, message, ...meta, { logID: this.idCounter })
         }
 
         this.logMap[this.idCounter % logmapSize] = {}
@@ -200,3 +199,44 @@ export class ToolkitLogger extends BaseLogger implements vscode.Disposable {
         }
     }
 }
+
+/**
+ * Wraps a `ToolkitLogger` and defers to it for everything except `topic`.
+ */
+export class TopicLogger extends BaseLogger implements vscode.Disposable {
+    /**
+     * Wraps a `ToolkitLogger` and defers to it for everything except `topic`.
+     */
+    public constructor(
+        topic: LogTopic,
+        private logger: ToolkitLogger
+    ) {
+        super()
+        this.topic = topic
+    }
+
+    override setLogLevel(logLevel: LogLevel): void {
+        this.logger.setLogLevel(logLevel)
+    }
+
+    override logLevelEnabled(logLevel: LogLevel): boolean {
+        return this.logger.logLevelEnabled(logLevel)
+    }
+
+    override getLogById(logID: number, file: vscode.Uri): string | undefined {
+        return this.logger.getLogById(logID, file)
+    }
+
+    override enableDebugConsole(): void {
+        this.logger.enableDebugConsole()
+    }
+
+    override sendToLog(level: LogLevel, message: string | Error, ...meta: any[]): number {
+        if (typeof message === 'string') {
+            message = prependTopic(this.topic, message) as string
+        }
+        return this.logger.sendToLog(level, message, meta)
+    }
+
+    public async dispose(): Promise<void> {}
+}
diff --git a/packages/core/src/test/shared/logger/toolkitLogger.test.ts b/packages/core/src/test/shared/logger/toolkitLogger.test.ts
@@ -10,7 +10,8 @@ import * as vscode from 'vscode'
 import { ToolkitLogger } from '../../../shared/logger/toolkitLogger'
 import { MockOutputChannel } from '../../mockOutputChannel'
 import { sleep, waitUntil } from '../../../shared/utilities/timeoutUtils'
-import { ToolkitError } from '../../../shared/errors'
+import { getLogger } from '../../../shared/logger'
+import { assertLogsContain } from '../../globalSetup.test'
 
 /**
  * Disposes the logger then waits for the write streams to flush. The `expected` and `unexpected` arrays just look
@@ -240,55 +241,20 @@ describe('ToolkitLogger', function () {
         })
 
         it('prepends topic to message', async function () {
-            testLogger = new ToolkitLogger('info')
-            testLogger.logToOutputChannel(outputChannel, false)
-            testLogger.setTopic('test')
-            testLogger.setLogLevel('verbose')
-
-            const testMessageWithHeader = 'test: This is a test message'
-            testLogger.verbose('This is a test message')
-            assert.ok(
-                (await waitForLoggedTextByContents(testMessageWithHeader)).includes(testMessageWithHeader),
-                'Expected header added'
-            )
-
-            const msg = "topic: 'test'"
-            testLogger.verbose(new ToolkitError('root error', { code: 'something went wrong' }))
-            assert.ok((await waitForLoggedTextByContents(msg)).includes(msg), 'Expected header added')
-
-            const msg2 = "topic: 'test'"
-            testLogger.verbose(new ToolkitError('root error', { code: 'something went wrong' }))
-            assert.ok((await waitForLoggedTextByContents(msg2)).includes(msg2), 'Expected header added')
-        })
-
-        it('unknown topic header ignored in message', async function () {
-            const testMessage = 'This is a test message'
-            const unknowntestMessage = 'unknown: This is a test message'
+            const logger = getLogger('notifications')
+            logger.setLogLevel('verbose')
 
-            testLogger = new ToolkitLogger('info')
-            testLogger.logToOutputChannel(outputChannel, false)
-            testLogger.setTopic('unknown')
-            testLogger.setLogLevel('verbose')
-            testLogger.verbose(testMessage)
-
-            const waitForMessage = waitForLoggedTextByContents(testMessage)
-            assert.ok((await waitForMessage).includes(testMessage), 'Expected message logged')
-            assert.ok(!(await waitForMessage).includes(unknowntestMessage), 'unexpected header in log')
-        })
+            logger.verbose('This is a test message')
+            assertLogsContain('notifications: This is a test message', true, 'verbose')
 
-        it('switch topic on same logger', async function () {
-            const testMessage = 'This is a test message'
-            const testMessageWithHeader = 'test: This is a test message'
-
-            testLogger = new ToolkitLogger('info')
-            testLogger.logToOutputChannel(outputChannel, false)
-            testLogger.setTopic('unknown')
-            testLogger.setTopic('test')
-            testLogger.setLogLevel('verbose')
-            testLogger.verbose(testMessage)
+            // const msg2 = "topic: 'test'"
+            // logger.verbose(new ToolkitError('root error', { code: 'something went wrong' }))
+            // assertLogsContain("topic: 'something went wrong'", true, 'verbose')
 
-            const waitForMessage = waitForLoggedTextByContents(testMessageWithHeader)
-            assert.ok((await waitForMessage).includes(testMessageWithHeader), 'Expected header added')
+            // 'unknown' is not prepended
+            const logger3 = getLogger('unknown')
+            logger3.verbose('This is a test message')
+            assertLogsContain('This is a test message', true, 'verbose')
         })
 
         happyLogScenarios.forEach((scenario) => {
