Improve HTTPRateLimiter

[mcuadros]

The current HTTPRateLimiter it's not working properly since is hitting the rate and returning errors, instead of wait until the query can be done.

BTW The current implementation is copy pasted from terraform-github
hashicorp/terraform-provider-github@263b46a

[se7entyse7en]

I investigated this issue. And what's happening is that the console is getting flooded by errors such as the following:

ghsync_1 | time="2019-06-19T17:10:55.4939114Z" level=error msg="error handling request" error="GET https://api.github.com/repos/src-d/go-git/issues?page=9&per_page=100&state=all: 403 API rate limit of 60 still exceeded until 2019-06-19 18:09:04 +0000 UTC, not making remote request. [rate reset in 58m09s]" name=go-git owner=src-d type=repository

The thing is that the go-github library itself checks for rate limit error, so there's an overlap between this check and the one made at transport level by http rate limiter.

The sleep and the waiting for the reset of the limit are done in the http rate limiter, so if an excess of requests is detected by the client library, the http call is skipped, hence no sleeping occurs. That's why the console is getting flooded by errors.

I think that we could wrap the go-github client's methods (c.PullRequests.List, c.Issues.List, etc.) with the logic that is now implemented in the http rate limiter.

WDYT?

[smacker]

I don't get it.
go-github skips requests that's true but only when rate limit is exceeded, but our round-tripper should catch the very first limit error and block everything with this sleep: https://github.com/src-d/ghsync/blob/master/utils/rate.go#L90

So our code would make a new request only after retryAfter.
The current logic (overall) should work there is just a bug somewhere most probably.

[smacker]

Looks like there is some misunderstanding. The logic I see which is implemented right now and in theory should work fine:

github.List() -> github.Do() -> (no error from limit yet) -> HTTPRateLimiter -> 
Real HTTP request -> Response

Response -> HTTPRateLimiter catches the error, goes to sleep and blocks everything
-> github.Do finishes only after sleep
-> github.List finishes only after sleep
-> github.List again
-> there is no limit because we were sleeping in block

[mcuadros]

Yes, @smacker this is how should work, the problem is that looks like some times the sleep is ignored, and then you get quota errors.

[se7entyse7en]

Linking here the conversation with @smacker: https://src-d.slack.com/archives/C7TB5NEDN/p1561021087371200.

[se7entyse7en]

Okay, I had another quick look and the reason should be that the rate limiter sleeps when the corresponding request already reached the limit, but it should sleep when the last available request has been made before doing the next one that will fail. So instead of checking for error in the response, we should check the value of the X-Ratelimit-Remaining header whether it is equal to 0.

[smacker]

@se7entyse7en why? The logic above is described for the sleep after the response. And it looks correct.
I still guess the bug changes the expected flow which results in skipping the sleep. So we need to fix the bug, not the logic.

[mcuadros]

BTW the RateLimiter was extractor from Terraform github provider, and was in use for some years

[se7entyse7en]

@smacker I've started working on this again focusing on shallow sync.

I still have some doubts about the workflow that you explained:

Real HTTP request -> Response

Response -> HTTPRateLimiter catches the error, goes to sleep and blocks everything
-> github.Do finishes only after sleep
-> github.List finishes only after sleep
-> github.List again
-> there is no limit because we were sleeping in block

Let's say that I start the shallow sync and that the quota is N, so:

github.Do() -> HTTPRateLimiter -> Real HTTP reqquest -> Response -> client sets remaining to N
github.Do() -> HTTPRateLimiter -> Real HTTP request -> Response -> client sets remaining to N - 1
...
github.Do() -> HTTPRateLimiter -> Real HTTP request -> Response -> client sets remaining to 1
github.Do() -> HTTPRateLimiter -> Real HTTP request -> Response -> client sets remaining to 0
github.Do() -> RateLimitError (real http request is skipped because client knows that remaining is 0 from last)

So for shallow sync it will simply exit, so it's not a big deal until we implement retry. In case of deep, the error makes the consumer take in charge the next item and when tyring request data for it, the client will raise the same RateLimitError and avoid doing the real http request. This will repeat again and again until all the items in the queue have been consumed.

