From 6e4961f914f77c4004c68dc87c6f8d7c703ecbdf Mon Sep 17 00:00:00 2001 From: Luke Karrys Date: Tue, 18 Oct 2022 18:08:52 -0700 Subject: [PATCH] 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 https://github.com/npm/statusboard/issues/455 Closes https://github.com/npm/statusboard/issues/454 --- docs/lib/content/using-npm/logging.md | 12 ++++- lib/utils/config/definitions.js | 4 +- lib/utils/display.js | 21 ++++++--- tap-snapshots/test/lib/docs.js.test.cjs | 7 ++- test/fixtures/mock-logs.js | 58 +++++++++++++++++++++---- test/lib/npm.js | 17 +++++++- test/lib/utils/display.js | 2 +- 7 files changed, 98 insertions(+), 23 deletions(-) diff --git a/docs/lib/content/using-npm/logging.md b/docs/lib/content/using-npm/logging.md index e52c19004d542..4470d5d155acd 100644 --- a/docs/lib/content/using-npm/logging.md +++ b/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` diff --git a/lib/utils/config/definitions.js b/lib/utils/config/definitions.js index 86ab9ed74d2ed..85d13762eef67 100644 --- a/lib/utils/config/definitions.js +++ b/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\`. `, }) diff --git a/lib/utils/display.js b/lib/utils/display.js index b23b2467ff4e6..35d221c09cae8 100644 --- a/lib/utils/display.js +++ b/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) { diff --git a/tap-snapshots/test/lib/docs.js.test.cjs b/tap-snapshots/test/lib/docs.js.test.cjs index a0651e34ec4e8..b1b7d5b6b493e 100644 --- a/tap-snapshots/test/lib/docs.js.test.cjs +++ b/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 diff --git a/test/fixtures/mock-logs.js b/test/fixtures/mock-logs.js index 706c9a3050ac4..c75de5e509463 100644 --- a/test/fixtures/mock-logs.js +++ b/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 diff --git a/test/lib/npm.js b/test/lib/npm.js index 9e0ff67bc52b8..f850ff6aff8a4 100644 --- a/test/lib/npm.js +++ b/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 => { diff --git a/test/lib/utils/display.js b/test/lib/utils/display.js index 30cd2cc270dc5..c7332bce8e249 100644 --- a/test/lib/utils/display.js +++ b/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')