investigation: add trace logger

Sources/ClientRuntime/Config/DefaultSDKRuntimeConfiguration.swift

@@ -91,7 +91,7 @@ public extension DefaultSDKRuntimeConfiguration {
     static func makeClient(
         httpClientConfiguration: HttpClientConfiguration = defaultHttpClientConfiguration
     ) -> HTTPClient {
-        #if os(iOS) || os(tvOS) || os(watchOS) || os(visionOS) || os(macOS)
+        #if os(iOS) || os(tvOS) || os(watchOS) || os(visionOS)
         return URLSessionHTTPClient(httpClientConfiguration: httpClientConfiguration)
         #else
         let connectTimeoutMs = httpClientConfiguration.connectTimeout.map { UInt32($0 * 1000) }

Sources/ClientRuntime/Interceptor/DefaultInterceptorContext.swift

@@ -8,6 +8,7 @@
 import class Smithy.Context
 import protocol Smithy.RequestMessage
 import protocol Smithy.ResponseMessage
+import struct Smithy.SwiftLogger
 
 /// Default implementation for all interceptor context types.
 ///
@@ -38,7 +39,7 @@ public class DefaultInterceptorContext<
         return self.attributes
     }
 
-    internal func setResult(result: Result<OutputType, Error>) {
+    internal func setResult(result: Result<OutputType, Error>?) {
         self.result = result
     }
 }
@@ -81,6 +82,8 @@ extension DefaultInterceptorContext: AfterDeserialization {
         case .success(let output):
             return output
         case .failure(let error):
+            let logger = SwiftLogger(label: "GetOutputLogger")
+            logger.info("ABOUT TO THROW AN ERROR \(error)")
             throw error
         }
     }

Sources/ClientRuntime/Networking/Http/CRT/CRTClientEngine.swift

@@ -206,6 +206,7 @@
 
             // START - smithy.client.http.connections.acquire_duration
             let acquireConnectionStart = Date().timeIntervalSinceReferenceDate
+            logger.info("TEST LOGGER WORKS BEFORE ACQUIRE CONNECTION")
             let connection = try await connectionMgr.acquireConnection()
             let acquireConnectionEnd = Date().timeIntervalSinceReferenceDate
             telemetry.connectionsAcquireDuration.record(
@@ -398,6 +399,8 @@
             defer {
                 span.end()
             }
+
+            // Attempt to get or create the connection manager
             let connectionMgr = try await serialExecutor.getOrCreateHTTP2ConnectionPool(endpoint: request.endpoint)
 
             self.logger.debug("Using HTTP/2 connection")
@@ -412,69 +415,83 @@
                     serverAddress: CRTClientEngine.makeServerAddress(request: request)
                 )
                 Task { [logger] in
-                    let stream: HTTP2Stream
-                    var acquireConnectionEnd: TimeInterval
                     do {
-                        // START - smithy.client.http.connections.acquire_duration
                         let acquireConnectionStart = Date().timeIntervalSinceReferenceDate
-                        stream = try await connectionMgr.acquireStream(requestOptions: requestOptions)
-                        acquireConnectionEnd = Date().timeIntervalSinceReferenceDate
+                        logger.info("TEST LOGGER WORKS BEFORE ACQUIRE STREAM")
+                        // Retry logic for acquiring the stream
+                        let stream = try await retryWithBackoff(maxRetries: 3, initialDelay: 2) {
+                            try await connectionMgr.acquireStream(requestOptions: requestOptions)
+                        }
+                        let acquireConnectionEnd = Date().timeIntervalSinceReferenceDate
+
+                        // Telemetry
                         telemetry.connectionsAcquireDuration.record(
                             value: acquireConnectionEnd - acquireConnectionStart,
                             attributes: Attributes(),
                             context: telemetryContext)
-                        // END - smithy.client.http.connections.acquire_duration
-                        let queuedEnd = acquireConnectionEnd
                         telemetry.requestsQueuedDuration.record(
-                            value: queuedEnd - queuedStart,
+                            value: acquireConnectionEnd - queuedStart,
                             attributes: Attributes(),
                             context: telemetryContext)
-                        // END - smithy.client.http.requests.queued_duration
+
+                        // Handle writing body and other tasks asynchronously
+                        Task {
+                            do {
+                                let connectionUptimeStart = acquireConnectionEnd
+                                defer {
+                                    telemetry.connectionsUptime.record(
+                                        value: Date().timeIntervalSinceReferenceDate - connectionUptimeStart,
+                                        attributes: Attributes(),
+                                        context: telemetryContext)
+                                }
+                                try await stream.write(
+                                    body: request.body,
+                                    telemetry: telemetry,
+                                    serverAddress: CRTClientEngine.makeServerAddress(request: request))
+                            } catch {
+                                logger.error("Error writing stream body: \(error.localizedDescription)")
+                            }
+                        }
                     } catch {
-                        logger.error(error.localizedDescription)
+                        logger.error("Failed to acquire stream: \(error.localizedDescription)")
+                        logger.info("(Logging) ERROR BEING RESUMED in executeHTTP2Request: \(error)")
+                        // Allow the error to propagate to the higher-level retry mechanism
                         wrappedContinuation.safeResume(error: error)
                         return
                     }
+                }
+            }
+        } catch {
+            // Surface any errors to the caller
+            logger.info("(Logging) ERROR BEING THROWN in executeHTTP2Request: \(error)")
+            throw error
+        }
+    }
 
