Fix Missing Use of SuccessFunction in Determining Response Success …

…for Log Levels Motivation: The `ResponseLogLevelMapper.of()` did not use the `SuccessFunction` to determine whether a response was successful. Modifications: - Updated `ResponseLogLevelMapper.of()` to use the `SuccessFunction` when determining the success of a response. Result: - Log levels for responses are now correctly mapped based on the `SuccessFunction`.
line · Dec 18, 2024 · 5dc5aae · 5dc5aae
1 parent 8957ba7
commit 5dc5aae
Show file tree

Hide file tree

Showing 7 changed files with 123 additions and 31 deletions.
diff --git a/core/src/main/java/com/linecorp/armeria/common/logging/DefaultLogWriter.java b/core/src/main/java/com/linecorp/armeria/common/logging/DefaultLogWriter.java
@@ -28,8 +28,11 @@
 
 import com.google.common.base.MoreObjects;
 
+import com.linecorp.armeria.client.ClientRequestContext;
 import com.linecorp.armeria.common.RequestContext;
+import com.linecorp.armeria.common.SuccessFunction;
 import com.linecorp.armeria.common.util.SafeCloseable;
+import com.linecorp.armeria.server.ServiceRequestContext;
 
 final class DefaultLogWriter implements LogWriter {
 
@@ -98,19 +101,23 @@ public void logResponse(RequestLog log) {
             final String responseStr = logFormatter.formatResponse(log);
             final RequestContext ctx = log.context();
             try (SafeCloseable ignored = ctx.push()) {
-                if (responseCause == null) {
+                if (isSuccess(log)) {
                     responseLogLevel.log(logger, responseStr);
                     return;
                 }
+                // If the request is not successful,
+                // we log the request first if it's unlogged to help debugging.
 
                 final LogLevel requestLogLevel = requestLogLevelMapper.apply(log);
                 assert requestLogLevel != null;
                 if (!requestLogLevel.isEnabled(logger)) {
-                    // Request wasn't logged, but this is an unsuccessful response,
-                    // so we log the request too to help debugging.
                     responseLogLevel.log(logger, logFormatter.formatRequest(log));
                 }
 
+                if (responseCause == null) {
+                    responseLogLevel.log(logger, responseStr);
+                    return;
+                }
                 if (responseCauseFilter.test(ctx, responseCause)) {
                     responseLogLevel.log(logger, responseStr);
                 } else {
@@ -120,6 +127,20 @@ public void logResponse(RequestLog log) {
         }
     }
 
+    static boolean isSuccess(RequestLog log) {
+        final RequestContext ctx = log.context();
+        final SuccessFunction successFunction;
+        if (ctx instanceof ClientRequestContext) {
+            successFunction = ((ClientRequestContext) ctx).options().successFunction();
+        } else if (ctx instanceof ServiceRequestContext) {
+            successFunction = ((ServiceRequestContext) ctx).config().successFunction();
+        } else {
+            throw new IllegalStateException(
+                    ctx + " is neither ClientRequestContext nor ServiceRequestContext");
+        }
+        return successFunction.isSuccess(ctx, log);
+    }
+
     @Override
     public String toString() {
         return MoreObjects.toStringHelper(this)

diff --git a/core/src/main/java/com/linecorp/armeria/common/logging/ResponseLogLevelMapper.java b/core/src/main/java/com/linecorp/armeria/common/logging/ResponseLogLevelMapper.java
@@ -16,6 +16,7 @@
 
 package com.linecorp.armeria.common.logging;
 
+import static com.linecorp.armeria.common.logging.DefaultLogWriter.isSuccess;
 import static java.util.Objects.requireNonNull;
 
 import java.util.function.Function;
@@ -43,7 +44,7 @@ public interface ResponseLogLevelMapper extends Function<RequestLog, LogLevel> {
      * {@code failureResponseLogLevel} if failure.
      */
     static ResponseLogLevelMapper of(LogLevel successfulResponseLogLevel, LogLevel failureResponseLogLevel) {
-        return log -> log.responseCause() == null ? successfulResponseLogLevel : failureResponseLogLevel;
+        return log -> isSuccess(log) ? successfulResponseLogLevel : failureResponseLogLevel;
     }
 
     /**

diff --git a/core/src/test/java/com/linecorp/armeria/client/logging/LoggingClientTest.java b/core/src/test/java/com/linecorp/armeria/client/logging/LoggingClientTest.java
@@ -90,7 +90,7 @@ void logger() throws Exception {
 
         customLoggerClient.execute(ctx, req);
 
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
 
         // verify request log
         verify(logger).info(argThat((String actLog) -> actLog.contains("Request:") &&
@@ -152,7 +152,7 @@ void sanitizeRequestHeaders() throws Exception {
         client.execute(ctx, req);
 
         // After the sanitization.
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
 
         // verify request log
         verify(logger).info(argThat((String text) -> text.contains("Request:") &&
@@ -196,7 +196,7 @@ void sanitizeRequestHeadersByLogFormatter() throws Exception {
         client.execute(ctx, req);
 
         // After the sanitization.
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
 
         // verify request log
         verify(logger).info(argThat((String text) -> text.contains("Request:") &&
@@ -239,10 +239,10 @@ void sanitizeRequestContent() throws Exception {
 
         client.execute(ctx, req);
 
-        // Ensure the request content (the phone number 333-490-4499) is sanitized.
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
 
         // verify request log
+        // Ensure the request content (the phone number 333-490-4499) is sanitized.
         verify(logger).info(argThat((String text) -> text.contains("Request:") &&
                                                      !text.contains("333-490-4499")));
         // verify response log
@@ -283,10 +283,10 @@ void sanitizeRequestContentByLogFormatter() throws Exception {
 
         client.execute(ctx, req);
 
-        // Ensure the request content (the phone number 333-490-4499) is sanitized.
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
 
         // verify request log
+        // Ensure the request content (the phone number 333-490-4499) is sanitized.
         verify(logger).info(argThat((String text) -> text.contains("Request:") &&
                                                      !text.contains("333-490-4499")));
         // verify response log
@@ -301,7 +301,7 @@ void internalServerError() throws Exception {
         ctx.logBuilder().responseHeaders(ResponseHeaders.of(HttpStatus.INTERNAL_SERVER_ERROR));
 
         final Logger logger = LoggingTestUtil.newMockLogger(ctx, capturedCause);
-        when(logger.isDebugEnabled()).thenReturn(true);
+        when(logger.isWarnEnabled()).thenReturn(true);
 
         // use custom logger
         final LoggingClient customLoggerClient =
@@ -312,13 +312,14 @@ void internalServerError() throws Exception {
         customLoggerClient.execute(ctx, req);
 
         verify(logger, times(2)).isDebugEnabled();
+        verify(logger, times(1)).isWarnEnabled();
 
         // verify request log
-        verify(logger).debug(argThat((String actLog) -> actLog.contains("Request:") &&
+        verify(logger).warn(argThat((String actLog) -> actLog.contains("Request:") &&
                                                         actLog.endsWith("headers=[:method=GET, :path=/]}")));
 
         // verify response log
-        verify(logger).debug(argThat((String actLog) -> actLog.contains("Response:") &&
+        verify(logger).warn(argThat((String actLog) -> actLog.contains("Response:") &&
                                                         actLog.endsWith("headers=[:status=500]}")));
     }
 

diff --git a/core/src/test/java/com/linecorp/armeria/common/logging/LoggingDecoratorBuilderTest.java b/core/src/test/java/com/linecorp/armeria/common/logging/LoggingDecoratorBuilderTest.java
@@ -67,12 +67,6 @@ class LoggingDecoratorBuilderTest {
                 assertThat(content).isNotNull();
                 return SANITIZED_CONTENT;
             };
-    private static final BiFunction<? super RequestContext, ? super Throwable, ?> CAUSE_SANITIZER =
-            (ctx, cause) -> {
-                assertThat(ctx).isNotNull();
-                assertThat(cause).isNotNull();
-                return "dummy cause sanitizer";
-            };
 
     private Builder builder;
     private ServiceRequestContext ctx;

diff --git a/core/src/test/java/com/linecorp/armeria/common/logging/ResponseLogLevelMapperTest.java b/core/src/test/java/com/linecorp/armeria/common/logging/ResponseLogLevelMapperTest.java
@@ -0,0 +1,56 @@
+/*
+ * Copyright 2024 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.common.logging;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+import java.util.stream.Stream;
+
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.Arguments;
+import org.junit.jupiter.params.provider.MethodSource;
+
+import com.linecorp.armeria.client.ClientRequestContext;
+import com.linecorp.armeria.common.HttpMethod;
+import com.linecorp.armeria.common.HttpRequest;
+import com.linecorp.armeria.common.RequestContext;
+import com.linecorp.armeria.common.ResponseHeaders;
+import com.linecorp.armeria.server.ServiceRequestContext;
+
+class ResponseLogLevelMapperTest {
+
+    @MethodSource("contexts")
+    @ParameterizedTest
+    void foo(RequestContext ctx, int status) {
+        final ResponseLogLevelMapper logLevelMapper = ResponseLogLevelMapper.of(LogLevel.DEBUG, LogLevel.WARN);
+        final RequestLogBuilder logBuilder = ctx.logBuilder();
+        logBuilder.endRequest();
+        logBuilder.responseHeaders(ResponseHeaders.of(status));
+        logBuilder.endResponse();
+        final LogLevel expected = status == 200 ? LogLevel.DEBUG : LogLevel.WARN;
+        assertThat(logLevelMapper.apply(ctx.log().ensureComplete())).isSameAs(expected);
+    }
+
+    private static Stream<Arguments> contexts() {
+        final HttpRequest request = HttpRequest.of(HttpMethod.GET, "/");
+        return Stream.of(
+                Arguments.of(ClientRequestContext.of(request), 200),
+                Arguments.of(ServiceRequestContext.of(request), 200),
+                Arguments.of(ClientRequestContext.of(request), 500),
+                Arguments.of(ServiceRequestContext.of(request), 500)
+        );
+    }
+}
diff --git a/core/src/test/java/com/linecorp/armeria/server/healthcheck/HealthCheckServiceTest.java b/core/src/test/java/com/linecorp/armeria/server/healthcheck/HealthCheckServiceTest.java
@@ -143,6 +143,7 @@ static void ensureScheduledHealthCheckerStopped() {
     void setUp() {
         reset(logger);
         when(logger.isDebugEnabled()).thenReturn(true);
+        when(logger.isWarnEnabled()).thenReturn(true);
         checker.setHealthy(true);
     }
 
@@ -189,7 +190,7 @@ void getWhenUnhealthy() throws Exception {
                              "connection: close\r\n\r\n" +
                              "{\"healthy\":false}");
         await().untilAsserted(() -> {
-            verify(logger).debug(anyString());
+            verify(logger).warn(anyString());
         });
     }
 
@@ -214,7 +215,7 @@ void headWhenUnhealthy() throws Exception {
                              "armeria-lphc: 60, 5\r\n" +
                              "content-length: 17\r\n" +
                              "connection: close\r\n\r\n");
-        verify(logger).debug(anyString());
+        verify(logger).warn(anyString());
     }
 
     private static void assertResponseEquals(String request, String expectedResponse) throws Exception {

diff --git a/core/src/test/java/com/linecorp/armeria/server/logging/LoggingServiceTest.java b/core/src/test/java/com/linecorp/armeria/server/logging/LoggingServiceTest.java
@@ -100,7 +100,7 @@ void defaultsSuccess() throws Exception {
                 LoggingService.builder()
                               .logWriter(LogWriter.of(logger))
                               .newDecorator().apply(delegate);
-
+        ctx.logBuilder().responseHeaders(ResponseHeaders.of(200));
         service.serve(ctx, ctx.request());
         verify(logger, times(2)).isDebugEnabled();
     }
@@ -128,14 +128,24 @@ void defaultsError() throws Exception {
 
     @MethodSource("expectedException")
     @ParameterizedTest
-    void shouldNotLogHttpStatusAndResponseExceptions(Exception exception) throws Exception {
+    void shouldLogHttpStatusAndResponseExceptionsWhenServerError(Exception exception) throws Exception {
         final ServiceRequestContext ctx = serviceRequestContext();
         final Logger logger = LoggingTestUtil.newMockLogger(ctx, capturedCause);
         final Throwable cause = exception.getCause();
+
+        if (exception instanceof HttpResponseException) {
+            // Set the response headers because this test case doesn't use HttpResponseSubscriber which
+            // sets the response headers.
+            ctx.logBuilder().responseHeaders(ResponseHeaders.of(200));
+        }
+
         ctx.logBuilder().endResponse(exception);
 
         if (cause == null) {
             when(logger.isDebugEnabled()).thenReturn(true);
+            if (exception instanceof HttpStatusException) {
+                when(logger.isWarnEnabled()).thenReturn(true);
+            }
         } else {
             when(logger.isWarnEnabled()).thenReturn(true);
         }
@@ -146,10 +156,18 @@ void shouldNotLogHttpStatusAndResponseExceptions(Exception exception) throws Exc
 
         service.serve(ctx, ctx.request());
 
+        // cause != null => failure response
+        // 500 status (HttpStatusException) => failure response
+
         if (cause == null) {
             // Log a response without an HttpResponseException or HttpStatusException
             verify(logger).debug(matches(".*Request:.*headers=\\[:method=GET, :path=/].*"));
-            verify(logger).debug(matches(".*Response:.*"));
+            if (exception instanceof HttpStatusException) {
+                // 500 status code
+                verify(logger).warn(matches(".*Response:.*"));
+            } else {
+                verify(logger).debug(matches(".*Response:.*"));
+            }
         } else {
             verify(logger).warn(matches(".*Request:.*headers=\\[:method=GET, :path=/].*"));
             verify(logger).warn(matches(".*Response:.*cause=" + cause.getClass().getName() + ".*"),
@@ -215,7 +233,7 @@ void mapRequestLogLevelMapper() throws Exception {
         // Check if logs at WARN level if there are headers we're looking for.
         service.serve(ctx, ctx.request());
         verify(logger, never()).isInfoEnabled();
-        verify(logger, times(2)).isWarnEnabled();
+        verify(logger, times(3)).isWarnEnabled();
         verify(logger).warn(matches(".*Request:.*headers=\\[:method=GET, :path=/, x-req=test, x-res=test].*"));
         verify(logger).warn(matches(".*Response:.*"));
         verifyNoMoreInteractions(logger);
@@ -251,7 +269,7 @@ void mapRequestLogLevelMapperUnmatched() throws Exception {
 
         // Check if logs at INFO level if there are no headers we're looking for.
         service.serve(ctx, ctx.request());
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
         verify(logger, never()).isWarnEnabled();
         verify(logger).info(matches(".*Request:.*headers=\\[:method=GET, :path=/].*"));
         verify(logger).info(matches(".*Response:.*"));
@@ -515,10 +533,10 @@ void sanitizeRequestContent() throws Exception {
 
         service.serve(ctx, ctx.request());
 
-        // Ensure the request content (the phone number 333-490-4499) is sanitized.
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
 
         // verify request and response log
+        // Ensure the request content (the phone number 333-490-4499) is sanitized.
         verify(logger, times(2)).info(argThat((String text) -> !text.contains("333-490-4499")));
         verifyNoMoreInteractions(logger);
     }
@@ -556,10 +574,10 @@ void sanitizeRequestContentByLogFormatter() throws Exception {
 
         service.serve(ctx, ctx.request());
 
-        // Ensure the request content (the phone number 333-490-4499) is sanitized.
-        verify(logger, times(2)).isInfoEnabled();
+        verify(logger, times(3)).isInfoEnabled();
 
         // verify request and response log
+        // Ensure the request content (the phone number 333-490-4499) is sanitized.
         verify(logger, times(2)).info(argThat((String text) -> !text.contains("333-490-4499")));
         verifyNoMoreInteractions(logger);
     }