diff --git a/CHANGELOG.md b/CHANGELOG.md index 681e1ba8af..88f39b4f0a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ - Session Replay: Expand fix for crash on devices to all Unisoc/Spreadtrum chipsets ([#4510](https://github.com/getsentry/sentry-java/pull/4510)) - Log parameter objects are now turned into `String` via `toString` ([#4515](https://github.com/getsentry/sentry-java/pull/4515)) - One of the two `SentryLogEventAttributeValue` constructors did not convert the value previously. +- Logs are now flushed on shutdown ([#4503](https://github.com/getsentry/sentry-java/pull/4503)) ### Features diff --git a/sentry-logback/src/test/kotlin/io/sentry/logback/SentryAppenderTest.kt b/sentry-logback/src/test/kotlin/io/sentry/logback/SentryAppenderTest.kt index 63d6a96ec6..431ede18d9 100644 --- a/sentry-logback/src/test/kotlin/io/sentry/logback/SentryAppenderTest.kt +++ b/sentry-logback/src/test/kotlin/io/sentry/logback/SentryAppenderTest.kt @@ -14,8 +14,10 @@ import io.sentry.ITransportFactory import io.sentry.InitPriority import io.sentry.Sentry import io.sentry.SentryLevel +import io.sentry.SentryLogLevel import io.sentry.SentryOptions import io.sentry.checkEvent +import io.sentry.checkLogs import io.sentry.test.initForTest import io.sentry.transport.ITransport import java.time.Instant @@ -44,9 +46,11 @@ class SentryAppenderTest { dsn: String? = "http://key@localhost/proj", minimumBreadcrumbLevel: Level? = null, minimumEventLevel: Level? = null, + minimumLevel: Level? = null, contextTags: List? = null, encoder: Encoder? = null, sendDefaultPii: Boolean = false, + enableLogs: Boolean = false, options: SentryOptions = SentryOptions(), startLater: Boolean = false, ) { @@ -63,10 +67,12 @@ class SentryAppenderTest { this.encoder = encoder options.dsn = dsn options.isSendDefaultPii = sendDefaultPii + options.logs.isEnabled = enableLogs contextTags?.forEach { options.addContextTag(it) } appender.setOptions(options) appender.setMinimumBreadcrumbLevel(minimumBreadcrumbLevel) appender.setMinimumEventLevel(minimumEventLevel) + appender.setMinimumLevel(minimumLevel) appender.context = loggerContext appender.setTransportFactory(transportFactory) encoder?.context = loggerContext @@ -306,6 +312,154 @@ class SentryAppenderTest { ) } + @Test + fun `converts trace log level to Sentry log level`() { + fixture = Fixture(minimumLevel = Level.TRACE, enableLogs = true) + fixture.logger.trace("testing trace level") + + Sentry.flush(1000) + + verify(fixture.transport) + .send(checkLogs { logs -> assertEquals(SentryLogLevel.TRACE, logs.items.first().level) }) + } + + @Test + fun `converts debug log level to Sentry log level`() { + fixture = Fixture(minimumLevel = Level.DEBUG, enableLogs = true) + fixture.logger.debug("testing debug level") + + Sentry.flush(1000) + + verify(fixture.transport) + .send(checkLogs { logs -> assertEquals(SentryLogLevel.DEBUG, logs.items.first().level) }) + } + + @Test + fun `converts info log level to Sentry log level`() { + fixture = Fixture(minimumLevel = Level.INFO, enableLogs = true) + fixture.logger.info("testing info level") + + Sentry.flush(1000) + + verify(fixture.transport) + .send(checkLogs { logs -> assertEquals(SentryLogLevel.INFO, logs.items.first().level) }) + } + + @Test + fun `converts warn log level to Sentry log level`() { + fixture = Fixture(minimumLevel = Level.WARN, enableLogs = true) + fixture.logger.warn("testing warn level") + + Sentry.flush(1000) + + verify(fixture.transport) + .send(checkLogs { logs -> assertEquals(SentryLogLevel.WARN, logs.items.first().level) }) + } + + @Test + fun `converts error log level to Sentry log level`() { + fixture = Fixture(minimumLevel = Level.ERROR, enableLogs = true) + fixture.logger.error("testing error level") + + Sentry.flush(1000) + + verify(fixture.transport) + .send(checkLogs { logs -> assertEquals(SentryLogLevel.ERROR, logs.items.first().level) }) + } + + @Test + fun `sends formatted log message if no encoder`() { + fixture = Fixture(minimumLevel = Level.TRACE, enableLogs = true) + fixture.logger.trace("Testing {} level", "TRACE") + + Sentry.flush(1000) + + verify(fixture.transport) + .send( + checkLogs { logs -> + val log = logs.items.first() + assertEquals("Testing TRACE level", log.body) + val attributes = log.attributes!! + assertEquals("Testing {} level", attributes["sentry.message.template"]?.value) + assertEquals("TRACE", attributes["sentry.message.parameter.0"]?.value) + } + ) + } + + @Test + fun `does not send formatted log message if encoder is available but sendDefaultPii is off`() { + var encoder = PatternLayoutEncoder() + encoder.pattern = "encoderadded %msg" + fixture = Fixture(minimumLevel = Level.TRACE, enableLogs = true, encoder = encoder) + fixture.logger.trace("Testing {} level", "TRACE") + + Sentry.flush(1000) + + verify(fixture.transport) + .send( + checkLogs { logs -> + val log = logs.items.first() + assertEquals("encoderadded Testing TRACE level", log.body) + val attributes = log.attributes!! + assertNull(attributes["sentry.message.template"]) + assertNull(attributes["sentry.message.parameter.0"]) + } + ) + } + + @Test + fun `sends formatted log message if encoder is available and sendDefaultPii is on but encoder throws`() { + var encoder = ThrowingEncoder() + fixture = + Fixture( + minimumLevel = Level.TRACE, + enableLogs = true, + sendDefaultPii = true, + encoder = encoder, + ) + fixture.logger.trace("Testing {} level", "TRACE") + + Sentry.flush(1000) + + verify(fixture.transport) + .send( + checkLogs { logs -> + val log = logs.items.first() + assertEquals("Testing TRACE level", log.body) + val attributes = log.attributes!! + assertEquals("Testing {} level", attributes["sentry.message.template"]?.value) + assertEquals("TRACE", attributes["sentry.message.parameter.0"]?.value) + } + ) + } + + @Test + fun `sends formatted log message if encoder is available and sendDefaultPii is on`() { + var encoder = PatternLayoutEncoder() + encoder.pattern = "encoderadded %msg" + fixture = + Fixture( + minimumLevel = Level.TRACE, + enableLogs = true, + sendDefaultPii = true, + encoder = encoder, + ) + fixture.logger.trace("Testing {} level", "TRACE") + + Sentry.flush(1000) + + verify(fixture.transport) + .send( + checkLogs { logs -> + val log = logs.items.first() + assertEquals("encoderadded Testing TRACE level", log.body) + val attributes = log.attributes!! + assertEquals("Testing {} level", attributes["sentry.message.template"]?.value) + assertEquals("TRACE", attributes["sentry.message.parameter.0"]?.value) + } + ) + } + @Test fun `attaches thread information`() { fixture = Fixture(minimumEventLevel = Level.WARN) diff --git a/sentry-test-support/api/sentry-test-support.api b/sentry-test-support/api/sentry-test-support.api index 44a3bc7f14..2623a7813d 100644 --- a/sentry-test-support/api/sentry-test-support.api +++ b/sentry-test-support/api/sentry-test-support.api @@ -6,6 +6,7 @@ public final class io/sentry/AssertionsKt { public static final fun assertEnvelopeTransaction (Ljava/util/List;Lio/sentry/ILogger;Lkotlin/jvm/functions/Function2;)Lio/sentry/protocol/SentryTransaction; public static synthetic fun assertEnvelopeTransaction$default (Ljava/util/List;Lio/sentry/ILogger;Lkotlin/jvm/functions/Function2;ILjava/lang/Object;)Lio/sentry/protocol/SentryTransaction; public static final fun checkEvent (Lkotlin/jvm/functions/Function1;)Lio/sentry/SentryEnvelope; + public static final fun checkLogs (Lkotlin/jvm/functions/Function1;)Lio/sentry/SentryEnvelope; public static final fun checkTransaction (Lkotlin/jvm/functions/Function1;)Lio/sentry/SentryEnvelope; public static final fun getMockServerRequestTimeoutMillis ()J } diff --git a/sentry-test-support/src/main/kotlin/io/sentry/Assertions.kt b/sentry-test-support/src/main/kotlin/io/sentry/Assertions.kt index 8bbf5392f2..73affefa2f 100644 --- a/sentry-test-support/src/main/kotlin/io/sentry/Assertions.kt +++ b/sentry-test-support/src/main/kotlin/io/sentry/Assertions.kt @@ -14,6 +14,18 @@ fun checkEvent(predicate: (SentryEvent) -> Unit): SentryEnvelope = check { } } +/** Verifies is [SentryEnvelope] contains log events matching a predicate. */ +fun checkLogs(predicate: (SentryLogEvents) -> Unit): SentryEnvelope { + return check { + val events: SentryLogEvents? = it.items.first().getLogs(JsonSerializer(SentryOptions.empty())) + if (events != null) { + predicate(events) + } else { + throw SkipError("event is null") + } + } +} + fun checkTransaction(predicate: (SentryTransaction) -> Unit): SentryEnvelope = check { val transaction = it.items.first().getTransaction(JsonSerializer(SentryOptions.empty())) if (transaction != null) { diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api index 864d23840c..1f1a3d9a74 100644 --- a/sentry/api/sentry.api +++ b/sentry/api/sentry.api @@ -4817,6 +4817,7 @@ public abstract interface class io/sentry/logger/ILoggerApi { public abstract interface class io/sentry/logger/ILoggerBatchProcessor { public abstract fun add (Lio/sentry/SentryLogEvent;)V public abstract fun close (Z)V + public abstract fun flush (J)V } public final class io/sentry/logger/LoggerApi : io/sentry/logger/ILoggerApi { @@ -4838,6 +4839,7 @@ public final class io/sentry/logger/LoggerBatchProcessor : io/sentry/logger/ILog public fun (Lio/sentry/SentryOptions;Lio/sentry/ISentryClient;)V public fun add (Lio/sentry/SentryLogEvent;)V public fun close (Z)V + public fun flush (J)V } public final class io/sentry/logger/NoOpLoggerApi : io/sentry/logger/ILoggerApi { @@ -4856,6 +4858,7 @@ public final class io/sentry/logger/NoOpLoggerApi : io/sentry/logger/ILoggerApi public final class io/sentry/logger/NoOpLoggerBatchProcessor : io/sentry/logger/ILoggerBatchProcessor { public fun add (Lio/sentry/SentryLogEvent;)V public fun close (Z)V + public fun flush (J)V public static fun getInstance ()Lio/sentry/logger/NoOpLoggerBatchProcessor; } diff --git a/sentry/src/main/java/io/sentry/SentryClient.java b/sentry/src/main/java/io/sentry/SentryClient.java index 617083b1a3..998f1c5d8d 100644 --- a/sentry/src/main/java/io/sentry/SentryClient.java +++ b/sentry/src/main/java/io/sentry/SentryClient.java @@ -1544,6 +1544,7 @@ public void close(final boolean isRestarting) { @Override public void flush(final long timeoutMillis) { + loggerBatchProcessor.flush(timeoutMillis); transport.flush(timeoutMillis); } diff --git a/sentry/src/main/java/io/sentry/logger/ILoggerBatchProcessor.java b/sentry/src/main/java/io/sentry/logger/ILoggerBatchProcessor.java index 9dbc7c883e..8d0fa154dc 100644 --- a/sentry/src/main/java/io/sentry/logger/ILoggerBatchProcessor.java +++ b/sentry/src/main/java/io/sentry/logger/ILoggerBatchProcessor.java @@ -7,4 +7,11 @@ public interface ILoggerBatchProcessor { void add(@NotNull SentryLogEvent event); void close(boolean isRestarting); + + /** + * Flushes log events. + * + * @param timeoutMillis time in milliseconds + */ + void flush(long timeoutMillis); } diff --git a/sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java b/sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java index 08532b64ef..5aa03a7411 100644 --- a/sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java +++ b/sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java @@ -4,15 +4,18 @@ import io.sentry.ISentryExecutorService; import io.sentry.ISentryLifecycleToken; import io.sentry.SentryExecutorService; +import io.sentry.SentryLevel; import io.sentry.SentryLogEvent; import io.sentry.SentryLogEvents; import io.sentry.SentryOptions; +import io.sentry.transport.ReusableCountLatch; import io.sentry.util.AutoClosableReentrantLock; import java.util.ArrayList; import java.util.List; import java.util.Queue; import java.util.concurrent.ConcurrentLinkedQueue; import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; @@ -30,6 +33,8 @@ public final class LoggerBatchProcessor implements ILoggerBatchProcessor { new AutoClosableReentrantLock(); private volatile boolean hasScheduled = false; + private final @NotNull ReusableCountLatch pendingCount = new ReusableCountLatch(); + public LoggerBatchProcessor( final @NotNull SentryOptions options, final @NotNull ISentryClient client) { this.options = options; @@ -40,6 +45,7 @@ public LoggerBatchProcessor( @Override public void add(final @NotNull SentryLogEvent logEvent) { + pendingCount.increment(); queue.offer(logEvent); maybeSchedule(false, false); } @@ -75,6 +81,17 @@ private void maybeSchedule(boolean forceSchedule, boolean immediately) { } } + @Override + public void flush(long timeoutMillis) { + maybeSchedule(true, true); + try { + pendingCount.waitTillZero(timeoutMillis, TimeUnit.MILLISECONDS); + } catch (InterruptedException e) { + options.getLogger().log(SentryLevel.ERROR, "Failed to flush log events", e); + Thread.currentThread().interrupt(); + } + } + private void flush() { flushInternal(); try (final @NotNull ISentryLifecycleToken ignored = scheduleLock.acquire()) { @@ -103,6 +120,9 @@ private void flushBatch() { if (!logEvents.isEmpty()) { client.captureBatchedLogEvents(new SentryLogEvents(logEvents)); + for (int i = 0; i < logEvents.size(); i++) { + pendingCount.decrement(); + } } } diff --git a/sentry/src/main/java/io/sentry/logger/NoOpLoggerBatchProcessor.java b/sentry/src/main/java/io/sentry/logger/NoOpLoggerBatchProcessor.java index 9568304444..372b9f6b67 100644 --- a/sentry/src/main/java/io/sentry/logger/NoOpLoggerBatchProcessor.java +++ b/sentry/src/main/java/io/sentry/logger/NoOpLoggerBatchProcessor.java @@ -24,4 +24,9 @@ public void add(@NotNull SentryLogEvent event) { public void close(final boolean isRestarting) { // do nothing } + + @Override + public void flush(long timeoutMillis) { + // do nothing + } }