feat(logs): added file output for logs

src/bp/core/app.inversify.ts

@@ -7,7 +7,7 @@ import { Botpress } from './botpress'
 import { BotConfigWriter } from './config'
 import { ConfigProvider, GhostConfigProvider } from './config/config-loader'
 import { DatabaseContainerModules } from './database/database.inversify'
-import { LoggerPersister, LoggerProvider, PersistedConsoleLogger } from './logger'
+import { LoggerDbPersister, LoggerFilePersister, LoggerProvider, PersistedConsoleLogger } from './logger'
 import { applyDisposeOnExit, applyInitializeFromConfig } from './misc/inversify'
 import { ModuleLoader } from './module-loader'
 import { RepositoriesContainerModules } from './repositories/repositories.inversify'
@@ -55,8 +55,13 @@ container
   .inSingletonScope()
 
 container
-  .bind<LoggerPersister>(TYPES.LoggerPersister)
-  .to(LoggerPersister)
+  .bind<LoggerDbPersister>(TYPES.LoggerDbPersister)
+  .to(LoggerDbPersister)
+  .inSingletonScope()
+
+container
+  .bind<LoggerFilePersister>(TYPES.LoggerFilePersister)
+  .to(LoggerFilePersister)
   .inSingletonScope()
 
 container // TODO Implement this

src/bp/core/botpress.ts

@@ -15,7 +15,7 @@ import { createForGlobalHooks } from './api'
 import { BotpressConfig } from './config/botpress.config'
 import { ConfigProvider } from './config/config-loader'
 import Database, { DatabaseType } from './database'
-import { LoggerPersister, LoggerProvider } from './logger'
+import { LoggerDbPersister, LoggerFilePersister, LoggerProvider } from './logger'
 import { ModuleLoader } from './module-loader'
 import HTTPServer from './server'
 import { GhostService } from './services'
