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

Author: paulmillar

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

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