Merge pull request #27 from checkout/PRISM-11093-log-the-breakdown-of-latency-metrics-by-operations-in-the-respective-events-on-risk-i-os

PRISM-11093 - Add latency metrics to logs

Author: precious-ossai-cko

Sources/Risk/Logging/LoggerService.swift

@@ -17,6 +17,18 @@ enum RiskEvent: String, Codable {
     case loadFailure = "riskLoadFailure"
 }
 
+struct Elapsed {
+    let block: Double? // time to retrieve configuration or loadFailure
+    let deviceDataPersist: Double? // time to persist data
+    let fpload: Double? // time to load fingerprint
+    let fppublish: Double? // time to publish fingerprint data
+    let total: Double? // total time
+
+    private enum CodingKeys: String, CodingKey {
+        case block = "Block", deviceDataPersist = "DeviceDataPersist", fpload = "FpLoad", fppublish = "FpPublish", total = "Total"
+    }
+}
+
 struct RiskLogError {
     let reason: String // service method
     let message: String // description of error
@@ -30,11 +42,11 @@ struct RiskLogError {
 
 protocol LoggerServiceProtocol {
     init(internalConfig: RiskSDKInternalConfig)
-    func log(riskEvent: RiskEvent, deviceSessionId: String?, requestId: String?, error: RiskLogError?)
+    func log(riskEvent: RiskEvent, blockTime: Double?, deviceDataPersistTime: Double?, fpLoadTime: Double?, fpPublishTime: Double?, deviceSessionId: String?, requestId: String?, error: RiskLogError?)
 }
 
 extension LoggerServiceProtocol {
-    func formatEvent(internalConfig: RiskSDKInternalConfig, riskEvent: RiskEvent, deviceSessionId: String?, requestId: String?, error: RiskLogError?) -> Event {
+    func formatEvent(internalConfig: RiskSDKInternalConfig, riskEvent: RiskEvent, deviceSessionId: String?, requestId: String?, error: RiskLogError?, latencyMetric: Elapsed) -> Event {
         let maskedPublicKey = getMaskedPublicKey(publicKey: internalConfig.merchantPublicKey)
         let ddTags = getDDTags(environment: internalConfig.environment.rawValue)
         var monitoringLevel: MonitoringLevel
@@ -56,17 +68,27 @@ extension LoggerServiceProtocol {
         switch riskEvent {
         case .published, .collected:
             properties = [
+                "Block": AnyCodable(latencyMetric.block),
+                "DeviceDataPersist": AnyCodable(latencyMetric.deviceDataPersist),
+                "FpLoad": AnyCodable(latencyMetric.fpload),
+                "FpPublish": AnyCodable(latencyMetric.fppublish),
+                "Total": AnyCodable(latencyMetric.total),
                 "EventType": AnyCodable(riskEvent.rawValue),
                 "FramesMode": AnyCodable(internalConfig.framesMode),
                 "MaskedPublicKey": AnyCodable(maskedPublicKey),
                 "ddTags": AnyCodable(ddTags),
                 "RiskSDKVersion": AnyCodable(Constants.riskSdkVersion),
                 "Timezone": AnyCodable(TimeZone.current.identifier),
-                "RequestId": AnyCodable(requestId),
+                "FpRequestId": AnyCodable(requestId),
                 "DeviceSessionId": AnyCodable(deviceSessionId),
             ]
         case .publishFailure, .loadFailure, .publishDisabled:
             properties = [
+                "Block": AnyCodable(latencyMetric.block),
+                "DeviceDataPersist": AnyCodable(latencyMetric.deviceDataPersist),
+                "FpLoad": AnyCodable(latencyMetric.fpload),
+                "FpPublish": AnyCodable(latencyMetric.fppublish),
+                "Total": AnyCodable(latencyMetric.total),
                 "EventType": AnyCodable(riskEvent.rawValue),
                 "FramesMode": AnyCodable(internalConfig.framesMode),
                 "MaskedPublicKey": AnyCodable(maskedPublicKey),
@@ -144,11 +166,16 @@ struct LoggerService: LoggerServiceProtocol {
 
     }
 
-    func log(riskEvent: RiskEvent, deviceSessionId: String? = nil, requestId: String? = nil, error: RiskLogError? = nil) {
-        let event = formatEvent(internalConfig: internalConfig, riskEvent: riskEvent, deviceSessionId: deviceSessionId, requestId: requestId, error: error)
+    func log(riskEvent: RiskEvent, blockTime: Double? = nil, deviceDataPersistTime: Double? = nil, fpLoadTime: Double? = nil, fpPublishTime: Double? = nil, deviceSessionId: String? = nil, requestId: String? = nil, error: RiskLogError? = nil) {
+        
+        let totalLatency = (blockTime ?? 0.00) + (deviceDataPersistTime ?? 0.00) + (fpLoadTime ?? 0.00) + (fpPublishTime ?? 0.00)
+        
+        let latencyMetric = Elapsed(block: blockTime, deviceDataPersist: deviceDataPersistTime, fpload: fpLoadTime, fppublish: fpPublishTime, total: totalLatency)
+        
+        let event = formatEvent(internalConfig: internalConfig, riskEvent: riskEvent, deviceSessionId: deviceSessionId, requestId: requestId, error: error, latencyMetric: latencyMetric)
         logger.log(event: event)
     }
-
+    
     private func getDeviceModel() -> String {
         #if targetEnvironment(simulator)
         if let identifier = ProcessInfo().environment["SIMULATOR_MODEL_IDENTIFIER"] {

Sources/Risk/Risk.swift

@@ -30,7 +30,8 @@ public final class Risk {
                 self.fingerprintService = FingerprintService(
                     fingerprintPublicKey: configuration.publicKey,
                     internalConfig: self.internalConfig,
-                    loggerService: self.loggerService
+                    loggerService: self.loggerService,
+                    blockTime: configuration.blockTime
                 )
                 completion(.success(()))
 
@@ -50,17 +51,17 @@ public final class Risk {
             guard let self = self else { return }
 
             switch fpResult {
-            case .success(let requestId):
-                self.persistFpData(cardToken: cardToken, fingerprintRequestId: requestId, completion: completion)
+            case .success(let response):
+                self.persistFpData(cardToken: cardToken, fingerprintRequestId: response.requestId, fpLoadTime: response.fpLoadTime, fpPublishTime: response.fpPublishTime, completion: completion)
 
             case .failure(let error):
                 completion(.failure(error))
             }
         }
     }
 
-    private func persistFpData(cardToken: String?, fingerprintRequestId: String, completion: @escaping (Result<PublishRiskData, RiskError.Publish>) -> Void) {
-        self.deviceDataService.persistFpData(fingerprintRequestId: fingerprintRequestId, cardToken: cardToken) { result in
+    private func persistFpData(cardToken: String?, fingerprintRequestId: String, fpLoadTime: Double, fpPublishTime: Double, completion: @escaping (Result<PublishRiskData, RiskError.Publish>) -> Void) {
+        self.deviceDataService.persistFpData(fingerprintRequestId: fingerprintRequestId, fpLoadTime: fpLoadTime, fpPublishTime: fpPublishTime, cardToken: cardToken) { result in
             switch result {
             case .success(let response):
                 completion(.success(PublishRiskData(deviceSessionId: response.deviceSessionId)))

Sources/Risk/Services/DeviceDataService.swift

@@ -7,6 +7,7 @@
 //
 
 import Foundation
+import QuartzCore
 
 struct FingerprintIntegration: Decodable, Equatable {
     let enabled: Bool
@@ -15,6 +16,7 @@ struct FingerprintIntegration: Decodable, Equatable {
 
 struct FingerprintConfiguration: Equatable {
     let publicKey: String
+    let blockTime: Double
 }
 
 struct DeviceDataConfiguration: Decodable, Equatable {
@@ -42,46 +44,50 @@ struct PersistDeviceDataResponse: Decodable, Equatable {
 
 protocol DeviceDataServiceProtocol {
     func getConfiguration(completion: @escaping (Result<FingerprintConfiguration, RiskError.Configuration>) -> Void)
-    func persistFpData(fingerprintRequestId: String, cardToken: String?, completion: @escaping (Result<PersistDeviceDataResponse, RiskError.Publish>) -> Void)
+    func persistFpData(fingerprintRequestId: String, fpLoadTime: Double, fpPublishTime: Double, cardToken: String?, completion: @escaping (Result<PersistDeviceDataResponse, RiskError.Publish>) -> Void)
 }
 
-struct DeviceDataService: DeviceDataServiceProtocol {
+final class DeviceDataService: DeviceDataServiceProtocol {
     let config: RiskSDKInternalConfig
     let apiService: APIServiceProtocol
     let loggerService: LoggerServiceProtocol
+    var blockTime: Double
 
     init(config: RiskSDKInternalConfig, apiService: APIServiceProtocol = APIService(), loggerService: LoggerServiceProtocol) {
         self.config = config
         self.apiService = apiService
         self.loggerService = loggerService
+        self.blockTime = 0.00
     }
 
     func getConfiguration(completion: @escaping (Result<FingerprintConfiguration, RiskError.Configuration>) -> Void) {
+        let startBlockTime = CACurrentMediaTime()
         let endpoint = "\(config.deviceDataEndpoint)/configuration?integrationType=\(config.integrationType.rawValue)&riskSdkVersion=\(Constants.riskSdkVersion)&timezone=\(TimeZone.current.identifier)"
         let authToken = config.merchantPublicKey
 
         apiService.getJSONFromAPIWithAuthorization(endpoint: endpoint, authToken: authToken, responseType: DeviceDataConfiguration.self) {
             result in
             switch result {
             case .success(let configuration):
-                
+                let endBlockTime = CACurrentMediaTime()
+                self.blockTime = (endBlockTime - startBlockTime) * 1000
                 guard configuration.fingerprintIntegration.enabled, let fingerprintPublicKey = configuration.fingerprintIntegration.publicKey else {
-                    loggerService.log(riskEvent: .publishDisabled, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "getConfiguration", message: RiskError.Configuration.integrationDisabled.localizedDescription, status: nil, type: "Error"))
+                    self.loggerService.log(riskEvent: .publishDisabled, blockTime: self.blockTime, deviceDataPersistTime: nil, fpLoadTime: nil, fpPublishTime: nil, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "getConfiguration", message: RiskError.Configuration.integrationDisabled.localizedDescription, status: nil, type: "Error"))
 
                     return completion(.failure(.integrationDisabled))
                 }
 
                 completion(.success(
-                    FingerprintConfiguration.init(publicKey: fingerprintPublicKey)))
+                    FingerprintConfiguration.init(publicKey: fingerprintPublicKey, blockTime: self.blockTime)))
             case .failure(let error):
-                
-                loggerService.log(riskEvent: .loadFailure, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "getConfiguration", message: error.localizedDescription, status: nil, type: "Error"))
+                self.loggerService.log(riskEvent: .loadFailure, blockTime: nil, deviceDataPersistTime: nil, fpLoadTime: nil, fpPublishTime: nil, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "getConfiguration", message: error.localizedDescription, status: nil, type: "Error"))
                 return completion(.failure(.couldNotRetrieveConfiguration))
             }
         }
     }
 
-    func persistFpData(fingerprintRequestId: String, cardToken: String?, completion: @escaping (Result<PersistDeviceDataResponse, RiskError.Publish>) -> Void) {
+    func persistFpData(fingerprintRequestId: String, fpLoadTime: Double, fpPublishTime: Double, cardToken: String?, completion: @escaping (Result<PersistDeviceDataResponse, RiskError.Publish>) -> Void) {
+        let startPersistTime = CACurrentMediaTime()
         let endpoint = "\(config.deviceDataEndpoint)/fingerprint?riskSdkVersion=\(Constants.riskSdkVersion)"
         let authToken = config.merchantPublicKey
         let integrationType = config.integrationType
@@ -96,11 +102,13 @@ struct DeviceDataService: DeviceDataServiceProtocol {
 
             switch result {
             case .success(let response):
-                loggerService.log(riskEvent: .published, deviceSessionId: response.deviceSessionId, requestId: fingerprintRequestId, error: nil)
+                let endPersistTime = CACurrentMediaTime()
+                let persistTime = (endPersistTime - startPersistTime) * 1000
+                self.loggerService.log(riskEvent: .published, blockTime: self.blockTime, deviceDataPersistTime: persistTime, fpLoadTime: fpLoadTime, fpPublishTime: fpPublishTime, deviceSessionId: response.deviceSessionId, requestId: fingerprintRequestId, error: nil)
 
                 completion(.success(response))
             case .failure(let error):
-                loggerService.log(riskEvent: .publishFailure, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "persistFpData", message: error.localizedDescription, status: nil, type: "Error"))
+                self.loggerService.log(riskEvent: .publishFailure, blockTime: self.blockTime, deviceDataPersistTime: nil, fpLoadTime: fpLoadTime, fpPublishTime: fpPublishTime, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "persistFpData", message: error.localizedDescription, status: nil, type: "Error"))
 
                 completion(.failure(.couldNotPersisRiskData))
             }

Sources/Risk/Services/FingerprintService.swift

@@ -7,9 +7,10 @@
 
 import FingerprintPro
 import Foundation
+import QuartzCore
 
 protocol FingerprintServiceProtocol {
-    func publishData(completion: @escaping (Result<String, RiskError.Publish>) -> Void)
+    func publishData(completion: @escaping (Result<FpPublishData, RiskError.Publish>) -> Void)
 }
 
 extension FingerprintServiceProtocol {
@@ -22,24 +23,41 @@ extension FingerprintServiceProtocol {
     }
 }
 
+struct FpPublishData {
+    let requestId: String
+    let fpLoadTime: Double
+    let fpPublishTime: Double
+}
+
 final class FingerprintService: FingerprintServiceProtocol {
     private var requestId: String?
     private let client: FingerprintClientProviding
     private let internalConfig: RiskSDKInternalConfig
     private let loggerService: LoggerServiceProtocol
+    private let fpLoadTime: Double
+    private var fpPublishTime: Double
+    private let blockTime: Double
 
-    init(fingerprintPublicKey: String, internalConfig: RiskSDKInternalConfig, loggerService: LoggerServiceProtocol) {
+    init(fingerprintPublicKey: String, internalConfig: RiskSDKInternalConfig, loggerService: LoggerServiceProtocol, blockTime: Double) {
+        
+        let startBlockTime = CACurrentMediaTime()
+        
         let customDomain: Region = .custom(domain: internalConfig.fingerprintEndpoint)
         let configuration = Configuration(apiKey: fingerprintPublicKey, region: customDomain)
         client = FingerprintProFactory.getInstance(configuration)
+        let endBlockTime = CACurrentMediaTime()
+        self.fpLoadTime = (endBlockTime - startBlockTime) * 1000
+        self.fpPublishTime = 0.00
+        self.blockTime = blockTime
         self.internalConfig = internalConfig
         self.loggerService = loggerService
     }
 
-    func publishData(completion: @escaping (Result<String, RiskError.Publish>) -> Void) {
+    func publishData(completion: @escaping (Result<FpPublishData, RiskError.Publish>) -> Void) {
+        let startFpPublishTime = CACurrentMediaTime()
 
         guard requestId == nil else {
-            return completion(.success(requestId!))
+            return completion(.success(FpPublishData(requestId: requestId!, fpLoadTime: self.fpLoadTime, fpPublishTime: self.fpPublishTime)))
         }
 
         let metadata = createMetadata(sourceType: internalConfig.sourceType.rawValue)
@@ -48,14 +66,16 @@ final class FingerprintService: FingerprintServiceProtocol {
 
             switch result {
             case .failure(let error):
-                self?.loggerService.log(riskEvent: .publishFailure, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "publishData", message: error.localizedDescription, status: nil, type: "Error"))
+                self?.loggerService.log(riskEvent: .publishFailure, blockTime: self?.blockTime, deviceDataPersistTime: nil, fpLoadTime: self?.fpLoadTime, fpPublishTime: nil, deviceSessionId: nil, requestId: nil, error: RiskLogError(reason: "publishData", message: error.localizedDescription, status: nil, type: "Error"))
 
                 return completion(.failure(.couldNotPublishRiskData))
             case let .success(response):
-                self?.loggerService.log(riskEvent: .collected, deviceSessionId: nil, requestId: response.requestId, error: nil)
+                let endFpPublishTime = CACurrentMediaTime()
+                self?.fpPublishTime = (endFpPublishTime - startFpPublishTime) * 1000
+                self?.loggerService.log(riskEvent: .collected, blockTime: self?.blockTime, deviceDataPersistTime: nil, fpLoadTime: self?.fpLoadTime, fpPublishTime: self?.fpPublishTime, deviceSessionId: nil, requestId: response.requestId, error: nil)
                 self?.requestId = response.requestId
 
-                completion(.success(response.requestId))
+                completion(.success(FpPublishData(requestId: response.requestId, fpLoadTime: self?.fpLoadTime ?? 0.00, fpPublishTime: self?.fpPublishTime ?? 0.00)))
             }
         }
     }

Tests/Mocks/MockDeviceDataService.swift

@@ -14,14 +14,14 @@ class MockDeviceDataService: DeviceDataServiceProtocol {
 
     func getConfiguration(completion: @escaping (Result<FingerprintConfiguration, RiskError.Configuration>) -> Void) {
         if shouldReturnConfiguration {
-            let configuration = FingerprintConfiguration(publicKey: "mocked_public_key")
+            let configuration = FingerprintConfiguration(publicKey: "mocked_public_key", blockTime: 123.00)
             completion(.success(configuration))
         } else {
             completion(.failure(.couldNotRetrieveConfiguration))
         }
     }
-
-    func persistFpData(fingerprintRequestId: String, cardToken: String?, completion: @escaping (Result<PersistDeviceDataResponse, RiskError.Publish>) -> Void) {
+    
+    func persistFpData(fingerprintRequestId: String, fpLoadTime: Double, fpPublishTime: Double, cardToken: String?, completion: @escaping (Result<PersistDeviceDataResponse, RiskError.Publish>) -> Void) {
         if shouldSucceedPersistFpData {
             let response = PersistDeviceDataResponse(deviceSessionId: "mocked_device_session_id")
             completion(.success(response))

Tests/Mocks/MockFingerprintService.swift

@@ -12,13 +12,13 @@ class MockFingerprintService: FingerprintServiceProtocol {
     var shouldSucceed: Bool = true
     var requestId: String?
 
-    func publishData(completion: @escaping (Result<String, RiskError.Publish>) -> Void) {
+    func publishData(completion: @escaping (Result<FpPublishData, RiskError.Publish>) -> Void) {
         if shouldSucceed {
             if let requestId = requestId {
-                completion(.success(requestId))
+                completion(.success(FpPublishData(requestId: requestId, fpLoadTime: 123.00, fpPublishTime: 321.00)))
             } else {
                 let fakeRequestId = "fakeRequestId"
-                completion(.success(fakeRequestId))
+                completion(.success(FpPublishData(requestId: fakeRequestId, fpLoadTime: 123.00, fpPublishTime: 321.00)))
             }
         } else {
             completion(.failure(.couldNotPublishRiskData))

Tests/Mocks/MockLoggerService.swift

@@ -8,5 +8,5 @@ struct MockLoggerService: LoggerServiceProtocol {
 
     init(internalConfig: RiskSDKInternalConfig) {}
 
-    func log(riskEvent: RiskEvent, deviceSessionId: String?, requestId: String?, error: RiskLogError?) {}
+    func log(riskEvent: RiskEvent, blockTime: Double?, deviceDataPersistTime: Double?, fpLoadTime: Double?, fpPublishTime: Double?, deviceSessionId: String?, requestId: String?, error: RiskLogError?) {}
 }