Issue #113 - CustomRequestLog

added missing copyright header in some new files

added CustomRequestLogTest in jetty-servlet to test things like
logFilename and logRequestHandler

the log strings produced do no longer contain a trailing newline

implemented more tests in CustomRequestLogTest
and finished implementing some of the logging in CustomRequestLog

Signed-off-by: Lachlan Roberts <lachlan@webtide.com>

jetty-security/src/test/java/org/eclipse/jetty/security/ConstraintTest.java

@@ -18,17 +18,6 @@
 
 package org.eclipse.jetty.security;
 
-import static org.hamcrest.MatcherAssert.assertThat;
-import static org.hamcrest.Matchers.containsString;
-import static org.hamcrest.Matchers.is;
-import static org.hamcrest.Matchers.isIn;
-import static org.hamcrest.Matchers.not;
-import static org.hamcrest.Matchers.startsWith;
-import static org.junit.jupiter.api.Assertions.assertEquals;
-import static org.junit.jupiter.api.Assertions.assertFalse;
-import static org.junit.jupiter.api.Assertions.assertNotNull;
-import static org.junit.jupiter.api.Assertions.assertTrue;
-
 import java.io.IOException;
 import java.nio.charset.StandardCharsets;
 import java.security.MessageDigest;
@@ -45,7 +34,6 @@ import java.util.function.Consumer;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 import java.util.stream.Stream;
-
 import javax.servlet.HttpConstraintElement;
 import javax.servlet.HttpMethodConstraintElement;
 import javax.servlet.ServletException;
