Update:Log uncaught exceptions to crash_logs.txt #706 & cleanup logger

2024-12-20 19:06:06 +01:00 · 2024-02-15 16:46:19 -06:00 · 2024-02-15 16:46:19 -06:00 · af7cb2432b
commit af7cb2432b
parent 04d16fc535
9 changed files with 223 additions and 107 deletions
--- a/client/pages/config/log.vue
+++ b/client/pages/config/log.vue
@ -8,7 +8,7 @@
      </div>

      <div class="relative">
-        <div ref="container" class="relative w-full h-full bg-primary border-bg overflow-x-hidden overflow-y-auto text-red shadow-inner rounded-md" style="max-height: 800px; min-height: 550px">
+        <div ref="container" id="log-container" class="relative w-full h-full bg-primary border-bg overflow-x-hidden overflow-y-auto text-red shadow-inner rounded-md" style="min-height: 550px">
          <template v-for="(log, index) in logs">
            <div :key="index" class="flex flex-nowrap px-2 py-1 items-start text-sm bg-opacity-10" :class="`bg-${logColors[log.level]}`">
              <p class="text-gray-400 w-36 font-mono text-xs">{{ log.timestamp }}</p>
@ -136,7 +136,15 @@ export default {
        this.loadedLogs = this.loadedLogs.slice(-5000)
      }
    },
