Access log nanoseconds

java/org/apache/catalina/AccessLog.java

@@ -16,6 +16,8 @@
  */
 package org.apache.catalina;
 
+import java.util.concurrent.TimeUnit;
+
 import org.apache.catalina.connector.Request;
 import org.apache.catalina.connector.Response;
 
@@ -57,13 +59,30 @@ public interface AccessLog {
 
     /**
      * Add the request/response to the access log using the specified processing time.
+     * <p>
+     * Note: As of Tomcat 10.1.x, this method will expect nanoseconds rather than milliseconds.
      *
      * @param request  Request (associated with the response) to log
      * @param response Response (associated with the request) to log
      * @param time     Time taken to process the request/response in milliseconds (use 0 if not known)
      */
     void log(Request request, Response response, long time);
 
+    /**
+     * Add the request/response to the access log using the specified processing time.
+     *
+     * @param request  Request (associated with the response) to log
+     * @param response Response (associated with the request) to log
+     * @param time     Time taken to process the request/response in nanoseconds (use 0 if not known)
+     *
+     * @deprecated This will be removed in Tomcat 10.1.x and the {@link #log(Request, Response, long)} method changed to
+     *                 expect nanoseconds.
+     */
+    @Deprecated
+    default void logNanos(Request request, Response response, long time) {
+        log(request, response, TimeUnit.NANOSECONDS.toMillis(time));
+    }
+
     /**
      * Should this valve use request attributes for IP address, hostname, protocol and port used for the request? The
      * attributes used are:

java/org/apache/catalina/Container.java

@@ -18,6 +18,7 @@
 
 import java.beans.PropertyChangeListener;
 import java.io.File;
+import java.util.concurrent.TimeUnit;
 
 import javax.management.ObjectName;
 
@@ -427,6 +428,8 @@ static Service getService(Container container) {
     /**
      * Log a request/response that was destined for this container but has been handled earlier in the processing chain
      * so that the request/response still appears in the correct access logs.
+     * <p>
+     * Note: As of Tomcat 10.1.x, this method will expect nanoseconds rather than milliseconds.
      *
      * @param request    Request (associated with the response) to log
      * @param response   Response (associated with the request) to log
@@ -437,6 +440,25 @@ static Service getService(Container container) {
     void logAccess(Request request, Response response, long time, boolean useDefault);
 
 
+    /**
+     * Log a request/response that was destined for this container but has been handled earlier in the processing chain
+     * so that the request/response still appears in the correct access logs.
+     *
+     * @param request    Request (associated with the response) to log
+     * @param response   Response (associated with the request) to log
+     * @param time       Time taken to process the request/response in nanoseconds (use 0 if not known)
+     * @param useDefault Flag that indicates that the request/response should be logged in the engine's default access
+     *                       log
+     *
+     * @deprecated This will be removed in Tomcat 10.1.x and the {@link #logAccess(Request, Response, long, boolean)}
+     *                 method changed to expect nanoseconds.
+     */
+    @Deprecated
+    default void logAccessNanos(Request request, Response response, long time, boolean useDefault) {
+        logAccess(request, response, TimeUnit.NANOSECONDS.toMillis(time), useDefault);
+    }
+
+
     /**
      * Obtain the AccessLog to use to log a request/response that is destined for this container. This is typically used
      * when the request/response was handled (and rejected) earlier in the processing chain so that the request/response

java/org/apache/catalina/connector/CoyoteAdapter.java

@@ -20,6 +20,7 @@
 import java.nio.charset.Charset;
 import java.nio.charset.StandardCharsets;
 import java.util.EnumSet;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 
 import javax.servlet.ReadListener;
@@ -110,6 +111,7 @@ public CoyoteAdapter(Connector connector) {
 
     // -------------------------------------------------------- Adapter Methods
 
+    @SuppressWarnings("deprecation")
     @Override
     public boolean asyncDispatch(org.apache.coyote.Request req, org.apache.coyote.Response res, SocketEvent status)
             throws Exception {
@@ -278,14 +280,14 @@ public boolean asyncDispatch(org.apache.coyote.Request req, org.apache.coyote.Re
             // Access logging
             if (!success || !request.isAsync()) {
                 long time = 0;
-                if (req.getStartTime() != -1) {
-                    time = System.currentTimeMillis() - req.getStartTime();
+                if (req.getStartTimeNanos() != -1) {
+                    time = System.nanoTime() - req.getStartTimeNanos();
                 }
                 Context context = request.getContext();
                 if (context != null) {
-                    context.logAccess(request, response, time, false);
+                    context.logAccessNanos(request, response, time, false);
                 } else {
-                    log(req, res, time);
+                    logNanos(req, res, time);
                 }
             }
 
@@ -302,6 +304,7 @@ public boolean asyncDispatch(org.apache.coyote.Request req, org.apache.coyote.Re
     }
 
 
+    @SuppressWarnings("deprecation")
     @Override
     public void service(org.apache.coyote.Request req, org.apache.coyote.Response res) throws Exception {
 
@@ -404,14 +407,14 @@ public void service(org.apache.coyote.Request req, org.apache.coyote.Response re
                 // The other possibility is that an error occurred early in
                 // processing and the request could not be mapped to a Context.
                 // Log via the host or engine in that case.
-                long time = System.currentTimeMillis() - req.getStartTime();
+                long time = System.nanoTime() - req.getStartTimeNanos();
                 if (context != null) {
-                    context.logAccess(request, response, time, false);
+                    context.logAccessNanos(request, response, time, false);
                 } else if (response.isError()) {
                     if (host != null) {
-                        host.logAccess(request, response, time, false);
+                        host.logAccessNanos(request, response, time, false);
                     } else {
-                        connector.getService().getContainer().logAccess(request, response, time, false);
+                        connector.getService().getContainer().logAccessNanos(request, response, time, false);
                     }
                 }
             }
@@ -451,6 +454,13 @@ public boolean prepare(org.apache.coyote.Request req, org.apache.coyote.Response
 
     @Override
     public void log(org.apache.coyote.Request req, org.apache.coyote.Response res, long time) {
+        logNanos(req, res, TimeUnit.MILLISECONDS.toNanos(time));
+    }
+
+
+    @Deprecated
+    @Override
+    public void logNanos(org.apache.coyote.Request req, org.apache.coyote.Response res, long time) {
 
         Request request = (Request) req.getNote(ADAPTER_NOTES);
         Response response = (Response) res.getNote(ADAPTER_NOTES);
@@ -482,13 +492,13 @@ public void log(org.apache.coyote.Request req, org.apache.coyote.Response res, l
             Host host = request.mappingData.host;
             if (context != null) {
                 logged = true;
-                context.logAccess(request, response, time, true);
+                context.logAccessNanos(request, response, time, true);
             } else if (host != null) {
                 logged = true;
-                host.logAccess(request, response, time, true);
+                host.logAccessNanos(request, response, time, true);
             }
             if (!logged) {
-                connector.getService().getContainer().logAccess(request, response, time, true);
+                connector.getService().getContainer().logAccessNanos(request, response, time, true);
             }
         } catch (Throwable t) {
             ExceptionUtils.handleThrowable(t);
@@ -518,7 +528,7 @@ public void checkRecycled(org.apache.coyote.Request req, org.apache.coyote.Respo
         if (messageKey != null) {
             // Log this request, as it has probably skipped the access log.
             // The log() method will take care of recycling.
-            log(req, res, 0L);
+            logNanos(req, res, 0L);
 
             if (connector.getState().isAvailable()) {
                 if (log.isInfoEnabled()) {
@@ -607,7 +617,7 @@ protected boolean postParseRequest(org.apache.coyote.Request req, Request reques
                 }
                 res.setHeader("Allow", allow.toString());
                 // Access log entry as processing won't reach AccessLogValve
-                connector.getService().getContainer().logAccess(request, response, 0, true);
+                connector.getService().getContainer().logAccessNanos(request, response, 0, true);
                 return false;
             } else {
                 response.sendError(400, sm.getString("coyoteAdapter.invalidURI"));
@@ -809,7 +819,7 @@ protected boolean postParseRequest(org.apache.coyote.Request req, Request reques
                 redirectPath = redirectPath + "?" + query;
             }
             response.sendRedirect(redirectPath);
-            request.getContext().logAccess(request, response, 0, true);
+            request.getContext().logAccessNanos(request, response, 0, true);
             return false;
         }
 

java/org/apache/catalina/core/AccessLogAdapter.java

@@ -18,6 +18,7 @@
 
 import java.util.Arrays;
 import java.util.Objects;
+import java.util.concurrent.TimeUnit;
 
 import org.apache.catalina.AccessLog;
 import org.apache.catalina.connector.Request;
@@ -44,8 +45,14 @@ public void add(AccessLog log) {
 
     @Override
     public void log(Request request, Response response, long time) {
+        logNanos(request, response, TimeUnit.MILLISECONDS.toNanos(time));
+    }
+
+    @SuppressWarnings("deprecation")
+    @Override
+    public void logNanos(Request request, Response response, long time) {
         for (AccessLog log : logs) {
-            log.log(request, response, time);
+            log.logNanos(request, response, time);
         }
     }
 

java/org/apache/catalina/core/ContainerBase.java

@@ -877,18 +877,25 @@ protected void destroyInternal() throws LifecycleException {
 
     @Override
     public void logAccess(Request request, Response response, long time, boolean useDefault) {
+        logAccessNanos(request, response, TimeUnit.MILLISECONDS.toNanos(time), useDefault);
+    }
+
+
+    @SuppressWarnings("deprecation")
+    @Override
+    public void logAccessNanos(Request request, Response response, long time, boolean useDefault) {
 
         boolean logged = false;
 
         if (getAccessLog() != null) {
-            getAccessLog().log(request, response, time);
+            getAccessLog().logNanos(request, response, time);
             logged = true;
         }
 
         if (getParent() != null) {
             // No need to use default logger once request/response has been logged
             // once
-            getParent().logAccess(request, response, time, (useDefault && !logged));
+            getParent().logAccessNanos(request, response, time, (useDefault && !logged));
         }
     }
 

java/org/apache/catalina/core/StandardEngine.java

@@ -219,13 +219,14 @@ protected void startInternal() throws LifecycleException {
      * default host and then the default host's ROOT context. If still none is found, return the default NoOp access
      * log.
      */
+    @SuppressWarnings("deprecation")
     @Override
-    public void logAccess(Request request, Response response, long time, boolean useDefault) {
+    public void logAccessNanos(Request request, Response response, long time, boolean useDefault) {
 
         boolean logged = false;
 
         if (getAccessLog() != null) {
-            accessLog.log(request, response, time);
+            accessLog.logNanos(request, response, time);
             logged = true;
         }
 
@@ -268,7 +269,7 @@ public void logAccess(Request request, Response response, long time, boolean use
                 }
             }
 
-            newDefaultAccessLog.log(request, response, time);
+            newDefaultAccessLog.logNanos(request, response, time);
         }
     }