Skip to content

Commit f2bfecd

Browse files
denrasedenrase
authored
Structured Logs: Flush logs on SDK flush/close (#5834)
1 parent 7a1d56c commit f2bfecd

File tree

7 files changed

+95
-31
lines changed

7 files changed

+95
-31
lines changed

‎CHANGELOG.md‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,11 @@
11
# Changelog
22

3+
## Unreleased
4+
5+
### Features
6+
7+
- Structured Logs: Flush logs on SDK flush/close (#5834)
8+
39
## 8.54.1-alpha.1
410

511
- No documented changes.

‎Sources/Swift/Helper/SentrySDK.swift‎

Lines changed: 17 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -359,14 +359,21 @@ import Foundation
359359
/// timeout in seconds. If there is no internet connection, the function returns immediately. The SDK
360360
/// doesn't dispose the client or the hub.
361361
/// - parameter timeout: The time to wait for the SDK to complete the flush.
362+
/// - note: This might take slightly longer than the specified timeout if there are many batched logs to capture.
362363
@objc(flush:)
363364
public static func flush(timeout: TimeInterval) {
364-
SentrySDKInternal.flush(timeout: timeout)
365+
let captureLogsDuration = captureLogs()
366+
// Capturing batched logs should never take long, but we need to fall back to a sane value.
367+
// This is a workaround for experimental logs, until we'll write batched logs to disk,
368+
// to avoid data loss due to crashes. This is a trade-off until then.
369+
SentrySDKInternal.flush(timeout: max(timeout / 2, timeout - captureLogsDuration))
365370
}
366371

367372
/// Closes the SDK, uninstalls all the integrations, and calls `flush` with
368373
/// `SentryOptions.shutdownTimeInterval`.
369374
@objc public static func close() {
375+
// Capturing batched logs should never take long, ignore the duration here.
376+
_ = captureLogs()
370377
SentrySDKInternal.close()
371378
}
372379

@@ -422,6 +429,15 @@ import Foundation
422429

423430
private static var _loggerLock = NSLock()
424431
private static var _logger: SentryLogger?
432+
433+
@discardableResult
434+
private static func captureLogs() -> TimeInterval {
435+
var duration: TimeInterval = 0.0
436+
_loggerLock.synchronized {
437+
duration = _logger?.captureLogs() ?? 0.0
438+
}
439+
return duration
440+
}
425441
}
426442

427443
extension SentryIdWrapper {

‎Sources/Swift/Tools/SentryLogBatcher.swift‎

Lines changed: 11 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -64,11 +64,15 @@ import Foundation
6464
}
6565
}
6666

