diff --git a/CHANGELOG.md b/CHANGELOG.md index 9aaa10b3482..16b2b90f046 100644 --- a/CHANGELOG.md +++ b/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)) diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api index 14780d1a4b2..fc1e125f7b3 100644 --- a/sentry/api/sentry.api +++ b/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; diff --git a/sentry/src/main/java/io/sentry/SentryEnvelopeItemHeader.java b/sentry/src/main/java/io/sentry/SentryEnvelopeItemHeader.java index 25f1e893fc3..23b3afc2a27 100644 --- a/sentry/src/main/java/io/sentry/SentryEnvelopeItemHeader.java +++ b/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, diff --git a/sentry/src/main/java/io/sentry/clientreport/ClientReportRecorder.java b/sentry/src/main/java/io/sentry/clientreport/ClientReportRecorder.java index b3756ed32e4..ccd7c5dc402 100644 --- a/sentry/src/main/java/io/sentry/clientreport/ClientReportRecorder.java +++ b/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 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 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(); diff --git a/sentry/src/test/java/io/sentry/clientreport/ClientReportTest.kt b/sentry/src/test/java/io/sentry/clientreport/ClientReportTest.kt index ceb254213cb..b89b1894f32 100644 --- a/sentry/src/test/java/io/sentry/clientreport/ClientReportTest.kt +++ b/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() - 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() 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() + 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() + 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? = 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())