Skip to content

Commit

Permalink
feat: timings are now written alongside debug log files
Browse files Browse the repository at this point in the history 
BREAKING CHANGE: `--timing` file changes:
- When run with the `--timing` flag, `npm` now writes timing data to a
file alongside the debug log data, respecting the `logs-dir` option and
falling back to `<CACHE>/_logs/` dir, instead of directly inside the
cache directory.
- The timing file data is no longer newline delimited JSON, and instead
each run will create a uniquely named `<ID>-timing.json` file, with the
`<ID>` portion being the same as the debug log.
- Finally, the data inside the file now has three top level keys,
`metadata`, `timers, and `unfinishedTimers` instead of everything being
a top level key.

Closes npm/statusboard#456
  • Loading branch information
@lukekarrys
lukekarrys committed Sep 27, 2022
1 parent 84598fe commit 3445da0
Show file tree
Hide file tree
Showing 15 changed files with 118 additions and 131 deletions.
7 changes: 3 additions & 4 deletions docs/content/using-npm/config.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1707,12 +1707,11 @@ particular, use care when overriding this setting for public packages.
* Default: false
* Type: Boolean

If true, writes a debug log to `logs-dir` and timing information to
`_timing.json` in the cache, even if the command completes successfully.
`_timing.json` is a newline delimited list of JSON objects.
If true, writes timing information to a process specific json file in the
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:
`npm exec -- json -g < ~/.npm/_timing.json`.
`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g`.

<!-- automatically generated, do not edit manually -->
<!-- see lib/utils/config/definitions.js -->
Expand Down
8 changes: 4 additions & 4 deletions docs/content/using-npm/logging.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,8 +12,7 @@ The `npm` CLI has various mechanisms for showing different levels of information

All logs are written to a debug log, with the path to that file printed if the execution of a command fails.

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.
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.

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.

Expand Down Expand Up @@ -62,9 +61,10 @@ The [`--timing` config](/using-npm/config#timing) can be set which does two
things:

1. Always shows the full path to the debug log regardless of command exit status
1. Write timing information to a timing file in the cache or `logs-dir`
1. Write timing information to a process specific timing file in the cache or `logs-dir`

This file is a newline delimited list of JSON objects that can be inspected to see timing data for each task in a `npm` CLI run.
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.

### Registry Response Headers

Expand Down
16 changes: 5 additions & 11 deletions lib/npm.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,9 +18,11 @@ const replaceInfo = require('./utils/replace-info.js')
const updateNotifier = require('./utils/update-notifier.js')
const pkg = require('../package.json')
const cmdList = require('./utils/cmd-list.js')
const runId = require('./utils/run-id.js')

let warnedNonDashArg = false
const _load = Symbol('_load')
const RUN_ID = runId()

class Npm extends EventEmitter {
static get version () {
Expand All @@ -38,9 +40,10 @@ class Npm extends EventEmitter {
#argvClean = []
#chalk = null

#logFile = new LogFile()
#logFile = new LogFile({ id: RUN_ID })
#display = new Display()
#timers = new Timers({
id: RUN_ID,
start: 'npm',
listener: (name, ms) => {
const args = ['timing', name, `Completed in ${ms}ms`]
Expand Down Expand Up @@ -207,10 +210,6 @@ class Npm extends EventEmitter {
writeTimingFile () {
this.#timers.writeFile({
command: this.#argvClean,
// We used to only ever report a single log file
// so to be backwards compatible report the last logfile
// XXX: remove this in npm 9 or just keep it forever
logfile: this.logFiles[this.logFiles.length - 1],
logfiles: this.logFiles,
version: this.version,
})
Expand Down Expand Up @@ -298,7 +297,7 @@ class Npm extends EventEmitter {

this.time('npm:load:timers', () =>
this.#timers.load({
dir: this.config.get('timing') ? this.timingDir : null,
dir: this.config.get('timing') ? this.logsDir : null,
})
)

Expand Down Expand Up @@ -376,11 +375,6 @@ class Npm extends EventEmitter {
return this.#timers.file
}

get timingDir () {
// XXX(npm9): make this always in logs-dir
return this.config.get('logs-dir') || this.cache
}

get cache () {
return this.config.get('cache')
}
Expand Down
8 changes: 3 additions & 5 deletions lib/utils/config/definitions.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2062,13 +2062,11 @@ define('timing', {
default: false,
type: Boolean,
description: `
If true, writes a debug log to \`logs-dir\` and timing information
to \`_timing.json\` in the cache, even if the command completes
successfully. \`_timing.json\` is a newline delimited list of JSON
objects.
If true, writes timing information to a process specific json file in
the 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: \`npm exec -- json -g < ~/.npm/_timing.json\`.
line: \`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g\`.
`,
})

