Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -1,12 +1,15 @@
package io.sentry.android.core

import androidx.test.ext.junit.runners.AndroidJUnit4
import com.google.common.truth.Truth.assertThat
import io.sentry.ISentryClient
import io.sentry.SentryLogEvent
import io.sentry.SentryLogLevel
import io.sentry.SentryOptions
import io.sentry.protocol.SentryId
import io.sentry.test.ImmediateExecutorService
import io.sentry.test.getProperty
import java.util.concurrent.atomic.AtomicBoolean
import kotlin.test.AfterTest
import kotlin.test.BeforeTest
import kotlin.test.Test
Expand All @@ -15,6 +18,7 @@ import kotlin.test.assertTrue
import org.junit.runner.RunWith
import org.mockito.kotlin.any
import org.mockito.kotlin.mock
import org.mockito.kotlin.never
import org.mockito.kotlin.verify
import org.mockito.kotlin.whenever

Expand Down Expand Up @@ -55,6 +59,16 @@ class AndroidLoggerBatchProcessorTest {
assertNotNull(AppState.getInstance().lifecycleObserver)
}

@Test
fun `onBackground does not flush before first accepted item`() {
val sut = fixture.getSut(useImmediateExecutor = true)

sut.onBackground()

assertThat(sut.getProperty<AtomicBoolean>("hasScheduled").get()).isFalse()
verify(fixture.client, never()).captureBatchedLogEvents(any())
}

