[WIP] Enhance DefaultUnhandledExceptionsReporter for better exception repor… #5601

coodercl · 2024-04-12T07:26:05Z

…ting

Motivation: #5567

Currently, the DefaultUnhandledExceptionsReporter stores only one exception and the number of unhandled exceptions in an interval. However, this implementation lacks sufficient information for effective debugging and analysis. To address this limitation, we propose enhancing the reporter to provide more detailed information about unhandled exceptions.

Proposed Changes:

Store Every Unique Exception and Its Count.

Modify the reporter to store every unique exception encountered along with its occurrence count. A unique exception refers to instances where the class type and stack traces are identical.

Include Corresponding Context

Enhance the reporting mechanism to include the corresponding context of each exception.

Modifications:

Store Every Unique Exception and Its Count
Include Corresponding Context

Result:

Closes Enhance DefaultUnhandledExceptionsReporter for Better Exception Reporting #5567
We can report the exceptions better.

…ting

coodercl · 2024-04-12T07:31:27Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

@@ -106,6 +109,7 @@ private void reportException() {
                        "detailed error logs. One of the thrown exceptions:",
                        newExceptionsCount,
                        TextFormatter.elapsed(intervalMillis, TimeUnit.MILLISECONDS), exception);
+            thrownExceptionCounters.computeIfAbsent(exception, k -> new LongAdder()).increment();


@injae-kim nim, I've implemented recording the exception in the thrownExceptionCounters when it's not null.
Did I understand the intention correctly?
Please let me know if I've misunderstood anything.
Thank you. 🙇

coodercl · 2024-04-12T07:37:04Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

@@ -59,7 +62,7 @@ final class DefaultUnhandledExceptionsReporter implements UnhandledExceptionsRep
    }

    @Override
