#26 - Expose HttpClientRequest.responseTimeMicros() ... for ease of metrics interceptors

Author: rbygrave

client/src/main/java/io/avaje/http/client/BasicAuthIntercept.java

@@ -31,8 +31,4 @@ public void beforeRequest(HttpClientRequest request) {
     request.header("Authorization", headerValue);
   }
 
-  @Override
-  public void afterResponse(HttpResponse<?> response, HttpClientRequest request) {
-    // do nothing
-  }
 }

client/src/main/java/io/avaje/http/client/DHttpClientRequest.java

@@ -43,7 +43,7 @@ class DHttpClientRequest implements HttpClientRequest, HttpClientResponse {
   private Map<String, List<String>> headers;
 
   private boolean bodyFormEncoded;
-  private long requestTimeNanos;
+  private long responseTimeNanos;
 
   private HttpResponse<?> httpResponse;
   private BodyContent encodedResponseBody;
@@ -421,7 +421,7 @@ protected <T> HttpResponse<T> performSend(HttpResponse.BodyHandler<T> responseHa
     try {
       return context.send(httpRequest, responseHandler);
     } finally {
-      requestTimeNanos = System.nanoTime() - startNanos;
+      responseTimeNanos = System.nanoTime() - startNanos;
     }
   }
 
@@ -449,7 +449,7 @@ protected <E> List<E> asyncList(Class<E> type, HttpResponse<byte[]> response) {
   }
 
   protected <E> Stream<E> asyncStream(Class<E> type, HttpResponse<Stream<String>> response) {
-    requestTimeNanos = System.nanoTime() - startAsyncNanos;
+    responseTimeNanos = System.nanoTime() - startAsyncNanos;
     httpResponse = response;
     context.afterResponse(this);
     if (response.statusCode() >= 300) {
@@ -460,20 +460,25 @@ protected <E> Stream<E> asyncStream(Class<E> type, HttpResponse<Stream<String>>
   }
 
   private void afterAsyncEncoded(HttpResponse<byte[]> response) {
-    requestTimeNanos = System.nanoTime() - startAsyncNanos;
+    responseTimeNanos = System.nanoTime() - startAsyncNanos;
     httpResponse = response;
     encodedResponseBody = context.readContent(response);
     context.afterResponse(this);
     context.checkMaybeThrow(response);
   }
 
   protected <E> HttpResponse<E> afterAsync(HttpResponse<E> response) {
-    requestTimeNanos = System.nanoTime() - startAsyncNanos;
+    responseTimeNanos = System.nanoTime() - startAsyncNanos;
     httpResponse = response;
     context.afterResponse(this);
     return response;
   }
 
+  @Override
+  public long responseTimeMicros() {
+    return responseTimeNanos / 1000;
+  }
+
   @Override
   public HttpResponse<byte[]> asByteArray() {
     return withHandler(HttpResponse.BodyHandlers.ofByteArray());
@@ -573,8 +578,8 @@ boolean isSkipAuthToken() {
   private class ListenerEvent implements RequestListener.Event {
 
     @Override
-    public long responseTimeNanos() {
-      return requestTimeNanos;
+    public long responseTimeMicros() {
+      return responseTimeNanos / 1000;
     }
 
     @Override

client/src/main/java/io/avaje/http/client/HttpClientRequest.java

@@ -2,6 +2,7 @@
 
 import java.io.InputStream;
 import java.net.http.HttpRequest;
+import java.net.http.HttpResponse;
 import java.nio.file.Path;
 import java.time.Duration;
 import java.util.List;
@@ -345,4 +346,10 @@ default HttpClientResponse delete() {
    */
   HttpClientResponse HEAD();
 
+  /**
+   * After the response is returned this method returns the response time in microseconds.
+   * <p>
+   * This is useful for use in {@link RequestIntercept#afterResponse(HttpResponse, HttpClientRequest)}
+   */
+  long responseTimeMicros();
 }

client/src/main/java/io/avaje/http/client/RequestIntercept.java

@@ -12,11 +12,15 @@ public interface RequestIntercept {
    * <p>
    * Typically we can add headers or modify the request prior to it being sent.
    */
-  void beforeRequest(HttpClientRequest request);
+  default void beforeRequest(HttpClientRequest request) {
+    // do nothing by default
+  }
 
   /**
    * After the response has been received.
    */
-  void afterResponse(HttpResponse<?> response, HttpClientRequest request);
+  default void afterResponse(HttpResponse<?> response, HttpClientRequest request) {
+    // do nothing by default
+  }
 
 }

client/src/main/java/io/avaje/http/client/RequestListener.java

@@ -25,7 +25,7 @@ interface Event {
     /**
      * Return the time from request to response in nanos.
      */
-    long responseTimeNanos();
+    long responseTimeMicros();
 
     /**
      * Return the URI for the request.

client/src/main/java/io/avaje/http/client/RequestLogger.java

@@ -42,7 +42,7 @@ public void response(Event event) {
     if (log.isDebugEnabled()) {
       final HttpResponse<?> response = event.response();
       final HttpRequest request = response.request();
-      long micros = event.responseTimeNanos() / 1000;
+      long micros = event.responseTimeMicros();
 
       StringBuilder sb = new StringBuilder();
       sb.append("statusCode:").append(response.statusCode())

client/src/test/java/io/avaje/http/client/RequestListenerTest.java

@@ -1,7 +1,6 @@
 package io.avaje.http.client;
 
 import com.fasterxml.jackson.databind.ObjectMapper;
-import org.example.webserver.HelloDto;
 import org.junit.jupiter.api.Test;
 
 import java.net.http.HttpResponse;
@@ -28,7 +27,7 @@ public void response(Event event) {
         assertThat(event.uri().toString()).isEqualTo("http://localhost:8887/hello/message");
         assertThat(event.requestBody()).isNull();
       }
-      assertThat(event.responseTimeNanos()).isGreaterThan(1L);
+      assertThat(event.responseTimeMicros()).isGreaterThan(1L);
       assertThat(event.response().statusCode()).isEqualTo(200);
       assertThat(event.request()).isEqualTo(event.response().request());
     }

client/src/test/java/io/avaje/http/client/RetryTest.java

@@ -9,26 +9,43 @@
 
 public class RetryTest extends BaseWebTest {
 
+  final MyIntercept myIntercept = new MyIntercept();
   final HttpClientContext clientContext = initClientWithRetry();
 
-  static HttpClientContext initClientWithRetry() {
+  HttpClientContext initClientWithRetry() {
     return HttpClientContext.newBuilder()
       .withBaseUrl("http://localhost:8887")
       .withBodyAdapter(new JacksonBodyAdapter(new ObjectMapper()))
       .withRequestListener(new RequestLogger())
       .withRetryHandler(new SimpleRetryHandler(4, 1))
+      .withRequestIntercept(myIntercept)
       .build();
   }
 
   @Test
   void retryTest() {
-
     HttpResponse<String> res = clientContext.request()
       .path("hello/retry")
       .GET()
       .asString();
 
     assertThat(res.body()).isEqualTo("All good at 3rd attempt");
+
+    assertThat(myIntercept.responseTimeMicros).isGreaterThan(1);
+    assertThat(myIntercept.counter).isEqualTo(1);
   }
 
+  static class MyIntercept implements RequestIntercept {
+    int counter;
+    long responseTimeMicros;
+
+    /**
+     * Not called for the retry attempts. Only called on the final success or error response.
+     */
+    @Override
+    public void afterResponse(HttpResponse<?> response, HttpClientRequest request) {
+      counter++;
+      responseTimeMicros = request.responseTimeMicros();
+    }
+  }
 }