Structured Logs: Buffering & flushing of logs (#5628)

Author: denrase

CHANGELOG.md

@@ -4,8 +4,7 @@
 
 ### Features
 
-- Add experimental support for capturing structured logs via `SentrySDK.logger` (#5532, #5593, #5639)
-- Add experimental support for capturing structured logs via `SentrySDK.logger` (#5532, #5593)
+- Add experimental support for capturing structured logs via `SentrySDK.logger` (#5532, #5593, #5639, #5628)
 
 ### Improvements
 

Samples/iOS-SwiftUI/iOS-SwiftUI-UITests/LaunchUITests.swift

@@ -15,7 +15,7 @@ class LaunchUITests: XCTestCase {
 
         let transactionName = app.staticTexts["TRANSACTION_NAME"]
         let transactionId = app.staticTexts["TRANSACTION_ID"]
-        if !transactionName.waitForExistence(timeout: 1) {
+        if !transactionName.waitForExistence(timeout: 5) {
             XCTFail("Span operation label not found")
         }
 

SentryTestUtils/TestClient.swift

@@ -150,8 +150,8 @@ public class TestClient: SentryClient {
         flushInvocations.record(timeout)
     }
 
-    public var captureLogsDataInvocations = Invocations<Data>()
-    public override func captureLogsData(_ data: Data) {
-        captureLogsDataInvocations.record(data)
+    public var captureLogsDataInvocations = Invocations<(data: Data, count: NSNumber)>()
+    public override func captureLogsData(_ data: Data, with count: NSNumber) {
+        captureLogsDataInvocations.record((data, count))
     }
 }

SentryTestUtils/TestSentryDispatchQueueWrapper.swift

@@ -62,6 +62,20 @@ import Foundation
         dispatchAfterInvocations.invocations.last?.block()
     }
 
+    public var dispatchAfterWorkItemInvocations = Invocations<(interval: TimeInterval, workItem: DispatchWorkItem)>()
+    public override func dispatch(after interval: TimeInterval, workItem: DispatchWorkItem) {
+        dispatchAfterWorkItemInvocations.record((interval, workItem))
+        if blockBeforeMainBlock() {
+            if dispatchAfterExecutesBlock {
+                workItem.perform()
+            }
+        }
+    }
+
+    public func invokeLastDispatchAfterWorkItem() {
+        dispatchAfterWorkItemInvocations.invocations.last?.workItem.perform()
+    }
+
     public var dispatchCancelInvocations = 0
     public override var shouldDispatchCancel: Bool {
         dispatchCancelInvocations += 1

Sources/Sentry/SentryClient.m

@@ -1129,12 +1129,13 @@ - (void)removeAttachmentProcessor:(id<SentryClientAttachmentProcessor>)attachmen
     return processedAttachments;
 }
 
-- (void)captureLogsData:(NSData *)data
+- (void)captureLogsData:(NSData *)data with:(NSNumber *)itemCount;
 {
     SentryEnvelopeItemHeader *header =
         [[SentryEnvelopeItemHeader alloc] initWithType:SentryEnvelopeItemTypeLog
                                                 length:data.length
-                                           contentType:@"application/vnd.sentry.items.log+json"];
+                                           contentType:@"application/vnd.sentry.items.log+json"
+                                             itemCount:itemCount];
 
     SentryEnvelopeItem *envelopeItem = [[SentryEnvelopeItem alloc] initWithHeader:header data:data];
     SentryEnvelope *envelope = [[SentryEnvelope alloc] initWithHeader:[SentryEnvelopeHeader empty]

Sources/Sentry/SentrySDK.m

@@ -118,14 +118,19 @@ + (SentryReplayApi *)replay
 
 + (SentryLogger *)logger
 {
+
     @synchronized(currentLoggerLock) {
         if (currentLogger == nil) {
+
             SentryLogBatcher *batcher;
             if (nil != currentHub.client && currentHub.client.options.experimental.enableLogs) {
-                batcher = [[SentryLogBatcher alloc] initWithClient:currentHub.client];
+                batcher = [[SentryLogBatcher alloc]
+                    initWithClient:currentHub.client
+                     dispatchQueue:SentryDependencyContainer.sharedInstance.dispatchQueueWrapper];
             } else {
                 batcher = nil;
             }
+
             currentLogger = [[SentryLogger alloc]
                  initWithHub:currentHub
                 dateProvider:SentryDependencyContainer.sharedInstance.dateProvider

Sources/Sentry/include/SentryClient+Logs.h

@@ -7,7 +7,7 @@ NS_ASSUME_NONNULL_BEGIN
 /**
  * Helper to capture encoded logs, as SentryEnvelope can't be used in the Swift SDK.
  */
-- (void)captureLogsData:(NSData *)data;
+- (void)captureLogsData:(NSData *)data with:(NSNumber *)itemCount;
 
 @end
 

Sources/Swift/Helper/SentryDispatchQueueWrapper.swift

@@ -45,11 +45,16 @@
     public func dispatch(after interval: TimeInterval, block: @escaping () -> Void) {
         internalWrapper.dispatch(after: interval, block: block)
     }
-
+    
     public func dispatchOnce(_ predicate: UnsafeMutablePointer<CLong>, block: @escaping () -> Void) {
         internalWrapper.dispatchOnce(predicate, block: block)
     }
 
+    @_spi(Private) public func dispatch(after interval: TimeInterval, workItem: DispatchWorkItem) {
+        // Swift only API, so we need to call the internal queue directly.
+        internalWrapper.queue.asyncAfter(deadline: .now() + interval, execute: workItem)
+    }
+
     // The ObjC version of this code wrapped `dispatch_cancel` and `dispatch_block_create`
     // However dispatch_block is not accessible in Swift. Unit tests rely on stubbing out
     // the creation and cancelation of dispatch blocks, so these two variables allow

Sources/Swift/Tools/SentryLogBatcher.swift

@@ -6,27 +6,135 @@ import Foundation
 @_spi(Private) public class SentryLogBatcher: NSObject {
 
     private let client: SentryClient
+    private let flushTimeout: TimeInterval
+    private let maxBufferSizeBytes: Int
+    private let dispatchQueue: SentryDispatchQueueWrapper
 
-    let options: Options
+    internal let options: Options
+
+    // All mutable state is accessed from the same serial dispatch queue.
 
-    @_spi(Private) public init(client: SentryClient) {
+    // Every logs data is added sepratley. They are flushed together in an envelope.
+    private var encodedLogs: [Data] = []
+    private var encodedLogsSize: Int = 0
+    private var timerWorkItem: DispatchWorkItem?
+
+    /// Initializes a new SentryLogBatcher.
+    /// - Parameters:
+    ///   - client: The SentryClient to use for sending logs
+    ///   - flushTimeout: The timeout interval after which buffered logs will be flushed
+    ///   - maxBufferSizeBytes: The maximum buffer size in bytes before triggering an immediate flush
+    ///   - dispatchQueue: A **serial** dispatch queue wrapper for thread-safe access to mutable state
+    ///
+    /// - Important: The `dispatchQueue` parameter MUST be a serial queue to ensure thread safety.
+    ///              Passing a concurrent queue will result in undefined behavior and potential data races.
+    @_spi(Private) public init(
+        client: SentryClient,
+        flushTimeout: TimeInterval,
+        maxBufferSizeBytes: Int,
+        dispatchQueue: SentryDispatchQueueWrapper
+    ) {
         self.client = client
         self.options = client.options
+        self.flushTimeout = flushTimeout
+        self.maxBufferSizeBytes = maxBufferSizeBytes
+        self.dispatchQueue = dispatchQueue
         super.init()
     }
 
-    func add(_ log: SentryLog) {
-        dispatch(logs: [log])
+    /// Convenience initializer with default flush timeout and buffer size.
+    /// - Parameters:
+    ///   - client: The SentryClient to use for sending logs
+    ///   - dispatchQueue: A **serial** dispatch queue wrapper for thread-safe access to mutable state
+    ///
+    /// - Important: The `dispatchQueue` parameter MUST be a serial queue to ensure thread safety.
+    ///              Passing a concurrent queue will result in undefined behavior and potential data races.
+    @_spi(Private) public convenience init(client: SentryClient, dispatchQueue: SentryDispatchQueueWrapper) {
+        self.init(
+            client: client,
+            flushTimeout: 5,
+            maxBufferSizeBytes: 1_024 * 1_024, // 1MB
+            dispatchQueue: dispatchQueue
+        )
+    }
+    
+    @_spi(Private) func add(_ log: SentryLog) {
+        dispatchQueue.dispatchAsync { [weak self] in
+            self?.encodeAndBuffer(log: log)
+        }
     }
 
-    private func dispatch(logs: [SentryLog]) {
+    @objc
+    @_spi(Private) func flush() {
+        dispatchQueue.dispatchAsync { [weak self] in
+            self?.performFlush()
+        }
+    }
+
+    // Helper
+
+    // Only ever call this from the serial dispatch queue.
+    private func encodeAndBuffer(log: SentryLog) {
         do {
-            let payload = ["items": logs]
-            let data = try encodeToJSONData(data: payload)
+            let encodedLog = try encodeToJSONData(data: log)
+            
+            let encodedLogsWereEmpty = encodedLogs.isEmpty
 
-            client.captureLogsData(data)
+            encodedLogs.append(encodedLog)
+            encodedLogsSize += encodedLog.count
+            
+            if encodedLogsSize >= maxBufferSizeBytes {
+                performFlush()
+            } else if encodedLogsWereEmpty && timerWorkItem == nil {
+                startTimer()
+            }
         } catch {
-            SentrySDKLog.error("Failed to create logs envelope.")
+            SentrySDKLog.error("Failed to encode log: \(error)")
+        }
+    }
+    
+    // Only ever call this from the serial dispatch queue.
+    private func startTimer() {
+        let timerWorkItem = DispatchWorkItem { [weak self] in
+            SentrySDKLog.debug("SentryLogBatcher: Timer fired, calling performFlush().")
+            self?.performFlush()
+        }
+        self.timerWorkItem = timerWorkItem
+        dispatchQueue.dispatch(after: flushTimeout, workItem: timerWorkItem)
+    }
+
+    // Only ever call this from the serial dispatch queue.
+    private func performFlush() {
+        // Reset logs on function exit
+        defer {
+            encodedLogs.removeAll()
+            encodedLogsSize = 0
+        }
+        
+        // Reset timer state
+        timerWorkItem?.cancel()
+        timerWorkItem = nil
+        
+        guard encodedLogs.count > 0 else {
+            SentrySDKLog.debug("SentryLogBatcher: No logs to flush.")
+            return
+        }
+
+        // Create the payload.
+        
+        var payloadData = Data()
+        payloadData.append(Data("{\"items\":[".utf8))
+        let separator = Data(",".utf8)
+        for (index, encodedLog) in encodedLogs.enumerated() {
+            if index > 0 {
+                payloadData.append(separator)
+            }
+            payloadData.append(encodedLog)
         }
+        payloadData.append(Data("]}".utf8))
+        
+        // Send the payload.
+        
+        client.captureLogsData(payloadData, with: NSNumber(value: encodedLogs.count))
     }
 }

Tests/Perf/metrics-test.yml

@@ -11,4 +11,4 @@ startupTimeTest:
 
 binarySizeTest:
   diffMin: 200 KiB
-  diffMax: 875 KiB
+  diffMax: 880 KiB