Skip to content

Commit 1ef5a5f

Browse files
whiskeysierrawhiskeysierra
authored
Merge pull request zalando#167 from zalando/feature/log-based-on-response-status
Added possibility to delay logging of requests until response can be inspected
2 parents 0e6110d + 254ea4e commit 1ef5a5f

12 files changed

+129
-25
lines changed

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

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,4 +12,8 @@ public interface Correlation<Request, Response> {
1212

1313
Response getResponse();
1414

15+
HttpRequest getOriginalRequest();
16+
17+
HttpResponse getOriginalResponse();
18+
1519
}

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

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ public ChunkingHttpLogWriter(final int size, final HttpLogWriter writer) {
2323
if (size <= 0) {
2424
throw new IllegalArgumentException("size is expected to be greater than zero");
2525
}
26-
this.minChunkSize = (size > MIN_MAX_DELTA ? size - MIN_MAX_DELTA : size);
26+
this.minChunkSize = size > MIN_MAX_DELTA ? size - MIN_MAX_DELTA : size;
2727
this.maxChunkSize = size;
2828
this.writer = writer;
2929
}
@@ -42,8 +42,13 @@ public void writeRequest(final Precorrelation<String> precorrelation) throws IOE
4242
@Override
4343
public void writeResponse(final Correlation<String, String> correlation) throws IOException {
4444
split(correlation.getResponse()).forEach(throwing(part ->
45-
writer.writeResponse(new SimpleCorrelation<>(correlation.getId(), correlation.getDuration(),
46-
correlation.getRequest(), part))));
45+
writer.writeResponse(new SimpleCorrelation<>(
46+
correlation.getId(),
47+
correlation.getDuration(),
48+
correlation.getRequest(),
49+
part,
50+
correlation.getOriginalRequest(),
51+
correlation.getOriginalResponse()))));
4752
}
4853

4954
private static <T> Consumer<T> throwing(final ThrowingConsumer<T> consumer) {

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

Lines changed: 18 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -54,9 +54,9 @@ public Optional<Correlator> write(final RawHttpRequest rawHttpRequest) throws IO
5454
final RawHttpResponse filteredRawHttpResponse = rawResponseFilter.filter(rawHttpResponse);
5555
final HttpResponse response = responseFilter.filter(filteredRawHttpResponse.withBody());
5656
final Correlation<HttpRequest, HttpResponse> correlation =
57-
new SimpleCorrelation<>(correlationId, duration, request, response);
57+
new SimpleCorrelation<>(correlationId, duration, request, response, request, response);
5858
final String message = formatter.format(correlation);
59-
writer.writeResponse(new SimpleCorrelation<>(correlationId, duration, format, message));
59+
writer.writeResponse(new SimpleCorrelation<>(correlationId, duration, format, message, request, response));
6060
});
6161
} else {
6262
return Optional.empty();
@@ -91,12 +91,17 @@ static class SimpleCorrelation<I, O> implements Correlation<I, O> {
9191
private final Duration duration;
9292
private final I request;
9393
private final O response;
94+
private final HttpRequest originalRequest;
95+
private final HttpResponse originalResponse;
9496

95-
public SimpleCorrelation(final String id, final Duration duration, final I request, final O response) {
97+
SimpleCorrelation(final String id, final Duration duration, final I request, final O response,
98+
final HttpRequest originalRequest, final HttpResponse originalResponse) {
9699
this.id = id;
97100
this.duration = duration;
98101
this.request = request;
99102
this.response = response;
103+
this.originalRequest = originalRequest;
104+
this.originalResponse = originalResponse;
100105
}
101106

102107
@Override
@@ -119,6 +124,16 @@ public O getResponse() {
119124
return response;
120125
}
121126

127+
@Override
128+
public HttpRequest getOriginalRequest() {
129+
return originalRequest;
130+
}
131+
132+
@Override
133+
public HttpResponse getOriginalResponse() {
134+
return originalResponse;
135+
}
136+
122137
}
123138

124139
}

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -85,7 +85,8 @@ public void shouldCreateWithSizeOfOne() throws IOException {
8585
}
8686

8787
private List<String> captureResponse(final String response) throws IOException {
88-
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("id", ZERO, "", response));
88+
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("id", ZERO, "", response,
89+
MockHttpRequest.create(), MockHttpResponse.create()));
8990

9091
verify(delegate, atLeastOnce()).writeResponse(responseCaptor.capture());
9192

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

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -73,8 +73,11 @@ public void shouldDelegateLogResponse() throws IOException {
7373
final HttpLogFormatter fallback = mock(HttpLogFormatter.class);
7474
final HttpLogFormatter unit = new CurlHttpLogFormatter(fallback);
7575

76+
final MockHttpRequest request = MockHttpRequest.create();
77+
final MockHttpResponse response = MockHttpResponse.create();
78+
7679
final Correlation<HttpRequest, HttpResponse> correlation = new SimpleCorrelation<>(
77-
"3881ae92-6824-11e5-921b-10ddb1ee7671", ZERO, MockHttpRequest.create(), MockHttpResponse.create());
80+
"3881ae92-6824-11e5-921b-10ddb1ee7671", ZERO, request, response, request, response);
7881

