From bb10d8a27e9fa99948fa6a13bf48a6bc59c40199 Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Mon, 4 Dec 2023 20:30:24 +0100
Subject: [PATCH 1/9] feat: add logger

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 package.json     |  2 ++
 src/builders.ts  | 75 ++++++++++++++++++++++--------------------------
 src/cli.ts       | 58 ++++++++++++++++++++-----------------
 src/logger.ts    | 43 +++++++++++++++++++++++++++
 src/npmRunner.ts | 22 +++++++-------
 5 files changed, 123 insertions(+), 77 deletions(-)
 create mode 100644 src/logger.ts

diff --git a/package.json b/package.json
index c869a9574..abb870f3d 100644
--- a/package.json
+++ b/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": {
diff --git a/src/builders.ts b/src/builders.ts
index 07419cd12..544bdb00a 100644
--- a/src/builders.ts
+++ b/src/builders.ts
@@ -18,11 +18,12 @@ Copyright (c) OWASP Foundation. All Rights Reserved.
 */
 
 import { type Builders, Enums, type Factories, Models, Utils } from '@cyclonedx/cyclonedx-library'
-import { existsSync } from 'fs'
+import { existsSync } from 'node:fs'
 import * as normalizePackageData from 'normalize-package-data'
 import { type PackageURL } from 'packageurl-js'
-import * as path from 'path'
+import * as path from 'node:path'
 
+import { type Logger } from './logger'
 import { makeNpmRunner, type runFunc } from './npmRunner'
 import { PropertyNames, PropertyValueBool } from './properties'
 import { versionCompare } from './versionCompare'
@@ -57,7 +58,7 @@ export class BomBuilder {
   flattenComponents: boolean
   shortPURLs: boolean
 
-  console: Console
+  logger: Logger
 
   constructor (
     toolBuilder: BomBuilder['toolBuilder'],
@@ -65,7 +66,7 @@ export class BomBuilder {
     treeBuilder: BomBuilder['treeBuilder'],
     purlFactory: BomBuilder['purlFactory'],
     options: BomBuilderOptions,
-    console_: BomBuilder['console']
+    logger_: BomBuilder['logger']
   ) {
     this.toolBuilder = toolBuilder
     this.componentBuilder = componentBuilder
@@ -80,7 +81,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,7 +96,7 @@ 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,
@@ -103,23 +104,20 @@ export class BomBuilder {
         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({stdout}, 'npm-ls:')
+      this.logger.warn({message}, 'npm-ls:')
+      this.logger.error({stderr}, 'npm-ls:')
+
       throw runError
     }
-    this.console.debug('DEBUG | detected NPM version %j', version)
+    this.logger.debug(`detected NPM version "${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 +138,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 +152,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=${odt}", internally using "--production" to mitigate`)
             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=${odt}", internally skipped this option`)
             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 ${JSON.stringify(args)} in "${projectDir}"`)
     let npmLsReturns: Buffer
     try {
       npmLsReturns = npmRunner(args, {
@@ -177,24 +174,20 @@ 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({message}, 'npm-ls:')
+      this.logger.error({stderr}, 'npm-ls:')
+
       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 +200,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 +319,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 "${dep.name}"`)
         }
 
         allComponents.set(depData.path, dep)
@@ -415,21 +407,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: ${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: ${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: ${data.name} ${data._id}`)
       return false
     }
 
@@ -448,7 +440,8 @@ 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: ${data.name} ${data._id}`)
       return undefined
     }
 
diff --git a/src/cli.ts b/src/cli.ts
index 45e2b6a42..27cea42a3 100644
--- a/src/cli.ts
+++ b/src/cli.ts
@@ -17,12 +17,15 @@ 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, VerbosityLevel, verbosityLevels } from "./logger";
+
 
 enum OutputFormat {
   JSON = 'JSON',
@@ -38,6 +41,7 @@ enum Omittable {
 const OutputStdOut = '-'
 
 interface CommandOptions {
+  verbosity: VerbosityLevel
   ignoreNpmErrors: boolean
   packageLockOnly: boolean
   omit: Omittable[]
@@ -58,6 +62,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('warn')
   ).addOption(
     new Option(
       '--ignore-npm-errors',
@@ -189,36 +199,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 })
 
   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, 'packageFile:')
   const projectDir = dirname(packageFile)
-  myConsole.info('INFO  | projectDir: %s', projectDir)
+  logger.info( `projectDir: "${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 +250,7 @@ export async function run (process: NodeJS.Process): Promise<number> {
       flattenComponents: options.flattenComponents,
       shortPURLs: options.shortPURLs
     },
-    myConsole
+    logger
   ).buildFromProjectDir(projectDir, process)
 
   const spec = Spec.SpecVersionDict[options.specVersion]
@@ -262,36 +271,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
diff --git a/src/logger.ts b/src/logger.ts
new file mode 100644
index 000000000..22174cf96
--- /dev/null
+++ b/src/logger.ts
@@ -0,0 +1,43 @@
+/*!
+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 { stderr } from 'node:process';
+import { type BaseLogger, type Level, type LevelWithSilent, pino } from 'pino'
+
+const logLevels: Level[] = ['debug', 'error', 'fatal', 'warn', 'info', 'trace'] as const
+export const verbosityLevels: LevelWithSilent[] = [...logLevels, 'silent'] as const;
+
+// all output shall be bound to stdError - stdOut is for result output only
+const streams = logLevels.map((level) => ({ level, stream: stderr }))
+
+export type Logger = BaseLogger
+export type VerbosityLevel = LevelWithSilent
+
+export const createLogger = (verbosityLevel: VerbosityLevel): Logger =>  pino({
+  name: 'cyclonedx-node-npm',
+  level: verbosityLevel,
+  transport: {
+    target: 'pino-pretty',
+    options: {
+      colorize: true,
+      ignore: 'pid,name,hostname',
+    }
+  }
+}, pino.multistream(streams))
+
diff --git a/src/npmRunner.ts b/src/npmRunner.ts
index 4c32d53be..ec8b274d9 100644
--- a/src/npmRunner.ts
+++ b/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 "${nodeExecPath}" with  "-- ${execPath}"`)
     return (args, options) => execFileSync(nodeExecPath, ['--', execPath, ...args], options)
   }
 
