6.x logging improvements

core/src/main/java/com/predic8/membrane/core/exceptions/ProblemDetails.java

@@ -18,6 +18,7 @@
 import com.predic8.membrane.core.interceptor.*;
 import org.jetbrains.annotations.*;
 import org.slf4j.*;
+import org.slf4j.spi.LoggingEventBuilder;
 
 import java.util.*;
 
@@ -263,20 +264,32 @@ private void provideLogKeyInsteadOfDetails(Map<String, Object> root) {
 
         try {
             MDC.put(LOG_KEY, logKey);
-            log.info("ProblemDetails hidden. type={}, title={}, detail={}, internal={}",
-                    getTypeSubtypeString(), title, detail, internalFields);
-            if (exception != null) {
-                log.info("Message={}", exception.getMessage());
-                if (stacktrace) {
-                    log.info("Stacktrace for hidden details:", exception);
-                }
-            }
+            buildLoggingEvent().log();
         } finally {
             MDC.remove(LOG_KEY);
         }
         root.put(DETAIL, "Internal details are hidden. See server log (key: %s)".formatted(logKey));
     }
 
+    private @NotNull LoggingEventBuilder buildLoggingEvent() {
+        var loggingEvent = log.atInfo()
+                .addArgument(getTypeSubtypeString())
+                .addArgument(title)
+                .addArgument(detail)
+                .addArgument(internalFields);
+
+        String msg = "ProblemDetails hidden. type={}, title={}, detail={}, internal={}";
+
+        if (exception != null) {
+            if (stacktrace) {
+                return loggingEvent.setCause(exception).setMessage(msg + ", Stacktrace for hidden details:");
+            } else {
+                return loggingEvent.addArgument(exception.getMessage()).setMessage(msg + ", Message={}");
+            }
+        }
+        return loggingEvent.setMessage(msg);
+    }
+
     private @NotNull String getTypeSubtypeString() {
         String type = "https://membrane-api.io/problems/" + this.type;
         if ((!production || (status >= 400 && status < 500)) && !subType.isEmpty()) {
@@ -411,4 +424,4 @@ public Throwable getException() {
     public boolean isStacktrace() {
         return stacktrace;
     }
-}
+}

core/src/main/java/com/predic8/membrane/core/interceptor/AbstractInterceptorWithSession.java

@@ -64,6 +64,14 @@ public Outcome handleRequest(Exchange exc) {
         Outcome outcome;
         try {
             outcome = handleRequestInternal(exc);
+        } catch (SessionManagementException e) {
+            internal(router.isProduction(),getDisplayName())
+                    .flow(REQUEST)
+                    .detail("Error handling session for request!")
+                    .exception(e)
+                    .stacktrace(false)
+                    .buildAndSetResponse(exc);
+            return ABORT;
         } catch (Exception e) {
             log.error("", e);
             internal(router.isProduction(),getDisplayName())

core/src/main/java/com/predic8/membrane/core/interceptor/HTTPClientInterceptor.java

@@ -132,6 +132,14 @@ public Outcome handleRequest(Exchange exc) {
                     .internal("url",exc.getRequest().getUri())
                     .buildAndSetResponse(exc);
             return ABORT;
+        } catch (NoResponseException e) {
+            log.error("NoResponseException due to {}; {}", e.getCause(), e.getCause().getMessage());
+            internal(router.isProduction(), getDisplayName())
+                    .exception(e)
+                    .stacktrace(false)
+                    .internal("proxy", exc.getProxy().getName())
+                    .buildAndSetResponse(exc);
+            return ABORT;
         } catch (Exception e) {
             log.error("", e);
             internal(router.isProduction(), getDisplayName())

core/src/main/java/com/predic8/membrane/core/interceptor/Interceptor.java

@@ -16,6 +16,7 @@
 
 import com.predic8.membrane.core.*;
 import com.predic8.membrane.core.exchange.*;
+import com.predic8.membrane.core.interceptor.session.SessionManagementException;
 
 import java.util.*;
 
@@ -52,7 +53,7 @@ public boolean isAbort() {
 		}
 	}
 
-	Outcome handleRequest(Exchange exchange);
+	Outcome handleRequest(Exchange exchange) throws SessionManagementException;
 	Outcome handleResponse(Exchange exchange);
 
 	/**

core/src/main/java/com/predic8/membrane/core/interceptor/oauth2/authorizationservice/AuthorizationService.java

@@ -340,10 +340,9 @@ public OAuth2TokenResponseBody refreshTokenRequest(Session session, String wante
                     refreshTokenBodyBuilder(refreshToken).scope(wantedScope), fc)
                     .buildExchange());
         } catch (Exception e) {
-            log.warn("Error contacting OAuth2 Authorization Server during refresh request: {}", e.getMessage());
             throw new OAuth2Exception(
                     MEMBRANE_OAUTH2_SERVER_COMMUNICATION_ERROR,
-                    MEMBRANE_OAUTH2_SERVER_COMMUNICATION_ERROR_DESCRIPTION,
+                    "%s %s".formatted(MEMBRANE_OAUTH2_SERVER_COMMUNICATION_ERROR_DESCRIPTION, e.getMessage()),
                     internalServerError().body(MEMBRANE_OAUTH2_SERVER_COMMUNICATION_ERROR_DESCRIPTION).build());
         }
         return parseTokenResponse(checkTokenResponse(response));

core/src/main/java/com/predic8/membrane/core/interceptor/oauth2client/rf/OAuth2CallbackRequestHandler.java

@@ -13,6 +13,7 @@
    limitations under the License. */
 package com.predic8.membrane.core.interceptor.oauth2client.rf;
 
+import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.databind.*;
 import com.predic8.membrane.core.exchange.*;
 import com.predic8.membrane.core.exchange.snapshots.*;
@@ -90,7 +91,11 @@ public void handleRequest(Exchange exc, Session session) throws Exception {
             try {
                 originalRequest = originalExchangeStore.reconstruct(exc, session, stateFromUri);
             } catch (Exception e) {
-                log.warn("Could not reconstruct exchange snapshot '{}'", stateFromUri);
+                if (e.getCause() instanceof JsonProcessingException) {
+                    log.warn("OAuth2 flow failed to reconstruct original exchange from data found in '{}'", originalExchangeStore.getClass().getSimpleName());
+                } else {
+                    log.warn("OAuth2 flow could not find original exchange data in '{}'. This is likely caused by either an illegal state (e.g. the user pressing 'back' inside the OAuth2 flow) or an operational issue with the exchange store.", originalExchangeStore.getClass().getSimpleName());
+                }
                 throw new OAuth2Exception(
                         MEMBRANE_EXCHANGE_NOT_FOUND,
                         MEMBRANE_EXCHANGE_NOT_FOUND_DESCRIPTION,

core/src/main/java/com/predic8/membrane/core/interceptor/oauth2client/rf/StateManager.java

@@ -88,7 +88,7 @@ public static void verifyCsrfToken(Session session, StateManager stateFromUri) t
                         MEMBRANE_CSRF_TOKEN_MISSING_IN_SESSION_DESCRIPTION,
                         badRequest().body(MEMBRANE_CSRF_TOKEN_MISSING_IN_SESSION_DESCRIPTION).build());
             } else {
-                log.warn("Token from Session: '{}', Token from URI: '{}'", session.get(SESSION_PARAMETER_STATE), stateFromUri.getSecurityToken());
+                log.debug("Token from Session: '{}', Token from URI: '{}'", session.get(SESSION_PARAMETER_STATE), stateFromUri.getSecurityToken());
                 throw new OAuth2Exception(
                         MEMBRANE_CSRF_TOKEN_MISMATCH,
                         MEMBRANE_CSRF_TOKEN_MISMATCH_DESCRIPTION,
@@ -98,7 +98,7 @@ public static void verifyCsrfToken(Session session, StateManager stateFromUri) t
 
         // state in session can be "merged" -> save the selected state in session overwriting the possibly merged value
         if (!(session.get(SESSION_PARAMETER_STATE).equals(stateFromUri.getSecurityToken()))) {
-            log.warn("Replacing saved state '{}' with '{}'", session.get(SESSION_PARAMETER_STATE), stateFromUri.getSecurityToken());
+            log.debug("Replacing saved state '{}' with '{}'", session.get(SESSION_PARAMETER_STATE), stateFromUri.getSecurityToken());
         }
         session.put(SESSION_PARAMETER_STATE, stateFromUri.getSecurityToken());
     }

core/src/main/java/com/predic8/membrane/core/interceptor/oauth2client/rf/token/AccessTokenRefresher.java

@@ -18,6 +18,7 @@
 import com.predic8.membrane.core.exchange.Exchange;
 import com.predic8.membrane.core.interceptor.oauth2.OAuth2AnswerParameters;
 import com.predic8.membrane.core.interceptor.oauth2.authorizationservice.AuthorizationService;
+import com.predic8.membrane.core.interceptor.oauth2client.rf.OAuth2Exception;
 import com.predic8.membrane.core.interceptor.session.Session;
 import org.jetbrains.annotations.NotNull;
 import org.slf4j.Logger;
@@ -56,7 +57,11 @@ public void refreshIfNeeded(Session session, Exchange exc) {
             try {
                 exc.setProperty(OAUTH2, refreshAccessToken(session, wantedScope));
             } catch (Exception e) {
-                log.warn("Failed to refresh access token, clearing session and restarting OAuth2 flow.", e);
+                if (e instanceof OAuth2Exception oae) {
+                    log.warn("Failed to refresh access token, clearing session and restarting OAuth2 flow. [{}]", oae.getErrorDescription());
+                } else {
+                    log.warn("Failed to refresh access token, clearing session and restarting OAuth2 flow.");
+                }
                 session.clearAuthentication();
             }
         }

core/src/main/java/com/predic8/membrane/core/interceptor/session/SessionManagementException.java

@@ -0,0 +1,19 @@
+package com.predic8.membrane.core.interceptor.session;
+
+public class SessionManagementException extends RuntimeException {
+    public SessionManagementException(Exception cause) {
+        super(getMessageFromCause(cause));
+    }
+
+    private static String getMessageFromCause(Throwable e) {
+        var cause = getInnermostCause(e);
+        return "%s: %s".formatted(cause.getClass().getSimpleName(), cause.getMessage());
+    }
+
+    private static Throwable getInnermostCause(Throwable e) {
+        if (e.getCause() == null || e.getCause() == e) {
+            return e;
+        }
+        return getInnermostCause(e.getCause());
+    }
+}

core/src/main/java/com/predic8/membrane/core/interceptor/session/SessionManager.java

@@ -33,6 +33,7 @@
 import java.time.ZoneOffset;
 import java.time.format.DateTimeFormatter;
 import java.util.*;
+import java.util.function.Supplier;
 import java.util.regex.Pattern;
 import java.util.stream.Collectors;
 import java.util.stream.Stream;
@@ -126,7 +127,7 @@ public void postProcess(Exchange exc) {
                 initIssuer(exc);
         }
 
-        getSessionFromExchange(exc).ifPresent(session -> {
+        Optional.ofNullable(exc.getProperty(SESSION, Session.class)).ifPresent(session -> {
             try {
                 createDefaultResponseIfNeeded(exc);
                 handleSetCookieHeaderForResponse(exc, session);
@@ -297,18 +298,20 @@ private Map<String,Map<String, Object>> convertValidCookiesToAttributes(Exchange
 
     @NotNull
     public Session getSession(Exchange exc) {
-        return getSessionFromExchange(exc).orElseGet(() -> getSessionFromManager(exc));
-    }
-
-    // TODO Side effect!
-    private Session getSessionFromManager(Exchange exc) {
-        exc.setProperty(SESSION, getSessionInternal(exc));
-        return getSessionFromExchange(exc).get();
+        try {
+            return getOrUpdateSession(exc, () -> getSessionInternal(exc));
+        } catch (Exception e) {
+            throw new SessionManagementException(e);
+        }
     }
 
-
-    private Optional<Session> getSessionFromExchange(Exchange exc) {
-        return Optional.ofNullable(exc.getProperty(SESSION, Session.class));
+    private Session getOrUpdateSession(Exchange exc, Supplier<Session> supplier) {
+        var session = exc.getProperty(SESSION, Session.class);
+        if (session == null) {
+            session = supplier.get();
+            exc.setProperty(SESSION, session);
+        }
+        return session;
     }
 
     public List<String> createCookieAttributes(Exchange exc) {

core/src/main/java/com/predic8/membrane/core/openapi/serviceproxy/OpenAPIInterceptor.java

@@ -127,12 +127,12 @@ public Outcome handleRequest(Exchange exc) {
 
             return RETURN;
         } catch (Throwable t /* On purpose! Catch absolutely all */) {
-            final String LOG_MESSAGE = "Message could not be validated against OpenAPI cause of an error during validation. Please check the OpenAPI with title %s.";
-            log.error(LOG_MESSAGE.formatted(rec.api.getInfo().getTitle()), t);
+            final String LOG_MESSAGE = "Message could not be validated against OpenAPI cause of an error during validation. Please check the OpenAPI with title %s.".formatted(rec.api.getInfo().getTitle());
+            log.error(LOG_MESSAGE, t);
             user(router.isProduction(), getDisplayName())
                     .addSubSee("generic")
                     .flow(REQUEST)
-                    .detail(LOG_MESSAGE.formatted(rec.api.getInfo().getTitle()))
+                    .detail(LOG_MESSAGE)
                     .exception(t)
                     .buildAndSetResponse(exc);