[BUG] Postinstall does not output anything from script (even with loglevel=silly)

[hasezoey]

Is there an existing issue for this?

• I have searched the existing issues

Current Behavior

When installing a package with a postinstall script to output to console if the script logs something (thanks to other issues i already know that it was intentional to make it "quieter", but even with --loglevel silly it did not output anything)

PS: when the script errors, the output is logged, but if it does not error out it is not logged (with loglevel silly)

NPM Output

$ npm i --loglevel silly
npm verb cli [
npm verb cli   '/usr/bin/node',
npm verb cli   '/home/hasezoey/.npm-packages/bin/npm',
npm verb cli   'i',
npm verb cli   '--loglevel',
npm verb cli   'silly'
npm verb cli ]
npm info using npm@7.15.1
npm info using node@v16.2.0
npm timing npm:load:whichnode Completed in 1ms
npm timing config:load:defaults Completed in 1ms
npm timing config:load:file:/home/hasezoey/.npm-packages/lib/node_modules/npm/npmrc Completed in 1ms
npm timing config:load:builtin Completed in 1ms
npm timing config:load:cli Completed in 2ms
npm timing config:load:env Completed in 0ms
npm timing config:load:file:/home/hasezoey/Downloads/npm-postinstall/root-package/.npmrc Completed in 1ms
npm timing config:load:project Completed in 1ms
npm timing config:load:file:/home/hasezoey/.npmrc Completed in 0ms
npm timing config:load:user Completed in 0ms
npm timing config:load:file:/home/hasezoey/.npm-packages/etc/npmrc Completed in 0ms
npm timing config:load:global Completed in 0ms
npm timing config:load:validate Completed in 1ms
npm timing config:load:credentials Completed in 0ms
npm timing config:load:setEnvs Completed in 1ms
npm timing config:load Completed in 7ms
npm timing npm:load:configload Completed in 7ms
npm timing npm:load:setTitle Completed in 0ms
npm timing npm:load:setupLog Completed in 1ms
npm timing npm:load:cleanupLog Completed in 1ms
npm timing npm:load:configScope Completed in 0ms
npm timing npm:load:projectScope Completed in 0ms
npm timing npm:load Completed in 12ms
npm timing config:load:flatten Completed in 1ms
npm timing arborist:ctor Completed in 1ms
npm timing idealTree:init Completed in 7ms
npm timing idealTree:userRequests Completed in 0ms
npm sill idealTree buildDeps
npm timing idealTree:#root Completed in 1ms
npm timing idealTree:buildDeps Completed in 1ms
npm timing idealTree:fixDepFlags Completed in 0ms
npm timing idealTree Completed in 8ms
npm timing reify:loadTrees Completed in 8ms
npm timing reify:diffTrees Completed in 0ms
npm sill reify moves {}
npm timing reify:retireShallow Completed in 1ms
npm timing reify:createSparse Completed in 0ms
npm timing reify:loadBundles Completed in 0ms
npm sill audit bulk request { postinstall_package: [ '1.0.0' ] }
npm timing reifyNode:node_modules/postinstall-package Completed in 18ms
npm timing reify:unpack Completed in 18ms
npm timing reify:unretire Completed in 0ms
npm timing build:queue Completed in 0ms
npm timing build:deps Completed in 1ms
npm timing build:queue Completed in 0ms
npm info run postinstall_package@1.0.0 postinstall ../postinstall-package node ./postinstall.js
npm info run postinstall_package@1.0.0 postinstall { code: 0, signal: null }
npm timing build:run:postinstall:../postinstall-package Completed in 25ms
npm timing build:run:postinstall Completed in 26ms
npm timing build:links Completed in 26ms
npm timing build Completed in 27ms
npm timing reify:build Completed in 27ms
npm timing reify:trash Completed in 0ms
npm timing reify:save Completed in 2ms
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 490ms
npm timing auditReport:getReport Completed in 492ms
npm sill audit report {}
npm timing auditReport:init Completed in 0ms
npm timing reify:audit Completed in 494ms
npm timing reify Completed in 510ms
npm sill ADD node_modules/postinstall-package

added 1 package, and audited 3 packages in 656ms

found 0 vulnerabilities
npm timing command:install Completed in 521ms
npm verb exit 0
npm timing npm Completed in 660ms
npm info ok

global npmrc:

prefix=/home/hasezoey/.npm-packages
sign-git-tag=true

Expected Behavior

The log from the script to be logged somehow to the console (even if it requires an different loglevel)

Steps To Reproduce

1. git clone https://github.com/hasezoey/npm-postinstall
2. cd npm-postinstall
3. cd root-package
4. npm install / npm install --loglevel silly

