Skip to content

Commit 9f37401

Browse files
adinaueradinauer
authored
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
1 parent ea7b9c1 commit 9f37401

File tree

9 files changed

+204
-0
lines changed

9 files changed

+204
-0
lines changed

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
- Session Replay: Expand fix for crash on devices to all Unisoc/Spreadtrum chipsets ([#4510](https://github.com/getsentry/sentry-java/pull/4510))
1313
- Log parameter objects are now turned into `String` via `toString` ([#4515](https://github.com/getsentry/sentry-java/pull/4515))
1414
- One of the two `SentryLogEventAttributeValue` constructors did not convert the value previously.
15+
- Logs are now flushed on shutdown ([#4503](https://github.com/getsentry/sentry-java/pull/4503))
1516

1617
### Features
1718

‎sentry-logback/src/test/kotlin/io/sentry/logback/SentryAppenderTest.kt‎

Lines changed: 154 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,8 +14,10 @@ import io.sentry.ITransportFactory
1414
import io.sentry.InitPriority
1515
import io.sentry.Sentry
1616
import io.sentry.SentryLevel
17+
import io.sentry.SentryLogLevel
1718
import io.sentry.SentryOptions
1819
import io.sentry.checkEvent
20+
import io.sentry.checkLogs
1921
import io.sentry.test.initForTest
2022
import io.sentry.transport.ITransport
2123
import java.time.Instant
@@ -44,9 +46,11 @@ class SentryAppenderTest {
4446
dsn: String? = "http://key@localhost/proj",
4547
minimumBreadcrumbLevel: Level? = null,
4648
minimumEventLevel: Level? = null,
49+
minimumLevel: Level? = null,
4750
contextTags: List<String>? = null,
4851
encoder: Encoder<ILoggingEvent>? = null,
4952
sendDefaultPii: Boolean = false,
53+
enableLogs: Boolean = false,
5054
options: SentryOptions = SentryOptions(),
5155
startLater: Boolean = false,
5256
) {
@@ -63,10 +67,12 @@ class SentryAppenderTest {
6367
this.encoder = encoder
6468
options.dsn = dsn
6569
options.isSendDefaultPii = sendDefaultPii
70+
options.logs.isEnabled = enableLogs
6671
contextTags?.forEach { options.addContextTag(it) }
6772
appender.setOptions(options)
6873
appender.setMinimumBreadcrumbLevel(minimumBreadcrumbLevel)
6974
appender.setMinimumEventLevel(minimumEventLevel)
75+
appender.setMinimumLevel(minimumLevel)
7076
appender.context = loggerContext
7177
appender.setTransportFactory(transportFactory)
7278
encoder?.context = loggerContext
@@ -306,6 +312,154 @@ class SentryAppenderTest {
306312
)
307313
}
308314

315+
@Test
316+
fun `converts trace log level to Sentry log level`() {
317+
fixture = Fixture(minimumLevel = Level.TRACE, enableLogs = true)
318+
fixture.logger.trace("testing trace level")
319+
320+
Sentry.flush(1000)
321+
322+
verify(fixture.transport)
323+
.send(checkLogs { logs -> assertEquals(SentryLogLevel.TRACE, logs.items.first().level) })
324+
}
325+
326+
@Test
327+
fun `converts debug log level to Sentry log level`() {
328+
fixture = Fixture(minimumLevel = Level.DEBUG, enableLogs = true)
329+
fixture.logger.debug("testing debug level")
330+
331+
Sentry.flush(1000)
332+
333+
verify(fixture.transport)
334+
.send(checkLogs { logs -> assertEquals(SentryLogLevel.DEBUG, logs.items.first().level) })
335+
}
336+
337+
@Test
338+
fun `converts info log level to Sentry log level`() {
339+
fixture = Fixture(minimumLevel = Level.INFO, enableLogs = true)
340+
fixture.logger.info("testing info level")
341+
342+
Sentry.flush(1000)
343+
344+
verify(fixture.transport)
345+
.send(checkLogs { logs -> assertEquals(SentryLogLevel.INFO, logs.items.first().level) })
346+
}
347+
348+
@Test
349+
fun `converts warn log level to Sentry log level`() {
350+
fixture = Fixture(minimumLevel = Level.WARN, enableLogs = true)
351+
fixture.logger.warn("testing warn level")
352+
353+
Sentry.flush(1000)
354+
355+
verify(fixture.transport)
356+
.send(checkLogs { logs -> assertEquals(SentryLogLevel.WARN, logs.items.first().level) })
357+
}
358+
359+
@Test
360+
fun `converts error log level to Sentry log level`() {
361+
fixture = Fixture(minimumLevel = Level.ERROR, enableLogs = true)
362+
fixture.logger.error("testing error level")
363+
364+
Sentry.flush(1000)
365+
366+
verify(fixture.transport)
367+
.send(checkLogs { logs -> assertEquals(SentryLogLevel.ERROR, logs.items.first().level) })
368+
}
369+
370+
@Test
371+
fun `sends formatted log message if no encoder`() {
372+
fixture = Fixture(minimumLevel = Level.TRACE, enableLogs = true)
373+
fixture.logger.trace("Testing {} level", "TRACE")
374+
375+
Sentry.flush(1000)
376+
377+
verify(fixture.transport)
378+
.send(
379+
checkLogs { logs ->
380+
val log = logs.items.first()
381+
assertEquals("Testing TRACE level", log.body)
382+
val attributes = log.attributes!!
383+
assertEquals("Testing {} level", attributes["sentry.message.template"]?.value)
384+
assertEquals("TRACE", attributes["sentry.message.parameter.0"]?.value)
385+
}
386+
)
387+
}
388+
389+
@Test
390+
fun `does not send formatted log message if encoder is available but sendDefaultPii is off`() {
391+
var encoder = PatternLayoutEncoder()
392+
encoder.pattern = "encoderadded %msg"
393+
fixture = Fixture(minimumLevel = Level.TRACE, enableLogs = true, encoder = encoder)
394+
fixture.logger.trace("Testing {} level", "TRACE")
395+
396+
Sentry.flush(1000)
397+
398+
verify(fixture.transport)
399+
.send(
400+
checkLogs { logs ->
401+
val log = logs.items.first()
402+
assertEquals("encoderadded Testing TRACE level", log.body)
403+
val attributes = log.attributes!!
404+
assertNull(attributes["sentry.message.template"])
405+
assertNull(attributes["sentry.message.parameter.0"])
406+
}
407+
)
408+
}
409+
410+
@Test
411+
fun `sends formatted log message if encoder is available and sendDefaultPii is on but encoder throws`() {
412+
var encoder = ThrowingEncoder()
413+
fixture =
414+
Fixture(
415+
minimumLevel = Level.TRACE,
416+
enableLogs = true,
417+
sendDefaultPii = true,
418+
encoder = encoder,
419+
)
420+
fixture.logger.trace("Testing {} level", "TRACE")
421+
422+
Sentry.flush(1000)
423+
424+
verify(fixture.transport)
425+
.send(
426+
checkLogs { logs ->
427+
val log = logs.items.first()
428+
assertEquals("Testing TRACE level", log.body)
429+
val attributes = log.attributes!!
430+
assertEquals("Testing {} level", attributes["sentry.message.template"]?.value)
431+
assertEquals("TRACE", attributes["sentry.message.parameter.0"]?.value)
432+
}
433+
)
434+
}
435+
436+
@Test
437+
fun `sends formatted log message if encoder is available and sendDefaultPii is on`() {
438+
var encoder = PatternLayoutEncoder()
439+
encoder.pattern = "encoderadded %msg"
440+
fixture =
441+
Fixture(
442+
minimumLevel = Level.TRACE,
443+
enableLogs = true,
444+
sendDefaultPii = true,
445+
encoder = encoder,
446+
)
447+
fixture.logger.trace("Testing {} level", "TRACE")
448+
449+
Sentry.flush(1000)
450+
451+
verify(fixture.transport)
452+
.send(
453+
checkLogs { logs ->
454+
val log = logs.items.first()
455+
assertEquals("encoderadded Testing TRACE level", log.body)
456+
val attributes = log.attributes!!
457+
assertEquals("Testing {} level", attributes["sentry.message.template"]?.value)
458+
assertEquals("TRACE", attributes["sentry.message.parameter.0"]?.value)
459+
}
460+
)
461+
}
462+
309463
@Test
310464
fun `attaches thread information`() {
311465
fixture = Fixture(minimumEventLevel = Level.WARN)

‎sentry-test-support/api/sentry-test-support.api‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ public final class io/sentry/AssertionsKt {
66
public static final fun assertEnvelopeTransaction (Ljava/util/List;Lio/sentry/ILogger;Lkotlin/jvm/functions/Function2;)Lio/sentry/protocol/SentryTransaction;
77
public static synthetic fun assertEnvelopeTransaction$default (Ljava/util/List;Lio/sentry/ILogger;Lkotlin/jvm/functions/Function2;ILjava/lang/Object;)Lio/sentry/protocol/SentryTransaction;
88
public static final fun checkEvent (Lkotlin/jvm/functions/Function1;)Lio/sentry/SentryEnvelope;
9+
public static final fun checkLogs (Lkotlin/jvm/functions/Function1;)Lio/sentry/SentryEnvelope;
910
public static final fun checkTransaction (Lkotlin/jvm/functions/Function1;)Lio/sentry/SentryEnvelope;
1011
public static final fun getMockServerRequestTimeoutMillis ()J
1112
}

‎sentry-test-support/src/main/kotlin/io/sentry/Assertions.kt‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,18 @@ fun checkEvent(predicate: (SentryEvent) -> Unit): SentryEnvelope = check {
1414
}
1515
}
1616

17+
/** Verifies is [SentryEnvelope] contains log events matching a predicate. */
18+
fun checkLogs(predicate: (SentryLogEvents) -> Unit): SentryEnvelope {
19+
return check {
20+
val events: SentryLogEvents? = it.items.first().getLogs(JsonSerializer(SentryOptions.empty()))
21+
if (events != null) {
22+
predicate(events)
23+
} else {
24+
throw SkipError("event is null")
25+
}
26+
}
27+
}
28+
1729
fun checkTransaction(predicate: (SentryTransaction) -> Unit): SentryEnvelope = check {
1830
val transaction = it.items.first().getTransaction(JsonSerializer(SentryOptions.empty()))
1931
if (transaction != null) {

‎sentry/api/sentry.api‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4817,6 +4817,7 @@ public abstract interface class io/sentry/logger/ILoggerApi {
48174817
public abstract interface class io/sentry/logger/ILoggerBatchProcessor {
48184818
public abstract fun add (Lio/sentry/SentryLogEvent;)V
48194819
public abstract fun close (Z)V
4820+
public abstract fun flush (J)V
48204821
}
48214822

48224823
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
48384839
public fun <init> (Lio/sentry/SentryOptions;Lio/sentry/ISentryClient;)V
48394840
public fun add (Lio/sentry/SentryLogEvent;)V
48404841
public fun close (Z)V
4842+
public fun flush (J)V
48414843
}
48424844

48434845
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
48564858
public final class io/sentry/logger/NoOpLoggerBatchProcessor : io/sentry/logger/ILoggerBatchProcessor {
48574859
public fun add (Lio/sentry/SentryLogEvent;)V
48584860
public fun close (Z)V
4861+
public fun flush (J)V
48594862
public static fun getInstance ()Lio/sentry/logger/NoOpLoggerBatchProcessor;
48604863
}
48614864

‎sentry/src/main/java/io/sentry/SentryClient.java‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1544,6 +1544,7 @@ public void close(final boolean isRestarting) {
15441544

15451545
@Override
15461546
public void flush(final long timeoutMillis) {
1547+
loggerBatchProcessor.flush(timeoutMillis);
15471548
transport.flush(timeoutMillis);
15481549
}
15491550

‎sentry/src/main/java/io/sentry/logger/ILoggerBatchProcessor.java‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,4 +7,11 @@ public interface ILoggerBatchProcessor {
77
void add(@NotNull SentryLogEvent event);
88

99
void close(boolean isRestarting);
10+
11+
/**
12+
* Flushes log events.
13+
*
14+
* @param timeoutMillis time in milliseconds
15+
*/
16+
void flush(long timeoutMillis);
1017
}

‎sentry/src/main/java/io/sentry/logger/LoggerBatchProcessor.java‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,15 +4,18 @@
44
import io.sentry.ISentryExecutorService;
55
import io.sentry.ISentryLifecycleToken;
66
import io.sentry.SentryExecutorService;
7+
import io.sentry.SentryLevel;
78
import io.sentry.SentryLogEvent;
89
import io.sentry.SentryLogEvents;
910
import io.sentry.SentryOptions;
11+
import io.sentry.transport.ReusableCountLatch;
1012
import io.sentry.util.AutoClosableReentrantLock;
1113
import java.util.ArrayList;
1214
import java.util.List;
1315
import java.util.Queue;
1416
import java.util.concurrent.ConcurrentLinkedQueue;
1517
import java.util.concurrent.Future;
18+
import java.util.concurrent.TimeUnit;
1619
import org.jetbrains.annotations.NotNull;
1720
import org.jetbrains.annotations.Nullable;
1821

@@ -30,6 +33,8 @@ public final class LoggerBatchProcessor implements ILoggerBatchProcessor {
3033
new AutoClosableReentrantLock();
3134
private volatile boolean hasScheduled = false;
3235

36+
private final @NotNull ReusableCountLatch pendingCount = new ReusableCountLatch();
37+
3338
public LoggerBatchProcessor(
3439
final @NotNull SentryOptions options, final @NotNull ISentryClient client) {
3540
this.options = options;
@@ -40,6 +45,7 @@ public LoggerBatchProcessor(
4045

4146
@Override
4247
public void add(final @NotNull SentryLogEvent logEvent) {
48+
pendingCount.increment();
4349
queue.offer(logEvent);
4450
maybeSchedule(false, false);
4551
}
@@ -75,6 +81,17 @@ private void maybeSchedule(boolean forceSchedule, boolean immediately) {
7581
}
7682
}
7783

84+
@Override
85+
public void flush(long timeoutMillis) {
86+
maybeSchedule(true, true);
87+
try {
88+
pendingCount.waitTillZero(timeoutMillis, TimeUnit.MILLISECONDS);
89+
} catch (InterruptedException e) {
90+
options.getLogger().log(SentryLevel.ERROR, "Failed to flush log events", e);
91+
Thread.currentThread().interrupt();
92+
}
93+
}
94+
7895
private void flush() {
7996
flushInternal();
8097
try (final @NotNull ISentryLifecycleToken ignored = scheduleLock.acquire()) {
@@ -103,6 +120,9 @@ private void flushBatch() {
103120

104121
if (!logEvents.isEmpty()) {
105122
client.captureBatchedLogEvents(new SentryLogEvents(logEvents));
123+
for (int i = 0; i < logEvents.size(); i++) {
124+
pendingCount.decrement();
125+
}
106126
}
107127
}
108128

‎sentry/src/main/java/io/sentry/logger/NoOpLoggerBatchProcessor.java‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,4 +24,9 @@ public void add(@NotNull SentryLogEvent event) {
2424
public void close(final boolean isRestarting) {
2525
// do nothing
2626
}
27+
28+
@Override
29+
public void flush(long timeoutMillis) {
30+
// do nothing
31+
}
2732
}

0 commit comments

Comments
 (0)