-    public void report(Throwable cause) {
+    public void report(ServiceRequestContext ctx, Throwable cause) {
        if (reportingTaskFuture == null && scheduledUpdater.compareAndSet(this, 0, 1)) {
            reportingTaskFuture = CommonPools.workerGroup().next().scheduleAtFixedRate(
                    this::reportException, intervalMillis, intervalMillis, TimeUnit.MILLISECONDS);


I have a question about this code.
Why is this::reportException called repeatedly at regular intervals?
I'm wondering why we don't call this::reportException only once when the report method is invoked.
Thank you. 🙇

Here, we lazily start the periodic timer task that logs and clears the exceptions and their count mapping every few seconds. The timer is started only once since it's guarded by the compareAndSet() call.

The reason we do this way is because otherwise the recently reported exceptions will not be logged until the 'next' exception is reported, which is not always the case.

github-actions · 2024-04-12T08:53:09Z

🔍 Build Scan® (commit: `1bfbfb0`)

Job name	Status	Build Scan®
build-windows-latest-jdk-19	❌ (failure)	https://ge.armeria.dev/s/kwirzpneawbk6
build-self-hosted-unsafe-jdk-8	❌ (failure)	https://ge.armeria.dev/s/2wufanlz2wiyq
build-self-hosted-unsafe-jdk-19-snapshot-blockhound	❌ (failure)	https://ge.armeria.dev/s/cd3w3ipu24g5q
build-self-hosted-unsafe-jdk-17-min-java-17-coverage	❌ (failure)	https://ge.armeria.dev/s/4rqmbnftqebj4
build-self-hosted-unsafe-jdk-17-min-java-11	❌ (failure)	https://ge.armeria.dev/s/zv72ryysjo4yc
build-self-hosted-unsafe-jdk-17-leak	❌ (failure)	https://ge.armeria.dev/s/pyyj32do4lmrk
build-self-hosted-unsafe-jdk-11	❌ (failure)	https://ge.armeria.dev/s/mziozxphfduzs
build-macos-12-jdk-19	❌ (failure)	https://ge.armeria.dev/s/g325thfoai4am

coodercl · 2024-04-24T01:35:16Z

core/src/test/java/com/linecorp/armeria/server/DefaultUnhandledExceptionReporterTest.java

+                .isEqualTo(1);
+        assertThat(defaultUnhandledExceptionsReporter.getThrownExceptions().get(cause3).first().longValue())
+                .isEqualTo(1);
+    }


@injae-kim nim, I have a question 🙇
When referring to this test, even though it's the same IllegalArgumentException, it's being recognized as a new key because they are different objects.
Is this the direction we want? I thought that even if they are different objects, they should be recognized as the same key if they have the same type. 😄
Thank you~!

Let's wait maintainer's comment here~! 🙇

If stack traces and exception messages differ, the same exception type should be corrected separately. Exceptions.traceText(cause) can be used as keys instead of instances themselves.

injae-kim · 2024-04-24T08:28:22Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

@@ -50,7 +55,7 @@ final class DefaultUnhandledExceptionsReporter implements UnhandledExceptionsRep
    @Nullable
    private ScheduledFuture<?> reportingTaskFuture;
    @Nullable
-    private Throwable thrownException;
+    private Map<Throwable, Pair<LongAdder, ServiceRequestContext>> thrownExceptions;


// akka implementation libs.akka.actor.typed.v213

private static class ThrowableEntry { LongAdder adder; ServiceRequestContext ctx; } private Map<Throwable, ThrowableEntry> thrownExceptions;

oh instead of import Pair on akka, can we add some class like ThrowableEntry?
then we don't need to import akka 😄

We don't want to add an additional dependency for this. Should we use Map.Entry or a custom class as suggested by @injae-kim instead?

ikhoon · 2024-04-23T04:37:18Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

@@ -37,6 +39,7 @@ final class DefaultUnhandledExceptionsReporter implements UnhandledExceptionsRep
    private static final AtomicIntegerFieldUpdater<DefaultUnhandledExceptionsReporter> scheduledUpdater =
            AtomicIntegerFieldUpdater.newUpdater(DefaultUnhandledExceptionsReporter.class,
                                                 "scheduled");
+    private Map<Throwable, LongAdder> thrownExceptionCounters = new ConcurrentHashMap<>();


Suggested change

private Map<Throwable, LongAdder> thrownExceptionCounters = new ConcurrentHashMap<>();

private final Map<Throwable, LongAdder> thrownExceptionCounters = new ConcurrentHashMap<>();

ikhoon · 2024-04-24T09:24:49Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

@@ -50,7 +55,7 @@ final class DefaultUnhandledExceptionsReporter implements UnhandledExceptionsRep
    @Nullable
    private ScheduledFuture<?> reportingTaskFuture;
    @Nullable
-    private Throwable thrownException;
+    private Map<Throwable, Pair<LongAdder, ServiceRequestContext>> thrownExceptions;


We don't want to add an additional dependency for this. Should we use Map.Entry or a custom class as suggested by @injae-kim instead?

ikhoon · 2024-04-24T09:27:31Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

-        if (thrownException == null) {
-            thrownException = cause;
+        if (thrownExceptions == null) {
+            thrownExceptions = new HashMap<>();


This method is called by multiple threads for which HashMap can' be used.

ikhoon · 2024-04-24T09:59:13Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

-                        TextFormatter.elapsed(intervalMillis, TimeUnit.MILLISECONDS), exception);
-            thrownException = null;
+                        TextFormatter.elapsed(intervalMillis, TimeUnit.MILLISECONDS), exceptions.toString());
+            thrownExceptions = null;


What do you think of a dedicated class to collect exceptions and encapsulate the logic?

final class ExceptionStats { private Map<String, ExceptionContext> exceptions = ...; // A lock is required to thread-safely update `exceptions` field private final ReentrantShortLock lock = ... void record(ServiceRequestContext ctx, Throwable cause) { lock.lock(); try { exceptions.compute(Exceptions.traceText(cause), (key, value) -> { ... value.increase(); ... }); } finally { lock.unlock(); } } Collection<ExceptionContext> dump() { lock.lock(); try { final Map<String, ExceptionContext> oldExceptions = exceptions; // Allocate a new map exceptions = new HashMap<>(); return oldExceptions.values(); } finally { lock.unlock(); } } private static class ExceptionContext { private final Throwable exception; // Capture the first context when the exception is raised for better debugging private final ServiceRequestContext ctx; private long counter = 1; ... } }

When reportException() is invoked, we may dump the counted exceptions and log all of them.

private void reportException() { for (exceptionContext: exceptionStats.dump()) { logger.warn("Observed {} exception(s) that ...", exceptionContext.count(), ...); } }

Introduce ExceptionStats class looks nice to me too here!

@ikhoon nim, thank you so much for providing detailed explanations along with the example code.
It has been really helpful in enhancing my understanding.
I would like to verify if I have correctly understood your instructions first and then proceed to write test codes.
Would you please review it again? 🙇

trustin

Any progress since the last review, @coodercl?

trustin · 2024-06-06T13:42:13Z

core/build.gradle

@@ -162,6 +162,9 @@ dependencies {
    }
    testImplementation libs.brave6.context.slf4j
    testImplementation libs.brave6.instrumentation.http.tests
+
+    // akka
+    implementation libs.akka.actor.typed.v213


As others pointed out, we can go without this dependency.

trustin · 2024-06-06T13:45:05Z

core/src/main/java/com/linecorp/armeria/server/DefaultUnhandledExceptionsReporter.java

@@ -59,7 +62,7 @@ final class DefaultUnhandledExceptionsReporter implements UnhandledExceptionsRep
    }

    @Override
-    public void report(Throwable cause) {
+    public void report(ServiceRequestContext ctx, Throwable cause) {
        if (reportingTaskFuture == null && scheduledUpdater.compareAndSet(this, 0, 1)) {
            reportingTaskFuture = CommonPools.workerGroup().next().scheduleAtFixedRate(
                    this::reportException, intervalMillis, intervalMillis, TimeUnit.MILLISECONDS);


Here, we lazily start the periodic timer task that logs and clears the exceptions and their count mapping every few seconds. The timer is started only once since it's guarded by the compareAndSet() call.

The reason we do this way is because otherwise the recently reported exceptions will not be logged until the 'next' exception is reported, which is not always the case.

coodercl · 2024-06-07T00:44:03Z

Oh, @trustin nim, sorry for the delay in updating. 😢 🙏
Let me update this PR by next week at the latest!
Thank you so much for the detailed explanation! 🙇 🙇

coodercl · 2024-06-11T09:31:51Z

Let me ping when I'm ready for review~! 🙇

Enhance DefaultUnhandledExceptionsReporter for better exception repor…

819344e

…ting

github-actions bot requested review from ikhoon, jrhee17, minwoox and trustin April 12, 2024 07:26

coodercl commented Apr 12, 2024

View reviewed changes

ikhoon added improvement sprint Issues for OSS Sprint participants labels Apr 23, 2024

coodercl added 2 commits April 24, 2024 02:05

address review

ace7ce3

add test

1bfbfb0

coodercl commented Apr 24, 2024

View reviewed changes

injae-kim reviewed Apr 24, 2024

View reviewed changes

ikhoon reviewed Apr 24, 2024

View reviewed changes

github-actions bot added the Stale label May 26, 2024

trustin reviewed Jun 6, 2024

View reviewed changes

github-actions bot removed the Stale label Jun 8, 2024

revert changes

28cd2d7

coodercl added 5 commits June 11, 2024 19:12

Implement ExceptionStats

aa4fd66

address comment

f270034

fix

1f5b24c

fix

28505e0

fix indent

e21d6a1

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WIP] Enhance DefaultUnhandledExceptionsReporter for better exception repor… #5601

[WIP] Enhance DefaultUnhandledExceptionsReporter for better exception repor… #5601

coodercl commented Apr 12, 2024

coodercl Apr 12, 2024 •

edited

coodercl Apr 12, 2024

trustin Jun 6, 2024

github-actions bot commented Apr 12, 2024 •

edited

coodercl Apr 24, 2024

injae-kim Apr 24, 2024

ikhoon Apr 25, 2024 •

edited

injae-kim Apr 24, 2024 •

edited

ikhoon Apr 24, 2024

ikhoon Apr 23, 2024

ikhoon Apr 24, 2024

ikhoon Apr 24, 2024

ikhoon Apr 24, 2024

injae-kim Apr 25, 2024

coodercl Jun 12, 2024

trustin left a comment

trustin Jun 6, 2024

trustin Jun 6, 2024

coodercl commented Jun 7, 2024

coodercl commented Jun 11, 2024

	private Map<Throwable, LongAdder> thrownExceptionCounters = new ConcurrentHashMap<>();
	private final Map<Throwable, LongAdder> thrownExceptionCounters = new ConcurrentHashMap<>();

[WIP] Enhance DefaultUnhandledExceptionsReporter for better exception repor… #5601

Are you sure you want to change the base?

[WIP] Enhance DefaultUnhandledExceptionsReporter for better exception repor… #5601

Conversation

coodercl commented Apr 12, 2024

coodercl Apr 12, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Apr 12, 2024 • edited

🔍 Build Scan® (commit: 1bfbfb0)

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ikhoon Apr 25, 2024 • edited

Choose a reason for hiding this comment

injae-kim Apr 24, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trustin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coodercl commented Jun 7, 2024

coodercl commented Jun 11, 2024

coodercl Apr 12, 2024 •

edited

github-actions bot commented Apr 12, 2024 •

edited

🔍 Build Scan® (commit: `1bfbfb0`)

ikhoon Apr 25, 2024 •

edited

injae-kim Apr 24, 2024 •

edited