Renovate: lockfiles not being updated

Created on 30 Oct 2020 · 54Comments · Source: renovatebot/renovate

Which Renovate are you using?

WhiteSource Renovate App

Which platform are you using?

GitHub.com

Have you checked the logs? Don't forget to include them if relevant

https://app.renovatebot.com/dashboard#github/taskcluster/taskcluster/253559885

What would you like to do?

This PR changed only package.json and not yarn.lock, causing errors from yarn install --frozen-lockfile. This started sometime yesterday.

npm priority-2-important bug

Source

djmitche

All 54 comments

@djmitche can you paste the logs here, as we are not allowed to see your renovate logs by default

viceice on 30 Oct 2020

There's nothing interesting there

djmitche on 30 Oct 2020

And, I can't figure out how to copy them all..

djmitche on 30 Oct 2020

Ah, here we go -- https://gist.github.com/djmitche/21c13d80c5f4bdcd5b632f3a29d32d09

djmitche on 30 Oct 2020

Possibly related, I've seen a few PRs that revert other repo changes, like

https://github.com/taskcluster/taskcluster/pull/3745/files

djmitche on 30 Oct 2020

i see, there is something going really wrong. @rarkins can you have a look?

viceice on 30 Oct 2020

~I'm not sure it we support renovate config in package,json?~ Yes we support

https://github.com/taskcluster/taskcluster/blob/d4a168feeaaf7f58ea78134b9362ee01bdd884be/package.json#L204

{
    "extends": [
      "config:base"
    ],
    "dependencyDashboard": true,
    "rebaseConflictedPrs": false,
    "prHourlyLimit": 0,
    "prConcurrentLimit": 9,
    "rangeStrategy": "update-lockfile",
    "semanticCommits": "disabled",
    "packageRules": [
      {
        "packagePatterns": [
          "^aws-sdk$",
          "^golang.org/x/.*"
        ],
        "schedule": [
          "after 9pm on sunday"
        ]
      },
      {
        "updateTypes": [
          "major"
        ],
        "prPriority": 1
      }
    ],
    "enabledManagers": [
      "npm",
      "gomod"
    ],
    "postUpdateOptions": [
      "gomodTidy"
    ]
  }

viceice on 30 Oct 2020

"rebaseConflictedPrs": false, should be "rebaseWhen": "never", but that can'tz be the cause for the issue

viceice on 30 Oct 2020

I suspect the fork has got out of sync somehow. https://github.com/renovate-bot/taskcluster

rarkins on 30 Oct 2020

Troubleshooting https://github.com/renovate-bot/taskcluster/commit/4c647c366e76b3fd652e24c71e08e03590d0bace

The package.json version was updated within the past 24 hours: https://github.com/taskcluster/taskcluster/commit/b49cb60334986bc16e339d88e7cd77aa1c83d40e

It was updated 8 days ago: https://github.com/taskcluster/taskcluster/commit/a6f46eb1713121460f91ee9e16dfed5c76e2c3ad

@djmitche I noticed recently that Renovate struggles to complete a job for this repo within our 50 minute timeout, due to the number of concurrent PRs being open plus an unfortunately side effect of update-lockfile which means Renovate runs yarn on every open branch every run to double check that the branch is fully updated.

Is it ok with you to try the following?

Reduce prConcurrentLimit to as low as you're willing: https://github.com/renovate-bot/taskcluster/blob/d4a168feeaaf7f58ea78134b9362ee01bdd884be/package.json#L211
Try to refrain from using the dashboard to open too many PRs at once until we have finished work optimizing update-lockfile behavior (Cc @zharinov)
Rename then close then delete the branch of as many of the current PRs as possible, especially the ones that are wrong. I can delete the branches directly from the bot's account if need be, which will result in GitHub closing the PRs automatically. They can then be renamed afterwards so that they don't count as blocking.

rarkins on 30 Oct 2020

Actually, it seems to have been completing much more jobs in recent days and much faster than when I looked a week or so ago:

rarkins on 30 Oct 2020

@djmitche can we experiment with seeing if a simple rebase request on one of the wrong PRs produces a better result?

rarkins on 30 Oct 2020

I suspect the rest of the team will be OK with fewer concurrent PRs, and keep my hands off the dashboard. I've been pushing to "catch up" but for no particularly good reason.

