Fix requestEndTime is set after send response when empty content request

Author: gibeom-gwon

core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java

@@ -1118,6 +1118,25 @@ public int currentAttempt() {
         return currentAttempt;
     }
 
+    @Override
+    public void requestEnd() {
+        requestEnd0(System.nanoTime());
+    }
+
+    @Override
+    public void requestEnd(long requestEndTimeNanos) {
+        requestEnd0(requestEndTimeNanos);
+    }
+
+    private void requestEnd0(long requestEndTimeNanos) {
+        if (isAvailable(REQUEST_END_TIME)) {
+            return;
+        }
+
+        this.requestEndTimeNanos = requestEndTimeNanos;
+        updateFlags(REQUEST_END_TIME);
+    }
+
     @Override
     public void endRequest() {
         endRequest0(null);
@@ -1183,7 +1202,10 @@ private void endRequest0(@Nullable Throwable requestCause, long requestEndTimeNa
             setNamesIfAbsent();
         }
 
-        this.requestEndTimeNanos = requestEndTimeNanos;
+        // Set requestEndTimeNanos if it is not already set
+        if (!isAvailable(REQUEST_END_TIME)) {
+            this.requestEndTimeNanos = requestEndTimeNanos;
+        }
 
         setRequestCause(requestCause);
         updateFlags(flags);

core/src/main/java/com/linecorp/armeria/common/logging/RequestLogBuilder.java

@@ -189,6 +189,16 @@ void session(@Nullable Channel channel, SessionProtocol sessionProtocol, @Nullab
     @UnstableApi
     void requestCause(Throwable cause);
 
+    /**
+     * Sets the {@link RequestLog#requestEndTimeNanos()}.
+     */
+    void requestEnd();
+
+    /**
+     * Sets the {@link RequestLog#requestEndTimeNanos()} with the specified timestamp.
+     */
+    void requestEnd(long requestEndTimeNanos);
+
     /**
      * Finishes the collection of the {@link Request} information. This method sets the following properties:
      * <ul>

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

@@ -83,6 +83,9 @@ final class EmptyContentDecodedHttpRequest implements DecodedHttpRequest {
     @Override
     public void init(ServiceRequestContext ctx) {
         this.ctx = ctx;
+
+        // EmptyContentDecodedHttpRequest does not have any additional data to read.
+        ctx.logBuilder().requestEnd();
     }
 
     @Nullable

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

@@ -22,10 +22,17 @@
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.extension.RegisterExtension;
 
+import com.linecorp.armeria.client.WebClient;
+import com.linecorp.armeria.common.AggregatedHttpResponse;
 import com.linecorp.armeria.common.ExchangeType;
 import com.linecorp.armeria.common.HttpMethod;
+import com.linecorp.armeria.common.HttpResponse;
+import com.linecorp.armeria.common.HttpStatus;
 import com.linecorp.armeria.common.RequestHeaders;
+import com.linecorp.armeria.common.logging.RequestLog;
+import com.linecorp.armeria.server.annotation.Get;
 import com.linecorp.armeria.testing.junit5.common.EventLoopExtension;
+import com.linecorp.armeria.testing.junit5.server.ServerExtension;
 
 import reactor.test.StepVerifier;
 
@@ -34,6 +41,21 @@ class EmptyContentDecodedHttpRequestTest {
     @RegisterExtension
     static EventLoopExtension eventLoop = new EventLoopExtension();
 
+    @RegisterExtension
+    static ServerExtension server = new ServerExtension() {
+        @Override
+        protected void configure(ServerBuilder sb) {
+            sb.annotatedService(new AnnotatedService());
+        }
+    };
+
+    static class AnnotatedService {
+        @Get("/get")
+        public HttpResponse get() {
+            return HttpResponse.of(HttpStatus.OK);
+        }
+    }
+
     @Test
     void emptyContent() {
         final RoutingContext routingContext = mock(RoutingContext.class);
@@ -47,4 +69,19 @@ void emptyContent() {
                     .verify();
         assertThat(req.headers()).isEqualTo(headers);
     }
+
+    @Test
+    void requestEndTimeNanosIsFasterThanResponseStartTimeNanos()
+            throws InterruptedException {
+        final WebClient webClient = server.webClient();
+
+        final AggregatedHttpResponse response = webClient.get("/get")
+                                                         .aggregate()
+                                                         .join();
+        assertThat(response.status()).isEqualTo(HttpStatus.OK);
+
+        final ServiceRequestContext sctx = server.requestContextCaptor().take();
+        final RequestLog log = sctx.log().whenComplete().join();
+        assertThat(log.requestEndTimeNanos()).isLessThan(log.responseStartTimeNanos());
+    }
 }