Merge pull request #127 from Pix4D/log-retry-reason

GitHub: log retry reason

CHANGELOG.md

@@ -5,6 +5,12 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
+## UNRELEASED [v0.10.2] - 2023-XX-XX
+
+### Changed
+
+- GitHub: log the reason for retrying [#123](https://github.com/Pix4D/cogito/issues/123).
+
 ## [v0.10.1] - 2023-05-31
 
 ### Added
@@ -243,3 +249,5 @@ This release allows to use cogito for the vast majority of chat notifications wh
 [v0.8.2]: https://github.com/Pix4D/cogito/releases/tag/v0.8.2
 [v0.9.0]: https://github.com/Pix4D/cogito/releases/tag/v0.9.0
 [v0.10.0]: https://github.com/Pix4D/cogito/releases/tag/v0.10.0
+[v0.10.1]: https://github.com/Pix4D/cogito/releases/tag/v0.10.1
+[v0.10.2]: https://github.com/Pix4D/cogito/releases/tag/v0.10.2

cogito/ghcommitsink.go

@@ -4,8 +4,9 @@ import (
 	"math/rand"
 	"time"
 
-	"github.com/Pix4D/cogito/github"
 	"github.com/hashicorp/go-hclog"
+
+	"github.com/Pix4D/cogito/github"
 )
 
 // Maximum number of retries for the retryable http request

github/commitstatus.go

@@ -77,7 +77,8 @@ type AddRequest struct {
 	Context     string `json:"context"`
 }
 
-// Add adds a commit state to the given sha, decorating it with targetURL and optional description.
+// Add adds a commit state to the given sha, decorating it with targetURL and optional
+// description.
 // Parameter sha is the 40 hexadecimal digit sha associated to the commit to decorate.
 // Parameter state is one of error, failure, pending, success.
 // Parameter targetURL (optional) points to the specific process (for example, a CI build)
@@ -111,7 +112,7 @@ func (s CommitStatus) Add(sha, state, targetURL, description string) error {
 	req.Header.Set("Content-Type", "application/json")
 
 	var response httpResponse
-	timeToSleep := 0 * time.Second // 0 seconds
+	timeToSleep := 0 * time.Second
 
 	for attempt := 1; attempt <= s.target.MaxRetries; attempt++ {
 		time.Sleep(timeToSleep)
@@ -120,14 +121,15 @@ func (s CommitStatus) Add(sha, state, targetURL, description string) error {
 		if err != nil {
 			return err
 		}
-		timeToSleep, err = checkForRetry(response, s.target.WaitTime, s.target.MaxSleepTime, s.target.Jitter)
+		timeToSleep, reason, err := checkForRetry(response, s.target.WaitTime,
+			s.target.MaxSleepTime, s.target.Jitter)
 		if err != nil {
 			return fmt.Errorf("internal error: %s", err)
 		}
 		if timeToSleep == 0 {
 			break
 		}
-		s.log.Info("Sleeping for", "time", timeToSleep)
+		s.log.Info("Sleeping for", "duration", timeToSleep, "reason", reason)
 	}
 
 	return s.checkStatus(response, state, sha, url)
@@ -250,35 +252,45 @@ func min(a, b int) int {
 	return b
 }
 
-// checkForRetry determines if we should retry the http request and calculates wait time between retries
-func checkForRetry(res httpResponse, waitTime, maxSleepTime, jitter time.Duration) (time.Duration, error) {
-	retrayalbeStatusCodes := []int{
+// checkForRetry determines if the HTTP request should be retried.
+// If yes, checkForRetry returns a positive duration.
+// If no, checkForRetry returns a 0 duration.
+//
+// It considers two different reasons for a retry:
+//  1. The request encountered a GitHub-specific rate limit.
+//     In this case, it considers parameters maxSleepTime and jitter.
+//  2. The HTTP status code is in a retryable subset of the 5xx status codes.
+//     In this case, it returns the same as the input parameter waitTime.
+func checkForRetry(res httpResponse, waitTime, maxSleepTime, jitter time.Duration,
+) (time.Duration, string, error) {
+	retryableStatusCodes := []int{
 		http.StatusInternalServerError, // 500
 		http.StatusBadGateway,          // 502
 		http.StatusServiceUnavailable,  // 503
 		http.StatusGatewayTimeout,      // 504
 	}
 
 	switch {
-	// If you exceed the rate limit, the response will have a 403 status and the x-ratelimit-remaining header will be 0
+	// If the request exceeds the rate limit, the response will have status 403 Forbidden
+	// and the x-ratelimit-remaining header will be 0
 	// https://docs.github.com/en/rest/overview/resources-in-the-rest-api?apiVersion=2022-11-28#exceeding-the-rate-limit
 	case res.statusCode == http.StatusForbidden && res.rateLimitRemaining == 0:
-		// Calculate sleeptime based solely on the server clock. This is unaffected
+		// Calculate the sleep time based solely on the server clock. This is unaffected
 		// by the inevitable clock drift between server and client.
 		sleepTime := res.rateLimitReset.Sub(res.date)
 		// Be a good netizen by adding some jitter to the time we sleep.
 		sleepTime += jitter
 		switch {
 		case sleepTime > maxSleepTime:
-			return 0, nil
+			return 0, "", nil
 		case sleepTime > 0 && sleepTime < maxSleepTime:
-			return sleepTime, nil
+			return sleepTime, "rate limited", nil
 		default:
-			return 0, fmt.Errorf("unexpected: negative sleep time: %s", sleepTime)
+			return 0, "", fmt.Errorf("unexpected: negative sleep time: %s", sleepTime)
 		}
-	case slices.Contains(retrayalbeStatusCodes, res.statusCode):
-		return waitTime, nil
+	case slices.Contains(retryableStatusCodes, res.statusCode):
+		return waitTime, http.StatusText(res.statusCode), nil
 	default:
-		return 0, nil
+		return 0, "", nil
 	}
 }

github/commitstatus_private_test.go

@@ -0,0 +1,81 @@
+package github
+
+import (
+	"net/http"
+	"testing"
+	"time"
+
+	"gotest.tools/v3/assert"
+)
+
+func TestCheckForRetrySuccess(t *testing.T) {
+	type testCase struct {
+		name         string
+		res          httpResponse
+		waitTime     time.Duration
+		maxSleepTime time.Duration
+		jitter       time.Duration
+		wantSleep    time.Duration
+		wantReason   string
+	}
+
+	run := func(t *testing.T, tc testCase) {
+		sleep, reason, err := checkForRetry(tc.res, tc.waitTime, tc.maxSleepTime, tc.jitter)
+
+		assert.NilError(t, err)
+		assert.Equal(t, sleep, tc.wantSleep)
+		assert.Equal(t, reason, tc.wantReason)
+	}
+
+	serverDate := time.Date(2001, time.April, 30, 13, 0, 0, 0, time.UTC)
+	const maxSleepTime = 15 * time.Minute
+
+	testCases := []testCase{
+		{
+			name:      "status OK: sleep==0",
+			res:       httpResponse{statusCode: http.StatusOK},
+			wantSleep: 0 * time.Second,
+		},
+		{
+			name:      "non retryable status code: sleep==0",
+			res:       httpResponse{statusCode: http.StatusTeapot},
+			wantSleep: 0 * time.Second,
+		},
+		{
+			name:       "retryable status code: sleep==waitTime",
+			res:        httpResponse{statusCode: http.StatusInternalServerError},
+			waitTime:   42 * time.Second,
+			wantSleep:  42 * time.Second,
+			wantReason: "Internal Server Error",
+		},
+		{
+			name: "rate limited, would sleep too long: sleep==0",
+			res: httpResponse{
+				statusCode:     http.StatusForbidden,
+				date:           serverDate,
+				rateLimitReset: serverDate.Add(30 * time.Minute),
+			},
+			maxSleepTime: maxSleepTime,
+			wantSleep:    0 * time.Second,
+		},
+		{
+			name: "rate limited, would sleep a bit, adding also the jitter",
+			res: httpResponse{
+				statusCode:     http.StatusForbidden,
+				date:           serverDate,
+				rateLimitReset: serverDate.Add(5 * time.Minute),
+			},
+			maxSleepTime: maxSleepTime,
+			jitter:       8 * time.Second,
+			wantSleep:    5*time.Minute + 8*time.Second,
+			wantReason:   "rate limited",
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) { run(t, tc) })
+	}
+}
+
+// BUG: sleeptime + jitter might cause a failure; test sleepTime > maxSleepTime should
+// be done before?

github/commitstatus_test.go

@@ -9,10 +9,11 @@ import (
 	"testing"
 	"time"
 
-	"github.com/Pix4D/cogito/github"
-	"github.com/Pix4D/cogito/testhelp"
 	"github.com/google/go-cmp/cmp"
 	"github.com/hashicorp/go-hclog"
+
+	"github.com/Pix4D/cogito/github"
+	"github.com/Pix4D/cogito/testhelp"
 )
 
 type mockedResponse struct {