Environment

• OS: Linux (Mint 20.1)
• Node: 16.2.0
• npm: 7.15.1 (also tested with 7.2.x)

[wraithgar]

Lifecycle events do output when they run:

~/D/n/lifecycles $ npm i

> lifecycle-events@1.0.0 preinstall
> echo foo preinstall script; touch lifecycle/preinstall

foo preinstall script

> lifecycle-events@1.0.0 install
> echo foo install script; touch lifecycle/install

foo install script

> lifecycle-events@1.0.0 postinstall
> echo foo postinstall script; touch lifecycle/postinstall

foo postinstall script
~/D/n/lifecycles $ npm -v
7.15.1

What is happening here is that the install script for a dependency that is being installed is not ran when you install it into another package. The package being installed into is the one that has its scripts ran. There is an RFC discussion here planning out what the former scenario would look like.

[hasezoey]

@wraithgar sorry, i dont not quite understand, do you mean that only the hooks of the root package (depth 0) are run, or only by the installed package (depth 1) (and not the transitive dependencies)
or did the hooks altogether change and need to be placed in some kind of .hooks directory to be run (the postinstalls i am speaking of only need to be run once - on actual install - but dont care if being run again)

just to make it an one-liner: i cannot get any log output from an postinstall script in npm 7.x when it successfully completes
(tested on at least 3 machines, all of them are linux)

and to re-describe my problem:
any output from an postinstall script is not being logged to the console in npm 7.x (even with highest loglevel), but it did in npm 6.x, so my question was why it is not being logged and how to activate it being logged

PS: the mentioned reproduction repository has 2 packages, the root-package, where dependencies are installed into (only the one other package in the repo), by default by path (to not hit any downloading), but even if downloading then there is no log output for any postinstall script

[wraithgar]

Sorry I see where I got confused. This is a situation that's still pretty confusing (even internally apparently) and we're working on improving it.

If you install from a file://../foo then the lifecycle scripts in foo aren't ran.
If you npm install foo the lifecycle scripts in foo are ran, but the output is suppressed. Errors still bubble up though.
In neither of these situations are the lifecycle scripts for the root package ran.

To get the output of lifecycle scripts that are suppressed, you need the --foreground-scripts option. This keeps things in the foreground.

The RFC I linked was the mirror of this problem, if you npm install foo in package bar, the lifecycle scripts in bar are not ran.

So TLDR --foreground-scripts is the flag you likely want, to see the output.

[wraithgar]

https://docs.npmjs.com/cli/v7/using-npm/config#foreground-scripts

[hasezoey]

here the full console output of trying to install the mentioned reproduction repository:

Complete Console Output

system: Linux Mint 20.1
terminal: zsh with oh-my-zsh and agnoster theme

 hasezoey@pina  ~/Downloads/npm-postinstall   master  ll
total 12
drwxrwxr-x 1 hasezoey hasezoey  712 Jun  3 18:52 .
drwxr-xr-x 1 hasezoey hasezoey  376 Jun  3 18:52 ..
drwxrwxr-x 1 hasezoey hasezoey 2016 Jun  3 18:52 .git
-rw-rw-r-- 1 hasezoey hasezoey   19 Jun  3 18:52 .gitignore
drwxrwxr-x 1 hasezoey hasezoey  336 Jun  3 18:52 postinstall-package
drwxrwxr-x 1 hasezoey hasezoey  544 Jun  3 18:52 root-package
 hasezoey@pina  ~/Downloads/npm-postinstall   master  cd root-package 
 hasezoey@pina  ~/Downloads/npm-postinstall/root-package   master  npm i

added 1 package, and audited 3 packages in 909ms

found 0 vulnerabilities
 hasezoey@pina  ~/Downloads/npm-postinstall/root-package   master  rm -rf node_modules 
 hasezoey@pina  ~/Downloads/npm-postinstall/root-package   master  npm i --loglevel silly
