[BUG] npm install -g of package itself calling npm in postinstall script causes constant 60s timeout

[ronjouch]

What / Why

I have a project with a CLI living in the project's / , producing Electron apps based on an app template living in /app/. Both the CLI and app template are included in my npm package and, since both have dependencies, I have two package.json files, one in / specifying CLI deps and one in /app/ specifying template deps. I want to separate both dependency sets, but I do not want to split the app template (/app/) into its own published npm package, because it has no intrinsic value on its own and is tied to the CLI living in /.

To automatically install the app template deps, the root package.json defines a simple postinstall script that calls "cd app && npm install".

• Installing my package with npm install works perfectly...
• ... however, installing it globally with npm install -g succeeds, but constantly finishes in a bit more than 60s, 99.9% of it spent in a executeActions stage, suggesting something (a lock?) inside this stage times out.

When

Consider this minimal reproduction package (here it is as npm-nested-minimal.tgz, please open it in an archive reader and verify it before installing):

└── package
    ├── inner
    │   └── package.json
    └── package.json

, with package.json containing:

{
  "name": "outer",
  "version": "1.0.0",
  "scripts": {
    "postinstall": "cd inner && npm install"
  }
}

, and inner/package.json containing:

{
  "name": "inner",
  "version": "1.0.0"
}

How

npm --verbose i -g npm-nested-minimal.tgz

Current Behavior

• Running node v12.14.1 / npm 6.13.6 under Arch Linux,
• Installing npm-nested-minimal.tgz constantly finishes in 60 seconds and a few milliseconds, with most of the 60s spent in an executeActions stage (see logs below).
• Problem is specific to -g, the same command without -g finishes instantly.
• Moving the inner install script from postinstall to preinstall doesn't change anything.

Logs for `npm --verbose i -g npm-nested-minimal.tgz`

~ npm --verbose i -g npm-nested-minimal.tgz
npm info it worked if it ends with ok
npm verb cli [
npm verb cli   '/usr/bin/node',
npm verb cli   '/usr/bin/npm',
npm verb cli   '--verbose',
npm verb cli   'i',
npm verb cli   '-g',
npm verb cli   'npm-nested-minimal.tgz'
npm verb cli ]
npm info using [email protected]
npm info using [email protected]
npm verb npm-session d3f55f496b33c2ed
npm timing stage:loadCurrentTree Completed in 52ms
npm timing stage:loadIdealTree:cloneCurrentTree Completed in 0ms
npm timing stage:loadIdealTree:loadShrinkwrap Completed in 1ms
npm timing stage:loadIdealTree:loadAllDepsIntoIdealTree Completed in 4ms
npm timing stage:loadIdealTree Completed in 7ms
npm timing stage:generateActionsToTake Completed in 4ms
npm verb correctMkdir /home/ronj/.npm/_locks correctMkdir not in flight; initializing
npm verb lock using /home/ronj/.npm/_locks/staging-1aa8906dd05b2d43.lock for /home/ronj/.node_modules/lib/node_modules/.staging
npm timing action:extract Completed in 14ms
npm info lifecycle [email protected]~preuninstall: [email protected]
npm info lifecycle [email protected]~uninstall: [email protected]
npm verb unbuild rmStuff [email protected] from /home/ronj/.node_modules/lib/node_modules
npm info lifecycle [email protected]~postuninstall: [email protected]
npm timing action:unbuild Completed in 4ms
npm timing action:remove Completed in 4ms
npm timing action:finalize Completed in 2ms
npm timing action:refresh-package-json Completed in 4ms
npm info lifecycle [email protected]~preinstall: [email protected]
npm timing action:preinstall Completed in 0ms
npm info linkStuff [email protected]
npm timing action:build Completed in 2ms
npm info lifecycle [email protected]~install: [email protected]
npm timing action:install Completed in 1ms
npm info lifecycle [email protected]~postinstall: [email protected]

> [email protected] postinstall /home/ronj/.node_modules/lib/node_modules/outer
> cd inner && npm install

