diff --git a/java/org/apache/catalina/AccessLog.java b/java/org/apache/catalina/AccessLog.java index 651bf033bd69..6ab13d0b642f 100644 --- a/java/org/apache/catalina/AccessLog.java +++ b/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,6 +59,8 @@ public interface AccessLog { /** * Add the request/response to the access log using the specified processing time. + *

+ * 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 @@ -64,6 +68,21 @@ public interface AccessLog { */ 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: diff --git a/java/org/apache/catalina/Container.java b/java/org/apache/catalina/Container.java index 4c2ed166c0b6..0e0d99b2fde8 100644 --- a/java/org/apache/catalina/Container.java +++ b/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. + *

+ * 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 diff --git a/java/org/apache/catalina/connector/CoyoteAdapter.java b/java/org/apache/catalina/connector/CoyoteAdapter.java index 6eccbdbc0f95..8388e56a95ef 100644 --- a/java/org/apache/catalina/connector/CoyoteAdapter.java +++ b/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; } diff --git a/java/org/apache/catalina/core/AccessLogAdapter.java b/java/org/apache/catalina/core/AccessLogAdapter.java index 666b058fd868..9e2a345a6c06 100644 --- a/java/org/apache/catalina/core/AccessLogAdapter.java +++ b/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); } } diff --git a/java/org/apache/catalina/core/ContainerBase.java b/java/org/apache/catalina/core/ContainerBase.java index e56074ba4a52..305cd1f01bcc 100644 --- a/java/org/apache/catalina/core/ContainerBase.java +++ b/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)); } } diff --git a/java/org/apache/catalina/core/StandardEngine.java b/java/org/apache/catalina/core/StandardEngine.java index 2089c4e50788..05da0fbfa4c1 100644 --- a/java/org/apache/catalina/core/StandardEngine.java +++ b/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); } } diff --git a/java/org/apache/catalina/valves/AbstractAccessLogValve.java b/java/org/apache/catalina/valves/AbstractAccessLogValve.java index 32aa5df0eeaa..d323477bc9c6 100644 --- a/java/org/apache/catalina/valves/AbstractAccessLogValve.java +++ b/java/org/apache/catalina/valves/AbstractAccessLogValve.java @@ -21,6 +21,7 @@ import java.io.IOException; import java.net.InetAddress; import java.text.SimpleDateFormat; +import java.time.Instant; import java.util.ArrayList; import java.util.Date; import java.util.Enumeration; @@ -30,6 +31,7 @@ import java.util.Locale; import java.util.Map; import java.util.TimeZone; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import javax.servlet.RequestDispatcher; @@ -83,9 +85,9 @@ *

  • %u - Remote user that was authenticated *
  • %U - Requested URL path *
  • %v - Local server name - *
  • %D - Time taken to process the request, in millis + *
  • %D - Time taken to process the request, in milliseconds *
  • %T - Time taken to process the request, in seconds - *
  • %F - Time taken to commit the response, in millis + *
  • %F - Time taken to commit the response, in milliseconds *
  • %I - current Request thread name (can compare later with stacktraces) *
  • %X - Connection status when response is completed: * *

    * Conditional logging is also supported. This can be done with the conditionUnless and @@ -659,27 +663,25 @@ public void invoke(Request request, Response response) throws IOException, Servl @Override public void log(Request request, Response response, long time) { + logNanos(request, response, TimeUnit.MILLISECONDS.toNanos(time)); + } + + + @Override + public void logNanos(Request request, Response response, long time) { if (!getState().isAvailable() || !getEnabled() || logElements == null || condition != null && null != request.getRequest().getAttribute(condition) || conditionIf != null && null == request.getRequest().getAttribute(conditionIf)) { return; } - /* - * XXX This is a bit silly, but we want to have start and stop time and duration consistent. It would be better - * to keep start and stop simply in the request and/or response object and remove time (duration) from the - * interface. - */ - long start = request.getCoyoteRequest().getStartTime(); - Date date = getDate(start + time); - CharArrayWriter result = charArrayWriters.pop(); if (result == null) { result = new CharArrayWriter(128); } for (AccessLogElement logElement : logElements) { - logElement.addElement(result, date, request, response, time); + logElement.addElement(result, request, response, time); } log(result); @@ -742,9 +744,43 @@ protected static Locale findLocale(String name, Locale fallback) { /** * AccessLogElement writes the partial message into the buffer. + *

    + * At least one method must be implemented else a loop will occur. + *

    + * When the deprecated method is removed in Tomcat 12, the default implementation for + * {@link #addElement(CharArrayWriter, Request, Response, long)} will also be removed. */ protected interface AccessLogElement { - void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time); + /** + * Called to create an access log entry. + * + * @param buf The buffer to which the log element should be added + * @param date The time stamp for the end of the request + * @param request The request that triggered this access log entry + * @param response The response to the request that triggered this access log entry + * @param time The time taken in milliseconds to process the request + * + * @deprecated Unused. Will be removed in Tomcat 12. Use + * {@link #addElement(CharArrayWriter, Request, Response, long)} + */ + @Deprecated + default void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + addElement(buf, request, response, TimeUnit.MILLISECONDS.toNanos(time)); + } + + /** + * Called to create an access log entry. + * + * @param buf The buffer to which the log element should be added + * @param request The request that triggered this access log entry + * @param response The response to the request that triggered this access log entry + * @param time The time taken in nanoseconds to process the request + */ + default void addElement(CharArrayWriter buf, Request request, Response response, long time) { + long durationMilliseconds = TimeUnit.NANOSECONDS.toMillis(time); + Date date = getDate(request.getCoyoteRequest().getStartTime() + durationMilliseconds); + addElement(buf, date, request, response, durationMilliseconds); + } } /** @@ -763,7 +799,7 @@ protected interface CachedElement { */ protected static class ThreadNameElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { RequestInfo info = request.getCoyoteRequest().getRequestProcessor(); if (info != null) { buf.append(info.getWorkerThreadName()); @@ -797,7 +833,7 @@ public LocalAddrElement(boolean ipv6Canonical) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { buf.append(localAddrValue); } } @@ -834,7 +870,7 @@ public RemoteAddrElement(String type) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String value = null; if (remoteAddressType == RemoteAddressType.PEER) { value = request.getPeerAddr(); @@ -874,7 +910,7 @@ public void cache(Request request) { */ protected class HostElement implements AccessLogElement, CachedElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String value = null; if (requestAttributesEnabled) { Object host = request.getAttribute(REMOTE_HOST_ATTRIBUTE); @@ -908,7 +944,7 @@ public void cache(Request request) { */ protected static class LogicalUserNameElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { buf.append('-'); } } @@ -918,7 +954,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected class ProtocolElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (requestAttributesEnabled) { Object proto = request.getAttribute(PROTOCOL_ATTRIBUTE); if (proto == null) { @@ -937,7 +973,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class UserElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (request != null) { String value = request.getRemoteUser(); if (value != null) { @@ -1080,11 +1116,11 @@ protected DateAndTimeElement(String sdf) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { - long timestamp = date.getTime(); + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { + Instant requestStartInstant = Instant.from(request.getCoyoteRequest().getStartInstant()); long frac; - if (usesBegin) { - timestamp -= time; + if (!usesBegin) { + requestStartInstant.plusNanos(time); } /* * Implementation note: This is deliberately not implemented using switch. If a switch is used the compiler @@ -1094,13 +1130,13 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response * pre-loading up to date as the name changes is error prone. */ if (type == FormatType.CLF) { - buf.append(localDateCache.get().getFormat(timestamp)); + buf.append(localDateCache.get().getFormat(requestStartInstant.toEpochMilli())); } else if (type == FormatType.SEC) { - buf.append(Long.toString(timestamp / 1000)); + buf.append(Long.toString(requestStartInstant.getEpochSecond())); } else if (type == FormatType.MSEC) { - buf.append(Long.toString(timestamp)); + buf.append(Long.toString(requestStartInstant.toEpochMilli())); } else if (type == FormatType.MSEC_FRAC) { - frac = timestamp % 1000; + frac = requestStartInstant.toEpochMilli() % 1000; if (frac < 100) { if (frac < 10) { buf.append('0'); @@ -1112,6 +1148,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response buf.append(Long.toString(frac)); } else { // FormatType.SDF + long timestamp = requestStartInstant.toEpochMilli(); String temp = localDateCache.get().getFormat(format, locale, timestamp); if (usesMsecs) { frac = timestamp % 1000; @@ -1140,7 +1177,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class RequestElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (request != null) { String method = request.getMethod(); if (method == null) { @@ -1168,7 +1205,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class HttpStatusCodeElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (response != null) { // This approach is used to reduce GC from toString conversion int status = response.getStatus(); @@ -1217,7 +1254,7 @@ public PortElement(String type) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (requestAttributesEnabled && portType == PortType.LOCAL) { Object port = request.getAttribute(SERVER_PORT_ATTRIBUTE); if (port == null) { @@ -1256,7 +1293,7 @@ public ByteSentElement(boolean conversion) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { // Don't need to flush since trigger for log message is after the // response has been committed long length = response.getBytesWritten(false); @@ -1284,7 +1321,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class MethodElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (request != null) { buf.append(request.getMethod()); } @@ -1295,29 +1332,77 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response * write time taken to process the request - %D, %T */ protected static class ElapsedTimeElement implements AccessLogElement { - private final boolean millis; + public enum Style { + SECONDS { + @Override + public void append(CharArrayWriter buf, long time) { + buf.append(Long.toString(TimeUnit.NANOSECONDS.toSeconds(time))); + } + }, + SECONDS_FRACTIONAL { + @Override + public void append(CharArrayWriter buf, long time) { + time = time / 1000000; // Convert to millis + buf.append(Long.toString(time / 1000)); + buf.append('.'); + int remains = (int) (time % 1000); + buf.append(Long.toString(remains / 100)); + remains = remains % 100; + buf.append(Long.toString(remains / 10)); + buf.append(Long.toString(remains % 10)); + } + }, + MILLISECONDS { + @Override + public void append(CharArrayWriter buf, long time) { + buf.append(Long.toString(TimeUnit.NANOSECONDS.toMillis(time))); + } + }, + MICROSECONDS { + @Override + public void append(CharArrayWriter buf, long time) { + buf.append(Long.toString(TimeUnit.NANOSECONDS.toMicros(time))); + } + }, + NANOSECONDS { + @Override + public void append(CharArrayWriter buf, long time) { + buf.append(Long.toString(time)); + } + }; + + /** + * Append the time to the buffer in the appropriate format. + * + * @param buf The buffer to append to. + * @param time The time to log in nanoseconds. + */ + public abstract void append(CharArrayWriter buf, long time); + } + + private final Style style; + + /** + * Creates a new ElapsedTimeElement that will log the time in the specified style. + * + * @param style The elapsed-time style to use. + */ + public ElapsedTimeElement(Style style) { + this.style = style; + } /** - * @param millis true, write time in millis - %D, if false, write time in seconds - %T + * @param micros true, write time in microseconds + * @param millis true, write time in milliseconds - %D, if both arguments are false, write + * time in seconds - %T */ - public ElapsedTimeElement(boolean millis) { - this.millis = millis; + public ElapsedTimeElement(boolean micros, boolean millis) { + this(micros ? Style.MICROSECONDS : millis ? Style.MILLISECONDS : Style.SECONDS_FRACTIONAL); } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { - if (millis) { - buf.append(Long.toString(time)); - } else { - // second - buf.append(Long.toString(time / 1000)); - buf.append('.'); - int remains = (int) (time % 1000); - buf.append(Long.toString(remains / 100)); - remains = remains % 100; - buf.append(Long.toString(remains / 10)); - buf.append(Long.toString(remains % 10)); - } + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { + style.append(buf, time); } } @@ -1326,13 +1411,13 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class FirstByteTimeElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { - long commitTime = response.getCoyoteResponse().getCommitTime(); + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { + long commitTime = response.getCoyoteResponse().getCommitTimeNanos(); if (commitTime == -1) { buf.append('-'); } else { - long delta = commitTime - request.getCoyoteRequest().getStartTime(); - buf.append(Long.toString(delta)); + long delta = commitTime - request.getCoyoteRequest().getStartTimeNanos(); + buf.append(Long.toString(TimeUnit.NANOSECONDS.toMillis(delta))); } } } @@ -1342,7 +1427,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class QueryElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String query = null; if (request != null) { query = request.getQueryString(); @@ -1359,7 +1444,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class SessionIdElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (request == null) { buf.append('-'); } else { @@ -1378,7 +1463,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class RequestURIElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (request != null) { buf.append(request.getRequestURI()); } else { @@ -1392,7 +1477,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected class LocalServerNameElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String value = null; if (requestAttributesEnabled) { Object serverName = request.getAttribute(SERVER_NAME_ATTRIBUTE); @@ -1425,7 +1510,7 @@ public StringElement(String str) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { buf.append(str); } } @@ -1441,7 +1526,7 @@ public HeaderElement(String header) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { Enumeration iter = request.getHeaders(header); if (iter.hasMoreElements()) { escapeAndAppend(iter.nextElement(), buf); @@ -1466,7 +1551,7 @@ public CookieElement(String cookieNameToLog) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { StringBuilder value = null; boolean first = true; Cookie[] cookies = request.getCookies(); @@ -1504,7 +1589,7 @@ public ResponseHeaderElement(String header) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (null != response) { Iterator iter = response.getHeaders(header).iterator(); if (iter.hasNext()) { @@ -1531,7 +1616,7 @@ public RequestAttributeElement(String attribute) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { Object value = null; if (request != null) { value = request.getAttribute(attribute); @@ -1561,7 +1646,7 @@ public SessionAttributeElement(String attribute) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { Object value = null; if (null != request) { HttpSession sess = request.getSession(false); @@ -1588,7 +1673,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response */ protected static class ConnectionStatusElement implements AccessLogElement { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (response != null && request != null) { boolean statusFound = false; @@ -1697,14 +1782,14 @@ private CachedElement[] createCachedElements(AccessLogElement[] elements) { */ protected AccessLogElement createAccessLogElement(String name, char pattern) { switch (pattern) { - case 'i': - return new HeaderElement(name); + case 'a': + return new RemoteAddrElement(name); case 'c': return new CookieElement(name); + case 'i': + return new HeaderElement(name); case 'o': return new ResponseHeaderElement(name); - case 'a': - return new RemoteAddrElement(name); case 'p': return new PortElement(name); case 'r': @@ -1716,6 +1801,19 @@ protected AccessLogElement createAccessLogElement(String name, char pattern) { return new SessionAttributeElement(name); case 't': return new DateAndTimeElement(name); + case 'T': + // ms for milliseconds, us for microseconds, and s for seconds + if ("ns".equals(name)) { + return new ElapsedTimeElement(ElapsedTimeElement.Style.NANOSECONDS); + } else if ("us".equals(name)) { + return new ElapsedTimeElement(ElapsedTimeElement.Style.MICROSECONDS); + } else if ("ms".equals(name)) { + return new ElapsedTimeElement(ElapsedTimeElement.Style.MILLISECONDS); + } else if ("fracsec".equals(name)) { + return new ElapsedTimeElement(ElapsedTimeElement.Style.SECONDS_FRACTIONAL); + } else { + return new ElapsedTimeElement(false, false); + } default: return new StringElement("???"); } @@ -1739,7 +1837,7 @@ protected AccessLogElement createAccessLogElement(char pattern) { case 'B': return new ByteSentElement(false); case 'D': - return new ElapsedTimeElement(true); + return new ElapsedTimeElement(false, true); case 'F': return new FirstByteTimeElement(); case 'h': @@ -1763,7 +1861,7 @@ protected AccessLogElement createAccessLogElement(char pattern) { case 't': return new DateAndTimeElement(); case 'T': - return new ElapsedTimeElement(false); + return new ElapsedTimeElement(false, false); case 'u': return new UserElement(); case 'U': diff --git a/java/org/apache/catalina/valves/ExtendedAccessLogValve.java b/java/org/apache/catalina/valves/ExtendedAccessLogValve.java index a7f9a04516bd..b0fd1bb2a991 100644 --- a/java/org/apache/catalina/valves/ExtendedAccessLogValve.java +++ b/java/org/apache/catalina/valves/ExtendedAccessLogValve.java @@ -144,11 +144,12 @@ protected static class DateElement implements AccessLogElement { ThreadLocal.withInitial(() -> new ElementTimestampStruct("yyyy-MM-dd")); @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { ElementTimestampStruct eds = currentDate.get(); long millis = eds.currentTimestamp.getTime(); - if (date.getTime() > (millis + INTERVAL - 1) || date.getTime() < millis) { - eds.currentTimestamp.setTime(date.getTime() - (date.getTime() % INTERVAL)); + long epochMilli = request.getCoyoteRequest().getStartInstant().toEpochMilli(); + if (epochMilli > (millis + INTERVAL - 1) || epochMilli < millis) { + eds.currentTimestamp.setTime(epochMilli - (epochMilli % INTERVAL)); eds.currentTimestampString = eds.currentTimestampFormat.format(eds.currentTimestamp); } buf.append(eds.currentTimestampString); @@ -163,11 +164,12 @@ protected static class TimeElement implements AccessLogElement { ThreadLocal.withInitial(() -> new ElementTimestampStruct("HH:mm:ss")); @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { ElementTimestampStruct eds = currentTime.get(); long millis = eds.currentTimestamp.getTime(); - if (date.getTime() > (millis + INTERVAL - 1) || date.getTime() < millis) { - eds.currentTimestamp.setTime(date.getTime() - (date.getTime() % INTERVAL)); + long epochMilli = request.getCoyoteRequest().getStartInstant().toEpochMilli(); + if (epochMilli > (millis + INTERVAL - 1) || epochMilli < millis) { + eds.currentTimestamp.setTime(epochMilli - (epochMilli % INTERVAL)); eds.currentTimestampString = eds.currentTimestampFormat.format(eds.currentTimestamp); } buf.append(eds.currentTimestampString); @@ -182,7 +184,7 @@ public RequestHeaderElement(String header) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getHeader(header), buf); } } @@ -195,7 +197,7 @@ public ResponseHeaderElement(String header) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(response.getHeader(header), buf); } } @@ -208,7 +210,7 @@ public ServletContextElement(String attribute) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getContext().getServletContext().getAttribute(attribute), buf); } } @@ -221,7 +223,7 @@ public CookieElement(String name) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { StringBuilder value = new StringBuilder(); boolean first = true; Cookie[] c = request.getCookies(); @@ -254,7 +256,7 @@ public ResponseAllHeaderElement(String header) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { if (null != response) { Iterator iter = response.getHeaders(header).iterator(); if (iter.hasNext()) { @@ -286,7 +288,7 @@ public RequestAttributeElement(String attribute) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getAttribute(attribute), buf); } } @@ -299,7 +301,7 @@ public SessionAttributeElement(String attribute) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { HttpSession session = null; if (request != null) { session = request.getSession(false); @@ -328,7 +330,7 @@ private String urlEncode(String value) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String parameterValue; try { parameterValue = request.getParameter(parameter); @@ -509,7 +511,7 @@ protected AccessLogElement getLogElement(String token, PatternTokenizer tokenize if (tokenizer.hasSubToken()) { String nextToken = tokenizer.getToken(); if ("taken".equals(nextToken)) { - return new ElapsedTimeElement(false); + return new ElapsedTimeElement(false, false); } } else { return new TimeElement(); @@ -533,7 +535,7 @@ protected AccessLogElement getLogElement(String token, PatternTokenizer tokenize } else if ("dns".equals(nextToken)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String value; try { @@ -572,7 +574,7 @@ protected AccessLogElement getClientToServerElement(PatternTokenizer tokenizer) } else if ("query".equals(token)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String query = request.getQueryString(); if (query != null) { @@ -586,7 +588,7 @@ public void addElement(CharArrayWriter buf, Date date, Request request, Response } else { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { String query = request.getQueryString(); buf.append(request.getRequestURI()); @@ -684,77 +686,77 @@ protected AccessLogElement getServletRequestElement(String parameter) { if ("authType".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getAuthType(), buf); } }; } else if ("remoteUser".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getRemoteUser(), buf); } }; } else if ("requestedSessionId".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getRequestedSessionId(), buf); } }; } else if ("requestedSessionIdFromCookie".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(String.valueOf(request.isRequestedSessionIdFromCookie()), buf); } }; } else if ("requestedSessionIdValid".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(String.valueOf(request.isRequestedSessionIdValid()), buf); } }; } else if ("contentLength".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(String.valueOf(request.getContentLengthLong()), buf); } }; } else if ("characterEncoding".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getCharacterEncoding(), buf); } }; } else if ("locale".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getLocale(), buf); } }; } else if ("protocol".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(request.getProtocol(), buf); } }; } else if ("scheme".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { buf.append(request.getScheme()); } }; } else if ("secure".equals(parameter)) { return new AccessLogElement() { @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { wrap(Boolean.valueOf(request.isSecure()), buf); } }; diff --git a/java/org/apache/catalina/valves/JDBCAccessLogValve.java b/java/org/apache/catalina/valves/JDBCAccessLogValve.java index ba1db102fd7e..5591d63f615c 100644 --- a/java/org/apache/catalina/valves/JDBCAccessLogValve.java +++ b/java/org/apache/catalina/valves/JDBCAccessLogValve.java @@ -24,6 +24,7 @@ import java.sql.SQLException; import java.sql.Timestamp; import java.util.Properties; +import java.util.concurrent.TimeUnit; import javax.servlet.ServletException; @@ -435,6 +436,12 @@ public void invoke(Request request, Response response) throws IOException, Servl @Override public void log(Request request, Response response, long time) { + logNanos(request, response, TimeUnit.MILLISECONDS.toNanos(time)); + } + + @Override + public void logNanos(Request request, Response response, long time) { + if (!getState().isAvailable()) { return; } diff --git a/java/org/apache/catalina/valves/JsonAccessLogValve.java b/java/org/apache/catalina/valves/JsonAccessLogValve.java index d680ccf7f78a..e535ec233af5 100644 --- a/java/org/apache/catalina/valves/JsonAccessLogValve.java +++ b/java/org/apache/catalina/valves/JsonAccessLogValve.java @@ -20,7 +20,6 @@ import java.util.ArrayList; import java.util.Arrays; import java.util.Collections; -import java.util.Date; import java.util.HashMap; import java.util.List; import java.util.ListIterator; @@ -123,7 +122,7 @@ public CharElement(char ch) { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { buf.write(ch); } } @@ -252,12 +251,12 @@ public AccessLogElement getDelegate() { } @Override - public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) { + public void addElement(CharArrayWriter buf, Request request, Response response, long time) { buf.append('"').append(attributeName).append('"').append(':'); if (quoteValue) { buf.append('"'); } - delegate.addElement(buf, date, request, response, time); + delegate.addElement(buf, request, response, time); if (quoteValue) { buf.append('"'); } diff --git a/java/org/apache/coyote/AbstractProcessor.java b/java/org/apache/coyote/AbstractProcessor.java index 6cfb24ec831c..d79dede93217 100644 --- a/java/org/apache/coyote/AbstractProcessor.java +++ b/java/org/apache/coyote/AbstractProcessor.java @@ -1088,6 +1088,6 @@ protected final void logAccess(SocketWrapperBase socketWrapper) throws IOExce // Set up the minimal response information response.setStatus(400); response.setError(); - getAdapter().log(request, response, 0); + getAdapter().logNanos(request, response, 0); } } diff --git a/java/org/apache/coyote/Adapter.java b/java/org/apache/coyote/Adapter.java index c390e91622cf..576e0be4298a 100644 --- a/java/org/apache/coyote/Adapter.java +++ b/java/org/apache/coyote/Adapter.java @@ -16,6 +16,8 @@ */ package org.apache.coyote; +import java.util.concurrent.TimeUnit; + import org.apache.tomcat.util.net.SocketEvent; /** @@ -74,6 +76,8 @@ public interface Adapter { /** * Callback to allow logging access outside of the execution of the regular service. + *

    + * Note: As of Tomcat 10.1.x, this method will expect nanoseconds rather than milliseconds. * * @param req the request object * @param res the response object @@ -81,6 +85,21 @@ public interface Adapter { */ void log(Request req, Response res, long time); + /** + * Callback to allow logging access outside of the execution of the regular service. + * + * @param req the request object + * @param res the response object + * @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 req, Response res, long time) { + log(req, res, TimeUnit.NANOSECONDS.toMillis(time)); + } + /** * Assert that request and response have been recycled. If they have not then log a warning and force a recycle. * This method is called as a safety check when a processor is being recycled and may be returned to a pool for diff --git a/java/org/apache/coyote/ajp/AjpProcessor.java b/java/org/apache/coyote/ajp/AjpProcessor.java index 7f5070f4c525..5970613276ed 100644 --- a/java/org/apache/coyote/ajp/AjpProcessor.java +++ b/java/org/apache/coyote/ajp/AjpProcessor.java @@ -329,6 +329,7 @@ protected SocketState dispatchEndRequest() { } + @SuppressWarnings("deprecation") @Override public SocketState service(SocketWrapperBase socket) throws IOException { @@ -435,7 +436,7 @@ public SocketState service(SocketWrapperBase socket) throws IOException { // 500 - Internal Server Error response.setStatus(500); setErrorState(ErrorState.CLOSE_CLEAN, t); - getAdapter().log(request, response, 0); + getAdapter().logNanos(request, response, 0); } } @@ -641,6 +642,7 @@ protected boolean refillReadBuffer(boolean block) throws IOException { /** * After reading the request headers, we have to setup the request filters. */ + @SuppressWarnings("deprecation") private void prepareRequest() { // Translate the HTTP method code to a String. @@ -888,7 +890,7 @@ private void prepareRequest() { parseHost(valueMB); if (!getErrorState().isIoAllowed()) { - getAdapter().log(request, response, 0); + getAdapter().logNanos(request, response, 0); } } diff --git a/java/org/apache/coyote/http11/Http11Processor.java b/java/org/apache/coyote/http11/Http11Processor.java index 9baecfec8f17..871c6659601c 100644 --- a/java/org/apache/coyote/http11/Http11Processor.java +++ b/java/org/apache/coyote/http11/Http11Processor.java @@ -248,6 +248,7 @@ private void addInputFilter(InputFilter[] inputFilters, String encodingName) { } + @SuppressWarnings("deprecation") @Override public SocketState service(SocketWrapperBase socketWrapper) throws IOException { RequestInfo rp = request.getRequestProcessor(); @@ -355,7 +356,7 @@ public SocketState service(SocketWrapperBase socketWrapper) throws IOExceptio response.setHeader("Connection", "Upgrade"); response.setHeader("Upgrade", requestedProtocol); action(ActionCode.CLOSE, null); - getAdapter().log(request, response, 0); + getAdapter().logNanos(request, response, 0); // Continue processing using new protocol InternalHttpUpgradeHandler upgradeHandler = upgradeProtocol @@ -425,7 +426,7 @@ public SocketState service(SocketWrapperBase socketWrapper) throws IOExceptio // 500 - Internal Server Error response.setStatus(500); setErrorState(ErrorState.CLOSE_CLEAN, t); - getAdapter().log(request, response, 0); + getAdapter().logNanos(request, response, 0); } } @@ -787,7 +788,7 @@ private void prepareRequest() throws IOException { parseHost(hostValueMB); if (!getErrorState().isIoAllowed()) { - getAdapter().log(request, response, 0); + getAdapter().logNanos(request, response, 0); } } diff --git a/java/org/apache/coyote/http2/StreamProcessor.java b/java/org/apache/coyote/http2/StreamProcessor.java index 624746903a55..975b1be70c9f 100644 --- a/java/org/apache/coyote/http2/StreamProcessor.java +++ b/java/org/apache/coyote/http2/StreamProcessor.java @@ -469,6 +469,7 @@ public final void pause() { } + @SuppressWarnings("deprecation") @Override public final SocketState service(SocketWrapperBase socket) throws IOException { try { @@ -476,7 +477,7 @@ public final SocketState service(SocketWrapperBase socket) throws IOException adapter.service(request, response); } else { response.setStatus(HttpServletResponse.SC_BAD_REQUEST); - adapter.log(request, response, 0); + adapter.logNanos(request, response, 0); setErrorState(ErrorState.CLOSE_CLEAN, null); } } catch (Exception e) { diff --git a/webapps/docs/changelog.xml b/webapps/docs/changelog.xml index 10b35085292a..e9c720d38af9 100644 --- a/webapps/docs/changelog.xml +++ b/webapps/docs/changelog.xml @@ -128,6 +128,10 @@ Further performance improvements for ParameterMap. (jengebr/markt) + + Refactor access log time stamps to be based on the Instant + request processing starts. (markt) +