@@ -71,7 +71,8 @@ export class Botpress {
     @inject(TYPES.LoggerProvider) private loggerProvider: LoggerProvider,
     @inject(TYPES.DialogJanitorRunner) private dialogJanitor: DialogJanitor,
     @inject(TYPES.LogJanitorRunner) private logJanitor: LogsJanitor,
-    @inject(TYPES.LoggerPersister) private loggerPersister: LoggerPersister,
+    @inject(TYPES.LoggerDbPersister) private loggerDbPersister: LoggerDbPersister,
+    @inject(TYPES.LoggerFilePersister) private loggerFilePersister: LoggerFilePersister,
     @inject(TYPES.NotificationsService) private notificationService: NotificationsService,
     @inject(TYPES.AppLifecycle) private lifecycle: AppLifecycle,
     @inject(TYPES.StateManager) private stateManager: StateManager,
@@ -196,8 +197,10 @@ export class Botpress {
   }
 
   private async initializeServices() {
-    await this.loggerPersister.initialize(this.database, await this.loggerProvider('LogPersister'))
-    this.loggerPersister.start()
+    await this.loggerDbPersister.initialize(this.database, await this.loggerProvider('LogDbPersister'))
+    this.loggerDbPersister.start()
+
+    await this.loggerFilePersister.initialize(this.config!, await this.loggerProvider('LogFilePersister'))
 
     await this.workspaceService.initialize()
     await this.cmsService.initialize()

src/bp/core/config/botpress.config.ts

@@ -30,14 +30,39 @@ export interface DialogConfig {
 
 export interface LogsConfig {
   /**
-   * Logs will be kept for this amount of time in the database
-   * @default 2 weeks
+   * The database output will not record Debug logs.
    */
-  expiration: string
+  dbOutput: {
+    /**
+     * Logs will be kept for this amount of time in the database
+     * @default 2 weeks
+     */
+    expiration: string
+    /**
+     * @default 30s
+     */
+    janitorInterval: string
+  }
   /**
-   * @default 30s
+   * The file output records everything that is displayed in the console logs.
    */
-  janitorInterval: string
+  fileOutput: {
+    /**
+     * Enable or disable the output of logs to the file system. A new file is created each day
+     * @default false
+     */
+    enabled: boolean
+    /**
+     * The path (relative or absolute) to the logs folder.
+     * @default ./
+     */
+    folder: string
+    /**
+     * The maximum file size that the log can reach before a new one is started (size in kb)
+     * @default 10000
+     */
+    maxFileSize: number
+  }
 }
 
 export type BotpressConfig = {

src/bp/core/logger/persister.ts → src/bp/core/logger/db-persister.ts

@@ -7,7 +7,7 @@ import ms from 'ms'
 import Database from '../database'
 
 @injectable()
-export class LoggerPersister {
+export class LoggerDbPersister {
   private readonly BATCH_SIZE = 100
   private readonly TABLE_NAME = 'srv_logs'
   private readonly INTERVAL = ms('2s')

src/bp/core/logger/file-persister.ts

@@ -0,0 +1,125 @@
+import { Logger, LoggerEntry } from 'botpress/sdk'
+import fs from 'fs'
+import { injectable } from 'inversify'
+
+import { BotpressConfig } from 'core/config/botpress.config'
+import _ from 'lodash'
+import moment from 'moment'
+import ms from 'ms'
+import path from 'path'
+
+@injectable()
+export class LoggerFilePersister {
+  private readonly INTERVAL = ms('2s')
+
+  private batch: string[] = []
+  private intervalRef
+  private currentPromise
+  private maxFileSize!: number
+  private outputFolder!: string
+  private logger!: Logger
+
+  constructor() {}
+
+  async initialize(botpressConfig: BotpressConfig, logger: Logger) {
+    const logsConfig = _.get(botpressConfig, 'logs.fileOutput', {})
+    if (!logsConfig.enabled) {
+      return
+    }
+
+    this.logger = logger
+    this.outputFolder = logsConfig.folder
+    this.maxFileSize = 1024 * logsConfig.maxFileSize
+
+    if (process.env.DEBUG_LOGGER) {
+      this.logger.debug(`Saving logs to ${this.outputFolder}, keeping file size under ${logsConfig.maxFileSize} kb`)
+    }
+
+    if (await this._isOutputWritable()) {
+      this.start()
+    }
+  }
+
+  appendLog(entry: LoggerEntry) {
+    const bot = entry.botId ? `(bot: ${entry.botId})` : ''
+    this.batch.push(`${entry.timestamp} ${entry.scope} (${entry.level}) ${bot} ${entry.message}${entry.metadata}\n`)
+  }
+
+  start() {
+    if (this.intervalRef) {
+      return
+    }
+    this.intervalRef = setInterval(this._runTask, this.INTERVAL)
+  }
+
+  stop() {
+    clearInterval(this.intervalRef)
+    this.intervalRef = undefined
+  }
+
+  private async _isOutputWritable() {
+    const fullPath = path.resolve(this.outputFolder)
+
+    try {
+      await fs.existsSync(fullPath)
+      await fs.accessSync(fullPath, fs.constants.W_OK)
+      return true
+    } catch (err) {
+      throw new Error(
+        `Unable to write in the specified folder ("${fullPath}"). Please check configuration or disable log file output`
+      )
+    }
+  }
+
+  private _getLogFileName(includeTimestamp = false) {
+    const format = includeTimestamp ? 'YYYYMMDD_HHmmss' : 'YYYYMMDD'
+    return `logs_${moment().format(format)}.log`
+  }
+
+  private async _rotateFile() {
+    const original = path.resolve(this.outputFolder, this._getLogFileName())
+    const newName = path.resolve(this.outputFolder, this._getLogFileName(true))
+
+    if (await fs.existsSync(original)) {
+      await fs.renameSync(original, newName)
+      if (process.env.DEBUG_LOGGER) {
+        this.logger.debug(`Log file rotated: ${original} -> ${newName}`)
+      }
+    }
+  }
+
+  private async _fileNeedsRotation(textLength) {
+    try {
+      const { size } = await fs.statSync(this._getLogFileName())
+      return size + textLength > this.maxFileSize
+    } catch (error) {
+      return false
+    }
+  }
+
+  private _runTask = async () => {
+    if (this.currentPromise || this.batch.length === 0) {
+      return
+    }
+
+    if (process.env.DEBUG_LOGGER) {
+      this.logger.debug(`Saving ${this.batch.length} logs`)
+    }
+
+    const content = this.batch.join('')
+    this.batch = []
+
+    if (await this._fileNeedsRotation(content.length)) {
+      await this._rotateFile()
+    }
+
+    const logStream = await fs.createWriteStream(this._getLogFileName(), { flags: 'a' })
+    this.currentPromise = Promise.fromCallback(cb =>
+      logStream.write(content, err => {
+        logStream.end(cb)
+      })
+    ).finally(() => {
+      this.currentPromise = undefined
+    })
+  }
+}

src/bp/core/logger/index.ts

@@ -1,2 +1,3 @@
 export * from './logger'
-export * from './persister'
+export * from './db-persister'
+export * from './file-persister'

src/bp/core/logger/logger.ts

@@ -5,11 +5,12 @@ import { inject, injectable } from 'inversify'
 import _ from 'lodash'
 import moment from 'moment'
 import os from 'os'
+import stripAnsi from 'strip-ansi'
 import util from 'util'
 
 import { TYPES } from '../types'
 
-import { LoggerPersister } from '.'
+import { LoggerDbPersister, LoggerFilePersister } from '.'
 
 export type LoggerProvider = (module: string) => Promise<Logger>
 
@@ -24,7 +25,8 @@ export class PersistedConsoleLogger implements Logger {
 
   constructor(
     @inject(TYPES.Logger_Name) private name: string,
-    @inject(TYPES.LoggerPersister) private loggerPersister: LoggerPersister
+    @inject(TYPES.LoggerDbPersister) private loggerDbPersister: LoggerDbPersister,
+    @inject(TYPES.LoggerFilePersister) private loggerFilePersister: LoggerFilePersister
   ) {
     this.displayLevel = process.VERBOSITY_LEVEL
   }
@@ -57,22 +59,6 @@ export class PersistedConsoleLogger implements Logger {
   }
 
   private print(level: LoggerLevel, message: string, metadata: any) {
-    const entry: LoggerEntry = {
-      botId: this.botId,
-      level: level.toString(),
-      scope: this.name,
-      message: message,
-      metadata: metadata,
-      timestamp: moment().toISOString()
-    }
-
-    if (this.willPersistMessage && level !== LoggerLevel.Debug) {
-      this.loggerPersister.appendLog(entry)
-    } else {
-      // We reset it right away to prevent race conditions (since the persister might log a new message asynchronously)
-      this.willPersistMessage = true
-    }
-
     if (this.attachedError) {
       try {
         const asAxios = this.attachedError as AxiosError
@@ -125,10 +111,28 @@ export class PersistedConsoleLogger implements Logger {
       indentedMessage += chalk.grey(os.EOL + this.attachedError.stack)
     }
 
+    const entry: LoggerEntry = {
+      botId: this.botId,
+      level: level.toString(),
+      scope: displayName,
+      message: stripAnsi(indentedMessage),
+      metadata: stripAnsi(serializedMetadata),
+      timestamp: moment().toISOString()
+    }
+
+    if (this.willPersistMessage && level !== LoggerLevel.Debug) {
+      this.loggerDbPersister.appendLog(entry)
+    } else {
+      // We reset it right away to prevent race conditions (since the persister might log a new message asynchronously)
+      this.willPersistMessage = true
+    }
+
     if (this.displayLevel >= this.currentMessageLevel!) {
       console.log(
         chalk`{grey ${time}} {${this.colors[level]}.bold ${displayName}} ${indentedMessage}${serializedMetadata}`
       )
+
+      this.loggerFilePersister.appendLog(entry)
     }
 
     this.currentMessageLevel = undefined

src/bp/core/services/logs/janitor.ts

@@ -33,7 +33,7 @@ export class LogsJanitor extends Janitor {
 
   protected async getInterval(): Promise<string> {
     const config = await this.getBotpresConfig()
-    return config.logs.janitorInterval
+    return _.get(config, 'logs.dbOutput.janitorInterval', '30s')
   }
 
   protected async runTask(): Promise<void> {
@@ -44,7 +44,7 @@ export class LogsJanitor extends Janitor {
     const botpressConfig = await this.getBotpresConfig()
     const botsConfigs = await this.botService.getBots()
     const botsIds = Array.from(botsConfigs.keys())
-    const globalLogsExpiryTime = ms(botpressConfig.logs.expiration)
+    const globalLogsExpiryTime = ms(_.get(botpressConfig, 'logs.dbOutput.expiration', '2 weeks'))
 
     Promise.mapSeries(botsIds, botId => {
       const botConfig = botsConfigs.get(botId)!

src/bp/core/types.ts

@@ -43,7 +43,8 @@ const TYPES = {
   MediaService: Symbol.for('MediaService'),
   JanitorRunner: Symbol.for('JanitorRunner'),
   DialogJanitorRunner: Symbol.for('DialogJanitorRunner'),
-  LoggerPersister: Symbol.for('LoggerPersister'),
+  LoggerDbPersister: Symbol.for('LoggerDbPersister'),
+  LoggerFilePersister: Symbol.for('LoggerFilePersister'),
   LogsService: Symbol.for('LogsService'),
   LogsRepository: Symbol.for('LogsRepository'),
   LogJanitorRunner: Symbol.for('LogJanitorRunner'),