refactor: use sophisticated logger

package.json

@@ -55,6 +55,8 @@
     "commander": "^10.0.0",
     "normalize-package-data": "^3||^4||^5||^6",
     "packageurl-js": "^1.2.1",
+    "pino": "^8.16.2",
+    "pino-pretty": "^10.2.3",
     "xmlbuilder2": "^3.0.2"
   },
   "devDependencies": {
@@ -74,7 +76,7 @@
   },
   "type": "commonjs",
   "engines": {
-    "node": ">=14",
+    "node": ">=14.17.0",
     "npm": "6 - 10"
   },
   "directories": {

src/builders.ts

@@ -17,12 +17,14 @@ SPDX-License-Identifier: Apache-2.0
 Copyright (c) OWASP Foundation. All Rights Reserved.
 */
 
+import { existsSync } from 'node:fs'
+import * as path from 'node:path'
+
 import { type Builders, Enums, type Factories, Models, Utils } from '@cyclonedx/cyclonedx-library'
-import { existsSync } from 'fs'
 import * as normalizePackageData from 'normalize-package-data'
 import { type PackageURL } from 'packageurl-js'
-import * as path from 'path'
 
+import { type Logger } from './logger'
 import { makeNpmRunner, type runFunc } from './npmRunner'
 import { PropertyNames, PropertyValueBool } from './properties'
 import { versionCompare } from './versionCompare'
@@ -57,15 +59,15 @@ export class BomBuilder {
   flattenComponents: boolean
   shortPURLs: boolean
 
-  console: Console
+  logger: Logger
 
   constructor (
     toolBuilder: BomBuilder['toolBuilder'],
     componentBuilder: BomBuilder['componentBuilder'],
     treeBuilder: BomBuilder['treeBuilder'],
     purlFactory: BomBuilder['purlFactory'],
     options: BomBuilderOptions,
-    console_: BomBuilder['console']
+    logger_: BomBuilder['logger']
   ) {
     this.toolBuilder = toolBuilder
     this.componentBuilder = componentBuilder
@@ -80,7 +82,7 @@ export class BomBuilder {
     this.flattenComponents = options.flattenComponents ?? false
     this.shortPURLs = options.shortPURLs ?? false
 
-    this.console = console_
+    this.logger = logger_
   }
 
   buildFromProjectDir (projectDir: string, process: NodeJS.Process): Models.Bom {
@@ -95,31 +97,33 @@ export class BomBuilder {
 
   private getNpmVersion (npmRunner: runFunc, process_: NodeJS.Process): string {
     let version: string
-    this.console.info('INFO  | detect NPM version ...')
+    this.logger.info('detect NPM version ...')
     try {
       version = npmRunner(['--version'], {
         env: process_.env,
         encoding: 'buffer',
         maxBuffer: Number.MAX_SAFE_INTEGER // DIRTY but effective
       }).toString().trim()
     } catch (runError: any) {
-      this.console.group('DEBUG | npm-ls: STDOUT')
-      this.console.debug('%s', runError.stdout)
-      this.console.groupEnd()
-      this.console.group('WARN  | npm-ls: MESSAGE')
-      this.console.warn('%s', runError.message)
-      this.console.groupEnd()
-      this.console.group('ERROR | npm-ls: STDERR')
-      this.console.error('%s', runError.stderr)
-      this.console.groupEnd()
+      const { stdout, message, stderr } = runError
+
+      this.logger.debug('npm-ls: STDOUT')
+      this.logger.debug('%s', stdout)
+
+      this.logger.warn('npm-ls: MESSAGE')
+      this.logger.warn('%s', message)
+
+      this.logger.error('npm-ls: STDERR')
+      this.logger.error('%s', stderr)
+
       throw runError
     }
-    this.console.debug('DEBUG | detected NPM version %j', version)
+    this.logger.debug('detected NPM version %j', version)
     return version
   }
 
   private fetchNpmLs (projectDir: string, process_: NodeJS.Process): [any, string | undefined] {
-    const npmRunner = makeNpmRunner(process_, this.console)
+    const npmRunner = makeNpmRunner(process_, this.logger)
 
     const npmVersionR = this.getNpmVersion(npmRunner, process_)
     const npmVersionT = this.versionTuple(npmVersionR)
@@ -140,7 +144,7 @@ export class BomBuilder {
       if (npmVersionT[0] >= 7) {
         args.push('--package-lock-only')
       } else {
-        this.console.warn('WARN  | your NPM does not support "--package-lock-only", internally skipped this option')
+        this.logger.warn('your NPM does not support "--package-lock-only", internally skipped this option')
       }
     }
 
@@ -154,20 +158,19 @@ export class BomBuilder {
       for (const odt of this.omitDependencyTypes) {
         switch (odt) {
           case 'dev':
-            this.console.warn('WARN  | your NPM does not support "--omit=%s", internally using "--production" to mitigate', odt)
+            this.logger.warn('your NPM does not support "--omit=%s", internally using "--production" to mitigate', odt)
             args.push('--production')
             break
           case 'peer':
           case 'optional':
-            this.console.warn('WARN  | your NPM does not support "--omit=%s", internally skipped this option', odt)
+            this.logger.warn('your NPM does not support "--omit=%s", internally skipped this option', odt)
             break
         }
       }
     }
 
-    // TODO use instead ? : https://www.npmjs.com/package/debug ?
-    this.console.info('INFO  | gather dependency tree ...')
-    this.console.debug('DEBUG | npm-ls: run npm with %j in %j', args, projectDir)
+    this.logger.info('gather dependency tree ...')
+    this.logger.debug('npm-ls: run npm with %j in %j', args, projectDir)
     let npmLsReturns: Buffer
     try {
       npmLsReturns = npmRunner(args, {
@@ -177,24 +180,23 @@ export class BomBuilder {
         maxBuffer: Number.MAX_SAFE_INTEGER // DIRTY but effective
       })
     } catch (runError: any) {
-      // this.console.group('DEBUG | npm-ls: STDOUT')
-      // this.console.debug('%s', runError.stdout)
-      // this.console.groupEnd()
-      this.console.group('WARN  | npm-ls: MESSAGE')
-      this.console.warn('%s', runError.message)
-      this.console.groupEnd()
-      this.console.group('ERROR | npm-ls: STDERR')
-      this.console.error('%s', runError.stderr)
-      this.console.groupEnd()
+      const { message, stderr } = runError
+
+      this.logger.warn('npm-ls: MESSAGE')
+      this.logger.warn('%s', message)
+
+      this.logger.error('npm-ls: STDERR')
+      this.logger.error('%s', stderr)
+
       if (!this.ignoreNpmErrors) {
         throw new Error(`npm-ls exited with errors: ${
           runError.status as string ?? 'noStatus'} ${
           runError.signal as string ?? 'noSignal'}`)
       }
-      this.console.debug('DEBUG | npm-ls exited with errors that are to be ignored.')
+      this.logger.debug('npm-ls exited with errors that are to be ignored.')
       npmLsReturns = runError.stdout ?? Buffer.alloc(0)
     }
-    // this.console.debug('stdout: %s', npmLsReturns)
+
     try {
       return [
         JSON.parse(npmLsReturns.toString()),
@@ -207,8 +209,7 @@ export class BomBuilder {
   }
 
   buildFromNpmLs (data: any, npmVersion?: string): Models.Bom {
-    // TODO use instead ? : https://www.npmjs.com/package/debug ?
-    this.console.info('INFO  | build BOM ...')
+    this.logger.info('build BOM ...')
 
     // region all components & dependencies
 
@@ -327,7 +328,7 @@ export class BomBuilder {
         dep = _dep ??
           new DummyComponent(Enums.ComponentType.Library, `InterferedDependency.${depName as string}`)
         if (dep instanceof DummyComponent) {
-          this.console.warn('WARN  | InterferedDependency $j', dep.name)
+          this.logger.warn('InterferedDependency $j', dep.name)
         }
 
         allComponents.set(depData.path, dep)
@@ -415,21 +416,21 @@ export class BomBuilder {
     // older npm-ls versions (v6) hide properties behind a `_`
     const isOptional = (data.optional ?? data._optional) === true
     if (isOptional && this.omitDependencyTypes.has('optional')) {
-      this.console.debug('DEBUG | omit optional component: %j %j', data.name, data._id)
+      this.logger.debug('omit optional component: %j %j', data.name, data._id)
       return false
     }
 
     // older npm-ls versions (v6) hide properties behind a `_`
     const isDev = (data.dev ?? data._development) === true
     if (isDev && this.omitDependencyTypes.has('dev')) {
-      this.console.debug('DEBUG | omit dev component: %j %j', data.name, data._id)
+      this.logger.debug('omit dev component: %j %j', data.name, data._id)
       return false
     }
 
     // attention: `data.devOptional` are not to be skipped with devs, since they are still required by optionals.
     const isDevOptional = data.devOptional === true
     if (isDevOptional && this.omitDependencyTypes.has('dev') && this.omitDependencyTypes.has('optional')) {
-      this.console.debug('DEBUG | omit devOptional component: %j %j', data.name, data._id)
+      this.logger.debug('omit devOptional component: %j %j', data.name, data._id)
       return false
     }
 
@@ -448,7 +449,7 @@ export class BomBuilder {
 
     const component = this.componentBuilder.makeComponent(_dataC, type)
     if (component === undefined) {
-      this.console.debug('DEBUG | skip broken component: %j %j', data.name, data._id)
+      this.logger.debug('skip broken component: %j %j', data.name, data._id)
       return undefined
     }
 

src/cli.ts

@@ -17,12 +17,14 @@ SPDX-License-Identifier: Apache-2.0
 Copyright (c) OWASP Foundation. All Rights Reserved.
 */
 
+import { existsSync, openSync, writeSync } from 'node:fs'
+import { dirname, resolve } from 'node:path'
+
 import { Builders, Enums, Factories, Serialize, Spec, Validation } from '@cyclonedx/cyclonedx-library'
 import { Argument, Command, Option } from 'commander'
-import { existsSync, openSync, writeSync } from 'fs'
-import { dirname, resolve } from 'path'
 
 import { BomBuilder, TreeBuilder } from './builders'
+import { createLogger, defaultLogLevel, type VerbosityLevel, verbosityLevels } from './logger'
 
 enum OutputFormat {
   JSON = 'JSON',
@@ -38,6 +40,7 @@ enum Omittable {
 const OutputStdOut = '-'
 
 interface CommandOptions {
+  verbosity: VerbosityLevel
   ignoreNpmErrors: boolean
   packageLockOnly: boolean
   omit: Omittable[]
@@ -58,6 +61,12 @@ function makeCommand (process: NodeJS.Process): Command {
   ).usage(
     // Need to add the `[--]` manually, to indicate how to stop a variadic option.
     '[options] [--] [<package-manifest>]'
+  ).addOption(
+    new Option(
+      '--verbosity <verbosity>',
+      'Which verbosity level the logger should write to STDERR'
+    ).choices(verbosityLevels
+    ).default(defaultLogLevel)
   ).addOption(
     new Option(
       '--ignore-npm-errors',
@@ -189,36 +198,35 @@ const ExitCode: Readonly<Record<string, number>> = Object.freeze({
 export async function run (process: NodeJS.Process): Promise<number> {
   process.title = 'cyclonedx-node-npm'
 
-  // all output shall be bound to stdError - stdOut is for result output only
-  const myConsole = new console.Console(process.stderr, process.stderr)
-
   const program = makeCommand(process)
   program.parse(process.argv)
 
   const options: CommandOptions = program.opts()
-  myConsole.debug('DEBUG | options: %j', options)
+  const logger = createLogger(options.verbosity)
+
+  logger.debug('options: %j', options)
 
   const packageFile = resolve(process.cwd(), program.args[0] ?? 'package.json')
   if (!existsSync(packageFile)) {
     throw new Error(`missing project's manifest file: ${packageFile}`)
   }
-  myConsole.debug('DEBUG | packageFile: %s', packageFile)
+  logger.debug('packageFile: %s', packageFile)
   const projectDir = dirname(packageFile)
-  myConsole.info('INFO  | projectDir: %s', projectDir)
+  logger.info('projectDir: %s', projectDir)
 
   if (existsSync(resolve(projectDir, 'npm-shrinkwrap.json'))) {
-    myConsole.debug('DEBUG | detected a npm shrinkwrap file')
+    logger.debug('detected a npm shrinkwrap file')
   } else if (existsSync(resolve(projectDir, 'package-lock.json'))) {
-    myConsole.debug('DEBUG | detected a package lock file')
+    logger.debug('detected a package lock file')
   } else if (!options.packageLockOnly && existsSync(resolve(projectDir, 'node_modules'))) {
-    myConsole.debug('DEBUG | detected a node_modules dir')
+    logger.debug('detected a node_modules dir')
     // npm7 and later also might put a `node_modules/.package-lock.json` file
   } else {
-    myConsole.log('LOG   | No evidence: no package lock file nor npm shrinkwrap file')
+    logger.trace('No evidence: no package lock file nor npm shrinkwrap file')
     if (!options.packageLockOnly) {
-      myConsole.log('LOG   | No evidence: no node_modules dir')
+      logger.trace('No evidence: no node_modules dir')
     }
-    myConsole.info('INFO  | ? Did you forget to run `npm install` on your project accordingly ?')
+    logger.info('Did you forget to run `npm install` on your project accordingly ?')
     throw new Error('missing evidence')
   }
 
@@ -241,7 +249,7 @@ export async function run (process: NodeJS.Process): Promise<number> {
       flattenComponents: options.flattenComponents,
       shortPURLs: options.shortPURLs
     },
-    myConsole
+    logger.child({}, { msgPrefix: 'BomBuilder > ' })
   ).buildFromProjectDir(projectDir, process)
 
   const spec = Spec.SpecVersionDict[options.specVersion]
@@ -262,36 +270,33 @@ export async function run (process: NodeJS.Process): Promise<number> {
       break
   }
 
-  myConsole.log('LOG   | serialize BOM')
+  logger.trace('serialize BOM')
   const serialized = serializer.serialize(bom, {
     sortLists: options.outputReproducible,
     space: 2
   })
 
   if (options.validate) {
-    myConsole.log('LOG   | try validate BOM result ...')
+    logger.trace('try validate BOM result ...')
     try {
       const validationErrors = await validator.validate(serialized)
       if (validationErrors !== null) {
-        myConsole.debug('DEBUG | BOM result invalid. details: ', validationErrors)
-        myConsole.error('ERROR | Failed to generate valid BOM.')
-        myConsole.warn(
-          'WARN  | Please report the issue and provide the npm lock file of the current project to:\n' +
-          '      | https://github.com/CycloneDX/cyclonedx-node-npm/issues/new?template=ValidationError-report.md&labels=ValidationError&title=%5BValidationError%5D')
+        logger.debug('BOM result invalid. details: ', validationErrors)
+        logger.error('Failed to generate valid BOM.')
+        logger.warn('Please report the issue and provide the npm lock file of the current project to: https://github.com/CycloneDX/cyclonedx-node-npm/issues/new?template=ValidationError-report.md&labels=ValidationError&title=%5BValidationError%5D')
         return ExitCode.FAILURE
       }
     } catch (err) {
       if (err instanceof Validation.MissingOptionalDependencyError) {
-        myConsole.info('INFO  | skipped validate BOM:', err.message)
+        logger.info('skipped validate BOM:', err.message)
       } else {
-        myConsole.error('ERROR | unexpected error')
+        logger.error('unexpected error')
         throw err
       }
     }
   }
 
-  // TODO use instead ? : https://www.npmjs.com/package/debug ?
-  myConsole.log('LOG   | writing BOM to', options.outputFile)
+  logger.trace('writing BOM to', options.outputFile)
   writeSync(
     options.outputFile === OutputStdOut
       ? process.stdout.fd

src/logger.ts

@@ -0,0 +1,47 @@
+/*!
+This file is part of CycloneDX generator for NPM projects.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+   http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+
+SPDX-License-Identifier: Apache-2.0
+Copyright (c) OWASP Foundation. All Rights Reserved.
+*/
+
+import { type BaseLogger, type Level, type LevelWithSilent, type LoggerExtras, pino } from 'pino'
+
+const logLevels: Level[] = ['debug', 'error', 'fatal', 'warn', 'info', 'trace'] as const
+export const verbosityLevels: LevelWithSilent[] = [...logLevels, 'silent'] as const
+
+export type Logger = BaseLogger & LoggerExtras<{
+  level: LevelWithSilent
+  name: string
+  transport: { options: { colorize: boolean, ignore: string }, target: string }
+}>
+
+export type VerbosityLevel = LevelWithSilent
+
+export const createLogger: (verbosityLevel: VerbosityLevel) => Logger = (verbosityLevel: VerbosityLevel) => pino({
+  name: 'cyclonedx-node-npm',
+  level: verbosityLevel,
+  timestamp: false,
+  transport: {
+    target: 'pino-pretty',
+    options: {
+      colorize: true,
+      ignore: 'pid,name,hostname',
+      destination: 2
+    }
+  }
+})
+
+export const defaultLogLevel: VerbosityLevel = 'warn'

src/npmRunner.ts

@@ -17,9 +17,11 @@ SPDX-License-Identifier: Apache-2.0
 Copyright (c) OWASP Foundation. All Rights Reserved.
 */
 
-import { execFileSync, execSync, type ExecSyncOptionsWithBufferEncoding } from 'child_process'
-import { existsSync } from 'fs'
-import { resolve } from 'path'
+import { execFileSync, execSync, type ExecSyncOptionsWithBufferEncoding } from 'node:child_process'
+import { existsSync } from 'node:fs'
+import { resolve } from 'node:path'
+
+import { type Logger } from './logger'
 
 /** !attention: args might not be shell-save. */
 export type runFunc = (args: string[], options: ExecSyncOptionsWithBufferEncoding) => Buffer
@@ -45,7 +47,7 @@ const jsMatcher = /\.[cm]?js$/
 /**
  * @throws {Error} when npm path unexpected
  */
-function getExecPath (process_: NodeJS.Process, console_: Console): string | undefined {
+function getExecPath (process_: NodeJS.Process, logger_: Logger): string | undefined {
   // `npm_execpath` will be whichever cli script has called this application by npm.
   // This can be `npm`, `npx`, or `undefined` if called by `node` directly.
   const execPath = process_.env.npm_execpath ?? ''
@@ -55,7 +57,7 @@ function getExecPath (process_: NodeJS.Process, console_: Console): string | und
 
   if (npxMatcher.test(execPath)) {
     // `npm` must be used for executing `ls`.
-    console_.debug('DEBUG | command: npx-cli.js usage detected, checking for npm-cli.js ...')
+    logger_.debug('command: npx-cli.js usage detected, checking for npm-cli.js ...')
     // Typically `npm-cli.js` is alongside `npx-cli.js`, as such we attempt to use this and validate it exists.
     // Replace the script in the path, and normalise it with resolve (eliminates any extraneous path separators).
     const npmPath = resolve(execPath.replace(npxMatcher, '$1npm-cli.js'))
@@ -69,20 +71,20 @@ function getExecPath (process_: NodeJS.Process, console_: Console): string | und
   throw new Error(`unexpected NPM execPath: ${execPath}`)
 }
 
-export function makeNpmRunner (process_: NodeJS.Process, console_: Console): runFunc {
-  const execPath = getExecPath(process_, console_)
+export function makeNpmRunner (process_: NodeJS.Process, logger_: Logger): runFunc {
+  const execPath = getExecPath(process_, logger_)
   if (execPath === undefined) {
-    console_.debug('DEBUG | makeNpmRunner caused execSync "npm"')
+    logger_.debug('makeNpmRunner caused execSync "npm"')
     // not shell-save - but this is okay four our use case - since we have complete control over `args` in the caller.
     return (args, options) => execSync('npm ' + args.join(' '), options)
   }
 
   if (jsMatcher.test(execPath)) {
     const nodeExecPath = process_.execPath
-    console_.debug('DEBUG | makeNpmRunner caused execFileSync "%s" with  "-- %s"', nodeExecPath, execPath)
+    logger_.debug('makeNpmRunner caused execFileSync "%s" with  "-- %s"', nodeExecPath, execPath)
     return (args, options) => execFileSync(nodeExecPath, ['--', execPath, ...args], options)
   }
 
-  console_.debug('DEBUG | makeNpmRunner caused execFileSync "%s"', execPath)
+  logger_.debug('makeNpmRunner caused execFileSync "%s"', execPath)
   return (args, options) => execFileSync(execPath, args, options)
 }