Skip to content

Commit

Permalink
Add an ability to set context-specific logger for RetryableRoundTripper
Browse files Browse the repository at this point in the history
vasayxtx committed Nov 11, 2024

Verified

This commit was created on GitHub.com and signed with GitHub’s verified signature. The key has expired.
1 parent 7bf23f5 commit 50c7173
Showing 3 changed files with 142 additions and 19 deletions.
6 changes: 6 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
@@ -16,6 +16,12 @@ The project includes the following packages:
+ [service](./service) - ready-to-use primitives for creating services and managing their lifecycle.
+ [testutil](./testutil) - helpers for writing tests.

## Installation

```
go get -u github.com/acronis/go-appkit
```

## Examples

### Simple service that provides HTTP API
85 changes: 66 additions & 19 deletions httpclient/retryable_round_tripper.go
Original file line number Diff line number Diff line change
@@ -37,44 +37,76 @@ const UnlimitedRetryAttempts = -1
const RetryAttemptNumberHeader = "X-Retry-Attempt"

// CheckRetryFunc is a function that is called right after RoundTrip() method
// and determines if next retry attempt is needed.
// and determines if the next retry attempt is needed.
type CheckRetryFunc func(ctx context.Context, resp *http.Response, roundTripErr error, doneRetryAttempts int) (bool, error)

// RetryableRoundTripper wraps an object that implements http.RoundTripper interface
// and provides retrying mechanism for HTTP requests.
// and provides a retrying mechanism for HTTP requests.
type RetryableRoundTripper struct {
// Delegate is an object that implements http.RoundTripper interface
// and is used for sending HTTP requests under the hood.
Delegate http.RoundTripper
Logger log.FieldLogger

// Logger is used for logging.
// When it's necessary to use context-specific logger, LoggerProvider should be used instead.
Logger log.FieldLogger

// LoggerProvider is a function that provides a context-specific logger.
// One of the typical use cases is to use a retryable client in the context of a request handler,
// where the logger should produce logs with request-specific information (e.g., request ID).
LoggerProvider func(ctx context.Context) log.FieldLogger

// MaxRetryAttempts determines how many maximum retry attempts can be done.
// The total number of sending HTTP request may be MaxRetryAttempts + 1 (the first request is not a retry attempt).
// If its value is UnlimitedRetryAttempts, it's supposed that retries mechanism will be stopped by BackoffPolicy.
// If its value is UnlimitedRetryAttempts, it's supposed that retry mechanism will be stopped by BackoffPolicy.
// By default, DefaultMaxRetryAttempts const is used.
MaxRetryAttempts int

// CheckRetry is called right after RoundTrip() method and determines if next retry attempt is needed.
// CheckRetry is called right after RoundTrip() method and determines if the next retry attempt is needed.
// By default, DefaultCheckRetry function is used.
CheckRetry CheckRetryFunc

// IgnoreRetryAfter determines if Retry-After HTTP header of the response is parsed and
// used as a wait time before doing next retry attempt.
// used as a wait time before doing the next retry attempt.
// If it's true or response doesn't contain Retry-After HTTP header, BackoffPolicy will be used for computing delay.
IgnoreRetryAfter bool

// BackoffPolicy is used for computing wait time before doing next retry attempt when the given response doesn't contain
// Retry-After HTTP header or IgnoreRetryAfter is true.
// BackoffPolicy is used for computing wait time before doing the next retry attempt
// when the given response doesn't contain Retry-After HTTP header or IgnoreRetryAfter is true.
// By default, DefaultBackoffPolicy is used.
BackoffPolicy retry.Policy
}

