fix(logging): logger functions do not handle varargs (#5680)

Problem:
Regression b2ebc10 in the logger: `debug('%s %s', foo, bar')`
sends `foo, bar` as a single `[foo, bar]` list to the first `%s`.
Example:

2024-09-26 12:18:29.631 [debug] getClientId: determined clientId as: [
      '96be923b-a00d-46d4-add1-c877abfcb01c',
      undefined,
      '96be923b-a00d-46d4-add1-c877abfcb01c'
    ], process.env clientId was: { logID: 1 }, stored clientId was: %s

Solution:
Spread the args when passing to sendToLog().

Author: justinmk3

packages/core/src/shared/logger/logger.ts

@@ -28,19 +28,19 @@ export interface Logger {
 
 export abstract class BaseLogger implements Logger {
     debug(message: string | Error, ...meta: any[]): number {
-        return this.sendToLog('debug', message, meta)
+        return this.sendToLog('debug', message, ...meta)
     }
     verbose(message: string | Error, ...meta: any[]): number {
-        return this.sendToLog('verbose', message, meta)
+        return this.sendToLog('verbose', message, ...meta)
     }
     info(message: string | Error, ...meta: any[]): number {
-        return this.sendToLog('info', message, meta)
+        return this.sendToLog('info', message, ...meta)
     }
     warn(message: string | Error, ...meta: any[]): number {
-        return this.sendToLog('warn', message, meta)
+        return this.sendToLog('warn', message, ...meta)
     }
     error(message: string | Error, ...meta: any[]): number {
-        return this.sendToLog('error', message, meta)
+        return this.sendToLog('error', message, ...meta)
     }
     log(logLevel: LogLevel, message: string | Error, ...meta: any[]): number {
         return this.sendToLog(logLevel, message, ...meta)

packages/core/src/test/globalSetup.test.ts

@@ -157,6 +157,7 @@ function writeLogsToFile(testName: string) {
     appendFileSync(testLogOutput, entries?.join('\n') ?? '', 'utf8')
 }
 
+// TODO: merge this with `toolkitLogger.test.ts:checkFile`
 export function assertLogsContain(text: string, exactMatch: boolean, severity: LogLevel) {
     assert.ok(
         getTestLogger()

packages/core/src/test/shared/logger/toolkitLogger.test.ts

@@ -16,6 +16,8 @@ import { ToolkitError } from '../../../shared/errors'
  * Disposes the logger then waits for the write streams to flush. The `expected` and `unexpected` arrays just look
  * for any occurence within the file, passing if all expected strings were found or failing if any unexpected strings
  * were found.
+ *
+ * TODO: merge this with `globalSetup.test.ts:assertLogsContain`
  */
 async function checkFile(
     logger: ToolkitLogger,
@@ -34,18 +36,22 @@ async function checkFile(
         const contents = fs.readFileSync(logPath.fsPath)
 
         // Error if unexpected messages are in the log file
-        const explicitUnexpectedMessages = unexpected
+        const foundUnexpected = unexpected
             .filter((t) => contents.includes(t))
             .reduce((a, b) => a + `Unexpected message in log: ${b}\n`, '')
-        if (explicitUnexpectedMessages) {
-            return reject(new Error(explicitUnexpectedMessages))
+        if (foundUnexpected) {
+            return reject(new Error(foundUnexpected))
         }
 
-        // Error if any of the expected messages are not in the log file
-        const expectedMessagesNotInLogFile = expected.filter((t) => !contents.includes(t))
-        if (expectedMessagesNotInLogFile.length > 0) {
+        // Fail if any of the expected messages are not in the log file
+        const notFound = expected.filter((t) => !contents.includes(t))
+        if (notFound.length > 0) {
+            const last10Lines = contents.toString().split('\n').slice(-10)
             reject(
-                new Error(expectedMessagesNotInLogFile.reduce((a, b) => a + `Unexpected message in log: ${b}\n`, ''))
+                new Error(
+                    notFound.reduce((a, b) => a + `Expected message not found in log: ${b}\n`, '') +
+                        `\n\n Last 10 log lines:\n${last10Lines.join('\n')}`
+                )
             )
         }
 
@@ -106,32 +112,32 @@ describe('ToolkitLogger', function () {
     const happyLogScenarios = [
         {
             name: 'logs debug',
-            logMessage: (logger: ToolkitLogger, message: string) => {
-                logger.debug(message)
+            logMessage: (logger: ToolkitLogger, msg: string, args: any[]) => {
+                logger.debug(msg, ...args)
             },
         },
         {
             name: 'logs verbose',
-            logMessage: (logger: ToolkitLogger, message: string) => {
-                logger.verbose(message)
+            logMessage: (logger: ToolkitLogger, msg: string, args: any[]) => {
+                logger.verbose(msg, ...args)
             },
         },
         {
             name: 'logs info',
-            logMessage: (logger: ToolkitLogger, message: string) => {
-                logger.info(message)
+            logMessage: (logger: ToolkitLogger, msg: string, args: any[]) => {
+                logger.info(msg, ...args)
             },
         },
         {
             name: 'logs warn',
-            logMessage: (logger: ToolkitLogger, message: string) => {
-                logger.warn(message)
+            logMessage: (logger: ToolkitLogger, msg: string, args: any[]) => {
+                logger.warn(msg, ...args)
             },
         },
         {
             name: 'logs error',
-            logMessage: (logger: ToolkitLogger, message: string) => {
-                logger.error(message)
+            logMessage: (logger: ToolkitLogger, msg: string, args: any[]) => {
+                logger.error(msg, ...args)
             },
         },
     ]
@@ -174,13 +180,15 @@ describe('ToolkitLogger', function () {
 
         happyLogScenarios.forEach((scenario) => {
             it(scenario.name, async () => {
-                const message = `message for ${scenario.name}`
+                const msg = `message for ${scenario.name} arg1 %s, arg2 %O`
+                const args = [42, ['a', 'b']]
+                const expectedMsg = `message for ${scenario.name} arg1 42, arg2 [ 'a', 'b' ]`
                 testLogger = new ToolkitLogger('debug')
                 testLogger.logToFile(tempLogPath)
 
-                scenario.logMessage(testLogger, message)
+                scenario.logMessage(testLogger, msg, args)
 
-                await checkFile(testLogger, tempLogPath, [message])
+                await checkFile(testLogger, tempLogPath, [expectedMsg])
             })
         })
     })
@@ -297,7 +305,7 @@ describe('ToolkitLogger', function () {
 
                 const waitForMessage = waitForLoggedTextByCount(1)
 
-                scenario.logMessage(testLogger, message)
+                scenario.logMessage(testLogger, message, [])
 
                 assert.ok((await waitForMessage).includes(message), 'Expected error message to be logged')
             })