Merge pull request #270 from goughy000/fix/request-time-log

Bug Fix: Log request time from ALB requests

Author: sapessi

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<ContainerRequestType extends HttpServletRequest, ContainerResponseType extends HttpServletResponse>
         implements LogFormatter<ContainerRequestType, ContainerResponseType> {
-    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(" ");
 

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]"));
+  }
+
+}