From 557f40f41fb50bd07caaa4fa65c5f0a27a5601a2 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Tue, 6 Nov 2018 11:46:26 +0100 Subject: [PATCH 01/24] Issue #113 - CustomRequestLog created new CustomRequestLog class Signed-off-by: Lachlan Roberts --- .../requestlog/jmh/RequestLogBenchmark.java | 24 +- .../jetty/server/CustomRequestLog.java | 436 ++++++++++++++++++ .../server/handler/CustomRequestLogTest.java | 122 +++++ 3 files changed, 566 insertions(+), 16 deletions(-) create mode 100644 jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java create mode 100644 jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java 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 index 9092a5fca6f..7058b0d2045 100644 --- 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 @@ -18,10 +18,6 @@ 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; @@ -43,6 +39,10 @@ import org.openjdk.jmh.runner.RunnerException; import org.openjdk.jmh.runner.options.Options; import org.openjdk.jmh.runner.options.OptionsBuilder; +import static java.lang.invoke.MethodHandles.dropArguments; +import static java.lang.invoke.MethodHandles.foldArguments; +import static java.lang.invoke.MethodType.methodType; + @State(Scope.Benchmark) @@ -79,14 +79,7 @@ public class RequestLogBenchmark } } - private ThreadLocal buffers = new ThreadLocal() - { - @Override - protected StringBuilder initialValue() - { - return new StringBuilder(256); - } - }; + private ThreadLocal buffers = ThreadLocal.withInitial(() -> new StringBuilder(256)); MethodHandle logHandle; Object[] iteratedLog; @@ -96,8 +89,7 @@ public class RequestLogBenchmark { 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 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); @@ -171,7 +163,7 @@ public class RequestLogBenchmark try { StringBuilder b = buffers.get(); - logHandle.invoke(buffers.get(), request); + logHandle.invoke(b, request); String l = b.toString(); b.setLength(0); return l; @@ -202,7 +194,7 @@ public class RequestLogBenchmark public String testHandle() { return logMethodHandle(Long.toString(ThreadLocalRandom.current().nextLong())); - }; + } public static void main(String[] args) throws RunnerException diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java new file mode 100644 index 00000000000..e0beb211a9d --- /dev/null +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -0,0 +1,436 @@ +// +// ======================================================================== +// 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; + +import java.io.IOException; +import java.lang.invoke.MethodHandle; +import java.lang.invoke.MethodHandles; +import java.lang.invoke.MethodType; +import java.util.ArrayList; +import java.util.List; +import java.util.Locale; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + +import org.eclipse.jetty.http.pathmap.PathMappings; +import org.eclipse.jetty.util.DateCache; +import org.eclipse.jetty.util.annotation.ManagedAttribute; +import org.eclipse.jetty.util.component.AbstractLifeCycle; +import org.eclipse.jetty.util.log.Log; +import org.eclipse.jetty.util.log.Logger; + +import static java.lang.invoke.MethodHandles.dropArguments; +import static java.lang.invoke.MethodHandles.foldArguments; +import static java.lang.invoke.MethodType.methodType; + +public class CustomRequestLog extends AbstractLifeCycle implements RequestLog +{ + protected static final Logger LOG = Log.getLogger(CustomRequestLog.class); + + private static ThreadLocal _buffers = ThreadLocal.withInitial(() -> new StringBuilder(256)); + + private String[] _ignorePaths; + private boolean _extended; + private transient PathMappings _ignorePathMap; + private boolean _preferProxiedForAddress; + private transient DateCache _logDateCache; + private String _logDateFormat = "dd/MMM/yyyy:HH:mm:ss Z"; + private Locale _logLocale = Locale.getDefault(); + private String _logTimeZone = "GMT"; + + private final MethodHandle _logHandle; + private final String _format; + + public CustomRequestLog(String formatString) + { + try + { + _format = formatString; + _logHandle = getLogHandle(formatString); + } + catch (Throwable t) + { + throw new IllegalStateException(); + } + } + + /* ------------------------------------------------------------ */ + + /** + * Is logging enabled + * @return true if logging is enabled + */ + protected boolean isEnabled() + { + return true; + } + + /* ------------------------------------------------------------ */ + + /** + * Write requestEntry out. (to disk or slf4j log) + * @param requestEntry the request entry + * @throws IOException if unable to write the entry + */ + protected void write(String requestEntry) throws IOException + { + } + + /* ------------------------------------------------------------ */ + + + /** + * Writes the request and response information to the output stream. + * + * @see org.eclipse.jetty.server.RequestLog#log(Request, Response) + */ + @Override + public void log(Request request, Response response) + { + try + { + if (_ignorePathMap != null && _ignorePathMap.getMatch(request.getRequestURI()) != null) + return; + + if (!isEnabled()) + return; + + StringBuilder sb = _buffers.get(); + sb.setLength(0); + + _logHandle.invoke(sb, request); + + String log = sb.toString(); + write(log); + } + catch (Throwable e) + { + LOG.warn(e); + } + } + + /** + * Extract the user authentication + * @param request The request to extract from + * @return The string to log for authenticated user. + */ + protected String getAuthentication(Request request) + { + Authentication authentication = request.getAuthentication(); + + if (authentication instanceof Authentication.User) + return ((Authentication.User)authentication).getUserIdentity().getUserPrincipal().getName(); + + // TODO extract the user name if it is Authentication.Deferred and return as '?username' + + return null; + } + + /** + * Set request paths that will not be logged. + * + * @param ignorePaths array of request paths + */ + public void setIgnorePaths(String[] ignorePaths) + { + _ignorePaths = ignorePaths; + } + + /** + * Retrieve the request paths that will not be logged. + * + * @return array of request paths + */ + public String[] getIgnorePaths() + { + return _ignorePaths; + } + + /** + * Controls whether the actual IP address of the connection or the IP address from the X-Forwarded-For header will + * be logged. + * + * @param preferProxiedForAddress true - IP address from header will be logged, false - IP address from the + * connection will be logged + */ + public void setPreferProxiedForAddress(boolean preferProxiedForAddress) + { + _preferProxiedForAddress = preferProxiedForAddress; + } + + /** + * Retrieved log X-Forwarded-For IP address flag. + * + * @return value of the flag + */ + public boolean getPreferProxiedForAddress() + { + return _preferProxiedForAddress; + } + + /** + * Set the extended request log format flag. + * + * @param extended true - log the extended request information, false - do not log the extended request information + */ + public void setExtended(boolean extended) + { + _extended = extended; + } + + /** + * Retrieve the extended request log format flag. + * + * @return value of the flag + */ + @ManagedAttribute("use extended NCSA format") + public boolean isExtended() + { + return _extended; + } + + /** + * Set up request logging and open log file. + * + * @see org.eclipse.jetty.util.component.AbstractLifeCycle#doStart() + */ + @Override + protected synchronized void doStart() throws Exception + { + if (_logDateFormat != null) + { + _logDateCache = new DateCache(_logDateFormat, _logLocale ,_logTimeZone); + } + + if (_ignorePaths != null && _ignorePaths.length > 0) + { + _ignorePathMap = new PathMappings<>(); + for (int i = 0; i < _ignorePaths.length; i++) + _ignorePathMap.put(_ignorePaths[i], _ignorePaths[i]); + } + else + _ignorePathMap = null; + + super.doStart(); + } + + @Override + protected void doStop() throws Exception + { + _logDateCache = null; + super.doStop(); + } + + /** + * Set the timestamp format for request log entries in the file. If this is not set, the pre-formated request + * timestamp is used. + * + * @param format timestamp format string + */ + public void setLogDateFormat(String format) + { + _logDateFormat = format; + } + + /** + * Retrieve the timestamp format string for request log entries. + * + * @return timestamp format string. + */ + public String getLogDateFormat() + { + return _logDateFormat; + } + + /** + * Set the locale of the request log. + * + * @param logLocale locale object + */ + public void setLogLocale(Locale logLocale) + { + _logLocale = logLocale; + } + + /** + * Retrieve the locale of the request log. + * + * @return locale object + */ + public Locale getLogLocale() + { + return _logLocale; + } + + /** + * Set the timezone of the request log. + * + * @param tz timezone string + */ + public void setLogTimeZone(String tz) + { + _logTimeZone = tz; + } + + /** + * Retrieve the timezone of the request log. + * + * @return timezone string + */ + @ManagedAttribute("the timezone") + public String getLogTimeZone() + { + return _logTimeZone; + } + + + private static void append(StringBuilder buf, String s) + { + if (s==null || s.length()==0) + buf.append('-'); + else + buf.append(s); + } + + private static void append(String s, StringBuilder buf) + { + append(buf, s); + } + + public static void logClientIP(StringBuilder b, Request request) + { + b.append(request.getRemoteAddr()); + } + + public static void main(String[] args) throws Throwable + { + Request request = new Request(null, null); + + + String formatString = "clientIP: %a | "; + MethodHandle logHandle = getLogHandle(formatString); + + + StringBuilder b = new StringBuilder(); + logHandle.invoke(b, request); + System.err.println(b.toString()); + + } + + private static MethodHandle getLogHandle(String formatString) throws NoSuchMethodException, IllegalAccessException + { + //TODO add response to signature + MethodType logType = methodType(Void.TYPE, StringBuilder.class, Request.class); + MethodHandle append = MethodHandles.lookup().findStatic(CustomRequestLog.class, "append", methodType(Void.TYPE, String.class, StringBuilder.class)); + MethodHandle logHandle = dropArguments(append.bindTo("\n"), 1, Request.class); + + for (Token s : tokenize(formatString)) + { + if (s.isLiteralString()) + { + logHandle = foldArguments(logHandle, dropArguments(append.bindTo(s.literal), 1, Request.class)); + } + else + { + switch (s.code) + { + + case "a": + { + String method = "logClientIP"; + MethodHandle specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); + logHandle = foldArguments(logHandle, specificHandle); + break; + } + } + } + } + + return logHandle; + } + + private static List tokenize(String value) + { + List tokens = new ArrayList<>(); + + final Pattern PERCENT_CODE = Pattern.compile("(?.*)%(?:\\{(?[^{}]+)})?(?[a-zA-Z%])"); + final Pattern LITERAL = Pattern.compile("(?.*%(?:\\{[^{}]+})?[a-zA-Z%])(?.*)"); + + while(value.length()>0) + { + Matcher m = PERCENT_CODE.matcher(value); + Matcher m2 = LITERAL.matcher(value); + if (m.matches()) + { + String code = m.group("code"); + String arg = m.group("arg"); + + tokens.add(new Token(code, arg)); + value = m.group("remaining"); + continue; + } + + String literal; + if (m2.matches()) + { + literal = m2.group("literal"); + value = m2.group("remaining"); + } + else + { + literal = value; + value = ""; + } + tokens.add(new Token(literal)); + + } + return tokens; + } + + + + + private static class Token + { + public boolean isLiteralString() + { + return(literal != null); + } + + public boolean isPercentCode() + { + return(code != null); + } + + public String code = null; + public String arg = null; + public String literal = null; + + public Token(String code, String arg) + { + this.code = code; + this.arg = arg; + } + + public Token(String literal) + { + this.literal = literal; + } + } +} diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java new file mode 100644 index 00000000000..6556508a4de --- /dev/null +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -0,0 +1,122 @@ +// +// ======================================================================== +// 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 java.io.IOException; +import java.util.concurrent.BlockingQueue; +import java.util.concurrent.TimeUnit; +import javax.servlet.ServletException; +import javax.servlet.http.HttpServletRequest; +import javax.servlet.http.HttpServletResponse; + +import org.eclipse.jetty.server.CustomRequestLog; +import org.eclipse.jetty.server.LocalConnector; +import org.eclipse.jetty.server.Request; +import org.eclipse.jetty.server.Server; +import org.eclipse.jetty.util.BlockingArrayQueue; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.containsString; + +public class CustomRequestLogTest +{ + Log _log; + Server _server; + LocalConnector _connector; + + + @BeforeEach + public void before() throws Exception + { + _server = new Server(); + _connector = new LocalConnector(_server); + _server.addConnector(_connector); + + } + + void testHandlerServerStart(String formatString) throws Exception + { + _log = new Log(formatString); + _server.setRequestLog(_log); + _server.setHandler(new TestHandler()); + _server.start(); + } + + @AfterEach + public void after() throws Exception + { + _server.stop(); + } + + + @Test + public void testQuery() throws Exception + { + testHandlerServerStart("clientIP: %a"); + + _connector.getResponse("GET /foo?name=value HTTP/1.0\n\n"); + String log = _log.entries.poll(5,TimeUnit.SECONDS); + assertThat(log,containsString("GET /foo?name=value")); + assertThat(log,containsString(" 200 ")); + } + + + + + private class Log extends CustomRequestLog + { + public BlockingQueue entries = new BlockingArrayQueue<>(); + + public Log(String formatString) + { + super(formatString); + } + + @Override + protected boolean isEnabled() + { + return true; + } + + @Override + public void write(String requestEntry) throws IOException + { + try + { + entries.add(requestEntry); + } + catch(Exception e) + { + e.printStackTrace(); + } + } + } + + private class TestHandler extends AbstractHandler + { + @Override + public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException + { + baseRequest.setHandled(true); + } + } +} From 012d412ccb40c4545f0c54bdd0bdd2a63aa74bbb Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Tue, 6 Nov 2018 11:48:08 +0100 Subject: [PATCH 02/24] Issue #113 - CustomRequestLog javadoc detailing the custom log formats Signed-off-by: Lachlan Roberts --- .../jetty/server/CustomRequestLog.java | 231 ++++++++++++++++++ 1 file changed, 231 insertions(+) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index e0beb211a9d..16f1f2c7fa1 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -39,6 +39,237 @@ import static java.lang.invoke.MethodHandles.dropArguments; import static java.lang.invoke.MethodHandles.foldArguments; import static java.lang.invoke.MethodType.methodType; +/** + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + +
Format StringDescription
%%The percent sign.
%aClient IP address of the request.
%{c}aUnderlying peer IP address of the connection.
%ALocal IP-address.
%BSize of response in bytes, excluding HTTP headers.
%bSize of response in bytes, excluding HTTP headers. In CLF format, i.e. a '-' rather than a 0 when no bytes are sent.
%{VARNAME}CThe contents of cookie VARNAME in the request sent to the server. Only version 0 cookies are fully supported.
%DThe time taken to serve the request, in microseconds.
%{VARNAME}eThe contents of the environment variable VARNAME.
%fFilename.
%hRemote hostname. Will log the IP address if HostnameLookups is set to Off, which is the default. If it logs the hostname for only a few hosts, you probably have access control directives mentioning them by name. See the Require host documentation.
%HThe request protocol.
%{VARNAME}iThe contents of VARNAME: header line(s) in the request sent to the server. Changes made by other modules (e.g. mod_headers) affect this. If you're interested in what the request header was prior to when most modules would have modified it, use mod_setenvif to copy the header into an internal environment variable and log that value with the %{VARNAME}e described above.
%kNumber of keepalive requests handled on this connection. Interesting if KeepAlive is being used, so that, for example, a '1' means the first keepalive request after the initial one, '2' the second, etc...; otherwise this is always 0 (indicating the initial request).
%lRemote logname (from identd, if supplied). This will return a dash unless mod_ident is present and IdentityCheck is set On.
%LThe request log ID from the error log (or '-' if nothing has been logged to the error log for this request). Look for the matching error log line to see what request caused what error.
%mThe request method.
%{VARNAME}nThe contents of note VARNAME from another module.
%{VARNAME}oThe contents of VARNAME: header line(s) in the reply.
%pThe canonical port of the server serving the request.
%{format}pThe canonical port of the server serving the request, or the server's actual port, or the client's actual port. Valid formats are canonical, local, or remote.
%PThe process ID of the child that serviced the request.
%{format}PThe process ID or thread ID of the child that serviced the request. Valid formats are pid, tid, and hextid. hextid requires APR 1.2.0 or higher.
%qThe query string (prepended with a ? if a query string exists, otherwise an empty string).
%rFirst line of request.
%RThe handler generating the response (if any).
%sStatus. For requests that have been internally redirected, this is the status of the original request. Use %>s for the final status.
%tTime the request was received, in the format [18/Sep/2011:19:18:28 -0400]. The last number indicates the timezone offset from GMT
%{format}t + The time, in the form given by format, which should be in an extended strftime(3) format (potentially localized). If the format starts with begin: (default) the time is taken at the beginning of the request processing. If it starts with end: it is the time when the log entry gets written, close to the end of the request processing. + +