npm verb cli [
npm verb cli   '/usr/bin/node',
npm verb cli   '/home/hasezoey/.npm-packages/bin/npm',
npm verb cli   'i',
npm verb cli   '--loglevel',
npm verb cli   'silly'
npm verb cli ]
npm info using npm@7.15.1
npm info using node@v16.2.0
npm timing npm:load:whichnode Completed in 2ms
npm timing config:load:defaults Completed in 0ms
npm timing config:load:file:/home/hasezoey/.npm-packages/lib/node_modules/npm/npmrc Completed in 0ms
npm timing config:load:builtin Completed in 1ms
npm timing config:load:cli Completed in 2ms
npm timing config:load:env Completed in 0ms
npm timing config:load:file:/home/hasezoey/Downloads/npm-postinstall/root-package/.npmrc Completed in 1ms
npm timing config:load:project Completed in 1ms
npm timing config:load:file:/home/hasezoey/.npmrc Completed in 1ms
npm timing config:load:user Completed in 1ms
npm timing config:load:file:/home/hasezoey/.npm-packages/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 1ms
npm timing config:load Completed in 7ms
npm timing npm:load:configload Completed in 8ms
npm timing npm:load:setTitle Completed in 0ms
npm timing npm:load:setupLog Completed in 1ms
npm timing npm:load:cleanupLog Completed in 1ms
npm timing npm:load:configScope Completed in 0ms
npm timing npm:load:projectScope Completed in 0ms
npm timing npm:load Completed in 15ms
npm timing config:load:flatten Completed in 2ms
npm timing arborist:ctor Completed in 0ms
npm timing idealTree:init Completed in 10ms
npm timing idealTree:userRequests Completed in 1ms
npm sill idealTree buildDeps
npm timing idealTree:#root Completed in 0ms
npm timing idealTree:buildDeps Completed in 1ms
npm timing idealTree:fixDepFlags Completed in 0ms
npm timing idealTree Completed in 12ms
npm timing reify:loadTrees Completed in 12ms
npm timing reify:diffTrees Completed in 0ms
npm sill reify moves {}
npm timing reify:retireShallow Completed in 0ms
npm timing reify:createSparse Completed in 0ms
npm timing reify:loadBundles Completed in 0ms
npm sill audit bulk request { postinstall_package: [ '1.0.0' ] }
npm timing reifyNode:node_modules/postinstall-package Completed in 22ms
npm timing reify:unpack Completed in 22ms
npm timing reify:unretire Completed in 0ms
npm timing build:queue Completed in 0ms
npm timing build:deps Completed in 1ms
npm timing build:queue Completed in 1ms
npm info run postinstall_package@1.0.0 postinstall ../postinstall-package node ./postinstall.js
npm info run postinstall_package@1.0.0 postinstall { code: 0, signal: null }
npm timing build:run:postinstall:../postinstall-package Completed in 43ms
npm timing build:run:postinstall Completed in 43ms
npm timing build:links Completed in 44ms
npm timing build Completed in 45ms
npm timing reify:build Completed in 45ms
npm timing reify:trash Completed in 0ms
npm timing reify:save Completed in 5ms
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 856ms
npm timing auditReport:getReport Completed in 857ms
npm sill audit report {}
npm timing auditReport:init Completed in 0ms
npm timing reify:audit Completed in 857ms
npm timing reify Completed in 877ms
npm sill ADD node_modules/postinstall-package

added 1 package, and audited 3 packages in 1s

found 0 vulnerabilities
npm timing command:install Completed in 883ms
npm verb exit 0
npm timing npm Completed in 1034ms
npm info ok 
 hasezoey@pina  ~/Downloads/npm-postinstall/root-package   master  node -v
v16.2.0
 hasezoey@pina  ~/Downloads/npm-postinstall/root-package   master  npm -v
7.15.1

---

So TLDR --foreground-scripts is the flag you likely want, to see the output.

so basically there is no way to output the log of the background-scripts (even after script completion) with higher loglevel activated? only way is this --foreground-scripts parameter?

---

thanks for mentioning this config option, i searched all over, but couldnt really find any way to force the log to appear again (looked into similar issues, suggested was an higher loglevel, and looked in some changelogs, but only mention was make output less noisy without telling what to do to get the log back, also didnt find this option)

[wraithgar]

so basically there is no way to output the log of the background-scripts (even after script completion) with higher loglevel activated? only way is this --foreground-scripts parameter?

Yes this is the only way.

[wraithgar]

thanks for mentioning this config option, i searched all over, but couldnt really find any way to force the log to appear again (looked into similar issues, suggested was an higher loglevel, and looked in some changelogs, but only mention was make output less noisy without telling what to do to get the log back, also didnt find this option)

Wherever you were instinctively looking for this would likely be a good candidate for updating the docs. If you would be so kind as to suggest an update to them via PR it would help us down the line.

Docs for commands live here: https://github.com/npm/cli/tree/latest/docs/content

[hasezoey]

@wraithgar with "similar issues" and "changelogs" i meant what i had found on google about this problem (stackoverflow, blog posts reporting on npm 7.x and some issues here and npm/config), but didnt really find an official changelog (that included this change and mention of the option), and where i "instinctively" (and after suggestions) looked was using an higher loglevel, it didnt even occur to me that an option like foreground-scripts was a thing

[wraithgar]

#3360