From 8e3dbf7792fc54f581fe1da4e172347f88f83e66 Mon Sep 17 00:00:00 2001 From: Mark Thomas Date: Wed, 24 Sep 2025 08:16:11 +0100 Subject: [PATCH 1/2] Make nanosecond resolution available to access log for request start --- java/org/apache/catalina/Container.java | 2 +- .../catalina/connector/CoyoteAdapter.java | 6 +- .../valves/AbstractAccessLogValve.java | 232 ++++++++++++------ .../valves/ExtendedAccessLogValve.java | 60 ++--- .../catalina/valves/JsonAccessLogValve.java | 7 +- .../catalina/valves/TesterAccessLogValve.java | 3 +- webapps/docs/changelog.xml | 4 + 7 files changed, 206 insertions(+), 108 deletions(-) diff --git a/java/org/apache/catalina/Container.java b/java/org/apache/catalina/Container.java index 4c2ed166c0b6..ee211d04d9e3 100644 --- a/java/org/apache/catalina/Container.java +++ b/java/org/apache/catalina/Container.java @@ -430,7 +430,7 @@ static Service getService(Container container) { * * @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) + * @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 */ diff --git a/java/org/apache/catalina/connector/CoyoteAdapter.java b/java/org/apache/catalina/connector/CoyoteAdapter.java index 6eccbdbc0f95..712834d0670e 100644 --- a/java/org/apache/catalina/connector/CoyoteAdapter.java +++ b/java/org/apache/catalina/connector/CoyoteAdapter.java @@ -278,8 +278,8 @@ 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) { @@ -404,7 +404,7 @@ 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); } else if (response.isError()) { diff --git a/java/org/apache/catalina/valves/AbstractAccessLogValve.java b/java/org/apache/catalina/valves/AbstractAccessLogValve.java index 32aa5df0eeaa..812bc292ad3c 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 @@ -665,21 +669,13 @@ public void log(Request request, Response response, long time) { 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 +738,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 +793,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 +827,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 +864,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 +904,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 +938,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 +948,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 +967,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 +1110,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 +1124,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 +1142,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 +1171,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 +1199,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 +1248,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 +1287,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 +1315,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 +1326,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 +1405,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 +1421,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 +1438,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 +1457,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 +1471,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 +1504,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 +1520,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 +1545,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 +1583,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 +1610,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 +1640,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 +1667,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 +1776,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 +1795,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 +1831,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 +1855,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/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/test/org/apache/catalina/valves/TesterAccessLogValve.java b/test/org/apache/catalina/valves/TesterAccessLogValve.java index 3d5511800241..5405b9e4c748 100644 --- a/test/org/apache/catalina/valves/TesterAccessLogValve.java +++ b/test/org/apache/catalina/valves/TesterAccessLogValve.java @@ -19,6 +19,7 @@ import java.io.IOException; import java.util.Queue; import java.util.concurrent.ConcurrentLinkedQueue; +import java.util.concurrent.TimeUnit; import javax.servlet.ServletException; @@ -44,7 +45,7 @@ public TesterAccessLogValve() { @Override public void log(Request request, Response response, long time) { - entries.add(new Entry(request.getRequestURI(), response.getStatus(), time)); + entries.add(new Entry(request.getRequestURI(), response.getStatus(), TimeUnit.NANOSECONDS.toMillis(time))); } @Override 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) + From 579df837eae54c094b2fc3c95a3ab00009036050 Mon Sep 17 00:00:00 2001 From: Mark Thomas Date: Wed, 24 Sep 2025 10:19:00 +0100 Subject: [PATCH 2/2] Avoid changing method parameter from millis to nanos This introduces separate methods for nanoseconds. These are marked as deprecated and the other log methods are marked as the time parameter changing from millis to nanos in 10.1.x --- java/org/apache/catalina/AccessLog.java | 19 +++++++++++ java/org/apache/catalina/Container.java | 24 +++++++++++++- .../catalina/connector/CoyoteAdapter.java | 32 ++++++++++++------- .../catalina/core/AccessLogAdapter.java | 9 +++++- .../apache/catalina/core/ContainerBase.java | 11 +++++-- .../apache/catalina/core/StandardEngine.java | 7 ++-- .../valves/AbstractAccessLogValve.java | 6 ++++ .../catalina/valves/JDBCAccessLogValve.java | 7 ++++ java/org/apache/coyote/AbstractProcessor.java | 2 +- java/org/apache/coyote/Adapter.java | 19 +++++++++++ java/org/apache/coyote/ajp/AjpProcessor.java | 6 ++-- .../apache/coyote/http11/Http11Processor.java | 7 ++-- .../apache/coyote/http2/StreamProcessor.java | 3 +- .../catalina/valves/TesterAccessLogValve.java | 3 +- 14 files changed, 128 insertions(+), 27 deletions(-) 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 ee211d04d9e3..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,16 +428,37 @@ 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 - * @param time Time taken to process the request/response in nanoseconds (use 0 if not known) + * @param time Time taken to process the request/response in milliseconds (use 0 if not known) * @param useDefault Flag that indicates that the request/response should be logged in the engine's default access * log */ 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 712834d0670e..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 { @@ -283,9 +285,9 @@ public boolean asyncDispatch(org.apache.coyote.Request req, org.apache.coyote.Re } 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 { @@ -406,12 +409,12 @@ public void service(org.apache.coyote.Request req, org.apache.coyote.Response re // Log via the host or engine in that case. 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 812bc292ad3c..d323477bc9c6 100644 --- a/java/org/apache/catalina/valves/AbstractAccessLogValve.java +++ b/java/org/apache/catalina/valves/AbstractAccessLogValve.java @@ -663,6 +663,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() || !getEnabled() || logElements == null || condition != null && null != request.getRequest().getAttribute(condition) || conditionIf != null && null == request.getRequest().getAttribute(conditionIf)) { 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/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/test/org/apache/catalina/valves/TesterAccessLogValve.java b/test/org/apache/catalina/valves/TesterAccessLogValve.java index 5405b9e4c748..3d5511800241 100644 --- a/test/org/apache/catalina/valves/TesterAccessLogValve.java +++ b/test/org/apache/catalina/valves/TesterAccessLogValve.java @@ -19,7 +19,6 @@ import java.io.IOException; import java.util.Queue; import java.util.concurrent.ConcurrentLinkedQueue; -import java.util.concurrent.TimeUnit; import javax.servlet.ServletException; @@ -45,7 +44,7 @@ public TesterAccessLogValve() { @Override public void log(Request request, Response response, long time) { - entries.add(new Entry(request.getRequestURI(), response.getStatus(), TimeUnit.NANOSECONDS.toMillis(time))); + entries.add(new Entry(request.getRequestURI(), response.getStatus(), time)); } @Override