Fix ExceptionReportingServiceErrorHandler to ignore expected except…

…ions. (#4922)

Motivation:

Do not log ignorable exceptions. 

Modifications:

- Fix `ExceptionReportingServiceErrorHandler` to ignore ignorable exceptions.
- Modify `DefaultUnhandledExceptionReporter` log messages. 
- Remove `ExceptionReportingServiceErrorHandlerTest`and add `DefaultUnhandledExceptionReporterTest` which test `DefaultUnhandledExceptionReporter`

Result:

- Closes #4861 .
- When ignorable exceptions are thrown, `DefaultUnhandledExceptionReporter` will not report anything.

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

@@ -101,15 +101,16 @@ private void reportException() {
 
         final Throwable exception = thrownException;
         if (exception != null) {
-            logger.warn("Observed {} unhandled exceptions in last {}. " +
-                        "Please consider adding the LoggingService decorator to get detailed error logs. " +
-                        "One of the thrown exceptions:",
+            logger.warn("Observed {} exception(s) that didn't reach a LoggingService in the last {}. " +
+                        "Please consider adding a LoggingService as the outermost decorator to get " +
+                        "detailed error logs. One of the thrown exceptions:",
                         newExceptionsCount,
                         TextFormatter.elapsed(intervalMillis, TimeUnit.MILLISECONDS), exception);
             thrownException = null;
         } else {
-            logger.warn("Observed {} unhandled exceptions in last {}. " +
-                        "Please consider adding the LoggingService decorator to get detailed error logs.",
+            logger.warn("Observed {} exception(s) that didn't reach a LoggingService in the last {}. " +
+                        "Please consider adding a LoggingService as the outermost decorator to get " +
+                        "detailed error logs.",
                         newExceptionsCount, TextFormatter.elapsed(intervalMillis, TimeUnit.MILLISECONDS));
         }
 

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

@@ -21,6 +21,7 @@
 import com.linecorp.armeria.common.HttpStatus;
 import com.linecorp.armeria.common.RequestHeaders;
 import com.linecorp.armeria.common.annotation.Nullable;
+import com.linecorp.armeria.common.util.Exceptions;
 
 final class ExceptionReportingServiceErrorHandler implements ServiceErrorHandler {
 
@@ -42,6 +43,9 @@ public HttpResponse onServiceException(ServiceRequestContext ctx, Throwable caus
     }
 
     private static boolean isIgnorableException(Throwable cause) {
+        if (Exceptions.isExpected(cause)) {
+            return true;
+        }
         return (cause instanceof HttpStatusException || cause instanceof HttpResponseException) &&
                cause.getCause() == null;
     }

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

@@ -149,7 +149,7 @@ void testAllConfigurationsAreRespected() {
         final ServiceRequestContext sctx = ServiceRequestContext.builder(HttpRequest.of(HttpMethod.GET, "/"))
                                                                 .build();
         // serviceErrorHandler is composed with ServerErrorHandler so we cannot do the equality check.
-        assertThat(homeFoo.errorHandler().onServiceException(sctx, null)
+        assertThat(homeFoo.errorHandler().onServiceException(sctx, new IllegalArgumentException("cause"))
                           .aggregate()
                           .join()
                           .status()).isSameAs(HttpStatus.OK);
@@ -162,7 +162,7 @@ void testAllConfigurationsAreRespected() {
         assertThat(homeBar.verboseResponses()).isTrue();
         assertThat(homeBar.multipartUploadsLocation()).isSameAs(multipartUploadsLocation);
         // serviceErrorHandler is composed with ServerErrorHandler so we cannot do the equality check.
-        assertThat(homeBar.errorHandler().onServiceException(sctx, null)
+        assertThat(homeBar.errorHandler().onServiceException(sctx, new IllegalArgumentException("cause"))
                           .aggregate()
                           .join()
                           .status()).isSameAs(HttpStatus.OK);

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

@@ -0,0 +1,127 @@
+/*
+ * Copyright 2023 LINE Corporation
+ *
+ * LINE Corporation licenses this file to you under the Apache License,
+ * version 2.0 (the "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at:
+ *
+ *   https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations
+ * under the License.
+ */
+
+package com.linecorp.armeria.server;
+
+import static org.assertj.core.api.Assertions.assertThat;
+import static org.awaitility.Awaitility.await;
+
+import java.time.Duration;
+
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.RegisterExtension;
+import org.mockito.Spy;
+import org.slf4j.LoggerFactory;
+
+import com.linecorp.armeria.common.HttpStatus;
+import com.linecorp.armeria.server.logging.LoggingService;
+import com.linecorp.armeria.testing.junit5.server.ServerExtension;
+
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
+
+class DefaultUnhandledExceptionReporterTest {
+
+    @Spy
+    final ListAppender<ILoggingEvent> logAppender = new ListAppender<>();
+    final Logger errorHandlerLogger =
+            (Logger) LoggerFactory.getLogger(DefaultUnhandledExceptionsReporter.class);
+    private static final long reportIntervalMillis = 1000;
+    private static final long awaitIntervalMillis = 2000;
+    private static volatile boolean throwNonIgnorableException;
+
+    @BeforeEach
+    public void attachAppender() {
+        logAppender.start();
+        errorHandlerLogger.addAppender(logAppender);
+        throwNonIgnorableException = false;
+    }
+
+    @AfterEach
+    public void detachAppender() {
+        errorHandlerLogger.detachAppender(logAppender);
+        logAppender.list.clear();
+    }
+
+    @RegisterExtension
+    static ServerExtension server = new ServerExtension() {
+        @Override
+        protected void configure(ServerBuilder sb) {
+            sb.route()
+              .get("/logging-service-subsequently-decorated")
+              .decorator(service -> (ctx, req) -> {
+                  if (throwNonIgnorableException) {
+                      throw new IllegalArgumentException("Non-ignorable exception");
+                  }
+                  return service.serve(ctx, req);
+              })
+              .decorator(LoggingService.newDecorator())
+              .build((ctx, req) -> {
+                  throw HttpStatusException.of(HttpStatus.BAD_REQUEST);
+              });
+            sb.route()
+              .get("/logging-service-previously-decorated")
+              .decorator(LoggingService.newDecorator())
+              .decorator(service -> (ctx, req) -> {
+                  if (throwNonIgnorableException) {
+                      throw new IllegalArgumentException("Non-ignorable exception");
+                  }
+                  return service.serve(ctx, req);
+              })
+              .build((ctx, req) -> {
+                  throw HttpStatusException.of(HttpStatus.BAD_REQUEST);
+              });
+            sb.unhandledExceptionsReportInterval(Duration.ofMillis(reportIntervalMillis));
+        }
+    };
+
+    @Test
+    void allExceptionShouldNotBeReportedWhenLoggingServiceIsSubsequentlyDecorated() throws Exception {
+        assertThat(server.blockingWebClient().get("/logging-service-subsequently-decorated").status().code())
+                .isEqualTo(400);
+        throwNonIgnorableException = true;
+        assertThat(server.blockingWebClient().get("/logging-service-subsequently-decorated").status().code())
+                .isEqualTo(500);
+        Thread.sleep(reportIntervalMillis + awaitIntervalMillis);
+        assertThat(logAppender.list).isEmpty();
+    }
+
+    @Test
+    void nonIgnorableExceptionShouldBeReportedWhenLoggingServiceIsPreviouslyDecorated() {
+        throwNonIgnorableException = true;
+        assertThat(server.blockingWebClient().get("/logging-service-previously-decorated").status().code())
+                .isEqualTo(500);
+        await().atMost(Duration.ofMillis(reportIntervalMillis + awaitIntervalMillis))
+               .untilAsserted(() -> assertThat(logAppender.list).isNotEmpty());
+
+        assertThat(logAppender.list
+                           .stream()
+                           .filter(event -> event.getFormattedMessage().contains(
+                                   "Observed 1 exception(s) that didn't reach a LoggingService"))
+                           .findAny()).isNotEmpty();
+    }
+
+    @Test
+    void ignorableExceptionShouldNotBeReportedEvenThoughLoggingServiceIsPreviouslyDecorated() throws Exception {
+        assertThat(server.blockingWebClient().get("/logging-service-previously-decorated").status().code())
+                .isEqualTo(400);
+        Thread.sleep(reportIntervalMillis + awaitIntervalMillis);
+        assertThat(logAppender.list).isEmpty();
+    }
+}

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

@@ -16,127 +16,69 @@
 
 package com.linecorp.armeria.server;
 
-import static org.assertj.core.api.Assertions.assertThat;
-import static org.awaitility.Awaitility.await;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.reset;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
 
-import java.time.Duration;
+import java.nio.channels.ClosedChannelException;
 
-import org.junit.jupiter.api.AfterEach;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
-import org.mockito.Spy;
-import org.slf4j.LoggerFactory;
-
-import com.linecorp.armeria.client.BlockingWebClient;
-import com.linecorp.armeria.common.HttpResponse;
-import com.linecorp.armeria.common.HttpStatus;
-import com.linecorp.armeria.server.logging.LoggingService;
-
-import ch.qos.logback.classic.Logger;
-import ch.qos.logback.classic.spi.ILoggingEvent;
-import ch.qos.logback.core.read.ListAppender;
+import org.mockito.Mock;
 
 class ExceptionReportingServiceErrorHandlerTest {
 
-    @Spy
-    final ListAppender<ILoggingEvent> logAppender = new ListAppender<>();
-    final Logger errorHandlerLogger =
-            (Logger) LoggerFactory.getLogger(DefaultUnhandledExceptionsReporter.class);
-    private static final long reportIntervalMillis = 1000;
-    private static final long awaitIntervalMillis = 2000;
+    @Mock
+    private ServiceErrorHandler delegate;
+    @Mock
+    private UnhandledExceptionsReporter reporter;
+    @Mock
+    private ServiceRequestContext ctx;
+
+    private ExceptionReportingServiceErrorHandler serviceErrorHandler;
 
     @BeforeEach
-    public void attachAppender() {
-        logAppender.start();
-        errorHandlerLogger.addAppender(logAppender);
+    void setUp() {
+        reset(reporter);
+        reset(ctx);
+        serviceErrorHandler = new ExceptionReportingServiceErrorHandler(delegate, reporter);
     }
 
-    @AfterEach
-    public void detachAppender() {
-        errorHandlerLogger.detachAppender(logAppender);
-        logAppender.list.clear();
+    @Test
+    void onServiceExceptionShouldNotReportWhenShouldReportUnhandledExceptionsIsFalse() {
+        when(ctx.shouldReportUnhandledExceptions()).thenReturn(false);
+        serviceErrorHandler.onServiceException(ctx, new IllegalArgumentException("Test"));
+        verify(reporter, times(0)).report(any());
     }
 
     @Test
-    void httpStatusExceptionWithCauseLogged() throws Exception {
-        final Server server = Server.builder()
-                                    .service("/hello", (ctx, req) -> {
-                                        throw HttpStatusException.of(HttpStatus.BAD_REQUEST,
-                                                                     new IllegalArgumentException("test"));
-                                    })
-                                    .unhandledExceptionsReportInterval(Duration.ofMillis(reportIntervalMillis))
-                                    .build();
-        try {
-            server.start().join();
-            BlockingWebClient.of("http://127.0.0.1:" + server.activeLocalPort()).get("/hello");
-            await().atMost(Duration.ofMillis(reportIntervalMillis + awaitIntervalMillis))
-                   .untilAsserted(() -> assertThat(logAppender.list).isNotEmpty());
-
-            assertThat(logAppender.list
-                               .stream()
-                               .filter(event -> event.getFormattedMessage().contains(
-                                       "Observed 1 unhandled exceptions"))
-                               .findAny()
-            ).isNotEmpty();
-        } finally {
-            server.stop();
-        }
+    void onServiceExceptionShouldNotReportWhenCauseIsExpected() {
+        when(ctx.shouldReportUnhandledExceptions()).thenReturn(true);
+        serviceErrorHandler.onServiceException(ctx, new ClosedChannelException());
+        verify(reporter, times(0)).report(any());
     }
 
     @Test
-    void httpStatusExceptionWithoutCauseIsIgnored() throws Exception {
-        final Server server = Server.builder()
-                                    .service("/hello", (ctx, req) -> {
-                                        throw HttpStatusException.of(HttpStatus.BAD_REQUEST);
-                                    })
-                                    .unhandledExceptionsReportInterval(Duration.ofMillis(reportIntervalMillis))
-                                    .build();
-        try {
-            server.start().join();
-            BlockingWebClient.of("http://127.0.0.1:" + server.activeLocalPort()).get("/hello");
-            Thread.sleep(reportIntervalMillis + awaitIntervalMillis);
-
-            assertThat(logAppender.list).isEmpty();
-        } finally {
-            server.stop();
-        }
+    void onServiceExceptionShouldReportWhenCauseIsNotExpected() {
+        when(ctx.shouldReportUnhandledExceptions()).thenReturn(true);
+        serviceErrorHandler.onServiceException(ctx, new IllegalArgumentException("Test"));
+        verify(reporter, times(1)).report(any());
     }
 
     @Test
-    void exceptionShouldNotBeLoggedWhenDecoratedWithLoggingService() throws Exception {
-        final Server server = Server.builder()
-                                    .service("/hello", (ctx, req) -> {
-                                        throw new IllegalArgumentException("test");
-                                    })
-                                    .unhandledExceptionsReportInterval(Duration.ofMillis(reportIntervalMillis))
-                                    .decorator(LoggingService.newDecorator())
-                                    .build();
-
-        try {
-            server.start().join();
-            BlockingWebClient.of("http://127.0.0.1:" + server.activeLocalPort()).get("/hello");
-            Thread.sleep(reportIntervalMillis + awaitIntervalMillis);
-
-            assertThat(logAppender.list).isEmpty();
-        } finally {
-            server.stop();
-        }
+    void onServiceExceptionShouldNotReportWhenCauseIsHttpStatusExceptionAndCauseNull() {
+        when(ctx.shouldReportUnhandledExceptions()).thenReturn(true);
+        serviceErrorHandler.onServiceException(ctx, HttpStatusException.of(500));
+        verify(reporter, times(0)).report(any());
     }
 
     @Test
-    void exceptionShouldNotBeLoggedWhenNoExceptionIsThrown() throws Exception {
-        final Server server = Server.builder()
-                                    .service("/hello", (ctx, req) -> HttpResponse.of(HttpStatus.OK))
-                                    .decorator(LoggingService.newDecorator())
-                                    .build();
-        try {
-            server.start().join();
-            BlockingWebClient.of("http://127.0.0.1:" + server.activeLocalPort()).get("/hello");
-            Thread.sleep(reportIntervalMillis + awaitIntervalMillis);
-
-            assertThat(logAppender.list).isEmpty();
-        } finally {
-            server.stop();
-        }
+    void onServiceExceptionShouldReportWhenCauseIsHttpStatusExceptionAndCauseNonNull() {
+        when(ctx.shouldReportUnhandledExceptions()).thenReturn(true);
+        serviceErrorHandler.onServiceException(
+                ctx, HttpStatusException.of(500, new IllegalArgumentException("test")));
+        verify(reporter, times(1)).report(any());
     }
 }