Renovate: Empty lockfile maintenance PR

[ikatyang]

It seems something wrong with lockfile maintenance PR, renovate created PR even if there's no diff, see https://github.com/ikatyang/jest-playback/pull/48, or this is for showing that renovate had checked it? If so, it'd be better to have an option to configure this behavior.

[rarkins]

@ikatyang thanks for the bug report, and sorry for the inconvenience!

1. The empty lockfile maintenance PR shouldn't be happening and is a bug
2. I think the autoclosing perhaps was when you updated your shareable config to disable lock file maintenance. Renovate always tries to "clean up" any old branches that shouldn't be there.

[rarkins]

@ikatyang am I seeing correctly that this repository doesn't have a lockfile?

[ikatyang]

There is the lockfile, you might have to close the hide-files-on-github chrome extension I think. 😅

[rarkins]

I just installed that extension yesterday :-/

[ikatyang]

I just saw it in your star list 😎

[rarkins]

Strangely, I can't reproduce this. I see this in the logs as I'd expect:

DEBUG: Yarn lock file does not need updating (repository=renovate-tests/jest-playback, packageFile=package.json)
DEBUG: No files to commit (repository=renovate-tests/jest-playback, branch=renovate/lock-file-maintenance)

I've modified the preset config in my fork of your repo as necessary, but I don't think it should have made any different. There's a chance that this was fixed by the fix for #708 but I am not sure why that would be.

[ikatyang]

It's strange indeed, and it is not the only one case I've seen, there is also the same thing in https://github.com/ikatyang/tslint-config-prettier-ext/pull/30 and https://github.com/ikatyang/tsconfig-extends/pull/32.

Maybe it's really fixed by your fix for #708 somehow?

[ikatyang]

Is it possible that's caused my not-pending lockfile maintenance branch created last week (I remembered some of them somehow does not raise the PR) and I changed it to immediate yesterday...

[rarkins]

Unlikely. The problem starts when the branch is created, while prCreation is evaluated later

[rarkins]

Setting status to "blocked" until we can work out how to reproduce.

[ikatyang]

Two more example this morning: https://github.com/ikatyang/jest-playback/pull/53 and https://github.com/ikatyang/generator-ts-jest/pull/34, still don't know why.

And the schedule contains on Mondays seems should be on Monday, I'll make a PR to renovate-config-schedule.

[rarkins]

Did you do anything to help the bot close it or did it create and close without any changes to config?

[ikatyang]

I just woke up and it's already happened (06:21~07:20 GMT+8), and I changed my config after it's already done (07:53 GMT+8).

[rarkins]

Sorry about that. I have changed my server settings to keep debug logs indefinitely so for any future problems I hopefully still have a record.

[rarkins]

I'm a little confused by the timing too. GitHub is reporting the commit happened around 6 hours ago and the delete happened about 5 hours ago. this sounds like around the time or just before you woke up i.e. well after 5am.

[rarkins]

I just realised that I also enabled log files at debug level! To start with, here are the hits for matches in the last 3 days:

$ grep "ikatyang/jest-playback" 2017082*.log | grep "Matches schedule"
20170821-000056.log:{"name":"renovate","hostname":"renovate-prod","pid":361,"repository":"ikatyang/jest-playback","branch":"renovate/lock-file-maintenance","level":20,"msg":"Matches schedule before 5am on monday","time":"2017-08-21T00:28:16.696Z","v":0}
20170821-010117.log:{"name":"renovate","hostname":"renovate-prod","pid":3021,"repository":"ikatyang/jest-playback","branch":"renovate/lock-file-maintenance","level":20,"msg":"Matches schedule before 5am on monday","time":"2017-08-21T01:29:31.545Z","v":0}
20170821-020053.log:{"name":"renovate","hostname":"renovate-prod","pid":5607,"repository":"ikatyang/jest-playback","branch":"renovate/lock-file-maintenance","level":20,"msg":"Matches schedule before 5am on monday","time":"2017-08-21T02:27:59.765Z","v":0}
20170821-030052.log:{"name":"renovate","hostname":"renovate-prod","pid":8182,"repository":"ikatyang/jest-playback","branch":"renovate/lock-file-maintenance","level":20,"msg":"Matches schedule before 5am on monday","time":"2017-08-21T03:26:57.175Z","v":0}
20170821-040117.log:{"name":"renovate","hostname":"renovate-prod","pid":10768,"repository":"ikatyang/jest-playback","branch":"renovate/lock-file-maintenance","level":20,"msg":"Matches schedule before 5am on monday","time":"2017-08-21T04:27:35.381Z","v":0}
20170821-220123.log:{"name":"renovate","hostname":"renovate-prod","pid":8287,"repository":"ikatyang/jest-playback","branch":"renovate/@types/glob-5.x","level":20,"msg":"Matches schedule before 8am","time":"2017-08-21T22:20:47.305Z","v":0}
20170821-220123.log:{"name":"renovate","hostname":"renovate-prod","pid":8287,"repository":"ikatyang/jest-playback","branch":"renovate/@types/lodash-4.x","level":20,"msg":"Matches schedule before 8am","time":"2017-08-21T22:20:57.916Z","v":0}
20170821-220123.log:{"name":"renovate","hostname":"renovate-prod","pid":8287,"repository":"ikatyang/jest-playback","branch":"renovate/@types/request-2.x","level":20,"msg":"Matches schedule before 8am","time":"2017-08-21T22:21:08.592Z","v":0}
20170821-230125.log:{"name":"renovate","hostname":"renovate-prod","pid":10167,"repository":"ikatyang/jest-playback","branch":"renovate/@types/glob-5.x","level":20,"msg":"Matches schedule before 8am","time":"2017-08-21T23:19:50.564Z","v":0}
20170821-230125.log:{"name":"renovate","hostname":"renovate-prod","pid":10167,"repository":"ikatyang/jest-playback","branch":"renovate/@types/lodash-4.x","level":20,"msg":"Matches schedule before 8am","time":"2017-08-21T23:19:55.553Z","v":0}
20170821-230125.log:{"name":"renovate","hostname":"renovate-prod","pid":10167,"repository":"ikatyang/jest-playback","branch":"renovate/@types/request-2.x","level":20,"msg":"Matches schedule before 8am","time":"2017-08-21T23:20:07.683Z","v":0}

The first 5 are for lock file maintenance. Seems to make sense that there are 5, and the times are in UTC so they also make sense because this was before I fixed the cascading timezone bug.

The remaining ones are non-lockfile ones and "before 8am", they go up until midnight UTC which also makes sense as your timezone is UTC+8.

So this does not answer why there was a lock file branch created today.

[rarkins]

I found the run where PR#53 was created. It has this, "msg":"Failed to parse schedule \"before 8am on Mondays\"

i.e. reason why it ran at all was because of faulty schedule.

Now why did it commit 0 files? Here's an extract of the logs:

{"msg":"hasGroupName: true","time":"2017-08-21T22:20:47.303Z"}
{"msg":"groupEligible: false","time":"2017-08-21T22:20:47.303Z"}
{"msg":"useGroupSettings: false","time":"2017-08-21T22:20:47.303Z"}
{"msg":"Compiling branchName and prTitle","time":"2017-08-21T22:20:47.303Z"}
{"msg":"Upgrade has semantic commits enabled","time":"2017-08-21T22:20:47.304Z"}
{"msg":"renovate/lock-file-maintenance, chore(deps): lock file maintenance","time":"2017-08-21T22:20:47.304Z"}
{"schedule":["before 8am on Mondays"],"msg":"Checking schedule","time":"2017-08-21T22:21:20.333Z"}
{"msg":"Failed to parse schedule \"before 8am on Mondays\"","time":"2017-08-21T22:21:20.333Z"}
{"msg":"Branch has 1 upgrade(s): ","time":"2017-08-21T22:21:20.333Z"}
{"msg":"Checking if branch exists: renovate/lock-file-maintenance","time":"2017-08-21T22:21:20.333Z"}
{"msg":"Branch needs creating","time":"2017-08-21T22:21:20.447Z"}
{"msg":"branch lockFileMaintenance","time":"2017-08-21T22:21:20.447Z"}
{"msg":"1 file(s) to commit","time":"2017-08-21T22:21:26.130Z"}
{"msg":"commitFilesToBranch('renovate/lock-file-maintenance', files, message, 'master)'","time":"2017-08-21T22:21:26.130Z"}
{"msg":"Checking if branch exists: renovate/lock-file-maintenance","time":"2017-08-21T22:21:27.511Z"}
{"msg":"Checking if branch exists: renovate/lock-file-maintenance","time":"2017-08-21T22:21:28.253Z"}
{"msg":"getBranchStatus(renovate/lock-file-maintenance)","time":"2017-08-21T22:21:28.915Z"}
{"msg":"getChangeLogJSON(undefined, undefined, undefined)","time":"2017-08-21T22:21:29.245Z"}
{"msg":"getBranchPr(renovate/lock-file-maintenance)","time":"2017-08-21T22:21:29.251Z"}
{"msg":"Creating PR for branch renovate/lock-file-maintenance","time":"2017-08-21T22:21:29.398Z"}
{"msg":"Skipping assignees and reviewers as automerge=true","time":"2017-08-21T22:21:29.915Z"}
{"msg":"Created Pull Request #53","time":"2017-08-21T22:21:29.915Z"}
{"msg":"Checking #53 for automerge","time":"2017-08-21T22:21:29.915Z"}
{"msg":"PR is configured for automerge","time":"2017-08-21T22:21:29.915Z"}
{"msg":"PR is not mergeable","time":"2017-08-21T22:21:29.915Z"}
{"msg":"branchList=renovate/@types/glob-5.x,renovate/@types/lodash-4.x,renovate/@types/request-2.x,renovate/lock-file-maintenance","time":"2017-08-21T22:21:29.915Z"}
{"msg":"renovateBranches=renovate/lock-file-maintenance,renovate/@types/glob-5.x,renovate/@types/lodash-4.x,renovate/@types/request-2.x","time":"2017-08-21T22:21:30.159Z"}
{"msg":"getBranchPr(renovate/lock-file-maintenance)","time":"2017-08-21T22:21:30.159Z"}

This part is strange: "msg":"1 file(s) to commit"

[rarkins]

Additional log:

{"packageFile":"package.json","level":20,"msg":"Yarn lock needs updating","time":"2017-08-21T22:21:26.130Z"}
{"branch":"renovate/lock-file-maintenance","level":20,"msg":"1 file(s) to commit","time":"2017-08-21T22:21:26.130Z"}

Important: Yarn lock needs updating

From this code:

  if (existingYarnLock.toString() === newYarnLock.contents.toString()) {
    logger.debug('Yarn lock file does not need updating');
    return null;
  }
  logger.debug('Yarn lock needs updating');
  return newYarnLock;

So it seems the branch was created because (a) schedule was invalid so ignored, and (b) Renovate though the new lock file was not equal to old one.

[rarkins]

And it was closed on the following run because of this:

https://github.com/singapore/renovate/blob/134065c7c797c35847968aa04248a1283884be4e/lib/workers/repository/cleanup.js#L36-L42

if (pr && pr.changed_files === 0) {
      logger.info(
        'Deleting lock file maintenance branch as it has no changed files'
      );
      await config.api.deleteBranch(
        `${config.branchPrefix}lock-file-maintenance`
      );
    }

I half forget when I added that code but it wasn't with the expectation that empty lock file PRs would keep getting created. They need to get stopped at the source.

[ikatyang]

It seems the empty commit was caused by rebasing? The PR was created at 06:21 GMT+8 and the commit was 07:20 GMT+8, but how could rebasing cause that, really strange..