If after reaching the limit, we restart the sync and the quota has not been reset yet, then the sleep occurs as the client doesn't have any information about how many remaining requests there are:

github.Do() -> client doesn't know that remaining is 0 -> HTTPRateLimiter -> Real HTTP request -> Response -> sleep

Initially, I thought that maybe when this was introduced this RT on terraform-provider-github, the client library doesn't perform any check, but it doesn't seem the case, at least it was already there since the very first release of terraform-provider-github. Maybe terraform has its own retry on error on top of their providers? So essentially what's happening is the same as restarting the process as I explained above, so sleep is actually working?

Does it make sense? Am I completely missing something?

[smacker]

I still have some doubts about the workflow

please check the code of HTTPRateLimiter.
It checks response before returning anything: https://github.com/src-d/ghsync/blob/master/utils/rate.go#L66
The check return error when remaining = 0: https://github.com/google/go-github/blob/master/github/github.go#L748
And then goes to sleep as explained before.

So the last github.Do() won't be executed as long as limit wasn't reset.

we implement retry

already implemented

In case of deep

It is possible that this flow isn't going to work in deep, I didn't check the code in all the details. But we use goroutines there in some places which may cause problems.

But I wouldn't care about deep too much now. Most probably we will change the code a lot before starting importing "deep".

[se7entyse7en]

But it checks for status code first, isn't it?

[smacker]

Do you mean that GitHub would return status 200 and headerRateRemaining = 0 in the same response?

I assumed it would return 403. But you are right, it's possible. (not sure if that really happens or not) In this case our limiter would be skipped. Can you test it? Just run shallow without token and log responses.

[se7entyse7en]

Do you mean that GitHub would return status 200 and headerRateRemaining = 0 in the same response?

Exactly, here's an output taken from the console while I was debugging:

Doing request: &{GET https://api.github.com/repos/Viralize/shamash/pulls?per_page=100&state=all HTTP/1.1 1 1 map[Accept:[application/vnd.github.symmetra-preview+json, application/vnd.github.sailor-v-preview+json, application/vnd.github.shadow-cat-preview+json] User-Agent:[go-github]] <nil> <nil> 0 [] false api.github.com map[] map[] <nil> map[]   <nil> <nil> <nil> 0xc0000a8008}
Request done. Resp: &{200 OK 200 HTTP/1.1 1 1 map[Access-Control-Allow-Origin:[*] Access-Control-Expose-Headers:[ETag, Link, Location, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval, X-GitHub-Media-Type] Cache-Control:[public, max-age=60, s-maxage=60] Content-Length:[2] Content-Security-Policy:[default-src 'none'] Content-Type:[application/json; charset=utf-8] Date:[Mon, 24 Jun 2019 16:44:11 GMT] Etag:["250ce138d4706285c4a567598eafec2a"] Referrer-Policy:[origin-when-cross-origin, strict-origin-when-cross-origin] Server:[GitHub.com] Status:[200 OK] Strict-Transport-Security:[max-age=31536000; includeSubdomains; preload] Vary:[Accept Accept-Encoding] X-Content-Type-Options:[nosniff] X-Frame-Options:[deny] X-Github-Media-Type:[github.symmetra-preview; format=json, github.sailor-v-preview; format=json, github.shadow-cat-preview; format=json] X-Github-Request-Id:[DB2B:11326:3A72724:4970ADB:5D10FDDB] X-Ratelimit-Limit:[60] X-Ratelimit-Remaining:[0] X-Ratelimit-Reset:[1561398195] X-Xss-Protection:[1; mode=block]] 0xc000162180 2 [] false false map[] 0xc000140400 0xc00035a000}, Err: <nil>

Can you test it? Just run shallow without token and log responses.

Yup, I always tested it without token to reproduce it (needed to change some lines of code).

[smacker]

I see. Thanks for debugging! Then I would proceed by changing the check inside HTTPRateLimiter. Instead of relying on go-github logic for errors it can just check that the header is present and the value of it is 0. And go to sleep. Because it is the only case limiter cares about.