Fix handling of GitHub ratelimit information

[rgmz]

Description:

This is a follow-up to #1912, which used the headers from the response to determine rate-limiting information, instead of using the values from RateLimitError.Rate:

trufflehog/pkg/sources/github/github.go

Lines 838 to 841 in 5058cad

	var rateLimit *github.RateLimitError
	var abuseLimit *github.AbuseRateLimitError
	if errors.As(errIn, &rateLimit) {
	// Do nothing

Although that logic seemed solid, I discovered that it did not work in some circumstances. This lead to the "unexpected" path more often than intended, and periodic instances where requests would be made before the ratelimit was refreshed.

trufflehog/pkg/sources/github/github.go

Line 872 in 5058cad

s.log.V(2).Error(errIn, "unexpected rate limit error", "retry_after", retryAfter.String(), "resume_time", resumeTime)

2023-10-29T17:28:25-04:00       error   trufflehog      Failed to parse ratelimit-remaining     {"error": "strconv.Atoi: parsing \"\": invalid syntax"}
2023-10-29T17:28:25-04:00       error   trufflehog      Failed to parse ratelimit-reset {"error": "strconv.Atoi: parsing \"\": invalid syntax"}
2023-10-29T17:28:08-04:00       error   trufflehog      unexpected rate limit error     {"retry_after": "5m0s", "retry_after_orig": "0s", "remaining": 0, "knownWait": false, "resume_time": "2023-10-29 17:33:08.06715002 -0400 EDT m=+6232.418916613", "headers": {}, "type": "*github.RateLimitError", "error": "GET https://api.github.com/repos/xxx/yyyl: 403 API rate limit of 5000 still exceeded until 2023-10-29 17:49:12 -0400 EDT, not making remote request. [rate reset in 21m04s]"}

Checklist:

• Tests passing (make test-community)?
• Lint passing (make lint this requires golangci-lint)?

[CLAassistant]

All committers have signed the CLA.

[rgmz]

I will note that this can still result in workers concurrently hitting the API and failing:

2023-10-29T19:43:18-04:00       info-0  trufflehog      rate limited    {"retry_after": "6m47.724523981s", "resume_time": "2023-10-29 19:50:06.000004355 -0400 EDT m=+520.724369060"}
2023-10-29T19:43:18-04:00       info-0  trufflehog      rate limited    {"retry_after": "6m47.474734374s", "resume_time": "2023-10-29 19:50:06.000003887 -0400 EDT m=+520.724368589"}
2023-10-29T19:43:22-04:00       info-0  trufflehog      rate limited    {"retry_after": "6m43.351695671s", "resume_time": "2023-10-29 19:50:06.000003626 -0400 EDT m=+520.724368327"}
2023-10-29T19:43:23-04:00       info-0  trufflehog      rate limited    {"retry_after": "6m42.607366169s", "resume_time": "2023-10-29 19:50:06.000004116 -0400 EDT m=+520.724368819"}
2023-10-29T19:43:25-04:00       info-0  trufflehog      rate limited    {"retry_after": "6m40.810664635s", "resume_time": "2023-10-29 19:50:06.000003248 -0400 EDT m=+520.724367948"}
2023-10-29T19:43:27-04:00       info-0  trufflehog      rate limited    {"retry_after": "6m38.59667703s", "resume_time": "2023-10-29 19:50:06.000003904 -0400 EDT m=+520.724368599"}
2023-10-29T19:43:28-04:00       info-0  trufflehog      rate limited    {"retry_after": "6m37.454843428s", "resume_time": "2023-10-29 19:50:06.000003603 -0400 EDT m=+520.724368302"}
...

I don't know if you get penalized for trying to make requests when you've hit your rate-limit. It may be worth adding a mutex to prevent extraneous requests from being dispatched.

[rosecodym]

Thanks for digging into this, it looks like gnarly stuff. The changes seem non-obvious and I want to ensure I've got them right. Tell me if this is correct:

There are two functional changes here. The first applies to when we're handling an error that turns out to be a primary rate limit error with a Remaining property that's in the future and no requests remaining. Before, we'd ignore Remaining and try to parse the rate limit response headers ourselves, but now we ignore the headers and just wait until that specified time.

The second case is in the header parsing logic. Before, if x-ratelimit-remaining was missing, we'd fall into the "unexpected" case. That behavior is no longer present - if the header is missing, we still attempt to process x-ratelimit-reset. (The code to parse that header has been changed to match the other one, but the effective logic hasn't changed. If the retry interval from the original error is non-positive, but x-ratelimit-reset is missing, we still fall into the "unexpected" case because we're supposed to wait but we can't figure out how long to wait for.)

