Merge branch '7.8' of github.com-at055612:gchq/stroom into 7.8

Author: at055612

stroom-proxy/stroom-proxy-app/src/main/java/stroom/proxy/app/handler/HttpSender.java

@@ -11,6 +11,8 @@
 import stroom.security.api.UserIdentityFactory;
 import stroom.util.NullSafe;
 import stroom.util.io.ByteCountInputStream;
+import stroom.util.io.ByteSize;
+import stroom.util.logging.DurationTimer;
 import stroom.util.logging.LambdaLogger;
 import stroom.util.logging.LambdaLoggerFactory;
 import stroom.util.logging.LogUtil;
@@ -33,7 +35,6 @@
 import java.io.InputStream;
 import java.nio.charset.StandardCharsets;
 import java.time.Duration;
-import java.time.Instant;
 import java.util.AbstractMap.SimpleEntry;
 import java.util.EnumSet;
 import java.util.Map;
@@ -87,8 +88,6 @@ public HttpSender(final LogStream logStream,
     @Override
     public void send(final AttributeMap attributeMap,
                      final InputStream inputStream) throws ForwardException {
-        final Instant startTime = Instant.now();
-
         if (NullSafe.isEmptyString(attributeMap.get(StandardHeaderArguments.FEED))) {
             throw new StroomStreamException(StroomStatusCode.FEED_MUST_BE_SPECIFIED, attributeMap);
         }
@@ -114,7 +113,7 @@ public void send(final AttributeMap attributeMap,
 
         // Execute and get the response.
         final ResponseStatus responseStatus = post(
-                httpPost, startTime, attributeMap, byteCountInputStream::getCount);
+                httpPost, attributeMap, byteCountInputStream::getCount);
         LOGGER.debug("responseStatus: {}", responseStatus);
     }
 
@@ -208,19 +207,19 @@ private void addAuthHeaders(final BasicHttpRequest request) {
     }
 
     private ResponseStatus post(final HttpPost httpPost,
-                                final Instant startTime,
                                 final AttributeMap attributeMap,
                                 final LongSupplier contentLengthSupplier) throws ForwardException {
         // Execute and get the response.
+        final DurationTimer timer = DurationTimer.start();
         try {
             final ResponseStatus responseStatus = httpClient.execute(httpPost, response -> {
                 LOGGER.debug(() -> LogUtil.message(
                         "'{}' - Closing stream, response header fields:\n{}",
                         forwarderName, formatHeaderEntryListForLogging(response.getHeaders())));
-                return logResponseToSendLog(startTime, response, attributeMap, contentLengthSupplier);
+                return logResponseToSendLog(timer.get(), response, attributeMap, contentLengthSupplier);
             });
 
-            LOGGER.debug("'{}' - responseStatus: {}", forwarderName, responseStatus);
+            LOGGER.debug("'{}' - responseStatus: {}, duration: {}", forwarderName, responseStatus, timer);
 
             // There is no point retrying with these
             final StroomStatusCode stroomStatusCode = responseStatus.stroomStatusCode;
@@ -235,10 +234,15 @@ private ResponseStatus post(final HttpPost httpPost,
             // Created above so we will have already logged
             throw e;
         } catch (final Exception e) {
-            logErrorToSendLog(startTime, e, attributeMap);
+            final Duration duration = timer.get();
+            final long byteCount = LogUtil.swallowExceptions(contentLengthSupplier)
+                    .orElse(0);
             // Have to assume that any exception is recoverable
+            final String msg = LogUtil.message("Error during HTTP POST, data sent: {}, duration: {}, error: {}",
+                    ByteSize.ofBytes(byteCount), duration, LogUtil.exceptionMessage(e));
+            logErrorToSendLog(duration, e, msg, attributeMap);
             throw ForwardException.recoverable(
-                    StroomStatusCode.UNKNOWN_ERROR, attributeMap, e.getMessage(), e);
+                    StroomStatusCode.UNKNOWN_ERROR, attributeMap, msg, e);
         }
     }
 
@@ -275,10 +279,11 @@ private String formatAttributeMapLogging(final AttributeMap attributeMap) {
                 .collect(Collectors.joining("\n"));
     }
 
-    private void logErrorToSendLog(final Instant startTime,
-                                   final Throwable e,
+    private void logErrorToSendLog(final Duration duration,
+                                   final Exception e,
+                                   final String exceptionMessage,
                                    final AttributeMap attributeMap) {
-        LOGGER.debug(() -> LogUtil.message("'{}' - {}", forwarderName, LogUtil.exceptionMessage(e), e));
+        LOGGER.debug(() -> LogUtil.message("'{}' - {}", forwarderName, exceptionMessage, e));
         logStream.log(
                 SEND_LOG,
                 attributeMap,
@@ -287,11 +292,11 @@ private void logErrorToSendLog(final Instant startTime,
                 StroomStatusCode.UNKNOWN_ERROR,
                 null,
                 0,
-                Duration.between(startTime, Instant.now()).toMillis(),
+                duration.toMillis(),
                 LogUtil.exceptionMessage(e));
     }
 
-    private ResponseStatus logResponseToSendLog(final Instant startTime,
+    private ResponseStatus logResponseToSendLog(final Duration duration,
                                                 final ClassicHttpResponse response,
                                                 final AttributeMap attributeMap,
                                                 final LongSupplier contentLengthSupplier) {
@@ -319,7 +324,7 @@ private ResponseStatus logResponseToSendLog(final Instant startTime,
                     stroomStatusCode,
                     receiptId,
                     contentLength,
-                    Duration.between(startTime, Instant.now()).toMillis());
+                    duration.toMillis());
 
             return responseStatus;
 //        } catch (StroomStreamException e) {

stroom-proxy/stroom-proxy-app/src/main/java/stroom/proxy/app/handler/RetryingForwardDestination.java

@@ -330,7 +330,7 @@ private boolean forwardDir(final Path dir) {
                         + "' to " + getDestinationType() + " forward destination '"
                         + destinationName + "' "
                         + "(attempts: " + attempts + ", retryAge: " + retryAge + "): "
-                        + LogUtil.exceptionMessage(getCause(e)) + ". "
+                        + e.getMessage() + ". "
                         + (e instanceof ForwardException fe
                                 ? "Feed: '" + fe.getFeedName() + "'. HTTP code: " + fe.getHttpResponseCode() + ". "
                                 : "")

stroom-util/src/main/java/stroom/util/logging/LogUtil.java

@@ -18,8 +18,14 @@
 import java.time.Instant;
 import java.util.Collection;
 import java.util.Objects;
+import java.util.Optional;
+import java.util.OptionalInt;
+import java.util.OptionalLong;
 import java.util.function.Consumer;
 import java.util.function.Function;
+import java.util.function.IntSupplier;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
 import java.util.stream.Collectors;
 
 public final class LogUtil {
@@ -417,4 +423,43 @@ public static void logStackTrace(final String message,
             }
         }
     }
+
+    /**
+     * Return the value supplied by supplier. Any exceptions will be swallowed and logged to debug only.
+     * Useful for getting values for logging that may throw.
+     */
+    public static <T> Optional<T> swallowExceptions(final Supplier<T> supplier) {
+        try {
+            return Optional.ofNullable(supplier.get());
+        } catch (Exception e) {
+            LOGGER.debug("Error swallowed", e);
+            return Optional.empty();
+        }
+    }
+
+    /**
+     * Return the value supplied by supplier. Any exceptions will be swallowed and logged to debug only.
+     * Useful for getting values for logging that may throw.
+     */
+    public static OptionalLong swallowExceptions(final LongSupplier supplier) {
+        try {
+            return OptionalLong.of(supplier.getAsLong());
+        } catch (Exception e) {
+            LOGGER.debug("Error swallowed", e);
+            return OptionalLong.empty();
+        }
+    }
+
+    /**
+     * Return the value supplied by supplier. Any exceptions will be swallowed and logged to debug only.
+     * Useful for getting values for logging that may throw.
+     */
+    public static OptionalInt swallowExceptions(final IntSupplier supplier) {
+        try {
+            return OptionalInt.of(supplier.getAsInt());
+        } catch (Exception e) {
+            LOGGER.debug("Error swallowed", e);
+            return OptionalInt.empty();
+        }
+    }
 }

unreleased_changes/20250411_084800_077__0.md

@@ -0,0 +1,19 @@
+* Improve log message when proxy HTTP forwarding fails. Now includes the time taken and the bytes sent.
+
+
+```sh
+# ONLY the top line will be included as a change entry in the CHANGELOG.
+# The entry should be in GitHub flavour markdown and should be written on a SINGLE
+# line with no hard breaks. You can have multiple change files for a single GitHub issue.
+# The  entry should be written in the imperative mood, i.e. 'Fix nasty bug' rather than
+# 'Fixed nasty bug'.
+#
+# Examples of acceptable entries are:
+#
+#
+# * Issue **123** : Fix bug with an associated GitHub issue in this repository
+#
+# * Issue **namespace/other-repo#456** : Fix bug with an associated GitHub issue in another repository
+#
+# * Fix bug with no associated GitHub issue.
+```