67-
@objc
68-
@_spi(Private) func flush() {
69-
dispatchQueue.dispatchAsync { [weak self] in
70-
self?.performFlush()
67+
// Captures batched logs sync and returns the duration.
68+
@discardableResult
69+
@_spi(Private) func captureLogs() -> TimeInterval {
70+
let startTimeNs = SentryDefaultCurrentDateProvider.getAbsoluteTime()
71+
dispatchQueue.dispatchSync { [weak self] in
72+
self?.performCaptureLogs()
7173
}
74+
let endTimeNs = SentryDefaultCurrentDateProvider.getAbsoluteTime()
75+
return TimeInterval(endTimeNs - startTimeNs) / 1_000_000_000.0 // Convert nanoseconds to seconds
7276
}
7377

7478
// Helper
@@ -84,7 +88,7 @@ import Foundation
8488
encodedLogsSize += encodedLog.count
8589

8690
if encodedLogsSize >= maxBufferSizeBytes {
87-
performFlush()
91+
performCaptureLogs()
8892
} else if encodedLogsWereEmpty && timerWorkItem == nil {
8993
startTimer()
9094
}
@@ -97,14 +101,14 @@ import Foundation
97101
private func startTimer() {
98102
let timerWorkItem = DispatchWorkItem { [weak self] in
99103
SentrySDKLog.debug("SentryLogBatcher: Timer fired, calling performFlush().")
100-
self?.performFlush()
104+
self?.performCaptureLogs()
101105
}
102106
self.timerWorkItem = timerWorkItem
103107
dispatchQueue.dispatch(after: flushTimeout, workItem: timerWorkItem)
104108
}
105109

106110
// Only ever call this from the serial dispatch queue.
107-
private func performFlush() {
111+
private func performCaptureLogs() {
108112
// Reset logs on function exit
109113
defer {
110114
encodedLogs.removeAll()

‎Sources/Swift/Tools/SentryLogger.swift‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -166,6 +166,13 @@ public final class SentryLogger: NSObject {
166166
let message = SentryLogMessage(stringLiteral: body)
167167
captureLog(level: .fatal, logMessage: message, attributes: attributes)
168168
}
169+
170+
// MARK: - Internal
171+
172+
// Captures batched logs sync and return the duration.
173+
func captureLogs() -> TimeInterval {
174+
return batcher?.captureLogs() ?? 0.0
175+
}
169176

170177
// MARK: - Private
171178

‎Tests/SentryTests/SentryLogBatcherTests.swift‎

Lines changed: 12 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -52,7 +52,7 @@ final class SentryLogBatcherTests: XCTestCase {
5252
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 0)
5353

5454
// Trigger flush manually
55-
sut.flush()
55+
sut.captureLogs()
5656

5757
// Verify both logs are batched together
5858
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 1)
@@ -140,9 +140,9 @@ final class SentryLogBatcherTests: XCTestCase {
140140
XCTAssertEqual(2, items.count)
141141
}
142142

143-
// MARK: - Manual Flush Tests
143+
// MARK: - Manual Capture Logs Tests
144144

145-
func testManualFlush_FlushesImmediately() throws {
145+
func testManualCaptureLogs_CapturesImmediately() throws {
146146
// Given
147147
let log1 = createTestLog(body: "Log 1")
148148
let log2 = createTestLog(body: "Log 2")
@@ -152,7 +152,7 @@ final class SentryLogBatcherTests: XCTestCase {
152152
sut.add(log2)
153153
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 0)
154154

155-
sut.flush()
155+
sut.captureLogs()
156156

157157
// Then
158158
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 1)
@@ -163,7 +163,7 @@ final class SentryLogBatcherTests: XCTestCase {
163163
XCTAssertEqual(2, items.count)
164164
}
165165

166-
func testManualFlush_CancelsScheduledFlush() throws {
166+
func testManualCaptureLogs_CancelsScheduledCapture() throws {
167167
// Given
168168
let log = createTestLog()
169169

@@ -175,7 +175,7 @@ final class SentryLogBatcherTests: XCTestCase {
175175
let timerWorkItem = try XCTUnwrap(testDispatchQueue.dispatchAfterWorkItemInvocations.first?.workItem)
176176

177177
// Manual flush immediately
178-
sut.flush()
178+
sut.captureLogs()
179179
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 1, "Manual flush should work")
180180

181181
// Try to trigger the timer work item (should not flush again since timer was cancelled)
@@ -185,14 +185,14 @@ final class SentryLogBatcherTests: XCTestCase {
185185
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 1, "Timer should be cancelled")
186186
}
187187

188-
func testFlushEmptyBuffer_DoesNothing() {
188+
func testManualCaptureLogs_WithEmptyBuffer_DoesNothing() {
189189
// When
190-
sut.flush()
190+
sut.captureLogs()
191191

192192
// Then
193193
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 0)
194194
}
195-
195+
196196
// MARK: - Edge Cases Tests
197197

198198
func testScheduledFlushAfterBufferAlreadyFlushed_DoesNothing() throws {
@@ -225,12 +225,12 @@ final class SentryLogBatcherTests: XCTestCase {
225225

226226
// When
227227
sut.add(log1)
228-
sut.flush()
228+
sut.captureLogs()
229229

230230
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 1)
231231

232232
sut.add(log2)
233-
sut.flush()
233+
sut.captureLogs()
234234

235235
// Then - should have two separate flush calls
236236
XCTAssertEqual(testClient.captureLogsDataInvocations.count, 2)
@@ -268,14 +268,7 @@ final class SentryLogBatcherTests: XCTestCase {
268268
}
269269
wait(for: [expectation], timeout: 1.0)
270270

271-
sutWithRealQueue.flush()
272-
273-
// Need to wait a bit for flush to complete since this uses a real queue
274-
let flushExpectation = self.expectation(description: "Wait for flush")
275-
DispatchQueue.main.asyncAfter(deadline: .now() + 0.1) {
276-
flushExpectation.fulfill()
277-
}
278-
waitForExpectations(timeout: 0.5)
271+
sutWithRealQueue.captureLogs()
279272

280273
// Verify all 10 logs were included in the single batch
281274
let sentData = try XCTUnwrap(testClient.captureLogsDataInvocations.first).data

‎Tests/SentryTests/SentrySDKInternalTests.swift‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -679,7 +679,7 @@ class SentrySDKInternalTests: XCTestCase {
679679
DispatchQueue.main.asyncAfter(deadline: .now() + 0.1) {
680680
expectation.fulfill()
681681
}
682-
waitForExpectations(timeout: 0.5)
682+
waitForExpectations(timeout: 5.0)
683683

684684
XCTAssertEqual(fixture.client.captureLogsDataInvocations.count, 1)
685685
}
@@ -695,7 +695,7 @@ class SentrySDKInternalTests: XCTestCase {
695695
DispatchQueue.main.asyncAfter(deadline: .now() + 0.1) {
696696
expectation.fulfill()
697697
}
698-
waitForExpectations(timeout: 0.5)
698+
waitForExpectations(timeout: 5.0)
699699

700700
XCTAssertEqual(fixture.client.captureLogsDataInvocations.count, 0)
701701
}
@@ -724,7 +724,7 @@ class SentrySDKInternalTests: XCTestCase {
724724
let flushTimeout = 10.0
725725
SentrySDK.flush(timeout: flushTimeout)
726726

727-
XCTAssertEqual(flushTimeout, transport.flushInvocations.first)
727+
XCTAssertEqual(flushTimeout, transport.flushInvocations.first ?? 0.0, accuracy: 0.001)
728728
}
729729

730730
@available(*, deprecated, message: "This is deprecated because SentryOptions integrations is deprecated")

‎Tests/SentryTests/SentrySDKTests.swift‎

Lines changed: 39 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -397,7 +397,7 @@ class SentrySDKTests: XCTestCase {
397397

398398
assertHubScopeNotChanged()
399399
}
400-
400+
401401
/// When events don't have debug meta the backend can't symbolicate the stack trace of events.
402402
/// This is a regression test for https://github.com/getsentry/sentry-cocoa/issues/5334
403403
func testCaptureNonFatalEvent_HasDebugMeta() throws {
@@ -441,6 +441,44 @@ class SentrySDKTests: XCTestCase {
441441
XCTAssertNotNil(debugMeta.imageSize)
442442
}
443443
}
444+
445+
// MARK: - Logger Flush Tests
446+
447+
func testFlush_CallsLoggerCaptureLogs() {
448+
fixture.client.options.experimental.enableLogs = true
449+
SentrySDKInternal.setCurrentHub(fixture.hub)
450+
SentrySDKInternal.setStart(with: fixture.client.options)
451+
452+
// Add a log to ensure there's something to flush
453+
SentrySDK.logger.info("Test log message")
454+
455+
// Initially no logs should be sent (they're buffered)
456+
XCTAssertEqual(fixture.client.captureLogsDataInvocations.count, 0)
457+
458+
// Flush the SDK
459+
SentrySDK.flush(timeout: 1.0)
460+
461+
// Now logs should be sent
462+
XCTAssertEqual(fixture.client.captureLogsDataInvocations.count, 1)
463+
}
464+
465+
func testClose_CallsLoggerCaptureLogs() {
466+
fixture.client.options.experimental.enableLogs = true
467+
SentrySDKInternal.setCurrentHub(fixture.hub)
468+
SentrySDKInternal.setStart(with: fixture.client.options)
469+
470+
// Add a log to ensure there's something to flush
471+
SentrySDK.logger.info("Test log message")
472+
473+
// Initially no logs should be sent (they're buffered)
474+
XCTAssertEqual(fixture.client.captureLogsDataInvocations.count, 0)
475+
476+
// Close the SDK
477+
SentrySDK.close()
478+
479+
// Now logs should be sent
480+
XCTAssertEqual(fixture.client.captureLogsDataInvocations.count, 1)
481+
}
444482
}
445483

446484
extension SentrySDKTests {

0 commit comments

Comments
 (0)