Downstream PR preview creation and build slowness/timeouts

[victorlin]

Context

When working on UI changes, it's useful to previews the changes on nextstrain.org. Currently, the process is simple but it takes a long time, at least 20 minutes: >10m to make the PR, then >10m to build the preview version of nextstrain.org. The slowness seems to be mostly due to npm install being slow when resolving git references.

Upstream issue

• [BUG] GitHub references to dependencies slow/hang npm/cli#4896

Past discussions

This has been disussed in #1565 (comment), #1567 (comment) and #1661 (comment). I thought it would be fixed with the upgrade to Node.js 16, but looks like it's still taking a while.

Solutions

• For time to create the downstream PR: Speed up review app installation #1870
• For time to build the review app on Heroku: auspice-client: Speed up build nextstrain.org#1041

Solutions that didn't work / weren't pursued

1. Accept the slowness and do things to fill the void while waiting, such as writing issues like this.
2. Try using yarn, maybe it's faster?
3. Do the npm install with https://
4. Replace github: with https:// in package.json + package-lock.json
5. (in git config on both the workflow that creates the PR and the heroku build env) Use url."ssh://git@".insteadOf git:// or url."https://github".insteadOf "git://github"

[jameshadfield]

Recent changes to how nextstrain.org is built & deployed have improved this a lot. npm is still slower installing from GitHub cf. the npm registry, but I don't think it's worth switching to yarn or similar. Please re-open this issue if it's still frustrating for anyone!

[victorlin]

Re-opening this because it is once again taking at least 20 minutes and even timing out on Heroku builds.

[victorlin]

Read through the upstream issue and added some more possible solutions which I'm trying in #1870.

[victorlin]

In nextstrain/nextstrain.org#1039 I tried some different workarounds mentioned in npm/cli#4896 but none seemed to work:

• use https:// – nextstrain/nextstrain.org@b0f539a
• use git+ssh://git@github.com – nextstrain/nextstrain.org@2fe815c
• set git config url."ssh://git@".insteadOf git:// – nextstrain/nextstrain.org@f6ad7a1

I then ran npm ci verbosely¹ which revealed where the slowness is happening. Here are the logs from the build that ran on GitHub which took a while but succeeded:

2024-10-18T02:07:38.2155165Z npm http fetch GET 200 https://registry.npmjs.org/core-js/-/core-js-3.29.1.tgz 6072ms (cache miss)
2024-10-18T02:07:38.2407069Z npm http fetch GET 200 https://codeload.github.com/nextstrain/auspice/tar.gz/80c8cf0c8946ea10e2c3a0ce3caad0ea2653891f 5464ms (cache miss)
2024-10-18T02:14:20.0421014Z npm info run core-js@3.29.1 postinstall node_modules/core-js node -e "try{require('./postinstall')}catch(e){}"

and on Heroku which timed out:

npm http fetch GET 200 https://codeload.github.com/nextstrain/auspice/tar.gz/80c8cf0c8946ea10e2c3a0ce3caad0ea2653891f 4088ms (cache miss)
npm http fetch GET 200 https://registry.npmjs.org/core-js/-/core-js-3.29.1.tgz 5152ms (cache miss)
ERROR: Build terminated for reason: Build Timeout Expired
npm verbose stack Error: git dep preparation failed
npm verbose stack     at promiseSpawn (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/lib/index.js:22:22)
npm verbose stack     at module.exports (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/pacote/lib/util/npm.js:13:10)
npm verbose stack     at /tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/pacote/lib/git.js:183:14
npm verbose stack     at async withTempDir (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/fs/lib/with-temp-dir.js:21:14)
npm error code 1
npm error git dep preparation failed
npm error command /tmp/build_a95b27fb/.heroku/node/bin/node /tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/bin/npm-cli.js install --force --cache=/tmp/npmcache.0D6Zr --prefer-offline=false --prefer-online=false --offline=false --no-progress --no-save --no-audit --include=dev --include=peer --include=optional --no-package-lock-only --no-dry-run
…
npm error npm verbose stack Error: command failed
npm error npm verbose stack     at promiseSpawn (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/lib/index.js:22:22)
npm error npm verbose stack     at spawnWithShell (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/lib/index.js:124:10)
npm error npm verbose stack     at promiseSpawn (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/lib/index.js:12:12)
npm error npm verbose stack     at runScriptPkg (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/run-script/lib/run-script-pkg.js:77:13)
npm error npm verbose stack     at runScript (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/run-script/lib/run-script.js:9:12)
npm error npm verbose stack     at /tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/arborist/rebuild.js:329:17
npm error npm verbose stack     at run (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/promise-call-limit/dist/commonjs/index.js:67:22)
npm error npm verbose stack     at /tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/promise-call-limit/dist/commonjs/index.js:84:9
npm error npm verbose stack     at new Promise (<anonymous>)
npm error npm verbose stack     at callLimit (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/promise-call-limit/dist/commonjs/index.js:35:69)
npm error npm verbose stack     at #runScripts (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/arborist/rebuild.js:289:11)
npm error npm verbose stack     at #build (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/arborist/rebuild.js:165:29)
npm error npm verbose stack     at async Arborist.rebuild (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/arborist/rebuild.js:62:5)
npm error npm verbose stack     at async [reifyPackages] (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/arborist/reify.js:325:11)
npm error npm verbose stack     at async Arborist.reify (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/node_modules/@npmcli/arborist/lib/arborist/reify.js:142:5)
npm error npm verbose stack     at async Install.exec (/tmp/build_a95b27fb/.heroku/node/lib/node_modules/npm/lib/commands/install.js:150:5)
npm error npm verbose pkgid puppeteer@20.6.0
npm error npm error path /tmp/npmcache.0D6Zr/_cacache/tmp/git-clonefajMNf/node_modules/puppeteer
npm error npm error command failed
npm error npm error signal SIGTERM
npm error npm error command sh -c node install.js
npm error npm error Chrome (114.0.5735.90) downloaded to /app/.cache/puppeteer/chrome/linux-114.0.5735.90
npm error npm verbose cwd /tmp/npmcache.0D6Zr/_cacache/tmp/git-clonefajMNf
npm error npm verbose os Linux 6.1.109-118.189.amzn2023.x86_64
npm error npm verbose node v20.18.0
npm error npm verbose npm  v10.9.0
npm error npm verbose exit 1
npm error npm verbose code 1
npm error npm error A complete log of this run can be found in: /tmp/npmcache.0D6Zr/_logs/2024-10-18T02_07_06_618Z-debug-0.log

Observations:

• The GitHub build spent 7 minutes on npm info run core-js@3.29.1 postinstall node_modules/core-js node -e "try{require('./postinstall')}catch(e){}" (or something else if verbose logs are still not telling the full story).

• The Heroku build is stuck on fetching from https://codeload.github.com/nextstrain/auspice/tar.gz/80c8cf0c8946ea10e2c3a0ce3caad0ea2653891f. I have a suspicion that this is related to the ongoing "Open Source Repository Engagement Data" incident. I submitted a support request regarding this. failed with git dep preparation failed. I've updated the support ticket with this info.

• On the surface, the git dep preparation failed message for the Heroku build looks like CI failures when npm installing deps from GitHub  nextstrain.org#895 but this time it is able to write to $HOME/.cache sucessfully:

  npm error Chrome (114.0.5735.90) downloaded to /app/.cache/puppeteer/chrome/linux-114.0.5735.90
  

  Also, this build succeeds on GitHub Actions and fails on Heroku instead of failing on GitHub Actions immediately.

¹ it took me a while to figure this one out since Heroku sets NPM_CONFIG_LOGLEVEL=error somewhere...

[victorlin]

Heroku support identified that it was timing out on puppeteer's download of Chrome and suggested using PUPPETEER_SKIP_DOWNLOAD=true to resolve the issue. I confirmed that the Heroku build now completes in ~5 minutes with that setting in nextstrain/nextstrain.org@20dc6c1.

I wouldn't treat that as a solution though. It's not clear to me why puppeteer is being downloaded in the first place since it is listed as a dev dependency of Auspice. On the surface it seems like it shouldn't because NODE_ENV is set to production on the Heroku build. I'll investigate further after lunch.

[victorlin]

This issue has two parts:

1. Time to create the downstream PR
2. Time to build the review app from the downstream PR

I've addressed (1) with #1870 which is ready for review. (2) is tricker with the weirdness I mentioned above. I'll continue to investigate that since these builds are still timing out on Heroku.

[victorlin]

Re: Heroku build issues, I think I've found an explanation in npm docs:

NOTE: If a package being installed through git contains a prepare script, its dependencies and devDependencies will be installed, and the prepare script will be run, before the package is packaged and installed.

and a reason for the elusiveness in logs:

As of npm@7 these scripts run in the background. To see the output, run with: --foreground-scripts.

[victorlin]

I just applied the solutions to #1373. Here's the improved timeline:

• [3:43pm] pushed e2d2658...1120581
• [3:47pm] preview PR updated
• [3:51pm] review app updated
  

[victorlin]

Fixed by #1870 and nextstrain/nextstrain.org#1041

[genehack]

👏