// RetryableRoundTripperOpts represents an options for RetryableRoundTripper.
// See documentation for RetryableRoundTripper fields for details.
type RetryableRoundTripperOpts struct {
Logger log.FieldLogger
// Logger is used for logging.
// When it's necessary to use context-specific logger, LoggerProvider should be used instead.
Logger log.FieldLogger

// LoggerProvider is a function that provides a context-specific logger.
// One of the typical use cases is to use a retryable client in the context of a request handler,
// where the logger should produce logs with request-specific information (e.g., request ID).
LoggerProvider func(ctx context.Context) log.FieldLogger

// MaxRetryAttempts determines how many maximum retry attempts can be done.
// The total number of sending HTTP request may be MaxRetryAttempts + 1 (the first request is not a retry attempt).
// If its value is UnlimitedRetryAttempts, it's supposed that retry mechanism will be stopped by BackoffPolicy.
// By default, DefaultMaxRetryAttempts const is used.
MaxRetryAttempts int
CheckRetryFunc CheckRetryFunc

// CheckRetry is called right after RoundTrip() method and determines if the next retry attempt is needed.
// By default, DefaultCheckRetry function is used.
CheckRetryFunc CheckRetryFunc

// IgnoreRetryAfter determines if Retry-After HTTP header of the response is parsed and
// used as a wait time before doing the next retry attempt.
// If it's true or response doesn't contain Retry-After HTTP header, BackoffPolicy will be used for computing delay.
IgnoreRetryAfter bool
BackoffPolicy retry.Policy

// BackoffPolicy is used for computing wait time before doing the next retry attempt
// when the given response doesn't contain Retry-After HTTP header or IgnoreRetryAfter is true.
// By default, DefaultBackoffPolicy is used.
BackoffPolicy retry.Policy
}

