From 557696653ddb57b83b44571066a1ab9150b60e17 Mon Sep 17 00:00:00 2001 From: Simone Bordet Date: Wed, 12 Oct 2022 17:46:49 +0200 Subject: [PATCH] Re-enable RequestLog tests. Re-implemented features that were commented out. Signed-off-by: Simone Bordet --- .../jetty/server/CustomRequestLog.java | 95 +-- .../jetty/server/CustomRequestLogTest.java | 744 ++++++++++-------- .../jetty/ee10/servlet/ServletChannel.java | 20 +- .../servlet/CustomRequestLogServletTest.java | 141 ---- .../ee10/servlet/CustomRequestLogTest.java | 158 ++++ .../eclipse/jetty/ee9/nested/HttpChannel.java | 16 +- .../ee9/servlet/CustomRequestLogTest.java | 134 ++-- 7 files changed, 714 insertions(+), 594 deletions(-) delete mode 100644 jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogServletTest.java create mode 100644 jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogTest.java diff --git a/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java b/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java index 37ffbdd14e4..3f8fd2da1d3 100644 --- a/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java +++ b/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java @@ -37,6 +37,7 @@ import org.eclipse.jetty.util.StringUtil; import org.eclipse.jetty.util.annotation.ManagedAttribute; import org.eclipse.jetty.util.annotation.ManagedObject; import org.eclipse.jetty.util.component.ContainerLifeCycle; +import org.eclipse.jetty.util.resource.Resource; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -318,11 +319,13 @@ import static java.lang.invoke.MethodType.methodType; @ManagedObject("Custom format request log") public class CustomRequestLog extends ContainerLifeCycle implements RequestLog { - protected static final Logger LOG = LoggerFactory.getLogger(CustomRequestLog.class); - public static final String DEFAULT_DATE_FORMAT = "dd/MMM/yyyy:HH:mm:ss ZZZ"; public static final String NCSA_FORMAT = "%{client}a - %u %t \"%r\" %s %O"; public static final String EXTENDED_NCSA_FORMAT = NCSA_FORMAT + " \"%{Referer}i\" \"%{User-Agent}i\""; + public static final String HANDLER_NAME = CustomRequestLog.class.getName() + ".handlerName"; + public static final String REAL_PATH = CustomRequestLog.class.getName() + ".realPath"; + public static final String USER_NAME = CustomRequestLog.class.getName() + ".userPrincipal"; + private static final Logger LOG = LoggerFactory.getLogger(CustomRequestLog.class); private static final ThreadLocal _buffers = ThreadLocal.withInitial(() -> new StringBuilder(256)); private final RequestLog.Writer _requestLogWriter; @@ -379,11 +382,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog return _requestLogWriter; } - /** - * Writes the request and response information to the output stream. - * - * @see org.eclipse.jetty.server.RequestLog#log(Request, Response) - */ @Override public void log(Request request, Response response) { @@ -409,27 +407,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog } } - /** - * Extract the user authentication - * - * @param request The request to extract from - * @param checkDeferred Whether to check for deferred authentication - * @return The string to log for authenticated user. - */ - protected static String getAuthentication(Request request, boolean checkDeferred) - { - // TODO -// Authentication authentication = request.getAuthentication(); -// if (checkDeferred && authentication instanceof Authentication.Deferred) -// authentication = ((Authentication.Deferred)authentication).authenticate(request); - - String name = null; -// if (authentication instanceof Authentication.User) -// name = ((Authentication.User)authentication).getUserIdentity().getUserPrincipal().getName(); -// - return name; - } - /** * Set request paths that will not be logged. * @@ -1046,8 +1023,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog @SuppressWarnings("unused") private static void logResponseSize(StringBuilder b, Request request, Response response) { - long written = Response.getContentBytesWritten(response); - b.append(written); + b.append(Response.getContentBytesWritten(response)); } @SuppressWarnings("unused") @@ -1123,7 +1099,6 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog } } } - b.append('-'); } @@ -1132,7 +1107,9 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog { List cookies = Request.getCookies(request); if (cookies == null || cookies.size() == 0) + { b.append('-'); + } else { for (int i = 0; i < cookies.size(); i++) @@ -1155,17 +1132,25 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog @SuppressWarnings("unused") private static void logFilename(StringBuilder b, Request request, Response response) { - b.append('-'); -// TODO UserIdentity.Scope scope = request.getUserIdentityScope(); -// if (scope == null || scope.getContextHandler() == null) -// b.append('-'); -// else -// { -// ContextHandler context = scope.getContextHandler(); -// int lengthToStrip = scope.getContextPath().length() > 1 ? scope.getContextPath().length() : 0; -// String filename = context.getServletContext().getRealPath(request.getPathInfo().substring(lengthToStrip)); -// append(b, filename); -// } + String realPath = (String)request.getAttribute(REAL_PATH); + if (realPath == null) + { + Context context = request.getContext(); + Resource baseResource = context.getBaseResource(); + if (baseResource != null) + { + String fileName = baseResource.resolve(request.getPathInContext()).getName(); + append(b, fileName); + } + else + { + b.append("-"); + } + } + else + { + b.append(realPath); + } } @SuppressWarnings("unused") @@ -1221,8 +1206,7 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog @SuppressWarnings("unused") private static void logRequestHandler(StringBuilder b, Request request, Response response) { - b.append('-'); -// TODO append(b, request.getServletName()); + append(b, (String)request.getAttribute(HANDLER_NAME)); } @SuppressWarnings("unused") @@ -1242,39 +1226,38 @@ public class CustomRequestLog extends ContainerLifeCycle implements RequestLog @SuppressWarnings("unused") private static void logLatencyMicroseconds(StringBuilder b, Request request, Response response) { - long currentTime = System.currentTimeMillis(); - long requestTime = request.getTimeStamp(); - - long latencyMs = currentTime - requestTime; - long latencyUs = TimeUnit.MILLISECONDS.toMicros(latencyMs); - - b.append(latencyUs); + logLatency(b, request, TimeUnit.MICROSECONDS); } @SuppressWarnings("unused") private static void logLatencyMilliseconds(StringBuilder b, Request request, Response response) { - long latency = System.currentTimeMillis() - request.getTimeStamp(); - b.append(latency); + logLatency(b, request, TimeUnit.MILLISECONDS); } @SuppressWarnings("unused") private static void logLatencySeconds(StringBuilder b, Request request, Response response) + { + logLatency(b, request, TimeUnit.SECONDS); + } + + private static void logLatency(StringBuilder b, Request request, TimeUnit unit) { long latency = System.currentTimeMillis() - request.getTimeStamp(); - b.append(TimeUnit.MILLISECONDS.toSeconds(latency)); + b.append(unit.convert(latency, TimeUnit.MILLISECONDS)); } @SuppressWarnings("unused") private static void logRequestAuthentication(StringBuilder b, Request request, Response response) { - append(b, getAuthentication(request, false)); + append(b, (String)request.getAttribute(USER_NAME)); } @SuppressWarnings("unused") private static void logRequestAuthenticationWithDeferred(StringBuilder b, Request request, Response response) { - append(b, getAuthentication(request, true)); + // TODO: deferred to be implemented. + logRequestAuthentication(b, request, response); } @SuppressWarnings("unused") diff --git a/jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/CustomRequestLogTest.java b/jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/CustomRequestLogTest.java index 69d4326c2eb..22b2948a863 100644 --- a/jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/CustomRequestLogTest.java +++ b/jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/CustomRequestLogTest.java @@ -13,162 +13,187 @@ package org.eclipse.jetty.server; +import java.io.IOException; import java.io.OutputStream; import java.net.InetAddress; import java.net.NetworkInterface; import java.net.Socket; -import java.net.URI; import java.nio.charset.StandardCharsets; -import java.util.Base64; +import java.util.ArrayList; import java.util.Enumeration; +import java.util.List; import java.util.Locale; import java.util.Objects; import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.atomic.AtomicReference; -import org.eclipse.jetty.http.HttpHeader; +import org.eclipse.jetty.http.HttpFields; +import org.eclipse.jetty.http.HttpStatus; +import org.eclipse.jetty.http.HttpTester; import org.eclipse.jetty.io.Content; import org.eclipse.jetty.io.QuietException; -import org.eclipse.jetty.server.handler.ContextHandler; -import org.eclipse.jetty.util.Blocker; import org.eclipse.jetty.util.BlockingArrayQueue; import org.eclipse.jetty.util.Callback; import org.eclipse.jetty.util.DateCache; +import org.eclipse.jetty.util.component.LifeCycle; import org.junit.jupiter.api.AfterEach; -import org.junit.jupiter.api.BeforeEach; -import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.ValueSource; import static org.hamcrest.MatcherAssert.assertThat; -import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.greaterThanOrEqualTo; import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.lessThanOrEqualTo; import static org.hamcrest.Matchers.not; +import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertNull; -import static org.junit.jupiter.api.Assertions.fail; public class CustomRequestLogTest { - private final BlockingQueue _entries = new BlockingArrayQueue<>(); - private final BlockingQueue requestTimes = new BlockingArrayQueue<>(); - private CustomRequestLog _log; + private final BlockingQueue _logs = new BlockingArrayQueue<>(); private Server _server; - private LocalConnector _connector; + private HttpConfiguration _httpConfig; private ServerConnector _serverConnector; - private URI _serverURI; + private CustomRequestLog _log; - private static final long DELAY = 2000; - - @BeforeEach - public void before() + private void start(String formatString) throws Exception { - _server = new Server(); - _connector = new LocalConnector(_server); - _serverConnector = new ServerConnector(_server); - _server.addConnector(_connector); - _server.addConnector(_serverConnector); + start(formatString, new SimpleHandler()); } - void testHandlerServerStart(String formatString) throws Exception + private void start(String formatString, Handler handler) throws Exception { - _serverConnector.setPort(0); - _serverConnector.getBean(HttpConnectionFactory.class).getHttpConfiguration().addCustomizer(new ForwardedRequestCustomizer()); + _server = new Server(); + _httpConfig = new HttpConfiguration(); + _serverConnector = new ServerConnector(_server, 1, 1, new HttpConnectionFactory(_httpConfig)); + _server.addConnector(_serverConnector); TestRequestLogWriter writer = new TestRequestLogWriter(); _log = new CustomRequestLog(writer, formatString); _server.setRequestLog(_log); - ContextHandler contextHandler = new ContextHandler(); - contextHandler.setHandler(new TestHandler()); - _server.setHandler(contextHandler); + _server.setHandler(handler); _server.start(); - - String host = _serverConnector.getHost(); - if (host == null) - host = "localhost"; - - int localPort = _serverConnector.getLocalPort(); - _serverURI = new URI(String.format("http://%s:%d/", host, localPort)); } @AfterEach public void after() throws Exception { - _server.stop(); + LifeCycle.stop(_server); + } + + private HttpTester.Response getResponse(String request) throws IOException + { + return getResponses(request, 1).get(0); + } + + private List getResponses(String request, int count) throws IOException + { + try (Socket socket = new Socket("localhost", _serverConnector.getLocalPort())) + { + OutputStream output = socket.getOutputStream(); + output.write(request.getBytes(StandardCharsets.UTF_8)); + output.flush(); + + List result = new ArrayList<>(); + HttpTester.Input input = HttpTester.from(socket.getInputStream()); + for (int i = 0; i < count; ++i) + { + HttpTester.Response response = HttpTester.parseResponse(input); + if (response != null) + result.add(response); + } + return result; + } } @Test public void testRequestFilter() throws Exception { + start("RequestPath: %U"); AtomicReference logRequest = new AtomicReference<>(); - testHandlerServerStart("RequestPath: %U"); _log.setFilter((request, response) -> logRequest.get()); logRequest.set(true); - _connector.getResponse("GET /path HTTP/1.0\n\n"); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("RequestPath: /path")); + HttpTester.Response response = getResponse("GET /path HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("RequestPath: /path")); logRequest.set(false); - _connector.getResponse("GET /path HTTP/1.0\n\n"); - assertNull(_entries.poll(1, TimeUnit.SECONDS)); - } - - @Test - @Disabled // TODO - public void testLogRemoteUser() throws Exception - { - String authHeader = HttpHeader.AUTHORIZATION + ": Basic " + Base64.getEncoder().encodeToString("username:password".getBytes()); - testHandlerServerStart("%u %{d}u"); - - _connector.getResponse("GET / HTTP/1.0\n\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, is("- -")); - - _connector.getResponse("GET / HTTP/1.0\n" + authHeader + "\n\n\n"); - log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, is("- username")); - - _connector.getResponse("GET /secure HTTP/1.0\n" + authHeader + "\n\n\n"); - log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, is("username username")); + response = getResponse("GET /path HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + log = _logs.poll(1, TimeUnit.SECONDS); + assertNull(log); } @Test public void testModifier() throws Exception { - testHandlerServerStart("%s: %!404,301{Referer}i"); + start("%s: %!404,301{Referer}i", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + String status = request.getHeaders().get("Status"); + response.setStatus(Integer.parseInt(status)); + callback.succeeded(); + } + }); - _connector.getResponse("GET /error404 HTTP/1.0\nReferer: testReferer\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse(""" + GET /path HTTP/1.0 + Status: 404 + Referer: testReferer + + """); + assertEquals(HttpStatus.NOT_FOUND_404, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("404: -")); - _connector.getResponse("GET /error301 HTTP/1.0\nReferer: testReferer\n\n"); - log = _entries.poll(5, TimeUnit.SECONDS); + response = getResponse(""" + GET /path HTTP/1.0 + Status: 301 + Referer: testReferer + + """); + assertEquals(HttpStatus.MOVED_PERMANENTLY_301, response.getStatus()); + log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("301: -")); - _connector.getResponse("GET /success HTTP/1.0\nReferer: testReferer\n\n"); - log = _entries.poll(5, TimeUnit.SECONDS); + response = getResponse(""" + GET /success HTTP/1.0 + Status: 200 + Referer: testReferer + + """); + assertEquals(HttpStatus.OK_200, response.getStatus()); + log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("200: testReferer")); } @Test public void testDoublePercent() throws Exception { - testHandlerServerStart("%%%%%%a"); + start("%%%%%%a"); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("%%%a")); } @Test public void testLogAddress() throws Exception { - testHandlerServerStart("%{local}a|%{local}p|" + - "%{remote}a|%{remote}p|" + - "%{server}a|%{server}p|" + - "%{client}a|%{client}p"); + start("" + + "%{local}a|%{local}p|" + + "%{remote}a|%{remote}p|" + + "%{server}a|%{server}p|" + + "%{client}a|%{client}p"); + _httpConfig.addCustomizer(new ForwardedRequestCustomizer()); Enumeration e = NetworkInterface.getNetworkInterfaces(); while (e.hasMoreElements()) @@ -180,17 +205,19 @@ public class CustomRequestLogTest while (ee.hasMoreElements()) { InetAddress i = ee.nextElement(); - try (Socket client = newSocket(i.getHostAddress(), _serverURI.getPort())) + try (Socket client = new Socket(i.getHostAddress(), _serverConnector.getLocalPort())) { - OutputStream os = client.getOutputStream(); - String request = "GET / HTTP/1.0\n" + - "Host: webtide.com:1234\n" + - "Forwarded: For=10.1.2.3:1337\n" + - "\n\n"; - os.write(request.getBytes(StandardCharsets.ISO_8859_1)); - os.flush(); + OutputStream output = client.getOutputStream(); + String request = """ + GET / HTTP/1.1 + Host: webtide.com:1234 + Forwarded: For=10.1.2.3:1337 - String[] log = Objects.requireNonNull(_entries.poll(5, TimeUnit.SECONDS)).split("\\|"); + """; + output.write(request.getBytes(StandardCharsets.UTF_8)); + output.flush(); + + String[] log = Objects.requireNonNull(_logs.poll(5, TimeUnit.SECONDS)).split("\\|"); assertThat(log.length, is(8)); String localAddr = log[0]; @@ -202,15 +229,14 @@ public class CustomRequestLogTest String clientAddr = log[6]; String clientPort = log[7]; - assertThat(serverPort, is("1234")); - assertThat(clientPort, is("1337")); - assertThat(remotePort, not(clientPort)); - assertThat(localPort, not(serverPort)); - - assertThat(serverAddr, is("webtide.com")); - assertThat(clientAddr, is("10.1.2.3")); - assertThat(InetAddress.getByName(remoteAddr), is(client.getInetAddress())); assertThat(InetAddress.getByName(localAddr), is(i)); + assertThat(localPort, not(serverPort)); + assertThat(InetAddress.getByName(remoteAddr), is(client.getInetAddress())); + assertThat(remotePort, not(clientPort)); + assertThat(serverAddr, is("webtide.com")); + assertThat(serverPort, is("1234")); + assertThat(clientAddr, is("10.1.2.3")); + assertThat(clientPort, is("1337")); } } } @@ -220,68 +246,107 @@ public class CustomRequestLogTest @Test public void testLogBytesSent() throws Exception { - testHandlerServerStart("BytesSent: %O"); + String content = "hello world"; + start("BytesSent: %O", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + Content.Sink.write(response, true, content, callback); + } + }); - _connector.getResponse("GET / HTTP/1.0\necho: hello world\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, is("BytesSent: 11")); + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("BytesSent: " + content.length())); } @Test public void testLogBytesReceived() throws Exception { - testHandlerServerStart("BytesReceived: %I"); + String content = "hello world"; + start("BytesReceived: %I", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + Content.Source.consumeAll(request, callback); + } + }); - _connector.getResponse("GET / HTTP/1.0\n" + - "Content-Length: 11\n\n" + - "hello world"); - - String log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, is("BytesReceived: 11")); + HttpTester.Response response = getResponse(""" + GET / HTTP/1.0 + Content-Length: %d + + %s""".formatted(content.length(), content)); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("BytesReceived: " + content.length())); } @Test public void testLogBytesTransferred() throws Exception { - testHandlerServerStart("BytesTransferred: %S"); + String content = "hello world"; + start("BytesTransferred: %S", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) throws Exception + { + String content = Content.Source.asString(request); + Content.Sink.write(response, true, content, callback); + } + }); - _connector.getResponse("GET / HTTP/1.0\n" + - "echo: hello world\n" + - "Content-Length: 11\n\n" + - "hello world"); + HttpTester.Response response = getResponse(""" + GET / HTTP/1.0 + Content-Length: %d - String log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, is("BytesTransferred: 22")); + %s""".formatted(content.length(), content)); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("BytesTransferred: " + (2 * content.length()))); } @Test public void testLogRequestCookie() throws Exception { - testHandlerServerStart("RequestCookies: %{cookieName}C, %{cookie2}C, %{cookie3}C"); + start("RequestCookies: %{cookieName}C, %{cookie2}C, %{cookie3}C"); - _connector.getResponse("GET / HTTP/1.0\nCookie: cookieName=cookieValue; cookie2=value2\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse(""" + GET / HTTP/1.0 + Cookie: cookieName=cookieValue; cookie2=value2 + + """); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("RequestCookies: cookieValue, value2, -")); } @Test public void testLogRequestCookies() throws Exception { - testHandlerServerStart("RequestCookies: %C"); + start("RequestCookies: %C"); - _connector.getResponse("GET / HTTP/1.0\nCookie: cookieName=cookieValue; cookie2=value2\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse(""" + GET / HTTP/1.0 + Cookie: cookieName=cookieValue; cookie2=value2 + + """); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("RequestCookies: cookieName=cookieValue;cookie2=value2")); } @Test public void testLogEnvironmentVar() throws Exception { - testHandlerServerStart("EnvironmentVar: %{JAVA_HOME}e"); - - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + start("EnvironmentVar: %{JAVA_HOME}e"); + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); String envVar = System.getenv("JAVA_HOME"); assertThat(log, is("EnvironmentVar: " + ((envVar == null) ? "-" : envVar))); } @@ -289,140 +354,193 @@ public class CustomRequestLogTest @Test public void testLogRequestProtocol() throws Exception { - testHandlerServerStart("%H"); + start("%H"); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("HTTP/1.0")); } @Test public void testLogRequestHeader() throws Exception { - testHandlerServerStart("RequestHeader: %{Header1}i, %{Header2}i, %{Header3}i"); + start("RequestHeader: %{Header1}i, %{Header2}i, %{Header3}i"); - _connector.getResponse("GET / HTTP/1.0\nHeader1: value1\nHeader2: value2\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse(""" + GET / HTTP/1.0 + Header1: value1 + Header2: value2 + + """); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("RequestHeader: value1, value2, -")); } @Test public void testLogKeepAliveRequests() throws Exception { - testHandlerServerStart("KeepAliveRequests: %k"); + start("KeepAliveRequests: %k"); - LocalConnector.LocalEndPoint connect = _connector.connect(); - connect.addInput(""" + getResponses(""" GET /a HTTP/1.0 Connection: keep-alive - """); - connect.addInput(""" GET /a HTTP/1.1 Host: localhost + + GET /a HTTP/1.0 + + """, 3); - """); - - assertThat(connect.getResponse(), containsString("200 OK")); - assertThat(connect.getResponse(), containsString("200 OK")); - - connect.addInput("GET /a HTTP/1.0\n\n"); - assertThat(connect.getResponse(), containsString("200 OK")); - - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("KeepAliveRequests: 1")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("KeepAliveRequests: 2")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("KeepAliveRequests: 3")); - } - - @Disabled - @Test - public void testLogKeepAliveRequestsHttp2() throws Exception - { - testHandlerServerStart("KeepAliveRequests: %k"); - fail(); + assertThat(_logs.poll(5, TimeUnit.SECONDS), is("KeepAliveRequests: 1")); + assertThat(_logs.poll(5, TimeUnit.SECONDS), is("KeepAliveRequests: 2")); + assertThat(_logs.poll(5, TimeUnit.SECONDS), is("KeepAliveRequests: 3")); } @Test public void testLogRequestMethod() throws Exception { - testHandlerServerStart("RequestMethod: %m"); + start("RequestMethod: %m"); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("RequestMethod: GET")); } @Test public void testLogResponseHeader() throws Exception { - testHandlerServerStart("ResponseHeader: %{Header1}o, %{Header2}o, %{Header3}o"); + start("ResponseHeader: %{Header1}o, %{Header2}o, %{Header3}o", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + response.getHeaders().add("Header1", "value1"); + response.getHeaders().add("Header2", "value2"); + callback.succeeded(); + } + }); - String response = _connector.getResponse("GET /responseHeaders HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse("GET /responseHeaders HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("ResponseHeader: value1, value2, -")); } @Test public void testLogQueryString() throws Exception { - testHandlerServerStart("QueryString: %q"); + start("QueryString: %q"); - _connector.getResponse("GET /path?queryString HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse("GET /path?queryString HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("QueryString: ?queryString")); } @Test public void testLogRequestFirstLine() throws Exception { - testHandlerServerStart("RequestFirstLin: %r"); + start("RequestFirstLine: %r"); - _connector.getResponse("GET /path?query HTTP/1.0\nHeader: null\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, is("RequestFirstLin: GET /path?query HTTP/1.0")); + HttpTester.Response response = getResponse(""" + GET /path?query HTTP/1.0 + Header: null + + """); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("RequestFirstLine: GET /path?query HTTP/1.0")); } @Test public void testLogResponseStatus() throws Exception { - testHandlerServerStart("LogResponseStatus: %s"); + start("LogResponseStatus: %s", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + String status = request.getHeaders().get("Status"); + response.setStatus(Integer.parseInt(status)); + callback.succeeded(); + } + }); - _connector.getResponse("GET /error404 HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse(""" + GET /path HTTP/1.0 + Status: 404 + + """); + assertEquals(HttpStatus.NOT_FOUND_404, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("LogResponseStatus: 404")); - _connector.getResponse("GET /error301 HTTP/1.0\n\n"); - log = _entries.poll(5, TimeUnit.SECONDS); + response = getResponse(""" + GET /path HTTP/1.0 + Status: 301 + + """); + assertEquals(HttpStatus.MOVED_PERMANENTLY_301, response.getStatus()); + log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("LogResponseStatus: 301")); - _connector.getResponse("GET / HTTP/1.0\n\n"); - log = _entries.poll(5, TimeUnit.SECONDS); + response = getResponse(""" + GET /path HTTP/1.0 + Status: 200 + + """); + assertEquals(HttpStatus.OK_200, response.getStatus()); + log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("LogResponseStatus: 200")); } @Test public void testLogRequestTime() throws Exception { - testHandlerServerStart("RequestTime: %t"); + AtomicLong requestTimeRef = new AtomicLong(); + start("RequestTime: %t", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + requestTimeRef.set(request.getTimeStamp()); + callback.succeeded(); + } + }); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - long requestTime = getTimeRequestReceived(); + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); DateCache dateCache = new DateCache(CustomRequestLog.DEFAULT_DATE_FORMAT, Locale.getDefault(), "GMT"); - assertThat(log, is("RequestTime: [" + dateCache.format(requestTime) + "]")); + assertThat(log, is("RequestTime: [" + dateCache.format(requestTimeRef.get()) + "]")); } @Test public void testLogRequestTimeCustomFormats() throws Exception { - testHandlerServerStart("%{EEE MMM dd HH:mm:ss zzz yyyy}t\n" + - "%{EEE MMM dd HH:mm:ss zzz yyyy|EST}t\n" + - "%{EEE MMM dd HH:mm:ss zzz yyyy|EST|ja}t"); + AtomicLong requestTimeRef = new AtomicLong(); + start(""" + %{EEE MMM dd HH:mm:ss zzz yyyy}t + %{EEE MMM dd HH:mm:ss zzz yyyy|EST}t + %{EEE MMM dd HH:mm:ss zzz yyyy|EST|ja}t""", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + requestTimeRef.set(request.getTimeStamp()); + callback.succeeded(); + } + }); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertNotNull(log); - long requestTime = getTimeRequestReceived(); + long requestTime = requestTimeRef.get(); DateCache dateCache1 = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", Locale.getDefault(), "GMT"); DateCache dateCache2 = new DateCache("EEE MMM dd HH:mm:ss zzz yyyy", Locale.getDefault(), "EST"); @@ -434,58 +552,41 @@ public class CustomRequestLogTest assertThat(logs[2], is("[" + dateCache3.format(requestTime) + "]")); } - @Test - public void testLogLatencyMicroseconds() throws Exception + @ParameterizedTest + @ValueSource(strings = {"us", "ms", "s"}) + public void testLogLatency(String unit) throws Exception { - testHandlerServerStart("%{us}T"); + long delay = 1000; + AtomicLong requestTimeRef = new AtomicLong(); + start("%{" + unit + "}T", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) throws Exception + { + requestTimeRef.set(request.getTimeStamp()); + Thread.sleep(delay); + callback.succeeded(); + } + }); - _connector.getResponse("GET /delay HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + TimeUnit timeUnit = switch (unit) + { + case "us" -> TimeUnit.MICROSECONDS; + case "ms" -> TimeUnit.MILLISECONDS; + case "s" -> TimeUnit.SECONDS; + default -> throw new IllegalArgumentException("invalid latency unit: " + unit); + }; + + HttpTester.Response response = getResponse("GET /delay HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertNotNull(log); - long lowerBound = getTimeRequestReceived(); + long lowerBound = requestTimeRef.get(); long upperBound = System.currentTimeMillis(); long measuredDuration = Long.parseLong(log); - long durationLowerBound = TimeUnit.MILLISECONDS.toMicros(DELAY); - long durationUpperBound = TimeUnit.MILLISECONDS.toMicros(upperBound - lowerBound); - - assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); - assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); - } - - @Test - public void testLogLatencyMilliseconds() throws Exception - { - testHandlerServerStart("%{ms}T"); - - _connector.getResponse("GET /delay HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - assertNotNull(log); - long lowerBound = getTimeRequestReceived(); - long upperBound = System.currentTimeMillis(); - - long measuredDuration = Long.parseLong(log); - long durationLowerBound = DELAY; - long durationUpperBound = upperBound - lowerBound; - - assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); - assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); - } - - @Test - public void testLogLatencySeconds() throws Exception - { - testHandlerServerStart("%{s}T"); - - _connector.getResponse("GET /delay HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - assertNotNull(log); - long lowerBound = getTimeRequestReceived(); - long upperBound = System.currentTimeMillis(); - - long measuredDuration = Long.parseLong(log); - long durationLowerBound = TimeUnit.MILLISECONDS.toSeconds(DELAY); - long durationUpperBound = TimeUnit.MILLISECONDS.toSeconds(upperBound - lowerBound); + long durationLowerBound = timeUnit.convert(delay, TimeUnit.MILLISECONDS); + long durationUpperBound = timeUnit.convert(upperBound - lowerBound, TimeUnit.MILLISECONDS); assertThat(measuredDuration, greaterThanOrEqualTo(durationLowerBound)); assertThat(measuredDuration, lessThanOrEqualTo(durationUpperBound)); @@ -494,99 +595,129 @@ public class CustomRequestLogTest @Test public void testLogUrlRequestPath() throws Exception { - testHandlerServerStart("UrlRequestPath: %U"); + start("UrlRequestPath: %U"); - _connector.getResponse("GET /path?query HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + HttpTester.Response response = getResponse("GET /path?query HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); assertThat(log, is("UrlRequestPath: /path")); } @Test public void testLogConnectionStatus() throws Exception { - testHandlerServerStart("%U ConnectionStatus: %s %X"); + start("%U ConnectionStatus: %s %X", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + if (request.getPathInContext().equals("/abort")) + { + Callback cbk = Callback.from(() -> callback.failed(new QuietException.Exception("test fail")), callback::failed); + Content.Sink.write(response, false, "data", cbk); + } + else + { + callback.succeeded(); + } + } + }); - String response = _connector.getResponse("GET /one HTTP/1.0\n\n"); - assertThat(response, containsString("200 OK")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("/one ConnectionStatus: 200 -")); + HttpTester.Response response = getResponse("GET /one HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("/one ConnectionStatus: 200 -")); - response = _connector.getResponse(""" + response = getResponse(""" GET /two HTTP/1.1 Host: localhost Connection: close """); - assertThat(response, containsString("200 OK")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("/two ConnectionStatus: 200 -")); + assertEquals(HttpStatus.OK_200, response.getStatus()); + log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("/two ConnectionStatus: 200 -")); - LocalConnector.LocalEndPoint connect = _connector.connect(); - connect.addInput(""" + getResponses(""" GET /three HTTP/1.0 Connection: keep-alive - """); - connect.addInput(""" GET /four HTTP/1.1 Host: localhost - """); - connect.addInput(""" GET /five HTTP/1.1 Host: localhost Connection: close - """); - assertThat(connect.getResponse(), containsString("200 OK")); - assertThat(connect.getResponse(), containsString("200 OK")); - assertThat(connect.getResponse(), containsString("200 OK")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("/three ConnectionStatus: 200 +")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("/four ConnectionStatus: 200 +")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("/five ConnectionStatus: 200 -")); + """, 3); - response = _connector.getResponse(""" + assertThat(_logs.poll(5, TimeUnit.SECONDS), is("/three ConnectionStatus: 200 +")); + assertThat(_logs.poll(5, TimeUnit.SECONDS), is("/four ConnectionStatus: 200 +")); + assertThat(_logs.poll(5, TimeUnit.SECONDS), is("/five ConnectionStatus: 200 -")); + + response = getResponse(""" GET /no/host HTTP/1.1 """); - assertThat(response, containsString(" 400 ")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("/no/host ConnectionStatus: 400 X")); + assertEquals(HttpStatus.BAD_REQUEST_400, response.getStatus()); + log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("/no/host ConnectionStatus: 400 X")); - response = _connector.getResponse(""" + getResponses(""" GET /abort HTTP/1.1 Host: localhost - """); - assertThat(response, containsString("200 OK")); - assertThat(_entries.poll(5, TimeUnit.SECONDS), is("/abort ConnectionStatus: 200 X")); + """, 1); + log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("/abort ConnectionStatus: 200 X")); } - @Disabled // TODO @Test public void testLogRequestTrailer() throws Exception { - testHandlerServerStart("%{trailerName}ti"); + start("%{trailerName}ti", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + Content.Source.consumeAll(request, callback); + } + }); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - fail(log); + HttpTester.Response response = getResponse(""" + GET / HTTP/1.1 + Host: localhost + Transfer-Encoding: chunked + + 0 + trailerName: 42 + + """); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("42")); } - @Disabled // TODO @Test public void testLogResponseTrailer() throws Exception { - testHandlerServerStart("%{trailerName}to"); + start("%{trailerName}to", new SimpleHandler() + { + @Override + public void process(Request request, Response response, Callback callback) + { + HttpFields.Mutable trailers = HttpFields.build(); + response.setTrailersSupplier(() -> trailers); + Content.Sink.write(response, false, "hello", Callback.NOOP); + trailers.put("trailerName", "42"); + callback.succeeded(); + } + }); - _connector.getResponse("GET / HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - fail(log); - } - - protected Socket newSocket(String host, int port) throws Exception - { - Socket socket = new Socket(host, port); - socket.setSoTimeout(10000); - socket.setTcpNoDelay(true); - return socket; + HttpTester.Response response = getResponse("GET / HTTP/1.0\n\n"); + assertEquals(HttpStatus.OK_200, response.getStatus()); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("42")); } class TestRequestLogWriter implements RequestLog.Writer @@ -594,72 +725,15 @@ public class CustomRequestLogTest @Override public void write(String requestEntry) { - try - { - _entries.add(requestEntry); - } - catch (Exception e) - { - e.printStackTrace(); - } + _logs.add(requestEntry); } } - private long getTimeRequestReceived() throws InterruptedException - { - Long requestTime = requestTimes.poll(5, TimeUnit.SECONDS); - assertNotNull(requestTime); - return requestTime; - } - - private class TestHandler extends Handler.Processor + private static class SimpleHandler extends Handler.Processor { @Override public void process(Request request, Response response, Callback callback) throws Exception { - requestTimes.offer(request.getTimeStamp()); - - if (request.getPathInContext().contains("error404")) - { - response.setStatus(404); - } - else if (request.getPathInContext().contains("error301")) - { - response.setStatus(301); - } - else if (request.getHeaders().get("echo") != null) - { - try (Blocker.Callback blocker = Blocker.callback()) - { - Content.Sink.write(response, false, String.valueOf(request.getHeaders().get("echo")), blocker); - blocker.block(); - } - } - else if (request.getPathInContext().contains("responseHeaders")) - { - response.getHeaders().add("Header1", "value1"); - response.getHeaders().add("Header2", "value2"); - } - else if (request.getPathInContext().contains("/abort")) - { - Content.Sink.write(response, false, "data", Callback.from(() -> callback.failed(new QuietException.Exception("test fail")), callback::failed)); - return; - } - else if (request.getPathInContext().contains("delay")) - { - try - { - Thread.sleep(DELAY); - } - catch (InterruptedException e) - { - e.printStackTrace(); - } - } - - if (request.getLength() > 0) - Content.Source.consumeAll(request); - callback.succeeded(); } } diff --git a/jetty-ee10/jetty-ee10-servlet/src/main/java/org/eclipse/jetty/ee10/servlet/ServletChannel.java b/jetty-ee10/jetty-ee10-servlet/src/main/java/org/eclipse/jetty/ee10/servlet/ServletChannel.java index 85bffa73f02..c34fed3b173 100644 --- a/jetty-ee10/jetty-ee10-servlet/src/main/java/org/eclipse/jetty/ee10/servlet/ServletChannel.java +++ b/jetty-ee10/jetty-ee10-servlet/src/main/java/org/eclipse/jetty/ee10/servlet/ServletChannel.java @@ -29,8 +29,8 @@ import java.util.function.Consumer; import jakarta.servlet.DispatcherType; import jakarta.servlet.RequestDispatcher; -import jakarta.servlet.http.HttpServletRequest; import org.eclipse.jetty.ee10.servlet.ServletRequestState.Action; +import org.eclipse.jetty.ee10.servlet.security.Authentication; import org.eclipse.jetty.http.BadMessageException; import org.eclipse.jetty.http.HttpFields; import org.eclipse.jetty.http.HttpHeader; @@ -41,6 +41,7 @@ import org.eclipse.jetty.io.Connection; import org.eclipse.jetty.io.EndPoint; import org.eclipse.jetty.io.QuietException; import org.eclipse.jetty.server.Connector; +import org.eclipse.jetty.server.CustomRequestLog; import org.eclipse.jetty.server.HttpConfiguration; import org.eclipse.jetty.server.Request; import org.eclipse.jetty.server.Response; @@ -781,14 +782,27 @@ public class ServletChannel implements Runnable public void onCompleted() { - HttpServletRequest httpServletRequest = _request.getHttpServletRequest(); + ServletContextRequest.ServletApiRequest apiRequest = _request.getServletApiRequest(); if (LOG.isDebugEnabled()) - LOG.debug("onCompleted for {} written={}", httpServletRequest.getRequestURI(), getBytesWritten()); + LOG.debug("onCompleted for {} written={}", apiRequest.getRequestURI(), getBytesWritten()); long idleTO = _configuration.getIdleTimeout(); if (idleTO >= 0 && getIdleTimeout() != _oldIdleTimeout) setIdleTimeout(_oldIdleTimeout); + if (getServer().getRequestLog() != null) + { + Authentication authentication = apiRequest.getAuthentication(); + if (authentication instanceof Authentication.User userAuthentication) + _request.setAttribute(CustomRequestLog.USER_NAME, userAuthentication.getUserIdentity().getUserPrincipal().getName()); + + String realPath = apiRequest.getServletContext().getRealPath(_request.getPathInContext()); + _request.setAttribute(CustomRequestLog.REAL_PATH, realPath); + + String servletName = _request.getServletName(); + _request.setAttribute(CustomRequestLog.HANDLER_NAME, servletName); + } + // Callback will either be succeeded here or failed in abort(). if (_state.completeResponse()) _callback.succeeded(); diff --git a/jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogServletTest.java b/jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogServletTest.java deleted file mode 100644 index 5b827d07f99..00000000000 --- a/jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogServletTest.java +++ /dev/null @@ -1,141 +0,0 @@ -// -// ======================================================================== -// Copyright (c) 1995-2022 Mort Bay Consulting Pty Ltd and others. -// -// This program and the accompanying materials are made available under the -// terms of the Eclipse Public License v. 2.0 which is available at -// https://www.eclipse.org/legal/epl-2.0, or the Apache License, Version 2.0 -// which is available at https://www.apache.org/licenses/LICENSE-2.0. -// -// SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 -// ======================================================================== -// - -package org.eclipse.jetty.ee10.servlet; - -import java.io.File; -import java.io.IOException; -import java.nio.file.Paths; -import java.util.concurrent.BlockingQueue; -import java.util.concurrent.TimeUnit; - -import jakarta.servlet.ServletException; -import jakarta.servlet.ServletOutputStream; -import jakarta.servlet.http.HttpServlet; -import jakarta.servlet.http.HttpServletRequest; -import jakarta.servlet.http.HttpServletResponse; -import org.eclipse.jetty.server.CustomRequestLog; -import org.eclipse.jetty.server.LocalConnector; -import org.eclipse.jetty.server.RequestLog; -import org.eclipse.jetty.server.Server; -import org.eclipse.jetty.util.BlockingArrayQueue; -import org.hamcrest.Matchers; -import org.junit.jupiter.api.AfterEach; -import org.junit.jupiter.api.BeforeEach; -import org.junit.jupiter.api.Disabled; -import org.junit.jupiter.api.Test; - -import static org.hamcrest.MatcherAssert.assertThat; -import static org.hamcrest.Matchers.is; - -@Disabled -public class CustomRequestLogServletTest -{ - RequestLog _log; - Server _server; - LocalConnector _connector; - BlockingQueue _entries = new BlockingArrayQueue<>(); - String _tmpDir; - - @BeforeEach - public void before() throws Exception - { - _server = new Server(); - _connector = new LocalConnector(_server); - _server.addConnector(_connector); - _tmpDir = new File(System.getProperty("java.io.tmpdir")).getCanonicalPath(); - } - - void testHandlerServerStart(String formatString) throws Exception - { - ServletContextHandler context = new ServletContextHandler(ServletContextHandler.SESSIONS); - context.setContextPath("/context"); - context.setBaseResource(Paths.get(_tmpDir)); - context.addServlet(TestServlet.class, "/servlet/*"); - - TestRequestLogWriter writer = new TestRequestLogWriter(); - _log = new CustomRequestLog(writer, formatString); - _server.setRequestLog(_log); - _server.setHandler(context); - _server.start(); - } - - @AfterEach - public void after() throws Exception - { - _server.stop(); - } - - @Test - public void testLogFilename() throws Exception - { - testHandlerServerStart("Filename: %f"); - - _connector.getResponse("GET /context/servlet/info HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - String expected = new File(_tmpDir + File.separator + "servlet" + File.separator + "info").getCanonicalPath(); - assertThat(log, is("Filename: " + expected)); - } - - @Test - public void testLogRequestHandler() throws Exception - { - testHandlerServerStart("RequestHandler: %R"); - - _connector.getResponse("GET /context/servlet/ HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, Matchers.containsString("TestServlet")); - } - - class TestRequestLogWriter implements RequestLog.Writer - { - @Override - public void write(String requestEntry) - { - try - { - _entries.add(requestEntry); - } - catch (Exception e) - { - e.printStackTrace(); - } - } - } - - public static class TestServlet extends HttpServlet - { - @Override - protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException - { - if (request.getRequestURI().contains("error404")) - { - response.setStatus(404); - } - else if (request.getRequestURI().contains("error301")) - { - response.setStatus(301); - } - else if (request.getHeader("echo") != null) - { - ServletOutputStream outputStream = response.getOutputStream(); - outputStream.print(request.getHeader("echo")); - } - else if (request.getRequestURI().contains("responseHeaders")) - { - response.addHeader("Header1", "value1"); - response.addHeader("Header2", "value2"); - } - } - } -} diff --git a/jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogTest.java b/jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogTest.java new file mode 100644 index 00000000000..e9569cc1edb --- /dev/null +++ b/jetty-ee10/jetty-ee10-servlet/src/test/java/org/eclipse/jetty/ee10/servlet/CustomRequestLogTest.java @@ -0,0 +1,158 @@ +// +// ======================================================================== +// Copyright (c) 1995-2022 Mort Bay Consulting Pty Ltd and others. +// +// This program and the accompanying materials are made available under the +// terms of the Eclipse Public License v. 2.0 which is available at +// https://www.eclipse.org/legal/epl-2.0, or the Apache License, Version 2.0 +// which is available at https://www.apache.org/licenses/LICENSE-2.0. +// +// SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 +// ======================================================================== +// + +package org.eclipse.jetty.ee10.servlet; + +import java.io.File; +import java.io.IOException; +import java.nio.file.Path; +import java.util.Base64; +import java.util.concurrent.BlockingQueue; +import java.util.concurrent.TimeUnit; + +import jakarta.servlet.ServletException; +import jakarta.servlet.http.HttpServlet; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import org.eclipse.jetty.ee10.servlet.security.ConstraintMapping; +import org.eclipse.jetty.ee10.servlet.security.ConstraintSecurityHandler; +import org.eclipse.jetty.ee10.servlet.security.HashLoginService; +import org.eclipse.jetty.ee10.servlet.security.UserStore; +import org.eclipse.jetty.ee10.servlet.security.authentication.BasicAuthenticator; +import org.eclipse.jetty.http.HttpHeader; +import org.eclipse.jetty.server.CustomRequestLog; +import org.eclipse.jetty.server.LocalConnector; +import org.eclipse.jetty.server.RequestLog; +import org.eclipse.jetty.server.Server; +import org.eclipse.jetty.util.BlockingArrayQueue; +import org.eclipse.jetty.util.component.LifeCycle; +import org.eclipse.jetty.util.security.Constraint; +import org.eclipse.jetty.util.security.Credential; +import org.hamcrest.Matchers; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; + +import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.is; + +public class CustomRequestLogTest +{ + private final BlockingQueue _logs = new BlockingArrayQueue<>(); + private Server _server; + private LocalConnector _connector; + private Path _tmpDir; + + private void start(String formatString, HttpServlet servlet) throws Exception + { + _server = new Server(); + _connector = new LocalConnector(_server); + _server.addConnector(_connector); + + TestRequestLogWriter writer = new TestRequestLogWriter(); + RequestLog requestLog = new CustomRequestLog(writer, formatString); + _server.setRequestLog(requestLog); + + _tmpDir = Path.of(System.getProperty("java.io.tmpdir")).toRealPath(); + ServletContextHandler context = new ServletContextHandler(ServletContextHandler.SESSIONS); + context.setBaseResource(_tmpDir); + context.setContextPath("/context"); + context.addServlet(new ServletHolder(servlet), "/servlet/*"); + + HashLoginService loginService = new HashLoginService(); + UserStore userStore = new UserStore(); + userStore.addUser("username", Credential.getCredential("password"), new String[]{"user"}); + loginService.setUserStore(userStore); + loginService.setName("realm"); + + Constraint constraint = new Constraint(); + constraint.setName("auth"); + constraint.setAuthenticate(true); + constraint.setRoles(new String[]{"**"}); + + ConstraintMapping mapping = new ConstraintMapping(); + mapping.setPathSpec("/secure/*"); + mapping.setConstraint(constraint); + + ConstraintSecurityHandler security = new ConstraintSecurityHandler(); + security.addConstraintMapping(mapping); + security.setAuthenticator(new BasicAuthenticator()); + security.setLoginService(loginService); + + context.setSecurityHandler(security); + + _server.setHandler(context); + + _server.start(); + } + + @AfterEach + public void after() + { + LifeCycle.stop(_server); + } + + @Test + public void testLogFilename() throws Exception + { + start("Filename: %f", new SimpleServlet()); + + _connector.getResponse("GET /context/servlet/info HTTP/1.0\n\n"); + String log = _logs.poll(5, TimeUnit.SECONDS); + String expected = new File(_tmpDir + File.separator + "servlet" + File.separator + "info").getCanonicalPath(); + assertThat(log, is("Filename: " + expected)); + } + + @Test + public void testLogRequestHandler() throws Exception + { + start("RequestHandler: %R", new SimpleServlet()); + + _connector.getResponse("GET /context/servlet/ HTTP/1.0\n\n"); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, Matchers.containsString(SimpleServlet.class.getSimpleName())); + } + + @Test + public void testLogRemoteUser() throws Exception + { + String authHeader = HttpHeader.AUTHORIZATION + ": Basic " + Base64.getEncoder().encodeToString("username:password".getBytes()); + start("%u", new SimpleServlet()); + + _connector.getResponse("GET /context/servlet/unsecure HTTP/1.0\n\n"); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("-")); + + _connector.getResponse("GET /context/servlet/secure HTTP/1.0\n" + authHeader + "\n\n"); + log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("username")); + } + + private class TestRequestLogWriter implements RequestLog.Writer + { + @Override + public void write(String requestEntry) + { + _logs.add(requestEntry); + } + } + + private static class SimpleServlet extends HttpServlet + { + @Override + protected void service(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException + { + // Trigger the authentication. + request.getRemoteUser(); + } + } +} diff --git a/jetty-ee9/jetty-ee9-nested/src/main/java/org/eclipse/jetty/ee9/nested/HttpChannel.java b/jetty-ee9/jetty-ee9-nested/src/main/java/org/eclipse/jetty/ee9/nested/HttpChannel.java index 7788634a24f..e5133395990 100644 --- a/jetty-ee9/jetty-ee9-nested/src/main/java/org/eclipse/jetty/ee9/nested/HttpChannel.java +++ b/jetty-ee9/jetty-ee9-nested/src/main/java/org/eclipse/jetty/ee9/nested/HttpChannel.java @@ -50,6 +50,7 @@ import org.eclipse.jetty.io.QuietException; import org.eclipse.jetty.server.AbstractConnector; import org.eclipse.jetty.server.ConnectionMetaData; import org.eclipse.jetty.server.Connector; +import org.eclipse.jetty.server.CustomRequestLog; import org.eclipse.jetty.server.HttpConfiguration; import org.eclipse.jetty.server.Server; import org.eclipse.jetty.util.BufferUtil; @@ -945,12 +946,25 @@ public class HttpChannel implements Runnable, HttpOutput.Interceptor public void onCompleted() { if (LOG.isDebugEnabled()) - LOG.debug("onCompleted for {} written={}", getRequest().getRequestURI(), getBytesWritten()); + LOG.debug("onCompleted for {} written={}", _request.getRequestURI(), getBytesWritten()); long idleTO = _configuration.getIdleTimeout(); if (idleTO >= 0 && getIdleTimeout() != _oldIdleTimeout) setIdleTimeout(_oldIdleTimeout); + if (getServer().getRequestLog() != null) + { + Authentication authentication = _request.getAuthentication(); + if (authentication instanceof Authentication.User userAuthentication) + _request.setAttribute(CustomRequestLog.USER_NAME, userAuthentication.getUserIdentity().getUserPrincipal().getName()); + + String realPath = _request.getServletContext().getRealPath(_request.getPathInContext()); + _request.setAttribute(CustomRequestLog.REAL_PATH, realPath); + + String servletName = _request.getServletName(); + _request.setAttribute(CustomRequestLog.HANDLER_NAME, servletName); + } + _request.onCompleted(); _combinedListener.onComplete(_request); Callback callback = _coreCallback; diff --git a/jetty-ee9/jetty-ee9-servlet/src/test/java/org/eclipse/jetty/ee9/servlet/CustomRequestLogTest.java b/jetty-ee9/jetty-ee9-servlet/src/test/java/org/eclipse/jetty/ee9/servlet/CustomRequestLogTest.java index 7661d6d1767..2e56b34a873 100644 --- a/jetty-ee9/jetty-ee9-servlet/src/test/java/org/eclipse/jetty/ee9/servlet/CustomRequestLogTest.java +++ b/jetty-ee9/jetty-ee9-servlet/src/test/java/org/eclipse/jetty/ee9/servlet/CustomRequestLogTest.java @@ -15,73 +15,99 @@ package org.eclipse.jetty.ee9.servlet; import java.io.File; import java.io.IOException; +import java.nio.file.Path; +import java.util.Base64; import java.util.concurrent.BlockingQueue; import java.util.concurrent.TimeUnit; import jakarta.servlet.ServletException; -import jakarta.servlet.ServletOutputStream; import jakarta.servlet.http.HttpServlet; import jakarta.servlet.http.HttpServletRequest; import jakarta.servlet.http.HttpServletResponse; +import org.eclipse.jetty.ee9.security.ConstraintMapping; +import org.eclipse.jetty.ee9.security.ConstraintSecurityHandler; +import org.eclipse.jetty.ee9.security.HashLoginService; +import org.eclipse.jetty.ee9.security.UserStore; +import org.eclipse.jetty.ee9.security.authentication.BasicAuthenticator; +import org.eclipse.jetty.http.HttpHeader; import org.eclipse.jetty.server.CustomRequestLog; import org.eclipse.jetty.server.LocalConnector; import org.eclipse.jetty.server.RequestLog; import org.eclipse.jetty.server.Server; import org.eclipse.jetty.util.BlockingArrayQueue; +import org.eclipse.jetty.util.component.LifeCycle; +import org.eclipse.jetty.util.security.Constraint; +import org.eclipse.jetty.util.security.Credential; import org.hamcrest.Matchers; import org.junit.jupiter.api.AfterEach; -import org.junit.jupiter.api.BeforeEach; -import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.is; -@Disabled // TODO public class CustomRequestLogTest { - RequestLog _log; - Server _server; - LocalConnector _connector; - BlockingQueue _entries = new BlockingArrayQueue<>(); - String _tmpDir; + private final BlockingQueue _logs = new BlockingArrayQueue<>(); + private Server _server; + private LocalConnector _connector; + private Path _tmpDir; - @BeforeEach - public void before() throws Exception + private void start(String formatString, HttpServlet servlet) throws Exception { _server = new Server(); _connector = new LocalConnector(_server); _server.addConnector(_connector); - _tmpDir = new File(System.getProperty("java.io.tmpdir")).getCanonicalPath(); - } - - void testHandlerServerStart(String formatString) throws Exception - { - ServletContextHandler context = new ServletContextHandler(ServletContextHandler.SESSIONS); - context.setContextPath("/context"); - context.setResourceBase(_tmpDir); - context.addServlet(TestServlet.class, "/servlet/*"); TestRequestLogWriter writer = new TestRequestLogWriter(); - _log = new CustomRequestLog(writer, formatString); - _server.setRequestLog(_log); + RequestLog requestLog = new CustomRequestLog(writer, formatString); + _server.setRequestLog(requestLog); + + _tmpDir = Path.of(System.getProperty("java.io.tmpdir")).toRealPath(); + ServletContextHandler context = new ServletContextHandler(ServletContextHandler.SESSIONS); + context.setBaseResource(_tmpDir); + context.setContextPath("/context"); + context.addServlet(new ServletHolder(servlet), "/servlet/*"); + + HashLoginService loginService = new HashLoginService(); + UserStore userStore = new UserStore(); + userStore.addUser("username", Credential.getCredential("password"), new String[]{"user"}); + loginService.setUserStore(userStore); + loginService.setName("realm"); + + Constraint constraint = new Constraint(); + constraint.setName("auth"); + constraint.setAuthenticate(true); + constraint.setRoles(new String[]{"**"}); + + ConstraintMapping mapping = new ConstraintMapping(); + mapping.setPathSpec("/secure/*"); + mapping.setConstraint(constraint); + + ConstraintSecurityHandler security = new ConstraintSecurityHandler(); + security.addConstraintMapping(mapping); + security.setAuthenticator(new BasicAuthenticator()); + security.setLoginService(loginService); + + context.setSecurityHandler(security); + _server.setHandler(context); + _server.start(); } @AfterEach - public void after() throws Exception + public void after() { - _server.stop(); + LifeCycle.stop(_server); } @Test public void testLogFilename() throws Exception { - testHandlerServerStart("Filename: %f"); + start("Filename: %f", new SimpleServlet()); _connector.getResponse("GET /context/servlet/info HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); + String log = _logs.poll(5, TimeUnit.SECONDS); String expected = new File(_tmpDir + File.separator + "servlet" + File.separator + "info").getCanonicalPath(); assertThat(log, is("Filename: " + expected)); } @@ -89,52 +115,44 @@ public class CustomRequestLogTest @Test public void testLogRequestHandler() throws Exception { - testHandlerServerStart("RequestHandler: %R"); + start("RequestHandler: %R", new SimpleServlet()); _connector.getResponse("GET /context/servlet/ HTTP/1.0\n\n"); - String log = _entries.poll(5, TimeUnit.SECONDS); - assertThat(log, Matchers.containsString("TestServlet")); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, Matchers.containsString(SimpleServlet.class.getSimpleName())); } - class TestRequestLogWriter implements RequestLog.Writer + @Test + public void testLogRemoteUser() throws Exception + { + String authHeader = HttpHeader.AUTHORIZATION + ": Basic " + Base64.getEncoder().encodeToString("username:password".getBytes()); + start("%u", new SimpleServlet()); + + _connector.getResponse("GET /context/servlet/unsecure HTTP/1.0\n\n"); + String log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("-")); + + _connector.getResponse("GET /context/servlet/secure HTTP/1.0\n" + authHeader + "\n\n"); + log = _logs.poll(5, TimeUnit.SECONDS); + assertThat(log, is("username")); + } + + private class TestRequestLogWriter implements RequestLog.Writer { @Override public void write(String requestEntry) { - try - { - _entries.add(requestEntry); - } - catch (Exception e) - { - e.printStackTrace(); - } + _logs.add(requestEntry); } } - public static class TestServlet extends HttpServlet + private static class SimpleServlet extends HttpServlet { @Override - protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException + protected void service(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException { - if (request.getRequestURI().contains("error404")) - { - response.setStatus(404); - } - else if (request.getRequestURI().contains("error301")) - { - response.setStatus(301); - } - else if (request.getHeader("echo") != null) - { - ServletOutputStream outputStream = response.getOutputStream(); - outputStream.print(request.getHeader("echo")); - } - else if (request.getRequestURI().contains("responseHeaders")) - { - response.addHeader("Header1", "value1"); - response.addHeader("Header2", "value2"); - } + // Trigger the authentication. + request.getRemoteUser(); } } }