diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index d8f8697d735..5556a7575c3 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -1162,8 +1162,13 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog private static void logLatencyMicroseconds(StringBuilder b, Request request, Response response) { - long latency = System.currentTimeMillis() - request.getTimeStamp(); - b.append(TimeUnit.MILLISECONDS.toMicros(latency)); + long currentTime = System.currentTimeMillis(); + long requestTime = request.getTimeStamp(); + + long latency_ms = currentTime - requestTime; + long latency_us = TimeUnit.MILLISECONDS.toMicros(latency_ms); + + b.append(latency_us); } private static void logLatencyMilliseconds(StringBuilder b, Request request, Response response) diff --git a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java index 247fa7795ce..af1175c3cb1 100644 --- a/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java +++ b/jetty-server/src/test/java/org/eclipse/jetty/server/handler/CustomRequestLogTest.java @@ -53,7 +53,7 @@ import org.junit.jupiter.api.Test; import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.containsString; -import static org.hamcrest.Matchers.greaterThan; +import static org.hamcrest.Matchers.greaterThanOrEqualTo; import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.lessThanOrEqualTo; import static org.hamcrest.Matchers.not; @@ -69,6 +69,7 @@ public class CustomRequestLogTest ServerConnector _serverConnector; URI _serverURI; + private final static long DELAY = 2000; @BeforeEach public void before() throws Exception @@ -394,13 +395,16 @@ public class CustomRequestLogTest testHandlerServerStart("%{us}T"); long lowerBound = System.currentTimeMillis(); - _connector.getResponse("GET / HTTP/1.0\n\n"); + _connector.getResponse("GET /delay HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); - long duration = upperBound-lowerBound; - assertThat(Long.parseLong(log), greaterThan((long)0)); - assertThat(Long.parseLong(log), lessThanOrEqualTo(TimeUnit.MILLISECONDS.toMicros(duration))); + long measuredDuration = Long.parseLong(log); + long durationLowerBound = TimeUnit.MILLISECONDS.toMicros(DELAY); + long durationUpperBound = TimeUnit.MILLISECONDS.toMicros(upperBound-lowerBound + DELAY); + + assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); + assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); } @Test @@ -409,13 +413,16 @@ public class CustomRequestLogTest testHandlerServerStart("%{ms}T"); long lowerBound = System.currentTimeMillis(); - _connector.getResponse("GET / HTTP/1.0\n\n"); + _connector.getResponse("GET /delay HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); - long duration = upperBound-lowerBound; - assertThat(Long.parseLong(log), greaterThan((long)0)); - assertThat(Long.parseLong(log), lessThanOrEqualTo(duration)); + long measuredDuration = Long.parseLong(log); + long durationLowerBound = DELAY; + long durationUpperBound = upperBound-lowerBound + DELAY; + + assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); + assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); } @Test @@ -428,10 +435,12 @@ public class CustomRequestLogTest String log = _entries.poll(5,TimeUnit.SECONDS); long upperBound = requestTimes.poll(5 ,TimeUnit.SECONDS); + long measuredDuration = Long.parseLong(log); + long durationLowerBound = TimeUnit.MILLISECONDS.toSeconds(DELAY); + long durationUpperBound = TimeUnit.MILLISECONDS.toSeconds(upperBound-lowerBound + DELAY); - long duration = upperBound-lowerBound; - assertThat(Long.parseLong(log), greaterThan((long)0)); - assertThat(Long.parseLong(log), lessThanOrEqualTo(TimeUnit.MILLISECONDS.toMicros(duration))); + assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); + assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); } @Test @@ -563,7 +572,7 @@ public class CustomRequestLogTest { try { - Thread.sleep(2000); + Thread.sleep(DELAY); } catch (InterruptedException e) { diff --git a/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java b/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java index 72374e44e17..bab1eb21ef2 100644 --- a/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java +++ b/jetty-servlet/src/test/java/org/eclipse/jetty/servlet/CustomRequestLogTest.java @@ -21,6 +21,7 @@ package org.eclipse.jetty.servlet; import java.io.IOException; import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; + import javax.servlet.ServletException; import javax.servlet.ServletOutputStream; import javax.servlet.http.HttpServlet; @@ -92,7 +93,7 @@ public class CustomRequestLogTest { testHandlerServerStart("RequestHandler: %R"); - _connector.getResponse("GET / HTTP/1.0\n\n"); + _connector.getResponse("GET /context/servlet/ HTTP/1.0\n\n"); String log = _entries.poll(5,TimeUnit.SECONDS); assertThat(log, Matchers.containsString("TestServlet")); }