Include the current attempt number in logs when retrying. (#5719)

Motivation: Currently, it is difficult to distinguish from a log if a request is being retried when a `LoggingClient` is added before a `RetryingClient`. Including the current attempt number in logs will help resolve this issue. Modifications: - Included the current attempt number in a `RequestLog`. Result: - The `RequestLog` now includes the current attempt number if the request is created from a retrying client. - Close #5716 - (Deprecated) - `ClientRequestContext.newDerivedContext(RequestId,HttpRequest,RpcRequest,Endpoint)` is deprecated. - Use `ClientRequestContext.newDerivedContext(RequestId,HttpRequest,RpcRequest,Endpoint,int)`.
line · Jun 10, 2024 · b6c4d73 · b6c4d73
1 parent f3dbf7b
commit b6c4d73
Show file tree

Hide file tree

Showing 12 changed files with 79 additions and 10 deletions.
diff --git a/core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java b/core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java
@@ -82,6 +82,8 @@ final class DefaultRequestLog implements RequestLog, RequestLogBuilder {
     private static final ResponseHeaders DUMMY_RESPONSE_HEADERS = ResponseHeaders.of(HttpStatus.UNKNOWN);
 
     private final RequestContext ctx;
+    private int currentAttempt;
+
     private final CompleteRequestLog notCheckingAccessor = new CompleteRequestLog();
 
     @Nullable
@@ -545,7 +547,11 @@ public void addChild(RequestLogAccess child) {
             children = new ArrayList<>();
             propagateRequestSideLog(child);
         }
+
         children.add(child);
+        if (child instanceof DefaultRequestLog) {
+            ((DefaultRequestLog) child).currentAttempt = children.size();
+        }
     }
 
     private void propagateRequestSideLog(RequestLogAccess child) {
@@ -1025,6 +1031,11 @@ public void requestTrailers(HttpHeaders requestTrailers) {
         updateFlags(RequestLogProperty.REQUEST_TRAILERS);
     }
 
+    @Override
+    public int currentAttempt() {
+        return currentAttempt;
+    }
+
     @Override
     public void endRequest() {
         endRequest0(null);
@@ -1779,6 +1790,11 @@ public HttpHeaders requestTrailers() {
             return requestTrailers;
         }
 
+        @Override
+        public int currentAttempt() {
+            return currentAttempt;
+        }
+
         @Override
         public long responseStartTimeMicros() {
             return responseStartTimeMicros;

diff --git a/core/src/main/java/com/linecorp/armeria/common/logging/JsonLogFormatter.java b/core/src/main/java/com/linecorp/armeria/common/logging/JsonLogFormatter.java
@@ -170,6 +170,12 @@ public String formatRequest(RequestOnlyLog log) {
             if (sanitizedTrailers != null) {
                 objectNode.set("trailers", sanitizedTrailers);
             }
+
+            final int currentAttempt = log.currentAttempt();
+            if (currentAttempt > 0) {
+                objectNode.put("currentAttempt", currentAttempt);
+            }
+
             return objectMapper.writeValueAsString(objectNode);
         } catch (Exception e) {
             logger.warn("Unexpected exception while formatting a request log: {}", log, e);

diff --git a/core/src/main/java/com/linecorp/armeria/common/logging/RequestOnlyLog.java b/core/src/main/java/com/linecorp/armeria/common/logging/RequestOnlyLog.java
@@ -271,6 +271,13 @@ default long requestDurationNanos() {
      */
     HttpHeaders requestTrailers();
 
+    /**
+     * Returns the current attempt number of the {@link Request}.
+     * It returns {@code 0} for the very first request. It returns {@code 1} for the first retry.
+     * It returns {@code 2} for the second retry, and so forth.
+     */
+    int currentAttempt();
+
     /**
      * Returns the string representation of the {@link Request}, with no sanitization of headers or content.
      * This method is a shortcut for:

diff --git a/core/src/main/java/com/linecorp/armeria/common/logging/TextLogFormatter.java b/core/src/main/java/com/linecorp/armeria/common/logging/TextLogFormatter.java
@@ -182,8 +182,12 @@ public String formatRequest(RequestOnlyLog log) {
             if (sanitizedTrailers != null) {
                 buf.append(", trailers=").append(sanitizedTrailers);
             }
-            buf.append('}');
 
+            final int currentAttempt = log.currentAttempt();
+            if (currentAttempt > 0) {
+                buf.append(", currentAttempt=").append(currentAttempt);
+            }
+            buf.append('}');
             return buf.toString();
         }
     }

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
@@ -378,7 +378,7 @@ void shouldLogFailedResponseWhenFailureSamplingRateIsAlways() throws Exception {
 
         // verify request log
         verify(logger).warn(argThat((String actLog) -> actLog.contains("Request:") &&
-                                                        actLog.endsWith("headers=[:method=GET, :path=/]}")));
+                                                       actLog.endsWith("headers=[:method=GET, :path=/]}")));
 
         // verify response log
         verify(logger).warn(argThat((String actLog) -> actLog.contains("Response:") &&

diff --git a/...test/java/com/linecorp/armeria/client/retry/RetryingClientWithEmptyEndpointGroupTest.java b/...test/java/com/linecorp/armeria/client/retry/RetryingClientWithEmptyEndpointGroupTest.java
@@ -86,6 +86,10 @@ void shouldRetryEvenIfEndpointGroupIsEmpty() {
         assertEmptyEndpointGroupException(log);
 
         assertThat(log.children()).hasSize(numAttempts);
+        for (int i = 0; i < log.children().size(); i++) {
+            assertThat(log.children().get(i).partial().currentAttempt()).isEqualTo(i + 1);
+        }
+
         log.children().stream()
            .map(RequestLogAccess::ensureComplete)
            .forEach(RetryingClientWithEmptyEndpointGroupTest::assertEmptyEndpointGroupException);

diff --git a/core/src/test/java/com/linecorp/armeria/common/logging/JsonLogFormatterTest.java b/core/src/test/java/com/linecorp/armeria/common/logging/JsonLogFormatterTest.java
@@ -27,11 +27,14 @@
 
 import com.fasterxml.jackson.databind.JsonNode;
 
+import com.linecorp.armeria.client.ClientRequestContext;
+import com.linecorp.armeria.client.Endpoint;
 import com.linecorp.armeria.common.HttpHeaderNames;
 import com.linecorp.armeria.common.HttpMethod;
 import com.linecorp.armeria.common.HttpRequest;
 import com.linecorp.armeria.common.HttpStatus;
 import com.linecorp.armeria.common.RequestHeaders;
+import com.linecorp.armeria.common.RequestId;
 import com.linecorp.armeria.common.ResponseHeaders;
 import com.linecorp.armeria.server.ServiceRequestContext;
 
@@ -62,6 +65,23 @@ void formatResponse() {
                          "\"duration\":\".+\",\"totalDuration\":\".+\",\"headers\":\\{\".+\"}}$");
     }
 
+    @Test
+    void derivedLog() {
+        final LogFormatter logFormatter = LogFormatter.ofJson();
+        final HttpRequest request = HttpRequest.of(HttpMethod.GET, "/format");
+        final ClientRequestContext ctx = ClientRequestContext.of(request);
+        final ClientRequestContext derivedCtx =
+                ctx.newDerivedContext(RequestId.of(1), request, null, Endpoint.of("127.0.0.1"));
+        final DefaultRequestLog log = (DefaultRequestLog) derivedCtx.log();
+        ctx.logBuilder().addChild(log);
+        log.endRequest();
+        final String requestLog = logFormatter.formatRequest(log);
+        assertThat(requestLog)
+                .matches("^\\{\"type\":\"request\",\"startTime\":\".+\",\"length\":\".+\"," +
+                         "\"duration\":\".+\",\"scheme\":\".+\",\"name\":\".+\",\"headers\":\\{\".+\"}" +
+                         ",\"currentAttempt\":1}$");
+    }
+
     @Test
     void maskSensitiveHeadersByDefault() {
         final LogFormatter logFormatter = LogFormatter.builderForJson()

diff --git a/core/src/test/java/com/linecorp/armeria/common/logging/TextLogFormatterTest.java b/core/src/test/java/com/linecorp/armeria/common/logging/TextLogFormatterTest.java
@@ -25,11 +25,14 @@
 import org.junit.jupiter.params.ParameterizedTest;
 import org.junit.jupiter.params.provider.CsvSource;
 
+import com.linecorp.armeria.client.ClientRequestContext;
+import com.linecorp.armeria.client.Endpoint;
 import com.linecorp.armeria.common.HttpHeaderNames;
 import com.linecorp.armeria.common.HttpMethod;
 import com.linecorp.armeria.common.HttpRequest;
 import com.linecorp.armeria.common.HttpStatus;
 import com.linecorp.armeria.common.RequestHeaders;
+import com.linecorp.armeria.common.RequestId;
 import com.linecorp.armeria.common.ResponseHeaders;
 import com.linecorp.armeria.server.ServiceRequestContext;
 
@@ -69,6 +72,23 @@ void formatResponse(boolean containContext) {
         }
     }
 
+    @Test
+    void derivedLog() {
+        final LogFormatter logFormatter = LogFormatter.builderForText().build();
+        final HttpRequest request = HttpRequest.of(HttpMethod.GET, "/format");
+        final ClientRequestContext ctx = ClientRequestContext.of(request);
+        final ClientRequestContext derivedCtx =
+                ctx.newDerivedContext(RequestId.of(1), request, null, Endpoint.of("127.0.0.1"));
+        final DefaultRequestLog log = (DefaultRequestLog) derivedCtx.log();
+        ctx.logBuilder().addChild(log);
+        log.endRequest();
+        final String requestLog = logFormatter.formatRequest(log);
+        final String regex =
+                ".*Request: .*\\{startTime=.+, length=.+, duration=.+, scheme=.+, name=.+, headers=.+" +
+                "currentAttempt=1}$";
+        assertThat(requestLog).matches(regex);
+    }
+
     @Test
     void maskSensitiveHeadersByDefault() {
         final LogFormatter logFormatter = LogFormatter.builderForText()
@@ -131,7 +151,6 @@ void maskRequestHeaders() {
         final DefaultRequestLog log = (DefaultRequestLog) ctx.log();
         log.endRequest();
         final String requestLog = logFormatter.formatRequest(log);
-        System.out.println(requestLog);
         final Matcher matcher1 = Pattern.compile("cookie=(.*?)[,\\]]").matcher(requestLog);
         assertThat(matcher1.find()).isTrue();
         assertThat(matcher1.group(1)).isEqualTo(

diff --git a/...2/src/test/java/com/linecorp/armeria/common/auth/oauth2/GrantedOAuth2AccessTokenTest.java b/...2/src/test/java/com/linecorp/armeria/common/auth/oauth2/GrantedOAuth2AccessTokenTest.java
@@ -173,7 +173,6 @@ void testToString() throws Exception {
                                                                        .scope(scope)
                                                                        .build();
 
-        System.out.println(token);
         assertThat(token.toString()).isEqualTo(toString);
     }
 

diff --git a/oauth2/src/test/java/com/linecorp/armeria/common/auth/oauth2/OAuth2TokenDescriptorTest.java b/oauth2/src/test/java/com/linecorp/armeria/common/auth/oauth2/OAuth2TokenDescriptorTest.java
@@ -197,8 +197,6 @@ void testToString() throws Exception {
                                                                       .extras(extras)
                                                                       .scope(scope)
                                                                       .build();
-
-        System.out.println(descriptor);
         assertThat(descriptor.toString()).isEqualTo(rawResponse);
     }
 

diff --git a/...est/java/com/linecorp/armeria/internal/common/auth/oauth2/TokenRevocationRequestTest.java b/...est/java/com/linecorp/armeria/internal/common/auth/oauth2/TokenRevocationRequestTest.java
@@ -69,7 +69,6 @@ public void testRevoke() throws Exception {
                 requestHeaders1, "token=" + token.grantedToken().accessToken() +
                                  "&token_type_hint=access_token").aggregate().join();
         assertThat(response1.status()).isEqualTo(HttpStatus.OK);
-        System.out.println(response1.contentUtf8());
         assertThat(response1.contentUtf8()).isEqualTo(HttpStatus.OK.toString());
 
         final RequestHeaders requestHeaders2 = RequestHeaders.of(

diff --git a/resteasy/src/test/java/com/linecorp/armeria/server/resteasy/BookServiceClientServerTest.java b/resteasy/src/test/java/com/linecorp/armeria/server/resteasy/BookServiceClientServerTest.java
@@ -112,7 +112,6 @@ void testBooks() throws Exception {
         assertThatThrownBy(getBooks::hasEntity)
                 .isInstanceOf(IllegalStateException.class)
                 .hasMessage("RESTEASY003765: Response is closed.");
-        System.out.println(getBooksEntry);
         assertThat(getBooksEntry).contains("John Doe");
         assertThat(getBooksEntry).contains("Java");
         final Book[] getBooksEntryArray = JSON.readValue(getBooksEntry, Book[].class);
@@ -134,7 +133,6 @@ void testBooks() throws Exception {
                 .isInstanceOf(IllegalStateException.class)
                 .hasMessage("RESTEASY003765: Response is closed.");
         final String getBooksEntry2 = JSON.writeValueAsString(getBooksEntryArray2);
-        System.out.println(getBooksEntry2);
         assertThat(getBooksEntry2).isEqualTo(getBooksEntry);
 
         final Response getAllBooks = webTarget.path(booksPath)
@@ -150,7 +148,6 @@ void testBooks() throws Exception {
         assertThat(getAllBooksEntryArray[0]).isInstanceOf(Book.class);
         assertThat(getAllBooksEntryArray).contains(getBooksEntryArray2);
         final String getAllBooksEntry = JSON.writeValueAsString(getBooksEntryArray2);
-        System.out.println(getAllBooksEntry);
 
         final String getBookPath = "/resteasy/app/books/978-3-16-148410-0";
         final Response getBook = webTarget.path(getBookPath)