lifecycle: Add additional logging

To make debugging of lifecycle scripts easier

PR-URL: https://github.com/npm/npm/pull/9227

1 files changed, 19 insertions, 9 deletions

diff --git a/lib/utils/lifecycle.js b/lib/utils/lifecycle.js
index d4c5e062f..1c0d437a9 100644
--- a/lib/utils/lifecycle.js
+++ b/lib/utils/lifecycle.js
@@ -23,6 +23,10 @@ if (process.platform === 'win32') {
   })
 }
 
+function logid (pkg, stage) {
+  return pkg._id + '~' + stage + ':'
+}
+
 function lifecycle (pkg, stage, wd, unsafe, failOk, cb) {
   if (typeof cb !== 'function') {
     cb = failOk
@@ -40,7 +44,7 @@ function lifecycle (pkg, stage, wd, unsafe, failOk, cb) {
   while (pkg && pkg._data) pkg = pkg._data
   if (!pkg) return cb(new Error('Invalid package data'))
 
-  log.info(stage, pkg._id)
+  log.info('lifecycle', logid(pkg, stage), pkg._id)
   if (!pkg.scripts || npm.config.get('ignore-scripts')) pkg.scripts = {}
 
   validWd(wd || path.resolve(npm.dir, pkg.name), function (er, wd) {
@@ -51,8 +55,7 @@ function lifecycle (pkg, stage, wd, unsafe, failOk, cb) {
     if ((wd.indexOf(npm.dir) !== 0 ||
           wd.indexOf(pkg.name) !== wd.length - pkg.name.length) &&
         !unsafe && pkg.scripts[stage]) {
-      log.warn(
-        'cannot run in wd',
+      log.warn('lifecycle', logid(pkg, stage), 'cannot run in wd',
         '%s %s (wd=%s)', pkg._id, pkg.scripts[stage], wd
       )
       return cb()
@@ -95,15 +98,17 @@ function lifecycle_ (pkg, stage, wd, env, unsafe, failOk, cb) {
   if (packageLifecycle) {
     // define this here so it's available to all scripts.
     env.npm_lifecycle_script = pkg.scripts[stage]
+  } else {
+    log.silly('lifecycle', logid(pkg, stage), 'no script for ' + stage + ', continuing')
   }
 
   function done (er) {
     if (er) {
       if (npm.config.get('force')) {
-        log.info('forced, continuing', er)
+        log.info('lifecycle', logid(pkg, stage), 'forced, continuing', er)
         er = null
       } else if (failOk) {
-        log.warn('continuing anyway', er.message)
+        log.warn('lifecycle', logid(pkg, stage), 'continuing anyway', er.message)
         er = null
       }
     }
@@ -168,7 +173,7 @@ function runCmd (note, cmd, pkg, env, stage, wd, unsafe, cb) {
     console.log(note)
     log.showProgress()
   }
-  log.verbose('unsafe-perm in lifecycle', unsafe)
+  log.verbose('lifecycle', logid(pkg, stage), 'unsafe-perm in lifecycle', unsafe)
 
   if (process.platform === 'win32') {
     unsafe = true
@@ -211,12 +216,17 @@ function runCmd_ (cmd, pkg, env, wd, stage, unsafe, uid, gid, cb_) {
     conf.windowsVerbatimArguments = true
   }
 
+  log.verbose('lifecycle', logid(pkg, stage), 'PATH:', env[PATH])
+  log.verbose('lifecycle', logid(pkg, stage), 'CWD:', wd)
+  log.silly('lifecycle', logid(pkg, stage), 'Args:', [shFlag, cmd])
+
   var progressEnabled = log.progressEnabled
   if (progressEnabled) log.disableProgress()
   var proc = spawn(sh, [shFlag, cmd], conf)
 
   proc.on('error', procError)
   proc.on('close', function (code, signal) {
+    log.silly('lifecycle', logid(pkg, stage), 'Returned: code:', code, ' signal:', signal)
     if (signal) {
       process.kill(process.pid, signal)
     } else if (code) {
@@ -228,7 +238,7 @@ function runCmd_ (cmd, pkg, env, wd, stage, unsafe, uid, gid, cb_) {
   function procError (er) {
     if (progressEnabled) log.enableProgress()
     if (er && !npm.ROLLBACK) {
-      log.info(pkg._id, 'Failed to exec ' + stage + ' script')
+      log.info('lifecycle', logid(pkg, stage), 'Failed to exec ' + stage + ' script')
       er.message = pkg._id + ' ' + stage + ': `' + cmd + '`\n' +
                    er.message
       if (er.code !== 'EPERM') {
@@ -240,8 +250,8 @@ function runCmd_ (cmd, pkg, env, wd, stage, unsafe, uid, gid, cb_) {
       er.pkgname = pkg.name
       return cb(er)
     } else if (er) {
-      log.error(pkg._id + '.' + stage, er)
-      log.error(pkg._id + '.' + stage, 'continuing anyway')
+      log.error('lifecycle', logid(pkg, stage), er)
+      log.error('lifecycle', logid(pkg, stage), 'continuing anyway')
       return cb()
     }
     cb(er)