feat(core): Improve logging: messages, levels, & formatting. Closes #9

Author: zenflow

TODO.md

@@ -1,18 +1,10 @@
 # TODO
 
-- Create Github issues for everything in this document
-    - use labels for features/bugs/tests/docs/website/community/upstream
-- logger
-	- remove the one logger.debug() call
-	- replace starting/stopping calls to logger.info() with logger.debug()
-	- use logger.info() when
-		- restarting crashed service
-		- received shutdown signal
 - improve formatting of output; introduce "$composite" stream prefix
 - ready helpers should be included as 2nd argument in call to `ready` config (adding the imports is annoying)
-- default `ready` should be `(ctx, helpers) => helpers.onceTimeout(1000)` ?
-- default `onCrash` should be `(ctx, helpers) => !ctx.isServiceReady && helpers.propagateCrash()`
+- default `onCrash` should be like `(ctx, helpers) => !ctx.isServiceReady && helpers.propagateCrash()`
 
+`gracefulShutdown` option should be `sequentialShutdown` instead
 ---
 
 - bugs

examples/shutdown.js

@@ -1,5 +1,8 @@
 const { startCompositeService } = require('..')
 
+const logLevel = process.argv.includes('--log-level')
+  ? process.argv[process.argv.indexOf('--log-level') + 1]
+  : undefined
 const hang = process.argv.includes('--hang')
 
 const command = [
@@ -19,14 +22,17 @@ process.on('SIGINT', () => {
 ]
 
 startCompositeService({
+  logLevel,
   gracefulShutdown: true,
   windowsCtrlCShutdown: true,
   serviceDefaults: {
     command,
     forceKillTimeout: 2000,
   },
   services: {
-    foo: {},
-    bar: { dependencies: ['foo'] },
+    one: {},
+    two: { dependencies: ['one'] },
+    three: { dependencies: ['one'] },
+    four: { dependencies: ['two', 'three'] },
   },
 })

package.json

@@ -45,6 +45,7 @@
     "document-api": "node scripts/document-api.js"
   },
   "dependencies": {
+    "chalk": "^4.1.0",
     "cloneable-readable": "^2.0.1",
     "express": "^4.17.1",
     "http-proxy-middleware": "^1.0.5",

src/core/CompositeService.ts

@@ -1,6 +1,7 @@
 import { Service } from './Service'
-import serializeJavascript from 'serialize-javascript'
+import serializeJs from 'serialize-javascript'
 import mergeStream from 'merge-stream'
+import chalk from 'chalk'
 import {
   NormalizedCompositeServiceConfig,
   validateAndNormalizeConfig,
@@ -28,52 +29,41 @@ export class CompositeService {
 
     this.logger = new Logger(this.config.logLevel)
     outputStream.add(this.logger.output)
-    this.logger.debug(
-      'Config: ' +
-        serializeJavascript(config, {
-          space: 2,
-          unsafe: true,
-        }),
-    )
 
-    process.on('SIGINT', () => this.die(130, "Received 'SIGINT' signal"))
-    process.on('SIGTERM', () => this.die(143, "Received 'SIGTERM' signal"))
+    const configText = serializeJs(config, { space: 2, unsafe: true })
+    this.logger.log('debug', `Config: ${configText}`)
+
+    process.on('SIGINT', () => this.handleShutdownSignal(130, 'SIGINT'))
+    process.on('SIGTERM', () => this.handleShutdownSignal(143, 'SIGTERM'))
     if (process.stdin.isTTY) {
       process.stdin.setRawMode(true)
       process.stdin.on('data', buffer => {
         if (buffer.toString('utf8') === '\u0003') {
-          this.die(130, 'Received ctrl+c')
+          this.handleShutdownSignal(130, 'ctrl+c')
         }
       })
     }
 
     this.services = Object.entries(this.config.services).map(
       ([id, config]) =>
-        new Service(id, config, this.logger, message =>
-          this.handleError(`Error in '${id}': ${message}`),
-        ),
+        new Service(id, config, this.logger, this.handleFatalError.bind(this)),
     )
     this.serviceMap = new Map(
       this.services.map(service => [service.id, service]),
     )
 
-    const maxLabelLength = Math.max(
-      ...Object.keys(this.config.services).map(({ length }) => length),
-    )
     outputStream.add(
-      this.services.map(({ output, id }) =>
-        output.pipe(
-          mapStreamLines(
-            line => `${`${rightPad(id, maxLabelLength)} | `}${line}`,
-          ),
-        ),
-      ),
+      this.services.map(({ output, id }, i) => {
+        // luminosity of 20 because at 256 colors, luminosity from 16 to 24 yields the most colors (12 colors) while keeping high contrast with text
+        const label = chalk.bgHsl((i / this.services.length) * 360, 100, 20)(id)
+        return output.pipe(mapStreamLines(line => `${label} | ${line}`))
+      }),
     )
 
-    this.logger.info('Starting composite service...')
+    this.logger.log('debug', 'Starting composite service...')
     Promise.all(
       this.services.map(service => this.startService(service)),
-    ).then(() => this.logger.info('Started composite service'))
+    ).then(() => this.logger.log('debug', 'Started composite service'))
   }
 
   private async startService(service: Service) {
@@ -90,29 +80,35 @@ export class CompositeService {
     }
   }
 
-  private handleError(message: string) {
-    return this.die(1, message)
+  private handleFatalError(message: string): void {
+    this.logger.log('error', `Fatal error: ${message}`)
+    if (!this.stopping) {
+      this.stop(1)
+    }
   }
 
-  private async die(exitCode: number, message: string): Promise<never> {
+  private handleShutdownSignal(exitCode: number, description: string): void {
     if (!this.stopping) {
-      this.stopping = true
-      const isSignalExit = exitCode > 128 // we have either a signal exit or an error exit
-      this.logger[isSignalExit ? 'info' : 'error'](message)
-      this.logger.info('Stopping composite service...')
-      if (this.config.windowsCtrlCShutdown) {
-        require('generate-ctrl-c-event')
-          .generateCtrlCAsync()
-          .catch((error: Error) => this.logger.error(String(error)))
-      }
-      await Promise.all(this.services.map(service => this.stopService(service)))
-      this.logger.info('Stopped composite service')
-      await Promise.resolve() // Wait one micro tick for output to flush
-      process.exit(exitCode)
+      this.logger.log('info', `Received shutdown signal (${description})`)
+      this.stop(exitCode)
     }
-    // simply return a promise that never resolves, since we can't do anything after exiting anyways
-    return never()
   }
+
+  private stop(exitCode: number): void {
+    if (this.stopping) return
+    this.stopping = true
+    this.logger.log('debug', 'Stopping composite service...')
+    if (this.config.windowsCtrlCShutdown) {
+      require('generate-ctrl-c-event')
+        .generateCtrlCAsync()
+        .catch((error: Error) => this.logger.log('error', String(error)))
+    }
+    Promise.all(this.services.map(service => this.stopService(service)))
+      .then(() => this.logger.log('debug', 'Stopped composite service'))
+      // Wait one micro tick for output to flush
+      .then(() => process.exit(exitCode))
+  }
+
   private async stopService(service: Service) {
     if (this.config.gracefulShutdown) {
       const dependents = this.services.filter(({ config }) =>
@@ -124,11 +120,6 @@ export class CompositeService {
   }
 }
 
-function rightPad(string: string, length: number): string {
-  // we assume length >= string.length
-  return string + ' '.repeat(length - string.length)
-}
-
 function never(): Promise<never> {
   return new Promise<never>(() => {})
 }

src/core/Logger.ts

@@ -1,25 +1,22 @@
 import { PassThrough } from 'stream'
+import chalk from 'chalk'
 
 export type LogLevel = 'debug' | 'info' | 'error'
 
-export const orderedLogLevels: LogLevel[] = ['error', 'info', 'debug']
+const orderedLogLevels: LogLevel[] = ['error', 'info', 'debug']
+const logLevelColors = { error: 'red', info: 'teal', debug: 'yellow' }
 
 export class Logger {
   private level: LogLevel
-  public readonly error: (text: string) => void
-  public readonly info: (text: string) => void
-  public readonly debug: (text: string) => void
   public readonly output = new PassThrough({ objectMode: true })
   constructor(level: LogLevel) {
     this.level = level
-    this.error = this.log.bind(this, 'error')
-    this.info = this.log.bind(this, 'info')
-    this.debug = this.log.bind(this, 'debug')
   }
-  private log(level: LogLevel, text: string) {
+  public log(level: LogLevel, text: string) {
     if (this.shouldLog(level)) {
+      const label = chalk.keyword(logLevelColors[level])(`(${level})`)
       for (const line of text.split('\n')) {
-        this.output.write(`${level}: ${line}\n`)
+        this.output.write(` ${label} ${line}\n`)
       }
     }
   }

src/core/Service.ts

@@ -17,7 +17,7 @@ export class Service {
   public readonly output = cloneable(new PassThrough({ objectMode: true }))
   private readonly outputClone = this.output.clone()
   private readonly logger: Logger
-  private readonly handleError: (message: string) => Promise<never>
+  private readonly handleFatalError: (message: string) => void
   private ready: Promise<void> | undefined
   private process: ServiceProcess | undefined
   private startResult: Promise<void> | undefined
@@ -28,26 +28,29 @@ export class Service {
     id: string,
     config: NormalizedServiceConfig,
     logger: Logger,
-    handleError: (message: string) => Promise<never>,
+    handleFatalError: (message: string) => void,
   ) {
     this.id = id
     this.config = config
     this.logger = logger
-    this.handleError = handleError
+    this.handleFatalError = handleFatalError
   }
 
   public start() {
     if (this.stopResult) {
-      this.logger.error(new InternalError('Cannot start after stopping').stack!)
+      this.logger.log(
+        'error',
+        new InternalError('Cannot start after stopping').stack!,
+      )
       return this.startResult
     }
     if (!this.startResult) {
-      this.logger.info(`Starting service '${this.id}'...`)
+      this.logger.log('debug', `Starting service '${this.id}'...`)
       this.defineReady()
       this.startResult = this.startProcess()
         .then(() => this.ready)
         .then(() => {
-          this.logger.info(`Started service '${this.id}'`)
+          this.logger.log('debug', `Started service '${this.id}'`)
         })
     }
     return this.startResult
@@ -58,11 +61,11 @@ export class Service {
       output: this.outputClone,
     }
     this.ready = promiseTry(() => this.config.ready(ctx))
-      .catch(error =>
-        this.handleError(`Error from ready function: ${maybeErrorText(error)}`),
-      )
-      .then(() => {
-        this.outputClone.destroy()
+      .finally(() => this.outputClone.destroy())
+      .catch(error => {
+        const prefix = `In \`ready\` function for service '${this.id}'`
+        this.handleFatalError(`${prefix}: ${maybeErrorText(error)}`)
+        return never()
       })
   }
 
@@ -78,12 +81,14 @@ export class Service {
     try {
       await this.process.started
     } catch (error) {
-      await this.handleError(`Error starting process: ${error}`)
+      const prefix = `Spawning process for service '${this.id}'`
+      this.handleFatalError(`${prefix}: ${error}`)
+      await never()
     }
   }
 
   private async handleCrash(proc: ServiceProcess) {
-    this.logger.info(`Service '${this.id}' crashed`)
+    this.logger.log('info', `Service '${this.id}' crashed`)
     const delayPromise = delay(this.config.minimumRestartDelay)
     const crash: ServiceCrash = {
       date: new Date(),
@@ -99,9 +104,9 @@ export class Service {
     try {
       await this.config.onCrash(ctx)
     } catch (error) {
-      await this.handleError(
-        `Error from onCrash function: ${maybeErrorText(error)}`,
-      )
+      const prefix = `In \`onCrash\` function for service ${this.id}`
+      this.handleFatalError(`${prefix}: ${maybeErrorText(error)}`)
+      await never()
     }
     if (this.stopResult) {
       return
@@ -110,7 +115,7 @@ export class Service {
     if (this.stopResult) {
       return
     }
-    this.logger.info(`Restarting service '${this.id}'`)
+    this.logger.log('info', `Restarting service '${this.id}'`)
     await this.startProcess()
   }
 
@@ -119,9 +124,9 @@ export class Service {
       if (!this.process || !this.process.isRunning()) {
         this.stopResult = Promise.resolve()
       } else {
-        this.logger.info(`Stopping service '${this.id}'...`)
+        this.logger.log('debug', `Stopping service '${this.id}'...`)
         this.stopResult = this.process.end(windowsCtrlCShutdown).then(() => {
-          this.logger.info(`Stopped service '${this.id}'`)
+          this.logger.log('debug', `Stopped service '${this.id}'`)
         })
       }
     }
@@ -150,3 +155,7 @@ function isResolved(promise: Promise<any>): Promise<boolean> {
     Promise.resolve().then(() => false),
   ])
 }
+
+function never(): Promise<never> {
+  return new Promise<never>(() => {})
+}

src/core/ServiceProcess.ts

@@ -71,11 +71,10 @@ export class ServiceProcess {
       this.wasEndCalled = true
       if (this.isRunning()) {
         if (windowsCtrlCShutdown) {
-          // Don't call this.process.kill(); ctrl+c was already sent to all services
+          // ctrl+c signal was already sent to all service processes
           this.forceKillAfterTimeout()
         } else if (process.platform === 'win32') {
           this.process.kill()
-          // Don't call this.forceKillAfterTimeout(); On Windows we don't have SIGINT vs SIGKILL
         } else {
           this.process.kill('SIGINT')
           this.forceKillAfterTimeout()
@@ -90,7 +89,7 @@ export class ServiceProcess {
     }
     setTimeout(() => {
       if (this.isRunning()) {
-        this.logger.info(`Force killing service '${this.serviceId}'`)
+        this.logger.log('info', `Force killing service '${this.serviceId}'`)
         this.process.kill('SIGKILL')
       }
     }, this.serviceConfig.forceKillTimeout)

src/core/startCompositeService.ts

@@ -11,9 +11,13 @@ let started = false
  * Each service defined in {@link CompositeServiceConfig.services}
  * is started and managed according to its {@link ServiceConfig}.
  *
+ * TODO: Move everything below to `docs/` & replace with "See Intro for more detailed specs".
+ *
  * The stdout & stderr from each service is piped to stdout,
  * each line prepended with the service ID.
  *
+ * TODO: Improve documentation below regarding shutting down & fatal errors
+ *
  * Each service is told to shut down
  * when the composite service is itself told to shut down
  * (with `ctrl+c`, `SIGINT`, or `SIGTERM`),