feat: separate configs for --timing and --loglevel

BREAKING CHANGE: `timing` and `loglevel` changes
- `timing` has been removed as a value for `--loglevel`
- `--timing` will show timing information regardless of
  `--loglevel`, except when `--silent`

Closes npm/statusboard#455
Closes npm/statusboard#454

Author: lukekarrys

docs/lib/content/using-npm/logging.md

@@ -14,6 +14,9 @@ All logs are written to a debug log, with the path to that file printed if the e
 
 The default location of the logs directory is a directory named `_logs` inside the npm cache. This can be changed with the `logs-dir` config option.
 
+For example, if you wanted to write all your logs to the current working directory, you could run: `npm install --logs-dir=.`.  This is especially helpful in debugging a specific `npm` issue as you can run
+a command multiple times with different config values and then diff all the log files.
+
 Log files will be removed from the `logs-dir` when the number of log files exceeds `logs-max`, with the oldest logs being deleted first.
 
 To turn off logs completely set `--logs-max=0`.
@@ -31,7 +34,6 @@ The default value of `loglevel` is `"notice"` but there are several levels/types
 - `"warn"`
 - `"notice"`
 - `"http"`
-- `"timing"`
 - `"info"`
 - `"verbose"`
 - `"silly"`
@@ -57,15 +59,21 @@ The `npm` CLI began hiding the output of lifecycle scripts for `npm install` as
 
 ### Timing Information
 