@@ -83,6 +71,17 @@ import org.junit.jupiter.params.ParameterizedTest;
 import org.junit.jupiter.params.provider.Arguments;
 import org.junit.jupiter.params.provider.MethodSource;
 
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.is;
+import static org.hamcrest.Matchers.isIn;
+import static org.hamcrest.Matchers.not;
+import static org.hamcrest.Matchers.startsWith;
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertNotNull;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
 public class ConstraintTest
 {
     private static final String TEST_REALM = "TestRealm";
@@ -1526,6 +1525,12 @@ public class ConstraintTest
 
             UserIdentity.Scope scope = new UserIdentity.Scope()
             {
+                @Override
+                public ContextHandler getContextHandler()
+                {
+                    return null;
+                }
+
                 @Override
                 public String getContextPath()
                 {

jetty-server/src/main/java/org/eclipse/jetty/server/AsyncRequestLogWriter.java

@@ -1,3 +1,21 @@
+//
+//  ========================================================================
+//  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;

jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java

@@ -34,6 +34,7 @@ import javax.servlet.http.Cookie;
 import org.eclipse.jetty.http.HttpFields;
 import org.eclipse.jetty.http.QuotedCSV;
 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.component.ContainerLifeCycle;
@@ -172,22 +173,8 @@ import static java.lang.invoke.MethodType.methodType;
  <td>
  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.)
- <br><br>
+ <br>
- The format parameter should be in an extended strftime(3) format (potentially localized).
+ The format parameter should be in a format supported by {@link DateCache}
- 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.
-
- <br><br>In addition to the formats supported by strftime(3), the following format tokens are supported:
-
- <pre>
- 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
- </pre>
-
- 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.
  </td>
  </tr>
 
@@ -263,14 +250,13 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 {
     protected static final Logger LOG = Log.getLogger(CustomRequestLog.class);
 
-    //TODO previous NCSA format includes "" in the append, so %C would print out "cookies" if cookies exist and - without the "" if they do not
     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";
 
     private static ThreadLocal<StringBuilder> _buffers = ThreadLocal.withInitial(() -> new StringBuilder(256));
 
     private String[] _ignorePaths;
     private transient PathMappings<String> _ignorePathMap;
-    private final static String DEFAULT_DATE_FORMAT = "dd/MMM/yyyy:HH:mm:ss ZZZ";
     private Locale _logLocale = Locale.getDefault();
     private String _logTimeZone = "GMT";
 
@@ -445,7 +431,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
     private MethodHandle getLogHandle(String formatString) throws NoSuchMethodException, IllegalAccessException
     {
         MethodHandle append = MethodHandles.lookup().findStatic(CustomRequestLog.class, "append", methodType(Void.TYPE, String.class, StringBuilder.class));
-        MethodHandle logHandle = dropArguments(dropArguments(append.bindTo("\n"), 1, Request.class), 2, Response.class);
+        MethodHandle logHandle = MethodHandles.lookup().findStatic(CustomRequestLog.class, "logNothing", methodType(Void.TYPE, StringBuilder.class, Request.class, Response.class));
 
         List<Token> tokens = getTokens(formatString);
         Collections.reverse(tokens);
@@ -515,13 +501,12 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 
     private static class Token
     {
-        //todo make final
+        public final String code;
-        public String code = null;
+        public final String arg;
-        public String arg = null;
+        public final List<String> modifiers;
-        public List<String> modifiers = null;
+        public final boolean negated;
-        public boolean negated = false;
 
-        public String literal = null;
+        public final String literal;
 
         public Token(String code, String arg, List<String> modifiers, boolean negated)
         {
@@ -529,9 +514,16 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
             this.arg = arg;
             this.modifiers = modifiers;
             this.negated = negated;
+
+            this.literal = null;
         }
         public Token(String literal)
         {
+            this.code = null;
+            this.arg = null;
+            this.modifiers = null;
+            this.negated = false;
+
             this.literal = literal;
         }
 
@@ -539,6 +531,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
         {
             return(literal != null);
         }
+
         public boolean isPercentCode()
         {
             return(code != null);
@@ -578,7 +571,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
         {
             case "%":
             {
-                //todo use literal
                 specificHandle = dropArguments(dropArguments(append.bindTo("%"), 1, Request.class), 2, Response.class);
                 break;
             }
@@ -773,7 +765,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 
             case "t":
             {
-                //todo is this correctly supporting the right formats
                 DateCache logDateCache;
                 if (arg == null || arg.isEmpty())
                     logDateCache = new DateCache(DEFAULT_DATE_FORMAT, _logLocale , _logTimeZone);
@@ -787,7 +778,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
                 break;
             }
 
-
             case "T":
             {
                 if (arg == null)
@@ -910,10 +900,11 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 
 
 
-
-
     //-----------------------------------------------------------------------------------//
 
+    private static void logNothing(StringBuilder b, Request request, Response response)
+    {
+    }
 
     private static void logClientIP(StringBuilder b, Request request, Response response)
     {
@@ -984,8 +975,16 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 
     private static void logFilename(StringBuilder b, Request request, Response response)
     {
-        //TODO verify
+        UserIdentity.Scope scope = request.getUserIdentityScope();
-        append(b, request.getServletContext().getRealPath(request.getPathInfo()));
+        if (scope==null || scope.getContextHandler()==null)
+            b.append('-');
+        else
+        {
+            ContextHandler context = scope.getContextHandler();
+            int lengthToStrip = scope.getContextPath().length()>1 ? scope.getContextPath().length() : 0;
+            String filename = context.getServletContext().getRealPath(request.getPathInfo().substring(lengthToStrip));
+            append(b, filename);
+        }
     }
 
     private static void logRemoteHostName(StringBuilder b, Request request, Response response)
@@ -1053,7 +1052,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 
     private static void logRequestHandler(StringBuilder b, Request request, Response response)
     {
-        //todo verify
         append(b, request.getServletName());
     }
 
@@ -1072,7 +1070,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 
     private static void logLatencyMicroseconds(StringBuilder b, Request request, Response response)
     {
-        //todo can we use nanotime?
         long latency = System.currentTimeMillis() - request.getTimeStamp();
         b.append(TimeUnit.MILLISECONDS.toMicros(latency));
     }
@@ -1122,14 +1119,13 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog
 
     private static void logBytesSent(StringBuilder b, Request request, Response response)
     {
-        //todo redirect to logResponseSize
+        //todo difference between this and logResponseSize
-        append(b, "?");
+        b.append(response.getHttpOutput().getWritten());
     }
 
     private static void logBytesTransferred(StringBuilder b, Request request, Response response)
     {
-        //todo implement: bytesTransferred = bytesReceived+bytesSent
+        b.append(request.getHttpInput().getContentConsumed() + response.getHttpOutput().getWritten());
-        append(b, "?");
     }
 
     private static void logRequestTrailer(String arg, StringBuilder b, Request request, Response response)

jetty-server/src/main/java/org/eclipse/jetty/server/RequestLogWriter.java

@@ -1,3 +1,21 @@
+//
+//  ========================================================================
+//  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;
@@ -7,7 +25,6 @@ import java.io.Writer;
 import java.util.TimeZone;
 
 import org.eclipse.jetty.util.RolloverFileOutputStream;
-import org.eclipse.jetty.util.StringUtil;
 import org.eclipse.jetty.util.component.AbstractLifeCycle;
 import org.eclipse.jetty.util.log.Log;
 import org.eclipse.jetty.util.log.Logger;
@@ -163,7 +180,7 @@ public class RequestLogWriter extends AbstractLifeCycle implements RequestLog.Wr
             if (_writer==null)
                 return;
             _writer.write(requestEntry);
-            _writer.write(StringUtil.__LINE_SEPARATOR);
+            _writer.write(System.lineSeparator());
             _writer.flush();
         }
     }

jetty-server/src/main/java/org/eclipse/jetty/server/Slf4jRequestLogWriter.java

@@ -1,3 +1,21 @@
+//
+//  ========================================================================
+//  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;

jetty-server/src/main/java/org/eclipse/jetty/server/UserIdentity.java

@@ -20,9 +20,10 @@ package org.eclipse.jetty.server;
 
 import java.security.Principal;
 import java.util.Map;
-
 import javax.security.auth.Subject;
 
+import org.eclipse.jetty.server.handler.ContextHandler;
+
 /** 
  * User object that encapsulates user identity and operations such as run-as-role actions,
  * checking isUserInRole and getUserPrincipal.
@@ -64,6 +65,12 @@ public interface UserIdentity
      */
     interface Scope
     {
+        /* ------------------------------------------------------------ */
+        /**
+         * @return The context handler that the identity is being considered within
+         */
+        ContextHandler getContextHandler();
+
         /* ------------------------------------------------------------ */
         /**
          * @return The context path that the identity is being considered within

jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java

@@ -32,21 +32,26 @@ import org.eclipse.jetty.server.Request;
 import org.eclipse.jetty.server.RequestLog;
 import org.eclipse.jetty.server.Server;
 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.Test;
 
 import static org.hamcrest.MatcherAssert.assertThat;
+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.junit.jupiter.api.Assertions.fail;
 
 public class CustomRequestLogTest
 {
-    RequestLog _log;
+    CustomRequestLog _log;
     Server _server;
     LocalConnector _connector;
     BlockingQueue<String> _entries = new BlockingArrayQueue<>();
+    BlockingQueue<Long> requestTimes = new BlockingArrayQueue<>();
 
 
     @BeforeEach
@@ -72,8 +77,6 @@ public class CustomRequestLogTest
         _server.stop();
     }
 
-
-
     @Test
     public void testModifier() throws Exception
     {
@@ -81,24 +84,17 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET /error404 HTTP/1.0\nReferer: testReferer\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("404: -\n"));
+        assertThat(log, is("404: -"));
 
         _connector.getResponse("GET /error301 HTTP/1.0\nReferer: testReferer\n\n");
         log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("301: -\n"));
+        assertThat(log, is("301: -"));
 
         _connector.getResponse("GET /success HTTP/1.0\nReferer: testReferer\n\n");
         log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("200: testReferer\n"));
+        assertThat(log, is("200: testReferer"));
     }
 
-    @Test
-    public void testInvalidArguments() throws Exception
-    {
-        fail();
-    }
-
-
     @Test
     public void testDoublePercent() throws Exception
     {
@@ -106,7 +102,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("%%%a\n"));
+        assertThat(log, is("%%%a"));
     }
 
     @Test
@@ -146,11 +142,11 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("ResponseSize: 0\n"));
+        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\n"));
+        assertThat(log, is("ResponseSize: 11"));
     }
 
     @Test
@@ -160,11 +156,11 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("ResponseSize: -\n"));
+        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\n"));
+        assertThat(log, is("ResponseSize: 11"));
     }
 
     @Test
@@ -174,7 +170,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\nCookie: cookieName=cookieValue; cookie2=value2\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("RequestCookies: cookieValue, value2, -\n"));
+        assertThat(log, is("RequestCookies: cookieValue, value2, -"));
     }
 
     @Test
@@ -184,7 +180,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\nCookie: cookieName=cookieValue; cookie2=value2\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("RequestCookies: cookieName=cookieValue;cookie2=value2\n"));
+        assertThat(log, is("RequestCookies: cookieName=cookieValue;cookie2=value2"));
     }
 
     @Test
@@ -194,17 +190,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("EnvironmentVar: " + System.getenv("JAVA_HOME") + "\n"));
+        assertThat(log, is("EnvironmentVar: " + System.getenv("JAVA_HOME") + ""));
-    }
-
-    @Test
-    public void testLogFilename() throws Exception
-    {
-        testHandlerServerStart("Filename: %f");
-
-        _connector.getResponse("GET / HTTP/1.0\n\n");
-        String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
     }
 
     @Test
@@ -224,7 +210,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("Protocol: HTTP/1.0\n"));
+        assertThat(log, is("Protocol: HTTP/1.0"));
     }
 
     @Test
@@ -234,7 +220,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\nHeader1: value1\nHeader2: value2\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("RequestHeader: value1, value2, -\n"));
+        assertThat(log, is("RequestHeader: value1, value2, -"));
     }
 
     @Test
@@ -242,14 +228,29 @@ public class CustomRequestLogTest
     {
         testHandlerServerStart("KeepAliveRequests: %k");
 
-        _connector.getResponse("GET / HTTP/1.0\n\n");
+        LocalConnector.LocalEndPoint connect = _connector.connect();
-        _connector.getResponse("GET / HTTP/1.0\n\n");
+        connect.addInput("GET /a HTTP/1.0\n" +
-        _connector.getResponse("GET / HTTP/1.0\n\n");
+                "Connection: keep-alive\n\n");
+        connect.addInput("GET /a HTTP/1.1\n" +
+                "Host: localhost\n\n");
 
-        _entries.poll(5,TimeUnit.SECONDS);
+        assertThat(connect.getResponse(), containsString("200 OK"));
-        _entries.poll(5,TimeUnit.SECONDS);
+        assertThat(connect.getResponse(), containsString("200 OK"));
-        String log = _entries.poll(5,TimeUnit.SECONDS);
+
-        fail(log);
+        connect.addInput("GET /a HTTP/1.0\n\n");
+        assertThat(connect.getResponse(), containsString("200 OK"));
+
+
+        assertThat(_entries.poll(5,TimeUnit.SECONDS), is("KeepAliveRequests: 1"));
+        assertThat(_entries.poll(5,TimeUnit.SECONDS), is("KeepAliveRequests: 2"));
+        assertThat(_entries.poll(5,TimeUnit.SECONDS), is("KeepAliveRequests: 3"));
+    }
+
+    @Test
+    public void testLogKeepAliveRequestsHttp2() throws Exception
+    {
+        testHandlerServerStart("KeepAliveRequests: %k");
+        fail();
     }
 
     @Test
@@ -259,7 +260,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("RequestMethod: GET\n"));
+        assertThat(log, is("RequestMethod: GET"));
     }
 
     @Test
@@ -269,7 +270,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET /responseHeaders HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("ResponseHeader: value1, value2, -\n"));
+        assertThat(log, is("ResponseHeader: value1, value2, -"));
     }
 
     @Test
@@ -318,7 +319,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET /path?queryString HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("QueryString: ?queryString\n"));
+        assertThat(log, is("QueryString: ?queryString"));
     }
 
     @Test
@@ -328,17 +329,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET /path?query HTTP/1.0\nHeader: null\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("RequestFirstLin: GET /path?query HTTP/1.0\n"));
+        assertThat(log, is("RequestFirstLin: GET /path?query HTTP/1.0"));
-    }
-
-    @Test
-    public void testLogRequestHandler() throws Exception
-    {
-        testHandlerServerStart("RequestHandler: %R");
-
-        _connector.getResponse("GET / HTTP/1.0\n\n");
-        String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
     }
 
     @Test
@@ -348,15 +339,15 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET /error404 HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("LogResponseStatus: 404\n"));
+        assertThat(log, is("LogResponseStatus: 404"));
 
         _connector.getResponse("GET /error301 HTTP/1.0\n\n");
         log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("LogResponseStatus: 301\n"));
+        assertThat(log, is("LogResponseStatus: 301"));
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("LogResponseStatus: 200\n"));
+        assertThat(log, is("LogResponseStatus: 200"));
     }
 
     @Test
@@ -366,63 +357,67 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
+        long requestTime = requestTimes.poll(5,TimeUnit.SECONDS).longValue();
+        DateCache dateCache = new DateCache(_log.DEFAULT_DATE_FORMAT, _log.getLogLocale(), _log.getLogTimeZone());
+        assertThat(log, is("RequestTime: ["+ dateCache.format(requestTime) +"]"));
     }
 
     @Test
     public void testLogRequestTimeCustomFormats() throws Exception
     {
-        /*
+        testHandlerServerStart("RequestTime: %{EEE MMM dd HH:mm:ss zzz yyyy}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.
-        */
-
-        testHandlerServerStart("RequestTime: %{?}t");
 
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
+        long requestTime = requestTimes.poll(5,TimeUnit.SECONDS).longValue();
+        DateCache dateCache = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", _log.getLogLocale(), _log.getLogTimeZone());
+        assertThat(log, is("RequestTime: ["+ dateCache.format(requestTime) +"]"));
     }
 
     @Test
     public void testLogLatencyMicroseconds() throws Exception
     {
-        testHandlerServerStart("LatencyMicroseconds: %{us}Tus");
+        testHandlerServerStart("%{us}T");
 
+        long lowerBound = System.currentTimeMillis();
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
+        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)));
     }
 
     @Test
     public void testLogLatencyMilliseconds() throws Exception
     {
-        testHandlerServerStart("LatencyMilliseconds: %{ms}Tms");
+        testHandlerServerStart("%{ms}T");
 
+        long lowerBound = System.currentTimeMillis();
         _connector.getResponse("GET / HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
+        long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS);
+
+        long duration = upperBound-lowerBound;
+        assertThat(Long.parseLong(log), greaterThan((long)0));
+        assertThat(Long.parseLong(log), lessThanOrEqualTo(duration));
     }
 
     @Test
     public void testLogLatencySeconds() throws Exception
     {
-        testHandlerServerStart("LatencySeconds: %{s}Ts");
+        testHandlerServerStart("%{s}T");
 
-        _connector.getResponse("GET / HTTP/1.0\n\n");
+        long lowerBound = System.currentTimeMillis();
+        _connector.getResponse("GET /delay HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
+        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)));
     }
 
     @Test
@@ -442,7 +437,7 @@ public class CustomRequestLogTest
 
         _connector.getResponse("GET /path?query HTTP/1.0\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        assertThat(log, is("UrlRequestPath: /path\n"));
+        assertThat(log, is("UrlRequestPath: /path"));
     }
 
     @Test
@@ -450,9 +445,9 @@ public class CustomRequestLogTest
     {
         testHandlerServerStart("ServerName: %v");
 
-        _connector.getResponse("GET / HTTP/1.0\n\n");
+        _connector.getResponse("GET / HTTP/1.0\nHost: webtide.com\n\n");
         String log = _entries.poll(5,TimeUnit.SECONDS);
-        fail(log);
+        assertThat(log, is("ServerName: webtide.com"));
     }
 
     @Test
@@ -555,7 +550,19 @@ public class CustomRequestLogTest
                 response.addHeader("Header1", "value1");
                 response.addHeader("Header2", "value2");
             }
+            else if (request.getRequestURI().contains("delay"))
+            {
+                try
+                {
+                    Thread.sleep(2000);
+                }
+                catch (InterruptedException e)
+                {
+                    e.printStackTrace();
+                }
+            }
 
+            requestTimes.offer(baseRequest.getTimeStamp());
             baseRequest.setHandled(true);
         }
     }