Expand Down
29 changes: 12 additions & 17 deletions lib/utils/display.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,11 +3,6 @@ const npmlog = require('npmlog')
const log = require('./log-shim.js')
const { explain } = require('./explain-eresolve.js')

const _logHandler = Symbol('logHandler')
const _eresolveWarn = Symbol('eresolveWarn')
const _log = Symbol('log')
const _npmlog = Symbol('npmlog')

class Display {
constructor () {
// pause by default until config is loaded
Expand All @@ -16,11 +11,11 @@ class Display {
}

on () {
process.on('log', this[_logHandler])
process.on('log', this.#logHandler)
}

off () {
process.off('log', this[_logHandler])
process.off('log', this.#logHandler)
// Unbalanced calls to enable/disable progress
// will leave change listeners on the tracker
// This pretty much only happens in tests but
Expand Down Expand Up @@ -72,44 +67,44 @@ class Display {
}

log (...args) {
this[_logHandler](...args)
this.#logHandler(...args)
}

[_logHandler] = (level, ...args) => {
#logHandler = (level, ...args) => {
try {
this[_log](level, ...args)
this.#log(level, ...args)
} catch (ex) {
try {
// if it crashed once, it might again!
this[_npmlog]('verbose', `attempt to log ${inspect(args)} crashed`, ex)
this.#npmlog('verbose', `attempt to log ${inspect(args)} crashed`, ex)
} catch (ex2) {
// eslint-disable-next-line no-console
console.error(`attempt to log ${inspect(args)} crashed`, ex, ex2)
}
}
}

[_log] (...args) {
return this[_eresolveWarn](...args) || this[_npmlog](...args)
#log (...args) {
return this.#eresolveWarn(...args) || this.#npmlog(...args)
}

// Explicitly call these on npmlog and not log shim
// This is the final place we should call npmlog before removing it.
[_npmlog] (level, ...args) {
#npmlog (level, ...args) {
npmlog[level](...args)
}

// Also (and this is a really inexcusable kludge), we patch the
// log.warn() method so that when we see a peerDep override
// explanation from Arborist, we can replace the object with a
// highly abbreviated explanation of what's being overridden.
[_eresolveWarn] (level, heading, message, expl) {
#eresolveWarn (level, heading, message, expl) {
if (level === 'warn' &&
heading === 'ERESOLVE' &&
expl && typeof expl === 'object'
) {
this[_npmlog](level, heading, message)
this[_npmlog](level, '', explain(expl, log.useColor(), 2))
this.#npmlog(level, heading, message)
this.#npmlog(level, '', explain(expl, log.useColor(), 2))
// Return true to short circuit other log in chain
return true
}
Expand Down
54 changes: 22 additions & 32 deletions lib/utils/log-file.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,18 +7,11 @@ const MiniPass = require('minipass')
const fsMiniPass = require('fs-minipass')
const fs = require('@npmcli/fs')
const log = require('./log-shim')
const runId = require('./run-id')

const padZero = (n, length) => n.toString().padStart(length.toString().length, '0')
const globify = pattern => pattern.split('\\').join('/')

const _logHandler = Symbol('logHandler')
const _formatLogItem = Symbol('formatLogItem')
const _getLogFilePath = Symbol('getLogFilePath')
const _openLogFile = Symbol('openLogFile')
const _cleanLogs = Symbol('cleanlogs')
const _endStream = Symbol('endStream')
const _isBuffered = Symbol('isBuffered')

class LogFiles {
// If we write multiple log files we want them all to have the same
// identifier for sorting and matching purposes
Expand Down Expand Up @@ -46,19 +39,16 @@ class LogFiles {
#files = []

constructor ({
id = runId(),
maxLogsPerFile = 50_000,
maxFilesPerProcess = 5,
} = {}) {
this.#logId = LogFiles.logId(new Date())
this.#logId = id
this.#MAX_LOGS_PER_FILE = maxLogsPerFile
this.#MAX_FILES_PER_PROCESS = maxFilesPerProcess
this.on()
}

static logId (d) {
return d.toISOString().replace(/[.:]/g, '_')
}

static format (count, level, title, ...args) {
let prefix = `${count} ${level}`
if (title) {
Expand All @@ -75,12 +65,12 @@ class LogFiles {

on () {
this.#logStream = new MiniPass()
process.on('log', this[_logHandler])
process.on('log', this.#logHandler)
}

off () {
process.off('log', this[_logHandler])
this[_endStream]()
process.off('log', this.#logHandler)
this.#endStream()
}

load ({ dir, logsMax = Infinity } = {}) {
Expand All @@ -100,7 +90,7 @@ class LogFiles {
// set that as the new log logstream for future writes
// if logs max is 0 then the user does not want a log file
if (this.#logsMax > 0) {
const initialFile = this[_openLogFile]()
const initialFile = this.#openLogFile()
if (initialFile) {
this.#logStream = this.#logStream.pipe(initialFile)
}
Expand All @@ -109,29 +99,29 @@ class LogFiles {
// Kickoff cleaning process, even if we aren't writing a logfile.
// This is async but it will always ignore the current logfile
// Return the result so it can be awaited in tests
return this[_cleanLogs]()
return this.#cleanLogs()
}

log (...args) {
this[_logHandler](...args)
this.#logHandler(...args)
}

get files () {
return this.#files
}

get [_isBuffered] () {
get #isBuffered () {
return this.#logStream instanceof MiniPass
}

[_endStream] (output) {
#endStream (output) {
if (this.#logStream) {
this.#logStream.end(output)
this.#logStream = null
}
}

[_logHandler] = (level, ...args) => {
#logHandler = (level, ...args) => {
// Ignore pause and resume events since we
// write everything to the log file
if (level === 'pause' || level === 'resume') {
Expand All @@ -143,9 +133,9 @@ class LogFiles {
return
}

const logOutput = this[_formatLogItem](level, ...args)
const logOutput = this.#formatLogItem(level, ...args)

if (this[_isBuffered]) {
if (this.#isBuffered) {
// Cant do anything but buffer the output if we dont
// have a file stream yet
this.#logStream.write(logOutput)
Expand All @@ -155,29 +145,29 @@ class LogFiles {
// Open a new log file if we've written too many logs to this one
if (this.#fileLogCount >= this.#MAX_LOGS_PER_FILE) {
// Write last chunk to the file and close it
this[_endStream](logOutput)
this.#endStream(logOutput)
if (this.#files.length >= this.#MAX_FILES_PER_PROCESS) {
// but if its way too many then we just stop listening
this.off()
} else {
// otherwise we are ready for a new file for the next event
this.#logStream = this[_openLogFile]()
this.#logStream = this.#openLogFile()
}
} else {
this.#logStream.write(logOutput)
}
}

[_formatLogItem] (...args) {
#formatLogItem (...args) {
this.#fileLogCount += 1
return LogFiles.format(this.#totalLogCount++, ...args)
}

[_getLogFilePath] (count = '') {
#getLogFilePath (count = '') {
return path.resolve(this.#dir, `${this.#logId}-debug-${count}.log`)
}

[_openLogFile] () {
#openLogFile () {
// Count in filename will be 0 indexed
const count = this.#files.length

Expand All @@ -186,7 +176,7 @@ class LogFiles {
// We never want to write files ending in `-9.log` and `-10.log` because
// log file cleaning is done by deleting the oldest so in this example
// `-10.log` would be deleted next
const f = this[_getLogFilePath](padZero(count, this.#MAX_FILES_PER_PROCESS))
const f = this.#getLogFilePath(padZero(count, this.#MAX_FILES_PER_PROCESS))
// Some effort was made to make the async, but we need to write logs
// during process.on('exit') which has to be synchronous. So in order
// to never drop log messages, it is easiest to make it sync all the time
Expand All @@ -210,15 +200,15 @@ class LogFiles {
}
}

async [_cleanLogs] () {
async #cleanLogs () {
// module to clean out the old log files
// this is a best-effort attempt. if a rm fails, we just
// log a message about it and move on. We do return a
// Promise that succeeds when we've tried to delete everything,
// just for the benefit of testing this function properly.

try {
const logPath = this[_getLogFilePath]()
const logPath = this.#getLogFilePath()
const logGlob = path.join(path.dirname(logPath), path.basename(logPath)
// tell glob to only match digits
.replace(/\d/g, '[0123456789]')
Expand Down
3 changes: 3 additions & 0 deletions lib/utils/run-id.js
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
module.exports = (d = new Date()) => {
return d.toISOString().replace(/[.:]/g, '_')
}
Loading

0 comments on commit 3445da0

Please sign in to comment.