Merge pull request zalando#168 from zalando/feature/duration

Added logging of durations

Author: whiskeysierra

README.md

@@ -183,6 +183,7 @@ Hello world!
 
 ```http
 Outgoing Response: 2d66e4bc-9a0d-11e5-a84c-1f39510f0d6b
+Duration: 25 ms
 HTTP/1.1 200
 Content-Type: application/json
 
@@ -219,6 +220,7 @@ Content-Type: application/json
   "origin": "local",
   "type": "response",
   "correlation": "2d66e4bc-9a0d-11e5-a84c-1f39510f0d6b",
+  "duration": 25,
   "protocol": "HTTP/1.1",
   "status": 200,
   "headers": {
@@ -236,6 +238,7 @@ a JSON response body will **not** be escaped and represented as a string:
   "origin": "local",
   "type": "response",
   "correlation": "2d66e4bc-9a0d-11e5-a84c-1f39510f0d6b",
+  "duration": 25,
   "protocol": "HTTP/1.1",
   "status": 200,
   "headers": {

logbook-api/src/main/java/org/zalando/logbook/Correlation.java

@@ -1,9 +1,13 @@
 package org.zalando.logbook;
 
+import java.time.Duration;
+
 public interface Correlation<Request, Response> {
 
     String getId();
 
+    Duration getDuration();
+
     Request getRequest();
 
     Response getResponse();

logbook-api/src/main/java/org/zalando/logbook/package-info.java

@@ -0,0 +1,4 @@
+@ParametersAreNonnullByDefault
+package org.zalando.logbook;
+
+import javax.annotation.ParametersAreNonnullByDefault;

logbook-core/src/main/java/org/zalando/logbook/ChunkingHttpLogWriter.java

@@ -42,7 +42,8 @@ public void writeRequest(final Precorrelation<String> precorrelation) throws IOE
     @Override
     public void writeResponse(final Correlation<String, String> correlation) throws IOException {
         split(correlation.getResponse()).forEach(throwing(part ->
-                writer.writeResponse(new SimpleCorrelation<>(correlation.getId(), correlation.getRequest(), part))));
+                writer.writeResponse(new SimpleCorrelation<>(correlation.getId(), correlation.getDuration(),
+                        correlation.getRequest(), part))));
     }
 
     private static <T> Consumer<T> throwing(final ThrowingConsumer<T> consumer) {

logbook-core/src/main/java/org/zalando/logbook/DefaultHttpLogFormatter.java

@@ -133,15 +133,16 @@ public List<String> prepare(final Correlation<HttpRequest, HttpResponse> correla
         final int status = response.getStatus();
         final String reasonPhrase = REASON_PHRASES.getOrDefault(Integer.toString(status), "");
         final String statusLine = String.format("%s %d %s", response.getProtocolVersion(), status, reasonPhrase).trim();
-        return prepare(response, "Response", correlation.getId(), statusLine);
+        return prepare(response, "Response", correlation.getId(),
+                "Duration: " + correlation.getDuration().toMillis() + " ms", statusLine);
     }
 
     private <H extends HttpMessage> List<String> prepare(final H message, final String type,
-            final String correlationId, final String line) throws IOException {
+            final String correlationId, final String... prefixes) throws IOException {
         final List<String> lines = new ArrayList<>();
 
         lines.add(direction(message) + " " + type + ": " + correlationId);
-        lines.add(line);
+        Collections.addAll(lines, prefixes);
         lines.addAll(formatHeaders(message));
 
         final String body = message.getBodyAsString();

logbook-core/src/main/java/org/zalando/logbook/DefaultLogbook.java

@@ -1,6 +1,9 @@
 package org.zalando.logbook;
 
 import java.io.IOException;
+import java.time.Clock;
+import java.time.Duration;
+import java.time.Instant;
 import java.util.Optional;
 import java.util.UUID;
 import java.util.function.Predicate;
@@ -14,6 +17,7 @@ final class DefaultLogbook implements Logbook {
     private final ResponseFilter responseFilter;
     private final HttpLogFormatter formatter;
     private final HttpLogWriter writer;
+    private final Clock clock = Clock.systemUTC();
 
     DefaultLogbook(
             final Predicate<RawHttpRequest> predicate,
@@ -34,6 +38,7 @@ final class DefaultLogbook implements Logbook {
 
     @Override
     public Optional<Correlator> write(final RawHttpRequest rawHttpRequest) throws IOException {
+        final Instant start = Instant.now(clock);
         if (writer.isActive(rawHttpRequest) && predicate.test(rawHttpRequest)) {
             final String correlationId = UUID.randomUUID().toString();
             final RawHttpRequest filteredRawHttpRequest = rawRequestFilter.filter(rawHttpRequest);
@@ -44,12 +49,14 @@ public Optional<Correlator> write(final RawHttpRequest rawHttpRequest) throws IO
             writer.writeRequest(new SimplePrecorrelation<>(correlationId, format));
 
             return Optional.of(rawHttpResponse -> {
+                final Instant end = Instant.now(clock);
+                final Duration duration = Duration.between(start, end);
                 final RawHttpResponse filteredRawHttpResponse = rawResponseFilter.filter(rawHttpResponse);
                 final HttpResponse response = responseFilter.filter(filteredRawHttpResponse.withBody());
                 final Correlation<HttpRequest, HttpResponse> correlation =
-                        new SimpleCorrelation<>(correlationId, request, response);
+                        new SimpleCorrelation<>(correlationId, duration, request, response);
                 final String message = formatter.format(correlation);
-                writer.writeResponse(new SimpleCorrelation<>(correlationId, format, message));
+                writer.writeResponse(new SimpleCorrelation<>(correlationId, duration, format, message));
             });
         } else {
             return Optional.empty();
@@ -81,11 +88,13 @@ public I getRequest() {
     static class SimpleCorrelation<I, O> implements Correlation<I, O> {
 
         private final String id;
+        private final Duration duration;
         private final I request;
         private final O response;
 
-        public SimpleCorrelation(final String id, final I request, final O response) {
+        public SimpleCorrelation(final String id, final Duration duration, final I request, final O response) {
             this.id = id;
+            this.duration = duration;
             this.request = request;
             this.response = response;
         }
@@ -95,6 +104,11 @@ public String getId() {
             return id;
         }
 
+        @Override
+        public Duration getDuration() {
+            return duration;
+        }
+
         @Override
         public I getRequest() {
             return request;

logbook-core/src/main/java/org/zalando/logbook/JsonHttpLogFormatter.java

@@ -114,14 +114,14 @@ public String format(final Correlation<HttpRequest, HttpResponse> correlation) t
      * @see DefaultHttpLogFormatter#prepare(Correlation)
      */
     public Map<String, Object> prepare(final Correlation<HttpRequest, HttpResponse> correlation) throws IOException {
-        final String correlationId = correlation.getId();
         final HttpResponse response = correlation.getResponse();
 
         final Map<String, Object> content = new LinkedHashMap<>();
 
         content.put("origin", translate(response.getOrigin()));
         content.put("type", "response");
-        content.put("correlation", correlationId);
+        content.put("correlation", correlation.getId());
+        content.put("duration", correlation.getDuration().toMillis());
         content.put("protocol", response.getProtocolVersion());
         content.put("status", response.getStatus());
 

logbook-core/src/test/java/org/zalando/logbook/ChunkingHttpLogWriterTest.java

@@ -10,6 +10,7 @@
 import java.io.IOException;
 import java.util.List;
 
+import static java.time.Duration.ZERO;
 import static java.util.stream.Collectors.toList;
 import static org.hamcrest.Matchers.contains;
 import static org.hamcrest.Matchers.is;
@@ -84,7 +85,7 @@ public void shouldCreateWithSizeOfOne() throws IOException {
     }
 
     private List<String> captureResponse(final String response) throws IOException {
-        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("id", "", response));
+        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("id", ZERO, "", response));
 
         verify(delegate, atLeastOnce()).writeResponse(responseCaptor.capture());
 

logbook-core/src/test/java/org/zalando/logbook/CurlHttpLogFormatterTest.java

@@ -6,6 +6,7 @@
 
 import java.io.IOException;
 
+import static java.time.Duration.ZERO;
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertThat;
 import static org.mockito.Mockito.mock;
@@ -70,7 +71,7 @@ public void shouldDelegateLogResponse() throws IOException {
         final HttpLogFormatter unit = new CurlHttpLogFormatter(fallback);
 
         final Correlation<HttpRequest, HttpResponse> correlation = new SimpleCorrelation<>(
-                "3881ae92-6824-11e5-921b-10ddb1ee7671", MockHttpRequest.create(), MockHttpResponse.create());
+                "3881ae92-6824-11e5-921b-10ddb1ee7671", ZERO, MockHttpRequest.create(), MockHttpResponse.create());
 
         unit.format(correlation);
 

logbook-core/src/test/java/org/zalando/logbook/DefaultHttpLogFormatterTest.java

@@ -5,7 +5,9 @@
 import org.zalando.logbook.DefaultLogbook.SimplePrecorrelation;
 
 import java.io.IOException;
+import java.time.Duration;
 
+import static java.time.Duration.ofMillis;
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertThat;
 
@@ -82,9 +84,10 @@ public void shouldLogResponse() throws IOException {
                 .withHeaders(MockHeaders.of("Content-Type", "application/json"))
                 .withBodyAsString("{\"success\":true}");
 
-        final String http = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String http = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(125), request, response));
 
         assertThat(http, is("Incoming Response: 2d51bc02-677e-11e5-8b9b-10ddb1ee7671\n" +
+                "Duration: 125 ms\n" +
                 "HTTP/1.0 201 Created\n" +
                 "Content-Type: application/json\n" +
                 "\n" +
@@ -100,9 +103,10 @@ public void shouldLogResponseWithoutBody() throws IOException {
                 .withStatus(400)
                 .withHeaders(MockHeaders.of("Content-Type", "application/json"));
 
-        final String http = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String http = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(100), request, response));
 
         assertThat(http, is("Outgoing Response: 3881ae92-6824-11e5-921b-10ddb1ee7671\n" +
+                "Duration: 100 ms\n" +
                 "HTTP/1.1 400 Bad Request\n" +
                 "Content-Type: application/json"));
     }

logbook-core/src/test/java/org/zalando/logbook/DefaultHttpLogWriterLevelTest.java

@@ -13,6 +13,7 @@
 import java.util.function.BiConsumer;
 import java.util.function.Predicate;
 
+import static java.time.Duration.ZERO;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.verify;
 
@@ -67,7 +68,7 @@ public void shouldLogRequestWithCorrectLevel() throws IOException {
 
     @Test
     public void shouldLogResponseWithCorrectLevel() throws IOException {
-        unit.writeResponse(new SimpleCorrelation<>("1", "foo", "bar"));
+        unit.writeResponse(new SimpleCorrelation<>("1", ZERO, "foo", "bar"));
 
         log.accept(verify(logger), "bar");
     }

logbook-core/src/test/java/org/zalando/logbook/DefaultHttpLogWriterTest.java

@@ -7,6 +7,7 @@
 
 import java.io.IOException;
 
+import static java.time.Duration.ZERO;
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertThat;
@@ -47,7 +48,7 @@ public void shouldDefaultToTraceLevelForLoggingResponses() throws IOException {
         final Logger logger = mock(Logger.class);
         final HttpLogWriter unit = new DefaultHttpLogWriter(logger);
 
-        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", "foo", "bar"));
+        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar"));
 
         verify(logger).trace("bar");
     }

logbook-core/src/test/java/org/zalando/logbook/JsonHttpLogFormatterTest.java

@@ -5,8 +5,11 @@
 import org.zalando.logbook.DefaultLogbook.SimplePrecorrelation;
 
 import java.io.IOException;
+import java.time.Duration;
 
 import static com.jayway.jsonassert.JsonAssert.with;
+import static java.time.Duration.ZERO;
+import static java.time.Duration.ofMillis;
 import static java.util.Collections.singletonList;
 import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.emptyString;
@@ -240,7 +243,7 @@ public void shouldLogResponse() throws IOException {
                 .withContentType("application/xml")
                 .withBodyAsString("<success>true<success>");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(125), request, response));
 
         with(json)
                 .assertThat("$.origin", is("local"))
@@ -250,7 +253,8 @@ public void shouldLogResponse() throws IOException {
                 .assertThat("$.status", is(200))
                 .assertThat("$.headers.*", hasSize(1))
                 .assertThat("$.headers['Date']", is(singletonList("Tue, 15 Nov 1994 08:12:31 GMT")))
-                .assertThat("$.body", is("<success>true<success>"));
+                .assertThat("$.body", is("<success>true<success>"))
+                .assertThat("$.duration", is(125));
     }
 
     @Test
@@ -259,7 +263,7 @@ public void shouldLogResponseWithoutHeaders() throws IOException {
         final HttpRequest request = MockHttpRequest.create();
         final HttpResponse response = create();
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         with(json)
                 .assertThat("$", not(hasKey("headers")));
@@ -273,7 +277,7 @@ public void shouldLogResponseWithoutBody() throws IOException {
         final HttpResponse response = create()
                 .withBodyAsString("");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         with(json)
                 .assertThat("$", not(hasKey("body")));
@@ -287,7 +291,7 @@ public void shouldEmbedJsonResponseBodyAsIs() throws IOException {
                 .withContentType("application/json")
                 .withBodyAsString("{\"name\":\"Bob\"}");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         with(json)
                 .assertThat("$.body.name", is("Bob"));
@@ -301,7 +305,7 @@ public void shouldCompactEmbeddedJsonResponseBody() throws IOException {
                 .withContentType("application/json")
                 .withBodyAsString("{\n  \"name\": \"Bob\"\n}");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         assertThat(json, containsString("{\"name\":\"Bob\"}"));
     }
@@ -314,7 +318,7 @@ public void shouldEmbedCustomJsonResponseBodyAsIs() throws IOException {
                 .withContentType("application/custom+json")
                 .withBodyAsString("{\"name\":\"Bob\"}");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         with(json)
                 .assertThat("$.body.name", is("Bob"));
@@ -328,7 +332,7 @@ public void shouldNotEmbedCustomTextJsonResponseBodyAsIs() throws IOException {
                 .withContentType("text/custom+json")
                 .withBodyAsString("{\"name\":\"Bob\"}");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         with(json)
                 .assertThat("$.body", is("{\"name\":\"Bob\"}"));
@@ -341,7 +345,7 @@ public void shouldEmbedJsonResponseBodyAsNullIfEmpty() throws IOException {
         final HttpResponse response = create()
                 .withContentType("application/json");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         with(json)
                 .assertThat("$.body", is(emptyString()));
@@ -355,7 +359,7 @@ public void shouldLogInvalidJsonResponseBodyAsIs() throws IOException {
                 .withContentType("text/custom+json")
                 .withBodyAsString("{\n \"name\":\"Bob\";;;\n;}");
 
-        final String json = unit.format(new SimpleCorrelation<>(correlationId, request, response));
+        final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
 
         with(json)
                 .assertThat("$.body", is("{\n \"name\":\"Bob\";;;\n;}"));

logbook-core/src/test/java/org/zalando/logbook/StreamHttpLogWriterTest.java

@@ -10,6 +10,7 @@
 import java.io.PrintStream;
 
 import static java.lang.System.lineSeparator;
+import static java.time.Duration.ZERO;
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertThat;
 import static org.mockito.Mockito.mock;
@@ -44,7 +45,7 @@ public void shouldLogResponseToStream() throws IOException {
         final PrintStream stream = mock(PrintStream.class);
         final HttpLogWriter unit = new StreamHttpLogWriter(stream);
 
-        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", "foo", "bar"));
+        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar"));
 
         verify(stream).println("bar");
     }
@@ -62,7 +63,7 @@ public void shouldRequestToStdoutByDefault() throws IOException {
     public void shouldResponseToStdoutByDefault() throws IOException {
         final HttpLogWriter unit = new StreamHttpLogWriter();
 
-        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", "foo", "bar"));
+        unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar"));
 
         assertThat(stdout.getLog(), is("bar" + lineSeparator()));
     }

logbook-httpclient/src/main/java/org/zalando/logbook/httpclient/package-info.java

@@ -0,0 +1,4 @@
+@ParametersAreNonnullByDefault
+package org.zalando.logbook.httpclient;
+
+import javax.annotation.ParametersAreNonnullByDefault;