From 3368df11e275a7cd23a49e8958518d5be12d41f4 Mon Sep 17 00:00:00 2001 From: Jack Gough Date: Sat, 13 Jul 2019 14:47:37 +0100 Subject: [PATCH] Bug Fix: Log request time from ALB requests - Previously logged as 01/01/1970:00:00:00Z as RequestTimeEpoch == 0 --- .../ApacheCombinedServletLogFormatter.java | 22 ++--- ...ApacheCombinedServletLogFormatterTest.java | 86 +++++++++++++++++++ 2 files changed, 98 insertions(+), 10 deletions(-) create mode 100644 aws-serverless-java-container-core/src/test/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatterTest.java diff --git a/aws-serverless-java-container-core/src/main/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatter.java b/aws-serverless-java-container-core/src/main/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatter.java index def4ecdfd..2105ffae3 100644 --- a/aws-serverless-java-container-core/src/main/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatter.java +++ b/aws-serverless-java-container-core/src/main/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatter.java @@ -11,15 +11,11 @@ import javax.servlet.http.HttpServletResponse; import javax.ws.rs.core.SecurityContext; -import java.time.LocalDateTime; -import java.time.ZoneId; -import java.time.ZoneOffset; -import java.time.ZonedDateTime; +import java.time.*; import java.time.format.DateTimeFormatter; import java.time.format.DateTimeFormatterBuilder; import java.util.Locale; -import static com.amazonaws.serverless.proxy.RequestReader.API_GATEWAY_CONTEXT_PROPERTY; import static com.amazonaws.serverless.proxy.RequestReader.API_GATEWAY_EVENT_PROPERTY; import static java.time.temporal.ChronoField.DAY_OF_MONTH; import static java.time.temporal.ChronoField.HOUR_OF_DAY; @@ -37,10 +33,16 @@ */ public class ApacheCombinedServletLogFormatter implements LogFormatter { - DateTimeFormatter dateFormat; + private final DateTimeFormatter dateFormat; + private final Clock clock; public ApacheCombinedServletLogFormatter() { - dateFormat = new DateTimeFormatterBuilder() + this(Clock.systemDefaultZone()); + } + + ApacheCombinedServletLogFormatter(Clock clock) { + this.clock = clock; + this.dateFormat = new DateTimeFormatterBuilder() .parseCaseInsensitive() .appendLiteral("[") .appendValue(DAY_OF_MONTH, 2) @@ -93,17 +95,17 @@ public String format(ContainerRequestType servletRequest, ContainerResponseType // %t - if (gatewayContext != null) { + if (gatewayContext != null && gatewayContext.getRequestTimeEpoch() > 0) { logLineBuilder.append( dateFormat.format( ZonedDateTime.of( LocalDateTime.ofEpochSecond(gatewayContext.getRequestTimeEpoch() / 1000, 0, ZoneOffset.UTC), - ZoneId.systemDefault() + clock.getZone() ) ) ); } else { - logLineBuilder.append(dateFormat.format(ZonedDateTime.now())); + logLineBuilder.append(dateFormat.format(ZonedDateTime.now(clock))); } logLineBuilder.append(" "); diff --git a/aws-serverless-java-container-core/src/test/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatterTest.java b/aws-serverless-java-container-core/src/test/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatterTest.java new file mode 100644 index 000000000..1c9527a32 --- /dev/null +++ b/aws-serverless-java-container-core/src/test/java/com/amazonaws/serverless/proxy/internal/servlet/ApacheCombinedServletLogFormatterTest.java @@ -0,0 +1,86 @@ +package com.amazonaws.serverless.proxy.internal.servlet; + + +import com.amazonaws.serverless.proxy.model.ApiGatewayRequestIdentity; +import com.amazonaws.serverless.proxy.model.AwsProxyRequest; +import com.amazonaws.serverless.proxy.model.AwsProxyRequestContext; +import org.junit.Before; +import org.junit.Test; + +import javax.servlet.http.HttpServletRequest; +import javax.servlet.http.HttpServletResponse; + +import java.time.Clock; +import java.time.Instant; +import java.time.ZoneId; + +import static com.amazonaws.serverless.proxy.RequestReader.API_GATEWAY_EVENT_PROPERTY; +import static org.hamcrest.CoreMatchers.containsString; +import static org.junit.Assert.assertThat; +import static org.mockito.Matchers.eq; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; + +public class ApacheCombinedServletLogFormatterTest { + + private ApacheCombinedServletLogFormatter sut; + + private HttpServletRequest mockServletRequest; + private HttpServletResponse mockServletResponse; + private AwsProxyRequest proxyRequest; + private AwsProxyRequestContext context; + + @Before + public void setup() { + proxyRequest = new AwsProxyRequest(); + Clock fixedClock = Clock.fixed(Instant.ofEpochSecond(665888523L), ZoneId.of("UTC")); + mockServletRequest = mock(HttpServletRequest.class); + when(mockServletRequest.getAttribute(eq(API_GATEWAY_EVENT_PROPERTY))) + .thenReturn(proxyRequest); + when(mockServletRequest.getMethod()) + .thenReturn("GET"); + mockServletResponse = mock(HttpServletResponse.class); + context = new AwsProxyRequestContext(); + context.setIdentity(new ApiGatewayRequestIdentity()); + proxyRequest.setRequestContext(context); + + sut = new ApacheCombinedServletLogFormatter(fixedClock); + } + + @Test + public void logsCurrentTimeWhenContextNull() { + // given + proxyRequest.setRequestContext(null); + + // when + String actual = sut.format(mockServletRequest, mockServletResponse, null); + + // then + assertThat(actual, containsString("[07/02/1991:01:02:03Z]")); + } + + @Test + public void logsCurrentTimeWhenRequestTimeZero() { + // given + context.setRequestTimeEpoch(0); + + // when + String actual = sut.format(mockServletRequest, mockServletResponse, null); + + // then + assertThat(actual, containsString("[07/02/1991:01:02:03Z]")); + } + + @Test + public void logsRequestTimeWhenRequestTimeEpochGreaterThanZero() { + // given + context.setRequestTimeEpoch(1563023494000L); + + // when + String actual = sut.format(mockServletRequest, mockServletResponse, null); + + // then + assertThat(actual, containsString("[13/07/2019:13:11:34Z]")); + } + +}