Log non-strings into log file like console.log does

server/Logger.js

@@ -1,5 +1,6 @@
 const date = require('./libs/dateAndTime')
 const { LogLevel } = require('./utils/constants')
+const util = require('util')
 
 class Logger {
   constructor() {
@@ -69,15 +70,17 @@ class Logger {
   /**
    *
    * @param {number} level
+   * @param {string} levelName
    * @param {string[]} args
    * @param {string} src
    */
-  async handleLog(level, args, src) {
+  async #logToFileAndListeners(level, levelName, args, src) {
+    const expandedArgs = args.map((arg) => (typeof arg !== 'string' ? util.inspect(arg) : arg))
     const logObj = {
       timestamp: this.timestamp,
       source: src,
-      message: args.join(' '),
+      message: expandedArgs.join(' '),
-      levelName: this.getLogLevelString(level),
+      levelName,
       level
     }
 
@@ -89,7 +92,7 @@ class Logger {
     })
 
     // Save log to file
-    if (level >= this.logLevel) {
+    if (level >= LogLevel.FATAL || level >= this.logLevel) {
       await this.logManager?.logToFile(logObj)
     }
   }
@@ -99,50 +102,50 @@ class Logger {
     this.debug(`Set Log Level to ${this.levelString}`)
   }
 
+  static ConsoleMethods = {
+    TRACE: 'trace',
+    DEBUG: 'debug',
+    INFO: 'info',
+    WARN: 'warn',
+    ERROR: 'error',
+    FATAL: 'error',
+    NOTE: 'log'
+  }
+
+  #log(levelName, source, ...args) {
+    const level = LogLevel[levelName]
+    if (level < LogLevel.FATAL && level < this.logLevel) return
+    const consoleMethod = Logger.ConsoleMethods[levelName]
+    console[consoleMethod](`[${this.timestamp}] ${levelName}:`, ...args)
+    this.#logToFileAndListeners(level, levelName, args, source)
+  }
+
   trace(...args) {
-    if (this.logLevel > LogLevel.TRACE) return
+    this.#log('TRACE', this.source, ...args)
-    console.trace(`[${this.timestamp}] TRACE:`, ...args)
-    this.handleLog(LogLevel.TRACE, args, this.source)
   }
 
   debug(...args) {
-    if (this.logLevel > LogLevel.DEBUG) return
+    this.#log('DEBUG', this.source, ...args)
-    console.debug(`[${this.timestamp}] DEBUG:`, ...args, `(${this.source})`)
-    this.handleLog(LogLevel.DEBUG, args, this.source)
   }
 
   info(...args) {
-    if (this.logLevel > LogLevel.INFO) return
+    this.#log('INFO', this.source, ...args)
-    console.info(`[${this.timestamp}] INFO:`, ...args)
-    this.handleLog(LogLevel.INFO, args, this.source)
   }
 
   warn(...args) {
-    if (this.logLevel > LogLevel.WARN) return
+    this.#log('WARN', this.source, ...args)
-    console.warn(`[${this.timestamp}] WARN:`, ...args, `(${this.source})`)
-    this.handleLog(LogLevel.WARN, args, this.source)
   }
 
   error(...args) {
-    if (this.logLevel > LogLevel.ERROR) return
+    this.#log('ERROR', this.source, ...args)
-    console.error(`[${this.timestamp}] ERROR:`, ...args, `(${this.source})`)
-    this.handleLog(LogLevel.ERROR, args, this.source)
   }
 
-  /**
-   * Fatal errors are ones that exit the process
-   * Fatal logs are saved to crash_logs.txt
-   *
-   * @param  {...any} args
-   */
   fatal(...args) {
-    console.error(`[${this.timestamp}] FATAL:`, ...args, `(${this.source})`)
+    this.#log('FATAL', this.source, ...args)
-    return this.handleLog(LogLevel.FATAL, args, this.source)
   }
 
   note(...args) {
-    console.log(`[${this.timestamp}] NOTE:`, ...args)
+    this.#log('NOTE', this.source, ...args)
-    this.handleLog(LogLevel.NOTE, args, this.source)
   }
 }
 module.exports = new Logger()

test/server/Logger.test.js

@@ -0,0 +1,285 @@
+const { expect } = require('chai')
+const sinon = require('sinon')
+const Logger = require('../../server/Logger') // Adjust the path as needed
+const { LogLevel } = require('../../server/utils/constants')
+const date = require('../../server/libs/dateAndTime')
+const util = require('util')
+
+describe('Logger', function () {
+  let consoleTraceStub
+  let consoleDebugStub
+  let consoleInfoStub
+  let consoleWarnStub
+  let consoleErrorStub
+  let consoleLogStub
+
+  beforeEach(function () {
+    // Stub the date format function to return a consistent timestamp
+    sinon.stub(date, 'format').returns('2024-09-10 12:34:56.789')
+    // Stub the source getter to return a consistent source
+    sinon.stub(Logger, 'source').get(() => 'some/source.js')
+    // Stub the console methods used in Logger
+    consoleTraceStub = sinon.stub(console, 'trace')
+    consoleDebugStub = sinon.stub(console, 'debug')
+    consoleInfoStub = sinon.stub(console, 'info')
+    consoleWarnStub = sinon.stub(console, 'warn')
+    consoleErrorStub = sinon.stub(console, 'error')
+    consoleLogStub = sinon.stub(console, 'log')
+    // Initialize the Logger's logManager as a mock object
+    Logger.logManager = {
+      logToFile: sinon.stub().resolves()
+    }
+  })
+
+  afterEach(function () {
+    sinon.restore()
+  })
+
+  describe('logging methods', function () {
+    it('should have a method for each log level defined in the static block', function () {
+      const loggerMethods = Object.keys(LogLevel).map((key) => key.toLowerCase())
+
+      loggerMethods.forEach((method) => {
+        expect(Logger).to.have.property(method).that.is.a('function')
+      })
+    })
+
+    it('should call console.trace for trace logging', function () {
+      // Arrange
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.trace('Test message')
+
+      // Assert
+      expect(consoleTraceStub.calledOnce).to.be.true
+    })
+
+    it('should call console.debug for debug logging', function () {
+      // Arrange
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.debug('Test message')
+
+      // Assert
+      expect(consoleDebugStub.calledOnce).to.be.true
+    })
+
+    it('should call console.info for info logging', function () {
+      // Arrange
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.info('Test message')
+
+      // Assert
+      expect(consoleInfoStub.calledOnce).to.be.true
+    })
+
+    it('should call console.warn for warn logging', function () {
+      // Arrange
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.warn('Test message')
+
+      // Assert
+      expect(consoleWarnStub.calledOnce).to.be.true
+    })
+
+    it('should call console.error for error logging', function () {
+      // Arrange
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.error('Test message')
+
+      // Assert
+      expect(consoleErrorStub.calledOnce).to.be.true
+    })
+
+    it('should call console.error for fatal logging', function () {
+      // Arrange
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.fatal('Test message')
+
+      // Assert
+      expect(consoleErrorStub.calledOnce).to.be.true
+    })
+
+    it('should call console.log for note logging', function () {
+      // Arrange
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.note('Test message')
+
+      // Assert
+      expect(consoleLogStub.calledOnce).to.be.true
+    })
+  })
+
+  describe('#log', function () {
+    it('should log to console and file if level is high enough', async function () {
+      // Arrange
+      const logArgs = ['Test message']
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      Logger.debug(...logArgs)
+
+      expect(consoleDebugStub.calledOnce).to.be.true
+      expect(consoleDebugStub.calledWithExactly('[2024-09-10 12:34:56.789] DEBUG:', ...logArgs)).to.be.true
+      expect(Logger.logManager.logToFile.calledOnce).to.be.true
+      expect(
+        Logger.logManager.logToFile.calledWithExactly({
+          timestamp: '2024-09-10 12:34:56.789',
+          source: 'some/source.js',
+          message: 'Test message',
+          levelName: 'DEBUG',
+          level: LogLevel.DEBUG
+        })
+      ).to.be.true
+    })
+
+    it('should not log if log level is too low', function () {
+      // Arrange
+      const logArgs = ['This log should not appear']
+      // Set log level to ERROR, so DEBUG log should be ignored
+      Logger.logLevel = LogLevel.ERROR
+
+      // Act
+      Logger.debug(...logArgs)
+
+      // Verify console.debug is not called
+      expect(consoleDebugStub.called).to.be.false
+      expect(Logger.logManager.logToFile.called).to.be.false
+    })
+
+    it('should emit log to all connected sockets with appropriate log level', async function () {
+      // Arrange
+      const socket1 = { id: '1', emit: sinon.spy() }
+      const socket2 = { id: '2', emit: sinon.spy() }
+      Logger.addSocketListener(socket1, LogLevel.DEBUG)
+      Logger.addSocketListener(socket2, LogLevel.ERROR)
+      const logArgs = ['Socket test']
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      await Logger.debug(...logArgs)
+
+      // socket1 should receive the log, but not socket2
+      expect(socket1.emit.calledOnce).to.be.true
+      expect(
+        socket1.emit.calledWithExactly('log', {
+          timestamp: '2024-09-10 12:34:56.789',
+          source: 'some/source.js',
+          message: 'Socket test',
+          levelName: 'DEBUG',
+          level: LogLevel.DEBUG
+        })
+      ).to.be.true
+
+      expect(socket2.emit.called).to.be.false
+    })
+
+    it('should log fatal messages to console and file regardless of log level', async function () {
+      // Arrange
+      const logArgs = ['Fatal error']
+      // Set log level to NOTE + 1, so nothing should be logged
+      Logger.logLevel = LogLevel.NOTE + 1
+
+      // Act
+      await Logger.fatal(...logArgs)
+
+      // Assert
+      expect(consoleErrorStub.calledOnce).to.be.true
+      expect(consoleErrorStub.calledWithExactly('[2024-09-10 12:34:56.789] FATAL:', ...logArgs)).to.be.true
+      expect(Logger.logManager.logToFile.calledOnce).to.be.true
+      expect(
+        Logger.logManager.logToFile.calledWithExactly({
+          timestamp: '2024-09-10 12:34:56.789',
+          source: 'some/source.js',
+          message: 'Fatal error',
+          levelName: 'FATAL',
+          level: LogLevel.FATAL
+        })
+      ).to.be.true
+    })
+
+    it('should log note messages to console and file regardless of log level', async function () {
+      // Arrange
+      const logArgs = ['Note message']
+      // Set log level to NOTE + 1, so nothing should be logged
+      Logger.logLevel = LogLevel.NOTE + 1
+
+      // Act
+      await Logger.note(...logArgs)
+
+      // Assert
+      expect(consoleLogStub.calledOnce).to.be.true
+      expect(consoleLogStub.calledWithExactly('[2024-09-10 12:34:56.789] NOTE:', ...logArgs)).to.be.true
+      expect(Logger.logManager.logToFile.calledOnce).to.be.true
+      expect(
+        Logger.logManager.logToFile.calledWithExactly({
+          timestamp: '2024-09-10 12:34:56.789',
+          source: 'some/source.js',
+          message: 'Note message',
+          levelName: 'NOTE',
+          level: LogLevel.NOTE
+        })
+      ).to.be.true
+    })
+
+    it('should log util.inspect(arg) for non-string objects', async function () {
+      // Arrange
+      const obj = { key: 'value' }
+      const logArgs = ['Logging object:', obj]
+      Logger.logLevel = LogLevel.TRACE
+
+      // Act
+      await Logger.debug(...logArgs)
+
+      // Assert
+      expect(consoleDebugStub.calledOnce).to.be.true
+      expect(consoleDebugStub.calledWithExactly('[2024-09-10 12:34:56.789] DEBUG:', 'Logging object:', obj)).to.be.true
+      expect(Logger.logManager.logToFile.calledOnce).to.be.true
+      expect(Logger.logManager.logToFile.firstCall.args[0].message).to.equal('Logging object: ' + util.inspect(obj))
+    })
+  })
+
+  describe('socket listeners', function () {
+    it('should add and remove socket listeners', function () {
+      // Arrange
+      const socket1 = { id: '1', emit: sinon.spy() }
+      const socket2 = { id: '2', emit: sinon.spy() }
+
+      // Act
+      Logger.addSocketListener(socket1, LogLevel.DEBUG)
+      Logger.addSocketListener(socket2, LogLevel.ERROR)
+      Logger.removeSocketListener('1')
+
+      // Assert
+      expect(Logger.socketListeners).to.have.lengthOf(1)
+      expect(Logger.socketListeners[0].id).to.equal('2')
+    })
+  })
+
+  describe('setLogLevel', function () {
+    it('should change the log level and log the new level', function () {
+      // Arrange
+      const debugSpy = sinon.spy(Logger, 'debug')
+
+      // Act
+      Logger.setLogLevel(LogLevel.WARN)
+
+      // Assert
+      expect(Logger.logLevel).to.equal(LogLevel.WARN)
+      expect(debugSpy.calledOnce).to.be.true
+      expect(debugSpy.calledWithExactly('Set Log Level to WARN')).to.be.true
+    })
+  })
+})