jetty-servlet/src/main/java/org/eclipse/jetty/servlet/ServletHolder.java

@@ -32,7 +32,6 @@ import java.util.List;
 import java.util.Map;
 import java.util.Set;
 import java.util.Stack;
-
 import javax.servlet.MultipartConfigElement;
 import javax.servlet.Servlet;
 import javax.servlet.ServletConfig;
@@ -756,6 +755,13 @@ public class ServletHolder extends Holder<Servlet> implements UserIdentity.Scope
         }
     }
 
+    /* ------------------------------------------------------------ */
+    @Override
+    public ContextHandler getContextHandler()
+    {
+        return ContextHandler.getContextHandler(_config.getServletContext());
+    }
+
     /* ------------------------------------------------------------ */
     /**
      * @see org.eclipse.jetty.server.UserIdentity.Scope#getContextPath()

jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java

@@ -0,0 +1,142 @@
+//
+//  ========================================================================
+//  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.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;
+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.RequestLog;
+import org.eclipse.jetty.server.Server;
+import org.eclipse.jetty.util.BlockingArrayQueue;
+import org.hamcrest.Matchers;
+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.is;
+
+public class CustomRequestLogTest
+{
+    RequestLog _log;
+    Server _server;
+    LocalConnector _connector;
+    BlockingQueue<String> _entries = new BlockingArrayQueue<>();
+    String _tmpDir = System.getProperty("java.io.tmpdir");
+
+    @BeforeEach
+    public void before()
+    {
+        _server = new Server();
+        _connector = new LocalConnector(_server);
+        _server.addConnector(_connector);
+    }
+
+    void testHandlerServerStart(String formatString) throws Exception
+    {
+        ServletContextHandler context = new ServletContextHandler(ServletContextHandler.SESSIONS);
+        context.setContextPath("/context");
+        context.setResourceBase(_tmpDir);
+        context.addServlet(TestServlet.class, "/servlet/*");
+
+        TestRequestLogWriter writer = new TestRequestLogWriter();
+        _log = new CustomRequestLog(writer, formatString);
+        _server.setRequestLog(_log);
+        _server.setHandler(context);
+        _server.start();
+    }
+
+    @AfterEach
+    public void after() throws Exception
+    {
+        _server.stop();
+    }
+
+    @Test
+    public void testLogFilename() throws Exception
+    {
+        testHandlerServerStart("Filename: %f");
+
+        _connector.getResponse("GET /context/servlet/info HTTP/1.0\n\n");
+        String log = _entries.poll(5,TimeUnit.SECONDS);
+        assertThat(log, is("Filename: " + _tmpDir + "/servlet/info"));
+    }
+
+
+    @Test
+    public void testLogRequestHandler() throws Exception
+    {
+        testHandlerServerStart("RequestHandler: %R");
+
+        _connector.getResponse("GET / HTTP/1.0\n\n");
+        String log = _entries.poll(5,TimeUnit.SECONDS);
+        assertThat(log, Matchers.containsString("TestServlet"));
+    }
+
+
+    class TestRequestLogWriter implements RequestLog.Writer
+    {
+        @Override
+        public void write(String requestEntry)
+        {
+            try
+            {
+                _entries.add(requestEntry);
+            }
+            catch(Exception e)
+            {
+                e.printStackTrace();
+            }
+        }
+    }
+
+    public static class TestServlet extends HttpServlet
+    {
+        @Override
+        protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException
+        {
+            if (request.getRequestURI().contains("error404"))
+            {
+                response.setStatus(404);
+            }
+            else if (request.getRequestURI().contains("error301"))
+            {
+                response.setStatus(301);
+            }
+            else if (request.getHeader("echo") != null)
+            {
+                ServletOutputStream outputStream = response.getOutputStream();
+                outputStream.print(request.getHeader("echo"));
+            }
+            else if (request.getRequestURI().contains("responseHeaders"))
+            {
+                response.addHeader("Header1", "value1");
+                response.addHeader("Header2", "value2");
+            }
+        }
+    }
+}