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.

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

x/build/maintner: GitHub issue events are not consistent with API values #29396

Open
andybons opened this Issue Dec 22, 2018 · 26 comments

Comments

Projects
None yet
4 participants
@andybons
Copy link
Member

andybons commented Dec 22, 2018

Moved from #28226

There are some issues that have events missing within the maintner corpus. This makes it impossible to create an accurate milestone burndown chart where you want to query for the state of an issue at a particular time window.

A few examples of issues in maintner that have incomplete event lists:

=== Issue events for golang.org/issues/28559
             labeled	milestone:         	label:Testing
             labeled	milestone:         	label:help wanted
             labeled	milestone:         	label:OS-OpenBSD
             labeled	milestone:         	label:Builders
             labeled	milestone:         	label:NeedsInvestigation
          milestoned	milestone:   Go1.12	label:

It does not record the final “closed” event: https://api.github.com/repos/golang/go/issues/28559/events

=== Issue events for golang.org/issues/28306
           mentioned	milestone:         	label:
          subscribed	milestone:         	label:
           mentioned	milestone:         	label:
          subscribed	milestone:         	label:
            assigned	milestone:         	label:
             labeled	milestone:         	label:Documentation
             labeled	milestone:         	label:NeedsInvestigation
          milestoned	milestone:   Go1.12	label:
             renamed	milestone:         	label:

The above event log is missing a few milestone-related events: https://api.github.com/repos/golang/go/issues/28306/events

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Dec 30, 2018

@andybons Hi! I worked on the maintner previously. I'm happy to pick this up for investigation.

@andybons

This comment has been minimized.

Copy link
Member Author

andybons commented Dec 30, 2018

@Skarlso go for it 👍

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Dec 31, 2018

Coolness. 👍🙂

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 6, 2019

@andybons Hi, sorry, I was insanely busy but picking this up now. 👍

Would you be so kind as to point me into the right direction here? I think I know where to start digging.

First off, I want to write a test to reproduce this bug. Ideally a unit test something like:

func TestParseMultipleGithubEvents(t *testing.T) {

}

I think the right code part here is

func parseGithubEvents(r io.Reader) ([]*GitHubIssueEvent, error) {

... if I see that correctly. Somewhere here is the bug buried. Am I poking in the right direction? The manual way of seeing the missing event? I fired up the maintserver and located said issue, but can't find the missing event as the comment is there and the issue is closed. I'm guessing it's somewhere else?

Thanks!

@andybons

This comment has been minimized.

Copy link
Member Author

andybons commented Jan 7, 2019

I fired up the maintserver and located said issue, but can't find the missing event as the comment is there and the issue is closed. I'm guessing it's somewhere else?

Is the closed event there? That's different than the issue being closed. Which example are you referring to?

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 7, 2019

I can't see "events", I can only see that it's closed. That's why I'm asking, that I must be looking at something else? :) This is my view and the ticket in question:
screenshot 2019-01-07 at 20 41 57

@andybons

This comment has been minimized.

Copy link
Member Author

andybons commented Jan 7, 2019

@Skarlso take a look at https://api.github.com/repos/golang/go/issues/28559/events

Notice how there is a "closed" event. This doesn't show up in the list of events when enumerating via https://godoc.org/golang.org/x/build/maintner#GitHubIssue.ForeachEvent

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 7, 2019

Oh I see, so this wouldn't show up in the UI but rather through a small code. Something like:

package main

import (
	"context"
	"fmt"
	"log"

	"golang.org/x/build/maintner/godata"
)

func main() {
	corpus, err := godata.Get(context.Background())
	if err != nil {
		log.Fatalln(err)
	}
	proj := corpus.Gerrit().Project("go.googlesource.com", "go")
	cl := proj.CL(101036)
        // enumerate events here.
}

Just not the CL probably, but the Issue. Gonna check that out.

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 7, 2019

	corpus.GitHub().Repo("golang", "go").Issue(28559).ForeachEvent(...)
@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 7, 2019

Alright! Reproduced with a single, small script:

Script:

package main

import (
	"context"
	"fmt"
	"log"

	"golang.org/x/build/maintner"
	"golang.org/x/build/maintner/godata"
)

func main() {
	corpus, err := godata.Get(context.Background())
	if err != nil {
		log.Fatalln(err)
	}
	corpus.GitHub().Repo("golang", "go").Issue(28559).ForeachEvent(func(e *maintner.GitHubIssueEvent) error {
		fmt.Println(e.Type)
		return nil
	})
}

Output:

❯ go run main.go
2019/01/07 21:38:10 Loading data from log *maintner.netMutSource ...
2019/01/07 21:38:11 Downloading 554570 bytes of https://maintner.golang.org/logs/44 ...
2019/01/07 21:38:12 wrote /Users/hannibal/Library/Caches/golang-maintner/0044.growing.mutlog
2019/01/07 21:38:21 Reloaded data from log *maintner.netMutSource.
labeled
labeled
labeled
labeled
labeled
milestoned

Close event is indeed missing.

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 7, 2019

The problem is probably further up the chain but going to write a unit test for ForeachEvent anyways...

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 9, 2019

So... I have a hunch...

if res.StatusCode != http.StatusOK {
    log.Printf("Fetching %s: %v: %+v", u, res.Status, res.Header)
    // TODO: rate limiting, etc.
    return nil, nil, fmt.Errorf("%s: %v", u, res.Status)
}

Maybe. :)

I would have to see the logs. Can I access some logs somewhere? @andybons

