Author: markt
Date: Sat Apr 16 21:22:58 2011
New Revision: 1094055
URL: http://svn.apache.org/viewvc?rev=1094055&view=rev
Log:
Fix https://issues.apache.org/bugzilla/show_bug.cgi?id=51038
Ensure async requests are included in access logs.
Added:
tomcat/trunk/test/org/apache/catalina/valves/TesterAccessLogValve.java
Modified:
tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java
tomcat/trunk/test/org/apache/catalina/core/TestAsyncContextImpl.java
tomcat/trunk/webapps/docs/changelog.xml
Modified: tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java
URL:
http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java?rev=1094055&r1=1094054&r2=1094055&view=diff
==============================================================================
--- tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java
(original)
+++ tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java Sat Apr
16 21:22:58 2011
@@ -317,6 +317,10 @@ public class CoyoteAdapter implements Ad
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) {
Modified: tomcat/trunk/test/org/apache/catalina/core/TestAsyncContextImpl.java
URL:
http://svn.apache.org/viewvc/tomcat/trunk/test/org/apache/catalina/core/TestAsyncContextImpl.java?rev=1094055&r1=1094054&r2=1094055&view=diff
==============================================================================
--- tomcat/trunk/test/org/apache/catalina/core/TestAsyncContextImpl.java
(original)
+++ tomcat/trunk/test/org/apache/catalina/core/TestAsyncContextImpl.java Sat
Apr 16 21:22:58 2011
@@ -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 extend
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 extend
}
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 extend
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 extend
}
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 extend
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 extend
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 extend
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 extend
private StringBuilder result;
+ public static final long THREAD_SLEEP_TIME = 1000;
+
public String getResult() {
return result.toString();
}
@@ -194,7 +254,7 @@ public class TestAsyncContextImpl extend
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 extend
private StringBuilder result;
+ public static final long THREAD_SLEEP_TIME = 1000;
+
public String getResult() {
return result.toString();
}
@@ -256,7 +318,7 @@ public class TestAsyncContextImpl extend
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 extend
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 extend
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 extend
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 extend
}
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 extend
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 extend
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 extend
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 extend
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 extend
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 extend
"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 extend
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 extend
}
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 extend
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 extend
@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 extend
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 extend
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 extend
@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);
Added: tomcat/trunk/test/org/apache/catalina/valves/TesterAccessLogValve.java
URL:
http://svn.apache.org/viewvc/tomcat/trunk/test/org/apache/catalina/valves/TesterAccessLogValve.java?rev=1094055&view=auto
==============================================================================
--- tomcat/trunk/test/org/apache/catalina/valves/TesterAccessLogValve.java
(added)
+++ tomcat/trunk/test/org/apache/catalina/valves/TesterAccessLogValve.java Sat
Apr 16 21:22:58 2011
@@ -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;
+ }
+ }
+}
Modified: tomcat/trunk/webapps/docs/changelog.xml
URL:
http://svn.apache.org/viewvc/tomcat/trunk/webapps/docs/changelog.xml?rev=1094055&r1=1094054&r2=1094055&view=diff
==============================================================================
--- tomcat/trunk/webapps/docs/changelog.xml (original)
+++ tomcat/trunk/webapps/docs/changelog.xml Sat Apr 16 21:22:58 2011
@@ -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">
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
