OperationQueue: log debug message when requests are found in cache …

…and skipped (#1926)

Right now there is no way to know when a request is being reused. If
this were to lead to a hard to debug issue, at lease we'll now have
evidence for this in the logs.

Sources/FoundationExtensions/OperationQueue+Extensions.swift

@@ -20,6 +20,7 @@ extension OperationQueue {
         case .firstCallbackAddedToList:
             self.addOperation(operation)
         case .addedToExistingInFlightList:
+            Logger.debug(Strings.network.reusing_existing_request_for_operation(operation))
             return
         }
     }

Sources/Logging/Strings/NetworkStrings.swift

@@ -19,6 +19,7 @@ enum NetworkStrings {
 
     case api_request_completed(_ request: HTTPRequest, httpCode: HTTPStatusCode)
     case api_request_started(HTTPRequest)
+    case reusing_existing_request_for_operation(CacheableNetworkOperation)
     case creating_json_error(error: String)
     case json_data_received(dataString: String)
     case parsing_json_error(error: Error)
@@ -45,6 +46,10 @@ extension NetworkStrings: CustomStringConvertible {
         case let .api_request_started(request):
             return "API request started: \(request.method.httpMethod) \(request.path.url?.path ?? "")"
 
+        case let .reusing_existing_request_for_operation(operation):
+            return "Network operation '\(type(of: operation))' found with the same cache key " +
+            "'\(operation.individualizedCacheKeyPart.prefix(15))...'. Skipping request."
+
         case let .creating_json_error(error):
             return "Error creating request with body: \(error)"
 

Tests/UnitTests/Networking/Backend/BackendGetOfferingsTests.swift

@@ -68,6 +68,24 @@ class BackendGetOfferingsTests: BaseBackendTests {
         expect(self.httpClient.calls).toEventually(haveCount(1))
     }
 
+    func testRepeatedRequestsLogDebugMessage() {
+        let logger = TestLogHandler()
+
+        self.httpClient.mock(
+            requestPath: .getOfferings(appUserID: Self.userID),
+            response: .init(statusCode: .success, response: Self.noOfferingsResponse as [String: Any])
+        )
+        self.offerings.getOfferings(appUserID: Self.userID, withRandomDelay: false) { _ in }
+        self.offerings.getOfferings(appUserID: Self.userID, withRandomDelay: false) { _ in }
+
+        expect(self.httpClient.calls).toEventually(haveCount(1))
+
+        logger.verifyMessageWasLogged(
+            "Network operation '\(GetOfferingsOperation.self)' found with the same cache key",
+            level: .debug
+        )
+    }
+
     func testGetEntitlementsDoesntCacheForMultipleUserID() {
         let response = MockHTTPClient.Response(statusCode: .success,
                                                response: Self.noOfferingsResponse as [String: Any])

Tests/UnitTests/Networking/Backend/__Snapshots__/BackendGetOfferingsTests/iOS12-testRepeatedRequestsLogDebugMessage.1.json

@@ -0,0 +1,10 @@
+{
+  "headers" : {
+    "Authorization" : "Bearer asharedsecret"
+  },
+  "request" : {
+    "body" : null,
+    "method" : "GET",
+    "url" : "https://api.revenuecat.com/v1/subscribers/user/offerings"
+  }
+}

Tests/UnitTests/Networking/Backend/__Snapshots__/BackendGetOfferingsTests/iOS13-testRepeatedRequestsLogDebugMessage.1.json

@@ -0,0 +1,10 @@
+{
+  "headers" : {
+    "Authorization" : "Bearer asharedsecret"
+  },
+  "request" : {
+    "body" : null,
+    "method" : "GET",
+    "url" : "https://api.revenuecat.com/v1/subscribers/user/offerings"
+  }
+}

Tests/UnitTests/Networking/Backend/__Snapshots__/BackendGetOfferingsTests/iOS14-testRepeatedRequestsLogDebugMessage.1.json

@@ -0,0 +1,10 @@
+{
+  "headers" : {
+    "Authorization" : "Bearer asharedsecret"
+  },
+  "request" : {
+    "body" : null,
+    "method" : "GET",
+    "url" : "https://api.revenuecat.com/v1/subscribers/user/offerings"
+  }
+}

Tests/UnitTests/Networking/Backend/__Snapshots__/BackendGetOfferingsTests/iOS15-testRepeatedRequestsLogDebugMessage.1.json

@@ -0,0 +1,10 @@
+{
+  "headers" : {
+    "Authorization" : "Bearer asharedsecret"
+  },
+  "request" : {
+    "body" : null,
+    "method" : "GET",
+    "url" : "https://api.revenuecat.com/v1/subscribers/user/offerings"
+  }
+}

Tests/UnitTests/Networking/Backend/__Snapshots__/BackendGetOfferingsTests/iOS16-testRepeatedRequestsLogDebugMessage.1.json

@@ -0,0 +1,10 @@
+{
+  "headers" : {
+    "Authorization" : "Bearer asharedsecret"
+  },
+  "request" : {
+    "body" : null,
+    "method" : "GET",
+    "url" : "https://api.revenuecat.com/v1/subscribers/user/offerings"
+  }
+}

Tests/UnitTests/TestHelpers/TestLogHandler.swift

@@ -87,7 +87,10 @@ extension TestLogHandler {
             line: line,
             self.messages
         )
-        .to(containElementSatisfying(Self.entryCondition(message: message, level: level)))
+        .to(
+            containElementSatisfying(Self.entryCondition(message: message, level: level)),
+            description: "Message not found. Logged messages: \(self.messages)"
+        )
     }
 
     func verifyMessageWasNotLogged(