It does not appear that I can close the branches. Here's the PRs I've closed:

djmitche on 30 Oct 2020

@djmitche in that case I'll log in using the bot's credentials and close those manually for now

rarkins on 30 Oct 2020

I did try rebasing one yesterday and it went from the no-yarn.lock-update state to reverting-other-changes.

djmitche on 30 Oct 2020

I've cleaned up those branches, this should see Renovate be able to complete each run much faster from now on. Now.. we hope it doesn't do anything wrong.

You have a neutrino monorepo PR open that's been edited, so that should leave space for one more.

There's a job started at 2020-10-30 13:36:14.720528+00, although the repo is now changed since that one so it may abort once if it realises that change.

rarkins on 30 Oct 2020

Thanks! I'll check back soon :)

If converting to the non-forking version would help, we could do that -- we no longer continuously deploy, so it's a bit safer for us to have automation pushing changes to the repo.

djmitche on 30 Oct 2020

In theory it should not make a difference. In practice the fork mode sync'ing is partial witch-craft (kind of a cousin to this amusing prank), so you are likely to see less problems with the non-forking mode if it's OK with you to use.

rarkins on 30 Oct 2020

I haven't seen any runs since the run 12h ago

djmitche on 30 Oct 2020

See your dependency dashboard

There is also a checkbox to force a run

viceice on 30 Oct 2020

That lerna error has come up over the past week or two, despite our not having changed anything with lerna (we barely use it). It's also just a warning, right?

I kind of don't understand how renovate decides to make a run for a repo, to be honest.

djmitche on 30 Oct 2020

It seems somehow the jobs are still not completing, so I'll need to debug. Renovate queues jobs hourly although doesn't always drain the queue if there's lots of PRs needing creating (e.g. a popular package releases).

rarkins on 30 Oct 2020

There's a job in progress since 4 minutes ago btw

rarkins on 30 Oct 2020

And actually a job completed before that, created this PR which looks right: https://github.com/taskcluster/taskcluster/pull/3824/files

rarkins on 30 Oct 2020

The job took only 7 minutes, which seems about right (updating a single lock file takes ~5 minutes).

The dashboard looks correct too (no warning anymore).

Now that the 2 concurrent PRs has been reached, I wouldn't expect any changes between runs unless you use the dashboard to open any extras.

rarkins on 30 Oct 2020

Cool, thanks! I think that "4 minutes ago" was when I clicked the checkbox.

djmitche on 30 Oct 2020

And for some reason that job is still running, ~15 minutes later! Argh

rarkins on 30 Oct 2020

😕1

