Merge pull request #1828 from dropwizard/fix_reqAttribute_request_logs

Fix request logs with request parameter in layout pattern

dropwizard-request-logging/src/main/java/io/dropwizard/request/logging/layout/LogbackAccessRequestLayout.java

@@ -15,6 +15,12 @@
  */
 public class LogbackAccessRequestLayout extends PatternLayout {
 
+    static  {
+        // Replace the buggy default converter which don't work async appenders
+        defaultConverterMap.put("requestParameter", SafeRequestParameterConverter.class.getName());
+        defaultConverterMap.put("reqParameter", SafeRequestParameterConverter.class.getName());
+    }
+
     public LogbackAccessRequestLayout(Context context, TimeZone timeZone) {
         setOutputPatternAsHeader(false);
         setPattern("%h %l %u [%t{dd/MMM/yyyy:HH:mm:ss Z," + timeZone.getID()

dropwizard-request-logging/src/main/java/io/dropwizard/request/logging/layout/SafeRequestParameterConverter.java

@@ -0,0 +1,44 @@
+package io.dropwizard.request.logging.layout;
+
+import ch.qos.logback.access.pattern.AccessConverter;
+import ch.qos.logback.access.spi.IAccessEvent;
+import ch.qos.logback.core.util.OptionHelper;
+
+import java.util.Arrays;
+
+/**
+ * A safe version of {@link ch.qos.logback.access.pattern.RequestParameterConverter} which works
+ * with async appenders. It loads request parameters from a cached map rather than trying to load
+ * request data from the original request which may be closed.
+ */
+public class SafeRequestParameterConverter extends AccessConverter {
+
+    private String key;
+
+    @Override
+    public void start() {
+        key = getFirstOption();
+        if (OptionHelper.isEmpty(key)) {
+            addWarn("Missing key for the request parameter");
+        } else {
+            super.start();
+        }
+    }
+
+    @Override
+    public String convert(IAccessEvent accessEvent) {
+        if (!isStarted()) {
+            return "INACTIVE_REQUEST_PARAM_CONV";
+        }
+
+        // This call should be safe, because the request map is cached beforehand
+        final String[] paramArray = accessEvent.getRequestParameterMap().get(key);
+        if (paramArray == null || paramArray.length == 0) {
+            return "-";
+        } else if (paramArray.length == 1) {
+            return paramArray[0];
+        } else {
+            return Arrays.toString(paramArray);
+        }
+    }
+}

dropwizard-request-logging/src/test/java/io/dropwizard/request/logging/layout/SafeRequestParameterConverterTest.java

@@ -0,0 +1,75 @@
+package io.dropwizard.request.logging.layout;
+
+import ch.qos.logback.access.spi.AccessEvent;
+import ch.qos.logback.access.spi.ServerAdapter;
+import com.google.common.collect.ImmutableList;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
+import org.mockito.Mockito;
+
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
+import java.util.Vector;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+public class SafeRequestParameterConverterTest {
+
+    private final SafeRequestParameterConverter safeRequestParameterConverter = new SafeRequestParameterConverter();
+    private final HttpServletRequest httpServletRequest = Mockito.mock(HttpServletRequest.class);
+    private AccessEvent accessEvent;
+
+    @Before
+    public void setUp() throws Exception {
+        accessEvent = new AccessEvent(httpServletRequest, Mockito.mock(HttpServletResponse.class),
+            Mockito.mock(ServerAdapter.class));
+
+        safeRequestParameterConverter.setOptionList(ImmutableList.of("name"));
+        safeRequestParameterConverter.start();
+    }
+
+    @After
+    public void tearDown() throws Exception {
+        safeRequestParameterConverter.stop();
+    }
+
+    @Test
+    public void testConvertOneParameter() throws Exception {
+        Mockito.when(httpServletRequest.getParameterValues("name")).thenReturn(new String[]{"Alice"});
+        final Vector<String> parameterNames = new Vector<>();
+        parameterNames.add("name");
+        Mockito.when(httpServletRequest.getParameterNames()).thenReturn(parameterNames.elements());
+
+        // Invoked by AccessEvent#prepareForDeferredProcessing
+        accessEvent.buildRequestParameterMap();
+        // Jetty recycled the request
+        Mockito.reset(httpServletRequest);
+
+        String value = safeRequestParameterConverter.convert(accessEvent);
+        assertThat(value).isEqualTo("Alice");
+    }
+
+    @Test
+    public void testConvertSeveralParameters() throws Exception {
+        Mockito.when(httpServletRequest.getParameterValues("name")).thenReturn(new String[]{"Alice", "Bob"});
+        final Vector<String> parameterNames = new Vector<>();
+        parameterNames.add("name");
+        Mockito.when(httpServletRequest.getParameterNames()).thenReturn(parameterNames.elements());
+
+        // Invoked by AccessEvent#prepareForDeferredProcessing
+        accessEvent.buildRequestParameterMap();
+        // Jetty recycled the request
+        Mockito.reset(httpServletRequest);
+
+        final String value = safeRequestParameterConverter.convert(accessEvent);
+        assertThat(value).isEqualTo("[Alice, Bob]");
+    }
+
+    @Test
+    public void testGetUnknownParameter() {
+        final String value = safeRequestParameterConverter.convert(accessEvent);
+        assertThat(value).isEqualTo("-");
+    }
+
+}