feat: delayed logging initialization

As logging module is using config module directly upon import, this practically forbids config's extension as the extension has to happen before config.get() call. This patch fix this with delayed logging initialization that happens upon first call of logging function (and not import / call of loggingFactory)

src/app.ts

@@ -7,12 +7,14 @@ import express from '@feathersjs/express'
 import socketio from '@feathersjs/socketio'
 
 import { Application } from './types'
-import logger from './logger'
+import { loggingFactory } from './logger'
 import sequelize from './sequelize'
 import blockchain from './blockchain'
 import { configure as confConfigure } from './conf'
 import storage from './storage'
 
+const logger = loggingFactory()
+
 export function appFactory (): Application {
   const app: Application = express(feathers())
 

src/blockchain/events.ts

@@ -4,12 +4,11 @@ import { Subscription } from 'web3-core-subscriptions'
 import { EventEmitter } from 'events'
 import { NotImplemented } from '@feathersjs/errors'
 import { Op } from 'sequelize'
-import { Logger } from 'winston'
 import { Sema } from 'async-sema'
 
 import { asyncFilter, scopeStore } from '../utils'
 import confFactory from '../conf'
-import { factory } from '../logger'
+import { loggingFactory, Logger } from '../logger'
 import Event, { EventInterface } from './event.model'
 import { Store } from '../types'
 
@@ -122,7 +121,7 @@ export class PollingNewBlockEmitter extends AutoStartStopEventEmitter {
   private lastBlockNumber = 0
 
   constructor (eth: Eth, pollingInterval: number = DEFAULT_POLLING_INTERVAL) {
-    super(factory('blockchain:block-emitter:polling'), NEW_BLOCK_EVENT_NAME)
+    super(loggingFactory('blockchain:block-emitter:polling'), NEW_BLOCK_EVENT_NAME)
     this.eth = eth
     this.pollingInterval = pollingInterval
   }
@@ -164,7 +163,7 @@ export class ListeningNewBlockEmitter extends AutoStartStopEventEmitter {
   private subscription?: Subscription<BlockHeader>
 
   constructor (eth: Eth) {
-    super(factory('blockchain:block-emitter:listening'), NEW_BLOCK_EVENT_NAME)
+    super(loggingFactory('blockchain:block-emitter:listening'), NEW_BLOCK_EVENT_NAME)
     this.eth = eth
   }
 
@@ -469,7 +468,7 @@ export abstract class BaseEventsEmitter extends AutoStartStopEventEmitter {
 export class PollingEventsEmitter extends BaseEventsEmitter {
   constructor (eth: Eth, contract: Contract, events: string[], options?: EventsEmitterOptions) {
     const loggerName = options?.loggerName || (options?.loggerBaseName ? `${options.loggerBaseName}:events:polling` : 'blockchain:events:polling')
-    const logger = factory(loggerName)
+    const logger = loggingFactory(loggerName)
     super(eth, contract, events, logger, options)
   }
 
@@ -516,7 +515,7 @@ export class PollingEventsEmitter extends BaseEventsEmitter {
  */
 export class ListeningEventsEmitter extends BaseEventsEmitter {
   constructor (eth: Eth, contract: Contract, events: string[], options: EventsEmitterOptions) {
-    const logger = factory('blockchain:events:listening')
+    const logger = loggingFactory('blockchain:events:listening')
     super(eth, contract, events, logger, options)
   }
 

src/conf.ts

@@ -1,7 +1,6 @@
-import { Application } from './types'
 import config from 'config'
 import Conf from 'conf'
-import { factory as logFactory } from './logger'
+import { loggingFactory as logFactory } from './logger'
 
 const logger = logFactory('conf')
 

src/index.ts

@@ -1,7 +1,8 @@
-import logger from './logger'
+import { loggingFactory } from './logger'
 import { appFactory } from './app'
 import config from 'config'
 
+const logger = loggingFactory()
 const app = appFactory()
 const port = config.get('port')
 const server = app.listen(port)

src/logger.ts

@@ -1,9 +1,23 @@
-import { createLogger, format, transports, addColors, Logger } from 'winston'
+import { createLogger, format, transports, addColors, Logger as RealLogger } from 'winston'
 import * as Transport from 'winston-transport'
 
 import colors from 'colors'
 import config from 'config'
 
+export interface Logger {
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  error (message: string | Error, ...meta: any[]): void
+
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  debug (message: string, ...meta: any[]): void
+
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  warn (message: string, ...meta: any[]): void
+
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  info (message: string, ...meta: any[]): void
+}
+
 // Inspired from https://github.com/visionmedia/debug
 const names: RegExp[] = []
 const skips: RegExp[] = []
@@ -88,45 +102,74 @@ addColors({
   info: 'blue'
 })
 
-loadFilter(config.get('log.filter') || '*')
+let mainLogger: RealLogger
+const loggers: Record<string, RealLogger> = {}
 
-const transportsSet: Transport[] = [new transports.Console()]
+function initLogging (): void {
+  loadFilter(config.get('log.filter') || '*')
 
-if (config.get('log.path')) {
-  transportsSet.push(new transports.File({
-    filename: config.get('log.path'),
-    maxsize: 5000000,
-    maxFiles: 5,
-    tailable: true,
-    format: format.uncolorize()
-  }))
+  const transportsSet: Transport[] = [new transports.Console()]
+
+  if (config.get('log.path')) {
+    transportsSet.push(new transports.File({
+      filename: config.get('log.path'),
+      maxsize: 5000000,
+      maxFiles: 5,
+      tailable: true,
+      format: format.uncolorize()
+    }))
+  }
+
+  mainLogger = createLogger({
+    // To see more detailed errors, change this to 'debug'
+    level: config.get('log.level') || 'info',
+    format: format.combine(
+      format.splat(),
+      format.metadata(),
+      filterServices(),
+      upperCaseLevel(),
+      format.errors({ stack: true }),
+      // format.padLevels(),
+      format.timestamp({ format: 'DD/MM hh:mm:ss' }),
+      format.colorize(),
+      format.printf(info => {
+        if (info.metadata.service) {
+          return `[${info.level}] ${colors.grey(info.timestamp)} (${info.metadata.service}): ${info.message}`
+        } else {
+          return `[${info.level}] ${colors.grey(info.timestamp)}: ${info.message}`
+        }
+      })
+    ),
+    transports: transportsSet
+  })
 }
 
-const logger = createLogger({
-  // To see more detailed errors, change this to 'debug'
-  level: config.get('log.level') || 'info',
-  format: format.combine(
-    format.splat(),
-    format.metadata(),
-    filterServices(),
-    upperCaseLevel(),
-    format.errors({ stack: true }),
-    // format.padLevels(),
-    format.timestamp({ format: 'DD/MM hh:mm:ss' }),
-    format.colorize(),
-    format.printf(info => {
-      if (info.metadata.service) {
-        return `[${info.level}] ${colors.grey(info.timestamp)} (${info.metadata.service}): ${info.message}`
-      } else {
-        return `[${info.level}] ${colors.grey(info.timestamp)}: ${info.message}`
+type SupportedLevels = 'error' | 'warn' | 'info' | 'debug'
+
+function delayedLoggingMethod (level: SupportedLevels, name?: string): (message: string, ...meta: any[]) => void {
+  return function (message: string, ...meta: any[]): void {
+    // First logging call, lets setup logging
+    if (!mainLogger) {
+      initLogging()
+    }
+
+    if (name) {
+      if (!loggers[name]) {
+        loggers[name] = mainLogger.child({ service: name })
       }
-    })
-  ),
-  transports: transportsSet
-})
 
-export function factory (name: string): Logger {
-  return logger.child({ service: name })
+      loggers[name][level](message, ...meta)
+    } else {
+      mainLogger[level](message, ...meta)
+    }
+  }
 }
 
-export default logger
+export function loggingFactory (name?: string): Logger {
+  return {
+    error: delayedLoggingMethod('error', name),
+    warn: delayedLoggingMethod('warn', name),
+    info: delayedLoggingMethod('info', name),
+    debug: delayedLoggingMethod('debug', name)
+  }
+}

src/sequelize.ts

@@ -1,10 +1,10 @@
 import { Sequelize, SequelizeOptions } from 'sequelize-typescript'
 import { Application } from './types'
-import { factory } from './logger'
+import { loggingFactory } from './logger'
 import path from 'path'
 import config from 'config'
 
-const logger = factory('db')
+const logger = loggingFactory('db')
 
 export function sequelizeFactory (): Sequelize {
   const dbSettings: SequelizeOptions = Object.assign({

src/storage/index.ts

@@ -4,14 +4,14 @@ import { AbiItem } from 'web3-utils'
 import config from 'config'
 import StorageOffer from './models/storage-offer.model'
 import { Application } from '../types'
-import { factory } from '../logger'
+import { loggingFactory } from '../logger'
 import { getEventsEmitterForService } from '../blockchain/utils'
 
 import hooks from './storage.hooks'
 import eventProcessor from './storage.blockchain'
 import pinningContractAbi from '@rsksmart/rif-martketplace-storage-pinning/build/contracts/PinningManager.json'
 
-const logger = factory('storage')
+const logger = loggingFactory('storage')
 
 export class StorageOfferService extends Service {
 }

src/storage/storage.blockchain.ts

@@ -1,9 +1,9 @@
 import StorageOffer from './models/storage-offer.model'
 import Price from './models/price.model'
 import { EventData } from 'web3-eth-contract'
-import { factory } from '../logger'
+import { loggingFactory } from '../logger'
 
-const logger = factory('storage:blockchain')
+const logger = loggingFactory('storage:blockchain')
 
 function updatePrices (offer: StorageOffer, period: number, price: number): Promise<Price> {
   const priceEntity = offer.prices && offer.prices.find(value => value.period === period)

test/blockchain/events.spec.ts

@@ -16,7 +16,7 @@ import chaiAsPromised from 'chai-as-promised'
 import util from 'util'
 import { Contract, EventData } from 'web3-eth-contract'
 import { EventEmitter } from 'events'
-import { factory } from '../../src/logger'
+import { loggingFactory } from '../../src/logger'
 import { Sequelize } from 'sequelize-typescript'
 import { sequelizeFactory } from '../../src/sequelize'
 import Event from '../../src/blockchain/event.model'
@@ -105,7 +105,7 @@ function receiptMock (blockNumber?: number, status = true): TransactionReceipt {
  */
 export class DummyEventsEmitter extends BaseEventsEmitter {
   constructor (eth: Eth, contract: Contract, events: string[], options?: EventsEmitterOptions) {
-    const logger = factory('blockchain:events:dummy')
+    const logger = loggingFactory('blockchain:events:dummy')
     super(eth, contract, events, logger, options)
   }