Fix https://issues.apache.org/bugzilla/show_bug.cgi?id=51038

Ensure async requests are included in access logs.

git-svn-id: https://svn.apache.org/repos/asf/tomcat/trunk@1094055 13f79535-47bb-0310-9956-ffa450edef68

diff --git a/java/org/apache/catalina/connector/CoyoteAdapter.java b/java/org/apache/catalina/connector/CoyoteAdapter.java
index 6d9dc32..10fb3c5 100644 (file)
--- a/java/org/apache/catalina/connector/CoyoteAdapter.java
+++ b/java/org/apache/catalina/connector/CoyoteAdapter.java
@@ -317,6 +317,10 @@ public class CoyoteAdapter implements Adapter {
                 request.finishRequest();
                 response.finishResponse();
                 req.action(ActionCode.POST_REQUEST , null);
+                ((Context) request.getMappingData().context).logAccess(
+                        request, response,
+                        System.currentTimeMillis() - req.getStartTime(),
+                        false);
             }
 
         } catch (IOException e) {

diff --git a/test/org/apache/catalina/core/TestAsyncContextImpl.java b/test/org/apache/catalina/core/TestAsyncContextImpl.java
index 0bd49ea..e617fc1 100644 (file)
--- a/test/org/apache/catalina/core/TestAsyncContextImpl.java
+++ b/test/org/apache/catalina/core/TestAsyncContextImpl.java
@@ -39,10 +39,17 @@ import org.apache.catalina.Wrapper;
 import org.apache.catalina.connector.Request;
 import org.apache.catalina.startup.Tomcat;
 import org.apache.catalina.startup.TomcatBaseTest;
+import org.apache.catalina.valves.TesterAccessLogValve;
+import org.apache.catalina.valves.TesterAccessLogValve.Entry;
 import org.apache.tomcat.util.buf.ByteChunk;
 
 public class TestAsyncContextImpl extends TomcatBaseTest {
 
+    // Time for a request to process (need to allow for threads to start etc.)
+    private static final long REQUEST_TIME = 500;
+    // Timeout thread (where used) checks for timeout every second
+    private static final long TIMEOUT_MARGIN = 1000;
+
     public void testBug49528() throws Exception {
         // Setup Tomcat instance
         Tomcat tomcat = getTomcatInstance();
@@ -57,6 +64,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         wrapper.setAsyncSupported(true);
         ctx.addServletMapping("/", "servlet");
         
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         // Call the servlet once
@@ -71,6 +81,16 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         }
 
         assertEquals("1false2true3true4true5false", servlet.getResult());
+
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() >
+                Bug49528Servlet.THREAD_SLEEP_TIME);
+        assertTrue(entry.toString(), entry.getTime() <
+                Bug49528Servlet.THREAD_SLEEP_TIME + REQUEST_TIME);
     }
     
     public void testBug49567() throws Exception {
@@ -87,6 +107,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         wrapper.setAsyncSupported(true);
         ctx.addServletMapping("/", "servlet");
         
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         // Call the servlet once
@@ -101,6 +124,16 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         }
 
         assertEquals("1false2true3true4true5false", servlet.getResult());