@andybons

This comment has been minimized.

Copy link
Member Author

andybons commented Jan 10, 2019

@Skarlso can you provide more context as to what your hunch is? I can’t surmise what you’re trying to figure out. Whether we’re being rate limited? If we were, then a lot of other requests would also fail subsequently and we’d see a lot more issues.

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 10, 2019

@andybons I see. I've begun writing unit tests around some of the functions.. Admittedly it's a bit slow going because the setup isn't trivial, but I'm getting there.

I'm tracing back where the events are coming from. The ForeachEvent function works fine. The events it gets are already not containing the missing events... So going back from there, we eventually end up here: https://github.com/golang/build/blob/master/maintner/github.go#L2023. (This is also interesting: https://github.com/golang/build/blob/master/maintner/github.go#L1990. And this: https://github.com/golang/build/blob/master/maintner/github.go#L2005)

And this is the main function that gets the events in the first place. And there are a lot of error possibilities here and this is largely untested code. So my hunch was that there is an error at some point in the function not necessarily because this function might be wrong. But.... I'm writing the unit test for it which either way sheds some light on the matter. Hopefully.

EDIT: The other hunch is my first hunch that I'm following. That parseGithubEvents is incorrectly parsing something. I begun writing a test for that. :D It's just tedious. :)

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 10, 2019

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 10, 2019

@Skarlso reminder I should actually chuck the full failing event stream in there. Also, use a fixture as it gets really really large.

@gopherbot

This comment has been minimized.

Copy link

gopherbot commented Jan 10, 2019

Change https://golang.org/cl/157437 mentions this issue: x/build/maintner: GitHub issue events are not consistent with API values

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 12, 2019

@andybons Alright. So... In the attached CL I added a bunch of tests around every sync event that happens that parses an incoming github event directly parsed from the API.

If you are aware of any part of the code any where else this could still fail, please tell me.

These tests all pass. What I also added is a retry logic around rate limiting.

I think right now the CL is solid as in adds a bit of logging and a lot of test cases for the area of the code that was not tested before. As is I think it's ready to merge, even though it does not fix the problem yet. ( unless the rate limiting does kick in from time to time, even though you are saying then other stuff should fail. ).

I have not stopped investigating, I just merely proved that THIS part of the code DOES work and correctly parses event logs.

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 27, 2019

@andybons Hi. :) Any thoughts on the above? :)

@andybons

This comment has been minimized.

Copy link
Member Author

andybons commented Jan 28, 2019

I will let the owners of the code weigh in on the review.

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 28, 2019

Cool, thanks!

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 30, 2019

EDIT: Nope. :( Red Herring.

OMG, I think I reproduced it:

M before:  owner:"foowner" repo:"bar" number:1001 event:<id:1943301510 event_type:"labeled" actor_id:5200974 created:<seconds:1541174039 > label:<name:"Testing" > > event:<id:1943301512 event_type:"labeled" actor_id:5200974 created:<seconds:1541174039 > label:<name:"help wanted" > > event:<id:1943301514 event_type:"labeled" actor_id:5200974 created:<seconds:1541174039 > label:<name:"OS-OpenBSD" > > event:<id:1943301515 event_type:"labeled" actor_id:5200974 created:<seconds:1541174039 > label:<name:"Builders" > > event:<id:1943301516 event_type:"labeled" actor_id:5200974 created:<seconds:1541174039 > label:<name:"NeedsInvestigation" > > event:<id:1943301518 event_type:"milestoned" actor_id:5200974 created:<seconds:1541174039 > milestone:<title:"Go1.12" > > event:<id:1943494698 event_type:"closed" actor_id:3194333 created:<seconds:1541179673 > > event_status:<server_date:<seconds:1548829177 > >
CORPUS after:  &{0x196ae88 <nil> false  false {{1 0} 0 0 -1073741824 0} false false map[Testing:Testing help wanted:help wanted OS-OpenBSD:OS-OpenBSD Builders:Builders NeedsInvestigation:NeedsInvestigation Go1.12:Go1.12] map[] 0xc0000b6800 <nil> [] [] <nil> {0 0 <nil>} [] map[] map[] map[] map[] map[]}

In the corpus the closed event from above is missing!!!!!

greatsuccess

The bug looks like is in processGithubIssueMutation. Next step, writing a unit test to prove, then fix. 👍

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Jan 30, 2019

Disregard the above. :/ Those are labels. The last close event didn't have labels. Continuing on..

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Feb 7, 2019

@andybons Hi. I opened a separate issue with the test coverage increase and the github throttle handling.

I searched for a long time, I believe it's either a race condition in sync logic, a timing issue, or github throwing some kind of error somewhere which is not being handled.

I created an issue which fixes the throttling which might fix this issue, but I ran out of ideas. Without logs that I could investigate on what's happening this is an insanely hard task with my code base knowledge.

Sorry, I couldn't help out. :/

@dmitshur

This comment has been minimized.

Copy link
Member

dmitshur commented Feb 8, 2019

Without logs that I could investigate on what's happening this is an insanely hard task with my code base knowledge.

Sorry, I couldn't help out.

Understandable, and no problem.

On the contrary, it is very helpful that you've investigated this far and shared your findings. This information will make it easier to make further progress towards identifying the root cause. Thank you very much @Skarlso, your efforts are greatly appreciated!

@Skarlso

This comment has been minimized.

Copy link
Contributor

Skarlso commented Feb 8, 2019

@dmitshur Thank you! Happy that I could contribute something. 😊

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment