From 2fff3f33877bc2b369b5bae72bd3b62a8fe999cb Mon Sep 17 00:00:00 2001 From: Paul Millar Date: Sat, 13 Dec 2025 22:04:18 +0100 Subject: [PATCH] common: increase robustness of access log file Motivaition: The information about HTTP-based requests (WebDAV and REST) are only logged in the access log file when the request has been processed. Currently, this logging only happens if the request is handled normally; i.e., no exception was thrown and (for async requests) the processing didn't take too long. This means that a request that triggers certain failure modes would not have an entry in the access log file. Modification: Update existing `requestCompleted` method to accept a `NetLoggerBuilder` consumer. This consumer should add any mode-specific additional logging information. Create methods that handle the three modes in which the processing of a request might finish: `requestCompletedNormally`, `requestCompletedExceptionally`, `requestTimedOut`. All three modes add mode-specific information to the access log entry. The access log entry key-value pairs derived from the response are moved to the `requestCompletedNormally` method. The other modes will use default responses, rendering this information unreliable in those cases. The async listener `LogOnComplete` is updated so that `onTimeout` and `onError` event notification trigger `requestTimedOut` and `requestCompletedExceptionally` logging, respectively. The `NetLoggerBuilder` class is updated to accept key-value pairs where the value has type Duration. Result: Fix bug where webdav and frontend door access log files would fail to log requests that trigger certain failures in dCache. Target: master Requires-notes: yes Requires-book: no Request: 11.1 Request: 11.0 Request: 10.2 Request: 10.1 Request: 10.0 Request: 9.2 Closes: #7939 Patch: https://rb.dcache.org/r/14581/ Acked-by: Tigran Mkrtchyan --- .../org/dcache/util/NetLoggerBuilder.java | 5 ++ .../dcache/http/AbstractLoggingHandler.java | 66 +++++++++++++++---- 2 files changed, 58 insertions(+), 13 deletions(-) diff --git a/modules/cells/src/main/java/org/dcache/util/NetLoggerBuilder.java b/modules/cells/src/main/java/org/dcache/util/NetLoggerBuilder.java index 0354284d050..69391d4fde8 100644 --- a/modules/cells/src/main/java/org/dcache/util/NetLoggerBuilder.java +++ b/modules/cells/src/main/java/org/dcache/util/NetLoggerBuilder.java @@ -8,6 +8,7 @@ import com.google.common.net.InetAddresses; import java.net.InetSocketAddress; import java.security.Principal; +import java.time.Duration; import java.time.ZonedDateTime; import java.time.format.DateTimeFormatter; import java.util.function.Function; @@ -242,6 +243,10 @@ public NetLoggerBuilder add(String name, long value) { return add(name, String.valueOf(value)); } + public NetLoggerBuilder add(String name, Duration d) { + return add(name, TimeUtils.describe(d).orElse("0")); + } + public NetLoggerBuilder add(String name, Exception e) { return add(name + ".class", e.getClass().getSimpleName()) .add(name + ".message", e.getMessage()); diff --git a/modules/dcache/src/main/java/org/dcache/http/AbstractLoggingHandler.java b/modules/dcache/src/main/java/org/dcache/http/AbstractLoggingHandler.java index 78c4f23446a..98d624bcf63 100644 --- a/modules/dcache/src/main/java/org/dcache/http/AbstractLoggingHandler.java +++ b/modules/dcache/src/main/java/org/dcache/http/AbstractLoggingHandler.java @@ -26,7 +26,9 @@ import java.net.InetAddress; import java.net.InetSocketAddress; import java.security.cert.X509Certificate; +import java.time.Duration; import java.util.Optional; +import java.util.function.Consumer; import javax.security.auth.Subject; import javax.servlet.AsyncEvent; import javax.servlet.AsyncListener; @@ -43,6 +45,8 @@ import org.eclipse.jetty.server.handler.HandlerWrapper; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import static com.google.common.base.Throwables.throwIfInstanceOf; +import static com.google.common.base.Throwables.throwIfUnchecked; /** * This class act as a base logging class for logging servlet-based activity. It is expected that @@ -61,25 +65,34 @@ private class LogOnComplete implements AsyncListener { @Override public void onComplete(AsyncEvent event) { - requestCompleted((HttpServletRequest) event.getSuppliedRequest(), - (HttpServletResponse) event.getSuppliedResponse()); + requestCompletedNormally( + (HttpServletRequest) event.getSuppliedRequest(), + (HttpServletResponse) event.getSuppliedResponse()); } @Override public void onTimeout(AsyncEvent event) { - LOGGER.warn("Unexpected timeout on async processing of {}", - event.getAsyncContext().getRequest()); + var timeout = Duration.ofMillis(event.getAsyncContext().getTimeout()); + requestTimedOut( + (HttpServletRequest) event.getSuppliedRequest(), + (HttpServletResponse) event.getSuppliedResponse(), + timeout); } @Override public void onError(AsyncEvent event) { - LOGGER.warn("Unexpected error on async processing of {}", - event.getAsyncContext().getRequest()); + Throwable cause = event.getThrowable(); + if (cause instanceof Exception) { + requestCompletedExceptionally( + (HttpServletRequest) event.getSuppliedRequest(), + (HttpServletResponse) event.getSuppliedResponse(), + (Exception) cause); + } } @Override public void onStartAsync(AsyncEvent event) { - LOGGER.warn("Unexpected error on async processing of {}", + LOGGER.warn("Unexpected reuse of async processing context for {}", event.getAsyncContext().getRequest()); } } @@ -107,17 +120,46 @@ public void handle(String target, Request baseRequest, request.setAttribute(REMOTE_ADDRESS, remoteAddress(request).orElse(null)); request.setAttribute(PROCESSING_TIME, processingTime); - super.handle(target, baseRequest, request, response); + try { + super.handle(target, baseRequest, request, response); + } catch (IOException|RuntimeException|ServletException e) { + requestCompletedExceptionally(request, response, e); + + throwIfInstanceOf(e, IOException.class); + throwIfInstanceOf(e, ServletException.class); + throwIfUnchecked(e); + throw new AssertionError(e); + } if (request.isAsyncStarted()) { request.getAsyncContext().addListener(new LogOnComplete()); } else { - requestCompleted(request, response); + requestCompletedNormally(request, response); } } } - private void requestCompleted(HttpServletRequest request, HttpServletResponse response) { + private void requestCompletedExceptionally(HttpServletRequest request, HttpServletResponse response, Exception e) { + requestCompleted(request, response, l -> { + l.add("failure", e); + }); + } + + private void requestTimedOut(HttpServletRequest request, HttpServletResponse response, Duration timeout) { + requestCompleted(request, response, l -> { + l.add("timeout", timeout); + }); + } + + private void requestCompletedNormally(HttpServletRequest request, HttpServletResponse response) { + requestCompleted(request, response, l -> { + l.add("response.reason", getReason(response)); + l.add("response.code", response.getStatus()); + l.add("location", response.getHeader("Location")); + }); + } + + private void requestCompleted(HttpServletRequest request, HttpServletResponse response, Consumer logEnricher) { var processingTime = (Stopwatch) request.getAttribute(PROCESSING_TIME); processingTime.stop(); @@ -127,6 +169,7 @@ private void requestCompleted(HttpServletRequest request, HttpServletResponse re .omitNullValues(); describeOperation(log, request, response); log.add("duration", processingTime.elapsed().toMillis()); + logEnricher.accept(log); log.toLogger(accessLogger()); } @@ -135,9 +178,6 @@ protected void describeOperation(NetLoggerBuilder log, log.add("session", CDC.getSession()); log.add("request.method", request.getMethod()); log.add("request.url", request.getRequestURL()); - log.add("response.code", response.getStatus()); - log.add("response.reason", getReason(response)); - log.add("location", response.getHeader("Location")); log.add("socket.remote", (InetSocketAddress) request.getAttribute(REMOTE_ADDRESS)); log.add("user-agent", request.getHeader("User-Agent"));