From 07cf71e818e7feca1a36164c216a225f198d50f0 Mon Sep 17 00:00:00 2001 From: mposolda Date: Mon, 7 Oct 2024 12:27:19 +0200 Subject: [PATCH] Better logging when error happens during transaction commit closes #33275 Signed-off-by: mposolda --- .../util/ExportImportSessionTask.java | 2 +- .../resteasy/QuarkusHttpRequest.java | 5 + .../models/utils/KeycloakModelUtils.java | 17 +-- .../services/scheduled/NamedSessionTask.java | 39 ++++++ .../scheduled/ScheduledTaskRunner.java | 23 ++-- .../transaction/RequestContextHelper.java | 128 ++++++++++++++++++ .../keycloak/models/KeycloakSessionTask.java | 9 +- .../DefaultKeycloakTransactionManager.java | 2 +- .../resources/admin/RealmAdminResource.java | 2 +- .../transaction/JtaTransactionWrapper.java | 49 +++++-- .../testsuite/model/ClientModelTest.java | 2 +- 11 files changed, 246 insertions(+), 32 deletions(-) create mode 100644 server-spi-private/src/main/java/org/keycloak/services/scheduled/NamedSessionTask.java create mode 100644 server-spi-private/src/main/java/org/keycloak/transaction/RequestContextHelper.java diff --git a/model/storage-services/src/main/java/org/keycloak/exportimport/util/ExportImportSessionTask.java b/model/storage-services/src/main/java/org/keycloak/exportimport/util/ExportImportSessionTask.java index fa186d8271..0415d667f5 100755 --- a/model/storage-services/src/main/java/org/keycloak/exportimport/util/ExportImportSessionTask.java +++ b/model/storage-services/src/main/java/org/keycloak/exportimport/util/ExportImportSessionTask.java @@ -37,7 +37,7 @@ public abstract class ExportImportSessionTask implements KeycloakSessionTask { throw new RuntimeException("Error during export/import: " + ioe.getMessage(), ioe); } } - + @Override public boolean useExistingSession() { return true; diff --git a/quarkus/runtime/src/main/java/org/keycloak/quarkus/runtime/integration/resteasy/QuarkusHttpRequest.java b/quarkus/runtime/src/main/java/org/keycloak/quarkus/runtime/integration/resteasy/QuarkusHttpRequest.java index c70ecfbb1d..80fcf9bfaa 100644 --- a/quarkus/runtime/src/main/java/org/keycloak/quarkus/runtime/integration/resteasy/QuarkusHttpRequest.java +++ b/quarkus/runtime/src/main/java/org/keycloak/quarkus/runtime/integration/resteasy/QuarkusHttpRequest.java @@ -54,11 +54,13 @@ public final class QuarkusHttpRequest implements HttpRequest { @Override public String getHttpMethod() { + if (context == null) return null; return context.getMethod(); } @Override public MultivaluedMap getDecodedFormParameters() { + if (context == null) return null; FormData parameters = context.getFormData(); if (parameters == null || !parameters.iterator().hasNext()) { @@ -84,6 +86,7 @@ public final class QuarkusHttpRequest implements HttpRequest { @Override public MultivaluedMap getMultiPartFormParameters() { + if (context == null) return null; FormData formData = context.getFormData(); if (formData == null) { @@ -119,6 +122,7 @@ public final class QuarkusHttpRequest implements HttpRequest { @Override public HttpHeaders getHttpHeaders() { + if (context == null) return null; return context.getHttpHeaders(); } @@ -147,6 +151,7 @@ public final class QuarkusHttpRequest implements HttpRequest { @Override public UriInfo getUri() { + if (context == null) return null; return context.getUriInfo(); } } diff --git a/server-spi-private/src/main/java/org/keycloak/models/utils/KeycloakModelUtils.java b/server-spi-private/src/main/java/org/keycloak/models/utils/KeycloakModelUtils.java index e432acb0a3..415d5f170a 100755 --- a/server-spi-private/src/main/java/org/keycloak/models/utils/KeycloakModelUtils.java +++ b/server-spi-private/src/main/java/org/keycloak/models/utils/KeycloakModelUtils.java @@ -58,6 +58,7 @@ import org.keycloak.representations.idm.CertificateRepresentation; import org.keycloak.sessions.AuthenticationSessionModel; import org.keycloak.sessions.RootAuthenticationSessionModel; import org.keycloak.transaction.JtaTransactionManagerLookup; +import org.keycloak.transaction.RequestContextHelper; import org.keycloak.utils.KeycloakSessionUtil; import jakarta.transaction.InvalidTransactionException; @@ -259,10 +260,7 @@ public final class KeycloakModelUtils { * @param task The task to execute */ public static void runJobInTransaction(KeycloakSessionFactory factory, KeycloakSessionTask task) { - runJobInTransactionWithResult(factory, null, session -> { - task.run(session); - return null; - }, task.useExistingSession()); + runJobInTransaction(factory, null, task); } /** @@ -275,7 +273,7 @@ public final class KeycloakModelUtils { runJobInTransactionWithResult(factory, context, session -> { task.run(session); return null; - }, task.useExistingSession()); + }, task.useExistingSession(), task.getTaskName()); } /** @@ -365,7 +363,7 @@ public final class KeycloakModelUtils { * @return The return value from the callable */ public static V runJobInTransactionWithResult(KeycloakSessionFactory factory, final KeycloakSessionTaskWithResult callable) { - return runJobInTransactionWithResult(factory, null, callable, false); + return runJobInTransactionWithResult(factory, null, callable, false, "Non-HTTP task"); } /** @@ -375,16 +373,19 @@ public final class KeycloakModelUtils { * @param context The context from the previous session to use * @param callable The callable to execute * @param useExistingSession if the existing session should be used + * @param taskName Name of the task. Can be useful for logging purposes * @return The return value from the callable */ - public static V runJobInTransactionWithResult(KeycloakSessionFactory factory, KeycloakContext context, final KeycloakSessionTaskWithResult callable, boolean useExistingSession) { + public static V runJobInTransactionWithResult(KeycloakSessionFactory factory, KeycloakContext context, final KeycloakSessionTaskWithResult callable, + boolean useExistingSession, String taskName) { V result; KeycloakSession existing = KeycloakSessionUtil.getKeycloakSession(); if (useExistingSession && existing != null && existing.getTransactionManager().isActive()) { return callable.run(existing); } - + try (KeycloakSession session = factory.create()) { + RequestContextHelper.getContext(session).setContextMessage(taskName); session.getTransactionManager().begin(); KeycloakSessionUtil.setKeycloakSession(session); try { diff --git a/server-spi-private/src/main/java/org/keycloak/services/scheduled/NamedSessionTask.java b/server-spi-private/src/main/java/org/keycloak/services/scheduled/NamedSessionTask.java new file mode 100644 index 0000000000..b390c5b5a8 --- /dev/null +++ b/server-spi-private/src/main/java/org/keycloak/services/scheduled/NamedSessionTask.java @@ -0,0 +1,39 @@ +/* + * Copyright 2024 Red Hat, Inc. and/or its affiliates + * and other contributors as indicated by the @author tags. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +package org.keycloak.services.scheduled; + +import org.keycloak.models.KeycloakSessionTask; + +/** + * @author Marek Posolda + */ +public abstract class NamedSessionTask implements KeycloakSessionTask { + + private final String taskName; + + public NamedSessionTask(String taskName) { + this.taskName = taskName; + } + + @Override + public String getTaskName() { + return taskName; + } +} diff --git a/server-spi-private/src/main/java/org/keycloak/services/scheduled/ScheduledTaskRunner.java b/server-spi-private/src/main/java/org/keycloak/services/scheduled/ScheduledTaskRunner.java index a4861c8d69..8fad62f9fc 100644 --- a/server-spi-private/src/main/java/org/keycloak/services/scheduled/ScheduledTaskRunner.java +++ b/server-spi-private/src/main/java/org/keycloak/services/scheduled/ScheduledTaskRunner.java @@ -23,6 +23,7 @@ import org.keycloak.models.KeycloakSessionFactory; import org.keycloak.models.utils.KeycloakModelUtils; import org.keycloak.timer.ScheduledTask; import org.keycloak.timer.TaskRunner; +import org.keycloak.transaction.RequestContextHelper; /** * @author Stian Thorgersen @@ -50,16 +51,20 @@ public class ScheduledTaskRunner implements TaskRunner { @Override public void run() { try { - KeycloakModelUtils.runJobInTransaction(sessionFactory, session -> { - try { - if (transactionLimit != 0) { - KeycloakModelUtils.setTransactionLimit(sessionFactory, transactionLimit); - } + KeycloakModelUtils.runJobInTransaction(sessionFactory, new NamedSessionTask("Scheduled task: " + task.getTaskName()) { - runTask(session); - } finally { - if (transactionLimit != 0) { - KeycloakModelUtils.setTransactionLimit(sessionFactory, 0); + @Override + public void run(KeycloakSession session) { + try { + if (transactionLimit != 0) { + KeycloakModelUtils.setTransactionLimit(sessionFactory, transactionLimit); + } + + runTask(session); + } finally { + if (transactionLimit != 0) { + KeycloakModelUtils.setTransactionLimit(sessionFactory, 0); + } } } }); diff --git a/server-spi-private/src/main/java/org/keycloak/transaction/RequestContextHelper.java b/server-spi-private/src/main/java/org/keycloak/transaction/RequestContextHelper.java new file mode 100644 index 0000000000..95660a9458 --- /dev/null +++ b/server-spi-private/src/main/java/org/keycloak/transaction/RequestContextHelper.java @@ -0,0 +1,128 @@ +/* + * Copyright 2024 Red Hat, Inc. and/or its affiliates + * and other contributors as indicated by the @author tags. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +package org.keycloak.transaction; + +import java.util.List; +import java.util.Set; + +import jakarta.ws.rs.core.MultivaluedMap; +import org.keycloak.OAuth2Constants; +import org.keycloak.common.util.StackUtil; +import org.keycloak.http.HttpRequest; +import org.keycloak.models.KeycloakSession; + +/** + * Provides some info about current HTTP request. Useful for example for logging + * + * @author Marek Posolda + */ +public class RequestContextHelper { + + public static final String SESSION_ATTRIBUTE = "REQ_CONTEXT_HELPER"; + + private static final Set ALLOWED_ATTRIBUTES = Set.of(OAuth2Constants.GRANT_TYPE, OAuth2Constants.CIBA_GRANT_TYPE, OAuth2Constants.SCOPE, OAuth2Constants.TOKEN_EXCHANGE_GRANT_TYPE, OAuth2Constants.ACCESS_TOKEN_TYPE, + OAuth2Constants.DEVICE_CODE_GRANT_TYPE, OAuth2Constants.RESPONSE_TYPE); + + private final KeycloakSession session; + + // Explicitly set information about context. This is useful when the request is executed outside of HTTP (for example during periodic cleaner tasks) + private String contextMessage; + + private RequestContextHelper(KeycloakSession session) { + this.session = session; + } + + public void setContextMessage(String message) { + this.contextMessage = message; + } + + public static RequestContextHelper getContext(KeycloakSession session) { + RequestContextHelper ctxHelper = (RequestContextHelper) session.getAttribute(SESSION_ATTRIBUTE); + if (ctxHelper != null) { + return ctxHelper; + } else { + ctxHelper = new RequestContextHelper(session); + session.setAttribute(SESSION_ATTRIBUTE, ctxHelper); + return ctxHelper; + } + } + + /** + * Providing short information about current request. For example just something "HTTP GET /realms/test/account" + * + * @return + */ + public String getContextInfo() { + if (contextMessage != null) return contextMessage; + + try { + HttpRequest httpRequest = session.getContext().getHttpRequest(); + if (httpRequest != null && httpRequest.getUri() != null) { + + return new StringBuilder("HTTP ") + .append(httpRequest.getHttpMethod()) + .append(" ") + .append(httpRequest.getUri().getPath()) + .toString(); + } + } catch (Exception e) { + return "Unknown context"; + } + return "Non-HTTP context"; + } + + /** + * Providing longer information about current request. For example something like "HTTP GET /realms/test/protocol/openid-connect/token, form parameters [ grant_type=code, redirect_uri=https://... ]" + * + * @return + */ + public String getDetailedContextInfo() { + try { + HttpRequest httpRequest = session.getContext().getHttpRequest(); + if (httpRequest != null && httpRequest.getUri() != null) { + StringBuilder builder = new StringBuilder("HTTP ") + .append(httpRequest.getHttpMethod()) + .append(" ") + .append(httpRequest.getUri().getRequestUri()); + + MultivaluedMap formParams = httpRequest.getDecodedFormParameters(); + if (formParams != null && !formParams.isEmpty()) { + + builder.append(", Form parameters [ "); + formParams.entrySet().forEach(entry -> { + String key = entry.getKey(); + List values = entry.getValue(); + values.forEach(value -> { + + if (!ALLOWED_ATTRIBUTES.contains(key)) value = "***"; + builder.append(key + "=" + value + ", "); + }); + }); + builder.append(" ]"); + } + + return builder.toString(); + } + } catch (Exception e) { + // Fallback to getContextInfo if this happens + } + return getContextInfo(); + } +} diff --git a/server-spi/src/main/java/org/keycloak/models/KeycloakSessionTask.java b/server-spi/src/main/java/org/keycloak/models/KeycloakSessionTask.java index b6c4829f67..429a9cb02a 100644 --- a/server-spi/src/main/java/org/keycloak/models/KeycloakSessionTask.java +++ b/server-spi/src/main/java/org/keycloak/models/KeycloakSessionTask.java @@ -25,9 +25,16 @@ package org.keycloak.models; public interface KeycloakSessionTask { void run(KeycloakSession session); - + default boolean useExistingSession() { return false; } + /** + * @return Details about the task. Can be useful for logging purposes + */ + default String getTaskName() { + return "Non-HTTP task"; + } + } diff --git a/services/src/main/java/org/keycloak/services/DefaultKeycloakTransactionManager.java b/services/src/main/java/org/keycloak/services/DefaultKeycloakTransactionManager.java index 734efbcf13..75d85ae351 100755 --- a/services/src/main/java/org/keycloak/services/DefaultKeycloakTransactionManager.java +++ b/services/src/main/java/org/keycloak/services/DefaultKeycloakTransactionManager.java @@ -99,7 +99,7 @@ public class DefaultKeycloakTransactionManager implements KeycloakTransactionMan if (jtaLookup != null) { TransactionManager tm = jtaLookup.getTransactionManager(); if (tm != null) { - enlist(new JtaTransactionWrapper(session.getKeycloakSessionFactory(), tm)); + enlist(new JtaTransactionWrapper(session, tm)); } } } diff --git a/services/src/main/java/org/keycloak/services/resources/admin/RealmAdminResource.java b/services/src/main/java/org/keycloak/services/resources/admin/RealmAdminResource.java index 44fa75a4b8..50797ff529 100644 --- a/services/src/main/java/org/keycloak/services/resources/admin/RealmAdminResource.java +++ b/services/src/main/java/org/keycloak/services/resources/admin/RealmAdminResource.java @@ -1117,7 +1117,7 @@ public class RealmAdminResource { AdminEventBuilder adminEventClone = adminEvent.clone(kcSession); // calling a static method to avoid using the wrong instances return getPartialImportResults(requestBody, kcSession, realmClone, adminEventClone); - }, false) + }, false, "Partial import in realm " + realm.getName()) ).build(); } catch (ModelDuplicateException e) { throw ErrorResponse.exists(e.getLocalizedMessage()); diff --git a/services/src/main/java/org/keycloak/transaction/JtaTransactionWrapper.java b/services/src/main/java/org/keycloak/transaction/JtaTransactionWrapper.java index 69ea378ae1..dccc7d2142 100644 --- a/services/src/main/java/org/keycloak/transaction/JtaTransactionWrapper.java +++ b/services/src/main/java/org/keycloak/transaction/JtaTransactionWrapper.java @@ -17,6 +17,7 @@ package org.keycloak.transaction; import org.jboss.logging.Logger; +import org.keycloak.models.KeycloakSession; import org.keycloak.models.KeycloakSessionFactory; import org.keycloak.models.KeycloakTransaction; import org.keycloak.provider.ExceptionConverter; @@ -37,18 +38,26 @@ public class JtaTransactionWrapper implements KeycloakTransaction { protected Transaction ut; protected Transaction suspended; protected Exception ended; - protected KeycloakSessionFactory factory; + protected KeycloakSession session; + private final RequestContextHelper requestContextHelper; - public JtaTransactionWrapper(KeycloakSessionFactory factory, TransactionManager tm) { + public JtaTransactionWrapper(KeycloakSession session, TransactionManager tm) { this.tm = tm; - this.factory = factory; + this.session = session; + this.requestContextHelper = RequestContextHelper.getContext(session); try { suspended = tm.suspend(); - logger.debug("new JtaTransactionWrapper"); - logger.debugv("was existing? {0}", suspended != null); + tm.begin(); ut = tm.getTransaction(); + + String messageToLog = "new JtaTransactionWrapper. Was existing transaction suspended: " + (suspended != null); + if (suspended != null) { + messageToLog = messageToLog + " Suspended transaction: " + suspended + ". "; + } + logMessage(messageToLog); + //ended = new Exception(); } catch (Exception e) { throw new RuntimeException(e); @@ -61,7 +70,8 @@ public class JtaTransactionWrapper implements KeycloakTransaction { } final Throwable finalE = e; - factory.getProviderFactoriesStream(ExceptionConverter.class) + logger.error(getDetailedMessage("Exception during transaction operation.")); + session.getKeycloakSessionFactory().getProviderFactoriesStream(ExceptionConverter.class) .map(factory -> ((ExceptionConverter) factory).convert(finalE)) .filter(Objects::nonNull) .forEach(throwable -> { @@ -86,7 +96,7 @@ public class JtaTransactionWrapper implements KeycloakTransaction { @Override public void commit() { try { - logger.debug("JtaTransactionWrapper commit"); + logMessage("JtaTransactionWrapper commit."); tm.commit(); } catch (Exception e) { handleException(e); @@ -98,7 +108,7 @@ public class JtaTransactionWrapper implements KeycloakTransaction { @Override public void rollback() { try { - logger.debug("JtaTransactionWrapper rollback"); + logMessage("JtaTransactionWrapper rollback."); tm.rollback(); } catch (Exception e) { handleException(e); @@ -149,10 +159,10 @@ public class JtaTransactionWrapper implements KeycloakTransaction { protected void end() { ended = null; - logger.debug("JtaTransactionWrapper end"); + logMessage("JtaTransactionWrapper end."); if (suspended != null) { try { - logger.debug("JtaTransactionWrapper resuming suspended"); + logger.debug("JtaTransactionWrapper resuming suspended user transaction: " + suspended); tm.resume(suspended); } catch (Exception e) { throw new RuntimeException(e); @@ -160,4 +170,23 @@ public class JtaTransactionWrapper implements KeycloakTransaction { } } + + private void logMessage(String messageBase) { + if (logger.isTraceEnabled()) { + String msg = getDetailedMessage(messageBase); + + // Log the detailed messages in "debug" level for backwards compatibility, but just if "Trace" level is enabled + logger.debug(msg); + } else if (logger.isDebugEnabled()) { + logger.debug(messageBase + " Request Context: " + requestContextHelper.getContextInfo()); + } + } + + private String getDetailedMessage(String messageBase) { + String msg = messageBase + " Request context: " + requestContextHelper.getDetailedContextInfo(); + if (ut != null) { + msg = msg + ", Transaction: " + ut; + } + return msg; + } } diff --git a/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/model/ClientModelTest.java b/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/model/ClientModelTest.java index 3e1af98597..59097f83a0 100644 --- a/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/model/ClientModelTest.java +++ b/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/model/ClientModelTest.java @@ -299,7 +299,7 @@ public class ClientModelTest extends AbstractKeycloakTest { client = realm.addClient(id, "application2"); return client.getId(); - }, false); + }, false, "ClientModel task"); KeycloakModelUtils.runJobInTransaction(session.getKeycloakSessionFactory(), session.getContext(), (KeycloakSession sessionAppWithId2) -> { currentSession = sessionAppWithId2;