In addition to the formats supported by strftime(3), the following format tokens are supported: + + 
+ sec         number of seconds since the Epoch
+ msec        number of milliseconds since the Epoch
+ usec        number of microseconds since the Epoch
+ msec_frac   millisecond fraction
+ usec_frac   microsecond fraction
+
+ + These tokens can not be combined with each other or strftime(3) formatting in the same format string. You can use multiple %{format}t tokens instead. +
%TThe time taken to serve the request, in seconds.
%{UNIT}TThe time taken to serve the request, in a time unit given by UNIT. Valid units are ms for milliseconds, us for microseconds, and s for seconds. Using s gives the same result as %T without any format; using us gives the same result as %D. Combining %T with a unit is available in 2.4.13 and later.
%uRemote user if the request was authenticated. May be bogus if return status (%s) is 401 (unauthorized).
%UThe URL path requested, not including any query string.
%vThe canonical ServerName of the server serving the request.
%VThe server name according to the UseCanonicalName setting.
%XConnection status when response is completed: + X = Connection aborted before the response completed. + + = Connection may be kept alive after the response is sent. + - = Connection will be closed after the response is sent.
%IBytes received, including request and headers. Cannot be zero. You need to enable mod_logio to use this.
%OBytes sent, including headers. May be zero in rare cases such as when a request is aborted before a response is sent. You need to enable mod_logio to use this.
%SBytes transferred (received and sent), including request and headers, cannot be zero. This is the combination of %I and %O. You need to enable mod_logio to use this.
%{VARNAME}^tiThe contents of VARNAME: trailer line(s) in the request sent to the server.
%{VARNAME}^toThe contents of VARNAME: trailer line(s) in the response sent from the server.
+ */ public class CustomRequestLog extends AbstractLifeCycle implements RequestLog { protected static final Logger LOG = Log.getLogger(CustomRequestLog.class); From 4be4b4e7b48b986f1fc934abe561cef81144e41b Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Tue, 6 Nov 2018 12:16:22 +0100 Subject: [PATCH 03/24] Issue #113 - CustomRequestLog update logHandle directly rather than creating list of tokens Signed-off-by: Lachlan Roberts --- .../jetty/server/CustomRequestLog.java | 118 +++++------------- 1 file changed, 33 insertions(+), 85 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index 16f1f2c7fa1..f0cb7d45556 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -22,8 +22,6 @@ import java.io.IOException; import java.lang.invoke.MethodHandle; import java.lang.invoke.MethodHandles; import java.lang.invoke.MethodType; -import java.util.ArrayList; -import java.util.List; import java.util.Locale; import java.util.regex.Matcher; import java.util.regex.Pattern; @@ -286,18 +284,16 @@ public class CustomRequestLog extends AbstractLifeCycle implements RequestLog private String _logTimeZone = "GMT"; private final MethodHandle _logHandle; - private final String _format; public CustomRequestLog(String formatString) { try { - _format = formatString; _logHandle = getLogHandle(formatString); } catch (Throwable t) { - throw new IllegalStateException(); + throw new IllegalStateException(t); } } @@ -549,119 +545,71 @@ public class CustomRequestLog extends AbstractLifeCycle implements RequestLog b.append(request.getRemoteAddr()); } - public static void main(String[] args) throws Throwable + + //TODO add response to signature + private static final MethodType LOG_TYPE = methodType(Void.TYPE, StringBuilder.class, Request.class); + + private MethodHandle getLogHandle(String formatString) throws Throwable { - Request request = new Request(null, null); - - - String formatString = "clientIP: %a | "; - MethodHandle logHandle = getLogHandle(formatString); - - - StringBuilder b = new StringBuilder(); - logHandle.invoke(b, request); - System.err.println(b.toString()); - - } - - private static MethodHandle getLogHandle(String formatString) throws NoSuchMethodException, IllegalAccessException - { - //TODO add response to signature - MethodType logType = methodType(Void.TYPE, StringBuilder.class, Request.class); MethodHandle append = MethodHandles.lookup().findStatic(CustomRequestLog.class, "append", methodType(Void.TYPE, String.class, StringBuilder.class)); MethodHandle logHandle = dropArguments(append.bindTo("\n"), 1, Request.class); - for (Token s : tokenize(formatString)) - { - if (s.isLiteralString()) - { - logHandle = foldArguments(logHandle, dropArguments(append.bindTo(s.literal), 1, Request.class)); - } - else - { - switch (s.code) - { - - case "a": - { - String method = "logClientIP"; - MethodHandle specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - logHandle = foldArguments(logHandle, specificHandle); - break; - } - } - } - } - - return logHandle; - } - - private static List tokenize(String value) - { - List tokens = new ArrayList<>(); - final Pattern PERCENT_CODE = Pattern.compile("(?.*)%(?:\\{(?[^{}]+)})?(?[a-zA-Z%])"); final Pattern LITERAL = Pattern.compile("(?.*%(?:\\{[^{}]+})?[a-zA-Z%])(?.*)"); - while(value.length()>0) + String remaining = formatString; + while(remaining.length()>0) { - Matcher m = PERCENT_CODE.matcher(value); - Matcher m2 = LITERAL.matcher(value); + Matcher m = PERCENT_CODE.matcher(remaining); if (m.matches()) { String code = m.group("code"); String arg = m.group("arg"); - tokens.add(new Token(code, arg)); - value = m.group("remaining"); + logHandle = updateLogHandle(logHandle, code, arg); + remaining = m.group("remaining"); continue; } + Matcher m2 = LITERAL.matcher(remaining); String literal; if (m2.matches()) { literal = m2.group("literal"); - value = m2.group("remaining"); + remaining = m2.group("remaining"); } else { - literal = value; - value = ""; + literal = remaining; + remaining = ""; } - tokens.add(new Token(literal)); - + logHandle = updateLogHandle(logHandle, append, literal); } - return tokens; + + return logHandle; } - - - private static class Token + private MethodHandle updateLogHandle(MethodHandle logHandle, MethodHandle append, String literal) { - public boolean isLiteralString() - { - return(literal != null); - } + return foldArguments(logHandle, dropArguments(append.bindTo(literal), 1, Request.class)); + } - public boolean isPercentCode() - { - return(code != null); - } - public String code = null; - public String arg = null; - public String literal = null; - - public Token(String code, String arg) + private MethodHandle updateLogHandle(MethodHandle logHandle, String code, String arg) throws Throwable + { + switch (code) { - this.code = code; - this.arg = arg; - } + case "a": + { + String method = "logClientIP"; + MethodHandle specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, LOG_TYPE); + return foldArguments(logHandle, specificHandle); + } - public Token(String literal) - { - this.literal = literal; + default: + LOG.warn("Unsupported code %{}", code); + return logHandle; } } } From 22e7679dd681f7f16dc5e795317e15a95403b597 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Tue, 6 Nov 2018 12:21:30 +0100 Subject: [PATCH 04/24] Issue 113 - CustomRequestLog changed the log type to include the response Signed-off-by: Lachlan Roberts --- .../org/eclipse/jetty/server/CustomRequestLog.java | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index f0cb7d45556..c13fcdba1c0 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -341,7 +341,7 @@ public class CustomRequestLog extends AbstractLifeCycle implements RequestLog StringBuilder sb = _buffers.get(); sb.setLength(0); - _logHandle.invoke(sb, request); + _logHandle.invoke(sb, request, response); String log = sb.toString(); write(log); @@ -540,19 +540,17 @@ public class CustomRequestLog extends AbstractLifeCycle implements RequestLog append(buf, s); } - public static void logClientIP(StringBuilder b, Request request) + public static void logClientIP(StringBuilder b, Request request, Response response) { b.append(request.getRemoteAddr()); } - - //TODO add response to signature - private static final MethodType LOG_TYPE = methodType(Void.TYPE, StringBuilder.class, Request.class); + private static final MethodType LOG_TYPE = methodType(Void.TYPE, StringBuilder.class, Request.class, Response.class); private MethodHandle getLogHandle(String formatString) throws Throwable { MethodHandle append = MethodHandles.lookup().findStatic(CustomRequestLog.class, "append", methodType(Void.TYPE, String.class, StringBuilder.class)); - MethodHandle logHandle = dropArguments(append.bindTo("\n"), 1, Request.class); + MethodHandle logHandle = dropArguments(dropArguments(append.bindTo("\n"), 1, Request.class), 2, Response.class); final Pattern PERCENT_CODE = Pattern.compile("(?.*)%(?:\\{(?[^{}]+)})?(?[a-zA-Z%])"); final Pattern LITERAL = Pattern.compile("(?.*%(?:\\{[^{}]+})?[a-zA-Z%])(?.*)"); @@ -592,7 +590,8 @@ public class CustomRequestLog extends AbstractLifeCycle implements RequestLog private MethodHandle updateLogHandle(MethodHandle logHandle, MethodHandle append, String literal) { - return foldArguments(logHandle, dropArguments(append.bindTo(literal), 1, Request.class)); + return foldArguments(logHandle, dropArguments(dropArguments(append.bindTo(literal), 1, Request.class), 2, Response.class)); + } From 3ce7016a35b9824956b0a886c3b53f7dcc68e0f4 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Thu, 8 Nov 2018 11:17:59 +0100 Subject: [PATCH 05/24] Issue 113 - CustomRequestLog added methods for each of the format codes described in javadoc Signed-off-by: Lachlan Roberts --- .../jetty/server/CustomRequestLog.java | 657 ++++++++++++++++-- 1 file changed, 609 insertions(+), 48 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index c13fcdba1c0..18f6eda06f5 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -22,10 +22,15 @@ import java.io.IOException; import java.lang.invoke.MethodHandle; import java.lang.invoke.MethodHandles; import java.lang.invoke.MethodType; +import java.util.List; import java.util.Locale; +import java.util.concurrent.TimeUnit; import java.util.regex.Matcher; import java.util.regex.Pattern; +import javax.servlet.http.Cookie; +import org.eclipse.jetty.http.HttpHeader; +import org.eclipse.jetty.http.QuotedCSV; import org.eclipse.jetty.http.pathmap.PathMappings; import org.eclipse.jetty.util.DateCache; import org.eclipse.jetty.util.annotation.ManagedAttribute; @@ -38,152 +43,152 @@ import static java.lang.invoke.MethodHandles.foldArguments; import static java.lang.invoke.MethodType.methodType; /** + * todo support modifiers + + + + + + + + + + + + + + + / + jetty.customrequestlog.filePath + /yyyy_mm_dd.request.log + + + + + + + + + + + + + + + + + + + + + diff --git a/jetty-server/src/main/config/modules/customrequestlog.mod b/jetty-server/src/main/config/modules/customrequestlog.mod new file mode 100644 index 00000000000..0d4eb9a8c41 --- /dev/null +++ b/jetty-server/src/main/config/modules/customrequestlog.mod @@ -0,0 +1,41 @@ +DO NOT EDIT - See: https://www.eclipse.org/jetty/documentation/current/startup-modules.html + +[description] +Enables a format string style request log. + +[provides] +requestlog + +[tags] +customrequestlog + +[depend] +server + +[xml] +etc/jetty-customrequestlog.xml + +[files] +logs/ + +[ini-template] +## Logging directory (relative to $jetty.base) +# jetty.customrequestlog.dir=logs + +## File path +# jetty.customrequestlog.filePath=${jetty.customrequestlog.dir}/yyyy_mm_dd.request.log + +## Date format for rollovered files (uses SimpleDateFormat syntax) +# jetty.customrequestlog.filenameDateFormat=yyyy_MM_dd + +## How many days to retain old log files +# jetty.customrequestlog.retainDays=90 + +## Whether to append to existing file +# jetty.customrequestlog.append=false + +## Timezone of the log entries +# jetty.customrequestlog.timezone=GMT + +## Format string +# jetty.customrequestlog.formatString=%a - %u %t "%r" %s %B "%{Referer}i" "%{User-Agent}i" "%C" From 7c0ea57923cf06942319fec7a9424511636377f4 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Sat, 24 Nov 2018 10:28:57 +0100 Subject: [PATCH 15/24] Issue #113 - CustomRequestLog terminology refactor replaced terminology for addresses and ports to use client and server referring to the logical connection and local and remote referring to the physical connection to the first hop finished implementing tests in CustomRequestLogTest otherwise disabled tests which will be verified manually instead Signed-off-by: Lachlan Roberts --- .../jetty/server/CustomRequestLog.java | 245 +++++++++------- .../server/handler/CustomRequestLogTest.java | 269 +++++++++--------- 2 files changed, 283 insertions(+), 231 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index 098dc1b4200..2896f9bbaaa 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -57,6 +57,22 @@ import static java.lang.invoke.MethodType.methodType; + + + + + + + + + + @@ -72,6 +88,19 @@ import static java.lang.invoke.MethodType.methodType; + + + + + + + + + + + @@ -105,11 +134,6 @@ import static java.lang.invoke.MethodType.methodType; - - - - - @@ -139,13 +163,18 @@ import static java.lang.invoke.MethodType.methodType; - + - + Valid formats are canonical, local, or remote. + todo update this documenatation + server, client logical + local, remote physical + @@ -203,11 +232,6 @@ import static java.lang.invoke.MethodType.methodType; - - - - - * * - * + * * * * @@ -269,8 +280,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private String[] _ignorePaths; private transient PathMappings _ignorePathMap; - private Locale _logLocale = Locale.getDefault(); - private String _logTimeZone = "GMT"; private RequestLog.Writer _requestLogWriter; private final MethodHandle _logHandle; @@ -369,7 +378,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog return _ignorePaths; } - /** * Retrieve the format string. * @@ -401,48 +409,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog super.doStart(); } - /** - * Set the locale of the request log. - * - * @param logLocale locale object - */ - public void setLogLocale(Locale logLocale) - { - _logLocale = logLocale; - } - - /** - * Retrieve the locale of the request log. - * - * @return locale object - */ - public Locale getLogLocale() - { - return _logLocale; - } - - /** - * Set the timezone of the request log. - * - * @param tz timezone string - */ - public void setLogTimeZone(String tz) - { - _logTimeZone = tz; - } - - /** - * Retrieve the timezone of the request log. - * - * @return timezone string - */ - @ManagedAttribute("the timezone") - public String getLogTimeZone() - { - return _logTimeZone; - } - - private static void append(StringBuilder buf, String s) { if (s == null || s.length() == 0) @@ -487,7 +453,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog {PARAM} is an optional string parameter to the percent code. CODE is a 1 to 2 character string corresponding to a format code. */ - final Pattern PATTERN = Pattern.compile("^(?:%(?!?[0-9,]+)?(?:\\{(?[^}]+)})?(?(?:(?:ti)|(?:to)|[a-zA-Z%]))|(?[^%]+))(?.*)"); + final Pattern PATTERN = Pattern.compile("^(?:%(?!?[0-9,]+)?(?:\\{(?[^}]+)})?(?(?:(?:ti)|(?:to)|[a-zA-Z%]))|(?[^%]+))(?.*)", Pattern.DOTALL|Pattern.MULTILINE); List tokens = new ArrayList<>(); String remaining = formatString; @@ -835,11 +801,36 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog case "t": { - DateCache logDateCache; - if (arg == null || arg.isEmpty()) - logDateCache = new DateCache(DEFAULT_DATE_FORMAT, _logLocale, _logTimeZone); - else - logDateCache = new DateCache(arg, _logLocale, _logTimeZone); + String format = DEFAULT_DATE_FORMAT; + TimeZone timeZone = TimeZone.getTimeZone("GMT"); + Locale locale = Locale.getDefault(); + + if (arg != null && !arg.isEmpty()) + { + String[] args = arg.split("\\|"); + switch (args.length) + { + case 1: + format = args[0]; + break; + + case 2: + format = args[0]; + timeZone = TimeZone.getTimeZone(args[1]); + break; + + case 3: + format = args[0]; + timeZone = TimeZone.getTimeZone(args[1]); + locale = Locale.forLanguageTag(args[2]); + break; + + default: + throw new IllegalArgumentException("Too many \"|\" characters in %t"); + } + } + + DateCache logDateCache = new DateCache(format, locale, timeZone); String method = "logRequestTime"; MethodType logTypeDateCache = methodType(Void.TYPE, DateCache.class, StringBuilder.class, Request.class, Response.class); diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java b/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java index 7f508e6cf95..c570c9d9223 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java @@ -25,6 +25,8 @@ import java.io.Writer; import java.util.TimeZone; import org.eclipse.jetty.util.RolloverFileOutputStream; +import org.eclipse.jetty.util.annotation.ManagedAttribute; +import org.eclipse.jetty.util.annotation.ManagedObject; import org.eclipse.jetty.util.component.AbstractLifeCycle; import org.eclipse.jetty.util.log.Log; import org.eclipse.jetty.util.log.Logger; @@ -32,6 +34,7 @@ import org.eclipse.jetty.util.log.Logger; /** * Writer which outputs pre-formatted request log strings to a file using {@link RolloverFileOutputStream}. */ +@ManagedObject("Request Log writer which writes to file") public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Writer { private static final Logger LOG = Log.getLogger(RequestLogWriter.class); @@ -83,6 +86,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr * * @return file name of the request log */ + @ManagedAttribute("filename") public String getFileName() { return _filename; @@ -95,6 +99,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr * * @return file name of the request log, or null if not applicable */ + @ManagedAttribute("dated filename") public String getDatedFilename() { if (_fileOut instanceof RolloverFileOutputStream) @@ -102,6 +107,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr return null; } + @Deprecated protected boolean isEnabled() { return (_fileOut != null); @@ -122,6 +128,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr * * @return number of days to keep a log file */ + @ManagedAttribute("number of days to keep a log file") public int getRetainDays() { return _retainDays; @@ -143,6 +150,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr * * @return value of the flag */ + @ManagedAttribute("if request log file will be appended after restart") public boolean isAppend() { return _append; @@ -164,6 +172,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr * * @return the log File Date Format */ + @ManagedAttribute("log file name date format") public String getFilenameDateFormat() { return _filenameDateFormat; @@ -208,6 +217,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr _timeZone = timeZone; } + @ManagedAttribute("timezone of the log") public String getTimeZone() { return _timeZone; diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLogWriter.java b/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLogWriter.java index b496283c653..91f1ce7262f 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLogWriter.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLogWriter.java @@ -20,9 +20,15 @@ package org.eclipse.jetty.server; import java.io.IOException; +import org.eclipse.jetty.util.annotation.ManagedAttribute; +import org.eclipse.jetty.util.annotation.ManagedObject; import org.eclipse.jetty.util.component.AbstractLifeCycle; import org.eclipse.jetty.util.log.Slf4jLog; +/** + * Request log writer using a Slf4jLog Logger + */ +@ManagedObject("Slf4j RequestLog Writer") public class Slf4jRequestLogWriter extends AbstractLifeCycle implements RequestLog.Writer { private Slf4jLog logger; @@ -39,6 +45,7 @@ public class Slf4jRequestLogWriter extends AbstractLifeCycle implements RequestL this.loggerName = loggerName; } + @ManagedAttribute("logger name") public String getLoggerName() { return loggerName; diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java index af1175c3cb1..efa346f58ff 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -27,6 +27,7 @@ import java.net.Socket; import java.net.URI; import java.nio.charset.StandardCharsets; import java.util.Enumeration; +import java.util.Locale; import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; @@ -373,20 +374,29 @@ public class CustomRequestLogTest _connector.getResponse("GET / HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); long requestTime = requestTimes.poll(5,TimeUnit.SECONDS); - DateCache dateCache = new DateCache(_log.DEFAULT_DATE_FORMAT, _log.getLogLocale(), _log.getLogTimeZone()); + DateCache dateCache = new DateCache(_log.DEFAULT_DATE_FORMAT, Locale.getDefault(), "GMT"); assertThat(log, is("RequestTime: ["+ dateCache.format(requestTime) +"]")); } @Test public void testLogRequestTimeCustomFormats() throws Exception { - testHandlerServerStart("RequestTime: %{EEE MMM dd HH:mm:ss zzz yyyy}t"); + testHandlerServerStart("%{EEE MMM dd HH:mm:ss zzz yyyy}t\n" + + "%{EEE MMM dd HH:mm:ss zzz yyyy|EST}t\n" + + "%{EEE MMM dd HH:mm:ss zzz yyyy|EST|ja}t"); _connector.getResponse("GET / HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); long requestTime = requestTimes.poll(5,TimeUnit.SECONDS); - DateCache dateCache = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", _log.getLogLocale(), _log.getLogTimeZone()); - assertThat(log, is("RequestTime: ["+ dateCache.format(requestTime) +"]")); + + DateCache dateCache1 = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", Locale.getDefault(), "GMT"); + DateCache dateCache2 = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", Locale.getDefault(), "EST"); + DateCache dateCache3 = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", Locale.forLanguageTag("ja"), "EST"); + + String[] logs = log.split("\n"); + assertThat(logs[0], is("["+ dateCache1.format(requestTime) +"]")); + assertThat(logs[1], is("["+ dateCache2.format(requestTime) +"]")); + assertThat(logs[2], is("["+ dateCache3.format(requestTime) +"]")); } @Test From e58fd9374266d05cfc5ed1f454f7ee844222cc39 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Wed, 28 Nov 2018 16:05:03 +0100 Subject: [PATCH 22/24] Issue #113 - StacklessLogging for NcsaRequestLogTest expected exceptions Signed-off-by: Lachlan Roberts --- .../jetty/server/handler/NcsaRequestLogTest.java | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java index 2945a524e83..48c23b98953 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java @@ -37,6 +37,7 @@ import org.eclipse.jetty.http.BadMessageException; import org.eclipse.jetty.server.AbstractNCSARequestLog; import org.eclipse.jetty.server.CustomRequestLog; import org.eclipse.jetty.server.Handler; +import org.eclipse.jetty.server.HttpChannel; import org.eclipse.jetty.server.LocalConnector; import org.eclipse.jetty.server.Request; import org.eclipse.jetty.server.RequestLog; @@ -44,9 +45,11 @@ 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.eclipse.jetty.util.log.StacklessLogging; 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.params.ParameterizedTest; import org.junit.jupiter.params.provider.Arguments; import org.junit.jupiter.params.provider.MethodSource; @@ -61,6 +64,7 @@ public class NcsaRequestLogTest Server _server; LocalConnector _connector; BlockingQueue _entries = new BlockingArrayQueue<>(); + StacklessLogging stacklessLogging; private void setup(String logType) throws Exception { @@ -106,10 +110,17 @@ public class NcsaRequestLogTest + @BeforeEach + public void before() throws Exception + { + stacklessLogging = new StacklessLogging(HttpChannel.class); + } + @AfterEach public void after() throws Exception { _server.stop(); + stacklessLogging.close(); } From c2749ff5e3a622dfa9010d464c04a8e5530a62b8 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Wed, 28 Nov 2018 16:22:37 +0100 Subject: [PATCH 23/24] Issue #113 - fixed documentation inconsistency Signed-off-by: Lachlan Roberts --- .../eclipse/jetty/server/CustomRequestLog.java | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index 179690bad7c..4da726c5bb4 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -106,26 +106,26 @@ import static java.lang.invoke.MethodType.methodType; * * * - * + * * * * * - * + * * * * * - * + * * * * @@ -649,7 +649,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog String method; if (arg == null || arg.isEmpty()) method = "logBytesReceived"; - else if (arg.equals("CLF")) + else if (arg.equalsIgnoreCase("clf")) method = "logBytesReceivedCLF"; else throw new IllegalArgumentException("Invalid argument for %I"); @@ -663,7 +663,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog String method; if (arg == null || arg.isEmpty()) method = "logBytesSent"; - else if (arg.equals("CLF")) + else if (arg.equalsIgnoreCase("clf")) method = "logBytesSentCLF"; else throw new IllegalArgumentException("Invalid argument for %O"); @@ -677,7 +677,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog String method; if (arg == null || arg.isEmpty()) method = "logBytesTransferred"; - else if (arg.equals("CLF")) + else if (arg.equalsIgnoreCase("clf")) method = "logBytesTransferredCLF"; else throw new IllegalArgumentException("Invalid argument for %S"); From 472d7a1529697d510590b8c31474e62e55ee8f45 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Wed, 28 Nov 2018 22:28:40 +0100 Subject: [PATCH 24/24] Issue #113 - latency test failures fixed Signed-off-by: Lachlan Roberts --- .../server/handler/CustomRequestLogTest.java | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java index efa346f58ff..1710798b6df 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -404,14 +404,14 @@ public class CustomRequestLogTest { testHandlerServerStart("%{us}T"); - long lowerBound = System.currentTimeMillis(); _connector.getResponse("GET /delay HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); - long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long lowerBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long upperBound = System.currentTimeMillis(); long measuredDuration = Long.parseLong(log); long durationLowerBound = TimeUnit.MILLISECONDS.toMicros(DELAY); - long durationUpperBound = TimeUnit.MILLISECONDS.toMicros(upperBound-lowerBound + DELAY); + long durationUpperBound = TimeUnit.MILLISECONDS.toMicros(upperBound-lowerBound); assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); @@ -422,14 +422,14 @@ public class CustomRequestLogTest { testHandlerServerStart("%{ms}T"); - long lowerBound = System.currentTimeMillis(); _connector.getResponse("GET /delay HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); - long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long lowerBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long upperBound = System.currentTimeMillis(); long measuredDuration = Long.parseLong(log); long durationLowerBound = DELAY; - long durationUpperBound = upperBound-lowerBound + DELAY; + long durationUpperBound = upperBound-lowerBound; assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); @@ -440,14 +440,14 @@ public class CustomRequestLogTest { testHandlerServerStart("%{s}T"); - long lowerBound = System.currentTimeMillis(); _connector.getResponse("GET /delay HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); - long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long lowerBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long upperBound = System.currentTimeMillis(); long measuredDuration = Long.parseLong(log); long durationLowerBound = TimeUnit.MILLISECONDS.toSeconds(DELAY); - long durationUpperBound = TimeUnit.MILLISECONDS.toSeconds(upperBound-lowerBound + DELAY); + long durationUpperBound = TimeUnit.MILLISECONDS.toSeconds(upperBound-lowerBound); assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound));
Format String Description
The percent sign.
%{format}a + Client IP address of the request. + Valid formats are {server, client, local, remote} + + where server and client are the logical addresses + where local and remote are the physical addresses +
%a Client IP address of the request.Local IP-address.
%hRemote hostname. Will log a dotted-string form of the IP if the Hostname cannot be resolved.
%v + todo this is now %{server}a + The canonical ServerName of the server serving the request.
%B Size of response in bytes, excluding HTTP headers.Filename.
%hRemote hostname. Will log a dotted-string form of the IP if the Hostname cannot be resolved.
%H The request protocol.
%pThe canonical port of the server serving the request.The canonical port of the server serving the request. + todo merge this with below +
%{format}p The canonical port of the server serving the request, or the server's actual port, or the client's actual port. - Valid formats are canonical, local, or remote.
The URL path requested, not including any query string.
%vThe canonical ServerName of the server serving the request.
%X @@ -578,26 +602,35 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog case "a": { String method; - - if (arg != null) + switch (arg) { - if (!arg.equals("c")) - throw new IllegalArgumentException("Argument of %a which is not 'c'"); + case "server": + method = "logServerHost"; + break; - method = "logConnectionIP"; - } - else - { - method = "logClientIP"; + case "client": + method = "logClientHost"; + break; + + case "local": + method = "logLocalHost"; + break; + + case "remote": + method = "logRemoteHost"; + break; + + default: + throw new IllegalArgumentException("Invalid arg for %a"); } specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); break; } - case "A": + case "h": { - String method = "logLocalIP"; + String method = "logRemoteHostName"; specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); break; } @@ -616,6 +649,38 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog break; } + case "I": + { + String method; + if (arg == null || arg.isEmpty()) + method = "logBytesReceived"; + else if (arg.equals("CLF")) + { + method = "logBytesReceivedCLF"; + } + else + throw new IllegalArgumentException("Invalid argument for %I"); + + specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); + break; + } + + case "O": + { + String method; + if (arg == null || arg.isEmpty()) + method = "logBytesSent"; + else if (arg.equals("CLF")) + { + method = "logBytesSentCLF"; + } + else + throw new IllegalArgumentException("Invalid argument for %I"); + + specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); + break; + } + case "C": { if (arg == null || arg.isEmpty()) @@ -657,12 +722,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog break; } - case "h": - { - String method = "logRemoteHostName"; - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } case "H": { @@ -709,14 +768,16 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog case "p": { - if (arg == null || arg.isEmpty()) - arg = "canonical"; - String method; switch (arg) { - case "canonical": - method = "logCanonicalPort"; + + case "server": + method = "logServerPort"; + break; + + case "client": + method = "logClientPort"; break; case "local": @@ -822,13 +883,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog break; } - case "v": - { - String method = "logServerName"; - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } - case "X": { String method = "logConnectionStatus"; @@ -836,20 +890,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog break; } - case "I": - { - String method = "logBytesReceived"; - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } - - case "O": - { - String method = "logBytesSent"; - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } - case "S": { String method = "logBytesTransferred"; @@ -906,19 +946,44 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog { } - private static void logClientIP(StringBuilder b, Request request, Response response) + private static void logServerHost(StringBuilder b, Request request, Response response) { - append(b, request.getRemoteAddr()); + append(b, request.getServerName()); } - private static void logConnectionIP(StringBuilder b, Request request, Response response) + private static void logClientHost(StringBuilder b, Request request, Response response) + { + append(b, request.getRemoteHost()); + } + + private static void logLocalHost(StringBuilder b, Request request, Response response) + { + append(b, request.getHttpChannel().getEndPoint().getLocalAddress().getAddress().getHostAddress()); + } + + private static void logRemoteHost(StringBuilder b, Request request, Response response) { append(b, request.getHttpChannel().getEndPoint().getRemoteAddress().getAddress().getHostAddress()); } - private static void logLocalIP(StringBuilder b, Request request, Response response) + private static void logServerPort(StringBuilder b, Request request, Response response) { - append(b, request.getLocalAddr()); + b.append(request.getServerPort()); + } + + private static void logClientPort(StringBuilder b, Request request, Response response) + { + b.append(request.getRemotePort()); + } + + private static void logLocalPort(StringBuilder b, Request request, Response response) + { + b.append(request.getHttpChannel().getEndPoint().getLocalAddress().getPort()); + } + + private static void logRemotePort(StringBuilder b, Request request, Response response) + { + b.append(request.getHttpChannel().getEndPoint().getRemoteAddress().getPort()); } private static void logResponseSize(StringBuilder b, Request request, Response response) @@ -936,6 +1001,23 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog b.append(written); } + private static void logBytesSent(StringBuilder b, Request request, Response response) + { + b.append(response.getHttpChannel().getBytesWritten()); + } + + private static void logBytesReceived(StringBuilder b, Request request, Response response) + { + //todo this be content received rather than consumed + b.append(request.getHttpInput().getContentConsumed()); + } + + private static void logBytesTransferred(StringBuilder b, Request request, Response response) + { + b.append(request.getHttpInput().getContentConsumed() + response.getHttpOutput().getWritten()); + } + + private static void logRequestCookie(String arg, StringBuilder b, Request request, Response response) { for (Cookie c : request.getCookies()) @@ -987,11 +1069,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog } } - private static void logRemoteHostName(StringBuilder b, Request request, Response response) - { - append(b, request.getRemoteHost()); - } - private static void logRequestProtocol(StringBuilder b, Request request, Response response) { append(b, request.getProtocol()); @@ -1021,21 +1098,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog append(b, response.getHeader(arg)); } - private static void logCanonicalPort(StringBuilder b, Request request, Response response) - { - b.append(request.getServerPort()); - } - - private static void logLocalPort(StringBuilder b, Request request, Response response) - { - b.append(request.getLocalPort()); - } - - private static void logRemotePort(StringBuilder b, Request request, Response response) - { - b.append(request.getRemotePort()); - } - private static void logQueryString(StringBuilder b, Request request, Response response) { append(b, "?"+request.getQueryString()); @@ -1101,32 +1163,11 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog append(b, request.getRequestURI()); } - private static void logServerName(StringBuilder b, Request request, Response response) - { - append(b, request.getServerName()); - } - private static void logConnectionStatus(StringBuilder b, Request request, Response response) { b.append(request.getHttpChannel().isResponseCompleted() ? (request.getHttpChannel().isPersistent() ? '+' : '-') : 'X'); } - private static void logBytesReceived(StringBuilder b, Request request, Response response) - { - //todo should this be content received rather than consumed - b.append(request.getHttpInput().getContentConsumed()); - } - - private static void logBytesSent(StringBuilder b, Request request, Response response) - { - //todo difference between this and logResponseSize - b.append(response.getHttpOutput().getWritten()); - } - - private static void logBytesTransferred(StringBuilder b, Request request, Response response) - { - b.append(request.getHttpInput().getContentConsumed() + response.getHttpOutput().getWritten()); - } private static void logRequestTrailer(String arg, StringBuilder b, Request request, Response response) { diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java index dedf48241f2..eb8a22096f4 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -19,6 +19,14 @@ package org.eclipse.jetty.server.handler; import java.io.IOException; +import java.io.InputStream; +import java.io.OutputStream; +import java.net.InetAddress; +import java.net.NetworkInterface; +import java.net.Socket; +import java.net.URI; +import java.nio.charset.StandardCharsets; +import java.util.Enumeration; import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; import javax.servlet.ServletException; @@ -27,14 +35,18 @@ import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import org.eclipse.jetty.server.CustomRequestLog; +import org.eclipse.jetty.server.ForwardedRequestCustomizer; +import org.eclipse.jetty.server.HttpConnectionFactory; import org.eclipse.jetty.server.LocalConnector; import org.eclipse.jetty.server.Request; import org.eclipse.jetty.server.RequestLog; import org.eclipse.jetty.server.Server; +import org.eclipse.jetty.server.ServerConnector; import org.eclipse.jetty.util.BlockingArrayQueue; import org.eclipse.jetty.util.DateCache; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; import static org.hamcrest.MatcherAssert.assertThat; @@ -42,7 +54,7 @@ import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.greaterThan; import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.lessThanOrEqualTo; -import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.hamcrest.Matchers.not; import static org.junit.jupiter.api.Assertions.fail; public class CustomRequestLogTest @@ -52,6 +64,8 @@ public class CustomRequestLogTest LocalConnector _connector; BlockingQueue _entries = new BlockingArrayQueue<>(); BlockingQueue requestTimes = new BlockingArrayQueue<>(); + ServerConnector _serverConnector; + URI _serverURI; @BeforeEach @@ -59,16 +73,28 @@ public class CustomRequestLogTest { _server = new Server(); _connector = new LocalConnector(_server); + _serverConnector = new ServerConnector(_server); _server.addConnector(_connector); + _server.addConnector(_serverConnector); } void testHandlerServerStart(String formatString) throws Exception { + _serverConnector.setPort(0); + _serverConnector.getBean(HttpConnectionFactory.class).getHttpConfiguration().addCustomizer(new ForwardedRequestCustomizer()); TestRequestLogWriter writer = new TestRequestLogWriter(); _log = new CustomRequestLog(writer, formatString); _server.setRequestLog(_log); _server.setHandler(new TestHandler()); _server.start(); + + String host = _serverConnector.getHost(); + if (host == null) + { + host = "localhost"; + } + int localPort = _serverConnector.getLocalPort(); + _serverURI = new URI(String.format("http://%s:%d/",host,localPort)); } @AfterEach @@ -106,33 +132,58 @@ public class CustomRequestLogTest } @Test - public void testLogClientIP() throws Exception + public void testLogAddress() throws Exception { - testHandlerServerStart("ClientIP: %a"); + testHandlerServerStart("%{local}a|%{local}p|" + + "%{remote}a|%{remote}p|" + + "%{server}a|%{server}p|" + + "%{client}a|%{client}p"); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } + Enumeration e = NetworkInterface.getNetworkInterfaces(); + while(e.hasMoreElements()) + { + NetworkInterface n = (NetworkInterface) e.nextElement(); + if (n.isLoopback()) + { + Enumeration ee = n.getInetAddresses(); + while (ee.hasMoreElements()) + { + InetAddress i = (InetAddress)ee.nextElement(); + try (Socket client = newSocket(i.getHostAddress(), _serverURI.getPort())) + { + OutputStream os = client.getOutputStream(); + String request = "GET / HTTP/1.0\n" + + "Host: webtide.com:1234\n" + + "Forwarded: For=10.1.2.3:1337\n" + + "\n\n"; + os.write(request.getBytes(StandardCharsets.ISO_8859_1)); + os.flush(); - @Test - public void testLogConnectionIP() throws Exception - { - testHandlerServerStart("ConnectionIP: %{c}a"); + String[] log = _entries.poll(5, TimeUnit.SECONDS).split("\\|"); + assertThat(log.length, is(8)); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } + String localAddr = log[0]; + String localPort = log[1]; + String remoteAddr = log[2]; + String remotePort = log[3]; + String serverAddr = log[4]; + String serverPort = log[5]; + String clientAddr = log[6]; + String clientPort = log[7]; - @Test - public void testLogLocalIP() throws Exception - { - testHandlerServerStart("LocalIP: %A"); + assertThat(serverPort, is("1234")); + assertThat(clientPort, is("1337")); + assertThat(remotePort, not(clientPort)); + assertThat(localPort, not(serverPort)); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); + assertThat(serverAddr, is("webtide.com")); + assertThat(clientAddr, is("10.1.2.3")); + assertThat(InetAddress.getByName(remoteAddr), is(client.getInetAddress())); + assertThat(InetAddress.getByName(localAddr), is(i)); + } + } + } + } } @Test @@ -163,10 +214,47 @@ public class CustomRequestLogTest assertThat(log, is("ResponseSize: 11")); } + @Test + public void testLogBytesSent() throws Exception + { + testHandlerServerStart("BytesSent: %O"); + + _connector.getResponse("GET / HTTP/1.0\necho: hello world\n\n"); + String log = _entries.poll(5,TimeUnit.SECONDS); + assertThat(log, is("BytesSent: 11")); + } + + @Test + public void testLogBytesReceived() throws Exception + { + testHandlerServerStart("BytesReceived: %I"); + + _connector.getResponse("GET / HTTP/1.0\n" + + "Content-Length: 11\n\n" + + "hello world"); + + String log = _entries.poll(5,TimeUnit.SECONDS); + assertThat(log, is("BytesReceived: 11")); + } + + @Test + public void testLogBytesTransferred() throws Exception + { + testHandlerServerStart("BytesTransferred: %S"); + + _connector.getResponse("GET / HTTP/1.0\n" + + "echo: hello world\n" + + "Content-Length: 11\n\n" + + "hello world"); + + String log = _entries.poll(5,TimeUnit.SECONDS); + assertThat(log, is("BytesTransferred: 22")); + } + @Test public void testLogRequestCookie() throws Exception { - testHandlerServerStart("RequestCookie: %{cookieName}C, %{cookie2}C, %{cookie3}C"); + testHandlerServerStart("RequestCookies: %{cookieName}C, %{cookie2}C, %{cookie3}C"); _connector.getResponse("GET / HTTP/1.0\nCookie: cookieName=cookieValue; cookie2=value2\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); @@ -193,24 +281,14 @@ public class CustomRequestLogTest assertThat(log, is("EnvironmentVar: " + System.getenv("JAVA_HOME") + "")); } - @Test - public void testLogRemoteHostName() throws Exception - { - testHandlerServerStart("RemoteHostName: %h"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - @Test public void testLogRequestProtocol() throws Exception { - testHandlerServerStart("RequestProtocol: %H"); + testHandlerServerStart("%H"); _connector.getResponse("GET / HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); - assertThat(log, is("Protocol: HTTP/1.0")); + assertThat(log, is("HTTP/1.0")); } @Test @@ -246,6 +324,7 @@ public class CustomRequestLogTest assertThat(_entries.poll(5,TimeUnit.SECONDS), is("KeepAliveRequests: 3")); } + @Disabled @Test public void testLogKeepAliveRequestsHttp2() throws Exception { @@ -273,45 +352,6 @@ public class CustomRequestLogTest assertThat(log, is("ResponseHeader: value1, value2, -")); } - @Test - public void testLogCanonicalPort() throws Exception - { - testHandlerServerStart("CanonicalPort: %p, %{canonical}p"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - - @Test - public void testLogLocalPort() throws Exception - { - testHandlerServerStart("LocalPort: %{local}p"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - - @Test - public void testLogRemotePort() throws Exception - { - testHandlerServerStart("RemotePort: %{remote}p"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - - @Test - public void testLogUnknownPort() throws Exception - { - assertThrows(IllegalArgumentException.class, ()-> - { - testHandlerServerStart("%{unknown}p"); - }); - } - @Test public void testLogQueryString() throws Exception { @@ -357,7 +397,7 @@ public class CustomRequestLogTest _connector.getResponse("GET / HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); - long requestTime = requestTimes.poll(5,TimeUnit.SECONDS).longValue(); + long requestTime = requestTimes.poll(5,TimeUnit.SECONDS); DateCache dateCache = new DateCache(_log.DEFAULT_DATE_FORMAT, _log.getLogLocale(), _log.getLogTimeZone()); assertThat(log, is("RequestTime: ["+ dateCache.format(requestTime) +"]")); } @@ -369,7 +409,7 @@ public class CustomRequestLogTest _connector.getResponse("GET / HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); - long requestTime = requestTimes.poll(5,TimeUnit.SECONDS).longValue(); + long requestTime = requestTimes.poll(5,TimeUnit.SECONDS); DateCache dateCache = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", _log.getLogLocale(), _log.getLogTimeZone()); assertThat(log, is("RequestTime: ["+ dateCache.format(requestTime) +"]")); } @@ -420,16 +460,6 @@ public class CustomRequestLogTest assertThat(Long.parseLong(log), lessThanOrEqualTo(TimeUnit.MILLISECONDS.toMicros(duration))); } - @Test - public void testLogRequestAuthentication() throws Exception - { - testHandlerServerStart("RequestAuthentication: %u"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - @Test public void testLogUrlRequestPath() throws Exception { @@ -440,16 +470,7 @@ public class CustomRequestLogTest assertThat(log, is("UrlRequestPath: /path")); } - @Test - public void testLogServerName() throws Exception - { - testHandlerServerStart("ServerName: %v"); - - _connector.getResponse("GET / HTTP/1.0\nHost: webtide.com\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - assertThat(log, is("ServerName: webtide.com")); - } - + @Disabled @Test public void testLogConnectionStatus() throws Exception { @@ -460,56 +481,40 @@ public class CustomRequestLogTest fail(log); } - @Test - public void testLogBytesReceived() throws Exception - { - testHandlerServerStart("BytesReceived: %I"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - - @Test - public void testLogBytesSent() throws Exception - { - testHandlerServerStart("BytesSent: %I"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - - @Test - public void testLogBytesTransferred() throws Exception - { - testHandlerServerStart("BytesTransferred: %I"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); - } - + @Disabled @Test public void testLogRequestTrailer() throws Exception { - testHandlerServerStart("RequestTrailer: %{trailerName}ti"); + testHandlerServerStart("%{trailerName}ti"); _connector.getResponse("GET / HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); fail(log); } + @Disabled @Test public void testLogResponseTrailer() throws Exception { - testHandlerServerStart("ResponseTrailer: %{trailerName}to"); + testHandlerServerStart("%{trailerName}to"); _connector.getResponse("GET / HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); fail(log); } - + + protected Socket newSocket() throws Exception + { + return newSocket(_serverURI.getHost(), _serverURI.getPort()); + } + + protected Socket newSocket(String host, int port) throws Exception + { + Socket socket = new Socket(host, port); + socket.setSoTimeout(10000); + socket.setTcpNoDelay(true); + return socket; + } class TestRequestLogWriter implements RequestLog.Writer { @@ -564,6 +569,12 @@ public class CustomRequestLogTest requestTimes.offer(baseRequest.getTimeStamp()); baseRequest.setHandled(true); + + if (request.getContentLength() > 0) + { + InputStream in = request.getInputStream(); + while (in.read()>0); + } } } } From 2cd579353cf4acb2f8495ca6f827559497a66568 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Mon, 26 Nov 2018 14:12:16 +0100 Subject: [PATCH 16/24] Issue #113 - fix javadoc errors Signed-off-by: Lachlan Roberts --- .../main/java/org/eclipse/jetty/server/CustomRequestLog.java | 5 +++-- .../main/java/org/eclipse/jetty/server/NCSARequestLog.java | 5 ++++- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index 2896f9bbaaa..4bfb2448786 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -47,8 +47,9 @@ import static java.lang.invoke.MethodType.methodType; /** + - + @@ -267,7 +268,6 @@ import static java.lang.invoke.MethodType.methodType; -
CustomRequestLog Format Codes
Format StringFormat String Description
%{VARNAME}^to The contents of VARNAME: trailer line(s) in the response sent from the server.
*/ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog @@ -336,6 +336,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog /** * Extract the user authentication * @param request The request to extract from + * @param checkDeferred Whether to check for deferred authentication * @return The string to log for authenticated user. */ protected static String getAuthentication(Request request, boolean checkDeferred) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java index 76103dc4bb1..a8a5466543f 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java @@ -64,7 +64,10 @@ public class NCSARequestLog extends AbstractNCSARequestLog /* ------------------------------------------------------------ */ /** - * Create request log object with specified output file name. + * Create request log object given a RequestLogWriter file name. + * + * @param writer the writer which manages the output of the formatted string + * produced by the {@link RequestLog} */ public NCSARequestLog(RequestLogWriter writer) { From b35df419bb9402c0324a45e4e6e1843e83588980 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Tue, 27 Nov 2018 14:04:37 +0100 Subject: [PATCH 17/24] Issue #113 - reformat, javadoc update and changes after review Signed-off-by: Lachlan Roberts --- .../config/etc/jetty-customrequestlog.xml | 14 +- .../main/config/modules/customrequestlog.mod | 16 +- .../jetty/server/AbstractNCSARequestLog.java | 35 +- .../jetty/server/AsyncNCSARequestLog.java | 2 +- .../jetty/server/AsyncRequestLogWriter.java | 26 +- .../jetty/server/CustomRequestLog.java | 627 +++++++++--------- .../eclipse/jetty/server/NCSARequestLog.java | 27 +- .../org/eclipse/jetty/server/RequestLog.java | 20 +- .../jetty/server/RequestLogWriter.java | 33 +- .../eclipse/jetty/server/Slf4jRequestLog.java | 2 +- 10 files changed, 406 insertions(+), 396 deletions(-) diff --git a/jetty-server/src/main/config/etc/jetty-customrequestlog.xml b/jetty-server/src/main/config/etc/jetty-customrequestlog.xml index dd24cd80ec6..6b605261356 100644 --- a/jetty-server/src/main/config/etc/jetty-customrequestlog.xml +++ b/jetty-server/src/main/config/etc/jetty-customrequestlog.xml @@ -17,22 +17,22 @@ / jetty.customrequestlog.filePath - /yyyy_mm_dd.request.log + /yyyy_mm_dd.request.log - - - - + + + + - + - + diff --git a/jetty-server/src/main/config/modules/customrequestlog.mod b/jetty-server/src/main/config/modules/customrequestlog.mod index 0d4eb9a8c41..68517d85de9 100644 --- a/jetty-server/src/main/config/modules/customrequestlog.mod +++ b/jetty-server/src/main/config/modules/customrequestlog.mod @@ -7,7 +7,7 @@ Enables a format string style request log. requestlog [tags] -customrequestlog +requestlog [depend] server @@ -20,22 +20,22 @@ logs/ [ini-template] ## Logging directory (relative to $jetty.base) -# jetty.customrequestlog.dir=logs +# jetty.requestlog.dir=logs ## File path -# jetty.customrequestlog.filePath=${jetty.customrequestlog.dir}/yyyy_mm_dd.request.log +# jetty.requestlog.filePath=${jetty.requestlog.dir}/yyyy_mm_dd.request.log ## Date format for rollovered files (uses SimpleDateFormat syntax) -# jetty.customrequestlog.filenameDateFormat=yyyy_MM_dd +# jetty.requestlog.filenameDateFormat=yyyy_MM_dd ## How many days to retain old log files -# jetty.customrequestlog.retainDays=90 +# jetty.requestlog.retainDays=90 ## Whether to append to existing file -# jetty.customrequestlog.append=false +# jetty.requestlog.append=false ## Timezone of the log entries -# jetty.customrequestlog.timezone=GMT +# jetty.requestlog.timezone=GMT ## Format string -# jetty.customrequestlog.formatString=%a - %u %t "%r" %s %B "%{Referer}i" "%{User-Agent}i" "%C" +# jetty.requestlog.formatString=%a - %u %t "%r" %s %B "%{Referer}i" "%{User-Agent}i" "%C" diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java index d460d6af3cf..99e0a94cf63 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java @@ -20,6 +20,7 @@ package org.eclipse.jetty.server; import java.io.IOException; import java.util.Locale; + import javax.servlet.http.Cookie; import org.eclipse.jetty.http.HttpHeader; @@ -36,7 +37,8 @@ import org.eclipse.jetty.util.log.Logger; * Configuration options allow a choice between the standard Common Log Format (as used in the 3 log format) and the * Combined Log Format (single log format). This log format can be output by most web servers, and almost all web log * analysis software can understand these formats. - * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#NCSA_FORMAT} with a {@link RequestLog.Writer} + * + * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#EXTENDED_NCSA_FORMAT} with a {@link RequestLog.Writer} */ @Deprecated public class AbstractNCSARequestLog extends ContainerLifeCycle implements RequestLog @@ -67,6 +69,7 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques /** * Is logging enabled + * * @return true if logging is enabled */ protected boolean isEnabled() @@ -76,6 +79,7 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques /** * Write requestEntry out. (to disk or slf4j log) + * * @param requestEntry the request entry * @throws IOException if unable to write the entry */ @@ -84,9 +88,9 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques _requestLogWriter.write(requestEntry); } - private void append(StringBuilder buf,String s) + private void append(StringBuilder buf, String s) { - if (s==null || s.length()==0) + if (s == null || s.length() == 0) buf.append('-'); else buf.append(s); @@ -113,7 +117,7 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques if (_logServer) { - append(buf,request.getServerName()); + append(buf, request.getServerName()); buf.append(' '); } @@ -128,9 +132,9 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques buf.append(addr); buf.append(" - "); - + String auth = getAuthentication(request); - append(buf,auth==null?"-":auth); + append(buf, auth == null ? "-" : auth); buf.append(" ["); if (_logDateCache != null) @@ -139,15 +143,15 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques buf.append(request.getTimeStamp()); buf.append("] \""); - append(buf,request.getMethod()); + append(buf, request.getMethod()); buf.append(' '); - append(buf,request.getOriginalURI()); + append(buf, request.getOriginalURI()); buf.append(' '); - append(buf,request.getProtocol()); + append(buf, request.getProtocol()); buf.append("\" "); int status = response.getCommittedMetaData().getStatus(); - if (status >=0) + if (status >= 0) { buf.append((char)('0' + ((status / 100) % 10))); buf.append((char)('0' + ((status / 10) % 10))); @@ -222,21 +226,22 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques LOG.warn(e); } } - + /** * Extract the user authentication + * * @param request The request to extract from * @return The string to log for authenticated user. */ protected String getAuthentication(Request request) { Authentication authentication = request.getAuthentication(); - + if (authentication instanceof Authentication.User) return ((Authentication.User)authentication).getUserIdentity().getUserPrincipal().getName(); - + // TODO extract the user name if it is Authentication.Deferred and return as '?username' - + return null; } @@ -425,7 +430,7 @@ public class AbstractNCSARequestLog extends ContainerLifeCycle implements Reques { if (_logDateFormat != null) { - _logDateCache = new DateCache(_logDateFormat, _logLocale ,_logTimeZone); + _logDateCache = new DateCache(_logDateFormat, _logLocale, _logTimeZone); } if (_ignorePaths != null && _ignorePaths.length > 0) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncNCSARequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncNCSARequestLog.java index 6f3d986a06c..3290b7794d2 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncNCSARequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncNCSARequestLog.java @@ -22,7 +22,7 @@ import java.util.concurrent.BlockingQueue; /** * An asynchronously writing NCSA Request Log - * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#NCSA_FORMAT} with an {@link AsyncRequestLogWriter} + * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#EXTENDED_NCSA_FORMAT} with an {@link AsyncRequestLogWriter} */ @Deprecated public class AsyncNCSARequestLog extends NCSARequestLog diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java b/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java index 8f704fd572c..4c79d50ffb0 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java @@ -26,6 +26,10 @@ import org.eclipse.jetty.util.BlockingArrayQueue; import org.eclipse.jetty.util.log.Log; import org.eclipse.jetty.util.log.Logger; + +/** + * An asynchronously writing RequestLogWriter + */ public class AsyncRequestLogWriter extends RequestLogWriter { private static final Logger LOG = Log.getLogger(AsyncRequestLogWriter.class); @@ -38,19 +42,19 @@ public class AsyncRequestLogWriter extends RequestLogWriter this(null, null); } - public AsyncRequestLogWriter(String filename,BlockingQueue queue) + public AsyncRequestLogWriter(String filename, BlockingQueue queue) { super(filename); - if (queue==null) - queue=new BlockingArrayQueue<>(1024); - _queue=queue; + if (queue == null) + queue = new BlockingArrayQueue<>(1024); + _queue = queue; } private class WriterThread extends Thread { WriterThread() { - setName("AsyncRequestLogWriter@"+Integer.toString(AsyncRequestLogWriter.this.hashCode(),16)); + setName("AsyncRequestLogWriter@" + Integer.toString(AsyncRequestLogWriter.this.hashCode(), 16)); } @Override @@ -61,13 +65,13 @@ public class AsyncRequestLogWriter extends RequestLogWriter try { String log = _queue.poll(10, TimeUnit.SECONDS); - if (log!=null) + if (log != null) AsyncRequestLogWriter.super.write(log); - while(!_queue.isEmpty()) + while (!_queue.isEmpty()) { - log=_queue.poll(); - if (log!=null) + log = _queue.poll(); + if (log != null) AsyncRequestLogWriter.super.write(log); } } @@ -97,7 +101,7 @@ public class AsyncRequestLogWriter extends RequestLogWriter _thread.interrupt(); _thread.join(); super.doStop(); - _thread=null; + _thread = null; } @Override @@ -107,7 +111,7 @@ public class AsyncRequestLogWriter extends RequestLogWriter { if (_warnedFull) LOG.warn("Log Queue overflow"); - _warnedFull=true; + _warnedFull = true; } } } diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index 4bfb2448786..d8f8697d735 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -29,6 +29,7 @@ import java.util.concurrent.TimeUnit; import java.util.function.Supplier; import java.util.regex.Matcher; import java.util.regex.Pattern; + import javax.servlet.http.Cookie; import org.eclipse.jetty.http.HttpFields; @@ -37,6 +38,7 @@ import org.eclipse.jetty.http.pathmap.PathMappings; import org.eclipse.jetty.server.handler.ContextHandler; import org.eclipse.jetty.util.DateCache; import org.eclipse.jetty.util.annotation.ManagedAttribute; +import org.eclipse.jetty.util.annotation.ManagedObject; import org.eclipse.jetty.util.component.ContainerLifeCycle; import org.eclipse.jetty.util.log.Log; import org.eclipse.jetty.util.log.Logger; @@ -46,237 +48,223 @@ import static java.lang.invoke.MethodHandles.foldArguments; import static java.lang.invoke.MethodType.methodType; /** - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
CustomRequestLog Format Codes
Format StringDescription
%%The percent sign.
%{format}a - Client IP address of the request. - Valid formats are {server, client, local, remote} - - where server and client are the logical addresses - where local and remote are the physical addresses -
%aClient IP address of the request.
%{c}aUnderlying peer IP address of the connection.
%ALocal IP-address.
%hRemote hostname. Will log a dotted-string form of the IP if the Hostname cannot be resolved.
%v - todo this is now %{server}a - The canonical ServerName of the server serving the request.
%BSize of response in bytes, excluding HTTP headers.
%bSize of response in bytes, excluding HTTP headers. In CLF format, i.e. a '-' rather than a 0 when no bytes are sent.
%{VARNAME}C - The contents of cookie VARNAME in the request sent to the server. Only version 0 cookies are fully supported. - Optional VARNAME parameter, without this parameter %C will log all cookies from the request. -
%DThe time taken to serve the request, in microseconds.
%{VARNAME}eThe contents of the environment variable VARNAME.
%fFilename.
%HThe request protocol.
%{VARNAME}iThe contents of VARNAME: header line(s) in the request sent to the server.
%kNumber of keepalive requests handled on this connection. - Interesting if KeepAlive is being used, so that, for example, a '1' means the first keepalive request - after the initial one, '2' the second, etc...; otherwise this is always 0 (indicating the initial request).
%mThe request method.
%{VARNAME}oThe contents of VARNAME: header line(s) in the response.
%pThe canonical port of the server serving the request. - todo merge this with below -
%{format}pThe canonical port of the server serving the request, or the server's actual port, or the client's actual port. - Valid formats are canonical, local, or remote. - todo update this documenatation - server, client logical - local, remote physical -
%qThe query string (prepended with a ? if a query string exists, otherwise an empty string).
%rFirst line of request.
%RThe handler generating the response (if any).
%sResponse status.
%{format}t - The time, in the form given by an optional format, parameter (default format [18/Sep/2011:19:18:28 -0400] where - the last number indicates the timezone offset from GMT.) -
- The format parameter should be in a format supported by {@link DateCache} -
%TThe time taken to serve the request, in seconds.
%{UNIT}TThe time taken to serve the request, in a time unit given by UNIT. - Valid units are ms for milliseconds, us for microseconds, and s for seconds. - Using s gives the same result as %T without any format; using us gives the same result as %D.
%{d}u - Remote user if the request was authenticated. May be bogus if return status (%s) is 401 (unauthorized). - Optional parameter d, with this parameter deferred authentication will also be checked. -
%UThe URL path requested, not including any query string.
%X - Connection status when response is completed: - 
- X = Connection aborted before the response completed.
- + = Connection may be kept alive after the response is sent.
- - = Connection will be closed after the response is sent.
-
%IBytes received.
%OBytes sent.
%SBytes transferred (received and sent). This is the combination of %I and %O.
%{VARNAME}^tiThe contents of VARNAME: trailer line(s) in the request sent to the server.
%{VARNAME}^toThe contents of VARNAME: trailer line(s) in the response sent from the server.
+ * A flexible RequestLog, which produces log strings in a customizable format. + * The Logger takes a format string where request characteristics can be added using "%" format codes which are + * replaced by the corresponding value in the log output. + *

+ * The terms server, client, local and remote are used to refer to the different addresses and ports + * which can be logged. Server and client refer to the logical addresses which can be modified in the request + * headers. Where local and remote refer to the physical addresses which may be a proxy between the + * end-user and the server. + * + * + *

Percent codes are specified in the format %MODIFIERS{PARAM}CODE + *

+ * MODIFIERS:
+ *     Optional list of comma separated HTTP status codes which may be preceded by a single "!" to indicate
+ *     negation. If the status code is not in the list the literal string "-" will be logged instead of
+ *     the resulting value from the percent code.
+ * {PARAM}:
+ *     Parameter string which may be optional depending on the percent code used.
+ * CODE:
+ *     A one or two character code specified by the {@link CustomRequestLog} table of format codes.
+ *
+ * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + *
Format Codes
Format StringDescription
%%The percent sign.
%{format}a + * Address or Hostname. Valid formats are {server, client, local, remote} + * Optional format parameter which will be server by default. + *
+ * Where server and client are the logical addresses which can be modified in the request headers, while local and + * remote are the physical addresses so may be a proxy between the end-user and the server. + *
%{format}p + * Port. Valid formats are {server, client, local, remote} + * Optional format parameter which will be server by default. + *
+ * Where server and client are the logical ports which can be modified in the request headers, while local and + * remote are the physical ports so may be to a proxy between the end-user and the server. + *
%{clf}I + * Size of request in bytes, excluding HTTP headers. + * Optional parameter with value of clf to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. + *
%{clf}O + * Size of response in bytes, excluding HTTP headers. + * Optional parameter with value of clf to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. + *
%{clf}S + * Bytes transferred (received and sent). This is the combination of %I and %O. + * Optional parameter with value of clf to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. + *
%{VARNAME}C + * The contents of cookie VARNAME in the request sent to the server. Only version 0 cookies are fully supported. + * Optional VARNAME parameter, without this parameter %C will log all cookies from the request. + *
%DThe time taken to serve the request, in microseconds.
%{VARNAME}eThe contents of the environment variable VARNAME.
%fFilename.
%HThe request protocol.
%{VARNAME}iThe contents of VARNAME: header line(s) in the request sent to the server.
%kNumber of keepalive requests handled on this connection. + * Interesting if KeepAlive is being used, so that, for example, a '1' means the first keepalive request + * after the initial one, '2' the second, etc...; otherwise this is always 0 (indicating the initial request).
%mThe request method.
%{VARNAME}oThe contents of VARNAME: header line(s) in the response.
%qThe query string (prepended with a ? if a query string exists, otherwise an empty string).
%rFirst line of request.
%RThe handler generating the response (if any).
%sResponse status.
%{format}t + * The time, in the form given by an optional format, parameter (default format [18/Sep/2011:19:18:28 -0400] where + * the last number indicates the timezone offset from GMT.) + *
+ * The format parameter should be in a format supported by {@link DateCache} + *
%TThe time taken to serve the request, in seconds.
%{UNIT}TThe time taken to serve the request, in a time unit given by UNIT. + * Valid units are ms for milliseconds, us for microseconds, and s for seconds. + * Using s gives the same result as %T without any format; using us gives the same result as %D.
%{d}u + * Remote user if the request was authenticated. May be bogus if return status (%s) is 401 (unauthorized). + * Optional parameter d, with this parameter deferred authentication will also be checked. + *
%UThe URL path requested, not including any query string.
%X + * Connection status when response is completed: + * 
+ * X = Connection aborted before the response completed.
+ * + = Connection may be kept alive after the response is sent.
+ * - = Connection will be closed after the response is sent.
+ *
%{VARNAME}^tiThe contents of VARNAME: trailer line(s) in the request sent to the server.
%{VARNAME}^toThe contents of VARNAME: trailer line(s) in the response sent from the server.
*/ +@ManagedObject("Custom format request log") public class CustomRequestLog extends ContainerLifeCycle implements RequestLog { protected static final Logger LOG = Log.getLogger(CustomRequestLog.class); - public static final String NCSA_FORMAT = "%a - %u %t \"%r\" %s %B \"%{Referer}i\" \"%{User-Agent}i\" \"%C\""; public static final String DEFAULT_DATE_FORMAT = "dd/MMM/yyyy:HH:mm:ss ZZZ"; + public static final String NCSA_FORMAT = "%{client}a - %u %t \"%r\" %s %O"; + public static final String EXTENDED_NCSA_FORMAT = "%{client}a - %u %t \"%r\" %s %O \"%{Referer}i\" \"%{User-Agent}i\""; + private static ThreadLocal _buffers = ThreadLocal.withInitial(() -> new StringBuilder(256)); private String[] _ignorePaths; @@ -286,9 +274,11 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private RequestLog.Writer _requestLogWriter; private final MethodHandle _logHandle; + private final String _formatString; public CustomRequestLog(RequestLog.Writer writer, String formatString) { + _formatString = formatString; _requestLogWriter = writer; addBean(_requestLogWriter); @@ -335,7 +325,8 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog /** * Extract the user authentication - * @param request The request to extract from + * + * @param request The request to extract from * @param checkDeferred Whether to check for deferred authentication * @return The string to log for authenticated user. */ @@ -346,7 +337,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog String name = null; boolean deferred = false; - if (checkDeferred && authentication instanceof Authentication.Deferred) + if (checkDeferred && authentication instanceof Authentication.Deferred) { authentication = ((Authentication.Deferred)authentication).authenticate(request); deferred = true; @@ -355,7 +346,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog if (authentication instanceof Authentication.User) name = ((Authentication.User)authentication).getUserIdentity().getUserPrincipal().getName(); - return (name==null) ? null : (deferred ? ("?"+name):name); + return (name == null) ? null : (deferred ? ("?" + name) : name); } /** @@ -378,6 +369,18 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog return _ignorePaths; } + + /** + * Retrieve the format string. + * + * @return the format string + */ + @ManagedAttribute("format string") + public String getFormatString() + { + return _formatString; + } + /** * Set up request logging and open log file. * @@ -442,7 +445,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static void append(StringBuilder buf, String s) { - if (s==null || s.length()==0) + if (s == null || s.length() == 0) buf.append('-'); else buf.append(s); @@ -474,11 +477,21 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static List getTokens(String formatString) { + /* + Extracts literal strings and percent codes out of the format string. + We will either match a percent code of the format %MODIFIERS{PARAM}CODE, or a literal string + until the next percent code or the end of the formatString is reached. + + where + MODIFIERS is an optional comma separated list of numbers. + {PARAM} is an optional string parameter to the percent code. + CODE is a 1 to 2 character string corresponding to a format code. + */ final Pattern PATTERN = Pattern.compile("^(?:%(?!?[0-9,]+)?(?:\\{(?[^}]+)})?(?(?:(?:ti)|(?:to)|[a-zA-Z%]))|(?[^%]+))(?.*)"); List tokens = new ArrayList<>(); String remaining = formatString; - while(remaining.length()>0) + while (remaining.length() > 0) { Matcher m = PATTERN.matcher(remaining); if (m.matches()) @@ -542,6 +555,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog this.literal = null; } + public Token(String literal) { this.code = null; @@ -554,17 +568,16 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog public boolean isLiteralString() { - return(literal != null); + return (literal != null); } public boolean isPercentCode() { - return(code != null); + return (code != null); } } - private MethodHandle updateLogHandle(MethodHandle logHandle, MethodHandle append, String literal) { return foldArguments(logHandle, dropArguments(dropArguments(append.bindTo(literal), 1, Request.class), 2, Response.class)); @@ -577,11 +590,11 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog String responseCode = Integer.toString(response.getStatus()); if (negated) { - return(!modifiers.contains(responseCode)); + return (!modifiers.contains(responseCode)); } else { - return(modifiers.contains(responseCode)); + return (modifiers.contains(responseCode)); } } @@ -602,6 +615,9 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog case "a": { + if (arg == null || arg.isEmpty()) + arg = "server"; + String method; switch (arg) { @@ -629,23 +645,35 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog break; } - case "h": + case "p": { - String method = "logRemoteHostName"; - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } + if (arg == null || arg.isEmpty()) + arg = "server"; - case "B": - { - String method = "logResponseSize"; - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } + String method; + switch (arg) + { + + case "server": + method = "logServerPort"; + break; + + case "client": + method = "logClientPort"; + break; + + case "local": + method = "logLocalPort"; + break; + + case "remote": + method = "logRemotePort"; + break; + + default: + throw new IllegalArgumentException("Invalid arg for %p"); + } - case "b": - { - String method = "logResponseSizeCLF"; specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); break; } @@ -656,9 +684,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog if (arg == null || arg.isEmpty()) method = "logBytesReceived"; else if (arg.equals("CLF")) - { method = "logBytesReceivedCLF"; - } else throw new IllegalArgumentException("Invalid argument for %I"); @@ -672,11 +698,23 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog if (arg == null || arg.isEmpty()) method = "logBytesSent"; else if (arg.equals("CLF")) - { method = "logBytesSentCLF"; - } else - throw new IllegalArgumentException("Invalid argument for %I"); + throw new IllegalArgumentException("Invalid argument for %O"); + + specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); + break; + } + + case "S": + { + String method; + if (arg == null || arg.isEmpty()) + method = "logBytesTransferred"; + else if (arg.equals("CLF")) + method = "logBytesTransferredCLF"; + else + throw new IllegalArgumentException("Invalid argument for %S"); specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); break; @@ -767,36 +805,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog break; } - case "p": - { - String method; - switch (arg) - { - - case "server": - method = "logServerPort"; - break; - - case "client": - method = "logClientPort"; - break; - - case "local": - method = "logLocalPort"; - break; - - case "remote": - method = "logRemotePort"; - break; - - default: - throw new IllegalArgumentException("Invalid arg for %p"); - } - - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } - case "q": { String method = "logQueryString"; @@ -829,9 +837,9 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog { DateCache logDateCache; if (arg == null || arg.isEmpty()) - logDateCache = new DateCache(DEFAULT_DATE_FORMAT, _logLocale , _logTimeZone); + logDateCache = new DateCache(DEFAULT_DATE_FORMAT, _logLocale, _logTimeZone); else - logDateCache = new DateCache(arg, _logLocale , _logTimeZone); + logDateCache = new DateCache(arg, _logLocale, _logTimeZone); String method = "logRequestTime"; MethodType logTypeDateCache = methodType(Void.TYPE, DateCache.class, StringBuilder.class, Request.class, Response.class); @@ -891,14 +899,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog break; } - case "S": - { - String method = "logBytesTransferred"; - specificHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, method, logType); - break; - } - - case "ti": { if (arg == null || arg.isEmpty()) @@ -940,7 +940,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog } - //-----------------------------------------------------------------------------------// private static void logNothing(StringBuilder b, Request request, Response response) @@ -996,7 +995,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static void logResponseSizeCLF(StringBuilder b, Request request, Response response) { long written = response.getHttpChannel().getBytesWritten(); - if (written==0) + if (written == 0) b.append('-'); else b.append(written); @@ -1007,17 +1006,47 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog b.append(response.getHttpChannel().getBytesWritten()); } + private static void logBytesSentCLF(StringBuilder b, Request request, Response response) + { + long sent = response.getHttpChannel().getBytesWritten(); + if (sent == 0) + b.append('-'); + else + b.append(sent); + } + private static void logBytesReceived(StringBuilder b, Request request, Response response) { //todo this be content received rather than consumed b.append(request.getHttpInput().getContentConsumed()); } + private static void logBytesReceivedCLF(StringBuilder b, Request request, Response response) + { + //todo this be content received rather than consumed + long received = request.getHttpInput().getContentConsumed(); + if (received == 0) + b.append('-'); + else + b.append(received); + } + private static void logBytesTransferred(StringBuilder b, Request request, Response response) { + //todo this be content received rather than consumed b.append(request.getHttpInput().getContentConsumed() + response.getHttpOutput().getWritten()); } + private static void logBytesTransferredCLF(StringBuilder b, Request request, Response response) + { + //todo this be content received rather than consumed + long transferred = request.getHttpInput().getContentConsumed() + response.getHttpOutput().getWritten(); + if (transferred == 0) + b.append('-'); + else + b.append(transferred); + } + private static void logRequestCookie(String arg, StringBuilder b, Request request, Response response) { @@ -1059,12 +1088,12 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static void logFilename(StringBuilder b, Request request, Response response) { UserIdentity.Scope scope = request.getUserIdentityScope(); - if (scope==null || scope.getContextHandler()==null) + if (scope == null || scope.getContextHandler() == null) b.append('-'); else { ContextHandler context = scope.getContextHandler(); - int lengthToStrip = scope.getContextPath().length()>1 ? scope.getContextPath().length() : 0; + int lengthToStrip = scope.getContextPath().length() > 1 ? scope.getContextPath().length() : 0; String filename = context.getServletContext().getRealPath(request.getPathInfo().substring(lengthToStrip)); append(b, filename); } @@ -1101,7 +1130,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static void logQueryString(StringBuilder b, Request request, Response response) { - append(b, "?"+request.getQueryString()); + append(b, "?" + request.getQueryString()); } private static void logRequestFirstLine(StringBuilder b, Request request, Response response) @@ -1166,7 +1195,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static void logConnectionStatus(StringBuilder b, Request request, Response response) { - b.append(request.getHttpChannel().isResponseCompleted() ? (request.getHttpChannel().isPersistent() ? '+' : '-') : 'X'); + b.append(request.getHttpChannel().isResponseCompleted() ? (request.getHttpChannel().isPersistent() ? '+' : '-') : 'X'); } diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java index a8a5466543f..6a660fb3dc1 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java @@ -32,7 +32,8 @@ import org.eclipse.jetty.util.annotation.ManagedObject; * Format (single log format). This log format can be output by most web * servers, and almost all web log analysis software can understand these * formats. - * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#NCSA_FORMAT} with a {@link RequestLogWriter} + * + * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#EXTENDED_NCSA_FORMAT} with a {@link RequestLogWriter} */ @Deprecated @ManagedObject("NCSA standard format request log") @@ -40,7 +41,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog { private final RequestLogWriter _requestLogWriter; - /* ------------------------------------------------------------ */ /** * Create request log object with default settings. */ @@ -49,7 +49,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog this((String)null); } - /* ------------------------------------------------------------ */ /** * Create request log object with specified output file name. * @@ -62,7 +61,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog this(new RequestLogWriter(filename)); } - /* ------------------------------------------------------------ */ /** * Create request log object given a RequestLogWriter file name. * @@ -76,21 +74,18 @@ public class NCSARequestLog extends AbstractNCSARequestLog setExtended(true); } - /* ------------------------------------------------------------ */ /** * Set the output file name of the request log. * The file name may be in the format expected by * {@link RolloverFileOutputStream}. * * @param filename file name of the request log - * */ public void setFilename(String filename) { _requestLogWriter.setFilename(filename); } - /* ------------------------------------------------------------ */ @Override public void setLogTimeZone(String tz) { @@ -98,7 +93,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog _requestLogWriter.setTimeZone(tz); } - /* ------------------------------------------------------------ */ /** * Retrieve the output file name of the request log. * @@ -109,8 +103,7 @@ public class NCSARequestLog extends AbstractNCSARequestLog { return _requestLogWriter.getFileName(); } - - /* ------------------------------------------------------------ */ + /** * Retrieve the file name of the request log with the expanded * date wildcard if the output is written to the disk using @@ -123,14 +116,12 @@ public class NCSARequestLog extends AbstractNCSARequestLog return _requestLogWriter.getDatedFilename(); } - /* ------------------------------------------------------------ */ @Override protected boolean isEnabled() { return _requestLogWriter.isEnabled(); } - /* ------------------------------------------------------------ */ /** * Set the number of days before rotated log files are deleted. * @@ -141,7 +132,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog _requestLogWriter.setRetainDays(retainDays); } - /* ------------------------------------------------------------ */ /** * Retrieve the number of days before rotated log files are deleted. * @@ -153,7 +143,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog return _requestLogWriter.getRetainDays(); } - /* ------------------------------------------------------------ */ /** * Set append to log flag. * @@ -165,7 +154,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog _requestLogWriter.setAppend(append); } - /* ------------------------------------------------------------ */ /** * Retrieve append to log flag. * @@ -177,19 +165,17 @@ public class NCSARequestLog extends AbstractNCSARequestLog return _requestLogWriter.isAppend(); } - /* ------------------------------------------------------------ */ /** * Set the log file name date format. - * @see RolloverFileOutputStream#RolloverFileOutputStream(String, boolean, int, TimeZone, String, String) * * @param logFileDateFormat format string that is passed to {@link RolloverFileOutputStream} + * @see RolloverFileOutputStream#RolloverFileOutputStream(String, boolean, int, TimeZone, String, String) */ public void setFilenameDateFormat(String logFileDateFormat) { _requestLogWriter.setFilenameDateFormat(logFileDateFormat); } - /* ------------------------------------------------------------ */ /** * Retrieve the file name date format string. * @@ -200,14 +186,12 @@ public class NCSARequestLog extends AbstractNCSARequestLog return _requestLogWriter.getFilenameDateFormat(); } - /* ------------------------------------------------------------ */ @Override public void write(String requestEntry) throws IOException { _requestLogWriter.write(requestEntry); } - - /* ------------------------------------------------------------ */ + /** * Set up request logging and open log file. * @@ -219,7 +203,6 @@ public class NCSARequestLog extends AbstractNCSARequestLog super.doStart(); } - /* ------------------------------------------------------------ */ /** * Close the log file and perform cleanup. * diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLog.java index 5e59fe01139..4ad0fd64146 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLog.java @@ -16,30 +16,34 @@ // ======================================================================== // -package org.eclipse.jetty.server; +package org.eclipse.jetty.server; import java.io.IOException; import org.eclipse.jetty.server.handler.RequestLogHandler; -/** - * A RequestLog can be attached to a {@link org.eclipse.jetty.server.handler.RequestLogHandler} to enable +/** + * A RequestLog can be attached to a {@link org.eclipse.jetty.server.handler.RequestLogHandler} to enable * logging of requests/responses. + * * @see RequestLogHandler#setRequestLog(RequestLog) * @see Server#setRequestLog(RequestLog) */ public interface RequestLog { /** - * @param request The request to log. + * @param request The request to log. * @param response The response to log. Note that for some requests - * the response instance may not have been fully populated (Eg 400 bad request - * responses are sent without a servlet response object). Thus for basic - * log information it is best to consult {@link Response#getCommittedMetaData()} - * and {@link Response#getHttpChannel()} directly. + * the response instance may not have been fully populated (Eg 400 bad request + * responses are sent without a servlet response object). Thus for basic + * log information it is best to consult {@link Response#getCommittedMetaData()} + * and {@link Response#getHttpChannel()} directly. */ void log(Request request, Response response); + /** + * Writes the generated log string to a log sink + */ interface Writer { void write(String requestEntry) throws IOException; diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java b/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java index 7015709837d..7f508e6cf95 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java @@ -29,6 +29,9 @@ import org.eclipse.jetty.util.component.AbstractLifeCycle; import org.eclipse.jetty.util.log.Log; import org.eclipse.jetty.util.log.Logger; +/** + * Writer which outputs pre-formatted request log strings to a file using {@link RolloverFileOutputStream}. + */ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Writer { private static final Logger LOG = Log.getLogger(RequestLogWriter.class); @@ -53,7 +56,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr setAppend(true); setRetainDays(31); - if(filename != null) + if (filename != null) setFilename(filename); } @@ -63,7 +66,6 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr * {@link RolloverFileOutputStream}. * * @param filename file name of the request log - * */ public void setFilename(String filename) { @@ -86,7 +88,6 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr return _filename; } - /** * Retrieve the file name of the request log with the expanded * date wildcard if the output is written to the disk using @@ -126,7 +127,6 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr return _retainDays; } - /** * Set append to log flag. * @@ -148,19 +148,17 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr return _append; } - /** * Set the log file name date format. - * @see RolloverFileOutputStream#RolloverFileOutputStream(String, boolean, int, TimeZone, String, String) * * @param logFileDateFormat format string that is passed to {@link RolloverFileOutputStream} + * @see RolloverFileOutputStream#RolloverFileOutputStream(String, boolean, int, TimeZone, String, String) */ public void setFilenameDateFormat(String logFileDateFormat) { _filenameDateFormat = logFileDateFormat; } - /* ------------------------------------------------------------ */ /** * Retrieve the file name date format string. * @@ -171,13 +169,12 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr return _filenameDateFormat; } - /* ------------------------------------------------------------ */ @Override public void write(String requestEntry) throws IOException { - synchronized(this) + synchronized (this) { - if (_writer==null) + if (_writer == null) return; _writer.write(requestEntry); _writer.write(System.lineSeparator()); @@ -185,18 +182,12 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr } } - /* ------------------------------------------------------------ */ - /** - * Set up request logging and open log file. - * - * @see org.eclipse.jetty.util.component.AbstractLifeCycle#doStart() - */ @Override protected synchronized void doStart() throws Exception { if (_filename != null) { - _fileOut = new RolloverFileOutputStream(_filename,_append,_retainDays,TimeZone.getTimeZone(getTimeZone()),_filenameDateFormat,null); + _fileOut = new RolloverFileOutputStream(_filename, _append, _retainDays, TimeZone.getTimeZone(getTimeZone()), _filenameDateFormat, null); _closeOut = true; LOG.info("Opened " + getDatedFilename()); } @@ -205,7 +196,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr _out = _fileOut; - synchronized(this) + synchronized (this) { _writer = new OutputStreamWriter(_out); } @@ -222,12 +213,6 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr return _timeZone; } - /* ------------------------------------------------------------ */ - /** - * Close the log file and perform cleanup. - * - * @see org.eclipse.jetty.util.component.AbstractLifeCycle#doStop() - */ @Override protected void doStop() throws Exception { diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLog.java index 29388a227f9..a6340c9f399 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLog.java @@ -24,7 +24,7 @@ import org.eclipse.jetty.util.annotation.ManagedObject; /** * Implementation of NCSARequestLog where output is sent as a SLF4J INFO Log message on the named logger "org.eclipse.jetty.server.RequestLog" - * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#NCSA_FORMAT} with an {@link Slf4jRequestLogWriter} + * @deprecated use {@link CustomRequestLog} given format string {@link CustomRequestLog#EXTENDED_NCSA_FORMAT} with an {@link Slf4jRequestLogWriter} */ @Deprecated @ManagedObject("NCSA standard format request log to slf4j bridge") From b97c80b3c13311fd7acbd3fde2dfa73778ab5b16 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Tue, 27 Nov 2018 14:26:31 +0100 Subject: [PATCH 18/24] Issue #113 - testing of logConnectionStatus implemented Signed-off-by: Lachlan Roberts --- .../server/handler/CustomRequestLogTest.java | 42 ++++++++++++++++--- 1 file changed, 37 insertions(+), 5 deletions(-) diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java index eb8a22096f4..066d8fe890c 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -29,6 +29,7 @@ import java.nio.charset.StandardCharsets; import java.util.Enumeration; import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; + import javax.servlet.ServletException; import javax.servlet.ServletOutputStream; import javax.servlet.http.HttpServletRequest; @@ -38,6 +39,7 @@ import org.eclipse.jetty.server.CustomRequestLog; import org.eclipse.jetty.server.ForwardedRequestCustomizer; import org.eclipse.jetty.server.HttpConnectionFactory; import org.eclipse.jetty.server.LocalConnector; +import org.eclipse.jetty.server.QuietServletException; import org.eclipse.jetty.server.Request; import org.eclipse.jetty.server.RequestLog; import org.eclipse.jetty.server.Server; @@ -470,15 +472,39 @@ public class CustomRequestLogTest assertThat(log, is("UrlRequestPath: /path")); } - @Disabled @Test public void testLogConnectionStatus() throws Exception { - testHandlerServerStart("ConnectionStatus: %X"); + testHandlerServerStart("%U ConnectionStatus: %s %X"); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - fail(log); + _connector.getResponse("GET /one HTTP/1.0\n\n"); + assertThat(_entries.poll(5,TimeUnit.SECONDS), is("/one ConnectionStatus: 200 -")); + + _connector.getResponse("GET /two HTTP/1.1\n" + + "Host: localhost\n" + + "Connection: close\n" + + "\n"); + assertThat(_entries.poll(5,TimeUnit.SECONDS), is("/two ConnectionStatus: 200 -")); + + LocalConnector.LocalEndPoint connect = _connector.connect(); + connect.addInput("GET /three HTTP/1.0\n" + + "Connection: keep-alive\n\n"); + connect.addInput("GET /four HTTP/1.1\n" + + "Host: localhost\n\n"); + connect.addInput("GET /BAD HTTP/1.1\n\n"); + assertThat(connect.getResponse(), containsString("200 OK")); + assertThat(connect.getResponse(), containsString("200 OK")); + assertThat(connect.getResponse(), containsString("400 ")); + + assertThat(_entries.poll(5,TimeUnit.SECONDS), is("/three ConnectionStatus: 200 +")); + assertThat(_entries.poll(5,TimeUnit.SECONDS), is("/four ConnectionStatus: 200 +")); + assertThat(_entries.poll(5,TimeUnit.SECONDS), is("/BAD ConnectionStatus: 400 -")); + + _connector.getResponse("GET /abort HTTP/1.1\n" + + "Host: localhost\n" + + "\n"); + connect.getResponse(); + assertThat(_entries.poll(5,TimeUnit.SECONDS), is("/abort ConnectionStatus: 200 X")); } @Disabled @@ -555,6 +581,12 @@ public class CustomRequestLogTest response.addHeader("Header1", "value1"); response.addHeader("Header2", "value2"); } + else if (request.getRequestURI().contains("/abort")) + { + response.getOutputStream().println("data"); + response.flushBuffer(); + baseRequest.getHttpChannel().abort(new QuietServletException("test abort")); + } else if (request.getRequestURI().contains("delay")) { try From 8aa3655c5525434f4360b6dc41030b1c2ae2c9b2 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Wed, 28 Nov 2018 09:26:55 +0100 Subject: [PATCH 19/24] Issue #113 - fix to failing tests removed tests for %B and %b which have been removed in favor of %O adjusted the NcsaRequestLogTest to only test ExtendedNCSA format Signed-off-by: Lachlan Roberts --- .../server/handler/CustomRequestLogTest.java | 28 ------------------- .../server/handler/NcsaRequestLogTest.java | 13 +++------ 2 files changed, 4 insertions(+), 37 deletions(-) diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java index 066d8fe890c..247fa7795ce 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -188,34 +188,6 @@ public class CustomRequestLogTest } } - @Test - public void testLogResponseSize() throws Exception - { - testHandlerServerStart("ResponseSize: %B"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - assertThat(log, is("ResponseSize: 0")); - - _connector.getResponse("GET / HTTP/1.0\nEcho: hello world\n\n"); - log = _entries.poll(5,TimeUnit.SECONDS); - assertThat(log, is("ResponseSize: 11")); - } - - @Test - public void testLogResponseSizeCLF() throws Exception - { - testHandlerServerStart("ResponseSize: %b"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5,TimeUnit.SECONDS); - assertThat(log, is("ResponseSize: -")); - - _connector.getResponse("GET / HTTP/1.0\nEcho: hello world\n\n"); - log = _entries.poll(5,TimeUnit.SECONDS); - assertThat(log, is("ResponseSize: 11")); - } - @Test public void testLogBytesSent() throws Exception { diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java index 71aa3e5fa93..2945a524e83 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/NcsaRequestLogTest.java @@ -27,6 +27,7 @@ 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; @@ -52,7 +53,6 @@ import org.junit.jupiter.params.provider.MethodSource; import org.junit.jupiter.params.provider.ValueSource; import static org.hamcrest.MatcherAssert.assertThat; -import static org.hamcrest.Matchers.contains; import static org.hamcrest.Matchers.containsString; public class NcsaRequestLogTest @@ -69,14 +69,12 @@ public class NcsaRequestLogTest switch (logType) { case "customNCSA": - _log = new CustomRequestLog(writer, CustomRequestLog.NCSA_FORMAT); + _log = new CustomRequestLog(writer, CustomRequestLog.EXTENDED_NCSA_FORMAT); break; case "NCSA": { AbstractNCSARequestLog logNCSA = new AbstractNCSARequestLog(writer); logNCSA.setExtended(true); - logNCSA.setLogLatency(true); - logNCSA.setLogCookies(true); _log = logNCSA; break; } @@ -354,7 +352,7 @@ public class NcsaRequestLogTest _connector.getResponse("GET http://[:1]/foo HTTP/1.1\nReferer: http://other.site\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET http://[:1]/foo ")); - assertThat(log,containsString(" 400 50 \"http://other.site\" \"-\" - ")); + assertThat(log,containsString(" 400 50 \"http://other.site\" \"-\"")); } @ParameterizedTest() @@ -367,7 +365,7 @@ public class NcsaRequestLogTest _connector.getResponse("GET http://[:1]/foo HTTP/1.1\nReferer: http://other.site\nUser-Agent: Mozilla/5.0 (test)\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); assertThat(log,containsString("GET http://[:1]/foo ")); - assertThat(log,containsString(" 400 50 \"http://other.site\" \"Mozilla/5.0 (test)\" - ")); + assertThat(log,containsString(" 400 50 \"http://other.site\" \"Mozilla/5.0 (test)\"")); } @@ -490,9 +488,6 @@ public class NcsaRequestLogTest startServer(); makeRequest(requestPath); assertRequestLog(expectedLogEntry, _log); - - if (!(testHandler instanceof HelloHandler)) - assertThat(errors,contains(requestPath)); } From 63aa9ce97daa0e77f6d6b09e09a5ebec6a9e2d03 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Wed, 28 Nov 2018 10:52:17 +0100 Subject: [PATCH 20/24] Issue #113 - problems with latency tests and request handler name Signed-off-by: Lachlan Roberts --- .../jetty/server/CustomRequestLog.java | 9 +++-- .../server/handler/CustomRequestLogTest.java | 35 ++++++++++++------- .../jetty/servlet/CustomRequestLogTest.java | 3 +- 3 files changed, 31 insertions(+), 16 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index d8f8697d735..5556a7575c3 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -1162,8 +1162,13 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static void logLatencyMicroseconds(StringBuilder b, Request request, Response response) { - long latency = System.currentTimeMillis() - request.getTimeStamp(); - b.append(TimeUnit.MILLISECONDS.toMicros(latency)); + long currentTime = System.currentTimeMillis(); + long requestTime = request.getTimeStamp(); + + long latency_ms = currentTime - requestTime; + long latency_us = TimeUnit.MILLISECONDS.toMicros(latency_ms); + + b.append(latency_us); } private static void logLatencyMilliseconds(StringBuilder b, Request request, Response response) diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java index 247fa7795ce..af1175c3cb1 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -53,7 +53,7 @@ import org.junit.jupiter.api.Test; import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.containsString; -import static org.hamcrest.Matchers.greaterThan; +import static org.hamcrest.Matchers.greaterThanOrEqualTo; import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.lessThanOrEqualTo; import static org.hamcrest.Matchers.not; @@ -69,6 +69,7 @@ public class CustomRequestLogTest ServerConnector _serverConnector; URI _serverURI; + private final static long DELAY = 2000; @BeforeEach public void before() throws Exception @@ -394,13 +395,16 @@ public class CustomRequestLogTest testHandlerServerStart("%{us}T"); long lowerBound = System.currentTimeMillis(); - _connector.getResponse("GET / HTTP/1.0\n\n"); + _connector.getResponse("GET /delay HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); - long duration = upperBound-lowerBound; - assertThat(Long.parseLong(log), greaterThan((long)0)); - assertThat(Long.parseLong(log), lessThanOrEqualTo(TimeUnit.MILLISECONDS.toMicros(duration))); + long measuredDuration = Long.parseLong(log); + long durationLowerBound = TimeUnit.MILLISECONDS.toMicros(DELAY); + long durationUpperBound = TimeUnit.MILLISECONDS.toMicros(upperBound-lowerBound + DELAY); + + assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); + assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); } @Test @@ -409,13 +413,16 @@ public class CustomRequestLogTest testHandlerServerStart("%{ms}T"); long lowerBound = System.currentTimeMillis(); - _connector.getResponse("GET / HTTP/1.0\n\n"); + _connector.getResponse("GET /delay HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); - long duration = upperBound-lowerBound; - assertThat(Long.parseLong(log), greaterThan((long)0)); - assertThat(Long.parseLong(log), lessThanOrEqualTo(duration)); + long measuredDuration = Long.parseLong(log); + long durationLowerBound = DELAY; + long durationUpperBound = upperBound-lowerBound + DELAY; + + assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); + assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); } @Test @@ -428,10 +435,12 @@ public class CustomRequestLogTest String log = _entries.poll(5,TimeUnit.SECONDS); long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long measuredDuration = Long.parseLong(log); + long durationLowerBound = TimeUnit.MILLISECONDS.toSeconds(DELAY); + long durationUpperBound = TimeUnit.MILLISECONDS.toSeconds(upperBound-lowerBound + DELAY); - long duration = upperBound-lowerBound; - assertThat(Long.parseLong(log), greaterThan((long)0)); - assertThat(Long.parseLong(log), lessThanOrEqualTo(TimeUnit.MILLISECONDS.toMicros(duration))); + assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); + assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); } @Test @@ -563,7 +572,7 @@ public class CustomRequestLogTest { try { - Thread.sleep(2000); + Thread.sleep(DELAY); } catch (InterruptedException e) { diff --git a/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java b/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java index 72374e44e17..bab1eb21ef2 100644 --- a/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java +++ b/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java @@ -21,6 +21,7 @@ package org.eclipse.jetty.servlet; import java.io.IOException; import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; + import javax.servlet.ServletException; import javax.servlet.ServletOutputStream; import javax.servlet.http.HttpServlet; @@ -92,7 +93,7 @@ public class CustomRequestLogTest { testHandlerServerStart("RequestHandler: %R"); - _connector.getResponse("GET / HTTP/1.0\n\n"); + _connector.getResponse("GET /context/servlet/ HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); assertThat(log, Matchers.containsString("TestServlet")); } From 982895719cc900d5ca126770ea8089b583368590 Mon Sep 17 00:00:00 2001 From: Lachlan Roberts Date: Wed, 28 Nov 2018 14:58:28 +0100 Subject: [PATCH 21/24] Issue #113 - changes from review and bug fixes %t now takes in locale and timezone in the format string argument instead of getting it from the setters on the CustomRequestLog class fixed issue with multiline format strings requestLog writers are now managed objects Signed-off-by: Lachlan Roberts --- .../jetty/server/AsyncRequestLogWriter.java | 8 +- .../jetty/server/CustomRequestLog.java | 103 ++++++++---------- .../jetty/server/RequestLogWriter.java | 10 ++ .../jetty/server/Slf4jRequestLogWriter.java | 7 ++ .../server/handler/CustomRequestLogTest.java | 18 ++- 5 files changed, 82 insertions(+), 64 deletions(-) diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java b/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java index 4c79d50ffb0..7efc1ee760e 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java @@ -75,14 +75,14 @@ public class AsyncRequestLogWriter extends RequestLogWriter AsyncRequestLogWriter.super.write(log); } } - catch (IOException e) - { - LOG.warn(e); - } catch (InterruptedException e) { LOG.ignore(e); } + catch (Throwable t) + { + LOG.warn(t); + } } } } diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index 5556a7575c3..179690bad7c 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -25,6 +25,7 @@ import java.util.ArrayList; import java.util.Collections; import java.util.List; import java.util.Locale; +import java.util.TimeZone; import java.util.concurrent.TimeUnit; import java.util.function.Supplier; import java.util.regex.Matcher; @@ -199,12 +200,22 @@ import static java.lang.invoke.MethodType.methodType; *
%{format}t%{format|timeZone|locale}t - * The time, in the form given by an optional format, parameter (default format [18/Sep/2011:19:18:28 -0400] where - * the last number indicates the timezone offset from GMT.) - *
- * The format parameter should be in a format supported by {@link DateCache} + * The time that the request was received. + * Optional parameter in one of the following formats {format}, {format|timeZone} or {format|timeZone|locale}.

+ * + * 
+ * Format Parameter: (default format [18/Sep/2011:19:18:28 -0400] where the last number indicates the timezone offset from GMT.)
+ *     Must be in a format supported by {@link DateCache}
+ *
+ * TimeZone Parameter:
+ *     Default timeZone GMT
+ *     Must be in a format supported by {@link TimeZone#getTimeZone(String)}
+ *
+ * Locale Parameter:
+ *     Default locale {@link Locale#getDefault()}
+ *     Must be in a format supported by {@link Locale#forLanguageTag(String)}
*
%{clf}I%{CLF}I * Size of request in bytes, excluding HTTP headers. - * Optional parameter with value of clf to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. + * Optional parameter with value of "CLF" to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. *
%{clf}O%{CLF}O * Size of response in bytes, excluding HTTP headers. - * Optional parameter with value of clf to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. + * Optional parameter with value of "CLF" to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. *
%{clf}S%{CLF}S * Bytes transferred (received and sent). This is the combination of %I and %O. - * Optional parameter with value of clf to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. + * Optional parameter with value of "CLF" to use CLF format, i.e. a '-' rather than a 0 when no bytes are sent. *