diff --git a/cmd/kosli/attestationSubmit_test.go b/cmd/kosli/attestationSubmit_test.go index 2faaca538..325e72105 100644 --- a/cmd/kosli/attestationSubmit_test.go +++ b/cmd/kosli/attestationSubmit_test.go @@ -321,7 +321,7 @@ func TestAttestationSubmitterAttestsNothingWhenTheBucketRefusesTheFile(t *testin err := submitter.submit(submission) require.EqualError(t, err, "failed to upload attachment testdata/file1: "+ - "upload refused with HTTP 403: BadDigest: The SHA256 you specified did not match what we received") + "upload refused with HTTP 403 Forbidden: BadDigest: The SHA256 you specified did not match what we received") require.Empty(t, fake.recorded) } diff --git a/cmd/kosli/evaluateHelpers.go b/cmd/kosli/evaluateHelpers.go index 259723ec4..db8abab25 100644 --- a/cmd/kosli/evaluateHelpers.go +++ b/cmd/kosli/evaluateHelpers.go @@ -202,7 +202,7 @@ func fetchRemotePolicy(remoteURL string) ([]byte, error) { } defer func() { _ = resp.Body.Close() }() if resp.StatusCode < 200 || resp.StatusCode >= 300 { - return nil, fmt.Errorf("failed to fetch policy from %s: HTTP %d", remoteURL, resp.StatusCode) + return nil, fmt.Errorf("failed to fetch policy from %s: %s", remoteURL, requests.HTTPStatus(resp.StatusCode)) } body, err := io.ReadAll(io.LimitReader(resp.Body, policyMaxBytes+1)) @@ -421,9 +421,9 @@ func serverSideRequestError(err error) error { // Quoting what arrived instead would dress a proxy's page, or the decoder's // complaint about one, as the server's own reason. if !apiError.HasServerMessage || apiError.Message == "" { - return fmt.Errorf("the Kosli server answered %d", apiError.StatusCode) + return fmt.Errorf("the Kosli server answered %s", requests.HTTPStatus(apiError.StatusCode)) } - return fmt.Errorf("the Kosli server answered %d: %s", apiError.StatusCode, apiError.Message) + return fmt.Errorf("the Kosli server answered %s: %s", requests.HTTPStatus(apiError.StatusCode), apiError.Message) } // serverSideReadError reports a failure to read a verdict back. By this point diff --git a/cmd/kosli/evaluateHelpers_test.go b/cmd/kosli/evaluateHelpers_test.go index 5e331421d..cd107ebde 100644 --- a/cmd/kosli/evaluateHelpers_test.go +++ b/cmd/kosli/evaluateHelpers_test.go @@ -3,9 +3,12 @@ package main import ( "bytes" "encoding/json" + "net/http" + "net/http/httptest" "testing" "github.com/kosli-dev/cli/internal/evaluate" + "github.com/kosli-dev/cli/internal/requests" "github.com/stretchr/testify/require" ) @@ -21,3 +24,24 @@ func TestEvaluateResultKeysListsEveryKeyTheOutputCanHave(t *testing.T) { require.Contains(t, evaluateResultKeys, key) } } + +func TestFetchRemotePolicyNamesTheStatusItWasRefusedWith(t *testing.T) { + server := httptest.NewServer(http.NotFoundHandler()) + defer server.Close() + + _, err := fetchRemotePolicy(server.URL + "/policy.rego") + + require.EqualError(t, err, "failed to fetch policy from "+server.URL+"/policy.rego: HTTP 404 Not Found") +} + +func TestServerSideRequestErrorNamesTheStatus(t *testing.T) { + require.EqualError(t, + serverSideRequestError(&requests.APIError{StatusCode: http.StatusForbidden, Message: "not entitled", HasServerMessage: true}), + "the Kosli server answered HTTP 403 Forbidden: not entitled") + require.EqualError(t, + serverSideRequestError(&requests.APIError{StatusCode: http.StatusNotFound}), + "the Kosli server answered HTTP 404 Not Found") + require.EqualError(t, + serverSideRequestError(&requests.APIError{StatusCode: http.StatusBadRequest, HasServerMessage: true}), + "the Kosli server answered HTTP 400 Bad Request") +} diff --git a/internal/bitbucket/bitbucket.go b/internal/bitbucket/bitbucket.go index d412476e5..84d1b2f1f 100644 --- a/internal/bitbucket/bitbucket.go +++ b/internal/bitbucket/bitbucket.go @@ -244,7 +244,7 @@ func (c *Config) getPullRequestDetailsFromBitbucket(prApiUrl, prHtmlLink, commit } } } else { - return evidence, fmt.Errorf("failed to get PR details, got HTTP status %d. Please review repository permissions", response.Resp.StatusCode) + return evidence, fmt.Errorf("failed to get PR details, got %s instead of HTTP 200 OK", requests.HTTPStatus(response.Resp.StatusCode)) } return evidence, nil } @@ -332,7 +332,7 @@ func (c *Config) getPullRequestCommitsFromBitbucket(prID int) ([]types.Commit, e return nil, err } if response.Resp.StatusCode != 200 { - return nil, fmt.Errorf("failed to get PR commits, got HTTP status %d", response.Resp.StatusCode) + return nil, fmt.Errorf("failed to get PR commits, got %s instead of HTTP 200 OK", requests.HTTPStatus(response.Resp.StatusCode)) } var responseData map[string]any diff --git a/internal/bitbucket/odd_replies_test.go b/internal/bitbucket/odd_replies_test.go index 83df38da1..e093de5fd 100644 --- a/internal/bitbucket/odd_replies_test.go +++ b/internal/bitbucket/odd_replies_test.go @@ -160,11 +160,21 @@ func (rt redirectTransport) RoundTrip(req *http.Request) (*http.Response, error) // runOddReplies serves replies and collects evidence for oddCommit through // the given entry point: 1 for PREvidenceForCommitV1, 2 for V2. func runOddReplies(t *testing.T, version int, replies map[string]string) ([]*types.PREvidence, error) { + t.Helper() + return runOddRepliesWithStatus(t, version, replies, nil) +} + +// runOddRepliesWithStatus is runOddReplies with the status of each named reply +// set by statuses; any other reply is a 200. +func runOddRepliesWithStatus(t *testing.T, version int, replies map[string]string, statuses map[string]int) ([]*types.PREvidence, error) { t.Helper() var base string server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { for name, route := range oddRoutes { if r.URL.RequestURI() == route { + if status, ok := statuses[name]; ok { + w.WriteHeader(status) + } _, _ = w.Write([]byte(strings.ReplaceAll(replies[name], "{{base}}", base))) return } @@ -423,3 +433,17 @@ func TestOddReplies_CommitWithNoHashFails(t *testing.T) { }) } } + +// A 201 or 202 passes the client as a success but is not the reply the code +// reads, so it fails, naming the status. +func TestOddReplies_ASuccessOtherThanOKIsNamed(t *testing.T) { + for name, want := range map[string]string{ + "pullrequest": "failed to get PR details, got HTTP 202 Accepted instead of HTTP 200 OK", + "pullrequest_commits_1": "failed to get PR commits, got HTTP 202 Accepted instead of HTTP 200 OK", + } { + t.Run(name, func(t *testing.T) { + _, err := runOddRepliesWithStatus(t, 2, oddBaselineReplies(), map[string]int{name: http.StatusAccepted}) + require.EqualError(t, err, want) + }) + } +} diff --git a/internal/evaluations/client_test.go b/internal/evaluations/client_test.go index dab5e7543..071679135 100644 --- a/internal/evaluations/client_test.go +++ b/internal/evaluations/client_test.go @@ -221,10 +221,10 @@ func TestCreateSurfacesTheServerMessageAndStatus(t *testing.T) { } // A 5xx is retryable, so the shared HTTP client consumes it: it exhausts the -// retries and reports giving up, discarding the response and the server's -// message with it. Pinned because the enqueue failure the API documents at 503 -// therefore cannot reach a user as its own sentence, and any caller wanting to -// name that failure has to say something of its own instead. +// retries and reports giving up with only the status. Pinned because the +// enqueue failure the API documents at 503 therefore cannot reach a user as its +// own sentence, and any caller wanting to name that failure has to say +// something of its own instead. func TestCreateLosesTheServerMessageOnAServerError(t *testing.T) { server, _ := newFakeServer(t, http.StatusServiceUnavailable, `{"message":"Evaluation '01JABCDEF' could not be queued"}`) @@ -238,6 +238,7 @@ func TestCreateLosesTheServerMessageOnAServerError(t *testing.T) { require.False(t, errors.As(err, &apiError), "a 5xx does not arrive as an API error") require.NotContains(t, err.Error(), "could not be queued") require.Contains(t, err.Error(), "giving up after") + require.Contains(t, err.Error(), "HTTP 503") } func TestCreateSendsNothingOnADryRun(t *testing.T) { diff --git a/internal/requests/requests.go b/internal/requests/requests.go index bc60ec893..3589a55ec 100644 --- a/internal/requests/requests.go +++ b/internal/requests/requests.go @@ -9,6 +9,7 @@ import ( "fmt" "io" "log" + "math/rand/v2" "mime/multipart" "net/http" "net/url" @@ -17,6 +18,7 @@ import ( "reflect" "regexp" "strings" + "time" retryablehttp "github.com/hashicorp/go-retryablehttp" "github.com/kosli-dev/cli/internal/logger" @@ -149,6 +151,8 @@ func NewKosliClient(httpProxyURL string, maxAPIRetries int, debug bool, logger * retryClient := retryablehttp.NewClient() retryClient.RetryMax = maxAPIRetries retryClient.CheckRetry = customCheckRetry + retryClient.ErrorHandler = giveUpErrorHandler + retryClient.Backoff = jitteredBackoff if debug { retryClient.Logger = &CustomLogger{ Logger: log.New(os.Stderr, "[debug]", log.Lmsgprefix), @@ -384,10 +388,7 @@ func (c *Client) Do(p *RequestParams) (*HTTPResponse, error) { err := json.Unmarshal([]byte(body), &respBody) if err != nil { c.Logger.Debug("response body from %s (status %d):\n%s", req.URL, resp.StatusCode, string(body)) - // Still carry the status code so callers can distinguish e.g. a 404 - // with an empty or non-JSON body (a proxy/CDN page). Keep the - // (JSON parse) error text as the message. - return nil, &APIError{StatusCode: resp.StatusCode, Message: err.Error()} + return nil, &APIError{StatusCode: resp.StatusCode, Message: nonJSONErrorMessage(resp.StatusCode, body, c.Debug)} } cleanedErrorMessage := "" hasServerMessage := false @@ -497,9 +498,9 @@ func s3ErrorMessage(status int, body []byte) string { Message string `xml:"Message"` } if err := xml.Unmarshal(body, &s3Error); err != nil || s3Error.Code == "" { - return fmt.Sprintf("upload refused with HTTP %d", status) + return "upload refused with " + HTTPStatus(status) } - return fmt.Sprintf("upload refused with HTTP %d: %s: %s", status, s3Error.Code, s3Error.Message) + return fmt.Sprintf("upload refused with %s: %s: %s", HTTPStatus(status), s3Error.Code, s3Error.Message) } func (c *Client) PayloadOutput(req *http.Request, jsonFields map[string]any, message string) error { @@ -546,6 +547,54 @@ func isSuccess(status int) bool { return false } +// nonJSONErrorMessage reports an error response whose body is not JSON, such as +// a proxy's HTML page, by its status: the decoder's complaint about the body +// tells the user nothing. +func nonJSONErrorMessage(status int, body []byte, debug bool) string { + switch { + case len(bytes.TrimSpace(body)) == 0: + return HTTPStatus(status) + case debug: + return HTTPStatus(status) + ": the response is not JSON" + default: + return HTTPStatus(status) + ": the response is not JSON, rerun with --debug to see it" + } +} + +// giveUpErrorHandler keeps the last response's status, which retryablehttp's +// default handler drops. The *url.Error that http.Client wraps it in names the +// method and URL. +func giveUpErrorHandler(resp *http.Response, err error, numTries int) (*http.Response, error) { + msg := fmt.Sprintf("giving up after %d attempt(s)", numTries) + if resp != nil { + _, _ = io.Copy(io.Discard, io.LimitReader(resp.Body, 4096)) + _ = resp.Body.Close() + msg += ": " + HTTPStatus(resp.StatusCode) + } + if err != nil { + return nil, fmt.Errorf("%s: %w", msg, err) + } + return nil, errors.New(msg) +} + +// HTTPStatus renders a code as "HTTP 409 Conflict", or "HTTP 599" for a code +// with no standard text. +func HTTPStatus(code int) string { + return strings.TrimSpace(fmt.Sprintf("HTTP %d %s", code, http.StatusText(code))) +} + +// jitteredBackoff stretches each wait by a random 0-50%, so clients that failed +// together do not retry in lockstep, without shortening the time before giving up. +// A wait that differs from the plain exponential one came from Retry-After and +// is kept as is. +func jitteredBackoff(minWait, maxWait time.Duration, attempt int, resp *http.Response) time.Duration { + exponential := retryablehttp.DefaultBackoff(minWait, maxWait, attempt, nil) + if wait := retryablehttp.DefaultBackoff(minWait, maxWait, attempt, resp); wait != exponential { + return wait + } + return min(exponential+rand.N(exponential/2+1), maxWait) +} + func customCheckRetry(ctx context.Context, resp *http.Response, err error) (bool, error) { // Get the default retry policy for errors and certain status codes. // It will retry on 5xx, 429 (rate limit) and we add 409 (lock conflict) via a custom check. diff --git a/internal/requests/requests_test.go b/internal/requests/requests_test.go index 8cece4fb3..39f1501e9 100644 --- a/internal/requests/requests_test.go +++ b/internal/requests/requests_test.go @@ -5,10 +5,13 @@ import ( "fmt" "io" "log" + "net" "net/http" "strings" "testing" + "time" + "github.com/hashicorp/go-retryablehttp" "github.com/kosli-dev/cli/internal/logger" "github.com/kosli-dev/cli/internal/version" "github.com/maxcnunes/httpfake" @@ -76,6 +79,10 @@ func (suite *RequestsTestSuite) SetupSuite() { Get("/fail/"). Reply(500). BodyString("server broken") + suite.fakeService.NewHandler(). + Get("/blank/"). + Reply(401). + BodyString("\r\n") suite.fakeService.NewHandler(). Get("/proxy-block/"). Reply(403). @@ -320,7 +327,7 @@ func (suite *RequestsTestSuite) TestDo() { URL: suite.fakeService.ResolveURL("/no-content/"), }, wantError: true, - expectedErrorMsg: "unexpected end of JSON input", + expectedErrorMsg: "HTTP 204 No Content", }, { name: "206 is not a success: a partial body is not the answer", @@ -329,7 +336,7 @@ func (suite *RequestsTestSuite) TestDo() { URL: suite.fakeService.ResolveURL("/partial/"), }, wantError: true, - expectedErrorMsg: "unexpected end of JSON input", + expectedErrorMsg: "HTTP 206 Partial Content: the response is not JSON, rerun with --debug to see it", }, { name: "GET request to 404 endpoint", @@ -347,7 +354,7 @@ func (suite *RequestsTestSuite) TestDo() { URL: suite.fakeService.ResolveURL("/locked/"), }, wantError: true, - expectedErrorMsg: fmt.Sprintf("Get \"%s\": GET %s giving up after 2 attempt(s)", suite.fakeService.ResolveURL("/locked/"), suite.fakeService.ResolveURL("/locked/")), + expectedErrorMsg: fmt.Sprintf("Get \"%s\": giving up after 2 attempt(s): HTTP 409 Conflict", suite.fakeService.ResolveURL("/locked/")), }, { name: "409 is not retried and is surfaced when DisableConflictRetry is set", @@ -366,7 +373,7 @@ func (suite *RequestsTestSuite) TestDo() { URL: suite.fakeService.ResolveURL("/fail/"), }, wantError: true, - expectedErrorMsg: fmt.Sprintf("Get \"%s\": GET %s giving up after 2 attempt(s)", suite.fakeService.ResolveURL("/fail/"), suite.fakeService.ResolveURL("/fail/")), + expectedErrorMsg: fmt.Sprintf("Get \"%s\": giving up after 2 attempt(s): HTTP 500 Internal Server Error", suite.fakeService.ResolveURL("/fail/")), }, { name: "GET request with invalid URL causes an error", @@ -427,13 +434,22 @@ func (suite *RequestsTestSuite) TestDo() { expectedErrorMsg: "Denied", }, { - name: "GET request to a PUT endpoint fails because of invalid response", + name: "GET to an unrouted path reports the status of the empty 404", params: &RequestParams{ Method: http.MethodGet, URL: suite.fakeService.ResolveURL("/html"), }, wantError: true, - expectedErrorMsg: "unexpected end of JSON input", + expectedErrorMsg: "HTTP 404 Not Found", + }, + { + name: "a whitespace-only body reports the status alone", + params: &RequestParams{ + Method: http.MethodGet, + URL: suite.fakeService.ResolveURL("/blank/"), + }, + wantError: true, + expectedErrorMsg: "HTTP 401 Unauthorized", }, { name: "non-JSON error response body is logged with debug enabled", @@ -443,7 +459,7 @@ func (suite *RequestsTestSuite) TestDo() { }, debug: true, wantError: true, - expectedErrorMsg: "invalid character '<' looking for beginning of value", + expectedErrorMsg: "HTTP 403 Forbidden: the response is not JSON", expectedLog: `

403 Forbidden

Blocked by proxy

`, }, } { @@ -676,6 +692,81 @@ func TestRequestsTestSuite(t *testing.T) { suite.Run(t, new(RequestsTestSuite)) } +func TestHTTPStatus(t *testing.T) { + require.Equal(t, "HTTP 429 Too Many Requests", HTTPStatus(http.StatusTooManyRequests)) + require.Equal(t, "HTTP 599", HTTPStatus(599)) +} + +func TestJitteredBackoff(t *testing.T) { + const minWait, maxWait = time.Second, 30 * time.Second + + t.Run("never waits less than the default backoff", func(t *testing.T) { + for attempt := range 4 { + wait := retryablehttp.DefaultBackoff(minWait, maxWait, attempt, nil) + for range 1000 { + got := jitteredBackoff(minWait, maxWait, attempt, nil) + require.GreaterOrEqual(t, got, wait) + require.LessOrEqual(t, got, wait+wait/2) + } + } + }) + + t.Run("spreads the waits of clients that failed together", func(t *testing.T) { + seen := map[time.Duration]bool{} + for range 100 { + seen[jitteredBackoff(minWait, maxWait, 2, nil)] = true + } + require.Greater(t, len(seen), 1) + }) + + t.Run("never waits longer than the maximum", func(t *testing.T) { + for range 1000 { + require.Equal(t, maxWait, jitteredBackoff(minWait, maxWait, 10, nil)) + } + }) + + for _, resp := range []*http.Response{ + {StatusCode: http.StatusConflict, Header: http.Header{"Retry-After": []string{"7"}}}, + {StatusCode: http.StatusTooManyRequests, Header: http.Header{"Retry-After": []string{"soon"}}}, + } { + t.Run(fmt.Sprintf("jitters a %d with a Retry-After the backoff ignores", resp.StatusCode), func(t *testing.T) { + wait := retryablehttp.DefaultBackoff(minWait, maxWait, 1, nil) + seen := map[time.Duration]bool{} + for range 100 { + got := jitteredBackoff(minWait, maxWait, 1, resp) + require.GreaterOrEqual(t, got, wait) + require.LessOrEqual(t, got, wait+wait/2) + seen[got] = true + } + require.Greater(t, len(seen), 1) + }) + } + + t.Run("keeps the wait the server asked for", func(t *testing.T) { + resp := &http.Response{ + StatusCode: http.StatusTooManyRequests, + Header: http.Header{"Retry-After": []string{"7"}}, + } + require.Equal(t, 7*time.Second, jitteredBackoff(minWait, maxWait, 0, resp)) + }) +} + +func TestDoKeepsTheTransportErrorWhenRetriesRunOut(t *testing.T) { + listener, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + url := "http://" + listener.Addr().String() + "/closed/" + require.NoError(t, listener.Close()) + + client, err := NewKosliClient("", 1, false, logger.NewStandardLogger()) + require.NoError(t, err) + _, err = client.Do(&RequestParams{Method: http.MethodGet, URL: url}) + + require.Error(t, err) + require.Contains(t, err.Error(), "giving up after 2 attempt(s): ") + require.Contains(t, err.Error(), "connection refused") + require.NotContains(t, err.Error(), "HTTP ") +} + // A misspelled form item type must fail rather than silently drop the part. func TestCreateMultipartRequestBodyRejectsAnUnknownItemType(t *testing.T) { _, _, _, err := createMultipartRequestBody([]FormItem{