+
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() >
+        Bug49567Servlet.THREAD_SLEEP_TIME);
+        assertTrue(entry.toString(), entry.getTime() <
+                Bug49567Servlet.THREAD_SLEEP_TIME + REQUEST_TIME);
     }
     
     public void testAsyncStartNoComplete() throws Exception {
@@ -122,6 +155,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         wrapper.setAsyncSupported(true);
         ctx.addServletMapping("/", "servlet");
         
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         // Call the servlet the first time
@@ -133,6 +169,18 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         ByteChunk bc2 = getUrl("http://localhost:" + getPort() +
                 "/?echo=run2");
         assertEquals("OK-run2", bc2.toString());
+        
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(2, entries.size());
+        for (Entry entry : entries) {
+            assertEquals(200, entry.getStatus());
+            assertTrue(entry.toString(), entry.getTime() >
+                    AsyncStartNoCompleteServlet.ASYNC_TIMEOUT);
+            assertTrue(entry.toString(), entry.getTime() <
+                    AsyncStartNoCompleteServlet.ASYNC_TIMEOUT + TIMEOUT_MARGIN +
+                            REQUEST_TIME);
+        }
     }
     
     public void testAsyncStartWithComplete() throws Exception {
@@ -150,11 +198,21 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         wrapper.setAsyncSupported(true);
         ctx.addServletMapping("/", "servlet");
         
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         // Call the servlet once
         ByteChunk bc = getUrl("http://localhost:" + getPort() + "/");
         assertEquals("OK", bc.toString());
+
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() < REQUEST_TIME);
     }
     
     /*
@@ -168,6 +226,8 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         
         private StringBuilder result;
         
+        public static final long THREAD_SLEEP_TIME = 1000;
+
         public String getResult() {
             return result.toString();
         }
@@ -194,7 +254,7 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
                     try {
                         result.append('3');
                         result.append(req.isAsyncStarted());
-                        Thread.sleep(1000);
+                        Thread.sleep(THREAD_SLEEP_TIME);
                         result.append('4');
                         result.append(req.isAsyncStarted());
                         resp.setContentType("text/plain");
@@ -227,6 +287,8 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         
         private StringBuilder result;
         
+        public static final long THREAD_SLEEP_TIME = 1000;
+
         public String getResult() {
             return result.toString();
         }
@@ -256,7 +318,7 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
                             try {
                                 result.append('3');
                                 result.append(req.isAsyncStarted());
-                                Thread.sleep(1000);
+                                Thread.sleep(THREAD_SLEEP_TIME);
                                 result.append('4');
                                 result.append(req.isAsyncStarted());
                                 resp.setContentType("text/plain");
@@ -283,6 +345,8 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
     
     private static class AsyncStartNoCompleteServlet extends HttpServlet {
 
+        public static final long ASYNC_TIMEOUT = 1000;
+        
         private static final long serialVersionUID = 1L;
         
         @Override
@@ -298,7 +362,7 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
                 resp.getWriter().print("-" + echo);
             }
             // Speed up the test by reducing the timeout
-            actxt.setTimeout(1000);
+            actxt.setTimeout(ASYNC_TIMEOUT);
         }
     }
 
@@ -363,6 +427,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
 
         ctx.addApplicationListener(TrackingRequestListener.class.getName());
 
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         ByteChunk res = getUrl("http://localhost:" + getPort() + "/async");
         StringBuilder expected = new StringBuilder("requestInitialized-");
@@ -377,6 +444,16 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         }
         expected.append("requestDestroyed");
         assertEquals(expected.toString(), res.toString());
+
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() >
+                TimeoutServlet.ASYNC_TIMEOUT);
+        assertTrue(entry.toString(), entry.getTime() <
+                TimeoutServlet.ASYNC_TIMEOUT + TIMEOUT_MARGIN + REQUEST_TIME);
     }
     
     private static class TimeoutServlet extends HttpServlet {
@@ -385,6 +462,8 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         private boolean completeOnTimeout;
         private String dispatchUrl;
 
+        public static final long ASYNC_TIMEOUT = 3000;
+
         public TimeoutServlet(boolean completeOnTimeout, String dispatchUrl) {
             this.completeOnTimeout = completeOnTimeout;
             this.dispatchUrl = dispatchUrl;
@@ -396,7 +475,7 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
             if (req.isAsyncSupported()) {
                 resp.getWriter().print("TimeoutServletGet-");
                 final AsyncContext ac = req.startAsync();
-                ac.setTimeout(3000);
+                ac.setTimeout(ASYNC_TIMEOUT);
                 
                 ac.addListener(new TrackingListener(
                         false, completeOnTimeout, dispatchUrl));
@@ -450,6 +529,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
 
         ctx.addApplicationListener(TrackingRequestListener.class.getName());
 
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         StringBuilder url = new StringBuilder(48);
@@ -471,6 +553,14 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         expected.append("NonAsyncServletGet-");
         expected.append("requestDestroyed");
         assertEquals(expected.toString(), res.toString());
+        
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() > 0);
+        assertTrue(entry.toString(), entry.getTime() < REQUEST_TIME);
     }
     
     private static class DispatchingServlet extends HttpServlet {
@@ -547,6 +637,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         wrapper2.setAsyncSupported(true);
         ctx.addServletMapping("/stage2", "timeout");
 
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         StringBuilder url = new StringBuilder(48);
@@ -560,6 +653,16 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
                 "DispatchingServletGet-DispatchingServletGet-onStartAsync-" +
                 "TimeoutServletGet-onStartAsync-onTimeout-onComplete-",
                 res.toString());
+
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() >
+                TimeoutServlet.ASYNC_TIMEOUT);
+        assertTrue(entry.toString(), entry.getTime() <
+                TimeoutServlet.ASYNC_TIMEOUT + TIMEOUT_MARGIN + REQUEST_TIME);
     }
 
     private static class TrackingServlet extends HttpServlet {
@@ -754,6 +857,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
 
         ctx.addApplicationListener(TrackingRequestListener.class.getName());
 
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         StringBuilder url = new StringBuilder(48);
@@ -777,6 +883,14 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         }
         expected.append("ErrorServletGet-onError-onComplete-requestDestroyed");
         assertEquals(expected.toString(), res.toString());
+        
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() > 0);
+        assertTrue(entry.toString(), entry.getTime() < REQUEST_TIME);
     }
     
     private static class ErrorServlet extends HttpServlet {
@@ -806,21 +920,32 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         wrapper.setAsyncSupported(true);
         ctx.addServletMapping("/", "servlet");
 
-        ErrorServlet error = new ErrorServlet();
-        Tomcat.addServlet(ctx, "error", error);
-        ctx.addServletMapping("/stage2", "error");
-
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         ByteChunk res = getUrl("http://localhost:" + getPort() + "/");
         
         assertEquals("Runnable-onComplete-", res.toString());
+
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() >
+        AsyncStartRunnable.THREAD_SLEEP_TIME);
+        assertTrue(entry.toString(), entry.getTime() <
+                AsyncStartRunnable.THREAD_SLEEP_TIME + REQUEST_TIME);
     }
     
     private static final class AsyncStartRunnable extends HttpServlet {
         
         private static final long serialVersionUID = 1L;
 
+        public static final long THREAD_SLEEP_TIME = 3000;
+
         @Override
         protected void doGet(HttpServletRequest request,
                 HttpServletResponse response)
@@ -836,7 +961,7 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
                 @Override
                 public void run() {
                     try {
-                        Thread.sleep(3 * 1000);
+                        Thread.sleep(THREAD_SLEEP_TIME);
                         asyncContext.getResponse().getWriter().write(
                                 "Runnable-");
                         asyncContext.complete();
@@ -862,6 +987,9 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         wrapper.setAsyncSupported(true);
         ctx.addServletMapping("/", "servlet");
         
+        TesterAccessLogValve alv = new TesterAccessLogValve();
+        ctx.getPipeline().addValve(alv);
+        
         tomcat.start();
         
         // Call the servlet once
@@ -875,12 +1003,25 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
         assertNotNull(testHeader);
         assertEquals(1, testHeader.size());
         assertEquals("xyz",testHeader.get(0));
+        
+        // Check the access log
+        List<Entry> entries = alv.getEntries();
+        assertEquals(1, entries.size());
+        Entry entry = entries.get(0);
+        assertEquals(200, entry.getStatus());
+        assertTrue(entry.toString(), entry.getTime() >
+        Bug50753Servlet.THREAD_SLEEP_TIME);
+        assertTrue(entry.toString(), entry.getTime() <
+                Bug50753Servlet.THREAD_SLEEP_TIME + REQUEST_TIME);
+
     }
 
     private static class Bug50753Servlet extends HttpServlet {
 
         private static final long serialVersionUID = 1L;
 
+        public static final long THREAD_SLEEP_TIME = 5000;
+
         @Override
         protected void doGet(HttpServletRequest req,
                 final HttpServletResponse resp)
@@ -890,7 +1031,7 @@ public class TestAsyncContextImpl extends TomcatBaseTest {
                 @Override
                 public void run() { 
                     try { 
-                        Thread.sleep(5000); 
+                        Thread.sleep(THREAD_SLEEP_TIME); 
                         resp.setHeader("A", "xyz"); 
                         resp.setContentType("text/plain"); 
                         resp.setContentLength("OK".getBytes().length); 

diff --git a/test/org/apache/catalina/valves/TesterAccessLogValve.java b/test/org/apache/catalina/valves/TesterAccessLogValve.java
new file mode 100644 (file)
index 0000000..b578b01
--- /dev/null
+++ b/test/org/apache/catalina/valves/TesterAccessLogValve.java
@@ -0,0 +1,94 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License.  You may obtain a copy of the License at
+ * 
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.catalina.valves;
+
+import java.io.IOException;
+import java.util.ArrayList;
+import java.util.List;
+
+import javax.servlet.ServletException;
+
+import org.apache.catalina.AccessLog;
+import org.apache.catalina.connector.Request;
+import org.apache.catalina.connector.Response;
+
+public class TesterAccessLogValve extends ValveBase implements AccessLog {
+
+    private List<Entry> entries = new ArrayList<Entry>();
+
+    public TesterAccessLogValve() {
+        // Async requests are supported
+        super(true);
+    }
+
+    @Override
+    public void log(Request request, Response response, long time) {
+        entries.add(new Entry(request.getRequestURI(), response.getStatus(),
+                time));
+    }
+
+    @Override
+    public void setRequestAttributesEnabled(boolean requestAttributesEnabled) {
+        // NOOP - test code
+    }
+
+    @Override
+    public boolean getRequestAttributesEnabled() {
+        // Always false - test code
+        return false;
+    }
+
+    @Override
+    public void invoke(Request request, Response response) throws IOException,
+            ServletException {
+        // Just invoke next - access logging happens via log() method
+        getNext().invoke(request, response);
+    }
+
+    public List<Entry> getEntries() {
+        return entries;
+    }
+
+    public static class Entry {
+        private String uri;
+        private int status;
+        private long time;
+
+        public Entry(String uri, int status, long time) {
+            this.uri = uri;
+            this.status = status;
+            this.time = time;
+        }
+
+        public String getUri() {
+            return uri;
+        }
+
+        public int getStatus() {
+            return status;
+        }
+
+        public long getTime() {
+            return time;
+        }
+
+        @Override
+        public String toString() {
+            return "Uri: " + uri + ", Status: " + status + ", Time: " + time;
+        }
+    }
+}

diff --git a/webapps/docs/changelog.xml b/webapps/docs/changelog.xml
index 19474d8..20985ff 100644 (file)
--- a/webapps/docs/changelog.xml
+++ b/webapps/docs/changelog.xml
@@ -61,6 +61,10 @@
         take a long time to process, which might indicate that their processing
         threads are stuck. Based on a patch provided by TomLu. (slaurent)
       </add>
+      <fix>
+        <bug>51038</bug>: Ensure that asynchronous requests are included in
+        access logs. (markt)
+      </fix>
     </changelog>
   </subsection>
   <subsection name="Coyote">