fix(clientreport): Stop deserializing discarded logs (JAVA-662)

CHANGELOG.md

@@ -17,6 +17,8 @@
 - Use the original app build's ProGuard UUID for ANR profile chunks ([#5852](https://github.com/getsentry/sentry-java/pull/5852))
 - Fix potential ANR/deadlock in Session Replay when `checkCanRecord` runs on the replay executor thread ([#5837](https://github.com/getsentry/sentry-java/pull/5837))
 - Prevent concurrent PixelCopy access during Session Replay masking and bitmap cleanup ([#5808](https://github.com/getsentry/sentry-java/pull/5808))
+- Avoid a CPU busy-loop when recording discarded log or metric envelopes under rate limiting ([#5835](https://github.com/getsentry/sentry-java/pull/5835))
+  - `ClientReportRecorder` now reads the item count from the envelope item header instead of deserializing the payload, which under sustained rate limiting could pin CPU cores while repeatedly throwing exceptions
 - Release `MediaMuxer` when the replay video encoder fails to start to avoid a resource leak ([#5607](https://github.com/getsentry/sentry-java/pull/5607))
 - Set the correct platform (`android` instead of `java`) on ANR profile chunks so they are billed as UI Profile Hours rather than Continuous Profile Hours ([#5836](https://github.com/getsentry/sentry-java/pull/5836))
 

sentry/api/sentry.api

@@ -3112,6 +3112,7 @@ public final class io/sentry/SentryEnvelopeItemHeader : io/sentry/JsonSerializab
 	public fun getAttachmentType ()Ljava/lang/String;
 	public fun getContentType ()Ljava/lang/String;
 	public fun getFileName ()Ljava/lang/String;
+	public fun getItemCount ()Ljava/lang/Integer;
 	public fun getLength ()I
 	public fun getPlatform ()Ljava/lang/String;
 	public fun getType ()Lio/sentry/SentryItemType;

sentry/src/main/java/io/sentry/SentryEnvelopeItemHeader.java

@@ -52,6 +52,10 @@ public int getLength() {
     return platform;
   }
 
+  public @Nullable Integer getItemCount() {
+    return itemCount;
+  }
+
   @ApiStatus.Internal
   public SentryEnvelopeItemHeader(
       final @NotNull SentryItemType type,

sentry/src/main/java/io/sentry/clientreport/ClientReportRecorder.java

@@ -6,10 +6,6 @@
 import io.sentry.SentryEnvelopeItem;
 import io.sentry.SentryItemType;
 import io.sentry.SentryLevel;
-import io.sentry.SentryLogEvent;
-import io.sentry.SentryLogEvents;
-import io.sentry.SentryMetricsEvent;
-import io.sentry.SentryMetricsEvents;
 import io.sentry.SentryOptions;
 import io.sentry.protocol.SentrySpan;
 import io.sentry.protocol.SentryTransaction;
@@ -105,34 +101,18 @@ public void recordLostEnvelopeItem(
           recordLostEventInternal(reason.getReason(), itemCategory.getCategory(), 1L);
           executeOnDiscard(reason, itemCategory, 1L);
         } else if (itemCategory.equals(DataCategory.LogItem)) {
-          final @Nullable SentryLogEvents logs = envelopeItem.getLogs(options.getSerializer());
-          if (logs != null) {
-            final @NotNull List<SentryLogEvent> items = logs.getItems();
-            final long count = items.size();
-            recordLostEventInternal(reason.getReason(), itemCategory.getCategory(), count);
-            final long logBytes = envelopeItem.getData().length;
-            recordLostEventInternal(
-                reason.getReason(), DataCategory.LogByte.getCategory(), logBytes);
-            executeOnDiscard(reason, itemCategory, count);
-          } else {
-            options.getLogger().log(SentryLevel.ERROR, "Unable to parse lost logs envelope item.");
-          }
+          final long count = itemCountFromHeader(envelopeItem);
+          recordLostEventInternal(reason.getReason(), itemCategory.getCategory(), count);
+          final long logBytes = envelopeItem.getData().length;
+          recordLostEventInternal(reason.getReason(), DataCategory.LogByte.getCategory(), logBytes);
+          executeOnDiscard(reason, itemCategory, count);
         } else if (itemCategory.equals(DataCategory.TraceMetric)) {
-          final @Nullable SentryMetricsEvents metrics =
-              envelopeItem.getMetrics(options.getSerializer());
-          if (metrics != null) {
-            final @NotNull List<SentryMetricsEvent> items = metrics.getItems();
-            final long count = items.size();
-            recordLostEventInternal(reason.getReason(), itemCategory.getCategory(), count);
-            final long metricBytes = envelopeItem.getData().length;
-            recordLostEventInternal(
-                reason.getReason(), DataCategory.TraceMetricByte.getCategory(), metricBytes);
-            executeOnDiscard(reason, itemCategory, count);
-          } else {
-            options
-                .getLogger()
-                .log(SentryLevel.ERROR, "Unable to parse lost metrics envelope item.");
-          }
+          final long count = itemCountFromHeader(envelopeItem);
+          recordLostEventInternal(reason.getReason(), itemCategory.getCategory(), count);
+          final long metricBytes = envelopeItem.getData().length;
+          recordLostEventInternal(
+              reason.getReason(), DataCategory.TraceMetricByte.getCategory(), metricBytes);
+          executeOnDiscard(reason, itemCategory, count);
         } else {
           recordLostEventInternal(reason.getReason(), itemCategory.getCategory(), 1L);
           executeOnDiscard(reason, itemCategory, 1L);
@@ -176,6 +156,14 @@ private void recordLostEventInternal(
     storage.addCount(key, countToAdd);
   }
 
+  // The number of items batched into a log or metric envelope item is stored in its header, so we
+  // read it from there instead of deserializing the payload. Deserializing on the discard path is
+  // expensive and, under sustained rate limiting, caused a CPU busy-loop (JAVA-662).
+  private long itemCountFromHeader(final @NotNull SentryEnvelopeItem envelopeItem) {
+    final @Nullable Integer itemCount = envelopeItem.getHeader().getItemCount();
+    return itemCount != null ? itemCount : 1L;
+  }
+
   @Nullable
   ClientReport resetCountsAndGenerateClientReport() {
     final Date currentDate = DateUtils.getCurrentDateTime();

sentry/src/test/java/io/sentry/clientreport/ClientReportTest.kt

@@ -15,7 +15,9 @@ import io.sentry.Sentry
 import io.sentry.SentryEnvelope
 import io.sentry.SentryEnvelopeHeader
 import io.sentry.SentryEnvelopeItem
+import io.sentry.SentryEnvelopeItemHeader
 import io.sentry.SentryEvent
+import io.sentry.SentryItemType
 import io.sentry.SentryLogEvent
 import io.sentry.SentryLogEvents
 import io.sentry.SentryLogLevel
@@ -46,11 +48,17 @@ import java.util.UUID
 import kotlin.test.Test
 import kotlin.test.assertEquals
 import kotlin.test.assertTrue
+import org.mockito.kotlin.any
+import org.mockito.kotlin.doReturn
 import org.mockito.kotlin.mock
+import org.mockito.kotlin.never
 import org.mockito.kotlin.times
 import org.mockito.kotlin.verify
 import org.mockito.kotlin.whenever
 
+private const val LOG_CONTENT_TYPE = "application/vnd.sentry.items.log+json"
+private const val METRIC_CONTENT_TYPE = "application/vnd.sentry.items.trace-metric+json"
+
 class ClientReportTest {
   lateinit var opts: SentryOptions
   lateinit var clientReportRecorder: ClientReportRecorder
@@ -312,28 +320,24 @@ class ClientReportTest {
   }
 
   @Test
-  fun `recording envelope with lost client report does not duplicate onDiscard executions`() {
-    val onDiscardMock = mock<SentryOptions.OnDiscardCallback>()
-    givenClientReportRecorder { options -> options.onDiscard = onDiscardMock }
-
-    clientReportRecorder.recordLostEvent(DiscardReason.CACHE_OVERFLOW, DataCategory.Attachment)
-    clientReportRecorder.recordLostEvent(DiscardReason.CACHE_OVERFLOW, DataCategory.Attachment)
-    clientReportRecorder.recordLostEvent(DiscardReason.RATELIMIT_BACKOFF, DataCategory.Error)
-    clientReportRecorder.recordLostEvent(DiscardReason.QUEUE_OVERFLOW, DataCategory.Error)
-    clientReportRecorder.recordLostEvent(DiscardReason.BEFORE_SEND, DataCategory.Profile)
-
-    val envelope = clientReportRecorder.attachReportToEnvelope(testHelper.newEnvelope())
-    clientReportRecorder.recordLostEnvelope(DiscardReason.EVENT_PROCESSOR, envelope)
-
-    verify(onDiscardMock, times(2))
-      .execute(DiscardReason.CACHE_OVERFLOW, DataCategory.Attachment, 1)
-    verify(onDiscardMock, times(1)).execute(DiscardReason.RATELIMIT_BACKOFF, DataCategory.Error, 1)
-    verify(onDiscardMock, times(1)).execute(DiscardReason.QUEUE_OVERFLOW, DataCategory.Error, 1)
-    verify(onDiscardMock, times(1)).execute(DiscardReason.BEFORE_SEND, DataCategory.Profile, 1)
+  fun `restoring counts via recordLostEnvelope does not fire onDiscard again`() {
+    assertRestoringCountsDoesNotFireOnDiscard { recorder, envelope ->
+      recorder.recordLostEnvelope(DiscardReason.EVENT_PROCESSOR, envelope)
+    }
   }
 
   @Test
-  fun `recording lost client report does not duplicate onDiscard executions`() {
+  fun `restoring counts via recordLostEnvelopeItem does not fire onDiscard again`() {
+    assertRestoringCountsDoesNotFireOnDiscard { recorder, envelope ->
+      recorder.recordLostEnvelopeItem(DiscardReason.NETWORK_ERROR, envelope.items.first())
+    }
+  }
+
+  // Counts restored from an attached client report were already reported once, so replaying them
+  // must not fire onDiscard a second time. Both public entry points have to hold the property.
+  private fun assertRestoringCountsDoesNotFireOnDiscard(
+    recordLost: (ClientReportRecorder, SentryEnvelope) -> Unit
+  ) {
     val onDiscardMock = mock<SentryOptions.OnDiscardCallback>()
     givenClientReportRecorder { options -> options.onDiscard = onDiscardMock }
 
@@ -344,7 +348,7 @@ class ClientReportTest {
     clientReportRecorder.recordLostEvent(DiscardReason.BEFORE_SEND, DataCategory.Profile)
 
     val envelope = clientReportRecorder.attachReportToEnvelope(testHelper.newEnvelope())
-    clientReportRecorder.recordLostEnvelopeItem(DiscardReason.NETWORK_ERROR, envelope.items.first())
+    recordLost(clientReportRecorder, envelope)
 
     verify(onDiscardMock, times(2))
       .execute(DiscardReason.CACHE_OVERFLOW, DataCategory.Attachment, 1)
@@ -417,6 +421,98 @@ class ClientReportTest {
     assertEquals(envelope.items.first().data.size.toLong(), metricByteItem.quantity)
   }
 
+  @Test
+  fun `recording lost log item reads count from the header without deserializing the payload`() {
+    val onDiscardMock = mock<SentryOptions.OnDiscardCallback>()
+    givenClientReportRecorder { options -> options.onDiscard = onDiscardMock }
+
+    val payload = "irrelevant payload".toByteArray()
+    val item = mockEnvelopeItem(SentryItemType.Log, LOG_CONTENT_TYPE, itemCount = 5, data = payload)
+
+    clientReportRecorder.recordLostEnvelopeItem(DiscardReason.NETWORK_ERROR, item)
+
+    // Deserializing here is what pinned CPU cores under sustained rate limiting (JAVA-662), so the
+    // count must come from the header and the payload must stay untouched.
+    verify(item, never()).getLogs(any())
+    verify(onDiscardMock, times(1)).execute(DiscardReason.NETWORK_ERROR, DataCategory.LogItem, 5)
+
+    val clientReport = clientReportRecorder.resetCountsAndGenerateClientReport()
+    assertEquals(5, clientReport.quantityOf(DataCategory.LogItem))
+    assertEquals(payload.size.toLong(), clientReport.quantityOf(DataCategory.LogByte))
+  }
+
+  @Test
+  fun `recording lost metric item reads count from the header without deserializing the payload`() {
+    val onDiscardMock = mock<SentryOptions.OnDiscardCallback>()
+    givenClientReportRecorder { options -> options.onDiscard = onDiscardMock }
+
+    val payload = "irrelevant payload".toByteArray()
+    val item =
+      mockEnvelopeItem(
+        SentryItemType.TraceMetric,
+        METRIC_CONTENT_TYPE,
+        itemCount = 5,
+        data = payload,
+      )
+
+    clientReportRecorder.recordLostEnvelopeItem(DiscardReason.NETWORK_ERROR, item)
+
+    verify(item, never()).getMetrics(any())
+    verify(onDiscardMock, times(1))
+      .execute(DiscardReason.NETWORK_ERROR, DataCategory.TraceMetric, 5)
+
+    val clientReport = clientReportRecorder.resetCountsAndGenerateClientReport()
+    assertEquals(5, clientReport.quantityOf(DataCategory.TraceMetric))
+    assertEquals(payload.size.toLong(), clientReport.quantityOf(DataCategory.TraceMetricByte))
+  }
+
+  @Test
+  fun `recording lost log item without item count in header falls back to one`() {
+    givenClientReportRecorder()
+
+    val item =
+      mockEnvelopeItem(SentryItemType.Log, LOG_CONTENT_TYPE, itemCount = null, data = ByteArray(0))
+
+    clientReportRecorder.recordLostEnvelopeItem(DiscardReason.NETWORK_ERROR, item)
+
+    val clientReport = clientReportRecorder.resetCountsAndGenerateClientReport()
+    assertEquals(1, clientReport.quantityOf(DataCategory.LogItem))
+  }
+
+  @Test
+  fun `recording lost metric item without item count in header falls back to one`() {
+    givenClientReportRecorder()
+
+    val item =
+      mockEnvelopeItem(
+        SentryItemType.TraceMetric,
+        METRIC_CONTENT_TYPE,
+        itemCount = null,
+        data = ByteArray(0),
+      )
+
+    clientReportRecorder.recordLostEnvelopeItem(DiscardReason.NETWORK_ERROR, item)
+
+    val clientReport = clientReportRecorder.resetCountsAndGenerateClientReport()
+    assertEquals(1, clientReport.quantityOf(DataCategory.TraceMetric))
+  }
+
+  private fun mockEnvelopeItem(
+    type: SentryItemType,
+    contentType: String,
+    itemCount: Int?,
+    data: ByteArray,
+  ): SentryEnvelopeItem {
+    val itemHeader = SentryEnvelopeItemHeader(type, 0, contentType, null, null, null, itemCount)
+    return mock {
+      on { it.header } doReturn itemHeader
+      on { it.data } doReturn data
+    }
+  }
+
+  private fun ClientReport?.quantityOf(category: DataCategory): Long =
+    this!!.discardedEvents!!.first { it.category == category.category }.quantity
+
   private fun givenClientReportRecorder(
     callback: Sentry.OptionsConfiguration<SentryOptions>? = null
   ) {
@@ -470,9 +566,6 @@ class ClientReportTestHelper(val options: SentryOptions) {
     return SentryEnvelope(header, items.toList())
   }
 
-  fun toEnvelopeItem(clientReport: ClientReport): SentryEnvelopeItem =
-    SentryEnvelopeItem.fromClientReport(options.serializer, clientReport)
-
   companion object {
     fun retryableHint() = HintUtils.createWithTypeCheckHint(TestRetryable())