-  console_.debug('DEBUG | makeNpmRunner caused execFileSync "%s"', execPath)
+  logger_.debug(`makeNpmRunner caused execFileSync "${execPath}"`)
   return (args, options) => execFileSync(execPath, args, options)
 }

From e7d67943aa5c2aaf3494c8c52b1b1515a38b388a Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Mon, 4 Dec 2023 20:31:29 +0100
Subject: [PATCH 2/9] feat: add logger

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 src/builders.ts | 20 ++++++++++----------
 src/cli.ts      |  5 ++---
 src/logger.ts   | 10 +++++-----
 3 files changed, 17 insertions(+), 18 deletions(-)

diff --git a/src/builders.ts b/src/builders.ts
index 544bdb00a..c14ad68a9 100644
--- a/src/builders.ts
+++ b/src/builders.ts
@@ -17,11 +17,12 @@ SPDX-License-Identifier: Apache-2.0
 Copyright (c) OWASP Foundation. All Rights Reserved.
 */
 
-import { type Builders, Enums, type Factories, Models, Utils } from '@cyclonedx/cyclonedx-library'
 import { existsSync } from 'node:fs'
+import * as path from 'node:path'
+
+import { type Builders, Enums, type Factories, Models, Utils } from '@cyclonedx/cyclonedx-library'
 import * as normalizePackageData from 'normalize-package-data'
 import { type PackageURL } from 'packageurl-js'
-import * as path from 'node:path'
 
 import { type Logger } from './logger'
 import { makeNpmRunner, type runFunc } from './npmRunner'
@@ -104,11 +105,11 @@ export class BomBuilder {
         maxBuffer: Number.MAX_SAFE_INTEGER // DIRTY but effective
       }).toString().trim()
     } catch (runError: any) {
-      const {stdout, message, stderr} = runError;
+      const { stdout, message, stderr } = runError
 
-      this.logger.debug({stdout}, 'npm-ls:')
-      this.logger.warn({message}, 'npm-ls:')
-      this.logger.error({stderr}, 'npm-ls:')
+      this.logger.debug({ stdout }, 'npm-ls:')
+      this.logger.warn({ message }, 'npm-ls:')
+      this.logger.error({ stderr }, 'npm-ls:')
 
       throw runError
     }
