libre.sh/keycloak-scim
3
0
Fork 0
Code Issues 15 Pull requests Releases Packages Activity Actions

Better logging when error happens during transaction commit

Browse source 
closes #33275

Signed-off-by: mposolda <mposolda@gmail.com>
This commit is contained in:
mposolda 2024-10-07 12:27:19 +02:00 committed by Marek Posolda
parent f2615919ff
commit 07cf71e818
11 changed files with 246 additions and 32 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

5
quarkus/runtime/src/main/java/org/keycloak/quarkus/runtime/integration/resteasy/QuarkusHttpRequest.java
View file

@ -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<String, String> 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<String, FormPartValue> 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();
}
}

15
server-spi-private/src/main/java/org/keycloak/models/utils/KeycloakModelUtils.java
View file

@ -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> V runJobInTransactionWithResult(KeycloakSessionFactory factory, final KeycloakSessionTaskWithResult<V> callable) {
return runJobInTransactionWithResult(factory, null, callable, false);
return runJobInTransactionWithResult(factory, null, callable, false, "Non-HTTP task");
}
/**
@ -375,9 +373,11 @@ 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> V runJobInTransactionWithResult(KeycloakSessionFactory factory, KeycloakContext context, final KeycloakSessionTaskWithResult<V> callable, boolean useExistingSession) {
public static <V> V runJobInTransactionWithResult(KeycloakSessionFactory factory, KeycloakContext context, final KeycloakSessionTaskWithResult<V> callable,
boolean useExistingSession, String taskName) {
V result;
KeycloakSession existing = KeycloakSessionUtil.getKeycloakSession();
if (useExistingSession && existing != null && existing.getTransactionManager().isActive()) {
@ -385,6 +385,7 @@ public final class KeycloakModelUtils {
}
try (KeycloakSession session = factory.create()) {
RequestContextHelper.getContext(session).setContextMessage(taskName);
session.getTransactionManager().begin();
KeycloakSessionUtil.setKeycloakSession(session);
try {

39
server-spi-private/src/main/java/org/keycloak/services/scheduled/NamedSessionTask.java Normal file
View file

@ -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 <a href="mailto:mposolda@redhat.com">Marek Posolda</a>
*/
public abstract class NamedSessionTask implements KeycloakSessionTask {
private final String taskName;
public NamedSessionTask(String taskName) {
this.taskName = taskName;
}
@Override
public String getTaskName() {
return taskName;
}
}

7
server-spi-private/src/main/java/org/keycloak/services/scheduled/ScheduledTaskRunner.java
View file

@ -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 <a href="mailto:sthorger@redhat.com">Stian Thorgersen</a>
@ -50,7 +51,10 @@ public class ScheduledTaskRunner implements TaskRunner {
@Override
public void run() {
try {
KeycloakModelUtils.runJobInTransaction(sessionFactory, session -> {
KeycloakModelUtils.runJobInTransaction(sessionFactory, new NamedSessionTask("Scheduled task: " + task.getTaskName()) {
@Override
public void run(KeycloakSession session) {
try {
if (transactionLimit != 0) {
KeycloakModelUtils.setTransactionLimit(sessionFactory, transactionLimit);
@ -62,6 +66,7 @@ public class ScheduledTaskRunner implements TaskRunner {
KeycloakModelUtils.setTransactionLimit(sessionFactory, 0);
}
}
}
});
} catch (Throwable t) {
logger.errorf(t, "Failed to run scheduled task %s", task.getTaskName());

128
server-spi-private/src/main/java/org/keycloak/transaction/RequestContextHelper.java Normal file
View file

@ -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 <a href="mailto:mposolda@redhat.com">Marek Posolda</a>
*/
public class RequestContextHelper {
public static final String SESSION_ATTRIBUTE = "REQ_CONTEXT_HELPER";
private static final Set<String> 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<String, String> formParams = httpRequest.getDecodedFormParameters();
if (formParams != null && !formParams.isEmpty()) {
builder.append(", Form parameters [ ");
formParams.entrySet().forEach(entry -> {
String key = entry.getKey();
List<String> 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();
}
}

7
server-spi/src/main/java/org/keycloak/models/KeycloakSessionTask.java
View file

@ -30,4 +30,11 @@ public interface KeycloakSessionTask {
return false;
}
/**
* @return Details about the task. Can be useful for logging purposes
*/
default String getTaskName() {
return "Non-HTTP task";
}
}

2
services/src/main/java/org/keycloak/services/DefaultKeycloakTransactionManager.java
View file

@ -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));
}
}
}

2
services/src/main/java/org/keycloak/services/resources/admin/RealmAdminResource.java
View file

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

49
services/src/main/java/org/keycloak/transaction/JtaTransactionWrapper.java
View file

@ -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;
}
}

2
testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/model/ClientModelTest.java
View file

@ -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;