feat: add logs-dir config to set custom logging location

This also allows logs-max to be set to 0 to disable log file writing.

Closes #4466
Closes #4206

7 files changed, 180 insertions, 119 deletions

diff --git a/lib/utils/config/definitions.js b/lib/utils/config/definitions.js
index abc989d0e..04da7f607 100644
--- a/lib/utils/config/definitions.js
+++ b/lib/utils/config/definitions.js
@@ -1229,11 +1229,25 @@ define('loglevel', {
   },
 })
 
+define('logs-dir', {
+  default: null,
+  type: [null, path],
+  defaultDescription: `
+    A directory named \`_logs\` inside the cache
+`,
+  description: `
+    The location of npm's log directory.  See [\`npm
+    logging\`](/using-npm/logging) for more information.
+  `,
+})
+
 define('logs-max', {
   default: 10,
   type: Number,
   description: `
     The maximum number of log files to store.
+
+    If set to 0, no log files will be written for the current run.
   `,
 })
 
@@ -2025,8 +2039,8 @@ define('timing', {
   default: false,
   type: Boolean,
   description: `
-    If true, writes an \`npm-debug\` log to \`_logs\` and timing information
-    to \`_timing.json\`, both in your cache, even if the command completes
+    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.
 
diff --git a/lib/utils/exit-handler.js b/lib/utils/exit-handler.js
index 6186ea81d..f96d162ce 100644
--- a/lib/utils/exit-handler.js
+++ b/lib/utils/exit-handler.js
@@ -1,14 +1,15 @@
 const os = require('os')
-const log = require('./log-shim.js')
 
+const log = require('./log-shim.js')
 const errorMessage = require('./error-message.js')
 const replaceInfo = require('./replace-info.js')
 
 const messageText = msg => msg.map(line => line.slice(1).join(' ')).join('\n')
+const indent = (val) => Array.isArray(val) ? val.map(v => indent(v)) : `    ${val}`
 
 let npm = null // set by the cli
 let exitHandlerCalled = false
-let showLogFileMessage = false
+let showLogFileError = false
 
 process.on('exit', code => {
   log.disableProgress()
@@ -36,42 +37,73 @@ process.on('exit', code => {
   if (!exitHandlerCalled) {
     process.exitCode = code || 1
     log.error('', 'Exit handler never called!')
+    // eslint-disable-next-line no-console
     console.error('')
     log.error('', 'This is an error with npm itself. Please report this error at:')
     log.error('', '    <https://github.com/npm/cli/issues>')
-    showLogFileMessage = true
-  }
-
-  // In timing mode we always show the log file message
-  if (hasLoadedNpm && npm.config.get('timing')) {
-    showLogFileMessage = true
+    showLogFileError = true
   }
 
   // npm must be loaded to know where the log file was written
-  if (showLogFileMessage && hasLoadedNpm) {
-    // just a line break if not in silent mode
-    if (!npm.silent) {
-      console.error('')
-    }
+  if (hasLoadedNpm) {
+    // write the timing file now, this might do nothing based on the configs set.
+    // we need to call it here in case it errors so we dont tell the user
+    // about a timing file that doesn't exist
+    npm.writeTimingFile()
 
-    log.error(
-      '',
-      [
-        'A complete log of this run can be found in:',
-        ...npm.logFiles.map(f => '    ' + f),
-      ].join('\n')
-    )
-  }
+    const logsDir = npm.logsDir
+    const logFiles = npm.logFiles
 
-  // This removes any listeners npm setup and writes files if necessary
-  // This is mostly used for tests to avoid max listener warnings
-  if (hasLoadedNpm) {
+    const timingDir = npm.timingDir
+    const timingFile = npm.timingFile
+
+    const timing = npm.config.get('timing')
+    const logsMax = npm.config.get('logs-max')
+
+    // Determine whether to show log file message and why it is
+    // being shown since in timing mode we always show the log file message
+    const logMethod = showLogFileError ? 'error' : timing ? 'info' : null
+
+    if (logMethod) {
+      if (!npm.silent) {
+        // just a line break if not in silent mode
+        // eslint-disable-next-line no-console
+        console.error('')
+      }
+
+      const message = []
+
+      if (timingFile) {
+        message.push('Timing info written to:', indent(timingFile))
+      } else if (timing) {
+        message.push(
+          `The timing file was not written due to an error writing to the directory: ${timingDir}`
+        )
+      }
+
+      if (logFiles.length) {
+        message.push('A complete log of this run can be found in:', ...indent(logFiles))
+      } else if (logsMax <= 0) {
+        // user specified no log file
+        message.push(`Log files were not written due to the config logs-max=${logsMax}`)
+      } else {
+        // could be an error writing to the directory
+        message.push(
+          `Log files were not written due to an error writing to the directory: ${logsDir}`,
+          'You can rerun the command with `--loglevel=verbose` to see the logs in your terminal'
+        )
+      }
+
+      log[logMethod]('', message.join('\n'))
+    }
+
+    // This removes any listeners npm setup, mostly for tests to avoid max listener warnings
     npm.unload()
   }
 
   // these are needed for the tests to have a clean slate in each test case
   exitHandlerCalled = false
-  showLogFileMessage = false
+  showLogFileError = false
 })
 
 const exitHandler = err => {
@@ -84,12 +116,14 @@ const exitHandler = err => {
 
   if (!hasNpm) {
     err = err || new Error('Exit prior to setting npm in exit handler')
+    // eslint-disable-next-line no-console
     console.error(err.stack || err.message)
     return process.exit(1)
   }
 
   if (!hasLoadedNpm) {
     err = err || new Error('Exit prior to config file resolving.')
+    // eslint-disable-next-line no-console
     console.error(err.stack || err.message)
   }
 
@@ -135,10 +169,8 @@ const exitHandler = err => {
         }
       }
 
-      const args = replaceInfo(process.argv)
       log.verbose('cwd', process.cwd())
       log.verbose('', os.type() + ' ' + os.release())
-      log.verbose('argv', args.map(JSON.stringify).join(' '))
       log.verbose('node', process.version)
       log.verbose('npm ', 'v' + npm.version)
 
@@ -162,7 +194,7 @@ const exitHandler = err => {
             detail: messageText(msg.detail),
           },
         }
-        console.error(JSON.stringify(error, null, 2))
+        npm.outputError(JSON.stringify(error, null, 2))
       }
 
       if (typeof err.errno === 'number') {
@@ -175,17 +207,18 @@ const exitHandler = err => {
 
   log.verbose('exit', exitCode || 0)
 
-  showLogFileMessage = (hasLoadedNpm && npm.silent) || noLogMessage
+  showLogFileError = (hasLoadedNpm && npm.silent) || noLogMessage
     ? false
     : !!exitCode
 
   // explicitly call process.exit now so we don't hang on things like the
-  // update notifier, also flush stdout beforehand because process.exit doesn't
+  // update notifier, also flush stdout/err beforehand because process.exit doesn't
   // wait for that to happen.
-  process.stdout.write('', () => process.exit(exitCode))
+  let flushed = 0
+  const flush = [process.stderr, process.stdout]
+  const exit = () => ++flushed === flush.length && process.exit(exitCode)
+  flush.forEach((f) => f.write('', exit))
 }
 
 module.exports = exitHandler
-module.exports.setNpm = n => {
-  npm = n
-}
+module.exports.setNpm = n => (npm = n)
diff --git a/lib/utils/log-file.js b/lib/utils/log-file.js
index 0bf1e0054..282c72700 100644
--- a/lib/utils/log-file.js
+++ b/lib/utils/log-file.js
@@ -5,8 +5,8 @@ const rimraf = promisify(require('rimraf'))
 const glob = promisify(require('glob'))
 const MiniPass = require('minipass')
 const fsMiniPass = require('fs-minipass')
+const fs = require('@npmcli/fs')
 const log = require('./log-shim')
-const withChownSync = require('./with-chown-sync')
 
 const padZero = (n, length) => n.toString().padStart(length.toString().length, '0')
 
@@ -82,7 +82,9 @@ class LogFiles {
     this[_endStream]()
   }
 
-  load ({ dir, logsMax } = {}) {
+  load ({ dir, logsMax = Infinity } = {}) {
+    // dir is user configurable and is required to exist so
+    // this can error if the dir is missing or not configured correctly
     this.#dir = dir
     this.#logsMax = logsMax
 
@@ -90,16 +92,22 @@ class LogFiles {
     if (!this.#logStream) {
       return
     }
+
+    log.verbose('logfile', `logs-max:${logsMax} dir:${dir}`)
+
     // Pipe our initial stream to our new file stream and
     // set that as the new log logstream for future writes
-    const initialFile = this[_openLogFile]()
-    if (initialFile) {
-      this.#logStream = this.#logStream.pipe(initialFile)
+    // if logs max is 0 then the user does not want a log file
+    if (this.#logsMax > 0) {
+      const initialFile = this[_openLogFile]()
+      if (initialFile) {
+        this.#logStream = this.#logStream.pipe(initialFile)
+      }
     }
 
-    // Kickoff cleaning process. This is async but it wont delete
-    // our next log file since it deletes oldest first. Return the
-    // result so it can be awaited in tests
+    // 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]()
   }
 
@@ -164,8 +172,8 @@ class LogFiles {
     return LogFiles.format(this.#totalLogCount++, ...args)
   }
 
-  [_getLogFilePath] (prefix, suffix, sep = '-') {
-    return path.resolve(this.#dir, prefix + sep + 'debug' + sep + suffix + '.log')
+  [_getLogFilePath] (count = '') {
+    return path.resolve(this.#dir, `${this.#logId}-debug-${count}.log`)
   }
 
   [_openLogFile] () {
@@ -173,17 +181,19 @@ class LogFiles {
     const count = this.#files.length
 
     try {
-      const logStream = withChownSync(
-        // Pad with zeros so that our log files are always sorted properly
-        // 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
-        this[_getLogFilePath](this.#logId, 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
-        // and this was measured to be about 1.5% slower for 40k lines of output
-        (f) => new fsMiniPass.WriteStreamSync(f, { flags: 'a' })
+      // Pad with zeros so that our log files are always sorted properly
+      // 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))
+      // 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
+      // and this was measured to be about 1.5% slower for 40k lines of output
+      const logStream = fs.withOwnerSync(
+        f,
+        () => new fsMiniPass.WriteStreamSync(f, { flags: 'a' }),
+        { owner: 'inherit' }
       )
       if (count > 0) {
         // Reset file log count if we are opening
@@ -193,9 +203,7 @@ class LogFiles {
       this.#files.push(logStream.path)
       return logStream
     } catch (e) {
-      // XXX: do something here for errors?
-      // log to display only?
-      return null
+      log.warn('logfile', `could not be created: ${e}`)
     }
   }
 
@@ -206,14 +214,16 @@ class LogFiles {
     // Promise that succeeds when we've tried to delete everything,
     // just for the benefit of testing this function properly.
 
-    if (typeof this.#logsMax !== 'number') {
-      return
-    }
-
     try {
-      // Handle the old (prior to 8.2.0) log file names which did not have an counter suffix
-      // so match by anything after `-debug` and before `.log` (including nothing)
-      const logGlob = 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]')
+        // Handle the old (prior to 8.2.0) log file names which did not have a
+        // counter suffix
+        .replace(/-\.log$/, '*.log')
+      )
+
       // Always ignore the currently written files
       const files = await glob(logGlob, { ignore: this.#files })
       const toDelete = files.length - this.#logsMax
@@ -233,6 +243,8 @@ class LogFiles {
       }
     } catch (e) {
       log.warn('logfile', 'error cleaning log files', e)
+    } finally {
+      log.silly('logfile', 'done cleaning log files')
     }
   }
 }
diff --git a/lib/utils/replace-info.js b/lib/utils/replace-info.js
index e9d19ef5f..b9ce61935 100644
--- a/lib/utils/replace-info.js
+++ b/lib/utils/replace-info.js
@@ -1,33 +1,31 @@
-const URL = require('url').URL
+const { cleanUrl } = require('npm-registry-fetch')
+const isString = (v) => typeof v === 'string'
 
-// replaces auth info in an array of arguments or in a strings
-function replaceInfo (arg) {
-  const isArray = Array.isArray(arg)
-  const isString = str => typeof str === 'string'
-
-  if (!isArray && !isString(arg)) {
-    return arg
-  }
+// split on \s|= similar to how nopt parses options
+const splitAndReplace = (str) => {
+  // stateful regex, don't move out of this scope
+  const splitChars = /[\s=]/g
 
-  const testUrlAndReplace = str => {
-    try {
-      const url = new URL(str)
-      return url.password === '' ? str : str.replace(url.password, '***')
-    } catch (e) {
-      return str
-    }
+  let match = null
+  let result = ''
+  let index = 0
+  while (match = splitChars.exec(str)) {
+    result += cleanUrl(str.slice(index, match.index)) + match[0]
+    index = splitChars.lastIndex
   }
 
-  const args = isString(arg) ? arg.split(' ') : arg
-  const info = args.map(a => {
-    if (isString(a) && a.indexOf(' ') > -1) {
-      return a.split(' ').map(testUrlAndReplace).join(' ')
-    }
+  return result + cleanUrl(str.slice(index))
+}
 
-    return testUrlAndReplace(a)
-  })
+// replaces auth info in an array of arguments or in a strings
+function replaceInfo (arg) {
+  if (isString(arg)) {
+    return splitAndReplace(arg)
+  } else if (Array.isArray(arg)) {
+    return arg.map((a) => isString(a) ? splitAndReplace(a) : a)
+  }
 
-  return isString(arg) ? info.join(' ') : info
+  return arg
 }
 
 module.exports = replaceInfo
diff --git a/lib/utils/timers.js b/lib/utils/timers.js
index acff29eb0..3336c3b51 100644
--- a/lib/utils/timers.js
+++ b/lib/utils/timers.js
@@ -1,8 +1,7 @@
 const EE = require('events')
-const path = require('path')
-const fs = require('graceful-fs')
+const { resolve } = require('path')
+const fs = require('@npmcli/fs')
 const log = require('./log-shim')
-const withChownSync = require('./with-chown-sync.js')
 
 const _timeListener = Symbol('timeListener')
 const _timeEndListener = Symbol('timeEndListener')
@@ -12,10 +11,11 @@ const _init = Symbol('init')
 // only listen on a single internal event that gets
 // emitted whenever a timer ends
 class Timers extends EE {
+  file = null
+
   #unfinished = new Map()
   #finished = {}
   #onTimeEnd = Symbol('onTimeEnd')
-  #dir = null
   #initialListener = null
   #initialTimer = null
 
@@ -62,11 +62,27 @@ class Timers extends EE {
     }
   }
 
-  load ({ dir }) {
-    this.#dir = dir
+  time (name, fn) {
+    process.emit('time', name)
+    const end = () => process.emit('timeEnd', name)
+    if (typeof fn === 'function') {
+      const res = fn()
+      return res && res.finally ? res.finally(end) : (end(), res)
+    }
+    return end
+  }
+
+  load ({ dir } = {}) {
+    if (dir) {
+      this.file = resolve(dir, '_timing.json')
+    }
   }
 
   writeFile (fileData) {
+    if (!this.file) {
+      return
+    }
+
     try {
       const globalStart = this.started
       const globalEnd = this.#finished.npm || Date.now()
@@ -79,16 +95,17 @@ class Timers extends EE {
           return acc
         }, {}),
       }
-      withChownSync(
-        path.resolve(this.#dir, '_timing.json'),
-        (f) =>
-          // we append line delimited json to this file...forever
-          // XXX: should we also write a process specific timing file?
-          // with similar rules to the debug log (max files, etc)
-          fs.appendFileSync(f, JSON.stringify(content) + '\n')
+      // we append line delimited json to this file...forever
+      // XXX: should we also write a process specific timing file?
+      // with similar rules to the debug log (max files, etc)
+      fs.withOwnerSync(
+        this.file,
+        () => fs.appendFileSync(this.file, JSON.stringify(content) + '\n'),
+        { owner: 'inherit' }
       )
     } catch (e) {
-      log.warn('timing', 'could not write timing file', e)
+      this.file = null
+      log.warn('timing', `could not write timing file: ${e}`)
     }
   }
 
diff --git a/lib/utils/update-notifier.js b/lib/utils/update-notifier.js
index 875c3a99a..dde0202b7 100644
--- a/lib/utils/update-notifier.js
+++ b/lib/utils/update-notifier.js
@@ -122,5 +122,5 @@ module.exports = async npm => {
   // fails, it's ok.  might be using /dev/null as the cache or something weird
   // like that.
   writeFile(lastCheckedFile(npm), '').catch(() => {})
-  npm.updateNotification = notification
+  return notification
 }
diff --git a/lib/utils/with-chown-sync.js b/lib/utils/with-chown-sync.js
deleted file mode 100644
index 481b5696d..000000000
--- a/lib/utils/with-chown-sync.js
+++ /dev/null
@@ -1,13 +0,0 @@
-const mkdirp = require('mkdirp-infer-owner')
-const fs = require('graceful-fs')
-const path = require('path')
-
-module.exports = (file, method) => {
-  const dir = path.dirname(file)
-  mkdirp.sync(dir)
-  const result = method(file)
-  const st = fs.lstatSync(dir)
-  fs.chownSync(dir, st.uid, st.gid)
-  fs.chownSync(file, st.uid, st.gid)
-  return result
-}