-                    let connectionsLimit = serialExecutor.maxConnectionsPerEndpoint
-                    let connectionMgrMetrics = connectionMgr.fetchMetrics()
-                    telemetry.updateHTTPMetricsUsage { httpMetricsUsage in
-                        // TICK - smithy.client.http.connections.limit
-                        httpMetricsUsage.connectionsLimit = connectionsLimit
-
-                        // TICK - smithy.client.http.connections.usage
-                        httpMetricsUsage.idleConnections = connectionMgrMetrics.availableConcurrency
-                        httpMetricsUsage.acquiredConnections = connectionMgrMetrics.leasedConcurrency
-
-                        // TICK - smithy.client.http.requests.usage
-                        httpMetricsUsage.inflightRequests = connectionMgrMetrics.leasedConcurrency
-                        httpMetricsUsage.queuedRequests = connectionMgrMetrics.pendingConcurrencyAcquires
-                    }
+    // Helper function for retry logic
+    private func retryWithBackoff<T>(
+        maxRetries: Int,
+        initialDelay: TimeInterval,
+        task: @escaping () async throws -> T
+    ) async throws -> T {
+        var attempt = 0
+        var delay = initialDelay
 
-                    // At this point, continuation is resumed when the initial headers are received
-                    // it is now safe to write the body
-                    // writing is done in a separate task to avoid blocking the continuation
-                    // START - smithy.client.http.connections.uptime
-                    do {
-                        // DURATION - smithy.client.http.connections.uptime
-                        let connectionUptimeStart = acquireConnectionEnd
-                        defer {
-                            telemetry.connectionsUptime.record(
-                                value: Date().timeIntervalSinceReferenceDate - connectionUptimeStart,
-                                attributes: Attributes(),
-                                context: telemetryContext)
-                        }
-                        // TICK - smithy.client.http.bytes_sent
-                        try await stream.write(
-                            body: request.body,
-                            telemetry: telemetry,
-                            serverAddress: CRTClientEngine.makeServerAddress(request: request))
-                    } catch {
-                        logger.error(error.localizedDescription)
-                    }
+        while attempt < maxRetries {
+            do {
+                return try await task()
+            } catch {
+                if attempt >= maxRetries - 1 {
+                    throw error // Exhaust retries
                 }
+                let logger = SwiftLogger(label: "RetryAcquireStreamLogger")
+                logger.info("RETRYING ACQUIRE STREAM DUE TO \(error)")
+                await Task.sleep(UInt64(delay * 1_000_000_000)) // Delay before retry
+                delay *= 2 // Exponential backoff
+                attempt += 1
             }
         }
+        throw NSError(domain: "RetryError", code: 1, userInfo: [NSLocalizedDescriptionKey: "Max retries reached"])
     }
 
     /// Creates a `HTTPRequestOptions` object that can be used to make a HTTP request

Sources/ClientRuntime/Networking/Http/CRT/SDKDefaultIO.swift

