npm: Put the npm-debug logs in the cache folder, not cwd.

We also are storing a configurable number of previous log files.

PR-URL: npm/npm#11439
Fixes: npm#5252
Fixes: npm#6350
Fixes: npm#1548
Fixes: npm#7614

Credit: @kenany
Credit: @othiym23
Credit: @isaacs
Credit: @iarna

doc/misc/npm-config.md

@@ -576,6 +576,13 @@ stderr.
 If the `color` config is set to true, then this stream will receive
 colored output if it is a TTY.
 
+### logs-max
+
+* Default: 10
+* Type: Number
+
+The maximum number of log files to store.
+
 ### long
 
 * Default: false

lib/config/defaults.js

@@ -164,6 +164,7 @@ Object.defineProperty(exports, 'defaults', {get: function () {
     'local-address': undefined,
     loglevel: 'warn',
     logstream: process.stderr,
+    'logs-max': 10,
     long: false,
     maxsockets: 50,
     message: '%s',
@@ -278,6 +279,7 @@ exports.types = {
   'local-address': getLocalAddresses(),
   loglevel: ['silent', 'error', 'warn', 'http', 'info', 'verbose', 'silly'],
   logstream: Stream,
+  'logs-max': Number,
   long: Boolean,
   maxsockets: Number,
   message: String,

lib/npm.js

@@ -29,6 +29,8 @@
   var path = require('path')
   var abbrev = require('abbrev')
   var which = require('which')
+  var glob = require('glob')
+  var rimraf = require('rimraf')
   var CachingRegClient = require('./cache/caching-client.js')
   var parseJSON = require('./utils/parse-json.js')
   var aliases = require('./config/cmd-list').aliases
@@ -286,8 +288,21 @@
           log.disableProgress()
         }
 
+        glob(path.resolve(npm.cache, '_logs', '*-debug.log'), function (er, files) {
+          if (er) return cb(er)
+
+          while (files.length >= npm.config.get('logs-max')) {
+            rimraf.sync(files[0])
+            files.splice(0, 1)
+          }
+        })
+
         log.resume()
 
+        // at this point the configs are all set.
+        // go ahead and spin up the registry client.
+        npm.registry = new CachingRegClient(npm.config)
+
         var umask = npm.config.get('umask')
         npm.modes = {
           exec: parseInt('0777', 8) & (~umask),

lib/utils/error-handler.js

@@ -14,6 +14,15 @@ var chain = require('slide').chain
 var writeStreamAtomic = require('fs-write-stream-atomic')
 var errorMessage = require('./error-message.js')
 var stopMetrics = require('./metrics.js').stop
+var mkdir = require('mkdirp')
+
+var logFileName
+function getLogFile () {
+  if (!logFileName) {
+    logFileName = path.resolve(npm.config.get('cache'), '_logs', (new Date()).toISOString().replace(/[.:]/g, '_') + '-debug.log')
+  }
+  return logFileName
+}
 
 process.on('exit', function (code) {
   log.disableProgress()
@@ -37,7 +46,7 @@ process.on('exit', function (code) {
         '',
         [
           'Please include the following file with any support request:',
-          '    ' + path.resolve('npm-debug.log')
+          '    ' + getLogFile()
         ].join('\n')
       )
       wroteLogFile = false
@@ -79,7 +88,7 @@ function exit (code, noLog) {
         else writeLogFile(reallyExit.bind(this, er))
       } else {
         if (!noLog && code) writeLogFile(reallyExit)
-        else rm('npm-debug.log', reallyExit)
+        else rm(getLogFile(), reallyExit)
       }
     })
     rollbacks.length = 0
@@ -191,22 +200,26 @@ function writeLogFile (cb) {
   writingLogFile = true
   wroteLogFile = true
 
-  var fstr = writeStreamAtomic('npm-debug.log')
   var os = require('os')
-  var out = ''
 
-  log.record.forEach(function (m) {
-    var pref = [m.id, m.level]
-    if (m.prefix) pref.push(m.prefix)
-    pref = pref.join(' ')
-
-    m.message.trim().split(/\r?\n/).map(function (line) {
-      return (pref + ' ' + line).trim()
-    }).forEach(function (line) {
-      out += line + os.EOL
+  mkdir(path.resolve(npm.config.get('cache'), '_logs'), function (er) {
+    if (er) {
+      cb(er)
+      return
+    }
+    var fstr = writeStreamAtomic(getLogFile())
+    log.record.forEach(function (m) {
+      var pref = [m.id, m.level]
+      if (m.prefix) pref.push(m.prefix)
+      pref = pref.join(' ')
+
+      m.message.trim().split(/\r?\n/).map(function (line) {
+        return (pref + ' ' + line).trim()
+      }).forEach(function (line) {
+        fstr.write(line + os.EOL)
+      })
     })
+    fstr.end()
+    fstr.on('close', cb)
   })
-
-  fstr.end(out)
-  fstr.on('close', cb)
 }

test/tap/debug-logs.js

@@ -0,0 +1,102 @@
+'use strict'
+var path = require('path')
+var test = require('tap').test
+var Tacks = require('tacks')
+var glob = require('glob')
+var asyncMap = require('slide').asyncMap
+var File = Tacks.File
+var Dir = Tacks.Dir
+var extend = Object.assign || require('util')._extend
+var common = require('../common-tap.js')
+
+var basedir = path.join(__dirname, path.basename(__filename, '.js'))
+var testdir = path.join(basedir, 'testdir')
+var cachedir = path.join(basedir, 'cache')
+var globaldir = path.join(basedir, 'global')
+var tmpdir = path.join(basedir, 'tmp')
+
+var conf = {
+  cwd: testdir,
+  env: extend(extend({}, process.env), {
+    npm_config_cache: cachedir,
+    npm_config_tmp: tmpdir,
+    npm_config_prefix: globaldir,
+    npm_config_registry: common.registry,
+    npm_config_loglevel: 'warn'
+  })
+}
+
+var fixture = new Tacks(Dir({
+  cache: Dir(),
+  global: Dir(),
+  tmp: Dir(),
+  testdir: Dir({
+    'package.json': File({
+      name: 'debug-logs',
+      version: '1.0.0',
+      scripts: {
+        true: 'node -e "process.exit(0)"',
+        false: 'node -e "process.exit(1)"'
+      }
+    })
+  })
+}))
+
+function setup () {
+  cleanup()
+  fixture.create(basedir)
+}
+
+function cleanup () {
+  fixture.remove(basedir)
+}
+
+test('setup', function (t) {
+  setup()
+  t.done()
+})
+
+test('example', function (t) {
+  common.npm(['run', 'false'], conf, function (err, code, stdout, stderr) {
+    if (err) throw err
+    t.is(code, 1, 'command errored')
+    var matches = stderr.match(/Please include the following file with any support request:.*\nnpm ERR! {5,5}(.*)/)
+    t.ok(matches, 'debug log mentioned in error message')
+    if (matches) {
+      var logfile = matches[1]
+      t.matches(path.relative(cachedir, logfile), /^_logs/, 'debug log is inside the cache in _logs')
+    }
+
+    // we run a bunch concurrently, this will actually create > than our limit as the check is done
+    // when the command starts
+    var todo = [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12]
+    asyncMap(todo, function (num, next) {
+      common.npm(['run', '--logs-max=10', 'false'], conf, function (err, code) {
+        if (err) throw err
+        t.is(code, 1, 'run #' + num + ' errored as expected')
+        next()
+      })
+    }, function () {
+      // now we do one more and that should clean up the list
+      common.npm(['run', '--logs-max=10', 'false'], conf, function (err, code) {
+        if (err) throw err
+        t.is(code, 1, 'final run errored as expected')
+        var files = glob.sync(path.join(cachedir, '_logs', '*'))
+        t.is(files.length, 10, 'there should never be more than 10 log files')
+        common.npm(['run', '--logs-max=5', 'true'], conf, function (err, code) {
+          if (err) throw err
+          t.is(code, 0, 'success run is ok')
+          var files = glob.sync(path.join(cachedir, '_logs', '*'))
+          t.is(files.length, 4, 'after success there should be logs-max - 1 log files')
+          t.done()
+        })
+      })
+    })
+  })
+})
+
+test('cleanup', function (t) {
+  cleanup()
+  t.done()
+})
+

test/tap/gently-rm-overeager.js

@@ -1,13 +1,13 @@
-var resolve = require('path').resolve
+var path = require('path')
 var fs = require('graceful-fs')
 var test = require('tap').test
 var mkdirp = require('mkdirp')
 var rimraf = require('rimraf')
 
 var common = require('../common-tap.js')
 
-var pkg = resolve(__dirname, 'gently-rm-overeager')
-var dep = resolve(__dirname, 'test-whoops')
+var pkg = path.join(__dirname, 'gently-rm-overeager')
+var dep = path.join(__dirname, 'test-whoops')
 
 var EXEC_OPTS = { cwd: pkg }
 
@@ -32,8 +32,7 @@ test('cache add', function (t) {
     t.ok(c, 'test-whoops install also failed')
     fs.readdir(pkg, function (er, files) {
       t.ifError(er, 'package directory is still there')
-      t.deepEqual(files, ['npm-debug.log'], 'only debug log remains')
-
+      t.deepEqual(files, [], 'no files remain')
       t.end()
     })
   })
@@ -53,7 +52,7 @@ function cleanup () {
 function setup () {
   mkdirp.sync(pkg)
   // so it doesn't try to install into npm's own node_modules
-  mkdirp.sync(resolve(pkg, 'node_modules'))
+  mkdirp.sync(path.join(pkg, 'node_modules'))
   mkdirp.sync(dep)
-  fs.writeFileSync(resolve(dep, 'package.json'), JSON.stringify(fixture))
+  fs.writeFileSync(path.join(dep, 'package.json'), JSON.stringify(fixture))
 }