diff --git a/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionLogic.swift b/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionLogic.swift index dd3d8b532..6f971b237 100644 --- a/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionLogic.swift +++ b/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionLogic.swift @@ -30,16 +30,27 @@ public protocol AdClickAttributionLogicDelegate: AnyObject { public class AdClickAttributionLogic { - public enum State { + public enum State: CustomDebugStringConvertible { case noAttribution - case preparingAttribution(vendor: String, session: SessionInfo, completionBlocks: [(() -> Void)]) + case preparingAttribution(vendor: String, session: SessionInfo, requestID: UUID, completionBlocks: [(() -> Void)]) case activeAttribution(vendor: String, session: SessionInfo, rules: ContentBlockerRulesManager.Rules) var isActiveAttribution: Bool { if case .activeAttribution = self { return true } return false } + + public var debugDescription: String { + switch self { + case .noAttribution: + return "noAttribution" + case .preparingAttribution(let vendor, _, let requestID, let completionBlocks): + return "preparingAttribution(\(vendor), \(requestID), blocks: \(completionBlocks.count))" + case .activeAttribution(let vendor, _, _): + return "activeAttribution(\(vendor))" + } + } } public struct SessionInfo { @@ -63,7 +74,15 @@ public class AdClickAttributionLogic { self.eventReporting?.fire(.adAttributionPageLoads, parameters: [AdClickAttributionEvents.Parameters.count: String(count)]) }) - public private(set) var state = State.noAttribution + public var debugID: String { + ObjectIdentifier(self).debugDescription + } + + public private(set) var state = State.noAttribution { + willSet { + Logger.contentBlocking.debug("<\(self.debugID)> will set state from \(self.state.debugDescription) to \(newValue.debugDescription)") + } + } private var registerFirstActivity = false @@ -94,7 +113,7 @@ public class AdClickAttributionLogic { switch state { case .noAttribution: self.state = state - case .preparingAttribution(let vendor, let info, _): + case .preparingAttribution(let vendor, let info, _, _): requestAttribution(forVendor: vendor, attributionStartedAt: info.attributionStartedAt) case .activeAttribution(_, let sessionInfo, _): @@ -106,10 +125,11 @@ public class AdClickAttributionLogic { } public func onRulesChanged(latestRules: [ContentBlockerRulesManager.Rules]) { + Logger.contentBlocking.debug("<\(self.debugID)> Responding to RulesChanged event") switch state { case .noAttribution: applyRules() - case .preparingAttribution(let vendor, _, let completionBlocks): + case .preparingAttribution(let vendor, _, _, let completionBlocks): requestAttribution(forVendor: vendor, completionBlocks: completionBlocks) case .activeAttribution(let vendor, _, _): requestAttribution(forVendor: vendor) @@ -145,19 +165,20 @@ public class AdClickAttributionLogic { switch state { case .noAttribution: completion() - case .preparingAttribution(let vendor, let session, var completionBlocks): - Logger.contentBlocking.debug("Suspending provisional navigation...") + case .preparingAttribution(let vendor, let session, let id, var completionBlocks): + Logger.contentBlocking.debug("<\(self.debugID)> Suspending provisional navigation...") completionBlocks.append(completion) state = .preparingAttribution(vendor: vendor, session: session, + requestID: id, completionBlocks: completionBlocks) case .activeAttribution(_, let session, _): if currentTime.timeIntervalSince(session.attributionStartedAt) >= featureConfig.totalExpiration { - Logger.contentBlocking.debug("Attribution has expired - total expiration") + Logger.contentBlocking.debug("<\(self.debugID)> Attribution has expired - total expiration") disableAttribution() } else if let leftAttributionContextAt = session.leftAttributionContextAt, currentTime.timeIntervalSince(leftAttributionContextAt) >= featureConfig.navigationExpiration { - Logger.contentBlocking.debug("Attribution has expired - navigational expiration") + Logger.contentBlocking.debug("<\(self.debugID)> Attribution has expired - navigational expiration") disableAttribution() } completion() @@ -183,23 +204,23 @@ public class AdClickAttributionLogic { } if currentTime.timeIntervalSince(session.attributionStartedAt) >= featureConfig.totalExpiration { - Logger.contentBlocking.debug("Attribution has expired - total expiration") + Logger.contentBlocking.debug("<\(self.debugID)> Attribution has expired - total expiration") disableAttribution() return } if let leftAttributionContextAt = session.leftAttributionContextAt { if currentTime.timeIntervalSince(leftAttributionContextAt) >= featureConfig.navigationExpiration { - Logger.contentBlocking.debug("Attribution has expired - navigational expiration") + Logger.contentBlocking.debug("<\(self.debugID)> Attribution has expired - navigational expiration") disableAttribution() } else if tld.eTLDplus1(host) == vendor { - Logger.contentBlocking.debug("Refreshing navigational duration for attribution") + Logger.contentBlocking.debug("<\(self.debugID)> Refreshing navigational duration for attribution") state = .activeAttribution(vendor: vendor, session: SessionInfo(start: session.attributionStartedAt), rules: rules) } } else if tld.eTLDplus1(host) != vendor { - Logger.contentBlocking.debug("Leaving attribution context") + Logger.contentBlocking.debug("<\(self.debugID)> Leaving attribution context") state = .activeAttribution(vendor: vendor, session: SessionInfo(start: session.attributionStartedAt, leftContextAt: Date()), @@ -221,31 +242,39 @@ public class AdClickAttributionLogic { applyRules() } - private func onAttributedRulesCompiled(forVendor vendor: String, _ rules: ContentBlockerRulesManager.Rules) { - guard case .preparingAttribution(let expectedVendor, let session, let completionBlocks) = state else { - Logger.contentBlocking.error("Attributed Rules received unexpectedly") + private func onAttributedRulesCompiled(forVendor vendor: String, requestID: UUID, _ rules: ContentBlockerRulesManager.Rules) { + guard case .preparingAttribution(let expectedVendor, let session, let id, let completionBlocks) = state else { + Logger.contentBlocking.error("<\(self.debugID)> Attributed Rules received unexpectedly") errorReporting?.fire(.adAttributionLogicUnexpectedStateOnRulesCompiled) return } + guard id == requestID else { + Logger.contentBlocking.debug("<\(self.debugID)> Ignoring outdated rules") + return + } guard expectedVendor == vendor else { - Logger.contentBlocking.debug("Attributed Rules received for wrong vendor") + Logger.contentBlocking.debug("<\(self.debugID)> Attributed Rules received for wrong vendor") errorReporting?.fire(.adAttributionLogicWrongVendorOnSuccessfulCompilation) return } state = .activeAttribution(vendor: vendor, session: session, rules: rules) applyRules() - Logger.contentBlocking.debug("Resuming provisional navigation for \(completionBlocks.count, privacy: .public) requests") + Logger.contentBlocking.debug("<\(self.debugID)> Resuming provisional navigation for \(completionBlocks.count, privacy: .public) requests") for completion in completionBlocks { completion() } } - private func onAttributedRulesCompilationFailed(forVendor vendor: String) { - guard case .preparingAttribution(let expectedVendor, _, let completionBlocks) = state else { - Logger.contentBlocking.error("Attributed Rules compilation failed") + private func onAttributedRulesCompilationFailed(forVendor vendor: String, requestID: UUID) { + guard case .preparingAttribution(let expectedVendor, _, let id, let completionBlocks) = state else { + Logger.contentBlocking.error("<\(self.debugID)> Attributed Rules compilation failed") errorReporting?.fire(.adAttributionLogicUnexpectedStateOnRulesCompilationFailed) return } + guard id == requestID else { + Logger.contentBlocking.debug("<\(self.debugID)> Ignoring outdated rules") + return + } guard expectedVendor == vendor else { errorReporting?.fire(.adAttributionLogicWrongVendorOnFailedCompilation) return @@ -253,7 +282,7 @@ public class AdClickAttributionLogic { state = .noAttribution applyRules() - Logger.contentBlocking.debug("Resuming provisional navigation for \(completionBlocks.count, privacy: .public) requests") + Logger.contentBlocking.debug("<\(self.debugID)> Resuming provisional navigation for \(completionBlocks.count, privacy: .public) requests") for completion in completionBlocks { completion() } @@ -269,24 +298,27 @@ public class AdClickAttributionLogic { /// Request attribution when we detect it is needed private func requestAttribution(forVendor vendorHost: String, attributionStartedAt: Date = Date(), completionBlocks: [() -> Void] = []) { + Logger.contentBlocking.debug("<\(self.debugID)> Requesting attribution and new rules for \(vendorHost)") + let requestID = UUID() state = .preparingAttribution(vendor: vendorHost, session: SessionInfo(start: attributionStartedAt), + requestID: requestID, completionBlocks: completionBlocks) - scheduleTimeout(forVendor: vendorHost) + scheduleTimeout(forVendor: vendorHost, requestID: requestID) rulesProvider.requestAttribution(forVendor: vendorHost) { [weak self] rules in self?.cancelTimeout() if let rules = rules { - self?.onAttributedRulesCompiled(forVendor: vendorHost, rules) + self?.onAttributedRulesCompiled(forVendor: vendorHost, requestID: requestID, rules) } else { - self?.onAttributedRulesCompilationFailed(forVendor: vendorHost) + self?.onAttributedRulesCompilationFailed(forVendor: vendorHost, requestID: requestID) } } } - private func scheduleTimeout(forVendor vendor: String) { + private func scheduleTimeout(forVendor vendor: String, requestID: UUID) { let timeoutWorkItem = DispatchWorkItem { [weak self] in - self?.onAttributedRulesCompilationFailed(forVendor: vendor) + self?.onAttributedRulesCompilationFailed(forVendor: vendor, requestID: requestID) self?.attributionTimeout = nil self?.errorReporting?.fire(.adAttributionLogicRequestingAttributionTimedOut) @@ -307,21 +339,21 @@ public class AdClickAttributionLogic { switch state { case .noAttribution: - Logger.contentBlocking.debug("Preparing attribution for \(vendorHost)") + Logger.contentBlocking.debug("<\(self.debugID)> Preparing attribution for \(vendorHost)") requestAttribution(forVendor: vendorHost) - case .preparingAttribution(let expectedVendor, _, let completionBlocks): + case .preparingAttribution(let expectedVendor, _, _, let completionBlocks): if expectedVendor != vendorHost { - Logger.contentBlocking.debug("Preparing attributon for \(vendorHost) replacing pending one for \(expectedVendor)") + Logger.contentBlocking.debug("<\(self.debugID)> Preparing attributon for \(vendorHost) replacing pending one for \(expectedVendor)") requestAttribution(forVendor: vendorHost, completionBlocks: completionBlocks) } else { - Logger.contentBlocking.debug("Preparing attribution for \(vendorHost) already in progress") + Logger.contentBlocking.debug("<\(self.debugID)> Preparing attribution for \(vendorHost) already in progress") } case .activeAttribution(let expectedVendor, _, _): if expectedVendor != vendorHost { - Logger.contentBlocking.debug("Preparing attributon for \(vendorHost) replacing \(expectedVendor)") + Logger.contentBlocking.debug("<\(self.debugID)> Preparing attributon for \(vendorHost) replacing \(expectedVendor)") requestAttribution(forVendor: vendorHost) } else { - Logger.contentBlocking.debug("Attribution for \(vendorHost) already active") + Logger.contentBlocking.debug("<\(self.debugID)> Attribution for \(vendorHost) already active") } } } @@ -332,7 +364,7 @@ extension AdClickAttributionLogic: AdClickAttributionDetectionDelegate { public func attributionDetection(_ detection: AdClickAttributionDetection, didDetectVendor vendorHost: String) { - Logger.contentBlocking.debug("Detected attribution requests for \(vendorHost)") + Logger.contentBlocking.debug("<\(self.debugID)> Detected attribution requests for \(vendorHost)") onAttributionRequested(forVendor: vendorHost) registerFirstActivity = true } diff --git a/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionRulesProvider.swift b/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionRulesProvider.swift index 3bcf1764d..36f5893ce 100644 --- a/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionRulesProvider.swift +++ b/Sources/BrowserServicesKit/ContentBlocking/AdClickAttribution/AdClickAttributionRulesProvider.swift @@ -155,7 +155,9 @@ public class AdClickAttributionRulesProvider: AdClickAttributionRulesProviding { // This is optimization: in case multiple tabs request same attribution at the same time, we will respond quickly. var matchingTasks = tasks.filter { $0 == attributionTask } tasks.removeAll(where: { $0 == attributionTask }) - matchingTasks.append(attributionTask) + + // Preserve order in which rules were requested + matchingTasks.insert(attributionTask, at: 0) Logger.contentBlocking.debug("Returning attribution rules for vendor \(attributionTask.vendor) to \(matchingTasks.count, privacy: .public) caller(s)")