7982
unit.format(correlation);
8083

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

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,6 @@
55
import org.zalando.logbook.DefaultLogbook.SimplePrecorrelation;
66

77
import java.io.IOException;
8-
import java.time.Duration;
98

109
import static java.time.Duration.ofMillis;
1110
import static org.hamcrest.Matchers.is;
@@ -84,7 +83,8 @@ public void shouldLogResponse() throws IOException {
8483
.withHeaders(MockHeaders.of("Content-Type", "application/json"))
8584
.withBodyAsString("{\"success\":true}");
8685

87-
final String http = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(125), request, response));
86+
final String http = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(125), request, response,
87+
request, response));
8888

8989
assertThat(http, is("Incoming Response: 2d51bc02-677e-11e5-8b9b-10ddb1ee7671\n" +
9090
"Duration: 125 ms\n" +
@@ -103,7 +103,8 @@ public void shouldLogResponseWithoutBody() throws IOException {
103103
.withStatus(400)
104104
.withHeaders(MockHeaders.of("Content-Type", "application/json"));
105105

106-
final String http = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(100), request, response));
106+
final String http = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(100), request, response,
107+
request, response));
107108

108109
assertThat(http, is("Outgoing Response: 3881ae92-6824-11e5-921b-10ddb1ee7671\n" +
109110
"Duration: 100 ms\n" +

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -68,7 +68,8 @@ public void shouldLogRequestWithCorrectLevel() throws IOException {
6868

6969
@Test
7070
public void shouldLogResponseWithCorrectLevel() throws IOException {
71-
unit.writeResponse(new SimpleCorrelation<>("1", ZERO, "foo", "bar"));
71+
unit.writeResponse(new SimpleCorrelation<>("1", ZERO, "foo", "bar",
72+
MockHttpRequest.create(), MockHttpResponse.create()));
7273

7374
log.accept(verify(logger), "bar");
7475
}

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -48,7 +48,8 @@ public void shouldDefaultToTraceLevelForLoggingResponses() throws IOException {
4848
final Logger logger = mock(Logger.class);
4949
final HttpLogWriter unit = new DefaultHttpLogWriter(logger);
5050

51-
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar"));
51+
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar",
52+
MockHttpRequest.create(), MockHttpResponse.create()));
5253

5354
verify(logger).trace("bar");
5455
}

‎logbook-core/src/test/java/org/zalando/logbook/DelayedResponseLogWriter.java

Lines changed: 32 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,32 @@
1+
package org.zalando.logbook;
2+
3+
import org.zalando.logbook.DefaultLogbook.SimplePrecorrelation;
4+
5+
import java.io.IOException;
6+
7+
// proof of concept
8+
final class DelayedResponseLogWriter implements HttpLogWriter {
9+
10+
private final HttpLogWriter delegate;
11+
12+
DelayedResponseLogWriter(final HttpLogWriter delegate) {
13+
this.delegate = delegate;
14+
}
15+
16+
@Override
17+
public void writeRequest(final Precorrelation<String> precorrelation) throws IOException {
18+
// do nothing
19+
}
20+
21+
@Override
22+
public void writeResponse(final Correlation<String, String> correlation) throws IOException {
23+
final HttpResponse response = correlation.getOriginalResponse();
24+
25+
if (response.getStatus() >= 400) {
26+
// delayed request logging until we have the response at hand
27+
delegate.writeRequest(new SimplePrecorrelation<>(correlation.getId(), correlation.getRequest()));
28+
delegate.writeResponse(correlation);
29+
}
30+
}
31+
32+
}

‎logbook-core/src/test/java/org/zalando/logbook/DelayedResponseLogWriterTest.java

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
package org.zalando.logbook;
2+
3+
import org.junit.Test;
4+
import org.mockito.Mockito;
5+
6+
import java.io.IOException;
7+
8+
import static org.mockito.ArgumentMatchers.any;
9+
import static org.mockito.Mockito.never;
10+
import static org.mockito.Mockito.verify;
11+
12+
public final class DelayedResponseLogWriterTest {
13+
14+
private final HttpLogWriter delegate = Mockito.mock(HttpLogWriter.class);
15+
private final HttpLogWriter unit = new DelayedResponseLogWriter(delegate);
16+
17+
@Test
18+
public void shouldDelayRequestLogging() throws IOException {
19+
final Logbook logbook = Logbook.builder().writer(unit).build();
20+
21+
final Correlator correlator = logbook.write(MockRawHttpRequest.create()).orElseThrow(AssertionError::new);
22+
23+
verify(delegate, never()).writeRequest(any());
24+
25+
correlator.write(MockRawHttpResponse.create().withStatus(404));
26+
27+
verify(delegate).writeRequest(any());
28+
verify(delegate).writeResponse(any());
29+
}
30+
31+
}

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

Lines changed: 18 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,6 @@
55
import org.zalando.logbook.DefaultLogbook.SimplePrecorrelation;
66

77
import java.io.IOException;
8-
import java.time.Duration;
98

109
import static com.jayway.jsonassert.JsonAssert.with;
1110
import static java.time.Duration.ZERO;
@@ -243,7 +242,8 @@ public void shouldLogResponse() throws IOException {
243242
.withContentType("application/xml")
244243
.withBodyAsString("<success>true<success>");
245244

246-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(125), request, response));
245+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ofMillis(125), request, response,
246+
request, response));
247247