Sorry we are such a PITA :(

djmitche on 30 Oct 2020

Nah, it should just work.. I hope to get to the bottom of it

rarkins on 30 Oct 2020

OK, I discovered one problem: taskcluster/taskcluster is showing up as uninstalled. This is why scheduled runs aren't occurring although it seems ones triggered by npm packages getting update do, because that event doesn't check the installed flag before enqueuing a job. I think there's a conflict in our backend logic because the same org is in both renovate and forking-renovate (although each repo is only in one, from what I can tell).

rarkins on 31 Oct 2020

OK this is more like it:

Hourly, ~10 minutes per run

rarkins on 1 Nov 2020

@djmitche I think if you increase the number of concurrent PRs either through config or on-demand then you'll probably see ~5 minute per PR increase. Up to 5 open at a time should hopefully be ok until we can optimize update-lockfile to not run Yarn every time.

rarkins on 1 Nov 2020

Sounds good. Does that time apply to already-created PRs, too? We're into the major version bumps and some are just "hard". Typically we've left these open and then forced another (easier) update to keep momentum going, but maybe we should find another approach?

djmitche on 1 Nov 2020

Yes, the 5 minutes per branch applies regardless of update type. My own approach is to keep major updates requiring dashboard approval and open them once I think we have time to work on them if they need code changes in order to pass. Renovate will also always try to propose "easier" PRs first, e.g. pin -> patch -> minor -> major, so you hopefully don't get a logjam.

Just to recap:

Inconsistent scheduling: fixed, once I found the SQL query that was making the forking renovate installation as uninstalled sometimes (it was added once we found a bug in GitHub where repos would have duplicate installations, and wasn't intended to forbid both apps at the same time)
slow execution time: worked around for now by reducing the number of open branches. needs a medium-complexity feature added to Renovate to cache enough info about branches that we can skip yarn commands if lockfile was already updated to the expected value
"wrong" PR: not sure of this. Possibly was bad luck or a race condition due to the forking magic, and failed to clean itself up due to the problems. We need to watch for this happening again

rarkins on 1 Nov 2020

Thanks for the summary! We're now seeing two open PRs as expected. Two other unexpected things, though:

those PRs are being force-pushed about once every 2 hours. taskcluster/taskcluster#3827 is an example. [edit:] It appears to be pushing the same diff every time, e.g., https://github.com/taskcluster/taskcluster/commit/b7d5c5d05826c4664f4c1dd82683bf6a428be69b and https://github.com/taskcluster/taskcluster/commit/d00195115cc7f61ec9a8cd982bfc707e4748bfad.
a bunch of merged PRs, such as taskcluster/taskcluster#3771, are listed as "ignored or blocked". I renamed these to see what happens -- maybe this is just a cosmetic issue.

djmitche on 2 Nov 2020

Thanks for the summary! We're now seeing two open PRs as expected. Two other unexpected things, though:

those PRs are being force-pushed about once every 2 hours. taskcluster/taskcluster#3827 is an example. [edit:] It appears to be pushing the same diff every time, e.g., taskcluster/taskcluster@b7d5c5d and taskcluster/taskcluster@d001951.

can you provide the logs for the force pushed commits?

a bunch of merged PRs, such as taskcluster/taskcluster#3771, are listed as "ignored or blocked". I renamed these to see what happens -- maybe this is just a cosmetic issue.

The ignored pr should be auto removed from dashboard by renovate when you rename the pr (eg add - bug). Maybe your prefix is ignored by renovate, so it thinks it's closed / blocked

viceice on 2 Nov 2020

https://gist.github.com/djmitche/280d03975f78c15c2e4c20ef929341f2 generated taskcluster/taskcluster@b7d5c5d.

The ignored pr should be auto removed from dashboard by renovate when you rename the pr (eg add - bug). Maybe your prefix is ignored by renovate, so it thinks it's closed / blocked

The question was, why was it "ignoring" a merged PR?

djmitche on 2 Nov 2020

If you already merged a PR, but then need the update again, renovate assumes it's because you rolled back and don't want to be pestered again by the same version. Ticking the dashboard checkbox should override that assumption.

rarkins on 2 Nov 2020

Strange, no lockfile update generated https://gist.github.com/djmitche/280d03975f78c15c2e4c20ef929341f2#file-gistfile1-txt-L7606

If you already merged a PR, but then need the update again, renovate assumes it's because you rolled back and don't want to be pestered again by the same version. Ticking the dashboard checkbox should override that assumption.

But the pr was already renamed. 🤔

hit by docker egrs restriction? https://github.com/taskcluster/taskcluster/pull/3827#issuecomment-720527941

viceice on 2 Nov 2020

That definitely looks like the Docker Hubapocalypse

rarkins on 2 Nov 2020

Let's deal with Docker Hub in the main repo

rarkins on 2 Nov 2020

Here's another example of a fresh PR without a lockfile update:

djmitche on 3 Nov 2020

Did that log indicate anything error with the yarn output?

rarkins on 3 Nov 2020

Seeing the same here. For that PR:

cmd:

docker run --rm --name=renovate_node --label=renovate_child -v "/mnt/renovate/gh/taskcluster/taskcluster":"/mnt/renovate/gh/taskcluster/taskcluster" -v "/tmp/renovate-cache":"/tmp/renovate-cache" -v "/home/ubuntu/.npmrc":"/home/ubuntu/.npmrc" -e NPM_CONFIG_CACHE -e npm_config_store -w "/mnt/renovate/gh/taskcluster/taskcluster" docker.io/renovate/node:12.19.0 bash -l -c "npm i -g yarn@'^1.22.10' && sed -i 's/ steps,/ steps.slice(0,1),/' /home/ubuntu/.npm-global/lib/node_modules/yarn/lib/cli.js && npm i -g lerna@latest && yarn install --ignore-scripts --ignore-engines --ignore-platform && lerna bootstrap --no-ci --ignore-scripts -- --ignore-scripts --ignore-engines --ignore-platform

stdout:

> [email protected] preinstall /home/ubuntu/.npm-global/lib/node_modules/yarn
> :; (node ./preinstall.js > /dev/null 2>&1 || true)

/home/ubuntu/.npm-global/bin/yarn -> /home/ubuntu/.npm-global/lib/node_modules/yarn/bin/yarn.js
/home/ubuntu/.npm-global/bin/yarnpkg -> /home/ubuntu/.npm-global/lib/node_modules/yarn/bin/yarn.js
+ [email protected]
added 1 package in 1.595s
/home/ubuntu/.npm-global/bin/lerna -> /home/ubuntu/.npm-global/lib/node_modules/lerna/cli.js
+ [email protected]
added 753 packages from 387 contributors in 60.585s
yarn install v1.22.10
[1/4] Resolving packages...
[2/4] Fetching packages...
[3/4] Linking dependencies...
[4/4] Building fresh packages...
success Saved lockfile.
Done in 125.24s.
yarn install v1.22.10
[1/4] Resolving packages...
success Already up-to-date.
Done in 2.86s.

stderr:

npm WARN deprecated [email protected]: Please see https://github.com/lydell/urix#deprecated
npm WARN deprecated [email protected]: https://github.com/lydell/resolve-url#deprecated
npm WARN deprecated [email protected]: request has been deprecated, see https://github.com/request/request/issues/3142
npm WARN deprecated [email protected]: this library is no longer supported
npm WARN deprecated [email protected]: This package is broken and no longer maintained. 'mkdirp' itself supports promises now, please switch to that.
npm WARN @octokit/[email protected] requires a peer of @octokit/core@>=3 but none is installed. You must install peer dependencies yourself.

warning "newrelic > @grpc/[email protected]" has unmet peer dependency "[email protected] || 6.x".
warning Ignored scripts due to flag.
lerna notice cli v3.22.1
lerna info bootstrap root only

The next few log entries are

{"level":20,"branch":"renovate/email-templates-7.x","msg":"No updated lock files in branch","time":"2020-11-03T23:09:02.818Z"}
{"level":20,"branch":"renovate/email-templates-7.x","msg":"1 file(s) to commit","time":"2020-11-03T23:09:02.819Z"}

Is lerna confusing things here? I suspect we could just rm lerna.json and not lose any functionality.

djmitche on 4 Nov 2020

Did you tried to run yarn install and lerna bootstrap locally? Can you reproduce it locally?

viceice on 4 Nov 2020

The good news (I think) is that branch seems correct now:
https://github.com/taskcluster/taskcluster/pull/3849/files

The bad news is that Renovate seems to be force pushing to it ~hourly:

The last commit seems to be from a wrong state (no lock file update) to the one you see which is correct (includes lock file update). Nothing has changed on Renovate's code in that time.

Here's the diff: https://www.diffchecker.com/SDbQJjGI

The second time it needed to download renovate/node, but that worked.. and besides the second one is the working one. Otherwise it seems to be practically the same except for not detecting changes or not.

rarkins on 4 Nov 2020

My best guess right now is that this is a rangeStrategy=update-lockfile bug when new version does not satisfy the existing range:

We reuse the existing branch
We mark the package file as updated even if it's not.. because we want to trigger the lock file update
The lock file command runs in the same/existing branch, so thinks nothing has changed in the lock file
We push the package file update only to the branch, which removes the lock file update

And then this repeats.. one run losing the update, another getting it back.. etc. Probably independent of lerna. I'll try to reproduce it with a single dependency in a repo.

rarkins on 4 Nov 2020

I can reproduce in a simple repo and have a fix

rarkins on 4 Nov 2020

@rarkins can this happen to other managers too? or is this specific to npm?

viceice on 4 Nov 2020

Yes, I think it could be any. But only happens when the package file needs changing while rangeStrategy=update-lockfile.

rarkins on 4 Nov 2020

Thanks! This has definitely been intermittent..

djmitche on 4 Nov 2020

:tada: This issue has been resolved in version 23.70.1 :tada:

The release is available on: