feat: timings are now written alongside debug log files

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

Author: lukekarrys

docs/content/using-npm/config.md

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

docs/content/using-npm/logging.md

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

lib/npm.js

@@ -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 () {
@@ -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`]
@@ -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,
     })
@@ -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,
       })
     )
 
@@ -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')
   }

lib/utils/config/definitions.js

@@ -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\`.
   `,
 })
 

lib/utils/display.js

@@ -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
@@ -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
@@ -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
     }

lib/utils/log-file.js

@@ -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
@@ -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) {
@@ -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 } = {}) {
@@ -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)
       }
@@ -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') {
@@ -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)
@@ -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
 
@@ -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
@@ -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]')

lib/utils/run-id.js

@@ -0,0 +1,3 @@
+module.exports = (d = new Date()) => {
+  return d.toISOString().replace(/[.:]/g, '_')
+}