Skip to content

Commit

Permalink
feat: separate configs for --timing and --loglevel
Browse files Browse the repository at this point in the history
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
  • Loading branch information
lukekarrys committed Oct 19, 2022
1 parent 7563a94 commit 6e4961f
Show file tree
Hide file tree
Showing 7 changed files with 98 additions and 23 deletions.
12 changes: 10 additions & 2 deletions docs/lib/content/using-npm/logging.md
Original file line number Diff line number Diff line change
Expand Up @@ -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`.
Expand All @@ -31,7 +34,6 @@ The default value of `loglevel` is `"notice"` but there are several levels/types
- `"warn"`
- `"notice"`
- `"http"`
- `"timing"`
- `"info"`
- `"verbose"`
- `"silly"`
Expand All @@ -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`
Expand Down
4 changes: 3 additions & 1 deletion lib/utils/config/definitions.js
Original file line number Diff line number Diff line change
Expand Up @@ -1273,7 +1273,6 @@ define('loglevel', {
'warn',
'notice',
'http',
'timing',
'info',
'verbose',
'silly',
Expand Down Expand Up @@ -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\`.
`,
})

Expand Down
21 changes: 14 additions & 7 deletions lib/utils/display.js
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
7 changes: 5 additions & 2 deletions tap-snapshots/test/lib/docs.js.test.cjs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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
Expand Down
58 changes: 49 additions & 9 deletions test/fixtures/mock-logs.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 = {}) => {
Expand All @@ -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
Expand Down Expand Up @@ -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) => {
Expand All @@ -85,7 +125,7 @@ const mockLogs = (otherMocks = {}) => {
)),
}

return { logs, logMocks }
return { logs, logMocks, display }
}

module.exports = mockLogs
17 changes: 16 additions & 1 deletion test/lib/npm.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 => {
Expand Down
2 changes: 1 addition & 1 deletion test/lib/utils/display.js
Original file line number Diff line number Diff line change
Expand Up @@ -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')
Expand Down

0 comments on commit 6e4961f

Please sign in to comment.