Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

x/build/cmd/gopherbot: created multiple backport issues (and now offline) #25031

Closed
FiloSottile opened this issue Apr 23, 2018 · 11 comments
Closed

x/build/cmd/gopherbot: created multiple backport issues (and now offline) #25031

FiloSottile opened this issue Apr 23, 2018 · 11 comments
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge
Milestone
Unreleased

Comments

@FiloSottile
Copy link
Contributor

@gopherbot created multiple backport issues at #23920 (comment).

While some lag is expected for the "done" comment to reach the corpus, it should not have created duplicated issues anyway.

gopherbot is offline while this is being fixed.
@gopherbot gopherbot added this to the Unreleased milestone Apr 23, 2018
@gopherbot gopherbot added the Builders x/build issues (builders, bots, dashboards) label Apr 23, 2018
@FiloSottile
Copy link
Contributor Author

Now it's really offline.

@FiloSottile FiloSottile self-assigned this Apr 23, 2018
@FiloSottile
Copy link
Contributor Author

FiloSottile commented Apr 23, 2018 •
edited

Timeline:

  • 22:56:24 the first issue is created
  • 22:57:06 the second issue is created
  • 22:57:08 "Backport issue(s) created" comment reaches the corpus
E  2018/04/23 22:56:21 Updating data from log *maintner.netMutSource ...
E  2018/04/23 22:56:22 Downloading 110 bytes of https://maintner.golang.org/logs/35 ...
E  2018/04/23 22:56:22 wrote /cache/golang-maintner/0035.growing.mutlog
E  2018/04/23 22:56:23 Reloaded data from log *maintner.netMutSource.
E  2018/04/23 22:56:23 got corpus update after 1.1626916s
I  open-backport-issue-1.10
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
I  open-backport-issue-1.9
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
E  2018/04/23 22:56:25 gopherbot ran in 2.514644276s
E  2018/04/23 22:56:25 Updating data from log *maintner.netMutSource ...
E  2018/04/23 22:56:25 Downloading 411 bytes of https://maintner.golang.org/logs/35 ...
E  2018/04/23 22:56:25 wrote /cache/golang-maintner/0035.growing.mutlog
E  2018/04/23 22:56:25 Reloaded data from log *maintner.netMutSource.
E  2018/04/23 22:56:25 got corpus update after 76.778857ms
I  open-backport-issue-1.10
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
I  open-backport-issue-1.9
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
E  2018/04/23 22:56:26 gopherbot ran in 945.286333ms
E  2018/04/23 22:56:26 Updating data from log *maintner.netMutSource ...
E  2018/04/23 22:56:26 Downloading 42 bytes of https://maintner.golang.org/logs/35 ...
E  2018/04/23 22:56:26 wrote /cache/golang-maintner/0035.growing.mutlog
E  2018/04/23 22:56:26 Reloaded data from log *maintner.netMutSource.
E  2018/04/23 22:56:26 got corpus update after 284.062807ms
I  open-backport-issue-1.10
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
I  open-backport-issue-1.9
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
E  2018/04/23 22:56:27 gopherbot ran in 765.333821ms
E  2018/04/23 22:56:27 Updating data from log *maintner.netMutSource ...
E  2018/04/23 22:56:27 Downloading 277 bytes of https://maintner.golang.org/logs/35 ...
E  2018/04/23 22:56:27 wrote /cache/golang-maintner/0035.growing.mutlog
E  2018/04/23 22:56:27 Reloaded data from log *maintner.netMutSource.
E  2018/04/23 22:56:27 got corpus update after 79.952719ms
I  open-backport-issue-1.10
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
I  open-backport-issue-1.9
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
E  2018/04/23 22:56:32 gopherbot ran in 4.483157875s
E  2018/04/23 22:56:32 Updating data from log *maintner.netMutSource ...
E  2018/04/23 22:57:06 Downloading 129 bytes of https://maintner.golang.org/logs/35 ...
E  2018/04/23 22:57:06 wrote /cache/golang-maintner/0035.growing.mutlog
E  2018/04/23 22:57:06 Reloaded data from log *maintner.netMutSource.
E  2018/04/23 22:57:06 got corpus update after 34.035469826s
I  open-backport-issue-1.10
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
I  open-backport-issue-1.9
I  	https://golang.org/issue/23920  cmd/test2json: misparses subtest names with : in them
E  2018/04/23 22:57:08 gopherbot ran in 1.798463405s
E  2018/04/23 22:57:08 Updating data from log *maintner.netMutSource ...
E  2018/04/23 22:57:08 Downloading 674 bytes of https://maintner.golang.org/logs/35 ...
E  2018/04/23 22:57:08 wrote /cache/golang-maintner/0035.growing.mutlog
E  2018/04/23 22:57:08 Reloaded data from log *maintner.netMutSource.
E  2018/04/23 22:57:08 got corpus update after 81.447334ms
E  2018/04/23 22:57:09 gopherbot ran in 1.051588406s
E  2018/04/23 22:57:09 Updating data from log *maintner.netMutSource ...
E  2018/04/23 22:57:09 Downloading 425 bytes of https://maintner.golang.org/logs/35 ...
E  2018/04/23 22:57:09 wrote /cache/golang-maintner/0035.growing.mutlog
E  2018/04/23 22:57:09 Reloaded data from log *maintner.netMutSource.
E  2018/04/23 22:57:09 got corpus update after 78.918721ms
E  2018/04/23 22:57:09 gopherbot ran in 570.380313ms