// NewRetryableRoundTripper returns a new instance of RetryableRoundTripper.
@@ -108,6 +140,7 @@ func NewRetryableRoundTripperWithOpts(
return &RetryableRoundTripper{
Delegate: delegate,
Logger: opts.Logger,
LoggerProvider: opts.LoggerProvider,
MaxRetryAttempts: opts.MaxRetryAttempts,
CheckRetry: opts.CheckRetryFunc,
BackoffPolicy: opts.BackoffPolicy,
@@ -144,13 +177,15 @@ func (rt *RetryableRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
if curRetryAttemptNum == 0 {
return nil, &RetryableRoundTripperError{Inner: rewindErr}
}
rt.Logger.Error("failed to rewind request body between retry attempts", log.Error(rewindErr))
rt.logger(reqCtx).Error(fmt.Sprintf(
"failed to rewind request body between retry attempts, %d request(s) done", curRetryAttemptNum+1),
log.Error(rewindErr))
return resp, roundTripErr
}

// Discard and close response body before next retry.
if resp != nil && roundTripErr == nil {
rt.drainResponseBody(resp)
rt.drainResponseBody(reqCtx, resp)
}

if curRetryAttemptNum > 0 {
@@ -166,7 +201,9 @@ func (rt *RetryableRoundTripper) RoundTrip(req *http.Request) (*http.Response, e
// Check if another retry attempt should be done
needRetry, checkRetryErr := rt.CheckRetry(reqCtx, resp, roundTripErr, curRetryAttemptNum)
if checkRetryErr != nil {
rt.Logger.Error("failed to check if retry is needed", log.Error(checkRetryErr))
rt.logger(reqCtx).Error(fmt.Sprintf(
"failed to check if retry is needed, %d request(s) done", curRetryAttemptNum+1),
log.Error(checkRetryErr))
return resp, roundTripErr
}
if !needRetry {
@@ -175,6 +212,8 @@ func (rt *RetryableRoundTripper) RoundTrip(req *http.Request) (*http.Response, e

// Check should we stop (max attempts exceeded or by backoff policy).
if rt.MaxRetryAttempts > 0 && curRetryAttemptNum >= rt.MaxRetryAttempts {
rt.logger(reqCtx).Warnf("max retry attempts exceeded (%d), %d request(s) done",
rt.MaxRetryAttempts, curRetryAttemptNum+1)
return resp, roundTripErr
}
waitTime, stop := getNextWaitTime(resp)
@@ -184,7 +223,8 @@ func (rt *RetryableRoundTripper) RoundTrip(req *http.Request) (*http.Response, e

select {
case <-reqCtx.Done():
rt.Logger.Error("context canceled while waiting for retry attempt", log.Error(reqCtx.Err()))
rt.logger(reqCtx).Warnf("context canceled (%v) while waiting for the next retry attempt, %d request(s) done",
reqCtx.Err(), curRetryAttemptNum+1)
return resp, roundTripErr
case <-time.After(waitTime):
}
@@ -206,15 +246,22 @@ func (rt *RetryableRoundTripper) makeNextWaitTimeProvider() waitTimeProvider {
}
}

func (rt *RetryableRoundTripper) drainResponseBody(resp *http.Response) {
func (rt *RetryableRoundTripper) drainResponseBody(ctx context.Context, resp *http.Response) {
defer func() {
if closeErr := resp.Body.Close(); closeErr != nil {
rt.Logger.Error("failed to close previous response body between retry attempts", log.Error(closeErr))
rt.logger(ctx).Error("failed to close previous response body between retry attempts", log.Error(closeErr))
}
}()
if _, err := io.Copy(io.Discard, resp.Body); err != nil {
rt.Logger.Error("failed to discard previous response body between retry attempts", log.Error(err))
rt.logger(ctx).Error("failed to discard previous response body between retry attempts", log.Error(err))
}
}

func (rt *RetryableRoundTripper) logger(ctx context.Context) log.FieldLogger {
if rt.LoggerProvider != nil {
return rt.LoggerProvider(ctx)
}
return rt.Logger
}

// RetryableRoundTripperError is returned in RoundTrip method of RetryableRoundTripper
70 changes: 70 additions & 0 deletions httpclient/retryable_round_tripper_test.go
Original file line number Diff line number Diff line change
@@ -8,6 +8,8 @@ package httpclient

import (
"bytes"
"context"
"errors"
"io"
"net/http"
"net/http/httptest"
@@ -21,6 +23,8 @@ import (
"github.com/cenkalti/backoff/v4"
"github.com/stretchr/testify/require"

"github.com/acronis/go-appkit/log"
"github.com/acronis/go-appkit/log/logtest"
"github.com/acronis/go-appkit/retry"
)

@@ -431,3 +435,69 @@ func TestCheckErrorIsTemporary(t *testing.T) {
})
}
}

func TestRetryableRoundTripper_RoundTrip_Logging(t *testing.T) {
srv := httptest.NewServer(http.HandlerFunc(func(wr http.ResponseWriter, req *http.Request) {
wr.WriteHeader(http.StatusServiceUnavailable)
}))
defer srv.Close()

type ctxKey string
const ctxKeyLogger ctxKey = "keyLogger"

internalErr := errors.New("internal error")

doRequestAndCheckLogs := func(t *testing.T, client *http.Client, req *http.Request, logRecorder *logtest.Recorder) {
resp, err := client.Do(req)
require.NoError(t, err)
require.Equal(t, http.StatusServiceUnavailable, resp.StatusCode)
require.NoError(t, resp.Body.Close())

require.Len(t, logRecorder.Entries(), 1)
require.Equal(t, "failed to check if retry is needed, 1 request(s) done", logRecorder.Entries()[0].Text)
logField, found := logRecorder.Entries()[0].FindField("error")
require.True(t, found)
require.Equal(t, internalErr, logField.Any)
}

t.Run("logger", func(t *testing.T) {
logRecorder := logtest.NewRecorder()

var rt http.RoundTripper
rt = http.DefaultTransport.(*http.Transport).Clone()
rt, err := NewRetryableRoundTripperWithOpts(rt, RetryableRoundTripperOpts{
Logger: logRecorder,
CheckRetryFunc: func(ctx context.Context, resp *http.Response, roundTripErr error, doneRetryAttempts int) (bool, error) {
return false, internalErr
},
})
require.NoError(t, err)

req, err := http.NewRequest(http.MethodGet, srv.URL, nil)
require.NoError(t, err)

doRequestAndCheckLogs(t, &http.Client{Transport: rt}, req, logRecorder)
})

t.Run("logger from context", func(t *testing.T) {
logRecorder := logtest.NewRecorder()

var rt http.RoundTripper
rt = http.DefaultTransport.(*http.Transport).Clone()
rt, err := NewRetryableRoundTripperWithOpts(rt, RetryableRoundTripperOpts{
LoggerProvider: func(ctx context.Context) log.FieldLogger {
return ctx.Value(ctxKeyLogger).(log.FieldLogger)
},
CheckRetryFunc: func(ctx context.Context, resp *http.Response, roundTripErr error, doneRetryAttempts int) (bool, error) {
return false, internalErr
},
})
require.NoError(t, err)

req, err := http.NewRequest(http.MethodGet, srv.URL, nil)
require.NoError(t, err)
req = req.WithContext(context.WithValue(req.Context(), ctxKeyLogger, logRecorder))

doRequestAndCheckLogs(t, &http.Client{Transport: rt}, req, logRecorder)
})
}

0 comments on commit 50c7173

Please sign in to comment.