Logs are now flushed on shutdown (#4503)

* Add user id, username and email to log attributes

* wip

* Check log event count before sending envelope

* changelog

* Min event level config option; enable logs in logback sample

* Flush logs when client flushes

* Improve log flushing and add test

* review feedback

* treat unformatted message and params as pii if logback encoder is present

* add tests for pii handling

* changelog

* api

Author: adinauer

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
 

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<String>? = null,
     encoder: Encoder<ILoggingEvent>? = 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)

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
 }

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) {

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 <init> (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;
 }
 

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);
   }
 

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);
 }

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();
+      }
     }
   }
 

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
+  }
 }