From 161f1698cfe0869e855c8da290f8422232142e0a Mon Sep 17 00:00:00 2001 From: Greg Wilkins Date: Thu, 1 Nov 2018 17:06:04 +0100 Subject: [PATCH] Jetty 9.4.x 3018 request logging bad messages (#3020) Issue #3018 improve logging and handling of slow data rates. * Slow data rates now result in aborted channels, but exception is still thrown. Test for 408 in requestLog * Updated many RequestLog usages to use Server.setRequestLog rather than a RequestLogHandler * Fixed javadoc * removed BadRequestLogHandlerTest (tested in RequestLogTest) * added JMH to show the future of request logging for #113 * copyright header. * Updates from review * Revert to throwing BadMessageException * BME ensures a 408 is logged rather than a 500 Signed-off-by: Greg Wilkins --- .../eclipse/jetty/embedded/LikeJettyXml.java | 5 +- .../eclipse/jetty/embedded/ManyHandlers.java | 20 +- .../eclipse/jetty/ant/ServerProxyImpl.java | 7 +- .../requestlog/jmh/RequestLogBenchmark.java | 222 +++++ .../jetty/maven/plugin/ServerSupport.java | 6 +- .../java/org/eclipse/jetty/runner/Runner.java | 12 +- .../org/eclipse/jetty/server/HttpChannel.java | 15 +- .../org/eclipse/jetty/server/HttpInput.java | 7 +- .../org/eclipse/jetty/server/HttpOutput.java | 7 +- .../server/handler/RequestLogHandler.java | 10 +- .../handler/BadRequestLogHandlerTest.java | 194 ---- .../server/handler/RequestLogHandlerTest.java | 886 ------------------ .../jetty/server/handler/RequestLogTest.java | 509 +++++++++- .../jetty/servlet/AsyncServletTest.java | 8 +- .../jetty/servlet/ServletRequestLogTest.java | 25 +- .../jetty/http/client/ServerTimeoutsTest.java | 26 +- .../jetty/http/client/TransportScenario.java | 13 + .../java/org/eclipse/jetty/TestServer.java | 6 +- 18 files changed, 770 insertions(+), 1208 deletions(-) create mode 100644 jetty-jmh/src/main/java/org/eclipse/jetty/requestlog/jmh/RequestLogBenchmark.java delete mode 100644 jetty-server/src/test/java/org/eclipse/jetty/server/handler/BadRequestLogHandlerTest.java delete mode 100644 jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogHandlerTest.java diff --git a/examples/embedded/src/main/java/org/eclipse/jetty/embedded/LikeJettyXml.java b/examples/embedded/src/main/java/org/eclipse/jetty/embedded/LikeJettyXml.java index 356a9181978..de276e02d68 100644 --- a/examples/embedded/src/main/java/org/eclipse/jetty/embedded/LikeJettyXml.java +++ b/examples/embedded/src/main/java/org/eclipse/jetty/embedded/LikeJettyXml.java @@ -44,7 +44,6 @@ import org.eclipse.jetty.server.SslConnectionFactory; import org.eclipse.jetty.server.handler.ContextHandlerCollection; import org.eclipse.jetty.server.handler.DefaultHandler; import org.eclipse.jetty.server.handler.HandlerCollection; -import org.eclipse.jetty.server.handler.RequestLogHandler; import org.eclipse.jetty.server.handler.StatisticsHandler; import org.eclipse.jetty.util.ssl.SslContextFactory; import org.eclipse.jetty.util.thread.QueuedThreadPool; @@ -214,9 +213,7 @@ public class LikeJettyXml requestLog.setExtended(true); requestLog.setLogCookies(false); requestLog.setLogTimeZone("GMT"); - RequestLogHandler requestLogHandler = new RequestLogHandler(); - requestLogHandler.setRequestLog(requestLog); - handlers.addHandler(requestLogHandler); + server.setRequestLog(requestLog); // === jetty-lowresources.xml === diff --git a/examples/embedded/src/main/java/org/eclipse/jetty/embedded/ManyHandlers.java b/examples/embedded/src/main/java/org/eclipse/jetty/embedded/ManyHandlers.java index 337f760af86..244ff29cf68 100644 --- a/examples/embedded/src/main/java/org/eclipse/jetty/embedded/ManyHandlers.java +++ b/examples/embedded/src/main/java/org/eclipse/jetty/embedded/ManyHandlers.java @@ -35,7 +35,6 @@ import org.eclipse.jetty.server.handler.DefaultHandler; import org.eclipse.jetty.server.handler.HandlerCollection; import org.eclipse.jetty.server.handler.HandlerList; import org.eclipse.jetty.server.handler.HandlerWrapper; -import org.eclipse.jetty.server.handler.RequestLogHandler; import org.eclipse.jetty.server.handler.gzip.GzipHandler; import org.eclipse.jetty.util.ajax.JSON; @@ -115,13 +114,12 @@ public class ManyHandlers HandlerWrapper wrapper = new WelcomeWrapHandler(); Handler hello = new HelloHandler(); Handler dft = new DefaultHandler(); - RequestLogHandler requestLog = new RequestLogHandler(); // configure request logging File requestLogFile = File.createTempFile("demo", "log"); NCSARequestLog ncsaLog = new NCSARequestLog( requestLogFile.getAbsolutePath()); - requestLog.setRequestLog(ncsaLog); + server.setRequestLog(ncsaLog); // create the handler collections HandlerCollection handlers = new HandlerCollection(); @@ -129,20 +127,8 @@ public class ManyHandlers // link them all together wrapper.setHandler(hello); - list.setHandlers(new Handler[] { param, new GzipHandler(), dft }); - handlers.setHandlers(new Handler[] { list, requestLog }); - - // Handler tree looks like the following - // 
-        // Server
-        // + HandlerCollection
-        // . + HandlerList
-        // . | + param (ParamHandler)
-        // . | + wrapper (WelcomeWrapHandler)
-        // . | | \ hello (HelloHandler)
-        // . | \ dft (DefaultHandler)
-        // . \ requestLog (RequestLogHandler)
-        //
+ list.setHandlers(new Handler[] { param, new GzipHandler() }); + handlers.setHandlers(new Handler[] { list, dft }); server.setHandler(handlers); diff --git a/jetty-ant/src/main/java/org/eclipse/jetty/ant/ServerProxyImpl.java b/jetty-ant/src/main/java/org/eclipse/jetty/ant/ServerProxyImpl.java index 2dd2fdb9ee0..ac62bfc280a 100644 --- a/jetty-ant/src/main/java/org/eclipse/jetty/ant/ServerProxyImpl.java +++ b/jetty-ant/src/main/java/org/eclipse/jetty/ant/ServerProxyImpl.java @@ -40,7 +40,6 @@ import org.eclipse.jetty.server.handler.ContextHandler; import org.eclipse.jetty.server.handler.ContextHandlerCollection; import org.eclipse.jetty.server.handler.DefaultHandler; import org.eclipse.jetty.server.handler.HandlerCollection; -import org.eclipse.jetty.server.handler.RequestLogHandler; import org.eclipse.jetty.util.Scanner; import org.eclipse.jetty.util.resource.Resource; import org.eclipse.jetty.xml.XmlConfiguration; @@ -407,9 +406,8 @@ public class ServerProxyImpl implements ServerProxy */ private void configureHandlers() { - RequestLogHandler requestLogHandler = new RequestLogHandler(); if (requestLog != null) - requestLogHandler.setRequestLog(requestLog); + server.setRequestLog(requestLog); contexts = (ContextHandlerCollection) server .getChildHandlerByClass(ContextHandlerCollection.class); @@ -422,8 +420,7 @@ public class ServerProxyImpl implements ServerProxy { handlers = new HandlerCollection(); server.setHandler(handlers); - handlers.setHandlers(new Handler[] { contexts, new DefaultHandler(), - requestLogHandler }); + handlers.setHandlers(new Handler[] { contexts, new DefaultHandler() }); } else { diff --git a/jetty-jmh/src/main/java/org/eclipse/jetty/requestlog/jmh/RequestLogBenchmark.java b/jetty-jmh/src/main/java/org/eclipse/jetty/requestlog/jmh/RequestLogBenchmark.java new file mode 100644 index 00000000000..9092a5fca6f --- /dev/null +++ b/jetty-jmh/src/main/java/org/eclipse/jetty/requestlog/jmh/RequestLogBenchmark.java @@ -0,0 +1,222 @@ +// +// ======================================================================== +// Copyright (c) 1995-2018 Mort Bay Consulting Pty. Ltd. +// ------------------------------------------------------------------------ +// All rights reserved. This program and the accompanying materials +// are made available under the terms of the Eclipse Public License v1.0 +// and Apache License v2.0 which accompanies this distribution. +// +// The Eclipse Public License is available at +// http://www.eclipse.org/legal/epl-v10.html +// +// The Apache License v2.0 is available at +// http://www.opensource.org/licenses/apache2.0.php +// +// You may elect to redistribute this code under either of these licenses. +// ======================================================================== +// + +package org.eclipse.jetty.requestlog.jmh; + +import static java.lang.invoke.MethodHandles.dropArguments; +import static java.lang.invoke.MethodHandles.foldArguments; +import static java.lang.invoke.MethodType.methodType; + +import java.lang.invoke.MethodHandle; +import java.lang.invoke.MethodHandles; +import java.lang.invoke.MethodType; +import java.util.concurrent.ThreadLocalRandom; +import java.util.concurrent.TimeUnit; + +import org.eclipse.jetty.util.TypeUtil; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.BenchmarkMode; +import org.openjdk.jmh.annotations.Measurement; +import org.openjdk.jmh.annotations.Mode; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.Threads; +import org.openjdk.jmh.annotations.Warmup; +import org.openjdk.jmh.profile.GCProfiler; +import org.openjdk.jmh.runner.Runner; +import org.openjdk.jmh.runner.RunnerException; +import org.openjdk.jmh.runner.options.Options; +import org.openjdk.jmh.runner.options.OptionsBuilder; + + + +@State(Scope.Benchmark) +@Threads(4) +@Warmup(iterations = 7, time = 500, timeUnit = TimeUnit.MILLISECONDS) +@Measurement(iterations = 7, time = 500, timeUnit = TimeUnit.MILLISECONDS) +public class RequestLogBenchmark +{ + + public static void append(String s, StringBuilder b) + { + b.append(s); + } + + public static void logURI(StringBuilder b, String request) + { + b.append(request); + } + + public static void logLength(StringBuilder b, String request) + { + b.append(request.length()); + } + + public static void logAddr(StringBuilder b, String request) + { + try + { + TypeUtil.toHex(request.hashCode(), b); + } + catch(Exception e) + { + throw new RuntimeException(e); + } + } + + private ThreadLocal buffers = new ThreadLocal() + { + @Override + protected StringBuilder initialValue() + { + return new StringBuilder(256); + } + }; + MethodHandle logHandle; + Object[] iteratedLog; + + public RequestLogBenchmark() + { + try + { + MethodType logType = methodType(Void.TYPE, StringBuilder.class, String.class); + + MethodHandle append = MethodHandles.lookup() + .findStatic(RequestLogBenchmark.class, "append", methodType(Void.TYPE, String.class, StringBuilder.class)); + MethodHandle logURI = MethodHandles.lookup().findStatic(RequestLogBenchmark.class, "logURI", logType); + MethodHandle logAddr = MethodHandles.lookup().findStatic(RequestLogBenchmark.class, "logAddr", logType); + MethodHandle logLength = MethodHandles.lookup().findStatic(RequestLogBenchmark.class, "logLength", logType); + + // setup iteration + iteratedLog = new Object[] + { + logURI, + " - ", + logAddr, + " ", + logLength, + "\n" + }; + + // setup methodHandle + logHandle = dropArguments(append.bindTo("\n"), 1, String.class); + logHandle = foldArguments(logHandle, logLength); + logHandle = foldArguments(logHandle, dropArguments(append.bindTo(" "), 1, String.class)); + logHandle = foldArguments(logHandle, logAddr); + logHandle = foldArguments(logHandle, dropArguments(append.bindTo(" - "), 1, String.class)); + logHandle = foldArguments(logHandle, logURI); + + } + catch (Throwable th) + { + throw new RuntimeException(th); + } + } + + + public String logFixed(String request) + { + StringBuilder b = buffers.get(); + logURI(b,request); + append(" - ",b); + logAddr(b,request); + append(" ",b); + logLength(b,request); + append("\n",b); + String l = b.toString(); + b.setLength(0); + return l; + } + + public String logIterate(String request) + { + try + { + + StringBuilder b = buffers.get(); + for (Object o : iteratedLog) + { + if (o instanceof String) + append((String)o, b); + else if (o instanceof MethodHandle) + ((MethodHandle)o).invoke(b, request); + } + String l = b.toString(); + b.setLength(0); + return l; + } + catch(Throwable th) + { + throw new RuntimeException(th); + } + } + + public String logMethodHandle(String request) + { + try + { + StringBuilder b = buffers.get(); + logHandle.invoke(buffers.get(), request); + String l = b.toString(); + b.setLength(0); + return l; + } + catch (Throwable th) + { + throw new RuntimeException(th); + } + } + + + @Benchmark + @BenchmarkMode({ Mode.Throughput}) + public String testFixed() + { + return logFixed(Long.toString(ThreadLocalRandom.current().nextLong())); + }; + + @Benchmark + @BenchmarkMode({ Mode.Throughput}) + public String testIterate() + { + return logIterate(Long.toString(ThreadLocalRandom.current().nextLong())); + }; + + @Benchmark + @BenchmarkMode({ Mode.Throughput}) + public String testHandle() + { + return logMethodHandle(Long.toString(ThreadLocalRandom.current().nextLong())); + }; + + + public static void main(String[] args) throws RunnerException + { + Options opt = new OptionsBuilder() + .include(RequestLogBenchmark.class.getSimpleName()) + .warmupIterations(20) + .measurementIterations(10) + .addProfiler(GCProfiler.class) + .forks(1) + .threads(100) + .build(); + + new Runner(opt).run(); + } + +} diff --git a/jetty-maven-plugin/src/main/java/org/eclipse/jetty/maven/plugin/ServerSupport.java b/jetty-maven-plugin/src/main/java/org/eclipse/jetty/maven/plugin/ServerSupport.java index 36eab2e0418..00c8e6c9c4c 100644 --- a/jetty-maven-plugin/src/main/java/org/eclipse/jetty/maven/plugin/ServerSupport.java +++ b/jetty-maven-plugin/src/main/java/org/eclipse/jetty/maven/plugin/ServerSupport.java @@ -33,7 +33,6 @@ import org.eclipse.jetty.server.Server; import org.eclipse.jetty.server.handler.ContextHandlerCollection; import org.eclipse.jetty.server.handler.DefaultHandler; import org.eclipse.jetty.server.handler.HandlerCollection; -import org.eclipse.jetty.server.handler.RequestLogHandler; import org.eclipse.jetty.util.resource.Resource; import org.eclipse.jetty.webapp.Configuration; import org.eclipse.jetty.webapp.WebAppContext; @@ -69,9 +68,8 @@ public class ServerSupport throw new IllegalArgumentException ("Server is null"); DefaultHandler defaultHandler = new DefaultHandler(); - RequestLogHandler requestLogHandler = new RequestLogHandler(); if (requestLog != null) - requestLogHandler.setRequestLog(requestLog); + server.setRequestLog(requestLog); ContextHandlerCollection contexts = findContextHandlerCollection(server); if (contexts == null) @@ -82,7 +80,7 @@ public class ServerSupport { handlers = new HandlerCollection(); server.setHandler(handlers); - handlers.setHandlers(new Handler[]{contexts, defaultHandler, requestLogHandler}); + handlers.setHandlers(new Handler[]{contexts, defaultHandler}); } else { diff --git a/jetty-runner/src/main/java/org/eclipse/jetty/runner/Runner.java b/jetty-runner/src/main/java/org/eclipse/jetty/runner/Runner.java index 12fe3a27ca6..9348f82858f 100644 --- a/jetty-runner/src/main/java/org/eclipse/jetty/runner/Runner.java +++ b/jetty-runner/src/main/java/org/eclipse/jetty/runner/Runner.java @@ -43,7 +43,6 @@ import org.eclipse.jetty.server.handler.ContextHandler; import org.eclipse.jetty.server.handler.ContextHandlerCollection; import org.eclipse.jetty.server.handler.DefaultHandler; import org.eclipse.jetty.server.handler.HandlerCollection; -import org.eclipse.jetty.server.handler.RequestLogHandler; import org.eclipse.jetty.server.handler.StatisticsHandler; import org.eclipse.jetty.server.session.SessionHandler; import org.eclipse.jetty.servlet.ServletContextHandler; @@ -88,7 +87,6 @@ public class Runner protected URLClassLoader _classLoader; protected Classpath _classpath = new Classpath(); protected ContextHandlerCollection _contexts; - protected RequestLogHandler _logHandler; protected String _logFile; protected ArrayList _configFiles; protected boolean _enableStats=false; @@ -392,14 +390,6 @@ public class Runner handlers.addHandler(new DefaultHandler()); } - //ensure a log handler is present - _logHandler = (RequestLogHandler) handlers.getChildHandlerByClass(RequestLogHandler.class); - if (_logHandler == null) - { - _logHandler = new RequestLogHandler(); - handlers.addHandler(_logHandler); - } - //check a connector is configured to listen on Connector[] connectors = _server.getConnectors(); @@ -509,7 +499,7 @@ public class Runner { NCSARequestLog requestLog = new NCSARequestLog(_logFile); requestLog.setExtended(false); - _logHandler.setRequestLog(requestLog); + _server.setRequestLog(requestLog); } } diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannel.java b/jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannel.java index 43ab02dc183..95012aee8b5 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannel.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannel.java @@ -888,7 +888,6 @@ public class HttpChannel implements Runnable, HttpOutput.Interceptor @Override public void write(ByteBuffer content, boolean complete, Callback callback) { - _written+=BufferUtil.length(content); sendResponse(null,content,complete,callback); } @@ -1226,18 +1225,21 @@ public class HttpChannel implements Runnable, HttpOutput.Interceptor private class CommitCallback extends Callback.Nested { private final ByteBuffer _content; + private final int _length; private final boolean _complete; private CommitCallback(Callback callback, ByteBuffer content, boolean complete) { super(callback); - this._content = content == null ? BufferUtil.EMPTY_BUFFER : content.slice(); - this._complete = complete; + _content = content == null ? BufferUtil.EMPTY_BUFFER : content.slice(); + _length = _content.remaining(); + _complete = complete; } @Override public void succeeded() { + _written += _length; super.succeeded(); notifyResponseCommit(_request); if (_content.hasRemaining()) @@ -1299,18 +1301,21 @@ public class HttpChannel implements Runnable, HttpOutput.Interceptor private class ContentCallback extends Callback.Nested { private final ByteBuffer _content; + private final int _length; private final boolean _complete; private ContentCallback(Callback callback, ByteBuffer content, boolean complete) { super(callback); - this._content = content == null ? BufferUtil.EMPTY_BUFFER : content.slice(); - this._complete = complete; + _content = content == null ? BufferUtil.EMPTY_BUFFER : content.slice(); + _length = _content.remaining(); + _complete = complete; } @Override public void succeeded() { + _written += _length; super.succeeded(); if (_content.hasRemaining()) notifyResponseContent(_request, _content); diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/HttpInput.java b/jetty-server/src/main/java/org/eclipse/jetty/server/HttpInput.java index 28f6d2622e1..d4592a72607 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/HttpInput.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/HttpInput.java @@ -286,7 +286,12 @@ public class HttpInput extends ServletInputStream implements Runnable { long minimum_data = minRequestDataRate * TimeUnit.NANOSECONDS.toMillis(period) / TimeUnit.SECONDS.toMillis(1); if (_contentArrived < minimum_data) - throw new BadMessageException(HttpStatus.REQUEST_TIMEOUT_408,String.format("Request content data rate < %d B/s",minRequestDataRate)); + { + BadMessageException bad = new BadMessageException(HttpStatus.REQUEST_TIMEOUT_408, + String.format("Request content data rate < %d B/s", minRequestDataRate)); + _channelState.getHttpChannel().abort(bad); + throw bad; + } } } diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/HttpOutput.java b/jetty-server/src/main/java/org/eclipse/jetty/server/HttpOutput.java index 6fcd6370435..4402d193a93 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/HttpOutput.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/HttpOutput.java @@ -25,6 +25,7 @@ import java.nio.channels.ReadableByteChannel; import java.nio.channels.WritePendingException; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicReference; + import javax.servlet.RequestDispatcher; import javax.servlet.ServletOutputStream; import javax.servlet.ServletRequest; @@ -934,7 +935,11 @@ public class HttpOutput extends ServletOutputStream implements Runnable if (LOG.isDebugEnabled()) LOG.debug("Flushed bytes min/actual {}/{}", minFlushed, _flushed); if (_flushed < minFlushed) - throw new IOException(String.format("Response content data rate < %d B/s", minDataRate)); + { + IOException ioe = new IOException(String.format("Response content data rate < %d B/s", minDataRate)); + _channel.abort(ioe); + throw ioe; + } } public void recycle() diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java b/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java index 838d3323422..e30764a2e92 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java @@ -31,11 +31,11 @@ import org.eclipse.jetty.server.Server; /** - * RequestLogHandler. - * This handler can be used to wrap an individual context for context logging. - * To set a {@link RequestLog} instance for the entire {@link Server}, use - * {@link Server#setRequestLog(RequestLog)} instead of this handler. - * + *

This handler provides an alternate way (other than {@link Server#setRequestLog(RequestLog)}) + * to log request, that can be applied to a particular handler (eg context). + * This handler can be used to wrap an individual context for context logging, or can be listed + * prior to a handler. + *

* @see Server#setRequestLog(RequestLog) */ public class RequestLogHandler extends HandlerWrapper diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/BadRequestLogHandlerTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/BadRequestLogHandlerTest.java deleted file mode 100644 index 1c54de4ca0a..00000000000 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/BadRequestLogHandlerTest.java +++ /dev/null @@ -1,194 +0,0 @@ -// -// ======================================================================== -// Copyright (c) 1995-2018 Mort Bay Consulting Pty. Ltd. -// ------------------------------------------------------------------------ -// All rights reserved. This program and the accompanying materials -// are made available under the terms of the Eclipse Public License v1.0 -// and Apache License v2.0 which accompanies this distribution. -// -// The Eclipse Public License is available at -// http://www.eclipse.org/legal/epl-v10.html -// -// The Apache License v2.0 is available at -// http://www.opensource.org/licenses/apache2.0.php -// -// You may elect to redistribute this code under either of these licenses. -// ======================================================================== -// - -package org.eclipse.jetty.server.handler; - -import static org.hamcrest.MatcherAssert.assertThat; -import static org.hamcrest.Matchers.is; -import static org.junit.jupiter.api.Assertions.assertTimeoutPreemptively; - -import java.io.IOException; -import java.io.InputStream; -import java.io.InputStreamReader; -import java.io.OutputStream; -import java.io.OutputStreamWriter; -import java.io.StringReader; -import java.io.StringWriter; -import java.net.InetAddress; -import java.net.InetSocketAddress; -import java.net.Socket; -import java.net.SocketAddress; -import java.nio.charset.StandardCharsets; -import java.time.Duration; -import java.util.ArrayList; -import java.util.List; -import java.util.stream.Stream; - -import javax.servlet.ServletException; -import javax.servlet.http.HttpServletRequest; -import javax.servlet.http.HttpServletResponse; - -import org.eclipse.jetty.server.Connector; -import org.eclipse.jetty.server.Request; -import org.eclipse.jetty.server.RequestLog; -import org.eclipse.jetty.server.Response; -import org.eclipse.jetty.server.Server; -import org.eclipse.jetty.server.ServerConnector; -import org.eclipse.jetty.util.IO; -import org.eclipse.jetty.util.component.AbstractLifeCycle; -import org.eclipse.jetty.util.log.Log; -import org.eclipse.jetty.util.log.Logger; -import org.junit.jupiter.api.Disabled; -import org.junit.jupiter.api.Tag; -import org.junit.jupiter.params.ParameterizedTest; -import org.junit.jupiter.params.provider.Arguments; -import org.junit.jupiter.params.provider.MethodSource; - -/** - * Testing oddball request scenarios (like error 400) where the error should - * be logged - */ -@Tag("Unstable") -@Disabled -public class BadRequestLogHandlerTest -{ - private static final Logger LOG = Log.getLogger(BadRequestLogHandlerTest.class); - - public static class CaptureLog extends AbstractLifeCycle implements RequestLog - { - public List captured = new ArrayList<>(); - - @Override - public void log(Request request, Response response) - { - int status = response.getCommittedMetaData().getStatus(); - captured.add(String.format("%s %s %s %03d",request.getMethod(),request.getHttpURI(),request.getProtocol(),status)); - } - } - - private static class HelloHandler extends AbstractHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - response.setContentType("text/plain"); - response.getWriter().print("Hello World"); - baseRequest.setHandled(true); - } - } - - public static Stream data() - { - List data = new ArrayList<>(); - - data.add(new String[]{ "GET /bad VER\r\n" - + "Host: localhost\r\n" - + "Connection: close\r\n\r\n" , - "GET HTTP/1.1 400" }); - data.add(new String[]{ "GET /%%adsasd HTTP/1.1\r\n" - + "Host: localhost\r\n" - + "Connection: close\r\n\r\n" , - "GET HTTP/1.1 400" }); - - return data.stream().map(Arguments::of); - } - - @ParameterizedTest - @MethodSource("data") - public void testLogHandler(String requestHeader, String expectedLog) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[] { connector }); - - CaptureLog captureLog = new CaptureLog(); - - RequestLogHandler requestLog = new RequestLogHandler(); - requestLog.setRequestLog(captureLog); - - requestLog.setHandler(new HelloHandler()); - - server.setHandler(requestLog); - - try - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - - InetAddress destAddr = InetAddress.getByName(host); - int port = connector.getLocalPort(); - SocketAddress endpoint = new InetSocketAddress(destAddr,port); - - Socket socket = new Socket(); - socket.setSoTimeout(1000); - socket.connect(endpoint); - - assertTimeoutPreemptively(Duration.ofSeconds(4), ()-> { - try (OutputStream out = socket.getOutputStream(); - OutputStreamWriter writer = new OutputStreamWriter(out, StandardCharsets.UTF_8); - InputStream in = socket.getInputStream(); - InputStreamReader reader = new InputStreamReader(in, StandardCharsets.UTF_8)) - { - StringReader request = new StringReader(requestHeader); - IO.copy(request, writer); - writer.flush(); - StringWriter response = new StringWriter(); - IO.copy(reader, response); - LOG.info("Response: {}", response); - } - finally - { - socket.close(); - } - }); - - assertRequestLog(expectedLog, captureLog); - } - finally - { - server.stop(); - } - } - - private void assertRequestLog(final String expectedLog, CaptureLog captureLog) - { - int captureCount = captureLog.captured.size(); - - if (captureCount != 1) - { - LOG.warn("Capture Log size is {}, expected to be 1",captureCount); - if (captureCount > 1) - { - for (int i = 0; i < captureCount; i++) - { - LOG.warn("[{}] {}",i,captureLog.captured.get(i)); - } - } - assertThat("Capture Log Entry Count",captureLog.captured.size(),is(1)); - } - - String actual = captureLog.captured.get(0); - assertThat("Capture Log",actual,is(expectedLog)); - } -} diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogHandlerTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogHandlerTest.java deleted file mode 100644 index a57c4186c85..00000000000 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogHandlerTest.java +++ /dev/null @@ -1,886 +0,0 @@ -// -// ======================================================================== -// Copyright (c) 1995-2018 Mort Bay Consulting Pty. Ltd. -// ------------------------------------------------------------------------ -// All rights reserved. This program and the accompanying materials -// are made available under the terms of the Eclipse Public License v1.0 -// and Apache License v2.0 which accompanies this distribution. -// -// The Eclipse Public License is available at -// http://www.eclipse.org/legal/epl-v10.html -// -// The Apache License v2.0 is available at -// http://www.opensource.org/licenses/apache2.0.php -// -// You may elect to redistribute this code under either of these licenses. -// ======================================================================== -// - -package org.eclipse.jetty.server.handler; - -import static org.hamcrest.MatcherAssert.assertThat; -import static org.hamcrest.Matchers.is; -import static org.hamcrest.Matchers.notNullValue; - -import java.io.IOException; -import java.io.InputStream; -import java.io.InputStreamReader; -import java.io.PrintWriter; -import java.io.StringWriter; -import java.net.HttpURLConnection; -import java.net.URI; -import java.util.ArrayList; -import java.util.List; -import java.util.stream.Stream; - -import javax.servlet.AsyncContext; -import javax.servlet.AsyncEvent; -import javax.servlet.AsyncListener; -import javax.servlet.RequestDispatcher; -import javax.servlet.ServletException; -import javax.servlet.http.HttpServletRequest; -import javax.servlet.http.HttpServletResponse; - -import org.eclipse.jetty.server.Connector; -import org.eclipse.jetty.server.Handler; -import org.eclipse.jetty.server.HttpChannel; -import org.eclipse.jetty.server.HttpChannelState; -import org.eclipse.jetty.server.Request; -import org.eclipse.jetty.server.RequestLog; -import org.eclipse.jetty.server.Response; -import org.eclipse.jetty.server.Server; -import org.eclipse.jetty.server.ServerConnector; -import org.eclipse.jetty.toolchain.test.IO; -import org.eclipse.jetty.util.component.AbstractLifeCycle; -import org.eclipse.jetty.util.log.Log; -import org.eclipse.jetty.util.log.Logger; -import org.eclipse.jetty.util.log.StacklessLogging; -import org.junit.jupiter.api.Disabled; -import org.junit.jupiter.api.Tag; -import org.junit.jupiter.params.ParameterizedTest; -import org.junit.jupiter.params.provider.Arguments; -import org.junit.jupiter.params.provider.MethodSource; - -/** - * Tests for RequestLogHandler behavior. - *

- * Tests different request handler behavior against different server+error configurations - */ -@Tag("Unstable") -@Disabled -public class RequestLogHandlerTest -{ - private static final Logger LOG = Log.getLogger(RequestLogHandlerTest.class); - - public static class CaptureLog extends AbstractLifeCycle implements RequestLog - { - public List captured = new ArrayList<>(); - - @Override - public void log(Request request, Response response) - { - int status = response.getCommittedMetaData().getStatus(); - captured.add(String.format("%s %s %s %03d",request.getMethod(),request.getRequestURI(),request.getProtocol(),status)); - } - } - - private static abstract class AbstractTestHandler extends AbstractHandler - { - @Override - public String toString() - { - return this.getClass().getSimpleName(); - } - } - - private static class HelloHandler extends AbstractTestHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - response.setContentType("text/plain"); - response.getWriter().print("Hello World"); - baseRequest.setHandled(true); - } - } - - private static class ResponseSendErrorHandler extends AbstractTestHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - response.sendError(500,"Whoops"); - baseRequest.setHandled(true); - } - } - - private static class ServletExceptionHandler extends AbstractTestHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - throw new ServletException("Whoops"); - } - } - - private static class IOExceptionHandler extends AbstractTestHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - throw new IOException("Whoops"); - } - } - - private static class RuntimeExceptionHandler extends AbstractTestHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - throw new RuntimeException("Whoops"); - } - } - - private static class AsyncOnTimeoutCompleteHandler extends AbstractTestHandler implements AsyncListener - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - AsyncContext ac = request.startAsync(); - ac.setTimeout(1000); - ac.addListener(this); - baseRequest.setHandled(true); - } - - @Override - public void onTimeout(AsyncEvent event) throws IOException - { - event.getAsyncContext().complete(); - } - - @Override - public void onStartAsync(AsyncEvent event) throws IOException - { - } - - @Override - public void onError(AsyncEvent event) throws IOException - { - } - - @Override - public void onComplete(AsyncEvent event) throws IOException - { - } - } - - private static class AsyncOnTimeoutCompleteUnhandledHandler extends AbstractTestHandler implements AsyncListener - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - AsyncContext ac = request.startAsync(); - ac.setTimeout(1000); - ac.addListener(this); - } - - @Override - public void onTimeout(AsyncEvent event) throws IOException - { - event.getAsyncContext().complete(); - } - - @Override - public void onStartAsync(AsyncEvent event) throws IOException - { - } - - @Override - public void onError(AsyncEvent event) throws IOException - { - } - - @Override - public void onComplete(AsyncEvent event) throws IOException - { - } - } - - private static class AsyncOnTimeoutDispatchHandler extends AbstractTestHandler implements AsyncListener - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - if (request.getAttribute("deep") == null) - { - AsyncContext ac = request.startAsync(); - ac.setTimeout(1000); - ac.addListener(this); - baseRequest.setHandled(true); - request.setAttribute("deep",true); - } - } - - @Override - public void onTimeout(AsyncEvent event) throws IOException - { - event.getAsyncContext().dispatch(); - } - - @Override - public void onStartAsync(AsyncEvent event) throws IOException - { - } - - @Override - public void onError(AsyncEvent event) throws IOException - { - } - - @Override - public void onComplete(AsyncEvent event) throws IOException - { - } - } - - private static class AsyncOnStartIOExceptionHandler extends AbstractTestHandler implements AsyncListener - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException - { - AsyncContext ac = request.startAsync(); - ac.setTimeout(1000); - ac.addListener(this); - baseRequest.setHandled(true); - } - - @Override - public void onTimeout(AsyncEvent event) throws IOException - { - } - - @Override - public void onStartAsync(AsyncEvent event) throws IOException - { - event.getAsyncContext().complete(); - throw new IOException("Whoops"); - } - - @Override - public void onError(AsyncEvent event) throws IOException - { - LOG.warn("onError() -> {}",event); - } - - @Override - public void onComplete(AsyncEvent event) throws IOException - { - } - } - - public static class OKErrorHandler extends ErrorHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException - { - if (baseRequest.isHandled() || response.isCommitted()) - { - return; - } - - // collect error details - String reason = (response instanceof Response)?((Response)response).getReason():null; - int status = response.getStatus(); - - // intentionally set response status to OK (this is a test to see what is actually logged) - response.setStatus(200); - response.setContentType("text/plain"); - PrintWriter out = response.getWriter(); - out.printf("Error %d: %s%n",status,reason); - baseRequest.setHandled(true); - } - } - - public static class DispatchErrorHandler extends ErrorHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException - { - if (baseRequest.isHandled() || response.isCommitted()) - { - return; - } - - RequestDispatcher dispatcher = request.getRequestDispatcher("/errorok/"); - assertThat("Dispatcher", dispatcher, notNullValue()); - - try - { - dispatcher.forward(request,response); - } - catch (ServletException e) - { - throw new IOException("Dispatch.forward failed",e); - } - } - } - - public static class AltErrorHandler extends ErrorHandler - { - @Override - public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException - { - if (baseRequest.isHandled() || response.isCommitted()) - { - return; - } - - // collect error details - String reason = (response instanceof Response)?((Response)response).getReason():null; - int status = response.getStatus(); - - // intentionally set response status to OK (this is a test to see what is actually logged) - response.setContentType("text/plain"); - PrintWriter out = response.getWriter(); - out.printf("Error %d: %s%n",status,reason); - baseRequest.setHandled(true); - } - } - - public static Stream data() - { - List data = new ArrayList<>(); - - data.add(new Object[] { new HelloHandler(), "/test/", "GET /test/ HTTP/1.1 200" }); - data.add(new Object[] { new AsyncOnTimeoutCompleteHandler(), "/test/", "GET /test/ HTTP/1.1 200" }); - data.add(new Object[] { new AsyncOnTimeoutCompleteUnhandledHandler(), "/test/", "GET /test/ HTTP/1.1 200" }); - data.add(new Object[] { new AsyncOnTimeoutDispatchHandler(), "/test/", "GET /test/ HTTP/1.1 200" }); - - data.add(new Object[] { new AsyncOnStartIOExceptionHandler(), "/test/", "GET /test/ HTTP/1.1 500" }); - data.add(new Object[] { new ResponseSendErrorHandler(), "/test/", "GET /test/ HTTP/1.1 500" }); - data.add(new Object[] { new ServletExceptionHandler(), "/test/", "GET /test/ HTTP/1.1 500" }); - data.add(new Object[] { new IOExceptionHandler(), "/test/", "GET /test/ HTTP/1.1 500" }); - data.add(new Object[] { new RuntimeExceptionHandler(), "/test/", "GET /test/ HTTP/1.1 500" }); - - return data.stream().map(Arguments::of); - } - - /** - * Test a RequestLogHandler at the end of a HandlerCollection. all other configuration on server at defaults. - * @throws Exception if test failure - */ - @ParameterizedTest - @MethodSource("data") - public void testLogHandlerCollection(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[] { connector }); - - CaptureLog captureLog = new CaptureLog(); - - RequestLogHandler requestLog = new RequestLogHandler(); - requestLog.setRequestLog(captureLog); - - HandlerCollection handlers = new HandlerCollection(); - handlers.setHandlers(new Handler[] { testHandler, requestLog }); - server.setHandler(handlers); - - try - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - int port = connector.getLocalPort(); - - URI serverUri = new URI("http",null,host,port,requestPath,null,null); - - // Make call to test handler - HttpURLConnection connection = (HttpURLConnection)serverUri.toURL().openConnection(); - try - { - connection.setAllowUserInteraction(false); - - // log response status code - int statusCode = connection.getResponseCode(); - LOG.debug("Response Status Code: {}",statusCode); - - if (statusCode == 200) - { - // collect response message and log it - String content = getResponseContent(connection); - LOG.debug("Response Content: {}",content); - } - } - finally - { - connection.disconnect(); - } - - assertRequestLog(expectedLogEntry, captureLog); - } - finally - { - server.stop(); - } - } - - @ParameterizedTest - @MethodSource("data") - public void testMultipleLogHandlers(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[]{connector}); - - List captureLogs = new ArrayList<>(); - List handlerList = new ArrayList<>(); - handlerList.add(testHandler); - - for (int i = 0; i < 4; ++i) { - CaptureLog captureLog = new CaptureLog(); - captureLogs.add(captureLog); - RequestLogHandler requestLog = new RequestLogHandler(); - requestLog.setRequestLog(captureLog); - handlerList.add(requestLog); - } - - HandlerCollection handlers = new HandlerCollection(); - handlers.setHandlers(handlerList.toArray(new Handler[0])); - server.setHandler(handlers); - - try - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - int port = connector.getLocalPort(); - - URI serverUri = new URI("http",null,host,port,requestPath,null,null); - - // Make call to test handler - HttpURLConnection connection = (HttpURLConnection)serverUri.toURL().openConnection(); - try - { - connection.setAllowUserInteraction(false); - - // log response status code - int statusCode = connection.getResponseCode(); - LOG.debug("Response Status Code: {}",statusCode); - - if (statusCode == 200) - { - // collect response message and log it - String content = getResponseContent(connection); - LOG.debug("Response Content: {}",content); - } - } - finally - { - connection.disconnect(); - } - - for (CaptureLog captureLog:captureLogs) - assertRequestLog(expectedLogEntry, captureLog); - } - finally - { - server.stop(); - } - } - - /** - * Test a RequestLogHandler at the end of a HandlerCollection and also with the default ErrorHandler as server bean in place. - * @throws Exception if test failure - */ - @ParameterizedTest - @MethodSource("data") - public void testLogHandlerCollection_ErrorHandler_ServerBean(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[] { connector }); - - ErrorHandler errorHandler = new ErrorHandler(); - server.addBean(errorHandler); - - CaptureLog captureLog = new CaptureLog(); - - RequestLogHandler requestLog = new RequestLogHandler(); - requestLog.setRequestLog(captureLog); - - HandlerCollection handlers = new HandlerCollection(); - handlers.setHandlers(new Handler[] { testHandler, requestLog }); - server.setHandler(handlers); - - try - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - int port = connector.getLocalPort(); - - URI serverUri = new URI("http",null,host,port,requestPath,null,null); - - // Make call to test handler - HttpURLConnection connection = (HttpURLConnection)serverUri.toURL().openConnection(); - try - { - connection.setAllowUserInteraction(false); - - // log response status code - int statusCode = connection.getResponseCode(); - LOG.debug("Response Status Code: {}",statusCode); - - if (statusCode == 200) - { - // collect response message and log it - String content = getResponseContent(connection); - LOG.debug("Response Content: {}",content); - } - } - finally - { - connection.disconnect(); - } - - assertRequestLog(expectedLogEntry, captureLog); - } - finally - { - server.stop(); - } - } - - /** - * Test a RequestLogHandler at the end of a HandlerCollection and also with the ErrorHandler in place. - * @throws Exception if test failure - */ - @ParameterizedTest - @MethodSource("data") - public void testLogHandlerCollection_AltErrorHandler(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[] { connector }); - - AltErrorHandler errorDispatcher = new AltErrorHandler(); - server.addBean(errorDispatcher); - - ContextHandlerCollection contexts = new ContextHandlerCollection(); - ContextHandler errorContext = new ContextHandler("/errorpage"); - errorContext.setHandler(new AltErrorHandler()); - ContextHandler testContext = new ContextHandler("/test"); - testContext.setHandler(testHandler); - contexts.addHandler(errorContext); - contexts.addHandler(testContext); - - RequestLogHandler requestLog = new RequestLogHandler(); - CaptureLog captureLog = new CaptureLog(); - requestLog.setRequestLog(captureLog); - - HandlerCollection handlers = new HandlerCollection(); - handlers.setHandlers(new Handler[] { contexts, requestLog }); - server.setHandler(handlers); - - try - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - int port = connector.getLocalPort(); - - URI serverUri = new URI("http",null,host,port,requestPath,null,null); - - // Make call to test handler - HttpURLConnection connection = (HttpURLConnection)serverUri.toURL().openConnection(); - try - { - connection.setAllowUserInteraction(false); - - // log response status code - int statusCode = connection.getResponseCode(); - LOG.debug("Response Status Code: {}",statusCode); - - if (statusCode == 200) - { - // collect response message and log it - String content = getResponseContent(connection); - LOG.debug("Response Content: {}",content); - } - } - finally - { - connection.disconnect(); - } - - assertRequestLog(expectedLogEntry, captureLog); - } - finally - { - server.stop(); - } - } - - /** - * Test a RequestLogHandler at the end of a HandlerCollection and also with the ErrorHandler in place. - * @throws Exception if test failure - */ - @ParameterizedTest - @MethodSource("data") - public void testLogHandlerCollection_OKErrorHandler(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[] { connector }); - - OKErrorHandler errorDispatcher = new OKErrorHandler(); - server.addBean(errorDispatcher); - - ContextHandlerCollection contexts = new ContextHandlerCollection(); - ContextHandler errorContext = new ContextHandler("/errorpage"); - errorContext.setHandler(new AltErrorHandler()); - ContextHandler testContext = new ContextHandler("/test"); - testContext.setHandler(testHandler); - contexts.addHandler(errorContext); - contexts.addHandler(testContext); - - RequestLogHandler requestLog = new RequestLogHandler(); - CaptureLog captureLog = new CaptureLog(); - requestLog.setRequestLog(captureLog); - - HandlerCollection handlers = new HandlerCollection(); - handlers.setHandlers(new Handler[] { contexts, requestLog }); - server.setHandler(handlers); - - try - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - int port = connector.getLocalPort(); - - URI serverUri = new URI("http",null,host,port,requestPath,null,null); - - // Make call to test handler - HttpURLConnection connection = (HttpURLConnection)serverUri.toURL().openConnection(); - try - { - connection.setAllowUserInteraction(false); - - // log response status code - int statusCode = connection.getResponseCode(); - LOG.debug("Response Status Code: {}",statusCode); - - if (statusCode == 200) - { - // collect response message and log it - String content = getResponseContent(connection); - LOG.debug("Response Content: {}",content); - } - } - finally - { - connection.disconnect(); - } - - assertRequestLog(expectedLogEntry, captureLog); - } - finally - { - server.stop(); - } - } - - /** - * Test a RequestLogHandler at the end of a HandlerCollection and also with the ErrorHandler in place. - * @throws Exception if test failure - */ - @ParameterizedTest - @MethodSource("data") - public void testLogHandlerCollection_DispatchErrorHandler(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[] { connector }); - - DispatchErrorHandler errorDispatcher = new DispatchErrorHandler(); - server.addBean(errorDispatcher); - - ContextHandlerCollection contexts = new ContextHandlerCollection(); - ContextHandler errorContext = new ContextHandler("/errorok"); - errorContext.setHandler(new OKErrorHandler()); - ContextHandler testContext = new ContextHandler("/test"); - testContext.setHandler(testHandler); - contexts.addHandler(errorContext); - contexts.addHandler(testContext); - - RequestLogHandler requestLog = new RequestLogHandler(); - CaptureLog captureLog = new CaptureLog(); - requestLog.setRequestLog(captureLog); - - HandlerCollection handlers = new HandlerCollection(); - handlers.setHandlers(new Handler[] { contexts, requestLog }); - server.setHandler(handlers); - - try - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - int port = connector.getLocalPort(); - - URI serverUri = new URI("http",null,host,port,requestPath,null,null); - - // Make call to test handler - HttpURLConnection connection = (HttpURLConnection)serverUri.toURL().openConnection(); - try - { - connection.setAllowUserInteraction(false); - - // log response status code - int statusCode = connection.getResponseCode(); - LOG.debug("Response Status Code: {}",statusCode); - - if (statusCode == 200) - { - // collect response message and log it - String content = getResponseContent(connection); - LOG.debug("Response Content: {}",content); - } - } - finally - { - connection.disconnect(); - } - - assertRequestLog(expectedLogEntry, captureLog); - } - finally - { - server.stop(); - } - } - - @ParameterizedTest - @MethodSource("data") - public void testLogHandlerWrapped(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception - { - Server server = new Server(); - ServerConnector connector = new ServerConnector(server); - connector.setPort(0); - server.setConnectors(new Connector[] { connector }); - - CaptureLog captureLog = new CaptureLog(); - - RequestLogHandler requestLog = new RequestLogHandler(); - requestLog.setRequestLog(captureLog); - - requestLog.setHandler(testHandler); - - server.setHandler(requestLog); - - try (StacklessLogging ignore = new StacklessLogging(HttpChannel.class,HttpChannelState.class)) - { - server.start(); - - String host = connector.getHost(); - if (host == null) - { - host = "localhost"; - } - int port = connector.getLocalPort(); - - URI serverUri = new URI("http",null,host,port,requestPath,null,null); - - // Make call to test handler - HttpURLConnection connection = (HttpURLConnection)serverUri.toURL().openConnection(); - try - { - connection.setAllowUserInteraction(false); - - // log response status code - int statusCode = connection.getResponseCode(); - LOG.info("Response Status Code: {}",statusCode); - - if (statusCode == 200) - { - // collect response message and log it - String content = getResponseContent(connection); - LOG.info("Response Content: {}",content); - } - } - finally - { - connection.disconnect(); - } - - assertRequestLog(expectedLogEntry, captureLog); - } - finally - { - server.stop(); - } - } - - private void assertRequestLog(final String expectedLogEntry, CaptureLog captureLog) - { - int captureCount = captureLog.captured.size(); - - if (captureCount != 1) - { - LOG.warn("Capture Log size is {}, expected to be 1",captureCount); - if (captureCount > 1) - { - for (int i = 0; i < captureCount; i++) - { - LOG.warn("[{}] {}",i,captureLog.captured.get(i)); - } - } - assertThat("Capture Log Entry Count",captureLog.captured.size(),is(1)); - } - - String actual = captureLog.captured.get(0); - assertThat("Capture Log",actual,is(expectedLogEntry)); - } - - private String getResponseContent(HttpURLConnection connection) throws IOException - { - try (InputStream in = connection.getInputStream(); InputStreamReader reader = new InputStreamReader(in)) - { - StringWriter writer = new StringWriter(); - IO.copy(reader,writer); - return writer.toString(); - } - } -} diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogTest.java index 040e919d4b0..9c7069daf42 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/RequestLogTest.java @@ -18,31 +18,47 @@ package org.eclipse.jetty.server.handler; -import static org.hamcrest.Matchers.containsString; import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.contains; +import static org.hamcrest.Matchers.containsString; import java.io.IOException; import java.io.InputStream; import java.io.PrintWriter; +import java.util.ArrayList; import java.util.Arrays; -import java.util.concurrent.Exchanger; +import java.util.List; +import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; +import java.util.stream.Stream; +import javax.servlet.AsyncContext; import javax.servlet.ServletException; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; +import org.eclipse.jetty.http.BadMessageException; import org.eclipse.jetty.server.AbstractNCSARequestLog; +import org.eclipse.jetty.server.Handler; import org.eclipse.jetty.server.LocalConnector; import org.eclipse.jetty.server.Request; +import org.eclipse.jetty.server.RequestLog; +import org.eclipse.jetty.server.Response; import org.eclipse.jetty.server.Server; +import org.eclipse.jetty.util.BlockingArrayQueue; +import org.eclipse.jetty.util.component.AbstractLifeCycle; import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Assumptions; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; +import org.junit.jupiter.params.provider.MethodSource; public class RequestLogTest { - Exchanger _log; + Log _log; Server _server; LocalConnector _connector; @@ -50,19 +66,35 @@ public class RequestLogTest @BeforeEach public void before() throws Exception { - _log = new Exchanger(); + _log = new Log(); _server = new Server(); _connector = new LocalConnector(_server); _server.addConnector(_connector); - _server.setRequestLog(new Log()); + + } + + void testHandlerServerStart() throws Exception + { + _server.setRequestLog(_log); _server.setHandler(new TestHandler()); _server.start(); } + private void startServer() throws Exception + { + _server.start(); + } + + private void makeRequest(String requestPath) throws Exception + { + _connector.getResponse("GET "+requestPath+" HTTP/1.0\r\n\r\n"); + } + + + @AfterEach public void after() throws Exception { - _server.stop(); } @@ -70,35 +102,41 @@ public class RequestLogTest @Test public void testNotHandled() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo HTTP/1.0\" 404 ")); } @Test public void testRequestLine() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo?data=1 HTTP/1.0\nhost: host:80\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?data=1 HTTP/1.0\" 200 ")); _connector.getResponse("GET //bad/foo?data=1 HTTP/1.0\n\n"); - log = _log.exchange(null,5,TimeUnit.SECONDS); + log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET //bad/foo?data=1 HTTP/1.0\" 200 ")); _connector.getResponse("GET http://host:80/foo?data=1 HTTP/1.0\n\n"); - log = _log.exchange(null,5,TimeUnit.SECONDS); + log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET http://host:80/foo?data=1 HTTP/1.0\" 200 ")); } @Test public void testHTTP10Host() throws Exception { + testHandlerServerStart(); + _connector.getResponse( "GET /foo?name=value HTTP/1.0\n"+ "Host: servername\n"+ "\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?name=value")); assertThat(log,containsString(" 200 ")); } @@ -106,11 +144,13 @@ public class RequestLogTest @Test public void testHTTP11() throws Exception { + testHandlerServerStart(); + _connector.getResponse( "GET /foo?name=value HTTP/1.1\n"+ "Host: servername\n"+ "\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?name=value")); assertThat(log,containsString(" 200 ")); } @@ -118,11 +158,13 @@ public class RequestLogTest @Test public void testAbsolute() throws Exception { + testHandlerServerStart(); + _connector.getResponse( "GET http://hostname:8888/foo?name=value HTTP/1.1\n"+ "Host: servername\n"+ "\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET http://hostname:8888/foo?name=value")); assertThat(log,containsString(" 200 ")); } @@ -130,8 +172,10 @@ public class RequestLogTest @Test public void testQuery() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo?name=value HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?name=value")); assertThat(log,containsString(" 200 ")); } @@ -139,8 +183,10 @@ public class RequestLogTest @Test public void testSmallData() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo?data=42 HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?")); assertThat(log,containsString(" 200 42 ")); } @@ -148,8 +194,10 @@ public class RequestLogTest @Test public void testBigData() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo?data=102400 HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?")); assertThat(log,containsString(" 200 102400 ")); } @@ -157,8 +205,10 @@ public class RequestLogTest @Test public void testStatus() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo?status=206 HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?")); assertThat(log,containsString(" 206 0 ")); } @@ -166,8 +216,10 @@ public class RequestLogTest @Test public void testStatusData() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo?status=206&data=42 HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo?")); assertThat(log,containsString(" 206 42 ")); } @@ -175,83 +227,460 @@ public class RequestLogTest @Test public void testBadRequest() throws Exception { + testHandlerServerStart(); + _connector.getResponse("XXXXXXXXXXXX\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("\"- - -\"")); - assertThat(log,containsString(" 400 0 ")); + assertThat(log,containsString(" 400 ")); } @Test public void testBadCharacter() throws Exception { + testHandlerServerStart(); + _connector.getResponse("METHOD /f\00o HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("\"- - -\"")); - assertThat(log,containsString(" 400 0 ")); + assertThat(log,containsString(" 400 ")); } @Test public void testBadVersion() throws Exception { + testHandlerServerStart(); + _connector.getResponse("METHOD /foo HTTP/9\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("\"- - -\"")); - assertThat(log,containsString(" 400 0 ")); + assertThat(log,containsString(" 400 ")); } @Test public void testLongURI() throws Exception { + testHandlerServerStart(); + char[] chars = new char[10000]; Arrays.fill(chars,'o'); String ooo = new String(chars); _connector.getResponse("METHOD /f"+ooo+" HTTP/1.0\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("\"- - -\"")); - assertThat(log,containsString(" 414 0 ")); + assertThat(log,containsString(" 414 ")); } @Test public void testLongHeader() throws Exception { + testHandlerServerStart(); + char[] chars = new char[10000]; Arrays.fill(chars,'o'); String ooo = new String(chars); _connector.getResponse("METHOD /foo HTTP/1.0\name: f+"+ooo+"\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("\"METHOD /foo HTTP/1.0\"")); - assertThat(log,containsString(" 431 0 ")); + assertThat(log,containsString(" 431 ")); } @Test public void testBadRequestNoHost() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET /foo HTTP/1.1\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET /foo ")); - assertThat(log,containsString(" 400 0 ")); + assertThat(log,containsString(" 400 ")); } @Test public void testUseragentWithout() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET http://[:1]/foo HTTP/1.1\nReferer: http://other.site\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET http://[:1]/foo ")); - assertThat(log,containsString(" 400 0 \"http://other.site\" \"-\" - ")); + assertThat(log,containsString(" 400 50 \"http://other.site\" \"-\" - ")); } @Test public void testUseragentWith() throws Exception { + testHandlerServerStart(); + _connector.getResponse("GET http://[:1]/foo HTTP/1.1\nReferer: http://other.site\nUser-Agent: Mozilla/5.0 (test)\n\n"); - String log = _log.exchange(null,5,TimeUnit.SECONDS); + String log = _log.entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET http://[:1]/foo ")); - assertThat(log,containsString(" 400 0 \"http://other.site\" \"Mozilla/5.0 (test)\" - ")); + assertThat(log,containsString(" 400 50 \"http://other.site\" \"Mozilla/5.0 (test)\" - ")); } + + + // Tests from here use these parameters + public static Stream data() + { + List data = new ArrayList<>(); + + data.add(new Object[] { new NoopHandler(), "/noop", "\"GET /noop HTTP/1.0\" 404" }); + data.add(new Object[] { new HelloHandler(), "/hello", "\"GET /hello HTTP/1.0\" 200" }); + data.add(new Object[] { new ResponseSendErrorHandler(), "/sendError", "\"GET /sendError HTTP/1.0\" 599" }); + data.add(new Object[] { new ServletExceptionHandler(), "/sex", "\"GET /sex HTTP/1.0\" 500" }); + data.add(new Object[] { new IOExceptionHandler(), "/ioex", "\"GET /ioex HTTP/1.0\" 500" }); + data.add(new Object[] { new RuntimeExceptionHandler(), "/rtex", "\"GET /rtex HTTP/1.0\" 500" }); + data.add(new Object[] { new BadMessageHandler(), "/bad", "\"GET /bad HTTP/1.0\" 499" }); + data.add(new Object[] { new AbortHandler(), "/bad", "\"GET /bad HTTP/1.0\" 488" }); + + return data.stream().map(Arguments::of); + } + + @ParameterizedTest + @MethodSource("data") + public void testServerRequestLog(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + _server.setRequestLog(_log); + _server.setHandler(testHandler); + startServer(); + makeRequest(requestPath); + assertRequestLog(expectedLogEntry, _log); + } + + @ParameterizedTest + @MethodSource("data") + public void testLogHandlerWrapper(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + RequestLogHandler handler = new RequestLogHandler(); + handler.setRequestLog(_log); + handler.setHandler(testHandler); + _server.setHandler(handler); + startServer(); + makeRequest(requestPath); + assertRequestLog(expectedLogEntry, _log); + } + + @ParameterizedTest + @MethodSource("data") + public void testLogHandlerCollectionFirst(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + RequestLogHandler handler = new RequestLogHandler(); + handler.setRequestLog(_log); + HandlerCollection handlers = new HandlerCollection(); + handlers.setHandlers(new Handler[] { handler, testHandler }); + _server.setHandler(handlers); + startServer(); + makeRequest(requestPath); + assertRequestLog(expectedLogEntry, _log); + } + + + @ParameterizedTest + @MethodSource("data") + public void testLogHandlerCollectionLast(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + RequestLogHandler handler = new RequestLogHandler(); + handler.setRequestLog(_log); + // This is the old ordering of request handler and it cannot well handle thrown exception + Assumptions.assumeTrue( + testHandler instanceof NoopHandler || + testHandler instanceof HelloHandler || + testHandler instanceof ResponseSendErrorHandler + ); + + HandlerCollection handlers = new HandlerCollection(); + handlers.setHandlers(new Handler[] { testHandler, handler }); + _server.setHandler(handlers); + startServer(); + makeRequest(requestPath); + assertRequestLog(expectedLogEntry, _log); + } + + + @ParameterizedTest + @MethodSource("data") + public void testErrorHandler(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + _server.setRequestLog(_log); + AbstractHandler.ErrorDispatchHandler wrapper = new AbstractHandler.ErrorDispatchHandler() + { + @Override + protected void doNonErrorHandle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) + throws IOException, ServletException + { + testHandler.handle(target,baseRequest,request,response); + } + }; + + _server.setHandler(wrapper); + + List errors = new ArrayList<>(); + ErrorHandler errorHandler = new ErrorHandler() + { + @Override + public void doError(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException + { + errors.add(baseRequest.getRequestURI()); + super.doError(target, baseRequest, request, response); + } + }; + _server.addBean(errorHandler); + startServer(); + makeRequest(requestPath); + assertRequestLog(expectedLogEntry, _log); + + if (!(testHandler instanceof HelloHandler)) + assertThat(errors,contains(requestPath)); + } + + + @ParameterizedTest + @MethodSource("data") + public void testOKErrorHandler(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + _server.setRequestLog(_log); + AbstractHandler.ErrorDispatchHandler wrapper = new AbstractHandler.ErrorDispatchHandler() + { + @Override + protected void doNonErrorHandle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) + throws IOException, ServletException + { + testHandler.handle(target,baseRequest,request,response); + } + }; + + _server.setHandler(wrapper); + + ErrorHandler errorHandler = new OKErrorHandler(); + _server.addBean(errorHandler); + startServer(); + makeRequest(requestPath); + + expectedLogEntry = "\"GET " + requestPath + " HTTP/1.0\" 200"; + assertRequestLog(expectedLogEntry, _log); + } + + + @ParameterizedTest + @MethodSource("data") + public void testAsyncDispatch(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + _server.setRequestLog(_log); + _server.setHandler(new AbstractHandler() + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) + throws IOException, ServletException + { + if (Boolean.TRUE.equals(request.getAttribute("ASYNC"))) + testHandler.handle(target,baseRequest,request,response); + else + { + request.setAttribute("ASYNC",Boolean.TRUE); + AsyncContext ac = request.startAsync(); + ac.setTimeout(1000); + ac.dispatch(); + baseRequest.setHandled(true); + } + } + }); + startServer(); + makeRequest(requestPath); + + assertRequestLog(expectedLogEntry, _log); + } + + + @ParameterizedTest + @MethodSource("data") + public void testAsyncComplete(Handler testHandler, String requestPath, String expectedLogEntry) throws Exception + { + _server.setRequestLog(_log); + _server.setHandler(new AbstractHandler() + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) + throws IOException, ServletException + { + if (Boolean.TRUE.equals(request.getAttribute("ASYNC"))) + testHandler.handle(target,baseRequest,request,response); + else + { + request.setAttribute("ASYNC",Boolean.TRUE); + AsyncContext ac = request.startAsync(); + ac.setTimeout(1000); + baseRequest.setHandled(true); + _server.getThreadPool().execute(()-> + { + try + { + try + { + baseRequest.setHandled(false); + testHandler.handle(target, baseRequest, request, response); + if (!baseRequest.isHandled()) + response.sendError(404); + } + catch (BadMessageException bad) + { + response.sendError(bad.getCode()); + } + catch (Exception e) + { + response.sendError(500); + } + } + catch(Throwable th) + { + throw new RuntimeException(th); + } + ac.complete(); + }); + } + } + }); + startServer(); + makeRequest(requestPath); + assertRequestLog(expectedLogEntry, _log); + } + + + private void assertRequestLog(final String expectedLogEntry, Log log) throws Exception + { + String line = log.entries.poll(5, TimeUnit.SECONDS); + Assertions.assertNotNull(line); + assertThat(line,containsString(expectedLogEntry)); + Assertions.assertTrue(log.entries.isEmpty()); + } + + public static class CaptureLog extends AbstractLifeCycle implements RequestLog + { + public BlockingQueue log = new BlockingArrayQueue<>(); + + @Override + public void log(Request request, Response response) + { + int status = response.getCommittedMetaData().getStatus(); + log.add(String.format("%s %s %s %03d",request.getMethod(),request.getRequestURI(),request.getProtocol(),status)); + } + } + + private static abstract class AbstractTestHandler extends AbstractHandler + { + @Override + public String toString() + { + return this.getClass().getSimpleName(); + } + } + + private static class NoopHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + } + } + + private static class HelloHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + response.setContentType("text/plain"); + response.getWriter().print("Hello World"); + if (baseRequest!=null) + baseRequest.setHandled(true); + } + } + + private static class ResponseSendErrorHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + response.sendError(599,"expected"); + if (baseRequest!=null) + baseRequest.setHandled(true); + } + } + + private static class ServletExceptionHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + throw new ServletException("expected"); + } + } + + private static class IOExceptionHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + throw new IOException("expected"); + } + } + + private static class RuntimeExceptionHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + throw new RuntimeException("expected"); + } + } + + private static class BadMessageHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + throw new BadMessageException(499); + } + } + + private static class AbortHandler extends AbstractTestHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + BadMessageException bad = new BadMessageException(488); + baseRequest.getHttpChannel().abort(bad); + throw bad; + } + } + + public static class OKErrorHandler extends ErrorHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException + { + if (baseRequest.isHandled() || response.isCommitted()) + { + return; + } + + // collect error details + String reason = (response instanceof Response)?((Response)response).getReason():null; + int status = response.getStatus(); + + // intentionally set response status to OK (this is a test to see what is actually logged) + response.setStatus(200); + response.setContentType("text/plain"); + PrintWriter out = response.getWriter(); + out.printf("Error %d: %s%n",status,reason); + baseRequest.setHandled(true); + } + } + private class Log extends AbstractNCSARequestLog { + public BlockingQueue entries = new BlockingArrayQueue<>(); + + Log() { super.setExtended(true); super.setLogLatency(true); @@ -269,7 +698,7 @@ public class RequestLogTest { try { - _log.exchange(requestEntry); + entries.add(requestEntry); } catch(Exception e) { @@ -277,7 +706,7 @@ public class RequestLogTest } } } - + private class TestHandler extends AbstractHandler { @Override @@ -286,7 +715,7 @@ public class RequestLogTest String q = request.getQueryString(); if (q==null) return; - + baseRequest.setHandled(true); for (String action : q.split("\\&")) { @@ -300,12 +729,12 @@ public class RequestLogTest response.setStatus(Integer.parseInt(value)); break; } - + case "data": { int data = Integer.parseInt(value); PrintWriter out = response.getWriter(); - + int w=0; while (w(); RequestLog log=new Log(); - RequestLogHandler logHandler = new RequestLogHandler(); - logHandler.setRequestLog(log); - _server.setHandler(logHandler); + _server.setRequestLog(log); _expectedLogs=1; _expectedCode="200 "; ServletContextHandler context = new ServletContextHandler(ServletContextHandler.NO_SESSIONS); context.setContextPath("/ctx"); - logHandler.setHandler(context); + _server.setHandler(context); context.addEventListener(new DebugListener()); _errorHandler = new ErrorPageErrorHandler(); diff --git a/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/ServletRequestLogTest.java b/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/ServletRequestLogTest.java index 32d45af3edf..2ab0f0b5b7a 100644 --- a/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/ServletRequestLogTest.java +++ b/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/ServletRequestLogTest.java @@ -53,7 +53,6 @@ import org.eclipse.jetty.server.handler.ContextHandlerCollection; import org.eclipse.jetty.server.handler.DefaultHandler; import org.eclipse.jetty.server.handler.ErrorHandler; import org.eclipse.jetty.server.handler.HandlerCollection; -import org.eclipse.jetty.server.handler.RequestLogHandler; import org.eclipse.jetty.toolchain.test.IO; import org.eclipse.jetty.util.component.AbstractLifeCycle; import org.eclipse.jetty.util.log.Log; @@ -313,12 +312,9 @@ public class ServletRequestLogTest // Next the behavior as defined by etc/jetty-requestlog.xml // the id="RequestLog" - RequestLogHandler requestLog = new RequestLogHandler(); CaptureLog captureLog = new CaptureLog(); - requestLog.setRequestLog(captureLog); + server.setRequestLog(captureLog); - handlers.addHandler(requestLog); - // Lastly, the behavior as defined by deployment of a webapp // Add the Servlet Context ServletContextHandler app = new ServletContextHandler(ServletContextHandler.SESSIONS); @@ -404,12 +400,9 @@ public class ServletRequestLogTest // Next the behavior as defined by etc/jetty-requestlog.xml // the id="RequestLog" - RequestLogHandler requestLog = new RequestLogHandler(); CaptureLog captureLog = new CaptureLog(); - requestLog.setRequestLog(captureLog); + server.setRequestLog(captureLog); - handlers.addHandler(requestLog); - // Lastly, the behavior as defined by deployment of a webapp // Add the Servlet Context ServletContextHandler app = new ServletContextHandler(ServletContextHandler.SESSIONS); @@ -493,12 +486,9 @@ public class ServletRequestLogTest // Next the behavior as defined by etc/jetty-requestlog.xml // the id="RequestLog" - RequestLogHandler requestLog = new RequestLogHandler(); CaptureLog captureLog = new CaptureLog(); - requestLog.setRequestLog(captureLog); + server.setRequestLog(captureLog); - handlers.addHandler(requestLog); - // Lastly, the behavior as defined by deployment of a webapp // Add the Servlet Context ServletContextHandler app = new ServletContextHandler(ServletContextHandler.SESSIONS); @@ -587,14 +577,9 @@ public class ServletRequestLogTest // Next the proposed behavioral change to etc/jetty-requestlog.xml // the id="RequestLog" - RequestLogHandler requestLog = new RequestLogHandler(); CaptureLog captureLog = new CaptureLog(); - requestLog.setRequestLog(captureLog); - - Handler origServerHandler = server.getHandler(); - requestLog.setHandler(origServerHandler); - server.setHandler(requestLog); - + server.setRequestLog(captureLog); + // Lastly, the behavior as defined by deployment of a webapp // Add the Servlet Context ServletContextHandler app = new ServletContextHandler(ServletContextHandler.SESSIONS); diff --git a/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/ServerTimeoutsTest.java b/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/ServerTimeoutsTest.java index 399ec3418f7..ba32c40d9fa 100644 --- a/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/ServerTimeoutsTest.java +++ b/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/ServerTimeoutsTest.java @@ -20,9 +20,14 @@ package org.eclipse.jetty.http.client; import static org.eclipse.jetty.http.client.Transport.FCGI; import static org.eclipse.jetty.http.client.Transport.UNIX_SOCKET; +import static org.hamcrest.Matchers.containsString; +import static org.hamcrest.Matchers.instanceOf; +import static org.hamcrest.Matchers.is; +import static org.junit.Assert.assertThat; import static org.junit.jupiter.api.Assertions.assertArrayEquals; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertTrue; import java.io.IOException; @@ -56,10 +61,10 @@ import org.eclipse.jetty.server.Handler; import org.eclipse.jetty.server.HttpChannel; import org.eclipse.jetty.server.Request; import org.eclipse.jetty.server.handler.AbstractHandler; +import org.eclipse.jetty.util.BlockingArrayQueue; import org.eclipse.jetty.util.Callback; import org.eclipse.jetty.util.IO; import org.eclipse.jetty.util.log.StacklessLogging; -import org.eclipse.jetty.util.thread.QueuedThreadPool; import org.junit.jupiter.api.Assumptions; import org.junit.jupiter.params.ParameterizedTest; import org.junit.jupiter.params.provider.ArgumentsSource; @@ -616,6 +621,7 @@ public class ServerTimeoutsTest extends AbstractTest { init(transport); int bytesPerSecond = 20; + scenario.requestLog.clear(); scenario.httpConfig.setMinRequestDataRate(bytesPerSecond); CountDownLatch handlerLatch = new CountDownLatch(1); scenario.start(new AbstractHandler.ErrorDispatchHandler() @@ -643,13 +649,15 @@ public class ServerTimeoutsTest extends AbstractTest }); DeferredContentProvider contentProvider = new DeferredContentProvider(); - CountDownLatch resultLatch = new CountDownLatch(1); + BlockingQueue results = new BlockingArrayQueue<>(); scenario.client.newRequest(scenario.newURI()) .content(contentProvider) .send(result -> { - if (result.getResponse().getStatus() == HttpStatus.REQUEST_TIMEOUT_408) - resultLatch.countDown(); + if (result.isFailed()) + results.offer(result.getFailure()); + else + results.offer(result.getResponse().getStatus()); }); for (int i = 0; i < 3; ++i) @@ -659,9 +667,17 @@ public class ServerTimeoutsTest extends AbstractTest } contentProvider.close(); + assertThat(scenario.requestLog.poll(5,TimeUnit.SECONDS), containsString(" 408")); + // Request should timeout. assertTrue(handlerLatch.await(5, TimeUnit.SECONDS)); - assertTrue(resultLatch.await(5, TimeUnit.SECONDS)); + + Object result = results.poll(5, TimeUnit.SECONDS); + assertNotNull(result); + if (result instanceof Integer) + assertThat((Integer)result,is(408)); + else + assertThat(result,instanceOf(Throwable.class)); } @ParameterizedTest diff --git a/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/TransportScenario.java b/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/TransportScenario.java index 752d03aa382..174c1e51f1c 100644 --- a/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/TransportScenario.java +++ b/tests/test-http-client-transport/src/test/java/org/eclipse/jetty/http/client/TransportScenario.java @@ -25,6 +25,7 @@ import java.nio.file.Path; import java.util.ArrayList; import java.util.List; import java.util.Optional; +import java.util.concurrent.BlockingQueue; import javax.servlet.http.HttpServlet; @@ -56,6 +57,7 @@ import org.eclipse.jetty.servlet.ServletHolder; import org.eclipse.jetty.toolchain.test.MavenTestingUtils; import org.eclipse.jetty.unixsocket.UnixSocketConnector; import org.eclipse.jetty.unixsocket.client.HttpClientTransportOverUnixSockets; +import org.eclipse.jetty.util.BlockingArrayQueue; import org.eclipse.jetty.util.SocketAddressResolver; import org.eclipse.jetty.util.log.Log; import org.eclipse.jetty.util.log.Logger; @@ -75,6 +77,7 @@ public class TransportScenario protected String servletPath = "/servlet"; protected HttpClient client; protected Path sockFile; + protected final BlockingQueue requestLog= new BlockingArrayQueue<>(); public TransportScenario(final Transport transport) throws IOException { @@ -320,7 +323,15 @@ public class TransportScenario server.addBean(mbeanContainer); connector = newServerConnector(server); server.addConnector(connector); + + server.setRequestLog((request, response) -> + { + int status = response.getCommittedMetaData().getStatus(); + requestLog.offer(String.format("%s %s %s %03d",request.getMethod(),request.getRequestURI(),request.getProtocol(),status)); + }); + server.setHandler(handler); + try { server.start(); @@ -375,4 +386,6 @@ public class TransportScenario } } } + + } diff --git a/tests/test-webapps/test-jetty-webapp/src/test/java/org/eclipse/jetty/TestServer.java b/tests/test-webapps/test-jetty-webapp/src/test/java/org/eclipse/jetty/TestServer.java index a078dac760e..ca61e939857 100644 --- a/tests/test-webapps/test-jetty-webapp/src/test/java/org/eclipse/jetty/TestServer.java +++ b/tests/test-webapps/test-jetty-webapp/src/test/java/org/eclipse/jetty/TestServer.java @@ -34,7 +34,6 @@ import org.eclipse.jetty.server.handler.ContextHandlerCollection; import org.eclipse.jetty.server.handler.DefaultHandler; import org.eclipse.jetty.server.handler.HandlerCollection; import org.eclipse.jetty.server.handler.HandlerWrapper; -import org.eclipse.jetty.server.handler.RequestLogHandler; import org.eclipse.jetty.server.handler.ResourceHandler; import org.eclipse.jetty.server.session.DefaultSessionCache; import org.eclipse.jetty.server.session.FileSessionDataStore; @@ -105,9 +104,8 @@ public class TestServer // Handlers HandlerCollection handlers = new HandlerCollection(); ContextHandlerCollection contexts = new ContextHandlerCollection(); - RequestLogHandler requestLogHandler = new RequestLogHandler(); handlers.setHandlers(new Handler[] - { contexts, new DefaultHandler(), requestLogHandler }); + { contexts, new DefaultHandler() }); // Add restart handler to test the ability to save sessions and restart RestartHandler restart = new RestartHandler(); @@ -125,7 +123,7 @@ public class TestServer File log=File.createTempFile("jetty-yyyy_mm_dd", "log"); NCSARequestLog requestLog = new NCSARequestLog(log.toString()); requestLog.setExtended(false); - requestLogHandler.setRequestLog(requestLog); + server.setRequestLog(requestLog); server.setStopAtShutdown(true);