@Test
fun `onBackground schedules flush`() {
val sut = fixture.getSut(useImmediateExecutor = true)
Expand Down
17 changes: 11 additions & 6 deletions sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ public class LoggerBatchProcessor implements ILoggerBatchProcessor {
private final @NotNull Queue<SentryLogEvent> queue;
private final @NotNull ISentryExecutorService executorService;
private final @NotNull AtomicBoolean hasScheduled = new AtomicBoolean(false);
private volatile boolean hasAcceptedItem = false;
private volatile boolean isShuttingDown = false;

private final @NotNull ReusableCountLatch pendingCount = new ReusableCountLatch();
Expand Down Expand Up @@ -75,21 +76,22 @@ public void add(final @NotNull SentryLogEvent logEvent) {
}
pendingCount.increment();
queue.offer(logEvent);
hasAcceptedItem = true;
maybeSchedule(false);
Comment on lines 78 to 80

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bug: A race condition between add() and close() can cause log events to be lost if an event is added after the executor has been shut down but before the queue is drained.
Severity: MEDIUM

Suggested Fix

Synchronize access to the shutdown state and executor operations. For example, use a synchronized block around the shutdown check and item queuing in add() and the entire close() method to ensure that add() cannot proceed while a shutdown is in progress.

Prompt for AI Agent
Review the code at the location below. A potential bug has been identified by an AI
agent. Verify if this is a real issue. If it is, propose a fix; if not, explain why it's
not valid.

Location: sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java#L78-L80

Potential issue: A race condition exists between the `add()` and `close()` methods in
`LoggerBatchProcessor`. A thread calling `add()` can pass the `isShuttingDown` check
just before another thread calling `close()` sets `isShuttingDown` to true and shuts
down the `executorService`. The first thread then adds a log event to the queue but
fails to schedule a flush task because the executor is closed, leading to a
`RejectedExecutionException`. The event remains in the queue but is never processed
because the queue drain in `close()` may have already completed, resulting in the silent
loss of the log event.

Also affects:

  • sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java:116~124

Did we get this right? 👍 / 👎 to inform future reviews.

}

@SuppressWarnings("FutureReturnValueIgnored")
@Override
public void close(final boolean isRestarting) {
isShuttingDown = true;
if (isRestarting) {
if (isRestarting && hasAcceptedItem) {
maybeSchedule(true);
executorService.submit(() -> executorService.close(options.getShutdownTimeoutMillis()));
} else {
executorService.close(options.getShutdownTimeoutMillis());
while (!queue.isEmpty()) {
flushBatch();
}
return;
}
executorService.close(options.getShutdownTimeoutMillis());
while (!queue.isEmpty()) {
flushBatch();
}
}

Expand All @@ -114,6 +116,9 @@ private void maybeSchedule(boolean immediately) {

@Override
public void flush(long timeoutMillis) {
if (!hasAcceptedItem) {
return;
}
maybeSchedule(true);
try {
pendingCount.waitTillZero(timeoutMillis, TimeUnit.MILLISECONDS);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ package io.sentry.logger
import com.google.common.truth.Truth.assertThat
import io.sentry.DataCategory
import io.sentry.ISentryClient
import io.sentry.ISentryExecutorService
import io.sentry.SentryLogEvent
import io.sentry.SentryLogEvents
import io.sentry.SentryLogLevel
Expand All @@ -13,19 +14,106 @@ import io.sentry.clientreport.DiscardReason
import io.sentry.clientreport.DiscardedEvent
import io.sentry.protocol.SentryId
import io.sentry.test.DeferredExecutorService
import io.sentry.test.getProperty
import io.sentry.test.injectForField
import io.sentry.transport.ReusableCountLatch
import io.sentry.util.JsonSerializationUtils
import kotlin.test.Test
import kotlin.test.assertEquals
import kotlin.test.assertFalse
import kotlin.test.assertTrue
import org.mockito.kotlin.any
import org.mockito.kotlin.argumentCaptor
import org.mockito.kotlin.atLeast
import org.mockito.kotlin.mock
import org.mockito.kotlin.never
import org.mockito.kotlin.times
import org.mockito.kotlin.verify
import org.mockito.kotlin.verifyNoInteractions

class LoggerBatchProcessorTest {
@Test
fun `constructor does not submit processor work`() {
val mockExecutor = mock<ISentryExecutorService>()

LoggerBatchProcessor(SentryOptions(), mock(), mockExecutor)

verifyNoInteractions(mockExecutor)
}

@Test
fun `empty flush does not submit processor work`() {
val mockExecutor = mock<ISentryExecutorService>()
val processor = LoggerBatchProcessor(SentryOptions(), mock(), mockExecutor)

processor.flush(0)

verifyNoInteractions(mockExecutor)
}

@Test
fun `close before first accepted item does not submit processor work`() {
val mockExecutor = mock<ISentryExecutorService>()
val processor = LoggerBatchProcessor(SentryOptions(), mock(), mockExecutor)

processor.close(false)

verify(mockExecutor).close(any())
verify(mockExecutor, never()).schedule(any(), any())
verify(mockExecutor, never()).submit(any<Runnable>())
}

@Test
fun `restart close before first accepted item does not submit processor work`() {
val mockExecutor = mock<ISentryExecutorService>()
val processor = LoggerBatchProcessor(SentryOptions(), mock(), mockExecutor)

processor.close(true)

verify(mockExecutor).close(any())
verify(mockExecutor, never()).schedule(any(), any())
verify(mockExecutor, never()).submit(any<Runnable>())
}

@Test
fun `item rejected during shutdown does not mark processor as used`() {
val mockExecutor = mock<ISentryExecutorService>()
val processor = LoggerBatchProcessor(SentryOptions(), mock(), mockExecutor)
processor.close(false)

processor.add(logEvent("rejected"))
processor.flush(0)

verify(mockExecutor, never()).schedule(any(), any())
verify(mockExecutor, never()).submit(any<Runnable>())
}

@Test
fun `item rejected due to queue capacity does not mark processor as used`() {
val mockExecutor = mock<ISentryExecutorService>()
val processor = LoggerBatchProcessor(SentryOptions(), mock(), mockExecutor)
val pendingCount = processor.getProperty<ReusableCountLatch>("pendingCount")
repeat(LoggerBatchProcessor.MAX_QUEUE_SIZE) { pendingCount.increment() }

processor.add(logEvent("rejected"))
processor.flush(0)

verifyNoInteractions(mockExecutor)
}

@Test
fun `flush and restart close submit processor work after first accepted item`() {
val mockExecutor = mock<ISentryExecutorService>()
val processor = LoggerBatchProcessor(SentryOptions(), mock(), mockExecutor)
processor.add(logEvent("accepted"))

processor.flush(0)
processor.close(true)

verify(mockExecutor, times(3)).schedule(any(), any())
verify(mockExecutor).submit(any<Runnable>())
}

@Test
fun `schedules another flush after previous flush has run`() {
val mockClient = mock<ISentryClient>()
Expand All @@ -46,6 +134,9 @@ class LoggerBatchProcessorTest {
.inOrder()
}

private fun logEvent(body: String) =
SentryLogEvent(SentryId(), SentryNanotimeDate(), body, SentryLogLevel.INFO)

@Test
fun `drops log events after reaching MAX_QUEUE_SIZE limit`() {
// given
Expand Down
Loading