Renovate CLI stuck trying to npm install on a "rebase!"'d PR

[ludwigbacklund]

What Renovate type are you using? Renovate CLI

Describe the bug Renovate CLI gets stuck trying to run npm install in a PR that has been renamed to include "rebase!" in the title. That PR had previously failed with a "lock file problem, ETIMEDOUT" (which is another problem, but for another time). I wanted to try again so I put "rebase!" in the title and ran the CLI again which resulted in this.

Did you see anything helpful in debug logs? Nothing that looks like an apparent error.

To Reproduce

1. Let renovate create a PR that fails for some reason (not sure if failing is a pre-requisite though).
2. Put "rebase!" in the title of the PR.
3. Run renovate again and wait for it to get stuck.

Expected behavior Rebasing and updating the package*.json files without getting stuck.

Screenshots None

Additional context Org/repo has been censored with *

DEBUG: processBranch with 1 upgrades (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Setting baseBranch to myadsrelease (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Setting baseBranch to myadsrelease (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: branchExists(renovate/svgo-loader-2.x)=true (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: getBranchPr(renovate/svgo-loader-2.x) (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: findPr(renovate/svgo-loader-2.x, null, open) (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Found PR #52 (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Skipping unsupported graphql PullRequests.mergeStateStatus query on GHE (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Skipping unsupported graphql PullRequests.mergeStateStatus query on GHE (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
 INFO: PR not found in open or closed PRs list - trying to fetch it directly (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
       "prNo": 52
DEBUG: 1 commit and no configured gitAuthor so can rebase (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
       "prNo": 52
DEBUG: branchExists=true (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Branch has 1 upgrade(s) (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Checking if PR has been edited (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Found existing branch PR (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Checking schedule(at any time, null) (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: No schedule defined (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: branchExists(renovate/svgo-loader-2.x)=true (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Branch already exists (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: getBranchPr(renovate/svgo-loader-2.x) (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: findPr(renovate/svgo-loader-2.x, null, open) (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Found PR #52 (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Skipping unsupported graphql PullRequests.mergeStateStatus query on GHE (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Skipping unsupported graphql PullRequests.mergeStateStatus query on GHE (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
 INFO: PR not found in open or closed PRs list - trying to fetch it directly (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
       "prNo": 52
DEBUG: 1 commit and no configured gitAuthor so can rebase (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
       "prNo": 52
 INFO: Manual rebase requested via PR title for #52 (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Using parentBranch: undefined (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: manager.getUpdatedPackageFiles() (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: npm.updateDependency(): dependencies.svgo-loader = ^2.0.0 (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Replacing "^1.2.1" with "^2.0.0" at index 1713 (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: bumpVersion() (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Updating packageFile content (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Updated 1 package files (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Getting updated lock files (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: lock file dirs (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
       "dirs": {
         "yarnLockDirs": [],
         "npmLockDirs": ["package-lock.json"],
         "pnpmShrinkwrapDirs": [],
         "lernaDirs": []
       }
DEBUG: Writing package.json files (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
       "packageFiles": ["package.json"]
DEBUG: Writing package-lock.json (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Writing any updated package files (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Writing package.json (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Generating package-lock.json for . (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Spawning npm install to create /renovate/tmp/renovate/github/*/*-*/package-lock.json (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)
DEBUG: Using npm: node /renovate/node_modules/npm/bin/npm-cli.js --version && node /renovate/node_modules/npm/bin/npm-cli.js install --package-lock-only --no-audit (repository=*/*-*, dependencies=svgo-loader, branch=renovate/svgo-loader-2.x)

[rarkins]

I guess the best thing we can do is programmatically defend against this by including a timeout, but you'll still get a lock file failure in the end. For some reason npm is hanging here and not returning.

[ludwigbacklund]

but you'll still get a lock file failure in the end

Hmm, why is that? If it has failed once, will it always fail again (even if it's not going to time out with the request this time)? I just want it to try again. Also is there a way to debug what npm is doing when it gets stuck?

[rarkins]

Based on your log, npm is running but not returning. Or maybe it's still running and just needs more time? I'm not sure it's caused by the rebase part itself.

Questions:

• If you kill renovate and run it again, does it always "hang" on the npm command?
• If you close the PR (make sure it's still renamed) and delete the branch and run again, do you get the same effect? In this case it's not rebasing at all and will create a new branch from master. i.e. we can rule out if it has anything to do with rebasing or not.

[ludwigbacklund]

Hmm okay so I now saw that Renovate actually renamed the PR 15 minutes after I ran it (I had gone away for a meeting at that point and my ssh timed out so I couldn't see). I tried it again with a different PR that had the same problem and it actually does finish at some point, giving me the same ETIMEDOUT error that is presented in the PR. So it seems if I can figure out why it keeps timing out then this will resolve itself automatically. I'm not sure if there's anything you could but if you wanted maybe you could force a lower timeout value somehow? 15 minutes is a bit excessive I think, but maybe there's a reason for it being so high in npm.

[rarkins]

If you copy the package.json and package-lock.json into a new folder (no node_modules) and then update one of the packages in package.json manually before running npm install, how long does it take?

[ludwigbacklund]

@rarkins I found out what the problem was with the timeouts. We use a corporate proxy here and require every outgoing request to go through it. npm takes the HTTP_PROXY and HTTPS_PROXY environment variables into account for this but those get discarded here: https://github.com/renovatebot/renovate/blob/master/lib/manager/npm/post-update/index.js#L353. If I just let it use process.env there then it doesn't lock up and doesn't get any timeouts.

Digging some more I find an exposeEnv config key: https://github.com/renovatebot/renovate/blob/master/lib/config/migration.js#L112 (that is not documented on the site?) that sets this global.trustLevel to high if set to true, so setting that to true and reverting my previous change also makes it work. Not sure what the deal is with this key but it makes it play nice with our corporate proxy so I'll be using it. Insights into this are appreciated though.

[rarkins]

@ludwigbacklund exposeEnv is the old term, which is why you see it in the migration file. You should directly configure trustLevel="high" in your bot config. Documentation here: https://renovatebot.com/docs/self-hosted-configuration/#trustlevel

Basically there are some risks to exposing all env to child processes that a repository user can influence, which is why it's opt-in.

[ludwigbacklund]

Ah, that makes sense. Thanks!

[rarkins]

Thanks for keeping me updated about what the root cause was