@FiloSottile
Copy link
Contributor Author

Between the first and second issue being opened there were multiple cycles that didn't open an issue. My hypothesis is that an event updating an issue in the corpus at time > X arrived before the creation of the issue at time X in maintner. So the since parameter was moved past the issue creation date, disabling the live GitHub API check.

https://github.com/golang/build/blob/58ba60d65fdebb279bcf7990e5b51beeb62e5b89/cmd/gopherbot/gopherbot.go#L358

Either that, or the GitHub API showed an inconsistent rollbacked view, which would be much harder to fix.

/cc @bradfitz about events arriving out of order in maintner.

@FiloSottile
Copy link
Contributor Author

Deploying 4c90f83a585e99d6c4442b6117e77d06a1a6f6d4 pending merge to bring @gopherbot back online.

@gopherbot
Copy link

Change https://golang.org/cl/108977 mentions this issue: cmd/gopherbot: add safety buffer to createGitHubIssue deduplication

@FiloSottile
Copy link
Contributor Author

Deploying 31e3e5b991e909e2bf818bc6f1574aff9272c1e9 because 4c90f83 wasn't rebased on top of the #25024 fix.

@FiloSottile
Copy link
Contributor Author

It should be possible to check my hypothesis by looking at the maintner log, assuming it is append-only. If there is an event that sets a issue Updated field to >= 22:56:24 (#25028 creation time), and it appears before the event that makes #25028 visible, we found the issue.

@bradfitz
Copy link
Contributor

It's an append-only log.

@FiloSottile FiloSottile mentioned this issue Apr 25, 2018
Open
@FiloSottile
Copy link
Contributor Author

A scan of the log confirms that's probably what happened.

25028 seen! (Created: 2018-04-23 22:56:24 +0000 UTC)
Most recent Updated seen so far: 2018-04-23 22:57:04 +0000 UTC

The since value passed to the GitHub API progressed past the 25028 creation time (disabling the live deduplication check) before 25028 reached the log (disabling the log deduplication check).

Now trying to figure out if using Created instead of Updated to progress the since parameter is historically safe.

@FiloSottile
Copy link
Contributor Author

Unfortunately, I also found out-of-order creation events. They seem to mostly match maintner crashes, but two recent ones look like they were nothing else than load.

Out of order creation event! 2018-03-27 21:38:55 +0000 UTC (seen now, issue #24568) is before 2018-03-27 21:41:09 +0000 UTC (seen earlier, issue #24569)
Out of order creation event! 2018-03-27 21:37:36 +0000 UTC (seen now, issue #24567) is before 2018-03-27 21:41:09 +0000 UTC (seen earlier, issue #24569)

So I'm afraid also using Created to advance since is not safe, and we'll have to add a hacky buffer to account for out of order events as in CL 108977.

@FiloSottile
Copy link
Contributor Author

(Full source and output: https://gist.github.com/FiloSottile/aa24968d7fe30553047940e98221d51a)

@golang golang locked and limited conversation to collaborators Apr 27, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge
Projects
None yet
Milestone
Unreleased
Development

No branches or pull requests
3 participants
@bradfitz @FiloSottile @gopherbot