@@ -174,10 +175,10 @@ export class BomBuilder {
         maxBuffer: Number.MAX_SAFE_INTEGER // DIRTY but effective
       })
     } catch (runError: any) {
-      const {message, stderr} = runError;
+      const { message, stderr } = runError
 
-      this.logger.warn({message}, 'npm-ls:')
-      this.logger.error({stderr}, 'npm-ls:')
+      this.logger.warn({ message }, 'npm-ls:')
+      this.logger.error({ stderr }, 'npm-ls:')
 
       if (!this.ignoreNpmErrors) {
         throw new Error(`npm-ls exited with errors: ${
@@ -440,7 +441,6 @@ export class BomBuilder {
 
     const component = this.componentBuilder.makeComponent(_dataC, type)
     if (component === undefined) {
-
       this.logger.debug(`skip broken component: ${data.name} ${data._id}`)
       return undefined
     }
diff --git a/src/cli.ts b/src/cli.ts
index 27cea42a3..434362fef 100644
--- a/src/cli.ts
+++ b/src/cli.ts
@@ -24,8 +24,7 @@ import { Builders, Enums, Factories, Serialize, Spec, Validation } from '@cyclon
 import { Argument, Command, Option } from 'commander'
 
 import { BomBuilder, TreeBuilder } from './builders'
-import { createLogger, VerbosityLevel, verbosityLevels } from "./logger";
-
+import { createLogger, type VerbosityLevel, verbosityLevels } from './logger'
 
 enum OutputFormat {
   JSON = 'JSON',
@@ -213,7 +212,7 @@ export async function run (process: NodeJS.Process): Promise<number> {
   }
   logger.debug(packageFile, 'packageFile:')
   const projectDir = dirname(packageFile)
-  logger.info( `projectDir: "${projectDir}"`)
+  logger.info(`projectDir: "${projectDir}"`)
 
   if (existsSync(resolve(projectDir, 'npm-shrinkwrap.json'))) {
     logger.debug('detected a npm shrinkwrap file')
diff --git a/src/logger.ts b/src/logger.ts
index 22174cf96..ba40786c6 100644
--- a/src/logger.ts
+++ b/src/logger.ts
@@ -17,11 +17,12 @@ SPDX-License-Identifier: Apache-2.0
 Copyright (c) OWASP Foundation. All Rights Reserved.
 */
 
-import { stderr } from 'node:process';
+import { stderr } from 'node:process'
+
 import { type BaseLogger, type Level, type LevelWithSilent, pino } from 'pino'
 
 const logLevels: Level[] = ['debug', 'error', 'fatal', 'warn', 'info', 'trace'] as const
-export const verbosityLevels: LevelWithSilent[] = [...logLevels, 'silent'] as const;
+export const verbosityLevels: LevelWithSilent[] = [...logLevels, 'silent'] as const
 
 // all output shall be bound to stdError - stdOut is for result output only
 const streams = logLevels.map((level) => ({ level, stream: stderr }))
@@ -29,15 +30,14 @@ const streams = logLevels.map((level) => ({ level, stream: stderr }))
 export type Logger = BaseLogger
 export type VerbosityLevel = LevelWithSilent
 
-export const createLogger = (verbosityLevel: VerbosityLevel): Logger =>  pino({
+export const createLogger = (verbosityLevel: VerbosityLevel): Logger => pino({
   name: 'cyclonedx-node-npm',
   level: verbosityLevel,
   transport: {
     target: 'pino-pretty',
     options: {
       colorize: true,
-      ignore: 'pid,name,hostname',
+      ignore: 'pid,name,hostname'
     }
   }
 }, pino.multistream(streams))
-

From 3f600e34f13439c944fb4cf2ed6f32a718d2b892 Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Tue, 5 Dec 2023 21:00:51 +0100
Subject: [PATCH 3/9] feat: add default log level const

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 src/cli.ts    | 4 ++--
 src/logger.ts | 2 ++
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/src/cli.ts b/src/cli.ts
index 434362fef..0a38f600c 100644
--- a/src/cli.ts
+++ b/src/cli.ts
@@ -24,7 +24,7 @@ import { Builders, Enums, Factories, Serialize, Spec, Validation } from '@cyclon
 import { Argument, Command, Option } from 'commander'
 
 import { BomBuilder, TreeBuilder } from './builders'
-import { createLogger, type VerbosityLevel, verbosityLevels } from './logger'
+import { createLogger, defaultLogLevel, type VerbosityLevel, verbosityLevels } from './logger'
 
 enum OutputFormat {
   JSON = 'JSON',
@@ -66,7 +66,7 @@ function makeCommand (process: NodeJS.Process): Command {
       '--verbosity <verbosity>',
       'Which verbosity level the logger should write to STDERR'
     ).choices(verbosityLevels
-    ).default('warn')
+    ).default(defaultLogLevel)
   ).addOption(
     new Option(
       '--ignore-npm-errors',
diff --git a/src/logger.ts b/src/logger.ts
index ba40786c6..2905c3753 100644
--- a/src/logger.ts
+++ b/src/logger.ts
@@ -41,3 +41,5 @@ export const createLogger = (verbosityLevel: VerbosityLevel): Logger => pino({
     }
   }
 }, pino.multistream(streams))
+
+export const defaultLogLevel: VerbosityLevel = 'warn'

From 532f85314ef0cb3f795475188c8b14a3a9901be0 Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Tue, 5 Dec 2023 21:15:27 +0100
Subject: [PATCH 4/9] feat: adjust string interpolation via parameters

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 src/builders.ts  | 36 ++++++++++++++++++++++--------------
 src/cli.ts       |  6 +++---
 src/npmRunner.ts |  4 ++--
 3 files changed, 27 insertions(+), 19 deletions(-)

diff --git a/src/builders.ts b/src/builders.ts
index c14ad68a9..b70f0c9bc 100644
--- a/src/builders.ts
+++ b/src/builders.ts
@@ -107,13 +107,18 @@ export class BomBuilder {
     } catch (runError: any) {
       const { stdout, message, stderr } = runError
 
-      this.logger.debug({ stdout }, 'npm-ls:')
-      this.logger.warn({ message }, 'npm-ls:')
-      this.logger.error({ stderr }, 'npm-ls:')
+      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.logger.debug(`detected NPM version "${version}"`)
+    this.logger.debug('detected NPM version %s"', version)
     return version
   }
 
@@ -153,19 +158,19 @@ export class BomBuilder {
       for (const odt of this.omitDependencyTypes) {
         switch (odt) {
           case 'dev':
-            this.logger.warn(`your NPM does not support "--omit=${odt}", internally using "--production" to mitigate`)
+            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.logger.warn(`your NPM does not support "--omit=${odt}", internally skipped this option`)
+            this.logger.warn('your NPM does not support "--omit=%s", internally skipped this option', odt)
             break
         }
       }
     }
 
     this.logger.info('gather dependency tree ...')
-    this.logger.debug(`npm-ls: run npm with ${JSON.stringify(args)} in "${projectDir}"`)
+    this.logger.debug('npm-ls: run npm with %j in %j', args, projectDir)
     let npmLsReturns: Buffer
     try {
       npmLsReturns = npmRunner(args, {
@@ -177,8 +182,11 @@ export class BomBuilder {
     } catch (runError: any) {
       const { message, stderr } = runError
 
-      this.logger.warn({ message }, 'npm-ls:')
-      this.logger.error({ stderr }, 'npm-ls:')
+      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: ${
@@ -320,7 +328,7 @@ export class BomBuilder {
         dep = _dep ??
           new DummyComponent(Enums.ComponentType.Library, `InterferedDependency.${depName as string}`)
         if (dep instanceof DummyComponent) {
-          this.logger.warn(`InterferedDependency "${dep.name}"`)
+          this.logger.warn('InterferedDependency $j', dep.name)
         }
 
         allComponents.set(depData.path, dep)
@@ -408,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.logger.debug(`omit optional component: ${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.logger.debug(`omit dev component: ${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.logger.debug(`omit devOptional component: ${data.name} ${data._id}`)
+      this.logger.debug('omit devOptional component: %j %j', data.name, data._id)
       return false
     }
 
@@ -441,7 +449,7 @@ export class BomBuilder {
 
     const component = this.componentBuilder.makeComponent(_dataC, type)
     if (component === undefined) {
-      this.logger.debug(`skip broken component: ${data.name} ${data._id}`)
+      this.logger.debug('skip broken component: %j %j', data.name, data._id)
       return undefined
     }
 
diff --git a/src/cli.ts b/src/cli.ts
index 0a38f600c..dd3917dd9 100644
--- a/src/cli.ts
+++ b/src/cli.ts
@@ -204,15 +204,15 @@ export async function run (process: NodeJS.Process): Promise<number> {
   const options: CommandOptions = program.opts()
   const logger = createLogger(options.verbosity)
 
-  logger.debug({ options })
+  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}`)
   }
-  logger.debug(packageFile, 'packageFile:')
+  logger.debug('packageFile: %s', packageFile)
   const projectDir = dirname(packageFile)
-  logger.info(`projectDir: "${projectDir}"`)
+  logger.info('projectDir: %s', projectDir)
 
   if (existsSync(resolve(projectDir, 'npm-shrinkwrap.json'))) {
     logger.debug('detected a npm shrinkwrap file')
diff --git a/src/npmRunner.ts b/src/npmRunner.ts
index ec8b274d9..22f511c87 100644
--- a/src/npmRunner.ts
+++ b/src/npmRunner.ts
@@ -81,10 +81,10 @@ export function makeNpmRunner (process_: NodeJS.Process, logger_: Logger): runFu
 
   if (jsMatcher.test(execPath)) {
     const nodeExecPath = process_.execPath
-    logger_.debug(`makeNpmRunner caused execFileSync "${nodeExecPath}" with  "-- ${execPath}"`)
+    logger_.debug('makeNpmRunner caused execFileSync "%s" with  "-- %s"', nodeExecPath, execPath)
     return (args, options) => execFileSync(nodeExecPath, ['--', execPath, ...args], options)
   }
 
-  logger_.debug(`makeNpmRunner caused execFileSync "${execPath}"`)
+  logger_.debug('makeNpmRunner caused execFileSync "%s"', execPath)
   return (args, options) => execFileSync(execPath, args, options)
 }

From 91b4b489a815831592835066c2c9056459796402 Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Tue, 5 Dec 2023 21:18:20 +0100
Subject: [PATCH 5/9] fix: wrong placeholder

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 src/builders.ts | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/builders.ts b/src/builders.ts
index b70f0c9bc..0aff40a95 100644
--- a/src/builders.ts
+++ b/src/builders.ts
@@ -118,7 +118,7 @@ export class BomBuilder {
 
       throw runError
     }
-    this.logger.debug('detected NPM version %s"', version)
+    this.logger.debug('detected NPM version %j', version)
     return version
   }
 

From ecaf9a3f437dcc1b116f8083e11da2a0aac951da Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Tue, 5 Dec 2023 21:25:20 +0100
Subject: [PATCH 6/9] feat: add child logger

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 src/cli.ts    |  2 +-
 src/logger.ts | 11 ++++++++---
 2 files changed, 9 insertions(+), 4 deletions(-)

diff --git a/src/cli.ts b/src/cli.ts
index dd3917dd9..30165cdc2 100644
--- a/src/cli.ts
+++ b/src/cli.ts
@@ -249,7 +249,7 @@ export async function run (process: NodeJS.Process): Promise<number> {
       flattenComponents: options.flattenComponents,
       shortPURLs: options.shortPURLs
     },
-    logger
+    logger.child({}, { msgPrefix: 'BomBuilder > ' })
   ).buildFromProjectDir(projectDir, process)
 
   const spec = Spec.SpecVersionDict[options.specVersion]
diff --git a/src/logger.ts b/src/logger.ts
index 2905c3753..880a59d5b 100644
--- a/src/logger.ts
+++ b/src/logger.ts
@@ -19,7 +19,7 @@ Copyright (c) OWASP Foundation. All Rights Reserved.
 
 import { stderr } from 'node:process'
 
-import { type BaseLogger, type Level, type LevelWithSilent, pino } from 'pino'
+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
@@ -27,10 +27,15 @@ export const verbosityLevels: LevelWithSilent[] = [...logLevels, 'silent'] as co
 // all output shall be bound to stdError - stdOut is for result output only
 const streams = logLevels.map((level) => ({ level, stream: stderr }))
 
-export type Logger = BaseLogger
+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 => pino({
+export const createLogger: (verbosityLevel: VerbosityLevel) => Logger = (verbosityLevel: VerbosityLevel) => pino({
   name: 'cyclonedx-node-npm',
   level: verbosityLevel,
   transport: {

From b5af86bc09f17b99d44a3ab85baec662b052d0b9 Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Wed, 6 Dec 2023 20:44:42 +0100
Subject: [PATCH 7/9] fix: writing to stderr

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 src/logger.ts | 10 ++++------
 1 file changed, 4 insertions(+), 6 deletions(-)

diff --git a/src/logger.ts b/src/logger.ts
index 880a59d5b..20600913e 100644
--- a/src/logger.ts
+++ b/src/logger.ts
@@ -17,15 +17,11 @@ SPDX-License-Identifier: Apache-2.0
 Copyright (c) OWASP Foundation. All Rights Reserved.
 */
 
-import { stderr } from 'node:process'
-
 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
 
-// all output shall be bound to stdError - stdOut is for result output only
-const streams = logLevels.map((level) => ({ level, stream: stderr }))
 
 export type Logger = BaseLogger & LoggerExtras<{
   level: LevelWithSilent
@@ -42,9 +38,11 @@ export const createLogger: (verbosityLevel: VerbosityLevel) => Logger = (verbosi
     target: 'pino-pretty',
     options: {
       colorize: true,
-      ignore: 'pid,name,hostname'
+      translateTime: "SYS:yyyy-mm-dd HH:MM:ss.l",
+      ignore: 'pid,name,hostname',
+      destination: 2
     }
   }
-}, pino.multistream(streams))
+})
 
 export const defaultLogLevel: VerbosityLevel = 'warn'

From 49af968a8d60e0c542843176d91f16f338d1352d Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Wed, 6 Dec 2023 20:47:14 +0100
Subject: [PATCH 8/9] fix: raise required node version

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 package.json  | 2 +-
 src/logger.ts | 3 +--
 2 files changed, 2 insertions(+), 3 deletions(-)

diff --git a/package.json b/package.json
index 14ce26e90..beb498157 100644
--- a/package.json
+++ b/package.json
@@ -76,7 +76,7 @@
   },
   "type": "commonjs",
   "engines": {
-    "node": ">=14",
+    "node": ">=14.17.0",
     "npm": "6 - 10"
   },
   "directories": {
diff --git a/src/logger.ts b/src/logger.ts
index 20600913e..f4dec1298 100644
--- a/src/logger.ts
+++ b/src/logger.ts
@@ -22,7 +22,6 @@ import { type BaseLogger, type Level, type LevelWithSilent, type LoggerExtras, p
 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
@@ -38,7 +37,7 @@ export const createLogger: (verbosityLevel: VerbosityLevel) => Logger = (verbosi
     target: 'pino-pretty',
     options: {
       colorize: true,
-      translateTime: "SYS:yyyy-mm-dd HH:MM:ss.l",
+      translateTime: 'SYS:yyyy-mm-dd HH:MM:ss.l',
       ignore: 'pid,name,hostname',
       destination: 2
     }

From 8f58bca491ddabd632d61f6e3bbbbbb54b160d9c Mon Sep 17 00:00:00 2001
From: jase88 <804836+jase88@users.noreply.github.com>
Date: Thu, 7 Dec 2023 16:17:35 +0100
Subject: [PATCH 9/9] fix: disable timestamps

Signed-off-by: jase88 <804836+jase88@users.noreply.github.com>
---
 src/logger.ts | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/logger.ts b/src/logger.ts
index f4dec1298..41292c92c 100644
--- a/src/logger.ts
+++ b/src/logger.ts
@@ -33,11 +33,11 @@ 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,
-      translateTime: 'SYS:yyyy-mm-dd HH:MM:ss.l',
       ignore: 'pid,name,hostname',
       destination: 2
     }