AWS Client Loggers and Client Log Mode Support (aws#872)

aws/config.go

@@ -1,6 +1,9 @@
 package aws
 
-import "github.com/awslabs/smithy-go/middleware"
+import (
+	"github.com/awslabs/smithy-go/logging"
+	"github.com/awslabs/smithy-go/middleware"
+)
 
 // A Config provides service configuration for service clients.
 type Config struct {
@@ -43,6 +46,18 @@ type Config struct {
 	// client requests will be handled. This is useful for adding additional
 	// tracing data to a request, or changing behavior of the SDK's client.
 	APIOptions []func(*middleware.Stack) error
+
+	// The logger writer interface to write logging messages to. Defaults to
+	// standard error.
+	Logger logging.Logger
+
+	// Configures the events that will be sent to the configured logger.
+	// This can be used to configure the logging of signing, retries, request, and responses
+	// of the SDK clients.
+	//
+	// See the ClientLogMode type documentation for the complete set of logging modes and available
+	// configuration.
+	ClientLogMode ClientLogMode
 }
 
 // NewConfig returns a new Config pointer that can be chained with builder

aws/doc.go

@@ -58,4 +58,5 @@ package aws
 // generate.go uses a build tag of "ignore", go run doesn't need to specify
 // this because go run ignores all build flags when running a go file directly.
 //go:generate go run -tags codegen generate.go
+//go:generate go run -tags codegen logging_generate.go
 //go:generate gofmt -w -s .

aws/logging_generate.go

@@ -0,0 +1,76 @@
+// +build clientlogmode
+
+package main
+
+import (
+	"log"
+	"os"
+	"text/template"
+)
+
+var config = struct {
+	ModeBits []string
+}{
+	// Items should be appended only to keep bit-flag positions stable
+	ModeBits: []string{
+		"Signing",
+		"Retries",
+		"Request",
+		"RequestWithBody",
+		"Response",
+		"ResponseWithBody",
+	},
+}
+
+var tmpl = template.Must(template.New("ClientLogMode").Funcs(map[string]interface{}{
+	"symbolName": func(name string) string {
+		return "Log" + name
+	},
+}).Parse(`// Code generated by aws/logging_generate.go DO NOT EDIT.
+package aws
+
+// ClientLogMode represents the logging mode of SDK clients. The client logging mode is a bit-field where
+// each bit is a flag that describes the logging behavior for one or more client components.
+// The entire 64-bit group is reserved for later expansion by the SDK.
+//
+// Example: Setting ClientLogMode to enable logging of retries and requests
+//  clientLogMode := aws.LogRetries | aws.LogRequest
+//
+// Example: Adding an additional log mode to an existing ClientLogMode value
+//  clientLogMode |= aws.LogResponse
+type ClientLogMode uint64
+
+// Supported ClientLogMode bits that can be configured to toggle logging of specific SDK events.
+const (
+{{- range $index, $field := .ModeBits }}
+	{{ (symbolName $field) }}{{- if (eq 0 $index) }} ClientLogMode = 1 << (64 - 1 - iota){{- end }}
+{{- end }}
+)
+
+{{ range $_, $field := .ModeBits }}
+// Is{{- $field }} returns whether the {{ $field }} logging mode bit is set
+func (m ClientLogMode) Is{{- $field }}() bool {
+	return m&{{- (symbolName $field) }} != 0
+}
+{{ end }}
+
+{{ range $_, $field := .ModeBits }}
+// Clear{{- $field }} clears the {{ $field }} logging mode bit
+func (m *ClientLogMode) Clear{{- $field }}() {
+	*m &^= {{- (symbolName $field) }}
+}
+{{ end }}
+`))
+
+func main() {
+	file, err := os.Create("logging.go")
+	if err != nil {
+		log.Fatal(err)
+	}
+	defer file.Close()
+
+	err = tmpl.Execute(file, config)
+	if err != nil {
+		log.Fatal(err)
+	}
+}

aws/retry/middleware.go

@@ -10,6 +10,7 @@ import (
 	"github.com/aws/aws-sdk-go-v2/aws"
 	awsmiddle "github.com/aws/aws-sdk-go-v2/aws/middleware"
 	"github.com/aws/aws-sdk-go-v2/internal/sdk"
+	"github.com/awslabs/smithy-go/logging"
 	smithymiddle "github.com/awslabs/smithy-go/middleware"
 	"github.com/awslabs/smithy-go/transport/http"
 )
@@ -30,20 +31,35 @@ type retryMetadataKey struct{}
 // Attempt is a Smithy FinalizeMiddleware that handles retry attempts using the provided
 // Retryer implementation
 type Attempt struct {
+	// Enable the logging of retry attempts performed by the SDK.
+	// This will include logging retry attempts, unretryable errors, and when max attempts are reached.
+	LogAttempts bool
+
 	retryer       Retryer
 	requestCloner RequestCloner
 }
 
 // NewAttemptMiddleware returns a new Attempt
-func NewAttemptMiddleware(retryer Retryer, requestCloner RequestCloner) *Attempt {
-	return &Attempt{retryer: retryer, requestCloner: requestCloner}
+func NewAttemptMiddleware(retryer Retryer, requestCloner RequestCloner, optFns ...func(*Attempt)) *Attempt {
+	m := &Attempt{retryer: retryer, requestCloner: requestCloner}
+	for _, fn := range optFns {
+		fn(m)
+	}
+	return m
 }
 
 // ID returns the middleware identifier
 func (r *Attempt) ID() string {
 	return "Retry"
 }
 
+func (r Attempt) logf(logger logging.Logger, classification logging.Classification, format string, v ...interface{}) {
+	if !r.LogAttempts {
+		return
+	}
+	logger.Logf(classification, format, v...)
+}
+
 // HandleFinalize utilizes the provider Retryer implementation to attempt retries over the next handler
 func (r Attempt) HandleFinalize(ctx context.Context, in smithymiddle.FinalizeInput, next smithymiddle.FinalizeHandler) (
 	out smithymiddle.FinalizeOutput, metadata smithymiddle.Metadata, err error,
@@ -55,6 +71,9 @@ func (r Attempt) HandleFinalize(ctx context.Context, in smithymiddle.FinalizeInp
 
 	relRetryToken := r.retryer.GetInitialToken()
 
+	logger := smithymiddle.GetLogger(ctx)
+	service, operation := awsmiddle.GetServiceID(ctx), awsmiddle.GetOperationName(ctx)
+
 	for {
 		attemptNum++
 
@@ -74,21 +93,28 @@ func (r Attempt) HandleFinalize(ctx context.Context, in smithymiddle.FinalizeInp
 					return out, metadata, fmt.Errorf("failed to rewind transport stream for retry, %w", err)
 				}
 			}
+
+			r.logf(logger, logging.Debug, "retrying request %s/%s, attempt %d", service, operation, attemptNum)
 		}
 
 		out, metadata, reqErr := next.HandleFinalize(attemptCtx, attemptInput)
 
-		relRetryToken(reqErr)
+		if releaseError := relRetryToken(reqErr); releaseError != nil && reqErr != nil {
+			return out, metadata, fmt.Errorf("failed to release token after request error, %v", reqErr)
+		}
+
 		if reqErr == nil {
 			return out, metadata, nil
 		}
 
 		retryable := r.retryer.IsErrorRetryable(reqErr)
 		if !retryable {
+			r.logf(logger, logging.Debug, "request failed with unretryable error %v", reqErr)
 			return out, metadata, reqErr
 		}
 
 		if maxAttempts > 0 && attemptNum >= maxAttempts {
+			r.logf(logger, logging.Debug, "max retry attempts exhausted, max %d", maxAttempts)
 			err = &MaxAttemptsError{
 				Attempt: attemptNum,
 				Err:     reqErr,
@@ -179,11 +205,18 @@ func setRetryMetadata(ctx context.Context, metadata retryMetadata) context.Conte
 // associated middleware.
 type AddRetryMiddlewaresOptions struct {
 	Retryer Retryer
+
+	// Enable the logging of retry attempts performed by the SDK.
+	// This will include logging retry attempts, unretryable errors, and when max attempts are reached.
+	LogRetryAttempts bool
 }
 
 // AddRetryMiddlewares adds retry middleware to operation middleware stack
 func AddRetryMiddlewares(stack *smithymiddle.Stack, options AddRetryMiddlewaresOptions) error {
-	attempt := NewAttemptMiddleware(options.Retryer, http.RequestCloner)
+	attempt := NewAttemptMiddleware(options.Retryer, http.RequestCloner, func(middleware *Attempt) {
+		middleware.LogAttempts = options.LogRetryAttempts
+	})
+
 	if err := stack.Finalize.Add(attempt, smithymiddle.After); err != nil {
 		return err
 	}