-    init(attempts = 0) {
+    async loadLoggerData() {
+      const loggerData = await this.$axios.$get('/api/logger-data').catch((error) => {
+        console.error('Failed to load logger data', error)
+        this.$toast.error('Failed to load logger data')
+      })
+
+      this.loadedLogs = loggerData?.currentDailyLogs || []
+    },
+    async init(attempts = 0) {
      if (!this.$root.socket) {
        if (attempts > 10) {
          return console.error('Failed to setup socket listeners')
@ -147,14 +155,11 @@ export default {
        return
      }

+      await this.loadLoggerData()
+
      this.newServerSettings = this.serverSettings ? { ...this.serverSettings } : {}
-      this.$root.socket.on('daily_logs', this.dailyLogsLoaded)
      this.$root.socket.on('log', this.logEvtReceived)
      this.$root.socket.emit('set_log_listener', this.newServerSettings.logLevel)
-      this.$root.socket.emit('fetch_daily_logs')
-    },
-    dailyLogsLoaded(lines) {
-      this.loadedLogs = lines
    }
  },
  updated() {
@ -166,13 +171,15 @@ export default {
  beforeDestroy() {
    if (!this.$root.socket) return
    this.$root.socket.emit('remove_log_listener')
-    this.$root.socket.off('daily_logs', this.dailyLogsLoaded)
    this.$root.socket.off('log', this.logEvtReceived)
  }
 }
 </script>

 <style scoped>
+#log-container {
+  height: calc(100vh - 285px);
+}
 .logmessage {
  width: calc(100% - 208px);
 }
--- a/server/Logger.js
+++ b/server/Logger.js
@ -3,13 +3,17 @@ const { LogLevel } = require('./utils/constants')

 class Logger {
  constructor() {
+    /** @type {import('./managers/LogManager')} */
+    this.logManager = null
+
    this.isDev = process.env.NODE_ENV !== 'production'
    this.logLevel = !this.isDev ? LogLevel.INFO : LogLevel.TRACE
    this.socketListeners = []
-
-    this.logManager = null
  }

+  /**
+   * @returns {string}
+   */
  get timestamp() {
    return date.format(new Date(), 'YYYY-MM-DD HH:mm:ss.SSS')
  }
@ -23,6 +27,9 @@ class Logger {
    return 'UNKNOWN'
  }

+  /**
+   * @returns {string}
+   */
  get source() {
    try {
      throw new Error()
@ -62,7 +69,12 @@ class Logger {
    this.socketListeners = this.socketListeners.filter(s => s.id !== socketId)
  }

-  handleLog(level, args) {
+  /**
+   * 
+   * @param {number} level 
+   * @param {string[]} args 
+   */
+  async handleLog(level, args) {
    const logObj = {
      timestamp: this.timestamp,
      source: this.source,
@ -71,15 +83,17 @@ class Logger {
      level
    }

-    if (level >= this.logLevel && this.logManager) {
-      this.logManager.logToFile(logObj)
-    }
-
+    // Emit log to sockets that are listening to log events
    this.socketListeners.forEach((socketListener) => {
      if (socketListener.level <= level) {
        socketListener.socket.emit('log', logObj)
      }
    })
+
+    // Save log to file
+    if (level >= this.logLevel) {
+      await this.logManager.logToFile(logObj)
+    }
  }

  setLogLevel(level) {
@ -117,9 +131,15 @@ class Logger {
    this.handleLog(LogLevel.ERROR, args)
  }

+  /**
+   * 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.handleLog(LogLevel.FATAL, args)
+    return this.handleLog(LogLevel.FATAL, args)
  }

  note(...args) {
--- a/server/Server.js
+++ b/server/Server.js
@ -2,6 +2,7 @@ const Path = require('path')
 const Sequelize = require('sequelize')
 const express = require('express')
 const http = require('http')
+const util = require('util')
 const fs = require('./libs/fsExtra')
 const fileUpload = require('./libs/expressFileupload')
 const rateLimit = require('./libs/expressRateLimit')
@ -21,11 +22,11 @@ const SocketAuthority = require('./SocketAuthority')
 const ApiRouter = require('./routers/ApiRouter')
 const HlsRouter = require('./routers/HlsRouter')

+const LogManager = require('./managers/LogManager')
 const NotificationManager = require('./managers/NotificationManager')
 const EmailManager = require('./managers/EmailManager')
 const AbMergeManager = require('./managers/AbMergeManager')
 const CacheManager = require('./managers/CacheManager')
-const LogManager = require('./managers/LogManager')
 const BackupManager = require('./managers/BackupManager')
 const PlaybackSessionManager = require('./managers/PlaybackSessionManager')
 const PodcastManager = require('./managers/PodcastManager')
@ -67,7 +68,6 @@ class Server {
    this.notificationManager = new NotificationManager()
    this.emailManager = new EmailManager()
    this.backupManager = new BackupManager()
-    this.logManager = new LogManager()
    this.abMergeManager = new AbMergeManager()
    this.playbackSessionManager = new PlaybackSessionManager()
    this.podcastManager = new PodcastManager(this.watcher, this.notificationManager)
@ -81,7 +81,7 @@ class Server {
    this.apiRouter = new ApiRouter(this)
    this.hlsRouter = new HlsRouter(this.auth, this.playbackSessionManager)

-    Logger.logManager = this.logManager
+    Logger.logManager = new LogManager()

    this.server = null
    this.io = null
@ -102,10 +102,13 @@ class Server {
   */
  async init() {
    Logger.info('[Server] Init v' + version)
+
    await this.playbackSessionManager.removeOrphanStreams()

    await Database.init(false)

+    await Logger.logManager.init()
+
    // Create token secret if does not exist (Added v2.1.0)
    if (!Database.serverSettings.tokenSecret) {
      await this.auth.initTokenSecret()
@ -115,7 +118,6 @@ class Server {
    await CacheManager.ensureCachePaths()

    await this.backupManager.init()
-    await this.logManager.init()
    await this.rssFeedManager.init()

    const libraries = await Database.libraryModel.getAllOldLibraries()
@ -135,8 +137,41 @@ class Server {
    }
  }

+  /**
+   * Listen for SIGINT and uncaught exceptions
+   */
+  initProcessEventListeners() {
+    let sigintAlreadyReceived = false
+    process.on('SIGINT', async () => {
+      if (!sigintAlreadyReceived) {
+        sigintAlreadyReceived = true
+        Logger.info('SIGINT (Ctrl+C) received. Shutting down...')
+        await this.stop()
+        Logger.info('Server stopped. Exiting.')
+      } else {
+        Logger.info('SIGINT (Ctrl+C) received again. Exiting immediately.')
+      }
+      process.exit(0)
+    })
+
+    /**
+     * @see https://nodejs.org/api/process.html#event-uncaughtexceptionmonitor
+     */
+    process.on('uncaughtExceptionMonitor', async (error, origin) => {
+      await Logger.fatal(`[Server] Uncaught exception origin: ${origin}, error:`, util.format('%O', error))
+    })
+    /**
+     * @see https://nodejs.org/api/process.html#event-unhandledrejection
+     */
+    process.on('unhandledRejection', async (reason, promise) => {
+      await Logger.fatal(`[Server] Unhandled rejection: ${reason}, promise:`, util.format('%O', promise))
+      process.exit(1)
+    })
+  }
+
  async start() {
    Logger.info('=== Starting Server ===')
+    this.initProcessEventListeners()
    await this.init()

    const app = express()
@ -284,19 +319,6 @@ class Server {
    })
    app.get('/healthcheck', (req, res) => res.sendStatus(200))

-    let sigintAlreadyReceived = false
-    process.on('SIGINT', async () => {
-      if (!sigintAlreadyReceived) {
-        sigintAlreadyReceived = true
-        Logger.info('SIGINT (Ctrl+C) received. Shutting down...')
-        await this.stop()
-        Logger.info('Server stopped. Exiting.')
-      } else {
-        Logger.info('SIGINT (Ctrl+C) received again. Exiting immediately.')
-      }
-      process.exit(0)
-    })
-
    this.server.listen(this.Port, this.Host, () => {
      if (this.Host) Logger.info(`Listening on http://${this.Host}:${this.Port}`)
      else Logger.info(`Listening on port :${this.Port}`)
--- a/server/SocketAuthority.js
+++ b/server/SocketAuthority.js
@ -116,7 +116,6 @@ class SocketAuthority {
      // Logs
      socket.on('set_log_listener', (level) => Logger.addSocketListener(socket, level))
      socket.on('remove_log_listener', () => Logger.removeSocketListener(socket.id))
-      socket.on('fetch_daily_logs', () => this.Server.logManager.socketRequestDailyLogs(socket))

      // Sent automatically from socket.io clients
      socket.on('disconnect', (reason) => {
--- a/server/controllers/MiscController.js
+++ b/server/controllers/MiscController.js
@ -699,7 +699,7 @@ class MiscController {
  }

  /**
-   * GET: /api/me/stats/year/:year
+   * GET: /api/stats/year/:year
   * 
   * @param {import('express').Request} req 
   * @param {import('express').Response} res 
@ -717,5 +717,23 @@ class MiscController {
    const stats = await adminStats.getStatsForYear(year)
    res.json(stats)
  }
+
+  /**
+   * GET: /api/logger-data
+   * admin or up
+   * 
+   * @param {import('express').Request} req 
+   * @param {import('express').Response} res 
+   */
+  async getLoggerData(req, res) {
+    if (!req.user.isAdminOrUp) {
+      Logger.error(`[MiscController] Non-admin user "${req.user.username}" attempted to get logger data`)
+      return res.sendStatus(403)
+    }
+
+    res.json({
+      currentDailyLogs: Logger.logManager.getMostRecentCurrentDailyLogs()
+    })
+  }
 }
 module.exports = new MiscController()
--- a/server/managers/LogManager.js
+++ b/server/managers/LogManager.js
@ -1,19 +1,34 @@
 const Path = require('path')
 const fs = require('../libs/fsExtra')

+const Logger = require('../Logger')
 const DailyLog = require('../objects/DailyLog')

-const Logger = require('../Logger')
+const { LogLevel } = require('../utils/constants')

 const TAG = '[LogManager]'

+/**
+ * @typedef LogObject
+ * @property {string} timestamp
+ * @property {string} source
+ * @property {string} message
+ * @property {string} levelName
+ * @property {number} level
+ */
+
 class LogManager {
  constructor() {
    this.DailyLogPath = Path.posix.join(global.MetadataPath, 'logs', 'daily')
    this.ScanLogPath = Path.posix.join(global.MetadataPath, 'logs', 'scans')

+    /** @type {DailyLog} */
    this.currentDailyLog = null
+
+    /** @type {LogObject[]} */
    this.dailyLogBuffer = []
+
+    /** @type {string[]} */
    this.dailyLogFiles = []
  }

@ -26,12 +41,12 @@ class LogManager {
    await fs.ensureDir(this.ScanLogPath)
  }

-  async ensureScanLogDir() {
-    if (!(await fs.pathExists(this.ScanLogPath))) {
-      await fs.mkdir(this.ScanLogPath)
-    }
-  }
-
+  /**
+   * 1. Ensure log directories exist
+   * 2. Load daily log files
+   * 3. Remove old daily log files
+   * 4. Create/set current daily log file
+   */
  async init() {
    await this.ensureLogDirs()

@ -46,11 +61,11 @@ class LogManager {
      }
    }

+    // set current daily log file or create if does not exist
    const currentDailyLogFilename = DailyLog.getCurrentDailyLogFilename()
    Logger.info(TAG, `Init current daily log filename: ${currentDailyLogFilename}`)

-    this.currentDailyLog = new DailyLog()
-    this.currentDailyLog.setData({ dailyLogDirPath: this.DailyLogPath })
+    this.currentDailyLog = new DailyLog(this.DailyLogPath)

    if (this.dailyLogFiles.includes(currentDailyLogFilename)) {
      Logger.debug(TAG, `Daily log file already exists - set in Logger`)
@ -59,7 +74,7 @@ class LogManager {
      this.dailyLogFiles.push(this.currentDailyLog.filename)
    }

-    // Log buffered Logs
+    // Log buffered daily logs
    if (this.dailyLogBuffer.length) {
      this.dailyLogBuffer.forEach((logObj) => {
        this.currentDailyLog.appendLog(logObj)
@ -68,9 +83,12 @@ class LogManager {
    }
  }

+  /**
+   * Load all daily log filenames in /metadata/logs/daily
+   */
  async scanLogFiles() {
    const dailyFiles = await fs.readdir(this.DailyLogPath)
-    if (dailyFiles && dailyFiles.length) {
+    if (dailyFiles?.length) {
      dailyFiles.forEach((logFile) => {
        if (Path.extname(logFile) === '.txt') {
          Logger.debug('Daily Log file found', logFile)
@ -83,30 +101,38 @@ class LogManager {
    this.dailyLogFiles.sort()
  }

-  async removeOldestLog() {
-    if (!this.dailyLogFiles.length) return
-    const oldestLog = this.dailyLogFiles[0]
-    return this.removeLogFile(oldestLog)
-  }
-
+  /**
+   * 
+   * @param {string} filename 
+   */
  async removeLogFile(filename) {
    const fullPath = Path.join(this.DailyLogPath, filename)
    const exists = await fs.pathExists(fullPath)
    if (!exists) {
      Logger.error(TAG, 'Invalid log dne ' + fullPath)
-      this.dailyLogFiles = this.dailyLogFiles.filter(dlf => dlf.filename !== filename)
+      this.dailyLogFiles = this.dailyLogFiles.filter(dlf => dlf !== filename)
    } else {
      try {
        await fs.unlink(fullPath)
        Logger.info(TAG, 'Removed daily log: ' + filename)
-        this.dailyLogFiles = this.dailyLogFiles.filter(dlf => dlf.filename !== filename)
+        this.dailyLogFiles = this.dailyLogFiles.filter(dlf => dlf !== filename)
      } catch (error) {
        Logger.error(TAG, 'Failed to unlink log file ' + fullPath)
      }
    }
  }

-  logToFile(logObj) {
+  /**
+   * 
+   * @param {LogObject} logObj 
+   */
+  async logToFile(logObj) {
+    // Fatal crashes get logged to a separate file
+    if (logObj.level === LogLevel.FATAL) {
+      await this.logCrashToFile(logObj)
+    }
+
+    // Buffer when logging before daily logs have been initialized
    if (!this.currentDailyLog) {
      this.dailyLogBuffer.push(logObj)
      return
@ -114,25 +140,39 @@ class LogManager {

    // Check log rolls to next day
    if (this.currentDailyLog.id !== DailyLog.getCurrentDateString()) {
-      const newDailyLog = new DailyLog()
-      newDailyLog.setData({ dailyLogDirPath: this.DailyLogPath })
-      this.currentDailyLog = newDailyLog
+      this.currentDailyLog = new DailyLog(this.DailyLogPath)
      if (this.dailyLogFiles.length > this.loggerDailyLogsToKeep) {
-        this.removeOldestLog()
+        // Remove oldest log
+        this.removeLogFile(this.dailyLogFiles[0])
      }
    }

    // Append log line to log file
-    this.currentDailyLog.appendLog(logObj)
+    return this.currentDailyLog.appendLog(logObj)
  }

-  socketRequestDailyLogs(socket) {
-    if (!this.currentDailyLog) {
-      return
-    }
+  /**
+   * 
+   * @param {LogObject} logObj 
+   */
+  async logCrashToFile(logObj) {
+    const line = JSON.stringify(logObj) + '\n'

-    const lastLogs = this.currentDailyLog.logs.slice(-5000)
-    socket.emit('daily_logs', lastLogs)
+    const logsDir = Path.join(global.MetadataPath, 'logs')
+    await fs.ensureDir(logsDir)
+    const crashLogPath = Path.join(logsDir, 'crash_logs.txt')
+    return fs.writeFile(crashLogPath, line, { flag: "a+" }).catch((error) => {
+      console.log('[LogManager] Appended crash log', error)
+    })
+  }
+
+  /**
+   * Most recent 5000 daily logs
+   * 
+   * @returns {string}
+   */
+  getMostRecentCurrentDailyLogs() {
+    return this.currentDailyLog?.logs.slice(-5000) || ''
  }
 }
 module.exports = LogManager
--- a/server/objects/DailyLog.js
+++ b/server/objects/DailyLog.js
@ -1,23 +1,28 @@
 const Path = require('path')
 const date = require('../libs/dateAndTime')
 const fs = require('../libs/fsExtra')
-const { readTextFile } = require('../utils/fileUtils')
+const fileUtils = require('../utils/fileUtils')
 const Logger = require('../Logger')

 class DailyLog {
-  constructor() {
-    this.id = null
-    this.datePretty = null
+  /**
+   * 
+   * @param {string} dailyLogDirPath Path to daily logs /metadata/logs/daily
+   */
+  constructor(dailyLogDirPath) {
+    this.id = date.format(new Date(), 'YYYY-MM-DD')

-    this.dailyLogDirPath = null
-    this.filename = null
-    this.path = null
-    this.fullPath = null
+    this.dailyLogDirPath = dailyLogDirPath
+    this.filename = this.id + '.txt'
+    this.fullPath = Path.join(this.dailyLogDirPath, this.filename)

-    this.createdAt = null
+    this.createdAt = Date.now()

+    /** @type {import('../managers/LogManager').LogObject[]} */
    this.logs = []
+    /** @type {string[]} */
    this.bufferedLogLines = []
+
    this.locked = false
  }

@ -32,8 +37,6 @@ class DailyLog {
  toJSON() {
    return {
      id: this.id,
-      datePretty: this.datePretty,
-      path: this.path,
      dailyLogDirPath: this.dailyLogDirPath,
      fullPath: this.fullPath,
      filename: this.filename,
@ -41,36 +44,34 @@ class DailyLog {
    }
  }

-  setData(data) {
-    this.id = date.format(new Date(), 'YYYY-MM-DD')
-    this.datePretty = date.format(new Date(), 'ddd, MMM D YYYY')
-
-    this.dailyLogDirPath = data.dailyLogDirPath
-
-    this.filename = this.id + '.txt'
-    this.path = Path.join('backups', this.filename)
-    this.fullPath = Path.join(this.dailyLogDirPath, this.filename)
-
-    this.createdAt = Date.now()
-  }
-
-  async appendBufferedLogs() {
-    var buffered = [...this.bufferedLogLines]
+  /**
+   * Append all buffered lines to daily log file
+   */
+  appendBufferedLogs() {
+    let buffered = [...this.bufferedLogLines]
    this.bufferedLogLines = []

-    var oneBigLog = ''
+    let oneBigLog = ''
    buffered.forEach((logLine) => {
      oneBigLog += logLine
    })
-    this.appendLogLine(oneBigLog)
+    return this.appendLogLine(oneBigLog)
  }

-  async appendLog(logObj) {
+  /**
+   * 
+   * @param {import('../managers/LogManager').LogObject} logObj 
+   */
+  appendLog(logObj) {
    this.logs.push(logObj)
-    var line = JSON.stringify(logObj) + '\n'
-    this.appendLogLine(line)
+    return this.appendLogLine(JSON.stringify(logObj) + '\n')
  }

+  /**
+   * Append log to daily log file
+   * 
+   * @param {string} line 
+   */
  async appendLogLine(line) {
    if (this.locked) {
      this.bufferedLogLines.push(line)
@ -84,24 +85,29 @@ class DailyLog {

    this.locked = false
    if (this.bufferedLogLines.length) {
-      this.appendBufferedLogs()
+      await this.appendBufferedLogs()
    }
  }

+  /**
+   * Load all logs from file
+   * Parses lines and re-saves the file if bad lines are removed
+   */
  async loadLogs() {
-    var exists = await fs.pathExists(this.fullPath)
-    if (!exists) {
+    if (!await fs.pathExists(this.fullPath)) {
      console.error('Daily log does not exist')
      return
    }

-    var text = await readTextFile(this.fullPath)
+    const text = await fileUtils.readTextFile(this.fullPath)

-    var hasFailures = false
+    let hasFailures = false

-    var logLines = text.split(/\r?\n/)
+    let logLines = text.split(/\r?\n/)
    // remove last log if empty
    if (logLines.length && !logLines[logLines.length - 1]) logLines = logLines.slice(0, -1)
+
+    // JSON parse log lines
    this.logs = logLines.map(t => {
      if (!t) {
        hasFailures = true
@ -118,7 +124,7 @@ class DailyLog {

    // Rewrite log file to remove errors
    if (hasFailures) {
-      var newLogLines = this.logs.map(l => JSON.stringify(l)).join('\n') + '\n'
+      const newLogLines = this.logs.map(l => JSON.stringify(l)).join('\n') + '\n'
      await fs.writeFile(this.fullPath, newLogLines)
      console.log('Re-Saved log file to remove bad lines')
    }
--- a/server/routers/ApiRouter.js
+++ b/server/routers/ApiRouter.js
@ -327,6 +327,7 @@ class ApiRouter {
    this.router.patch('/auth-settings', MiscController.updateAuthSettings.bind(this))
    this.router.post('/watcher/update', MiscController.updateWatchedPath.bind(this))
    this.router.get('/stats/year/:year', MiscController.getAdminStatsForYear.bind(this))
+    this.router.get('/logger-data', MiscController.getLoggerData.bind(this))
  }

  //
--- a/server/scanner/LibraryScan.js
+++ b/server/scanner/LibraryScan.js
@ -134,10 +134,13 @@ class LibraryScan {
  }

  async saveLog() {
-    await Logger.logManager.ensureScanLogDir()
+    const scanLogDir = Path.join(global.MetadataPath, 'logs', 'scans')

-    const logDir = Path.join(global.MetadataPath, 'logs', 'scans')
-    const outputPath = Path.join(logDir, this.logFilename)
+    if (!(await fs.pathExists(scanLogDir))) {
+      await fs.mkdir(scanLogDir)
+    }
+
+    const outputPath = Path.join(scanLogDir, this.logFilename)
    const logLines = [JSON.stringify(this.toJSON())]
    this.logs.forEach(l => {
      logLines.push(JSON.stringify(l))