HTTPClient: verbose logs for request IDs (#3320)

See https://github.com/RevenueCat/khepri/pull/6798.
This can help debug issues as it helps us cross-reference requests on
our end.

### Changes:
- Logging `X-Request-ID` and `X-Amzn-Trace-ID` headers if present (only
in verbose mode)
- Logging these even for failed requests
- Also logging `request_handled_by_load_shedder` for failed requests
- To accomplish that. `HTTPURLResponse` now conforms to our
`HTTPResponseType`, this allows us to extract headers in an uniform way

### Example:
```
[network] DEBUG: ℹ️ API request completed: GET '/v1/subscribers/$RCAnonymousID%3Ad9dc4f3b33054cf28c0f2ec9da0f48d5' (304)
Request-ID: 'be534c50-5231-403b-be2f-7c077861751d'; Amzn-Trace-ID: 'Root=1-6532c6ca-7ef80f961ec9c4145484df13'
```

Sources/FoundationExtensions/OperationQueue+Extensions.swift

@@ -30,7 +30,7 @@ extension OperationQueue {
             Logger.debug(
                 Strings.network.reusing_existing_request_for_operation(
                     T.self,
-                    Logger.logLevel == .verbose
+                    Logger.verboseLogsEnabled
                     ? factory.cacheKey
                     : factory.cacheKey.prefix(15) + "…"
                 )

Sources/Logging/Logger.swift

@@ -69,6 +69,12 @@ struct Logger {
 
 }
 
+extension Logger {
+
+    static var verboseLogsEnabled: Bool { self.logLevel == .verbose }
+
+}
+
 // MARK: - LoggerType implementation
 
 /// `Logger` can be used both with static or instance methods.

Sources/Logging/Strings/NetworkStrings.swift

@@ -18,8 +18,15 @@ import Foundation
 enum NetworkStrings {
 
     case api_request_started(HTTPRequest)
-    case api_request_completed(_ request: HTTPRequest, httpCode: HTTPStatusCode)
-    case api_request_failed(_ request: HTTPRequest, httpCode: HTTPStatusCode?, error: NetworkError)
+    case api_request_completed(
+        _ request: HTTPRequest,
+        httpCode: HTTPStatusCode,
+        metadata: HTTPClient.ResponseMetadata?
+    )
+    case api_request_failed(_ request: HTTPRequest,
+                            httpCode: HTTPStatusCode?,
+                            error: NetworkError,
+                            metadata: HTTPClient.ResponseMetadata?)
     case api_request_failed_status_code(HTTPStatusCode)
     case reusing_existing_request_for_operation(CacheableNetworkOperation.Type, String)
     case enqueing_operation(CacheableNetworkOperation.Type, cacheKey: String)
@@ -51,13 +58,25 @@ extension NetworkStrings: LogMessage {
         case let .api_request_started(request):
             return "API request started: \(request.description)"
 
-        case let .api_request_completed(request, httpCode):
-            return "API request completed: \(request.description) (\(httpCode.rawValue))"
+        case let .api_request_completed(request, httpCode, metadata):
+            let prefix = "API request completed: \(request.description) (\(httpCode.rawValue))"
 
-        case let .api_request_failed(request, statusCode, error):
-            return "API request failed: \(request.description) (\(statusCode?.rawValue.description ?? "<>")): " +
+            if let metadata {
+                return prefix + "\n" + metadata.description
+            } else {
+                return prefix
+            }
+
+        case let .api_request_failed(request, statusCode, error, metadata):
+            let prefix = "API request failed: \(request.description) (\(statusCode?.rawValue.description ?? "<>")): " +
             "\(error.description)"
 
+            if let metadata {
+                return prefix + "\n" + metadata.description
+            } else {
+                return prefix
+            }
+
         case let .api_request_failed_status_code(statusCode):
             return "API request failed with status code \(statusCode.rawValue)"
 
@@ -132,3 +151,12 @@ private extension HTTPRequest {
     }
 
 }
+
+private extension HTTPClient.ResponseMetadata {
+
+    var description: String {
+        return "Request-ID: '\(self.requestID ?? "")'; " +
+        "Amzn-Trace-ID: '\(self.amazonTraceID ?? "")'"
+    }
+
+}

Sources/Networking/HTTPClient/ETagManager.swift

@@ -81,7 +81,7 @@ class ETagManager {
     func httpResultFromCacheOrBackend(with response: VerifiedHTTPResponse<Data?>,
                                       request: URLRequest,
                                       retried: Bool) -> VerifiedHTTPResponse<Data>? {
-        let statusCode: HTTPStatusCode = response.statusCode
+        let statusCode: HTTPStatusCode = response.httpStatusCode
         let resultFromBackend = response.asOptionalResponse
 
         guard let eTagInResponse = response.value(forHeaderField: Self.eTagResponseHeader) else {
@@ -172,7 +172,7 @@ private extension ETagManager {
                 self.storeIfPossible(
                     Response(
                         eTag: eTag,
-                        statusCode: response.statusCode,
+                        statusCode: response.httpStatusCode,
                         data: data,
                         verificationResult: response.verificationResult
                     ),
@@ -257,7 +257,7 @@ extension ETagManager.Response {
         responseVerificationResult: VerificationResult
     ) -> VerifiedHTTPResponse<Data> {
         return HTTPResponse(
-            statusCode: self.statusCode,
+            httpStatusCode: self.statusCode,
             responseHeaders: headers,
             body: self.data,
             requestDate: requestDate
@@ -280,10 +280,10 @@ private extension VerifiedHTTPResponse {
 
     var shouldStore: Bool {
         return (
-            self.statusCode != .notModified &&
+            self.httpStatusCode != .notModified &&
             // Note that we do want to store 400 responses to help the server
             // If the request was wrong, it will also be wrong the next time.
-            !self.statusCode.isServerError &&
+            !self.httpStatusCode.isServerError &&
             self.verificationResult.shouldStore
         )
     }

Sources/Networking/HTTPClient/HTTPClient.swift

@@ -130,6 +130,8 @@ extension HTTPClient {
         case requestDate = "X-RevenueCat-Request-Time"
         case contentType = "Content-Type"
         case isLoadShedder = "X-RevenueCat-Fortress"
+        case requestID = "X-Request-ID"
+        case amazonTraceID = "X-Amzn-Trace-ID"
 
     }
 
@@ -323,7 +325,7 @@ private extension HTTPClient {
                 if let response = response, response.verificationResult == .failed {
                     if case .enforced = request.verificationMode {
                         return .failure(.signatureVerificationFailed(path: request.httpRequest.path,
-                                                                     code: response.statusCode))
+                                                                     code: response.httpStatusCode))
                     } else {
                         // Any other mode gets forwarded as a success, but we log the error
                         Logger.error(Strings.signing.request_failed_verification(request.httpRequest))
@@ -353,23 +355,35 @@ private extension HTTPClient {
         )
 
         if let response = response {
+            let httpURLResponse = urlResponse as? HTTPURLResponse
+
             switch response {
             case let .success(response):
                 Logger.debug(Strings.network.api_request_completed(
                     request.httpRequest,
                     // Getting status code from the original response to detect 304s
                     // If that can't be extracted, get status code from the parsed response.
-                    httpCode: urlResponse?.httpStatusCode ?? response.statusCode
+                    httpCode: httpURLResponse?.httpStatusCode ?? response.httpStatusCode,
+                    metadata: Logger.verboseLogsEnabled ? response.metadata : nil
                 ))
 
                 if response.isLoadShedder {
                     Logger.debug(Strings.network.request_handled_by_load_shedder(request.httpRequest.path))
                 }
 
             case let .failure(error):
-                Logger.debug(Strings.network.api_request_failed(request.httpRequest,
-                                                                httpCode: urlResponse?.httpStatusCode,
-                                                                error: error))
+                let httpURLResponse = urlResponse as? HTTPURLResponse
+
+                Logger.debug(Strings.network.api_request_failed(
+                    request.httpRequest,
+                    httpCode: httpURLResponse?.httpStatusCode,
+                    error: error,
+                    metadata: httpURLResponse?.metadata)
+                )
+
+                if httpURLResponse?.isLoadShedder == true {
+                    Logger.debug(Strings.network.request_handled_by_load_shedder(request.httpRequest.path))
+                }
             }
 
             request.completionHandler?(response)
@@ -470,6 +484,16 @@ private extension HTTPClient {
 
 // MARK: - Extensions
 
+extension HTTPClient {
+
+    /// Information from a response to help identify a request.
+    struct ResponseMetadata {
+        var requestID: String?
+        var amazonTraceID: String?
+    }
+
+}
+
 extension HTTPRequest {
 
     func requestAddingNonceIfRequired(
@@ -550,7 +574,7 @@ extension Result where Success == Data?, Failure == NetworkError {
         return self.flatMap { body in
             return .success(
                 .init(
-                    statusCode: .init(rawValue: response.statusCode),
+                    httpStatusCode: response.httpStatusCode,
                     responseHeaders: response.allHeaderFields,
                     body: body
                 )
@@ -583,7 +607,7 @@ extension Result where Success == VerifiedHTTPResponse<Data>, Failure == Network
     // Converts an unsuccessful response into a `Result.failure`
     fileprivate func convertUnsuccessfulResponseToError() -> Self {
         return self.flatMap {
-            $0.response.statusCode.isSuccessfulResponse
+            $0.response.httpStatusCode.isSuccessfulResponse
             ? .success($0)
             : .failure($0.response.parseUnsuccessfulResponse())
         }
@@ -602,8 +626,19 @@ private extension VerifiedHTTPResponse {
         }
     }
 
+}
+
+private extension HTTPResponseType {
+
     var isLoadShedder: Bool {
-        return self.response.value(forHeaderField: HTTPClient.ResponseHeader.isLoadShedder) == "true"
+        return self.value(forHeaderField: HTTPClient.ResponseHeader.isLoadShedder) == "true"
+    }
+
+    var metadata: HTTPClient.ResponseMetadata {
+        return .init(
+            requestID: self.value(forHeaderField: HTTPClient.ResponseHeader.requestID),
+            amazonTraceID: self.value(forHeaderField: HTTPClient.ResponseHeader.amazonTraceID)
+        )
     }
 
 }
@@ -618,7 +653,7 @@ private extension HTTPResponse where Body == Data {
             isJSON
                 ? .from(self.body)
                 : .defaultResponse,
-            self.statusCode
+            self.httpStatusCode
         )
     }
 

Sources/Networking/HTTPClient/HTTPResponse.swift

@@ -22,7 +22,7 @@ protocol HTTPResponseType {
     typealias Result = Swift.Result<Self, NetworkError>
     typealias Headers = [AnyHashable: Any]
 
-    var statusCode: HTTPStatusCode { get }
+    var httpStatusCode: HTTPStatusCode { get }
     /// Because this property is a standard Swift dictionary, its keys are case-sensitive.
     /// To perform a case-insensitive header lookup, use the `value(forHeaderField:)` method instead.
     var responseHeaders: HTTPClient.ResponseHeaders { get }
@@ -33,7 +33,7 @@ protocol HTTPResponseType {
 
 struct HTTPResponse<Body: HTTPResponseBody>: HTTPResponseType {
 
-    var statusCode: HTTPStatusCode
+    var httpStatusCode: HTTPStatusCode
     var responseHeaders: HTTPClient.ResponseHeaders
     var body: Body
     var requestDate: Date?
@@ -53,7 +53,7 @@ extension HTTPResponse: CustomStringConvertible {
     var description: String {
         return """
         HTTPResponse(
-            statusCode: \(self.statusCode.rawValue),
+            statusCode: \(self.httpStatusCode.rawValue),
             body: \(self.bodyDescription),
             requestDate: \(self.requestDate?.description ?? "<>")
         )
@@ -75,15 +75,15 @@ struct VerifiedHTTPResponse<Body: HTTPResponseBody>: HTTPResponseType {
     }
 
     init(
-        statusCode: HTTPStatusCode,
+        httpStatusCode: HTTPStatusCode,
         responseHeaders: HTTPClient.ResponseHeaders,
         body: Body,
         requestDate: Date? = nil,
         verificationResult: VerificationResult
     ) {
         self.init(
             response: .init(
-                statusCode: statusCode,
+                httpStatusCode: httpStatusCode,
                 responseHeaders: responseHeaders,
                 body: body,
                 requestDate: requestDate
@@ -99,7 +99,7 @@ extension VerifiedHTTPResponse: CustomStringConvertible {
     var description: String {
         return """
         VerifiedHTTPResponse(
-            statusCode: \(self.statusCode.rawValue),
+            statusCode: \(self.httpStatusCode.rawValue),
             body: \(self.response.bodyDescription),
             requestDate: \(self.requestDate?.description ?? "<>")
             verification: \(self.verificationResult)
@@ -109,6 +109,23 @@ extension VerifiedHTTPResponse: CustomStringConvertible {
 
 }
 
+// MARK: - URLResponse
+
+/// `HTTPURLResponse` conformance to `HTTPResponseType`
+extension HTTPURLResponse: HTTPResponseType {
+
+    typealias Body = Data?
+
+    var httpStatusCode: HTTPStatusCode { .init(rawValue: self.statusCode) }
+
+    var responseHeaders: HTTPClient.ResponseHeaders { return self.allHeaderFields }
+
+    var body: Data? { return nil }
+
+    var requestDate: Date? { HTTPResponse<Data>.parseRequestDate(headers: self.responseHeaders) }
+
+}
+
 // MARK: - Extensions
 
 extension HTTPResponseType {
@@ -153,7 +170,7 @@ extension VerifiedHTTPResponse where Body: OptionalType, Body.Wrapped: HTTPRespo
 extension HTTPResponse {
 
     func mapBody<NewBody>(_ mapping: (Body) throws -> NewBody) rethrows -> HTTPResponse<NewBody> {
-        return .init(statusCode: self.statusCode,
+        return .init(httpStatusCode: self.httpStatusCode,
                      responseHeaders: self.responseHeaders,
                      body: try mapping(self.body),
                      requestDate: self.requestDate)
@@ -172,17 +189,17 @@ extension HTTPResponse {
 
     /// Creates an `HTTPResponse` extracting the `requestDate` from its headers
     init(
-        statusCode: HTTPStatusCode,
+        httpStatusCode: HTTPStatusCode,
         responseHeaders: HTTPClient.ResponseHeaders,
         body: Body
     ) {
-        self.statusCode = statusCode
+        self.httpStatusCode = httpStatusCode
         self.responseHeaders = responseHeaders
         self.body = body
         self.requestDate = Self.parseRequestDate(headers: responseHeaders)
     }
 
-    private static func parseRequestDate(headers: Self.Headers) -> Date? {
+    fileprivate static func parseRequestDate(headers: HTTPResponseType.Headers) -> Date? {
         guard let stringValue = Self.value(
             forCaseInsensitiveHeaderField: HTTPClient.ResponseHeader.requestDate.rawValue,
             in: headers
@@ -196,7 +213,7 @@ extension HTTPResponse {
 
 extension VerifiedHTTPResponse {
 
-    var statusCode: HTTPStatusCode { self.response.statusCode }
+    var httpStatusCode: HTTPStatusCode { self.response.httpStatusCode }
     var responseHeaders: HTTPClient.ResponseHeaders { self.response.responseHeaders }
     var body: Body { self.response.body }
     var requestDate: Date? { self.response.requestDate }

Sources/Networking/HTTPClient/HTTPStatusCode.swift

@@ -101,13 +101,3 @@ extension HTTPStatusCode {
     }
 
 }
-
-extension URLResponse {
-
-    var httpStatusCode: HTTPStatusCode? {
-        guard let response = self as? HTTPURLResponse else { return nil }
-
-        return .init(rawValue: response.statusCode)
-    }
-
-}

Sources/Networking/Operations/Handling/CustomerInfoResponseHandler.swift

@@ -32,7 +32,7 @@ class CustomerInfoResponseHandler {
                 if !response.body.errorResponse.attributeErrors.isEmpty {
                     // If there are any, log attribute errors.
                     // Creating the error implicitly logs it.
-                    _ = response.body.errorResponse.asBackendError(with: response.statusCode)
+                    _ = response.body.errorResponse.asBackendError(with: response.httpStatusCode)
                 }
 
                 return response.body.customerInfo.copy(with: response.verificationResult)

Sources/Networking/Operations/LogInOperation.swift

@@ -84,7 +84,7 @@ private extension LogInOperation {
             .map { response in
                 (
                     response.body.copy(with: response.verificationResult),
-                    created: response.statusCode == .createdSuccess
+                    created: response.httpStatusCode == .createdSuccess
                 )
             }
             .mapError(BackendError.networkError)