x/build/cmd/gerritbot: sometimes fails to close PR after its imported CL is submitted

[dmitshur]

We should investigate why gerritbot didn't close a PR that was imported into Gerrit as a CL and submitted.

• PR net/http: fix Server.ConnContext modifying context for all new connections #35751
  • imported as CL 208318

See #35751 (comment) for more details.

Thanks @odeke-em for noticing and reporting.

[dmitshur]

This seems to be happening again with PR #37328. It has been submitted on Gerrit 30 minutes ago, yet gerritbot isn't closing it.

From its logs:

2020/02/22 15:49:57 Retrieving PR golang/go#37328 from GitHub using Etag "W/\"54eea6bb1cf5f438654ec4e769f55b80\"" ...
2020/02/22 15:49:57 GitHub: 3852/5000 calls remaining; Reset in 23m32.142630856s
2020/02/22 15:49:57 Returning cached version of golang/go#37328
2020/02/22 15:49:57 Processing PR https://github.com/golang/go/pull/37328 ...
2020/02/22 15:49:57 Changes for PR golang/go#37328 have yet to be mirrored in the maintner corpus. Skipping for now.

So gerritbot thinks that the PR hasn't yet been mirrored in the maintner corpus.

But querying maintner directly, I can see that it has latest data. That PR description was never edited.

There's likely some sort of logic problem in gerritbot.

[dmitshur]

Another case affected PR #58779. It was submitted on Gerrit 5 days ago and the PR wasn't marked as closed.

It once again got stuck on Changes [...] have yet to be mirrored in the maintner corpus. Skipping for now. indefinitely:

$ kubectl logs 'gerritbot-...' | grep "Skipping for now."
[...]
2023/03/05 02:34:35 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 02:39:33 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 02:44:39 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 02:49:51 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 02:55:15 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:00:22 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:05:32 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:11:07 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:16:33 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:21:52 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:34:50 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:40:10 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:45:09 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:53:03 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 03:58:31 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:04:05 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:09:48 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:15:19 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:23:57 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:33:40 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:38:40 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:46:32 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 04:51:52 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.
2023/03/05 05:01:28 Changes for PR golang/go#58779 have yet to be mirrored in the maintner corpus. Skipping for now.

There seems to be a race. The relevant code in bot.processPullRequest is:

cl := b.importedPRs[shortLink]

if cl != nil && b.pendingCLs[shortLink] == cl.Commit.Msg {
	delete(b.pendingCLs, shortLink)
}
if b.pendingCLs[shortLink] != "" {
	log.Printf("Changes for PR %s have yet to be mirrored in the maintner corpus. Skipping for now.", shortLink)
	return nil
}

But importedPRs is cleared at the start of each checkPullRequests iteration, and populated only with open CLs (from maintner corpus). The race seems to be that if a CL is submitted and maintner syncs that after pendingCLs has a chance to be cleared but before importedPRs is populated, then delete(b.pendingCLs, shortLink) will never run and the closePR never has a chance of being called.

There are many ways this problem can be fixed. I'll just note that GerritBot clearly knows when an imported CL becomes submitted (or closed) given that it stops showing up in maintner's ForeachOpenCL loop—if only it weren't so quick to discard what was in the previous iteration's importedPRs map...