@@ -26,7 +26,7 @@ public final class SDKDefaultIO: @unchecked Sendable {
     private init() {
         CommonRuntimeKit.initialize()
         do {
-            try Logger.initialize(target: .standardOutput, level: .none)
+            try Logger.initialize(target: .standardOutput, level: .trace)
         } catch CommonRunTimeError.crtError(let error)
                     where error.code == 6 && error.name == "AWS_ERROR_UNSUPPORTED_OPERATION" {
             // logger was already initialized, no need to initialize it

Sources/ClientRuntime/Orchestrator/Orchestrator.swift

@@ -14,6 +14,8 @@
 import SmithyHTTPAPI
 import protocol SmithyRetriesAPI.RetryStrategy
 import struct SmithyRetriesAPI.RetryErrorInfo
+import struct Smithy.SwiftLogger
+import enum AwsCommonRuntimeKit.CommonRunTimeError
 
 /// Orchestrates operation execution
 ///
@@ -256,29 +258,55 @@
     ) async {
         let copiedRequest = context.getRequest().toBuilder().build()
 
+        let logger = SwiftLogger(label: "startAttemptLogger")
+        logger.info("STARTING ATTEMPT")
         await attempt(context: context, attemptCount: attemptCount)
+        logger.info("ENDING ATTEMPT")
 
         do {
+            logger.info("ABOUT TO CALL getOutput() from START ATTEMPT")
             _ = try context.getOutput()
             await strategy.recordSuccess(token: token)
         } catch let error {
+            logger.info("ERROR CAUGHT HERE BEFORE RETRY ERROR INFO \(error)")
+            logger.info("RETRY PROVIDER: \(retryErrorInfoProvider)")
             // If we can't get errorInfo, we definitely can't retry
             guard let errorInfo = retryErrorInfoProvider(error) else { return }
 
-            // If the body is a nonseekable stream, we also can't retry
-            do {
-                guard try readyBodyForRetry(request: copiedRequest) else { return }
-            } catch {
-                return
+            logger.info("ERROR INFO: \(errorInfo)")
+
+            // Check if error is CRTError with code 2087
+            let skipReadyBodyCheck: Bool
+            if case CommonRunTimeError.crtError(let crtError) = error, crtError.code == 2087 {
+                skipReadyBodyCheck = true
+            } else {
+                skipReadyBodyCheck = false
+            }
+            logger.info("SKIP BODY CHECK: \(skipReadyBodyCheck)")
+
+            if !skipReadyBodyCheck {
+                // If the body is a nonseekable stream, we also can't retry
+                do {
+                    guard try readyBodyForRetry(request: copiedRequest) else { return }
+                } catch {
+                    logger.info("Body is a nonseekable stream, can't retry")
+                    return
+                }
+            } else {
+                logger.info("SKIPPING READY BODY FOR RETRY")
             }
 
             // When refreshing fails it throws, indicating we're done retrying
             do {
                 try await strategy.refreshRetryTokenForRetry(tokenToRenew: token, errorInfo: errorInfo)
             } catch {
+                logger.info("[retries] refresh failed")
                 return
             }
 
+            logger.info("RETRYING, starting attempt for real")
+            // clear previous error result
+            context.setResult(result: nil)
             context.updateRequest(updated: copiedRequest)
             await startAttempt(context: context, strategy: strategy, token: token, attemptCount: attemptCount + 1)
         }
@@ -289,8 +317,11 @@
     /// - Returns: `true` if the body of the request is safe to retry, `false` otherwise.  In general, a request body is retriable if it is not a stream, or
     ///   if the stream is seekable and successfully seeks to the start position / offset zero.
     private func readyBodyForRetry(request: RequestType) throws -> Bool {
+        let logger = SwiftLogger(label: "readyBodyForRetryLogger")
+        logger.info("ReadyBodyForRetry CALLED \(request.body)")
         switch request.body {
         case .stream(let stream):
+            logger.info("SEEKABLE? \(stream.isSeekable)")
             guard stream.isSeekable else { return false }
             do {
                 try stream.seek(toOffset: 0)
@@ -388,10 +419,13 @@
                 try await interceptors.modifyBeforeTransmit(context: context)
                 try await interceptors.readBeforeTransmit(context: context)
 
+                let logger = SwiftLogger(label: "attemptLogger")
+                logger.info("ABOUT TO EXECUTE")
                 let response = try await executeRequest.execute(
                     request: context.getRequest(),
                     attributes: context.getAttributes()
                 )
+                logger.info("EXECUTION COMPLETE")
                 context.updateResponse(updated: response)
 
                 try await interceptors.readAfterTransmit(context: context)
@@ -410,6 +444,8 @@
 
                 try await interceptors.readAfterDeserialization(context: context)
             } catch let error {
+                let logger = SwiftLogger(label: "caught attemptLogger")
+                logger.info("ERROR WAS CAUGHT IN ATTEMPT \(error)")
                 context.setResult(result: .failure(error))
             }
 
@@ -439,16 +475,20 @@
         } catch let error {
             context.setResult(result: .failure(error))
         }
+        let logger = SwiftLogger(label: "StartCompletionLogger")
+
 
         // The last error that occurred, if any, is thrown
         do {
+            logger.info("ABOUT TO CALL getOutput() from START COMPLETION")
             return try context.getOutput()
         } catch {
             // TICK - smithy.client.call.errors
             telemetry.rpcErrors.add(
                 value: 1,
                 attributes: telemetry.metricsAttributes,
                 context: telemetry.contextManager.current())
+            logger.info("ERROR WAS CAUGHT IN START COMPLETION \(error)")
             throw error
         }
     }

Sources/ClientRuntime/Retries/DefaultRetryErrorInfoProvider.swift

@@ -12,12 +12,15 @@ import protocol SmithyRetriesAPI.RetryErrorInfoProvider
 import struct Foundation.TimeInterval
 import class Foundation.NSError
 import var Foundation.NSURLErrorDomain
+import struct Smithy.SwiftLogger
 
 public enum DefaultRetryErrorInfoProvider: RetryErrorInfoProvider, Sendable {
     /// Returns information used to determine how & if to retry an error.
     /// - Parameter error: The error to be triaged for retry info
     /// - Returns: `RetryErrorInfo` for the passed error, or `nil` if the error should not be retried.
     public static func errorInfo(for error: Error) -> RetryErrorInfo? {
+        let logger = SwiftLogger(label: "DefaultRetryLogger")
+        logger.info("STUMBLED INTO DEFAULT RETRY")
         let retryableStatusCodes: [HTTPStatusCode] = [
             .internalServerError,  // 500
             .badGateway,           // 502