fix: Too long flush duration (#2370)

Move the calculation of the flush dispatch time to the beginning of the flush function to avoid any code until the call to dispatch_group_wait adds up to the total flush duration. Fixes GH-2334, GH-2340
getsentry · Nov 10, 2022 · e2a3f3e · e2a3f3e
1 parent f5f8910
commit e2a3f3e
Show file tree

Hide file tree

Showing 4 changed files with 37 additions and 28 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,5 +1,11 @@
 # Changelog
 
+## Unreleased
+
+### Fixes
+
+- Too long flush duration (#2370)
+
 ## 7.30.2
 
 ### Fixes

diff --git a/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme b/Sentry.xcodeproj/xcshareddata/xcschemes/Sentry.xcscheme
@@ -64,12 +64,6 @@
                <Test
                   Identifier = "SentryFileIOTrackingIntegrationTests/test_DataConsistency_readUrl_disabled()">
                </Test>
-               <Test
-                  Identifier = "SentryHttpTransportTests/testFlush_CalledMultipleTimes_ImmediatelyReturnsFalse_disabled()">
-               </Test>
-               <Test
-                  Identifier = "SentryHttpTransportTests/testFlush_CalledSequentially_BlocksTwice_disabled()">
-               </Test>
                <Test
                   Identifier = "SentryNetworkTrackerIntegrationTests/testGetRequest_SpanCreatedAndBaggageHeaderAdded_disabled()">
                </Test>

diff --git a/Sources/Sentry/SentryHttpTransport.m b/Sources/Sentry/SentryHttpTransport.m
@@ -151,6 +151,12 @@ - (void)recordLostEvent:(SentryDataCategory)category reason:(SentryDiscardReason
 
 - (BOOL)flush:(NSTimeInterval)timeout
 {
+    // Calculate the dispatch time of the flush duration as early as possible to guarantee an exact
+    // flush duration. Any code up to the dispatch_group_wait can take a couple of ms, adding up to
+    // the flush duration.
+    dispatch_time_t delta = (int64_t)(timeout * (NSTimeInterval)NSEC_PER_SEC);
+    dispatch_time_t dispatchTimeout = dispatch_time(DISPATCH_TIME_NOW, delta);
+
     // Double-Checked Locking to avoid acquiring unnecessary locks.
     if (_isFlushing) {
         SENTRY_LOG_DEBUG(@"Already flushing.");
@@ -171,9 +177,6 @@ - (BOOL)flush:(NSTimeInterval)timeout
 
     [self sendAllCachedEnvelopes];
 
-    dispatch_time_t delta = (int64_t)(timeout * (NSTimeInterval)NSEC_PER_SEC);
-    dispatch_time_t dispatchTimeout = dispatch_time(DISPATCH_TIME_NOW, delta);
-
     intptr_t result = dispatch_group_wait(self.dispatchGroup, dispatchTimeout);
 
     @synchronized(self) {

diff --git a/Tests/SentryTests/Networking/SentryHttpTransportTests.swift b/Tests/SentryTests/Networking/SentryHttpTransportTests.swift
@@ -629,7 +629,7 @@ class SentryHttpTransportTests: XCTestCase {
     func testFlush_BlocksCallingThread_TimesOut() {
         CurrentDate.setCurrentDateProvider(DefaultCurrentDateProvider.sharedInstance())
 
-        givenCachedEvents()
+        givenCachedEvents(amount: 30)
 
         fixture.requestManager.responseDelay = fixture.flushTimeout + 0.2
 
@@ -638,20 +638,23 @@ class SentryHttpTransportTests: XCTestCase {
         let blockingDuration = getDurationNs(beforeFlush, getAbsoluteTime()).toTimeInterval()
 
         XCTAssertGreaterThan(blockingDuration, fixture.flushTimeout)
-        XCTAssertLessThan(blockingDuration, fixture.flushTimeout + 0.2)
+        XCTAssertLessThan(blockingDuration, fixture.flushTimeout + 0.1)
 
         XCTAssertFalse(success, "Flush should time out.")
     }
 
     func testFlush_BlocksCallingThread_FinishesFlushingWhenSent() {
         CurrentDate.setCurrentDateProvider(DefaultCurrentDateProvider.sharedInstance())
 
-        givenCachedEvents()
+        givenCachedEvents(amount: 1)
 
-        assertFlushBlocksAndFinishesSuccessfully()
+        let beforeFlush = getAbsoluteTime()
+        XCTAssertTrue(sut.flush(fixture.flushTimeout), "Flush should not time out.")
+        let blockingDuration = getDurationNs(beforeFlush, getAbsoluteTime()).toTimeInterval()
+        XCTAssertLessThan(blockingDuration, fixture.flushTimeout)
     }
 
-    func testFlush_CalledSequentially_BlocksTwice_disabled() {
+    func testFlush_CalledSequentially_BlocksTwice() {
         CurrentDate.setCurrentDateProvider(DefaultCurrentDateProvider.sharedInstance())
 
         givenCachedEvents()
@@ -661,7 +664,8 @@ class SentryHttpTransportTests: XCTestCase {
         XCTAssertTrue(sut.flush(fixture.flushTimeout), "Flush should not time out.")
         let blockingDuration = getDurationNs(beforeFlush, getAbsoluteTime()).toTimeInterval()
 
-        XCTAssertLessThan(blockingDuration, 0.1)
+        XCTAssertLessThan(blockingDuration, fixture.flushTimeout * 2.2,
+                          "The blocking duration must not exceed the sum of the maximum flush duration.")
     }
 
     func testFlush_WhenNoEnvelopes_BlocksAndFinishes() {
@@ -679,10 +683,10 @@ class SentryHttpTransportTests: XCTestCase {
         assertFlushBlocksAndFinishesSuccessfully()
     }
 
-    func testFlush_CalledMultipleTimes_ImmediatelyReturnsFalse_disabled() {
+    func testFlush_CalledMultipleTimes_ImmediatelyReturnsFalse() {
         CurrentDate.setCurrentDateProvider(DefaultCurrentDateProvider.sharedInstance())
 
-        givenCachedEvents()
+        givenCachedEvents(amount: 30)
         fixture.requestManager.responseDelay = fixture.flushTimeout * 2
 
         let allFlushCallsGroup = DispatchGroup()
@@ -716,16 +720,17 @@ class SentryHttpTransportTests: XCTestCase {
         // double-checked lock, should return immediately.
 
         let initiallyInactiveQueue = fixture.queue
-        let count = 100
-        for _ in 0..<count {
+        for _ in 0..<2 {
             allFlushCallsGroup.enter()
             initiallyInactiveQueue.async {
-                let beforeFlush = getAbsoluteTime()
-                let result = self.sut.flush(self.fixture.flushTimeout)
-                let blockingDuration = getDurationNs(beforeFlush, getAbsoluteTime()).toTimeInterval()
-
-                XCTAssertGreaterThan(0.1, blockingDuration, "The flush call should have returned immediately.")
-                XCTAssertFalse(result)
+                for _ in 0..<10 {
+                    let beforeFlush = getAbsoluteTime()
+                    let result = self.sut.flush(self.fixture.flushTimeout)
+                    let blockingDuration = getDurationNs(beforeFlush, getAbsoluteTime()).toTimeInterval()
+
+                    XCTAssertGreaterThan(0.1, blockingDuration, "The flush call should have returned immediately.")
+                    XCTAssertFalse(result)
+                }
 
                 allFlushCallsGroup.leave()
             }
@@ -769,11 +774,12 @@ class SentryHttpTransportTests: XCTestCase {
         fixture.requestManager.returnResponse(response: HTTPURLResponse())
     }
 
-    private func givenCachedEvents() {
+    private func givenCachedEvents(amount: Int = 2) {
         givenNoInternetConnection()
 
-        sendEvent()
-        sendEvent()
+        for _ in 0..<amount {
+            sendEvent()
+        }
 
         givenOkResponse()
     }