[RRFC] Print npm version for each command

[styfle]

Motivation ("The Why")

When comparing CI logs, it would be very helpful to see the npm version that was used with npm install, npm run build, or really any npm command.

Example

This came up recently when npm changed the behavior of peer dependencies in npm@8.6.0 so that npm install suddenly started failing with npm ERR! Fix the upstream dependency conflict. If the version was printed, a simple diff of the npm install logs before and after would have made it clear that the npm version changed and that it wasn't a change to the package-lock.json that caused the error.

How

Current Behaviour

$ npm install

up to date, audited 228 packages in 577ms

78 packages are looking for funding
  run `npm fund` for details

found 0 vulnerabilities

Desired Behaviour

Something like yarn where it prints the version on the first line

$ yarn install

yarn install v1.22.17
[1/4] 🔍  Resolving packages...
success Already up-to-date.
✨  Done in 0.10s.

References

• n/a

[darcyclarke]

If you change the loglevel to pretty much anything but "notice" (which is the default) then the path, node version & npm version will display on each command run (ex. npm install --loglevel=info or you can set it in a .npmrc file - ref. https://docs.npmjs.org/cli/v8/using-npm/config#loglevel & https://docs.npmjs.org/cli/v8/using-npm/config#shorthands-and-other-cli-niceties).

I'm a bit concerned that providing this information by default on each run might be considered noisy for some folks but I'm open to it.

[ljharb]

It would definitely be noisy by default, even only in CI, but it seems pretty trivial to set the env var NPM_CONFIG_LOGLEVEL=info in one's CI config?

[styfle]

That --loglevel=info is way too verbose.

I only want to print the version of npm.

And it should be the default behavior, not hidden behind a flag, so it can benefit everyone before they run into a problem and its too late to retroactively update logs.

might be considered noisy for some folks but I'm open to it.

I would argue that info is too noisy and very few users will want to use it as is:

$ npm install --loglevel=info

npm info using npm@8.16.0
npm info using node@v16.17.1
npm timing npm:load:whichnode Completed in 0ms
npm timing config:load:defaults Completed in 0ms
npm timing config:load:file:/Users/styfle/.node/corepack/npm/8.16.0/npmrc Completed in 0ms
npm timing config:load:builtin Completed in 1ms
npm timing config:load:cli Completed in 1ms
npm timing config:load:env Completed in 0ms
npm timing config:load:file:/Users/styfle/Code/myproject/.npmrc Completed in 0ms
npm timing config:load:project Completed in 1ms
npm timing config:load:file:/Users/styfle/.npmrc Completed in 1ms
npm timing config:load:user Completed in 1ms
npm timing config:load:file:/usr/local/etc/npmrc Completed in 0ms
npm timing config:load:global Completed in 0ms
npm timing config:load:validate Completed in 0ms
npm timing config:load:credentials Completed in 1ms
npm timing config:load:setEnvs Completed in 0ms
npm timing config:load Completed in 5ms
npm timing npm:load:configload Completed in 5ms
npm timing npm:load:mkdirpcache Completed in 1ms
npm timing npm:load:mkdirplogs Completed in 0ms
npm timing npm:load:setTitle Completed in 6ms
npm timing config:load:flatten Completed in 1ms
npm timing npm:load:display Completed in 3ms
npm timing npm:load:logFile Completed in 3ms
npm timing npm:load:timers Completed in 0ms
npm timing npm:load:configScope Completed in 0ms
npm timing npm:load Completed in 19ms
npm timing arborist:ctor Completed in 1ms
npm timing idealTree:init Completed in 45ms
npm timing idealTree:userRequests Completed in 0ms
npm timing idealTree:#root Completed in 0ms
npm timing idealTree:buildDeps Completed in 0ms
npm timing idealTree:fixDepFlags Completed in 0ms
npm timing idealTree Completed in 48ms
npm timing arborist:ctor Completed in 0ms
npm timing reify:loadTrees Completed in 75ms
npm timing reify:diffTrees Completed in 6ms
npm timing reify:retireShallow Completed in 0ms
npm timing reify:createSparse Completed in 0ms
npm timing reify:loadBundles Completed in 0ms
npm timing reify:unpack Completed in 1ms
npm timing reify:unretire Completed in 0ms
npm timing build:queue Completed in 0ms
npm timing build:deps Completed in 1ms
npm timing build Completed in 1ms
npm timing reify:build Completed in 1ms
npm timing reify:trash Completed in 0ms
npm timing reify:save Completed in 14ms
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 368ms
npm timing auditReport:getReport Completed in 370ms
npm timing auditReport:init Completed in 0ms
npm timing reify:audit Completed in 371ms
npm timing reify Completed in 457ms

up to date, audited 228 packages in 534ms

78 packages are looking for funding
  run `npm fund` for details

found 0 vulnerabilities
npm timing command:install Completed in 466ms
npm timing npm Completed in 537ms
npm info ok

[ljharb]

Maybe a reasonable approach is to first create a new loglevel that only outputs node/npm versions? That way it could be experimented with via env var/npmrc before considering changing the default.

[styfle]

That sounds like a good first step 👍

[ljharb]

I've just had a situation where printing the location of the node binary would have helped me avoid hours of debugging - so i'd love to see this new loglevel include the which info.

[wraithgar]

Since npm already detects CI would it be a good idea to enable this loglevel in CI automatically?

[wraithgar]

An alternative suggestion is to only do this in CI

$ git diff
diff --git a/lib/npm.js b/lib/npm.js
index 0bdbcdb9e..f84aa04a9 100644
--- a/lib/npm.js
+++ b/lib/npm.js
@@ -5,6 +5,7 @@ const Config = require('@npmcli/config')
 const chalk = require('chalk')
 const which = require('which')
 const fs = require('fs/promises')
+const { isCI } = require('ci-info')

 // Patch the global fs module here at the app level
 require('graceful-fs').gracefulify(require('fs'))
@@ -122,6 +123,9 @@ class Npm extends EventEmitter {
     // since 'test', 'start', 'stop', etc. commands re-enter this function
     // to call the run-script command, we need to only set it one time.
     if (!this.command) {
+      if (isCI) {
+        this.output(`npm@${this.version} ${cmd}`)
+      }
       process.env.npm_command = command.name
       this.command = command.name
       this.commandInstance = command

$ node . whoami
gar

vs

$ node . whoami
npm@9.1.2 whoami
gar

[wraithgar]

The very first three things npm logs, fwiw

$ head ~/.npm/_logs/2022-11-21T21_40_51_609Z-debug-0.log
0 verbose cli /Users/wraithgar/.nvm/versions/node/v18.12.0/bin/node /Users/wraithgar/.nvm/versions/node/v18.12.0/bin/npm
1 info using npm@9.1.2
2 info using node@v18.12.0

[styfle]

I would be fine if the version was only printed in CI.

Especially if that helps avoid the need of a new log level (because no one will remember to set the loglevel).

It solves the original use case, especially if you don't have direct access to download the debug log file.

[wraithgar]

Does this need to be for every command? It can easily be added to anything that installs packages w/o a flag and not be too intrusive imho

$ git diff
diff --git a/lib/utils/reify-output.js b/lib/utils/reify-output.js
index b5c3a593b..c0c5dacc6 100644
--- a/lib/utils/reify-output.js
+++ b/lib/utils/reify-output.js
@@ -125,6 +125,7 @@ const getAuditReport = (npm, report) => {

 const packagesChangedMessage = (npm, { added, removed, changed, audited }) => {
   const msg = ['\n']
+  msg.push(`npm@${npm.version} `)
   if (added === 0 && removed === 0 && changed === 0) {
     msg.push('up to date')
     if (audited) {

$ node . i

npm@9.1.2 up to date, audited 1256 packages in 2s

found 0 vulnerabilities

[styfle]

I would prefer it print the version for every command because the flags can change between npm versions (for example, npm exec changed). And we don't know what the future holds for new version of npm so best to be safe and always print the version. Our future selves will thank us.