Install hangs when node_modules exists


(Petter Häggholm) #1

What I Wanted to Do

What Happened Instead

One of our packages has a postinstall script that installs additional dependencies based on dynamic criteria. On some machines, this works fine. At times, it stalls, apparently indefinitely. It gets to the loadAllDepsIntoIdealTree stage normally, but then takes minutes to inspect each dependency for resolveWithNewModule and removeObsoleteDep actions. CPU usage is stuck at over 100%. It eventually finished, but it took 28 minutes (1695795ms) on one system; on another, 72 minutes (4346119ms).

strace tells me that for the most part, it’s running thousands upon thousands of futex-related commands; an endless stream of

mmap(0x2d0509f80000, 1044480, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x2d0509f80000
munmap(0x2d050a000000, 520192) = 0
mprotect(0x2d0509f80000, 524288, PROT_READ|PROT_WRITE) = 0
futex(0x36c55c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x36c55cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x36c55cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x36c5578, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x36c55cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x36c55cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x36c55b4, FUTEX_WAIT_PRIVATE, 4, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x36c55c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x36c5578, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x3722258, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fff690f9f70, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fff690fa560, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fff690f9f68, FUTEX_WAKE_PRIVATE, 2147483647) = 4
futex(0x7fff690f9f70, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x36d1c60, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x36d1c60, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x36c55cc, FUTEX_WAKE_PRIVATE, 1) = 1
getpid() = 21839
futex(0x36c55cc, FUTEX_WAKE_PRIVATE, 1) = 1

Reproduction Steps

Unfortunately, I’ve only seen this happen with our own, internal repositories, so it cannot easily be reproduced.

I’m trying to run

npm install --no-save -ddd @owl-backend/api-uid @owl-backend/api-log-event @owl-backend/api-channel @owl-backend/api-background-task @owl-backend/api-storage @owl-backend/api-user @owl-backend/api-user-crypto @owl-backend/api-user-settings @owl-backend/api-user-session @owl-backend/api-user-device @owl-backend/api-user-storage @owl-backend/api-user-payment @owl-backend/api-team @owl-backend/api-team-billing @owl-backend/api-team-feature @owl-backend/api-team-crypto @owl-backend/api-team-permission @owl-backend/api-team-member @owl-backend/api-team-member-invitation @owl-backend/api-team-notification @owl-backend/api-team-work space-permission @owl-backend/api-team-workspace-participant @owl-backend/api-team-workspace-integration @owl-backend/api-team-workspace-stream @owl-backend/api-team-workspace-storage @owl-backend/api-team-stats

I can provide three logs: an npm log showing what’s happening, and some rather suspicious-looking strace logs, from before and after running npm cache clean. Unfortunately, this site won’t allow me to attach all three because new users aren’t allowed multiple attachments. I’ll paste the npm log below, at the bottom, as it’s not large, and attach one of my strace logs.

strace.after-cache-clean.log (3.4 MB)

Details

See below for log.

Platform Info

$ npm --versions
{ '@owl-backend/api-service': '1.2.2',
  npm: '6.4.1',
  ares: '1.14.0',
  cldr: '33.1',
  http_parser: '2.8.0',
  icu: '62.1',
  modules: '64',
  napi: '3',
  nghttp2: '1.34.0',
  node: '10.12.0',
  openssl: '1.1.0i',
  tz: '2018e',
  unicode: '11.0',
  uv: '1.23.2',
  v8: '6.8.275.32-node.35',
  zlib: '1.2.11' }
$ node -p process.platform
linux

Just in case, I also tried it with Node 11.0.0, but there was no apparent change.

npm log

Because “Sorry, new users can only put 5 links in a post”, I’ve had to edit out the download links, but they are of no value anyway, as you can’t access them.

npm install --no-save -ddd @owl-backend/api-uid @owl-backend/api-log-event @owl-backend/api-channel @owl-backend/api-background-task @owl-backend/api-storage @owl-backend/api-user @owl-backend/api-user-crypto @owl-backend/api-user-settings @owl-backend/api-user-session @owl-backend/api-user-device @owl-backend/api-user-storage @owl-backend/api-user-payment @owl-backend/api-team @owl-backend/api-team-billing @owl-backend/api-team-feature @owl-backend/api-team-crypto @owl-backend/api-team-permission @owl-backend/api-team-member @owl-backend/api-team-member-invitation @owl-backend/api-team-notification @owl-backend/api-team-workspace-permission @owl-backend/api-team-workspace-participant @owl-backend/api-team-workspace-integration @owl-backend/api-team-workspace-stream @owl-backend/api-team-workspace-storage @owl-backend/api-team-stats
npm info it worked if it ends with ok
npm verb cli [ ‘/usr/bin/node’,
npm verb cli ‘/usr/bin/npm’,
npm verb cli ‘install’,
npm verb cli ‘–no-save’,
npm verb cli ‘-ddd’,
npm verb cli ‘@owl-backend/api-uid’,
npm verb cli ‘@owl-backend/api-log-event’,
npm verb cli ‘@owl-backend/api-channel’,
npm verb cli ‘@owl-backend/api-background-task’,
npm verb cli ‘@owl-backend/api-storage’,
npm verb cli ‘@owl-backend/api-user’,
npm verb cli ‘@owl-backend/api-user-crypto’,
npm verb cli ‘@owl-backend/api-user-settings’,
npm verb cli ‘@owl-backend/api-user-session’,
npm verb cli ‘@owl-backend/api-user-device’,
npm verb cli ‘@owl-backend/api-user-storage’,
npm verb cli ‘@owl-backend/api-user-payment’,
npm verb cli ‘@owl-backend/api-team’,
npm verb cli ‘@owl-backend/api-team-billing’,
npm verb cli ‘@owl-backend/api-team-feature’,
npm verb cli ‘@owl-backend/api-team-crypto’,
npm verb cli ‘@owl-backend/api-team-permission’,
npm verb cli ‘@owl-backend/api-team-member’,
npm verb cli ‘@owl-backend/api-team-member-invitation’,
npm verb cli ‘@owl-backend/api-team-notification’,
npm verb cli ‘@owl-backend/api-team-workspace-permission’,
npm verb cli ‘@owl-backend/api-team-workspace-participant’,
npm verb cli ‘@owl-backend/api-team-workspace-integration’,
npm verb cli ‘@owl-backend/api-team-workspace-stream’,
npm verb cli ‘@owl-backend/api-team-workspace-storage’,
npm verb cli ‘@owl-backend/api-team-stats’ ]
npm info using npm@6.4.1
npm info using node@v10.12.0
npm verb npm-session 456f46532a2488cb
npm sill install loadCurrentTree
npm sill install readLocalPackageData
npm http fetch GET 200 /@owl-backend%2fapi-user 78ms
npm http fetch GET 200 /@owl-backend%2fapi-storage 81ms
npm http fetch GET 200 /@owl-backend%2fapi-log-event 82ms
npm http fetch GET 200 /@owl-backend%2fapi-channel 84ms
npm http fetch GET 200 /@owl-backend%2fapi-uid 92ms
npm http fetch GET 200 /@owl-backend%2fapi-background-task 87ms
npm http fetch GET 200 /@owl-backend%2fapi-user-crypto 99ms
npm http fetch GET 200 /@owl-backend%2fapi-user-settings 100ms
npm http fetch GET 200 /@owl-backend%2fapi-user-device 101ms
npm http fetch GET 200 /@owl-backend%2fapi-user-session 102ms
npm http fetch GET 200 /@owl-backend%2fapi-uid/-/api-uid-1.0.25.tgz 65ms
npm http fetch GET 200 /@owl-backend%2fapi-storage/-/api-storage-1.0.15.tgz 72ms
npm http fetch GET 200 /@owl-backend%2fapi-user/-/api-user-1.1.70.tgz 75ms
npm http fetch GET 200 /@owl-backend%2fapi-log-event/-/api-log-event-1.0.16.tgz 72ms
npm http fetch GET 200 /@owl-backend%2fapi-background-task/-/api-background-task-1.0.9.tgz 70ms
npm http fetch GET 200 /@owl-backend%2fapi-channel/-/api-channel-1.0.48.tgz 72ms
npm http fetch GET 200 /@owl-backend%2fapi-user-crypto/-/api-user-crypto-1.1.7.tgz 60ms
npm http fetch GET 200 /@owl-backend%2fapi-user-settings/-/api-user-settings-1.2.17.tgz 58ms
npm http fetch GET 200 /@owl-backend%2fapi-user-device/-/api-user-device-1.0.7.tgz 54ms
npm http fetch GET 200 /@owl-backend%2fapi-user-session/-/api-user-session-1.1.29.tgz 49ms
npm sill pacote tag manifest for @owl-backend/api-uid@latest fetched in 178ms
npm sill pacote tag manifest for @owl-backend/api-log-event@latest fetched in 170ms
npm sill pacote tag manifest for @owl-backend/api-background-task@latest fetched in 171ms
npm sill pacote tag manifest for @owl-backend/api-channel@latest fetched in 171ms
npm sill pacote tag manifest for @owl-backend/api-user-crypto@latest fetched in 171ms
npm sill pacote tag manifest for @owl-backend/api-user-settings@latest fetched in 174ms
npm sill pacote tag manifest for @owl-backend/api-storage@latest fetched in 176ms
npm sill pacote tag manifest for @owl-backend/api-user@latest fetched in 177ms
npm sill pacote tag manifest for @owl-backend/api-user-device@latest fetched in 178ms
npm sill pacote tag manifest for @owl-backend/api-user-session@latest fetched in 179ms
npm http fetch GET 200 /@owl-backend%2fapi-user-storage 18ms
npm http fetch GET 200 /@owl-backend%2fapi-user-payment 21ms
npm http fetch GET 200 /@owl-backend%2fapi-team 31ms
npm http fetch GET 200 /@owl-backend%2fapi-team-billing 33ms
npm http fetch GET 200 /@owl-backend%2fapi-team-permission 30ms
npm http fetch GET 200 /@owl-backend%2fapi-team-crypto 53ms
npm http fetch GET 200 /@owl-backend%2fapi-team-feature 57ms
npm http fetch GET 200 /@owl-backend%2fapi-team-member-invitation 50ms
npm http fetch GET 200 /@owl-backend%2fapi-user-storage/-/api-user-storage-1.0.9.tgz 47ms
npm http fetch GET 200 /@owl-backend%2fapi-team-notification 56ms
npm http fetch GET 200 /@owl-backend%2fapi-user-payment/-/api-user-payment-1.0.20.tgz 47ms
npm http fetch GET 200 /@owl-backend%2fapi-team-member 61ms
npm http fetch GET 200 /@owl-backend%2fapi-team/-/api-team-1.1.7.tgz 39ms
npm http fetch GET 200 /@owl-backend%2fapi-team-billing/-/api-team-billing-1.0.47.tgz 40ms
npm http fetch GET 200 /@owl-backend%2fapi-team-permission/-/api-team-permission-1.1.2.tgz 34ms
npm sill pacote tag manifest for @owl-backend/api-user-storage@latest fetched in 80ms
npm sill pacote tag manifest for @owl-backend/api-user-payment@latest fetched in 83ms
npm sill pacote tag manifest for @owl-backend/api-team@latest fetched in 99ms
npm sill pacote tag manifest for @owl-backend/api-team-billing@latest fetched in 101ms
npm sill pacote tag manifest for @owl-backend/api-team-permission@latest fetched in 106ms
npm http fetch GET 200 /@owl-backend%2fapi-team-crypto/-/api-team-crypto-1.1.16.tgz 68ms
npm http fetch GET 200 /@owl-backend%2fapi-team-member-invitation/-/api-team-member-invitation-1.0.58.tgz 66ms
npm http fetch GET 200 /@owl-backend%2fapi-team-feature/-/api-team-feature-1.1.4.tgz 69ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-permission 53ms
npm http fetch GET 200 /@owl-backend%2fapi-team-member/-/api-team-member-1.0.126.tgz 64ms
npm http fetch GET 200 /@owl-backend%2fapi-team-notification/-/api-team-notification-1.0.25.tgz 69ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-participant 56ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-stream 40ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-integration 51ms
npm sill pacote tag manifest for @owl-backend/api-team-crypto@latest fetched in 155ms
npm sill pacote tag manifest for @owl-backend/api-team-member-invitation@latest fetched in 150ms
npm sill pacote tag manifest for @owl-backend/api-team-feature@latest fetched in 162ms
npm sill pacote tag manifest for @owl-backend/api-team-member@latest fetched in 157ms
npm sill pacote tag manifest for @owl-backend/api-team-notification@latest fetched in 155ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-storage 47ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-permission/-/api-team-workspace-permission-1.1.2.tgz 30ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-participant/-/api-team-workspace-participant-1.1.8.tgz 26ms
npm sill pacote tag manifest for @owl-backend/api-team-workspace-permission@latest fetched in 99ms
npm sill pacote tag manifest for @owl-backend/api-team-workspace-participant@latest fetched in 98ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-stream/-/api-team-workspace-stream-1.0.101.tgz 35ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-integration/-/api-team-workspace-integration-1.0.22.tgz 29ms
npm http fetch GET 200 /@owl-backend%2fapi-team-workspace-storage/-/api-team-workspace-storage-1.0.39.tgz 22ms
npm sill pacote tag manifest for @owl-backend/api-team-workspace-stream@latest fetched in 82ms
npm http fetch GET 200 /@owl-backend%2fapi-team-stats 29ms
npm sill pacote tag manifest for @owl-backend/api-team-workspace-integration@latest fetched in 88ms
npm sill pacote tag manifest for @owl-backend/api-team-workspace-storage@latest fetched in 74ms
npm http fetch GET 200 /@owl-backend%2fapi-team-stats/-/api-team-stats-1.0.3.tgz 10ms
npm sill pacote tag manifest for @owl-backend/api-team-stats@latest fetched in 41ms
npm timing stage:loadCurrentTree Completed in 1465ms
npm sill install loadIdealTree
npm sill install cloneCurrentTreeToIdealTree
npm timing stage:loadIdealTree:cloneCurrentTree Completed in 4ms
npm sill install loadShrinkwrap
npm timing stage:loadIdealTree:loadShrinkwrap Completed in 256ms
npm sill install loadAllDepsIntoIdealTree
npm sill resolveWithNewModule @owl-backend/api-uid@1.0.25 checking installable status
npm sill removeObsoleteDep removing @owl-backend/api-uid@1.0.25 from the tree as its been replaced by a newer version or is no longer required
npm sill resolveWithNewModule @owl-backend/api-log-event@1.0.16 checking installable status
npm sill removeObsoleteDep removing @owl-backend/api-log-event@1.0.16 from the tree as its been replaced by a newer version or is no longer required


(Joshua) #2

Does it work if you install the packages one at a time?


(Petter Häggholm) #3

One at a time is just as bad.


(Joshua) #4

I know that, but this problem might be related to the fact that you are installing them all at once. So can you try it one at a time just once to see if it works?


(Petter Häggholm) #5

Sorry, I wasn’t being very clear. What I meant was, installing them one at a time works just as badly as all at once; I tried to install just one package and terminated it out of frustration after five or ten minutes.