[rarkins]

My suspicion is it could be caused by separate line endings. Renovate thinks the files don't match with === but once the file is committed to GitHub, it thinks there's no change. One way this can happen is if the line endings were different, because GitHub automatically translates.

[ikatyang]

It's impossible for my repos, I always set eol=lf in .gitattributes, or did I misunderstand the meaning of it? I'm always in the LF environment, not sure what behavior will it be in Renovate's environment.

[rarkins]

In that case, it would be very strange if it's the cause. What's also really strange is that when I fork your jest-playback repo and run a lock file maintenance update, it tells me the lock file doesn't need updating. i.e. it's not like the check is completely wrong.. but somehow it goes "wrong" of your repos. BTW I think I saw it one other time on another user's repo so this is probably a wide problem (he saw multiple create/delete yarn lock files each monday).

[rarkins]

@ikatyang I think I have fixed this one during #736. While working on it I was able to reproduce the same problem and found it was due to a string being compared to a Buffer.

[ikatyang]

I believe that one had fixed, but it appears another kind of empty PR this morning 😅, it somehow downgrade my denpendency and then upgrade it, cause an empty PR and then close it immediately. Since this issue's name is empty PR, I think there's no need to open an new issue?

And it'd better to show some renovate information (e.g. version, config) on every PR to ensure it's before/after the bugfix or it's a config issue.

[rarkins]

I think this is a different problem, but we may as well keep discussing it in this issue. How recently did you update tslint-config-ikatyang?

It looks like yarn install decided that v2.2.0 was the latest the first time it ran, and then the next run it found v2.3.0, and then because no files had changed it closed it itself. So the question is - not sure how renovate can be at fault - why did yarn install find v2.2.0 and not v2.3.0 the first time?

[ikatyang]

v2.3.0 - 2017-08-27 10:49 GMT+8

renovate schedule: 00:00-08:00 GMT+8

Yeah, that's weird, it looks like there's no chance to pick up the wrong latest version, but somehow it decided v2.3.0 v2.2.0 is the latest. 😅

[rarkins]

I previously saw that yarn was "flip flopping" versions in my yarn.lock but I thought they'd fixed that with 0.27.x because I hadn't seen it again. I would normally say "no way this can be a Renovate problem" however considering that we've had some similar types of problems before I can't be so sure anymore. We can leave this open but I can't think how to attempt to "fix" so we just have to watch it. It could be a yarn cache problem however I'd prefer not to delete cache on every run as that would increase the download/processing load.

[ikatyang]

Another question: I'm not sure how lock file maintenance works, but isn't it shouldn't affect the versions in package.json? It should only affect yarn.lock, maybe we can add some checks for that?

EDIT: sorry it's yarn.lock, my eye...

[rarkins]

Yes it only touches the yarn.lock files and not package.json. But even if we know that package should be 2.3.0 because package.json, it would be a lot of work to try to "verify" of yarn lock is correct by using that type of logic.

[rarkins]

I have an idea for why this happened. Can you check what time that new package was committed to master on the same repos? If it was committed to master in the same run as the lock file maintenance then the lock file branch would have been basing off the old master package json content. This is an "edge case" I've been meaning to document and fix that is not directly related to lock files but could result in this problem.

In short: package json content is cached per-run and so if an earlier branch is automerged to master then later branches will be based off the outdated package file.

[rarkins]

Created #750

[ikatyang]

• chore(deps): update dependency tslint-config-ikatyang to v2.3.0
  
  
  
  • [12:37 AM] chore(deps): update dependency tslint-config-ikatyang to v2.3.0
  
  
  • [01:36 AM] merged
  
  
• chore(deps): lock file maintenance
  
  
  
  • [01:37 AM] chore(deps): update lock file
  
  
  • [02:36 AM] chore(deps): update lock file
  
  
  • [02:36 AM] closed
  
  

[rarkins]

Ok will close this again and work on #750