-The [`--timing` config](/using-npm/config#timing) can be set which does two
+The [`--timing` config](/using-npm/config#timing) can be set which does a few
 things:
 
 1. Always shows the full path to the debug log regardless of command exit status
 1. Write timing information to a process specific timing file in the cache or `logs-dir`
+1. Output timing information to the terminal
 
 This file contains a `timers` object where the keys are an identifier for the
 portion of the process being timed and the value is the number of milliseconds it took to complete.
 
+Sometimes it is helpful to get timing information without outputting anything to the terminal. For
+example, the performance might be affected by writing to the terminal. In this case you can use
+`--timing --silent` which will still write the timing file, but not output anything to the terminal
+while running.
+
 ### Registry Response Headers
 
 #### `npm-notice`

lib/utils/config/definitions.js

@@ -1273,7 +1273,6 @@ define('loglevel', {
     'warn',
     'notice',
     'http',
-    'timing',
     'info',
     'verbose',
     'silly',
@@ -2086,6 +2085,9 @@ define('timing', {
 
     You can quickly view it with this [json](https://npm.im/json) command
     line: \`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g\`.
+
+    Timing information will also be reported in the terminal. To suppress this
+    while still writing the timing file, use \`--silent\`.
   `,
 })
 

lib/utils/display.js

@@ -34,13 +34,20 @@ class Display {
       heading = 'npm',
     } = config
 
-    // XXX: decouple timing from loglevel
-    if (timing && loglevel === 'notice') {
-      log.level = 'timing'
-    } else {
-      log.level = loglevel
-    }
-
+    // npmlog is still going away someday, so this is a hack to dynamically
+    // set the loglevel of timing based on the timing flag, instead of making
+    // a breaking change to npmlog. The result is that timing logs are never
+    // shown except when the --timing flag is set. We also need to change
+    // the index of the silly level since otherwise it is set to -Infinity
+    // and we can't go any lower than that. silent is still set to Infinify
+    // because we DO want silent to hide timing levels. This allows for the
+    // special case of getting timing information while hiding all CLI output
+    // in order to get perf information that might be affected by writing to
+    // a terminal. XXX(npmlog): this will be removed along with npmlog
+    log.levels.silly = -10000
+    log.levels.timing = log.levels[loglevel] + (timing ? 1 : -1)
+
+    log.level = loglevel
     log.heading = heading
 
     if (color) {

tap-snapshots/test/lib/docs.js.test.cjs

@@ -1258,8 +1258,8 @@ Ideal if all users are on npm version 7 and higher.
 #### \`loglevel\`
 
 * Default: "notice"
-* Type: "silent", "error", "warn", "notice", "http", "timing", "info",
-  "verbose", or "silly"
+* Type: "silent", "error", "warn", "notice", "http", "info", "verbose", or
+  "silly"
 
 What level of logs to report. All logs are written to a debug log, with the
 path to that file printed if the execution of a command fails.
@@ -1754,6 +1754,9 @@ cache or \`logs-dir\`. The file name ends with \`-timing.json\`.
 You can quickly view it with this [json](https://npm.im/json) command line:
 \`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g\`.
 
+Timing information will also be reported in the terminal. To suppress this
+while still writing the timing file, use \`--silent\`.
+
 #### \`umask\`
 
 * Default: 0

test/fixtures/mock-logs.js

@@ -2,6 +2,9 @@
 const NPMLOG = require('npmlog')
 const { LEVELS } = require('proc-log')
 
+const npmEmitLog = NPMLOG.emitLog.bind(NPMLOG)
+const npmLog = NPMLOG.log.bind(NPMLOG)
+
 const merge = (...objs) => objs.reduce((acc, obj) => ({ ...acc, ...obj }))
 
 const mockLogs = (otherMocks = {}) => {
@@ -22,6 +25,25 @@ const mockLogs = (otherMocks = {}) => {
     }, {})
   )
 
+  // the above logs array is anything logged and it not filtered by level.
+  // this display array is filtered and will not include items that
+  // would not be shown in the terminal
+  const display = Object.defineProperties(
+    [],
+    ['timing', ...LEVELS].reduce((acc, level) => {
+      acc[level] = {
+        get () {
+          return this
+            .filter(([l]) => level === l)
+            .map(([l, ...args]) => args)
+        },
+      }
+      return acc
+    }, {})
+  )
+
+  const npmLogBuffer = []
+
   // This returns an object with mocked versions of all necessary
   // logging modules. It mocks them with methods that add logs
   // to an array which it also returns. The reason it also returns
@@ -53,15 +75,33 @@ const mockLogs = (otherMocks = {}) => {
     // that reflected in the npmlog singleton.
     // XXX: remove with npmlog
     npmlog: Object.assign(NPMLOG, merge(
-      // no-op all npmlog methods by default so tests
-      // dont output anything to the terminal
-      Object.keys(NPMLOG.levels).reduce((acc, k) => {
-        acc[k] = () => {}
-        return acc
-      }, {}),
-      // except collect timing logs
       {
-        timing: (...args) => logs.push(['timing', ...args]),
+        log: (level, ...args) => {
+          // timing does not exist on proclog, so if it got logged
+          // with npmlog we need to push it to our logs
+          if (level === 'timing') {
+            logs.push([level, ...args])
+          }
+          npmLog(level, ...args)
+        },
+        write: (msg) => {
+          // npmlog.write is what outputs to the terminal.
+          // it writes in chunks so we push each chunk to an
+          // array that we will log and zero out
+          npmLogBuffer.push(msg)
+        },
+        emitLog: (m) => {
+          // this calls the original emitLog method
+          // which will filter based on loglevel
+          npmEmitLog(m)
+          // if anything was logged then we push to our display
+          // array which we can assert against in tests
+          if (npmLogBuffer.length) {
+            // first two parts are 'npm' and a single space
+            display.push(npmLogBuffer.slice(2))
+          }
+          npmLogBuffer.length = 0
+        },
         newItem: () => {
           return {
             info: (...p) => {
@@ -85,7 +125,7 @@ const mockLogs = (otherMocks = {}) => {
     )),
   }
 
-  return { logs, logMocks }
+  return { logs, logMocks, display }
 }
 
 module.exports = mockLogs

test/lib/npm.js

@@ -534,11 +534,26 @@ t.test('timings', async t => {
 
   t.test('does not write timings file with timers:false', async t => {
     const { npm, timingFile } = await loadMockNpm(t, {
-      config: { false: true },
+      config: { timing: false },
     })
     npm.writeTimingFile()
     await t.rejects(() => timingFile())
   })
+
+  const timingDisplay = [
+    [{ loglevel: 'silly' }, true, false],
+    [{ loglevel: 'silly', timing: true }, true, true],
+    [{ loglevel: 'silent', timing: true }, false, false],
+  ]
+
+  for (const [config, expectedDisplay, expectedTiming] of timingDisplay) {
+    const msg = `${JSON.stringify(config)}, display:${expectedDisplay}, timing:${expectedTiming}`
+    await t.test(`timing display: ${msg}`, async t => {
+      const { display } = await loadMockNpm(t, { config })
+      t.equal(!!display.length, expectedDisplay, 'display')
+      t.equal(!!display.timing.length, expectedTiming, 'timing display')
+    })
+  }
 })
 
 t.test('output clears progress and console.logs the message', async t => {

test/lib/utils/display.js

@@ -18,7 +18,7 @@ t.test('setup', async (t) => {
   const { display } = mockDisplay(t)
 
   display.load({ timing: true, loglevel: 'notice' })
-  t.equal(log.level, 'timing')
+  t.equal(log.level, 'notice')
 
   display.load({ timing: false, loglevel: 'notice' })
   t.equal(log.level, 'notice')