internal: true up internal metrics collection for post-SRA middleware (…

…#2642)

.changelog/ce369d28a2594b29aa49cd801c4ff959.json

@@ -0,0 +1,8 @@
+{
+    "id": "ce369d28-a259-4b29-aa49-cd801c4ff959",
+    "type": "bugfix",
+    "description": "Adjust internal metrics collection for revised authentication workflow.",
+    "modules": [
+        "."
+    ]
+}

aws/middleware/private/metrics/metrics.go

@@ -112,6 +112,8 @@ type MetricData struct {
 	ResolveEndpointStartTime   time.Time
 	ResolveEndpointEndTime     time.Time
 	EndpointResolutionDuration time.Duration
+	GetIdentityStartTime       time.Time
+	GetIdentityEndTime         time.Time
 	InThroughput               float64
 	OutThroughput              float64
 	RetryCount                 int
@@ -144,8 +146,6 @@ type AttemptMetrics struct {
 	ConnRequestedTime          time.Time
 	ConnObtainedTime           time.Time
 	ConcurrencyAcquireDuration time.Duration
-	CredentialFetchStartTime   time.Time
-	CredentialFetchEndTime     time.Time
 	SignStartTime              time.Time
 	SignEndTime                time.Time
 	SigningDuration            time.Duration

aws/middleware/private/metrics/metrics_test.go

@@ -109,8 +109,6 @@ func TestMetricData_ComputeRequestMetrics(t *testing.T) {
 			FirstByteTime:             time.Unix(1334, 0),
 			ConnRequestedTime:         time.Unix(1234, 0),
 			ConnObtainedTime:          time.Unix(1434, 0),
-			CredentialFetchStartTime:  time.Unix(1234, 0),
-			CredentialFetchEndTime:    time.Unix(1434, 0),
 			SignStartTime:             time.Unix(1234, 0),
 			SignEndTime:               time.Unix(1434, 0),
 			DeserializeStartTime:      time.Unix(1234, 0),
@@ -133,8 +131,6 @@ func TestMetricData_ComputeRequestMetrics(t *testing.T) {
 				FirstByteTime:             time.Unix(1334, 0),
 				ConnRequestedTime:         time.Unix(1234, 0),
 				ConnObtainedTime:          time.Unix(1434, 0),
-				CredentialFetchStartTime:  time.Unix(1234, 0),
-				CredentialFetchEndTime:    time.Unix(1434, 0),
 				SignStartTime:             time.Unix(1234, 0),
 				SignEndTime:               time.Unix(1434, 0),
 				DeserializeStartTime:      time.Unix(1234, 0),

aws/middleware/private/metrics/middleware/configuration.go

@@ -1,9 +1,10 @@
 package middleware
 
 import (
+	"net/http"
+
 	"github.com/aws/aws-sdk-go-v2/aws/middleware/private/metrics"
 	"github.com/aws/smithy-go/middleware"
-	"net/http"
 )
 
 func WithMetricMiddlewares(
@@ -20,10 +21,10 @@ func WithMetricMiddlewares(
 		if err := stack.Serialize.Add(GetRecordStackSerializeEndMiddleware(), middleware.After); err != nil {
 			return err
 		}
-		if err := stack.Serialize.Insert(GetRecordEndpointResolutionStartMiddleware(), "ResolveEndpoint", middleware.Before); err != nil {
+		if err := stack.Finalize.Insert(GetRecordEndpointResolutionStartMiddleware(), "ResolveEndpointV2", middleware.Before); err != nil {
 			return err
 		}
-		if err := stack.Serialize.Insert(GetRecordEndpointResolutionEndMiddleware(), "ResolveEndpoint", middleware.After); err != nil {
+		if err := stack.Finalize.Insert(GetRecordEndpointResolutionEndMiddleware(), "ResolveEndpointV2", middleware.After); err != nil {
 			return err
 		}
 		if err := stack.Build.Add(GetWrapDataStreamMiddleware(), middleware.After); err != nil {
@@ -47,6 +48,12 @@ func WithMetricMiddlewares(
 		if err := stack.Deserialize.Insert(GetTransportMetricsMiddleware(), "StackDeserializeStart", middleware.After); err != nil {
 			return err
 		}
+		if err := timeGetIdentity(stack); err != nil {
+			return err
+		}
+		if err := timeSigning(stack); err != nil {
+			return err
+		}
 		return nil
 	}
 }

aws/middleware/private/metrics/middleware/endpoint_resolution_end.go

@@ -6,6 +6,7 @@ package middleware
 
 import (
 	"context"
+
 	"github.com/aws/aws-sdk-go-v2/aws/middleware/private/metrics"
 	"github.com/aws/aws-sdk-go-v2/internal/sdk"
 	"github.com/aws/smithy-go/middleware"
@@ -21,6 +22,8 @@ func (m *EndpointResolutionEnd) ID() string {
 	return "EndpointResolutionEnd"
 }
 
+// Deprecated: Endpoint resolution now occurs in Finalize. The ResolveEndpoint
+// middleware remains in serialize but is largely a no-op.
 func (m *EndpointResolutionEnd) HandleSerialize(
 	ctx context.Context, in middleware.SerializeInput, next middleware.SerializeHandler,
 ) (
@@ -34,3 +37,13 @@ func (m *EndpointResolutionEnd) HandleSerialize(
 
 	return out, metadata, err
 }
+
+func (m *EndpointResolutionEnd) HandleFinalize(
+	ctx context.Context, in middleware.FinalizeInput, next middleware.FinalizeHandler,
+) (
+	middleware.FinalizeOutput, middleware.Metadata, error,
+) {
+	mctx := metrics.Context(ctx)
+	mctx.Data().ResolveEndpointEndTime = sdk.NowTime()
+	return next.HandleFinalize(ctx, in)
+}

aws/middleware/private/metrics/middleware/endpoint_resolution_start.go

@@ -6,6 +6,7 @@ package middleware
 
 import (
 	"context"
+
 	"github.com/aws/aws-sdk-go-v2/aws/middleware/private/metrics"
 	"github.com/aws/aws-sdk-go-v2/internal/sdk"
 	"github.com/aws/smithy-go/middleware"
@@ -21,6 +22,8 @@ func (m *EndpointResolutionStart) ID() string {
 	return "EndpointResolutionStart"
 }
 
+// Deprecated: Endpoint resolution now occurs in Finalize. The ResolveEndpoint
+// middleware remains in serialize but is largely a no-op.
 func (m *EndpointResolutionStart) HandleSerialize(
 	ctx context.Context, in middleware.SerializeInput, next middleware.SerializeHandler,
 ) (
@@ -34,3 +37,13 @@ func (m *EndpointResolutionStart) HandleSerialize(
 
 	return out, metadata, err
 }
+
+func (m *EndpointResolutionStart) HandleFinalize(
+	ctx context.Context, in middleware.FinalizeInput, next middleware.FinalizeHandler,
+) (
+	middleware.FinalizeOutput, middleware.Metadata, error,
+) {
+	mctx := metrics.Context(ctx)
+	mctx.Data().ResolveEndpointStartTime = sdk.NowTime()
+	return next.HandleFinalize(ctx, in)
+}

aws/middleware/private/metrics/middleware/identity.go

@@ -0,0 +1,47 @@
+package middleware
+
+import (
+	"context"
+
+	"github.com/aws/aws-sdk-go-v2/aws/middleware/private/metrics"
+	"github.com/aws/aws-sdk-go-v2/internal/sdk"
+	"github.com/aws/smithy-go/middleware"
+)
+
+func timeGetIdentity(stack *middleware.Stack) error {
+	if err := stack.Finalize.Insert(getIdentityStart{}, "GetIdentity", middleware.Before); err != nil {
+		return err
+	}
+	if err := stack.Finalize.Insert(getIdentityEnd{}, "GetIdentity", middleware.After); err != nil {
+		return err
+	}
+	return nil
+}
+
+type getIdentityStart struct{}
+
+func (m getIdentityStart) ID() string { return "getIdentityStart" }
+
+func (m getIdentityStart) HandleFinalize(
+	ctx context.Context, in middleware.FinalizeInput, next middleware.FinalizeHandler,
+) (
+	out middleware.FinalizeOutput, md middleware.Metadata, err error,
+) {
+	mctx := metrics.Context(ctx)
+	mctx.Data().GetIdentityStartTime = sdk.NowTime()
+	return next.HandleFinalize(ctx, in)
+}
+
+type getIdentityEnd struct{}
+
+func (m getIdentityEnd) ID() string { return "getIdentityEnd" }
+
+func (m getIdentityEnd) HandleFinalize(
+	ctx context.Context, in middleware.FinalizeInput, next middleware.FinalizeHandler,
+) (
+	out middleware.FinalizeOutput, md middleware.Metadata, err error,
+) {
+	mctx := metrics.Context(ctx)
+	mctx.Data().GetIdentityEndTime = sdk.NowTime()
+	return next.HandleFinalize(ctx, in)
+}

aws/middleware/private/metrics/middleware/signing.go

@@ -0,0 +1,57 @@
+package middleware
+
+import (
+	"context"
+
+	"github.com/aws/aws-sdk-go-v2/aws/middleware/private/metrics"
+	"github.com/aws/aws-sdk-go-v2/internal/sdk"
+	"github.com/aws/smithy-go/middleware"
+)
+
+func timeSigning(stack *middleware.Stack) error {
+	if err := stack.Finalize.Insert(signingStart{}, "Signing", middleware.Before); err != nil {
+		return err
+	}
+	if err := stack.Finalize.Insert(signingEnd{}, "Signing", middleware.After); err != nil {
+		return err
+	}
+	return nil
+}
+
+type signingStart struct{}
+
+func (m signingStart) ID() string { return "signingStart" }
+
+func (m signingStart) HandleFinalize(
+	ctx context.Context, in middleware.FinalizeInput, next middleware.FinalizeHandler,
+) (
+	out middleware.FinalizeOutput, md middleware.Metadata, err error,
+) {
+	mctx := metrics.Context(ctx)
+	attempt, err := mctx.Data().LatestAttempt()
+	if err != nil {
+		return out, md, err
+	}
+
+	attempt.SignStartTime = sdk.NowTime()
+	return next.HandleFinalize(ctx, in)
+}
+
+type signingEnd struct{}
+
+func (m signingEnd) ID() string { return "signingEnd" }
+
+func (m signingEnd) HandleFinalize(
+	ctx context.Context, in middleware.FinalizeInput, next middleware.FinalizeHandler,
+) (
+	out middleware.FinalizeOutput, md middleware.Metadata, err error,
+) {
+	mctx := metrics.Context(ctx)
+	attempt, err := mctx.Data().LatestAttempt()
+	if err != nil {
+		return out, md, err
+	}
+
+	attempt.SignEndTime = sdk.NowTime()
+	return next.HandleFinalize(ctx, in)
+}

aws/middleware/private/metrics/publisher/emf_test.go

@@ -78,8 +78,6 @@ func TestPostRequestMetrics(t *testing.T) {
 					FirstByteTime:             time.Unix(1234, 0),
 					ConnRequestedTime:         time.Unix(1234, 0),
 					ConnObtainedTime:          time.Unix(1434, 0),
-					CredentialFetchStartTime:  time.Unix(1234, 0),
-					CredentialFetchEndTime:    time.Unix(1434, 0),
 					SignStartTime:             time.Unix(1234, 0),
 					SignEndTime:               time.Unix(1434, 0),
 					DeserializeStartTime:      time.Unix(1234, 0),
@@ -102,8 +100,6 @@ func TestPostRequestMetrics(t *testing.T) {
 						FirstByteTime:             time.Unix(1234, 0),
 						ConnRequestedTime:         time.Unix(1234, 0),
 						ConnObtainedTime:          time.Unix(1434, 0),
-						CredentialFetchStartTime:  time.Unix(1234, 0),
-						CredentialFetchEndTime:    time.Unix(1434, 0),
 						SignStartTime:             time.Unix(1234, 0),
 						SignEndTime:               time.Unix(1434, 0),
 						DeserializeStartTime:      time.Unix(1234, 0),

aws/signer/v4/middleware.go

@@ -11,7 +11,6 @@ import (
 
 	"github.com/aws/aws-sdk-go-v2/aws"
 	awsmiddleware "github.com/aws/aws-sdk-go-v2/aws/middleware"
-	"github.com/aws/aws-sdk-go-v2/aws/middleware/private/metrics"
 	v4Internal "github.com/aws/aws-sdk-go-v2/aws/signer/internal/v4"
 	internalauth "github.com/aws/aws-sdk-go-v2/internal/auth"
 	"github.com/aws/aws-sdk-go-v2/internal/sdk"
@@ -301,22 +300,7 @@ func (s *SignHTTPRequestMiddleware) HandleFinalize(ctx context.Context, in middl
 		return out, metadata, &SigningError{Err: fmt.Errorf("computed payload hash missing from context")}
 	}
 
-	mctx := metrics.Context(ctx)
-
-	if mctx != nil {
-		if attempt, err := mctx.Data().LatestAttempt(); err == nil {
-			attempt.CredentialFetchStartTime = sdk.NowTime()
-		}
-	}
-
 	credentials, err := s.credentialsProvider.Retrieve(ctx)
-
-	if mctx != nil {
-		if attempt, err := mctx.Data().LatestAttempt(); err == nil {
-			attempt.CredentialFetchEndTime = sdk.NowTime()
-		}
-	}
-
 	if err != nil {
 		return out, metadata, &SigningError{Err: fmt.Errorf("failed to retrieve credentials: %w", err)}
 	}
@@ -337,20 +321,7 @@ func (s *SignHTTPRequestMiddleware) HandleFinalize(ctx context.Context, in middl
 		})
 	}
 
-	if mctx != nil {
-		if attempt, err := mctx.Data().LatestAttempt(); err == nil {
-			attempt.SignStartTime = sdk.NowTime()
-		}
-	}
-
 	err = s.signer.SignHTTP(ctx, credentials, req.Request, payloadHash, signingName, signingRegion, sdk.NowTime(), signerOptions...)
-
-	if mctx != nil {
-		if attempt, err := mctx.Data().LatestAttempt(); err == nil {
-			attempt.SignEndTime = sdk.NowTime()
-		}
-	}
-
 	if err != nil {
 		return out, metadata, &SigningError{Err: fmt.Errorf("failed to sign http request, %w", err)}
 	}