There is also the change of moving Now() to the start of the function - was that an important logic fix or just a nice cleanup you did while you were here?

[rgmz]

Coming back to this after a while, I went on a bit of a wild goose chase because it started returning a generic github.ErrorResponse, breaking the rate limit handling. It turns out that GitHub changed their documentation URL which broke the response handling (google/go-github@182859f).

I will push a change shortly that includes upgrading go-github.

[rgmz]

The second case is in the header parsing logic...

After fixing the aforementioned issue and experimenting with this further, I don't think there's a point to keeping this part. The go-github package should always translate response into a usable error, and if it can't then whatever the issue would likely impact us as well.

---

I've refactored the logic to use a sync.RWMutex. The goal is to make the logs more user-friendly/useful by only logging one message per given rate limit event. Any feedback or potential issues with this approach are welcome.

2023-12-10T15:01:29-05:00       info-0  trufflehog      rate limited    {"resume_time": "2023-12-10 15:02:37.14123656 -0500 EST m=+796.659151165"}
2023-12-10T15:03:12-05:00       info-0  trufflehog      rate limited    {"resume_time": "2023-12-10 15:04:20.218740308 -0500 EST m=+899.736654911"}
2023-12-10T15:04:43-05:00       info-0  trufflehog      rate limited    {"resume_time": "2023-12-10 15:05:51.38309714 -0500 EST m=+990.901011742"}
2023-12-10T15:06:25-05:00       info-0  trufflehog      rate limited    {"resume_time": "2023-12-10 15:07:30.166662804 -0500 EST m=+1089.684577403"}

There is also the change of moving Now() to the start of the function - was that an important logic fix or just a nice cleanup you did while you were here?

Calling time.Now() in multiple places bugged me and also resulted in minor inconsistencies. It's for stylistic and consistency purposes (albeit mostly the former).

[ahrav]

This looks good to me, thanks for taking the time to get this all cleaned up and updated.

[rgmz]

@ahrav I've resolved the conflicts if you want to re-run the workflows.

Edit: oops, forgot to fix up tests. One sec... Should work now.

[rosecodym]

I have a question about the currency, and unrelatedly, are any of these linting errors low-hanging fruit you can fix? If not, would you mind line-level disabling them using // staticcheck:nolint and opening a new issue to clean them up?

[rosecodym]

It's possible for a bunch of workers to get blocked here, right? And if they entered this function because of the secondary rate limit, won't they therefore all end up waiting for their rate limit period in sequence?

I'm having trouble juggling these locks in my head so I might be completely misunderstanding this. (Or maybe this is a theoretical possibility that's unlikely in practice?)

[rgmz]

While it's possible that multiple workers will hit this, the actual work performed in this block is minimal and the lock should be released fairly quickly. time.Sleep is called after rateLimitMu.Unlock().

trufflehog/pkg/sources/github/github.go

Lines 930 to 936 in 7bef8df

	rateLimitMu.Unlock()
	} else {
	retryAfter = time.Until(resumeTime)
	}
	githubNumRateLimitEncountered.WithLabelValues(s.name).Inc()
	time.Sleep(retryAfter)

Edit: I could always add another check after the lock to see if the resume time is still zero or in the past.

[rgmz]

I guess bumping the go-github version resulted in several deprecations. I can take a look at this later. 😅

[rosecodym]

@ahrav i know you already approved this, but is it going to conflict with anything you're currently working on?

[ahrav]

@ahrav i know you already approved this, but is it going to conflict with anything you're currently working on?

We should be good. Thanks for double checking 🙇