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"));