From 584b156b65d7c417d7027b9d5da001b3f04c13aa Mon Sep 17 00:00:00 2001 From: Nic Munroe Date: Mon, 12 Feb 2018 14:24:28 -0800 Subject: [PATCH 1/3] Allow for nanosecond precision total-request-time and time-spent-waiting-for-payload-chunks values Also set response end time on the HTTP processing state so that numbers are consistent across different areas of code like access logger and metrics --- .../server/handler/AccessLogEndHandler.java | 14 +++-- .../server/handler/AccessLogStartHandler.java | 20 ++++++- .../server/http/HttpProcessingState.java | 58 +++++++++++++++++++ .../riposte/server/http/ResponseSender.java | 24 +++++--- .../handler/AccessLogEndHandlerSpec.groovy | 8 ++- .../handler/AccessLogStartHandlerSpec.groovy | 27 ++++++++- .../codahale/CodahaleMetricsListener.java | 21 ++++--- .../codahale/CodahaleMetricsListenerTest.java | 40 +++++++------ 8 files changed, 162 insertions(+), 50 deletions(-) diff --git a/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogEndHandler.java b/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogEndHandler.java index 3d23fd6d..2863be46 100644 --- a/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogEndHandler.java +++ b/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogEndHandler.java @@ -13,8 +13,6 @@ import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import java.time.Instant; - import io.netty.channel.ChannelFutureListener; import io.netty.channel.ChannelHandlerContext; import io.netty.handler.codec.http.HttpResponse; @@ -57,7 +55,13 @@ protected void doAccessLogging(ChannelHandlerContext ctx) throws Exception { // Due to multiple messages and exception possibilities/interactions it's possible we've already done the access // logging for this request, so make sure we only do it if appropriate if (httpProcessingState != null && !httpProcessingState.isAccessLogCompletedOrScheduled()) { - Instant startTime = httpProcessingState.getRequestStartTime(); + httpProcessingState.setAccessLogCompletedOrScheduled(true); + + // Response end time should already be set by now under normal circumstances, + // but just in case it hasn't (i.e. exception corner cases)... + httpProcessingState.setResponseEndTimeNanosToNowIfNotAlreadySet(); + + // Gather the remaining bits needed to execute the access logger. ResponseInfo responseInfo = httpProcessingState.getResponseInfo(); HttpResponse actualResponseObject = httpProcessingState.getActualResponseObject(); RequestInfo requestInfo = httpProcessingState.getRequestInfo(); @@ -65,7 +69,7 @@ protected void doAccessLogging(ChannelHandlerContext ctx) throws Exception { ChannelFutureListener doTheAccessLoggingOperation = new ChannelFutureListenerWithTracingAndMdc( (channelFuture) -> accessLogger.log( requestInfo, actualResponseObject, responseInfo, - Instant.now().minusMillis(startTime.toEpochMilli()).toEpochMilli() + httpProcessingState.calculateTotalRequestTimeMillis() ), ctx ); @@ -76,8 +80,6 @@ protected void doAccessLogging(ChannelHandlerContext ctx) throws Exception { doTheAccessLoggingOperation.operationComplete(null); else httpProcessingState.getResponseWriterFinalChunkChannelFuture().addListener(doTheAccessLoggingOperation); - - httpProcessingState.setAccessLogCompletedOrScheduled(true); } } diff --git a/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogStartHandler.java b/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogStartHandler.java index 25996805..47b5f618 100644 --- a/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogStartHandler.java +++ b/riposte-core/src/main/java/com/nike/riposte/server/handler/AccessLogStartHandler.java @@ -12,6 +12,7 @@ import io.netty.channel.ChannelHandlerContext; import io.netty.handler.codec.http.HttpRequest; +import io.netty.handler.codec.http.LastHttpContent; import static com.nike.riposte.util.AsyncNettyHelper.runnableWithTracingAndMdc; @@ -33,15 +34,30 @@ public class AccessLogStartHandler extends BaseInboundHandlerWithTracingAndMdcSu private final Logger logger = LoggerFactory.getLogger(this.getClass()); @Override - public PipelineContinuationBehavior doChannelRead(ChannelHandlerContext ctx, Object msg) throws Exception { + public PipelineContinuationBehavior doChannelRead(ChannelHandlerContext ctx, Object msg) { if (msg instanceof HttpRequest) { HttpProcessingState httpProcessingState = ChannelAttributes.getHttpProcessingStateForChannel(ctx).get(); if (httpProcessingState != null) { httpProcessingState.setRequestStartTime(Instant.now()); + httpProcessingState.setRequestStartTimeNanos(System.nanoTime()); } else { runnableWithTracingAndMdc( - () -> logger.warn("HttpProcessingState is null. This shouldn't happen."), ctx + () -> logger.warn("HttpProcessingState is null reading HttpRequest. This shouldn't happen."), + ctx + ).run(); + } + } + + if (msg instanceof LastHttpContent) { + HttpProcessingState httpProcessingState = ChannelAttributes.getHttpProcessingStateForChannel(ctx).get(); + if (httpProcessingState != null) { + httpProcessingState.setRequestLastChunkArrivedTimeNanos(System.nanoTime()); + } + else { + runnableWithTracingAndMdc( + () -> logger.warn("HttpProcessingState is null reading LastHttpContent. This shouldn't happen."), + ctx ).run(); } } diff --git a/riposte-core/src/main/java/com/nike/riposte/server/http/HttpProcessingState.java b/riposte-core/src/main/java/com/nike/riposte/server/http/HttpProcessingState.java index b93ddc56..eef84498 100644 --- a/riposte-core/src/main/java/com/nike/riposte/server/http/HttpProcessingState.java +++ b/riposte-core/src/main/java/com/nike/riposte/server/http/HttpProcessingState.java @@ -6,6 +6,7 @@ import java.util.Deque; import java.util.Map; import java.util.concurrent.CompletableFuture; +import java.util.concurrent.TimeUnit; import java.util.function.Function; import io.netty.channel.ChannelFuture; @@ -30,6 +31,9 @@ public class HttpProcessingState implements ProcessingState { private Deque distributedTraceStack; private Map loggerMdcContextMap; private Instant requestStartTime; + private Long requestStartTimeNanos; + private Long requestLastChunkArrivedTimeNanos; + private Long responseEndTimeNanos; private ChannelFuture responseWriterFinalChunkChannelFuture; private boolean traceCompletedOrScheduled = false; private boolean accessLogCompletedOrScheduled = false; @@ -49,6 +53,9 @@ public HttpProcessingState(HttpProcessingState copyMe) { this.distributedTraceStack = copyMe.getDistributedTraceStack(); this.loggerMdcContextMap = copyMe.getLoggerMdcContextMap(); this.requestStartTime = copyMe.getRequestStartTime(); + this.requestStartTimeNanos = copyMe.getRequestStartTimeNanos(); + this.requestLastChunkArrivedTimeNanos = copyMe.getRequestLastChunkArrivedTimeNanos(); + this.responseEndTimeNanos = copyMe.getResponseEndTimeNanos(); this.responseWriterFinalChunkChannelFuture = copyMe.getResponseWriterFinalChunkChannelFuture(); this.traceCompletedOrScheduled = copyMe.isTraceCompletedOrScheduled(); this.accessLogCompletedOrScheduled = copyMe.isAccessLogCompletedOrScheduled(); @@ -68,6 +75,9 @@ public void cleanStateForNewRequest() { distributedTraceStack = null; loggerMdcContextMap = null; requestStartTime = null; + requestStartTimeNanos = null; + requestLastChunkArrivedTimeNanos = null; + responseEndTimeNanos = null; responseWriterFinalChunkChannelFuture = null; traceCompletedOrScheduled = false; accessLogCompletedOrScheduled = false; @@ -148,6 +158,54 @@ public void setRequestStartTime(Instant requestStartTime) { this.requestStartTime = requestStartTime; } + public Long getRequestStartTimeNanos() { + return requestStartTimeNanos; + } + + public void setRequestStartTimeNanos(Long requestStartTimeNanos) { + this.requestStartTimeNanos = requestStartTimeNanos; + } + + public Long getRequestLastChunkArrivedTimeNanos() { + return requestLastChunkArrivedTimeNanos; + } + + public void setRequestLastChunkArrivedTimeNanos(Long requestLastChunkArrivedTimeNanos) { + this.requestLastChunkArrivedTimeNanos = requestLastChunkArrivedTimeNanos; + } + + public Long getResponseEndTimeNanos() { + return responseEndTimeNanos; + } + + public void setResponseEndTimeNanosToNowIfNotAlreadySet() { + // Only the first piece of code that recognizes that the response is done gets to set response end time. + if (this.responseEndTimeNanos == null) { + this.responseEndTimeNanos = System.nanoTime(); + } + } + + /** + * @return Convenience method that returns the total time this request took from beginning to end-of-response-sent + * in milliseconds, or null if {@link #getRequestStartTimeNanos()} or {@link #getResponseEndTimeNanos()} is null. + * This method uses {@link TimeUnit#NANOSECONDS} {@link TimeUnit#toMillis(long)} to convert nanoseconds to + * milliseconds, so any nanosecond remainder will be chopped (i.e. 1_999_999 nanoseconds will convert to 1 + * millisecond - the 0.999999 milliseconds worth of nanosecond-remainder is dropped). + * + *

If you need greater precision than milliseconds you can refer to {@link #getRequestStartTimeNanos()} + * (and/or {@link #getRequestLastChunkArrivedTimeNanos()}) and {@link #getResponseEndTimeNanos()} for nanosecond + * precision, although you'll need to do the math yourself and you'll need to keep in mind that the values are only + * useful in relation to each other - they are not timestamps. For a timestamp you can refer to {@link + * #getRequestStartTime()} which returns an {@link Instant}. + */ + public Long calculateTotalRequestTimeMillis() { + if (requestStartTimeNanos == null || responseEndTimeNanos == null) { + return null; + } + + return TimeUnit.NANOSECONDS.toMillis(responseEndTimeNanos - requestStartTimeNanos); + } + public ChannelFuture getResponseWriterFinalChunkChannelFuture() { return responseWriterFinalChunkChannelFuture; } diff --git a/riposte-core/src/main/java/com/nike/riposte/server/http/ResponseSender.java b/riposte-core/src/main/java/com/nike/riposte/server/http/ResponseSender.java index b7cd5a9c..734ed4d6 100644 --- a/riposte-core/src/main/java/com/nike/riposte/server/http/ResponseSender.java +++ b/riposte-core/src/main/java/com/nike/riposte/server/http/ResponseSender.java @@ -1,7 +1,5 @@ package com.nike.riposte.server.http; -import com.fasterxml.jackson.core.JsonProcessingException; -import com.fasterxml.jackson.databind.ObjectMapper; import com.nike.riposte.server.channelpipeline.ChannelAttributes; import com.nike.riposte.server.channelpipeline.message.ChunkedOutboundMessage; import com.nike.riposte.server.channelpipeline.message.OutboundMessageSendContentChunk; @@ -14,6 +12,18 @@ import com.nike.wingtips.TraceAndSpanIdGenerator; import com.nike.wingtips.TraceHeaders; import com.nike.wingtips.Tracer; + +import com.fasterxml.jackson.core.JsonProcessingException; +import com.fasterxml.jackson.databind.ObjectMapper; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.nio.charset.Charset; +import java.util.Set; +import java.util.UUID; +import java.util.function.Consumer; + import io.netty.buffer.ByteBuf; import io.netty.buffer.Unpooled; import io.netty.channel.ChannelFuture; @@ -30,13 +40,6 @@ import io.netty.handler.codec.http.LastHttpContent; import io.netty.handler.codec.http.cookie.Cookie; import io.netty.handler.codec.http.cookie.ServerCookieEncoder; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; - -import java.nio.charset.Charset; -import java.util.Set; -import java.util.UUID; -import java.util.function.Consumer; import static com.nike.riposte.util.AsyncNettyHelper.consumerWithTracingAndMdc; import static com.nike.riposte.util.AsyncNettyHelper.runnableWithTracingAndMdc; @@ -513,6 +516,9 @@ else if (chunkToWrite instanceof HttpContent) if (state != null && isLastChunk) { // Set the state's responseWriterFinalChunkChannelFuture so that handlers can hook into it if desired. state.setResponseWriterFinalChunkChannelFuture(writeFuture); + + // Always attach a listener that sets response end time. + writeFuture.addListener(future -> state.setResponseEndTimeNanosToNowIfNotAlreadySet()); } // Always attach a listener that logs write errors. diff --git a/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogEndHandlerSpec.groovy b/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogEndHandlerSpec.groovy index 30fe2378..0b043579 100644 --- a/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogEndHandlerSpec.groovy +++ b/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogEndHandlerSpec.groovy @@ -47,7 +47,7 @@ class AccessLogEndHandlerSpec extends Specification { logger.clearAll() HttpProcessingState state = Mock(HttpProcessingState) - state.getRequestStartTime() >> Instant.EPOCH + state.calculateTotalRequestTimeMillis() >> 42 state.getResponseInfo() >> Mock(ResponseInfo) ChannelAttributes.getHttpProcessingStateForChannel(_) >> state ChannelHandlerContext mockContext = Mock(ChannelHandlerContext) @@ -72,6 +72,8 @@ class AccessLogEndHandlerSpec extends Specification { def (ChannelHandlerContext mockContext, HttpProcessingState state) = mockContext() ChannelFuture channelFutureMock = Mock(ChannelFuture) RequestInfo requestInfoMock = Mock(RequestInfo) + Long expectedElapsedTimeMillis = state.calculateTotalRequestTimeMillis() + assert expectedElapsedTimeMillis != null state.getResponseWriterFinalChunkChannelFuture() >> channelFutureMock state.isResponseSent() >> true state.getRequestInfo() >> requestInfoMock @@ -89,7 +91,7 @@ class AccessLogEndHandlerSpec extends Specification { HttpResponse actualResponseObjectMock = state.getActualResponseObject() ResponseInfo responseInfoMock = state.getResponseInfo() boolean accessLoggerCalled = false - accessLogger.log(_ as RequestInfo, actualResponseObjectMock, responseInfoMock, _ as Long) >> { + accessLogger.log(_ as RequestInfo, actualResponseObjectMock, responseInfoMock, expectedElapsedTimeMillis) >> { accessLoggerCalled = true return null } @@ -105,7 +107,7 @@ class AccessLogEndHandlerSpec extends Specification { protected List mockContext() { HttpProcessingState state = Mock(HttpProcessingState) - state.getRequestStartTime() >> Instant.EPOCH + state.calculateTotalRequestTimeMillis() >> 42 state.getResponseInfo() >> Mock(ResponseInfo) state.getActualResponseObject() >> Mock(HttpResponse) ChannelAttributes.getHttpProcessingStateForChannel(_) >> state diff --git a/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogStartHandlerSpec.groovy b/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogStartHandlerSpec.groovy index 3adf3e0d..474fff7e 100644 --- a/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogStartHandlerSpec.groovy +++ b/riposte-core/src/test/groovy/com/nike/riposte/server/handler/AccessLogStartHandlerSpec.groovy @@ -6,9 +6,11 @@ import com.nike.riposte.server.http.HttpProcessingState import io.netty.channel.Channel import io.netty.channel.ChannelHandlerContext import io.netty.handler.codec.http.HttpRequest +import io.netty.handler.codec.http.LastHttpContent import io.netty.util.Attribute import io.netty.util.AttributeKey import spock.lang.Specification +import spock.lang.Unroll import uk.org.lidalia.slf4jext.Level import uk.org.lidalia.slf4jtest.TestLogger import uk.org.lidalia.slf4jtest.TestLoggerFactory @@ -32,14 +34,30 @@ class AccessLogStartHandlerSpec extends Specification { given: "an AccessLogStartHandler" AccessLogStartHandler handler = new AccessLogStartHandler() def (ChannelHandlerContext mockContext, HttpProcessingState state) = mockContext() + assert state.getRequestStartTime() == null + assert state.getRequestStartTimeNanos() == null when: "we call doChannelRead()" PipelineContinuationBehavior response = handler.doChannelRead(mockContext, Mock(HttpRequest)) then: response == PipelineContinuationBehavior.CONTINUE - state.getRequestStartTime().class == Instant + state.getRequestStartTime() != null + state.getRequestStartTimeNanos() != null } - def "doChannelRead() - null HttpProcessingState"() { + def "doChannelRead() - message is LastHttpContent"() { + given: "an AccessLogStartHandler" + AccessLogStartHandler handler = new AccessLogStartHandler() + def (ChannelHandlerContext mockContext, HttpProcessingState state) = mockContext() + assert state.getRequestLastChunkArrivedTimeNanos() == null + when: "we call doChannelRead()" + PipelineContinuationBehavior response = handler.doChannelRead(mockContext, Mock(LastHttpContent)) + then: + response == PipelineContinuationBehavior.CONTINUE + state.getRequestLastChunkArrivedTimeNanos() != null + } + + @Unroll + def "doChannelRead() - null HttpProcessingState - message type: #message"(Object message) { given: "an AccessLogStartHandler" AccessLogStartHandler handler = new AccessLogStartHandler() HttpProcessingState state = new HttpProcessingState() @@ -55,12 +73,15 @@ class AccessLogStartHandlerSpec extends Specification { mockContext.channel() >> mockChannel when: "we call doChannelRead()" - PipelineContinuationBehavior response = handler.doChannelRead(mockContext, Mock(HttpRequest)) + PipelineContinuationBehavior response = handler.doChannelRead(mockContext, message) then: response == PipelineContinuationBehavior.CONTINUE logger.getAllLoggingEvents().size() == 1 logger.getAllLoggingEvents().get(0).level == Level.WARN logger.getAllLoggingEvents().get(0).message.contains("HttpProcessingState is null") + + where: + message << [Mock(HttpRequest), Mock(LastHttpContent)] } protected List mockContext() { diff --git a/riposte-metrics-codahale/src/main/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListener.java b/riposte-metrics-codahale/src/main/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListener.java index 3b31835d..34e2f4c0 100644 --- a/riposte-metrics-codahale/src/main/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListener.java +++ b/riposte-metrics-codahale/src/main/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListener.java @@ -22,7 +22,6 @@ import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import java.time.Instant; import java.util.List; import java.util.function.Supplier; import java.util.stream.Collectors; @@ -291,19 +290,25 @@ else if (ServerMetricsEvent.RESPONSE_SENT.equals(event)) { logger.error("Metrics Error: httpState.getResponseInfo() is null"); return; } - if (httpState.getRequestStartTime() == null) { - logger.error("Metrics Error: httpState.getRequestStartTime() is null"); + + // Response end time should already be set by now, but just in case it hasn't (i.e. due to an exception + // preventing any response from being sent)... + httpState.setResponseEndTimeNanosToNowIfNotAlreadySet(); + Long requestElapsedTimeMillis = httpState.calculateTotalRequestTimeMillis(); + if (requestElapsedTimeMillis == null) { + // This should only happen if httpState.getRequestStartTimeNanos() is null, + // which means AccessLogStartHandler never executed for a Netty HttpRequest message. Something + // went really wrong with this request. + logger.error( + "Metrics Error: httpState.calculateTotalRequestTimeMillis() is null. " + + "httpState.getRequestStartTimeNanos(): " + httpState.getRequestStartTimeNanos() + ); return; } final int responseHttpStatusCode = responseInfo.getHttpStatusCodeWithDefault(ResponseSender.DEFAULT_HTTP_STATUS_CODE); final int responseHttpStatusCodeXXValue = responseHttpStatusCode / 100; - // TODO: We (maybe) shouldn't calculate the elapsed time here (?) - - // there should (maybe) be a listener that gets executed when the response finishes - // and updates the HTTP state with a new requestEndTime variable. - final long requestElapsedTimeMillis = - Instant.now().toEpochMilli() - httpState.getRequestStartTime().toEpochMilli(); endpointMetricsHandler.handleRequest( requestInfo, responseInfo, httpState, responseHttpStatusCode, responseHttpStatusCodeXXValue, diff --git a/riposte-metrics-codahale/src/test/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListenerTest.java b/riposte-metrics-codahale/src/test/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListenerTest.java index 5f5cfdf0..0ded8bdb 100644 --- a/riposte-metrics-codahale/src/test/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListenerTest.java +++ b/riposte-metrics-codahale/src/test/java/com/nike/riposte/metrics/codahale/CodahaleMetricsListenerTest.java @@ -33,8 +33,6 @@ import org.mockito.internal.util.reflection.Whitebox; import org.slf4j.Logger; -import java.time.Instant; -import java.time.temporal.ChronoUnit; import java.util.Arrays; import java.util.Collection; import java.util.HashMap; @@ -43,6 +41,7 @@ import java.util.UUID; import java.util.concurrent.CompletableFuture; import java.util.concurrent.Executor; +import java.util.concurrent.TimeUnit; import java.util.function.Supplier; import java.util.stream.Collectors; @@ -53,6 +52,7 @@ import static com.nike.riposte.metrics.codahale.CodahaleMetricsListener.DEFAULT_REQUEST_AND_RESPONSE_SIZE_HISTOGRAM_SUPPLIER; import static com.nike.riposte.metrics.codahale.CodahaleMetricsListener.DefaultMetricNamingStrategy.DEFAULT_PREFIX; import static com.nike.riposte.metrics.codahale.CodahaleMetricsListener.DefaultMetricNamingStrategy.DEFAULT_WORD_DELIMITER; +import static java.util.concurrent.TimeUnit.NANOSECONDS; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.catchThrowable; import static org.mockito.Matchers.any; @@ -98,7 +98,7 @@ public class CodahaleMetricsListenerTest { private RequestInfo requestInfoMock; private ResponseInfo responseInfoMock; - private Instant requestStartTime; + private long requestStartTimeNanos; @Before public void beforeMethod() { @@ -146,8 +146,8 @@ public int maxRequestSizeInBytes() { state.setRequestInfo(requestInfoMock); state.setResponseInfo(responseInfoMock); - requestStartTime = Instant.now().minus(42, ChronoUnit.MILLIS); - state.setRequestStartTime(requestStartTime); + requestStartTimeNanos = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(42); + state.setRequestStartTimeNanos(requestStartTimeNanos); } private void setupMetricRegistryAndCodahaleMetricsCollector() { @@ -563,9 +563,9 @@ public void onEvent_works_as_expected_for_RESPONSE_SENT_with_endpoint( Thread.sleep((long)(Math.random() * 25)); // when - long beforeCallTime = System.currentTimeMillis(); + long beforeCallTimeNanos = System.nanoTime(); listener.onEvent(event, state); - long afterCallTime = System.currentTimeMillis(); + long afterCallTimeNanos = System.nanoTime(); // then // Inflight requests counter decremented @@ -581,17 +581,18 @@ public void onEvent_works_as_expected_for_RESPONSE_SENT_with_endpoint( verify(listener.requestSizes).update(requestRawContentLengthBytes); verify(listener.responseSizes).update(finalResponseContentLength); + // Response end time should be set correctly + assertThat(state.getResponseEndTimeNanos()).isBetween(beforeCallTimeNanos, afterCallTimeNanos); + // The EndpointMetricsHandler should have been notified int responseHttpStatusCodeXXValue = responseStatusCode / 100; - long expectedElapsedTimeMillisLowerBound = beforeCallTime - requestStartTime.toEpochMilli(); - long expectedElapsedTimeMillisUpperBound = afterCallTime - requestStartTime.toEpochMilli(); ArgumentCaptor elapsedTimeMillisArgCaptor = ArgumentCaptor.forClass(Long.class); verify(endpointMetricsHandlerMock).handleRequest( eq(requestInfoMock), eq(responseInfoMock), eq(state), eq(responseStatusCode), eq(responseHttpStatusCodeXXValue), elapsedTimeMillisArgCaptor.capture() ); - assertThat(elapsedTimeMillisArgCaptor.getValue()) - .isBetween(expectedElapsedTimeMillisLowerBound, expectedElapsedTimeMillisUpperBound); + long expectedElapsedTimeNanos = state.getResponseEndTimeNanos() - state.getRequestStartTimeNanos(); + assertThat(elapsedTimeMillisArgCaptor.getValue()).isEqualTo(NANOSECONDS.toMillis(expectedElapsedTimeNanos)); } @DataProvider(value = { @@ -618,9 +619,9 @@ public void onEvent_works_as_expected_for_RESPONSE_SENT_without_endpoint(int res doReturn(finalResponseContentLength).when(responseInfoMock).getFinalContentLength(); // when - long beforeCallTime = System.currentTimeMillis(); + long beforeCallTimeNanos = System.nanoTime(); listener.onEvent(event, state); - long afterCallTime = System.currentTimeMillis(); + long afterCallTimeNanos = System.nanoTime(); // then // Inflight requests counter decremented @@ -636,17 +637,18 @@ public void onEvent_works_as_expected_for_RESPONSE_SENT_without_endpoint(int res verify(listener.requestSizes).update(requestRawContentLengthBytes); verify(listener.responseSizes).update(finalResponseContentLength); + // Response end time should be set correctly + assertThat(state.getResponseEndTimeNanos()).isBetween(beforeCallTimeNanos, afterCallTimeNanos); + // The EndpointMetricsHandler should have been notified int responseHttpStatusCodeXXValue = responseStatusCode / 100; - long expectedElapsedTimeMillisLowerBound = beforeCallTime - requestStartTime.toEpochMilli(); - long expectedElapsedTimeMillisUpperBound = afterCallTime - requestStartTime.toEpochMilli(); ArgumentCaptor elapsedTimeMillisArgCaptor = ArgumentCaptor.forClass(Long.class); verify(endpointMetricsHandlerMock).handleRequest( eq(requestInfoMock), eq(responseInfoMock), eq(state), eq(responseStatusCode), eq(responseHttpStatusCodeXXValue), elapsedTimeMillisArgCaptor.capture() ); - assertThat(elapsedTimeMillisArgCaptor.getValue()) - .isBetween(expectedElapsedTimeMillisLowerBound, expectedElapsedTimeMillisUpperBound); + long expectedElapsedTimeNanos = state.getResponseEndTimeNanos() - state.getRequestStartTimeNanos(); + assertThat(elapsedTimeMillisArgCaptor.getValue()).isEqualTo(NANOSECONDS.toMillis(expectedElapsedTimeNanos)); } @Test @@ -700,9 +702,9 @@ public void onEvent_should_short_circuit_for_RESPONSE_SENT_if_response_info_is_n } @Test - public void onEvent_should_short_circuit_for_RESPONSE_SENT_if_request_start_time_is_null() { + public void onEvent_should_short_circuit_for_RESPONSE_SENT_if_request_start_time_nanos_is_null() { // given - state.setRequestStartTime(null); + state.setRequestStartTimeNanos(null); // when listener.onEvent(ServerMetricsEvent.RESPONSE_SENT, state); From 79a16d8a34b4dbd2796ee9be83b6d7ecf3c795f0 Mon Sep 17 00:00:00 2001 From: Nic Munroe Date: Mon, 12 Feb 2018 14:30:12 -0800 Subject: [PATCH 2/3] Remove span name from access logger default output --- .../riposte/server/logging/AccessLogger.java | 1 - .../server/logging/AccessLoggerSpec.groovy | 21 +++++++++---------- 2 files changed, 10 insertions(+), 12 deletions(-) diff --git a/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java b/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java index 6a29ede0..35b1b5b3 100644 --- a/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java +++ b/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java @@ -419,7 +419,6 @@ else if (responseInfo != null) Pair.of("error_uid-Res", errorUid), Pair.of(TRACE_ENABLED + "-Req", request.getHeaders().get(TRACE_ENABLED)), Pair.of(SPAN_ID + "-Req", request.getHeaders().get(SPAN_ID)), - Pair.of(SPAN_NAME + "-Req", request.getHeaders().get(SPAN_NAME)), Pair.of(TRACE_ID + "-Req", request.getHeaders().get(TRACE_ID)), Pair.of(TRACE_ID + "-Res", responseTraceId), Pair.of("raw_content_length-Req", String.valueOf(request.getRawContentLengthInBytes())), diff --git a/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy b/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy index 3a748bbc..4b5ba19a 100644 --- a/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy +++ b/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy @@ -43,7 +43,7 @@ class AccessLoggerSpec extends Specification { then: logger.getAllLoggingEvents().size() == 1 logger.getAllLoggingEvents().get(0).level == Level.INFO - logger.getAllLoggingEvents().get(0).message.contains("\"GET /test HTTP/1.1\" 210 20 \"myReferer\" \"myUserAgent\" accept-Req=- content-type-Req=- content-length-Res=- transfer_encoding-Res=- http_status_code-Res=210 error_uid-Res=- X-B3-Sampled-Req=- X-B3-SpanId-Req=- X-B3-SpanName-Req=- X-B3-TraceId-Req=- X-B3-TraceId-Res=- raw_content_length-Req=19 raw_content_length-Res=21 final_content_length-Res=20 elapsed_time_millis=20") + logger.getAllLoggingEvents().get(0).message.contains("\"GET /test HTTP/1.1\" 210 20 \"myReferer\" \"myUserAgent\" accept-Req=- content-type-Req=- content-length-Res=- transfer_encoding-Res=- http_status_code-Res=210 error_uid-Res=- X-B3-Sampled-Req=- X-B3-SpanId-Req=- X-B3-TraceId-Req=- X-B3-TraceId-Res=- raw_content_length-Req=19 raw_content_length-Res=21 final_content_length-Res=20 elapsed_time_millis=20") } def "log(): throws IllegalArgumentException if passed null request"() { @@ -91,7 +91,7 @@ class AccessLoggerSpec extends Specification { when: "we call logMessageAdditions()" List> result = accessLogger.logMessageAdditions(requestMock, null, responseMock, 20L) then: - result.size() == 17 + result.size() == 16 result.get(0) == Pair.of("accept-Req", "application/json") result.get(1) == Pair.of("content-type-Req", "application/json;charset=utf-8") result.get(2) == Pair.of("content-length-Res", "Content-LengthMock") @@ -100,15 +100,14 @@ class AccessLoggerSpec extends Specification { result.get(5) == Pair.of("error_uid-Res", "error_uidMock") result.get(6) == Pair.of("X-B3-Sampled-Req", "X-B3-SampledMock") result.get(7) == Pair.of("X-B3-SpanId-Req", "X-B3-SpanIdMock") - result.get(8) == Pair.of("X-B3-SpanName-Req", "X-B3-SpanNameMock") - result.get(9) == Pair.of("X-B3-TraceId-Req", "X-B3-TraceId-ReqMock") - result.get(10) == Pair.of("X-B3-TraceId-Res", "X-B3-TraceId-ResMock") - result.get(11) == Pair.of("raw_content_length-Req", "19") - result.get(12) == Pair.of("raw_content_length-Res", "21") - result.get(13) == Pair.of("final_content_length-Res", "20") - result.get(14) == Pair.of("elapsed_time_millis", "20") - result.get(15) == Pair.of("foo", "bar") - result.get(16) == Pair.of("whee", "yay") + result.get(8) == Pair.of("X-B3-TraceId-Req", "X-B3-TraceId-ReqMock") + result.get(9) == Pair.of("X-B3-TraceId-Res", "X-B3-TraceId-ResMock") + result.get(10) == Pair.of("raw_content_length-Req", "19") + result.get(11) == Pair.of("raw_content_length-Res", "21") + result.get(12) == Pair.of("final_content_length-Res", "20") + result.get(13) == Pair.of("elapsed_time_millis", "20") + result.get(14) == Pair.of("foo", "bar") + result.get(15) == Pair.of("whee", "yay") } def "logMessageAdditions(): includes missing headers but gives them null values"() { From 896f47f1c35f8905f8912daeb470e4603481f1c5 Mon Sep 17 00:00:00 2001 From: Nic Munroe Date: Mon, 12 Feb 2018 16:57:38 -0800 Subject: [PATCH 3/3] Handle corner cases so that access logging is always performed --- .../HttpChannelInitializer.java | 2 +- .../ChannelPipelineFinalizerHandler.java | 40 +++++++-- .../HttpChannelInitializerTest.java | 6 +- .../ChannelPipelineFinalizerHandlerTest.java | 83 +++++++++++++++++-- .../riposte/server/logging/AccessLogger.java | 2 +- .../server/logging/AccessLoggerSpec.groovy | 23 +++++ 6 files changed, 140 insertions(+), 16 deletions(-) diff --git a/riposte-core/src/main/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializer.java b/riposte-core/src/main/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializer.java index 1a1bcfae..c5eb3afc 100644 --- a/riposte-core/src/main/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializer.java +++ b/riposte-core/src/main/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializer.java @@ -561,7 +561,7 @@ public void initChannel(SocketChannel ch) { p.addLast( CHANNEL_PIPELINE_FINALIZER_HANDLER_NAME, new ChannelPipelineFinalizerHandler( - exceptionHandlingHandler, responseSender, metricsListener, workerChannelIdleTimeoutMillis + exceptionHandlingHandler, responseSender, metricsListener, accessLogger, workerChannelIdleTimeoutMillis ) ); diff --git a/riposte-core/src/main/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandler.java b/riposte-core/src/main/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandler.java index 2b272914..0d490f97 100644 --- a/riposte-core/src/main/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandler.java +++ b/riposte-core/src/main/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandler.java @@ -11,6 +11,8 @@ import com.nike.riposte.server.http.RequestInfo; import com.nike.riposte.server.http.ResponseInfo; import com.nike.riposte.server.http.ResponseSender; +import com.nike.riposte.server.http.impl.RequestInfoImpl; +import com.nike.riposte.server.logging.AccessLogger; import com.nike.riposte.server.metrics.ServerMetricsEvent; import com.nike.wingtips.Span; import com.nike.wingtips.Tracer; @@ -48,6 +50,7 @@ public class ChannelPipelineFinalizerHandler extends BaseInboundHandlerWithTraci private final ExceptionHandlingHandler exceptionHandlingHandler; private final ResponseSender responseSender; private final MetricsListener metricsListener; + private final AccessLogger accessLogger; private final long workerChannelIdleTimeoutMillis; private static final Throwable ARTIFICIAL_SERVER_WORKER_CHANNEL_CLOSED_EXCEPTION = new RuntimeException("Server worker channel closed"); @@ -59,13 +62,17 @@ public class ChannelPipelineFinalizerHandler extends BaseInboundHandlerWithTraci * @param responseSender * The {@link ResponseSender} that is used by the pipeline where this class is registered for sending data to * the user. + * @param accessLogger The {@link AccessLogger} that is used by the pipeline where this class is registered for + * access logging (i.e. the same access logger set on {@link AccessLogEndHandler}). * @param workerChannelIdleTimeoutMillis * The time in millis that should be given to {@link IdleChannelTimeoutHandler}s when they are created for * detecting idle channels that need to be closed. */ public ChannelPipelineFinalizerHandler(ExceptionHandlingHandler exceptionHandlingHandler, ResponseSender responseSender, - MetricsListener metricsListener, long workerChannelIdleTimeoutMillis) { + MetricsListener metricsListener, + AccessLogger accessLogger, + long workerChannelIdleTimeoutMillis) { if (exceptionHandlingHandler == null) throw new IllegalArgumentException("exceptionHandlingHandler cannot be null"); @@ -75,6 +82,7 @@ public ChannelPipelineFinalizerHandler(ExceptionHandlingHandler exceptionHandlin this.exceptionHandlingHandler = exceptionHandlingHandler; this.responseSender = responseSender; this.metricsListener = metricsListener; + this.accessLogger = accessLogger; this.workerChannelIdleTimeoutMillis = workerChannelIdleTimeoutMillis; } @@ -262,11 +270,14 @@ public PipelineContinuationBehavior doChannelInactive(ChannelHandlerContext ctx) ).run(); } + // The request/response is definitely done at this point since the channel is closing. Set the response end + // time if it hasn't already been done. + httpState.setResponseEndTimeNanosToNowIfNotAlreadySet(); + // Handle the case where the response wasn't fully sent or tracing wasn't completed for some reason. // We want to finish the distributed tracing span for this request since there's no other place it // might be done, and if the request wasn't fully sent then we should spit out a log message so // debug investigations can find out what happened. - // TODO: Is there a way we can handle access logging here, but only if it wasn't done elsewhere? Maybe similar to what we're doing with metrics? @SuppressWarnings("SimplifiableConditionalExpression") boolean tracingAlreadyCompleted = httpState.isTraceCompletedOrScheduled(); boolean responseNotFullySent = responseInfo == null || !responseInfo.isResponseSendingLastChunkSent(); @@ -275,26 +286,39 @@ public PipelineContinuationBehavior doChannelInactive(ChannelHandlerContext ctx) () -> { if (responseNotFullySent) { logger.warn( - "The caller's channel was closed before a response could be sent. This means that " - + "an access log probably does not exist for this request. Distributed tracing " - + "will be completed now if it wasn't already done. Any dangling resources will be " - + "released. response_info_is_null={}", + "The caller's channel was closed before a response could be sent. Distributed tracing " + + "will be completed now if it wasn't already done, and we will attempt to output an " + + "access log if needed. Any dangling resources will be released. " + + "response_info_is_null={}", (responseInfo == null) ); } if (!tracingAlreadyCompleted) { + httpState.setTraceCompletedOrScheduled(true); + Span currentSpan = Tracer.getInstance().getCurrentSpan(); if (currentSpan != null && !currentSpan.isCompleted()) Tracer.getInstance().completeRequestSpan(); - - httpState.setTraceCompletedOrScheduled(true); } }, ctx ).run(); } + // Make sure access logging is handled + if (!httpState.isAccessLogCompletedOrScheduled() && accessLogger != null) { + httpState.setAccessLogCompletedOrScheduled(true); + + RequestInfo requestInfoToUse = (requestInfo == null) + ? RequestInfoImpl.dummyInstanceForUnknownRequests() + : requestInfo; + accessLogger.log( + requestInfoToUse, httpState.getActualResponseObject(), responseInfo, + httpState.calculateTotalRequestTimeMillis() + ); + } + // Make sure metrics is handled handleMetricsForCompletedRequestIfNotAlreadyDone(httpState); diff --git a/riposte-core/src/test/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializerTest.java b/riposte-core/src/test/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializerTest.java index f4b0ac02..b53e4362 100644 --- a/riposte-core/src/test/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializerTest.java +++ b/riposte-core/src/test/java/com/nike/riposte/server/channelpipeline/HttpChannelInitializerTest.java @@ -1104,11 +1104,13 @@ public void initChannel_adds_DTraceEndHandler_immediately_before_ChannelPipeline } @Test - public void initChannel_adds_ChannelPipelineFinalizerHandler_as_the_last_handler_and_uses_the_ExceptionHandlingHandler_handler_and_responseSender_and_metricsListener() { + public void initChannel_adds_ChannelPipelineFinalizerHandler_as_the_last_handler_and_passes_the_expected_args() { // given HttpChannelInitializer hci = basicHttpChannelInitializerNoUtilityHandlers(); MetricsListener expectedMetricsListener = mock(MetricsListener.class); + AccessLogger expectedAccessLogger = mock(AccessLogger.class); Whitebox.setInternalState(hci, "metricsListener", expectedMetricsListener); + Whitebox.setInternalState(hci, "accessLogger", expectedAccessLogger); ResponseSender expectedResponseSender = extractField(hci, "responseSender"); // when @@ -1131,10 +1133,12 @@ public void initChannel_adds_ChannelPipelineFinalizerHandler_as_the_last_handler ExceptionHandlingHandler actualExceptionHandlingHandler = (ExceptionHandlingHandler) Whitebox.getInternalState(channelPipelineFinalizerHandler.getRight(), "exceptionHandlingHandler"); ResponseSender actualResponseSender = (ResponseSender) Whitebox.getInternalState(channelPipelineFinalizerHandler.getRight(), "responseSender"); MetricsListener actualMetricsListener = (MetricsListener) Whitebox.getInternalState(channelPipelineFinalizerHandler.getRight(), "metricsListener"); + AccessLogger actualAccessLogger = (AccessLogger) Whitebox.getInternalState(channelPipelineFinalizerHandler.getRight(), "accessLogger"); assertThat(actualExceptionHandlingHandler, is(expectedExceptionHandlingHandlerPair.getRight())); assertThat(actualResponseSender, is(expectedResponseSender)); assertThat(actualMetricsListener, is(expectedMetricsListener)); + Assertions.assertThat(actualAccessLogger).isSameAs(expectedAccessLogger); } @Test diff --git a/riposte-core/src/test/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandlerTest.java b/riposte-core/src/test/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandlerTest.java index 9aa57318..342a2082 100644 --- a/riposte-core/src/test/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandlerTest.java +++ b/riposte-core/src/test/java/com/nike/riposte/server/handler/ChannelPipelineFinalizerHandlerTest.java @@ -10,6 +10,7 @@ import com.nike.riposte.server.http.RequestInfo; import com.nike.riposte.server.http.ResponseInfo; import com.nike.riposte.server.http.ResponseSender; +import com.nike.riposte.server.logging.AccessLogger; import com.nike.riposte.server.metrics.ServerMetricsEvent; import com.nike.wingtips.Span; import com.nike.wingtips.Tracer; @@ -34,6 +35,7 @@ import io.netty.channel.ChannelHandler; import io.netty.channel.ChannelHandlerContext; import io.netty.channel.ChannelPipeline; +import io.netty.handler.codec.http.HttpResponse; import io.netty.util.Attribute; import io.netty.util.concurrent.GenericFutureListener; @@ -66,6 +68,7 @@ public class ChannelPipelineFinalizerHandlerTest { private ExceptionHandlingHandler exceptionHandlingHandlerMock; private ResponseSender responseSenderMock; private MetricsListener metricsListenerMock; + private AccessLogger accessLoggerMock; private Channel channelMock; private ChannelHandlerContext ctxMock; private ChannelPipeline pipelineMock; @@ -82,7 +85,9 @@ public void beforeMethod() { exceptionHandlingHandlerMock = mock(ExceptionHandlingHandler.class); responseSenderMock = mock(ResponseSender.class); metricsListenerMock = mock(MetricsListener.class); - handler = new ChannelPipelineFinalizerHandler(exceptionHandlingHandlerMock, responseSenderMock, metricsListenerMock, workerChannelIdleTimeoutMillis); + accessLoggerMock = mock(AccessLogger.class); + handler = new ChannelPipelineFinalizerHandler(exceptionHandlingHandlerMock, responseSenderMock, metricsListenerMock, + accessLoggerMock, workerChannelIdleTimeoutMillis); channelMock = mock(Channel.class); ctxMock = mock(ChannelHandlerContext.class); pipelineMock = mock(ChannelPipeline.class); @@ -111,8 +116,10 @@ public void beforeMethod() { @Test public void constructor_works_with_valid_args() { // given - ChannelPipelineFinalizerHandler handler = new ChannelPipelineFinalizerHandler(mock(ExceptionHandlingHandler.class), mock(ResponseSender.class), null, - workerChannelIdleTimeoutMillis); + ChannelPipelineFinalizerHandler handler = new ChannelPipelineFinalizerHandler( + mock(ExceptionHandlingHandler.class), mock(ResponseSender.class), null, null, + workerChannelIdleTimeoutMillis + ); // expect assertThat(handler, notNullValue()); @@ -121,13 +128,15 @@ public void constructor_works_with_valid_args() { @Test(expected = IllegalArgumentException.class) public void constructor_throws_IllegalArgumentException_if_exceptionHandlingHandler_is_null() { // expect - new ChannelPipelineFinalizerHandler(null, mock(ResponseSender.class), null, workerChannelIdleTimeoutMillis); + new ChannelPipelineFinalizerHandler(null, mock(ResponseSender.class), null, null, + workerChannelIdleTimeoutMillis); } @Test(expected = IllegalArgumentException.class) public void constructor_throws_IllegalArgumentException_if_responseSender_is_null() { // expect - new ChannelPipelineFinalizerHandler(mock(ExceptionHandlingHandler.class), null, null, workerChannelIdleTimeoutMillis); + new ChannelPipelineFinalizerHandler(mock(ExceptionHandlingHandler.class), null, null, null, + workerChannelIdleTimeoutMillis); } @Test @@ -565,6 +574,70 @@ public void argsAreEligibleForLinkingAndUnlinkingDistributedTracingInfo_returns_ ).isFalse(); } + @DataProvider(value = { + "true", + "false" + }, splitBy = "\\|") + @Test + public void doChannelInactive_should_call_accessLogger_if_access_logging_not_already_scheduled( + boolean requestInfoIsNull + ) throws Exception { + // given + state.setAccessLogCompletedOrScheduled(false); + if (requestInfoIsNull) { + state.setRequestInfo(null); + } + + HttpResponse actualResponseMock = mock(HttpResponse.class); + state.setActualResponseObject(actualResponseMock); + + HttpProcessingState stateSpy = spy(state); + doReturn(42L).when(stateSpy).calculateTotalRequestTimeMillis(); + doReturn(stateSpy).when(stateAttributeMock).get(); + + Assertions.assertThat(stateSpy.isAccessLogCompletedOrScheduled()).isFalse(); + + // when + handler.doChannelInactive(ctxMock); + + // then + verify(stateSpy).setResponseEndTimeNanosToNowIfNotAlreadySet(); + ArgumentCaptor requestInfoArgumentCaptor = ArgumentCaptor.forClass(RequestInfo.class); + verify(accessLoggerMock).log( + requestInfoArgumentCaptor.capture(), eq(actualResponseMock), eq(responseInfoMock), eq(42L) + ); + RequestInfo actualRequestInfo = requestInfoArgumentCaptor.getValue(); + if (requestInfoIsNull) { + Assertions.assertThat(actualRequestInfo.getUri()).isEqualTo(RequestInfo.NONE_OR_UNKNOWN_TAG); + } + else { + Assertions.assertThat(actualRequestInfo).isSameAs(requestInfoMock); + } + Assertions.assertThat(stateSpy.isAccessLogCompletedOrScheduled()).isTrue(); + } + + @DataProvider(value = { + "true | false", + "false | true" + }, splitBy = "\\|") + @Test + public void doChannelInactive_should_not_call_accessLogger_if_accessLogger_is_null_or_access_logging_already_scheduled( + boolean accessLoggerIsNull, boolean accessLoggingAlreadyScheduled + ) throws Exception { + // given + if (accessLoggerIsNull) + Whitebox.setInternalState(handler, "accessLogger", null); + + state.setAccessLogCompletedOrScheduled(accessLoggingAlreadyScheduled); + + // when + handler.doChannelInactive(ctxMock); + + // then + verifyZeroInteractions(accessLoggerMock); + Assertions.assertThat(state.isAccessLogCompletedOrScheduled()).isEqualTo(accessLoggingAlreadyScheduled); + } + @Test public void code_coverage_hoops() throws Exception { // jump! diff --git a/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java b/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java index 35b1b5b3..db4793ca 100644 --- a/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java +++ b/riposte-spi/src/main/java/com/nike/riposte/server/logging/AccessLogger.java @@ -424,7 +424,7 @@ else if (responseInfo != null) Pair.of("raw_content_length-Req", String.valueOf(request.getRawContentLengthInBytes())), Pair.of("raw_content_length-Res", uncompressedRawContentLength), Pair.of("final_content_length-Res", finalContentLength), - Pair.of("elapsed_time_millis", String.valueOf(elapsedTimeMillis)) + Pair.of("elapsed_time_millis", (elapsedTimeMillis == null) ? null : elapsedTimeMillis.toString()) )); List> customApplicationLogMessageExtras = diff --git a/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy b/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy index 4b5ba19a..17365035 100644 --- a/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy +++ b/riposte-spi/src/test/groovy/com/nike/riposte/server/logging/AccessLoggerSpec.groovy @@ -56,6 +56,29 @@ class AccessLoggerSpec extends Specification { thrown(IllegalArgumentException) } + def "log(): handles null response gracefully"() { + given: "the AccessLogger object" + AccessLogger accessLogger = new AccessLogger() + TestLogger logger = TestLoggerFactory.getTestLogger("ACCESS_LOG") + logger.clearAll() + and: "we've mocked the request object" + RequestInfo requestMock = Mock(RequestInfo) + requestMock.getHeaders() >> Mock(DefaultHttpHeaders) + requestMock.getHeaders().get("Referer") >> "myReferer" + requestMock.getHeaders().get("User-Agent") >> "myUserAgent" + requestMock.getMethod() >> HttpMethod.GET + requestMock.getUri() >> "/test" + requestMock.getProtocolVersion() >> HttpVersion.HTTP_1_1 + requestMock.getRawContentLengthInBytes() >> 19 + when: "we call logMessageAdditions()" + CompletableFuture cf = accessLogger.log(requestMock, null, null, null) + cf.join() + then: + logger.getAllLoggingEvents().size() == 1 + logger.getAllLoggingEvents().get(0).level == Level.INFO + logger.getAllLoggingEvents().get(0).message.contains("\"GET /test HTTP/1.1\" - - \"myReferer\" \"myUserAgent\" accept-Req=- content-type-Req=- content-length-Res=- transfer_encoding-Res=- http_status_code-Res=- error_uid-Res=- X-B3-Sampled-Req=- X-B3-SpanId-Req=- X-B3-TraceId-Req=- X-B3-TraceId-Res=- raw_content_length-Req=19 raw_content_length-Res=- final_content_length-Res=- elapsed_time_millis=-") + } + def "logMessageAdditions(): contains all expected headers including custom app ones"() { given: "the AccessLogger object that also returns some custom log message extras" AccessLogger accessLogger = new AccessLogger() {