diff --git a/Riot/Modules/Analytics/Analytics.swift b/Riot/Modules/Analytics/Analytics.swift index 849efd0b87..d9d68e2f85 100644 --- a/Riot/Modules/Analytics/Analytics.swift +++ b/Riot/Modules/Analytics/Analytics.swift @@ -215,7 +215,7 @@ import AnalyticsEvents @objc protocol E2EAnalytics { - func trackE2EEError(_ reason: DecryptionFailureReason, context: String) + func trackE2EEError(_ failure: DecryptionFailure) } @@ -225,21 +225,8 @@ protocol E2EAnalytics { /// - Parameters: /// - reason: The error that occurred. /// - context: Additional context of the error that occured - func trackE2EEError(_ reason: DecryptionFailureReason, context: String) { - let event = AnalyticsEvent.Error( - context: context, - cryptoModule: .Rust, - cryptoSDK: AnalyticsEvent.Error.CryptoSDK.Rust, - domain: .E2EE, - // XXX not yet supported. - eventLocalAgeMillis: nil, - isFederated: nil, - isMatrixDotOrg: nil, - name: reason.errorName, - timeToDecryptMillis: nil, - userTrustsOwnIdentity: nil, - wasVisibleToUser: nil - ) + func trackE2EEError(_ failure: DecryptionFailure) { + let event = failure.toAnalyticsEvent() capture(event: event) } diff --git a/Riot/Modules/Analytics/DecryptionFailure+Analytics.swift b/Riot/Modules/Analytics/DecryptionFailure+Analytics.swift new file mode 100644 index 0000000000..cd129aee35 --- /dev/null +++ b/Riot/Modules/Analytics/DecryptionFailure+Analytics.swift @@ -0,0 +1,44 @@ +// +// Copyright 2024 New Vector Ltd +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// + +import Foundation +import AnalyticsEvents + +extension DecryptionFailure { + + public func toAnalyticsEvent() -> AnalyticsEvent.Error { + + let timeToDecryptMillis: Int = if self.timeToDecrypt != nil { + Int(self.timeToDecrypt! * 1000) + } else { + -1 + } + return AnalyticsEvent.Error( + context: self.context, + cryptoModule: .Rust, + cryptoSDK: .Rust, + domain: .E2EE, + + eventLocalAgeMillis: nil, + isFederated: nil, + isMatrixDotOrg: nil, + name: self.reason.errorName, + timeToDecryptMillis: timeToDecryptMillis, + userTrustsOwnIdentity: nil, + wasVisibleToUser: nil + ) + } +} diff --git a/Riot/Modules/Analytics/DecryptionFailure.swift b/Riot/Modules/Analytics/DecryptionFailure.swift index b5804d258a..9e0ca57858 100644 --- a/Riot/Modules/Analytics/DecryptionFailure.swift +++ b/Riot/Modules/Analytics/DecryptionFailure.swift @@ -44,6 +44,9 @@ import AnalyticsEvents /// Additional context of failure let context: String + /// UTDs can be permanent or temporary. If temporary, this field will contain the time it took to decrypt the message in milliseconds. If permanent should be nil + var timeToDecrypt: TimeInterval? + init(failedEventId: String, reason: DecryptionFailureReason, context: String, ts: TimeInterval) { self.failedEventId = failedEventId self.reason = reason diff --git a/Riot/Modules/Analytics/DecryptionFailureTracker.swift b/Riot/Modules/Analytics/DecryptionFailureTracker.swift index f33f2b7c52..19b8afb19c 100644 --- a/Riot/Modules/Analytics/DecryptionFailureTracker.swift +++ b/Riot/Modules/Analytics/DecryptionFailureTracker.swift @@ -36,7 +36,10 @@ class DecryptionFailureTracker: NSObject { let GRACE_PERIOD: TimeInterval = 4 // Call `checkFailures` every `CHECK_INTERVAL` - let CHECK_INTERVAL: TimeInterval = 2 + let CHECK_INTERVAL: TimeInterval = 15 + + // The maximum time to wait for a late decryption before reporting as permanent UTD + let MAX_WAIT_FOR_LATE_DECRYPTION: TimeInterval = 60 @objc weak var delegate: E2EAnalytics? @@ -60,9 +63,6 @@ class DecryptionFailureTracker: NSObject { name: .mxEventDidDecrypt, object: nil) - Timer.scheduledTimer(withTimeInterval: CHECK_INTERVAL, repeats: true) { [weak self] _ in - self?.checkFailures() - } } @objc @@ -93,6 +93,14 @@ class DecryptionFailureTracker: NSObject { let context = String(format: "code: %ld, description: %@", error.code, event.decryptionError.localizedDescription) reportedFailures[failedEventId] = DecryptionFailure(failedEventId: failedEventId, reason: reason, context: context, ts: self.timeProvider.nowTs()) + + // Start the ticker if needed. There is no need to have a ticker if no failures are tracked + if checkFailuresTimer == nil { + self.checkFailuresTimer = Timer.scheduledTimer(withTimeInterval: CHECK_INTERVAL, repeats: true) { [weak self] _ in + self?.checkFailures() + } + } + } @objc @@ -104,8 +112,30 @@ class DecryptionFailureTracker: NSObject { func eventDidDecrypt(_ notification: Notification) { guard let event = notification.object as? MXEvent else { return } - // Could be an event in the reportedFailures, remove it + guard let reportedFailure = self.reportedFailures[event.eventId] else { return } + + let now = self.timeProvider.nowTs() + let ellapsedTime = now - reportedFailure.ts + + if ellapsedTime < 4 { + // event is graced + reportedFailures.removeValue(forKey: event.eventId) + } else { + // It's a late decrypt must be reported as a late decrypt + reportedFailure.timeToDecrypt = ellapsedTime + self.delegate?.trackE2EEError(reportedFailure) + } + // Remove from reported failures + self.trackedEvents.insert(event.eventId) reportedFailures.removeValue(forKey: event.eventId) + + // Check if we still need the ticker timer + if reportedFailures.isEmpty { + // Invalidate the current timer, nothing to check for + self.checkFailuresTimer?.invalidate() + self.checkFailuresTimer = nil + } + } /** @@ -116,23 +146,29 @@ class DecryptionFailureTracker: NSObject { func checkFailures() { guard let delegate = self.delegate else {return} - let tsNow = self.timeProvider.nowTs() var failuresToCheck = [DecryptionFailure]() for reportedFailure in self.reportedFailures.values { let ellapsed = tsNow - reportedFailure.ts - if ellapsed > GRACE_PERIOD { + if ellapsed > MAX_WAIT_FOR_LATE_DECRYPTION { failuresToCheck.append(reportedFailure) + reportedFailure.timeToDecrypt = nil reportedFailures.removeValue(forKey: reportedFailure.failedEventId) trackedEvents.insert(reportedFailure.failedEventId) } } for failure in failuresToCheck { - delegate.trackE2EEError(failure.reason, context: failure.context) + delegate.trackE2EEError(failure) } + // Check if we still need the ticker timer + if reportedFailures.isEmpty { + // Invalidate the current timer, nothing to check for + self.checkFailuresTimer?.invalidate() + self.checkFailuresTimer = nil + } } } diff --git a/RiotTests/DecryptionFailureTrackerTests.swift b/RiotTests/DecryptionFailureTrackerTests.swift index 9b5fe94ea4..7cd9bf480f 100644 --- a/RiotTests/DecryptionFailureTrackerTests.swift +++ b/RiotTests/DecryptionFailureTrackerTests.swift @@ -32,10 +32,9 @@ class DecryptionFailureTrackerTests: XCTestCase { } class AnalyticsDelegate : E2EAnalytics { - var reportedFailure: Element.DecryptionFailureReason?; + var reportedFailure: Element.DecryptionFailure?; - func trackE2EEError(_ reason: Element.DecryptionFailureReason, context: String) { - print("Error Tracked: ", reason) + func trackE2EEError(_ reason: Element.DecryptionFailure) { reportedFailure = reason } @@ -66,6 +65,9 @@ class DecryptionFailureTrackerTests: XCTestCase { timeShifter.timestamp = TimeInterval(2) + // simulate decrypted in the grace period + NotificationCenter.default.post(name: .mxEventDidDecrypt, object: fakeEvent) + decryptionFailureTracker.checkFailures(); XCTAssertNil(testDelegate.reportedFailure); @@ -73,11 +75,71 @@ class DecryptionFailureTrackerTests: XCTestCase { // Pass the grace period timeShifter.timestamp = TimeInterval(5) + decryptionFailureTracker.checkFailures(); + XCTAssertNil(testDelegate.reportedFailure); + + } + + func test_report_ratcheted_key_utd() { + + let myUser = "test@example.com"; + + let decryptionFailureTracker = DecryptionFailureTracker(); + decryptionFailureTracker.timeProvider = timeShifter; + + let testDelegate = AnalyticsDelegate(); + + decryptionFailureTracker.delegate = testDelegate; + + timeShifter.timestamp = TimeInterval(0) + + let fakeEvent = FakeEvent(id: "$0000"); + fakeEvent.decryptionError = NSError(domain: MXDecryptingErrorDomain, code: Int(MXDecryptingErrorOlmCode.rawValue)) + + + let fakeRoomState = FakeRoomState(); + fakeRoomState.mockMembers = FakeRoomMembers(joined: [myUser]) + decryptionFailureTracker.reportUnableToDecryptError(forEvent: fakeEvent, withRoomState: fakeRoomState, myUser: myUser); + + // Pass the max period + timeShifter.timestamp = TimeInterval(70) + + decryptionFailureTracker.checkFailures(); + + XCTAssertEqual(testDelegate.reportedFailure?.reason, DecryptionFailureReason.olmIndexError); + } + + func test_report_unspecified_error() { + + let myUser = "test@example.com"; + + let decryptionFailureTracker = DecryptionFailureTracker(); + decryptionFailureTracker.timeProvider = timeShifter; + + let testDelegate = AnalyticsDelegate(); + + decryptionFailureTracker.delegate = testDelegate; + + timeShifter.timestamp = TimeInterval(0) + + let fakeEvent = FakeEvent(id: "$0000"); + fakeEvent.decryptionError = NSError(domain: MXDecryptingErrorDomain, code: Int(MXDecryptingErrorBadRoomCode.rawValue)) + + + let fakeRoomState = FakeRoomState(); + fakeRoomState.mockMembers = FakeRoomMembers(joined: [myUser]) + decryptionFailureTracker.reportUnableToDecryptError(forEvent: fakeEvent, withRoomState: fakeRoomState, myUser: myUser); + + // Pass the max period + timeShifter.timestamp = TimeInterval(70) + decryptionFailureTracker.checkFailures(); - XCTAssertEqual(testDelegate.reportedFailure, DecryptionFailureReason.olmKeysNotSent); + XCTAssertEqual(testDelegate.reportedFailure?.reason, DecryptionFailureReason.unspecified); } + + func test_do_not_double_report() { let myUser = "test@example.com"; @@ -100,12 +162,12 @@ class DecryptionFailureTrackerTests: XCTestCase { decryptionFailureTracker.reportUnableToDecryptError(forEvent: fakeEvent, withRoomState: fakeRoomState, myUser: myUser); - // Pass the grace period - timeShifter.timestamp = TimeInterval(5) + // Pass the max period + timeShifter.timestamp = TimeInterval(70) decryptionFailureTracker.checkFailures(); - XCTAssertEqual(testDelegate.reportedFailure, DecryptionFailureReason.olmKeysNotSent); + XCTAssertEqual(testDelegate.reportedFailure?.reason, DecryptionFailureReason.olmKeysNotSent); // Try to report again the same event testDelegate.reportedFailure = nil @@ -192,5 +254,88 @@ class DecryptionFailureTrackerTests: XCTestCase { XCTAssertNil(testDelegate.reportedFailure); } + + func test_should_report_late_decrypt() { + + let myUser = "test@example.com"; + + let decryptionFailureTracker = DecryptionFailureTracker(); + decryptionFailureTracker.timeProvider = timeShifter; + + let testDelegate = AnalyticsDelegate(); + + decryptionFailureTracker.delegate = testDelegate; + + timeShifter.timestamp = TimeInterval(0) + + let fakeEvent = FakeEvent(id: "$0000"); + fakeEvent.decryptionError = NSError(domain: MXDecryptingErrorDomain, code: Int(MXDecryptingErrorUnknownInboundSessionIdCode.rawValue)) + + + let fakeRoomState = FakeRoomState(); + fakeRoomState.mockMembers = FakeRoomMembers(joined: [myUser]) + + decryptionFailureTracker.reportUnableToDecryptError(forEvent: fakeEvent, withRoomState: fakeRoomState, myUser: myUser); + + // Simulate succesful decryption after grace period but before max wait + timeShifter.timestamp = TimeInterval(20) + + // Simulate event gets decrypted + NotificationCenter.default.post(name: .mxEventDidDecrypt, object: fakeEvent) + + + decryptionFailureTracker.checkFailures(); + + // Event should have been reported as a late decrypt + XCTAssertEqual(testDelegate.reportedFailure?.reason, DecryptionFailureReason.olmKeysNotSent); + XCTAssertEqual(testDelegate.reportedFailure?.timeToDecrypt, TimeInterval(20)); + + // Assert that it's converted to millis for reporting + let analyticsError = testDelegate.reportedFailure!.toAnalyticsEvent() + + XCTAssertEqual(analyticsError.timeToDecryptMillis, 20000) + + } + + + + func test_should_report_permanent_decryption_error() { + + let myUser = "test@example.com"; + + let decryptionFailureTracker = DecryptionFailureTracker(); + decryptionFailureTracker.timeProvider = timeShifter; + + let testDelegate = AnalyticsDelegate(); + + decryptionFailureTracker.delegate = testDelegate; + + timeShifter.timestamp = TimeInterval(0) + + let fakeEvent = FakeEvent(id: "$0000"); + fakeEvent.decryptionError = NSError(domain: MXDecryptingErrorDomain, code: Int(MXDecryptingErrorUnknownInboundSessionIdCode.rawValue)) + + + let fakeRoomState = FakeRoomState(); + fakeRoomState.mockMembers = FakeRoomMembers(joined: [myUser]) + + decryptionFailureTracker.reportUnableToDecryptError(forEvent: fakeEvent, withRoomState: fakeRoomState, myUser: myUser); + + // Simulate succesful decryption after max wait + timeShifter.timestamp = TimeInterval(70) + + decryptionFailureTracker.checkFailures(); + + // Event should have been reported as a late decrypt + XCTAssertEqual(testDelegate.reportedFailure?.reason, DecryptionFailureReason.olmKeysNotSent); + XCTAssertNil(testDelegate.reportedFailure?.timeToDecrypt); + + + // Assert that it's converted to -1 for reporting + let analyticsError = testDelegate.reportedFailure!.toAnalyticsEvent() + + XCTAssertEqual(analyticsError.timeToDecryptMillis, -1) + + } }