248248
with(json)
249249
.assertThat("$.origin", is("local"))
@@ -263,7 +263,8 @@ public void shouldLogResponseWithoutHeaders() throws IOException {
263263
final HttpRequest request = MockHttpRequest.create();
264264
final HttpResponse response = create();
265265

266-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
266+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response,
267+
request, response));
267268

268269
with(json)
269270
.assertThat("$", not(hasKey("headers")));
@@ -277,7 +278,8 @@ public void shouldLogResponseWithoutBody() throws IOException {
277278
final HttpResponse response = create()
278279
.withBodyAsString("");
279280

280-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
281+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response, request,
282+
response));
281283

282284
with(json)
283285
.assertThat("$", not(hasKey("body")));
@@ -291,7 +293,8 @@ public void shouldEmbedJsonResponseBodyAsIs() throws IOException {
291293
.withContentType("application/json")
292294
.withBodyAsString("{\"name\":\"Bob\"}");
293295

294-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
296+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response,
297+
request, response));
295298

296299
with(json)
297300
.assertThat("$.body.name", is("Bob"));
@@ -305,7 +308,8 @@ public void shouldCompactEmbeddedJsonResponseBody() throws IOException {
305308
.withContentType("application/json")
306309
.withBodyAsString("{\n \"name\": \"Bob\"\n}");
307310

308-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
311+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response, request,
312+
response));
309313

310314
assertThat(json, containsString("{\"name\":\"Bob\"}"));
311315
}
@@ -318,7 +322,8 @@ public void shouldEmbedCustomJsonResponseBodyAsIs() throws IOException {
318322
.withContentType("application/custom+json")
319323
.withBodyAsString("{\"name\":\"Bob\"}");
320324

321-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
325+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response, request,
326+
response));
322327

323328
with(json)
324329
.assertThat("$.body.name", is("Bob"));
@@ -332,7 +337,8 @@ public void shouldNotEmbedCustomTextJsonResponseBodyAsIs() throws IOException {
332337
.withContentType("text/custom+json")
333338
.withBodyAsString("{\"name\":\"Bob\"}");
334339

335-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
340+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response, request,
341+
response));
336342

337343
with(json)
338344
.assertThat("$.body", is("{\"name\":\"Bob\"}"));
@@ -345,7 +351,8 @@ public void shouldEmbedJsonResponseBodyAsNullIfEmpty() throws IOException {
345351
final HttpResponse response = create()
346352
.withContentType("application/json");
347353

348-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
354+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response, request,
355+
response));
349356

350357
with(json)
351358
.assertThat("$.body", is(emptyString()));
@@ -359,7 +366,8 @@ public void shouldLogInvalidJsonResponseBodyAsIs() throws IOException {
359366
.withContentType("text/custom+json")
360367
.withBodyAsString("{\n \"name\":\"Bob\";;;\n;}");
361368

362-
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response));
369+
final String json = unit.format(new SimpleCorrelation<>(correlationId, ZERO, request, response, request,
370+
response));
363371

364372
with(json)
365373
.assertThat("$.body", is("{\n \"name\":\"Bob\";;;\n;}"));

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

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,8 @@ public void shouldLogResponseToStream() throws IOException {
4545
final PrintStream stream = mock(PrintStream.class);
4646
final HttpLogWriter unit = new StreamHttpLogWriter(stream);
4747

48-
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar"));
48+
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar", MockHttpRequest.create(),
49+
MockHttpResponse.create()));
4950

5051
verify(stream).println("bar");
5152
}
@@ -63,7 +64,8 @@ public void shouldRequestToStdoutByDefault() throws IOException {
6364
public void shouldResponseToStdoutByDefault() throws IOException {
6465
final HttpLogWriter unit = new StreamHttpLogWriter();
6566

66-
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar"));
67+
unit.writeResponse(new DefaultLogbook.SimpleCorrelation<>("1", ZERO, "foo", "bar", MockHttpRequest.create(),
68+
MockHttpResponse.create()));
6769

6870
assertThat(stdout.getLog(), is("bar" + lineSeparator()));
6971
}

0 commit comments

Comments
 (0)