npm info it worked if it ends with ok
npm verb cli [ '/usr/bin/node', '/usr/bin/npm', 'install' ]
npm info using [email protected]
npm info using [email protected]
npm verb npm-session 21a6f87449151841
npm timing stage:loadCurrentTree Completed in 39ms
npm timing stage:loadIdealTree:cloneCurrentTree Completed in 1ms
npm timing stage:loadIdealTree:loadShrinkwrap Completed in 1ms
npm timing stage:loadIdealTree:loadAllDepsIntoIdealTree Completed in 4ms
npm timing stage:loadIdealTree Completed in 7ms
npm timing stage:generateActionsToTake Completed in 5ms
npm verb correctMkdir /home/ronj/.npm/_locks correctMkdir not in flight; initializing
npm verb lock using /home/ronj/.npm/_locks/staging-1aa8906dd05b2d43.lock for /home/ronj/.node_modules/lib/node_modules/.staging
npm info lifecycle [email protected]~preuninstall: [email protected]
npm info lifecycle [email protected]~uninstall: [email protected]
npm verb unbuild rmStuff [email protected] from /home/ronj/.node_modules/lib/node_modules
npm info lifecycle [email protected]~postuninstall: [email protected]
npm timing action:unbuild Completed in 20ms
npm timing action:remove Completed in 2ms
npm timing action:finalize Completed in 3ms
npm timing action:refresh-package-json Completed in 6ms
npm info lifecycle [email protected]~preinstall: [email protected]
npm timing action:preinstall Completed in 1ms
npm info linkStuff [email protected]
npm timing action:build Completed in 2ms
npm info lifecycle [email protected]~install: [email protected]
npm timing action:install Completed in 1ms
npm info lifecycle [email protected]~postinstall: [email protected]
npm timing action:postinstall Completed in 1ms
npm verb unlock done using /home/ronj/.npm/_locks/staging-1aa8906dd05b2d43.lock for /home/ronj/.node_modules/lib/node_modules/.staging
npm timing stage:executeActions Completed in 60113ms
npm timing stage:rollbackFailedOptional Completed in 0ms
npm timing stage:runTopLevelLifecycles Completed in 60168ms
+ [email protected]
updated 1 package in 60.17s
npm verb exit [ 0, true ]
npm timing npm Completed in 60384ms
npm info ok 
npm verb lifecycle [email protected]~postinstall: unsafe-perm in lifecycle true
npm verb lifecycle [email protected]~postinstall: PATH: /usr/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/home/ronj/.node_modules/lib/node_modules/outer/node_modules/.bin:/home/ronj/.node_modules/lib/node_modules/.bin:/home/ronj/.node_modules/bin:/usr/local/bin:/usr/local/sbin:/usr/bin
npm verb lifecycle [email protected]~postinstall: CWD: /home/ronj/.node_modules/lib/node_modules/outer
npm timing action:postinstall Completed in 60527ms
npm verb unlock done using /home/ronj/.npm/_locks/staging-1aa8906dd05b2d43.lock for /home/ronj/.node_modules/lib/node_modules/.staging
npm timing stage:executeActions Completed in 60567ms
npm timing stage:rollbackFailedOptional Completed in 1ms
npm timing stage:runTopLevelLifecycles Completed in 60632ms
+ [email protected]
updated 1 package in 60.634s
npm verb exit [ 0, true ]
npm timing npm Completed in 60854ms
npm info ok 

Expected Behavior

• Install of dummy package should finish almost instantly.

Who

• n/a

References

• n/a

[remusao]

I spent a few minutes to investigates this and could reproduce locally with your provided archive. I found a few things:

• The hanging seems to happen at this step: npm verb correctMkdir /home/remi/.npm/_locks correctMkdir not in flight; initializing
• This seems to create a file in this ~/.npm/_locks/ directory, which is then deleted after the install process is terminated.
• I found someone with a similar issue here: https://stackoverflow.com/questions/43108745/how-does-npm-handle-lock-files
• Interestingly, he mentions the cache-lock-stale of option, which is described as "The number of ms before cache folder lockfiles are considered stale.", and its default values is... 60 seconds.

So for some reason the global install process gets stuck until the global lock file gets stalled and invalidated? My best guess so far is this:

1. The package has two package.json files
2. When installing the first one, it creates the lock file globally.
3. The postinstall calls the second package.json file, which has to wait for the first lock to expire (the one from top-level package.json) before it can proceed
4. This duration is 60 seconds.

So I guess the issue is having two package.json used in a global install with npm. I am not sure if there is a way to circumvent the issue though...

[darcyclarke]

npm v6 is no longer in active development; We will continue to push security releases to v6 at our team's discretion as-per our Support Policy.

If your bug is preproducible on v7, please re-file this issue using our new issue template.

If your issue was a feature request, please consider opening a new RRFC or RFC. If your issue was a question or other idea that was not CLI-specific, consider opening a discussion on our feedback repo

Closing: This is an automated message.