From 0527d441e3aa7f0986a403da6d5258fc37939a13 Mon Sep 17 00:00:00 2001 From: Bill Burke Date: Wed, 16 Dec 2015 12:23:41 -0500 Subject: [PATCH] better logging --- .../AuthenticationProcessor.java | 6 +++- .../DefaultAuthenticationFlow.java | 35 ++++++++++++------- 2 files changed, 28 insertions(+), 13 deletions(-) diff --git a/services/src/main/java/org/keycloak/authentication/AuthenticationProcessor.java b/services/src/main/java/org/keycloak/authentication/AuthenticationProcessor.java index 710c77d0e3..75803f1a6d 100755 --- a/services/src/main/java/org/keycloak/authentication/AuthenticationProcessor.java +++ b/services/src/main/java/org/keycloak/authentication/AuthenticationProcessor.java @@ -658,6 +658,7 @@ public class AuthenticationProcessor { } public Response authenticateClient() throws AuthenticationFlowException { + logger.debug("AUTHENTICATE CLIENT"); AuthenticationFlow authenticationFlow = createFlowExecution(this.flowId, null); try { Response challenge = authenticationFlow.processFlow(); @@ -693,6 +694,7 @@ public class AuthenticationProcessor { } public static void resetFlow(ClientSessionModel clientSession) { + logger.debug("RESET FLOW"); clientSession.setTimestamp(Time.currentTime()); clientSession.setAuthenticatedUser(null); clientSession.clearExecutionStatus(); @@ -715,6 +717,7 @@ public class AuthenticationProcessor { public Response authenticationAction(String execution) { + logger.debug("authenticationAction"); checkClientSession(); String current = clientSession.getNote(CURRENT_AUTHENTICATION_EXECUTION); if (!execution.equals(current)) { @@ -762,7 +765,8 @@ public class AuthenticationProcessor { } public Response authenticateOnly() throws AuthenticationFlowException { - checkClientSession(); + logger.debug("AUTHENTICATE ONLY"); + checkClientSession(); event.client(clientSession.getClient().getClientId()) .detail(Details.REDIRECT_URI, clientSession.getRedirectUri()) .detail(Details.AUTH_METHOD, clientSession.getAuthMethod()); diff --git a/services/src/main/java/org/keycloak/authentication/DefaultAuthenticationFlow.java b/services/src/main/java/org/keycloak/authentication/DefaultAuthenticationFlow.java index ab27bbb9f5..9a3a8c221a 100755 --- a/services/src/main/java/org/keycloak/authentication/DefaultAuthenticationFlow.java +++ b/services/src/main/java/org/keycloak/authentication/DefaultAuthenticationFlow.java @@ -1,5 +1,6 @@ package org.keycloak.authentication; +import org.jboss.logging.Logger; import org.keycloak.models.AuthenticationExecutionModel; import org.keycloak.models.AuthenticationFlowModel; import org.keycloak.models.ClientSessionModel; @@ -17,6 +18,7 @@ import java.util.List; * @version $Revision: 1 $ */ public class DefaultAuthenticationFlow implements AuthenticationFlow { + protected static Logger logger = Logger.getLogger(DefaultAuthenticationFlow.class); Response alternativeChallenge = null; AuthenticationExecutionModel challengedAlternativeExecution = null; boolean alternativeSuccessful = false; @@ -44,10 +46,12 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { @Override public Response processAction(String actionExecution) { + logger.debugv("processAction: {0}", actionExecution); while (executionIterator.hasNext()) { AuthenticationExecutionModel model = executionIterator.next(); + logger.debugv("check: {0} requirement: {1}", model.getAuthenticator(), model.getRequirement().toString()); if (isProcessed(model)) { - AuthenticationProcessor.logger.debug("execution is processed"); + logger.debug("execution is processed"); if (!alternativeSuccessful && model.isAlternative() && processor.isSuccessful(model)) alternativeSuccessful = true; continue; @@ -62,6 +66,7 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { } Authenticator authenticator = factory.create(processor.getSession()); AuthenticationProcessor.Result result = processor.createAuthenticatorContext(model, authenticator, executions); + logger.debugv("action: {0}", model.getAuthenticator()); authenticator.action(result); Response response = processResult(result); if (response == null) { @@ -80,19 +85,24 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { @Override public Response processFlow() { + logger.debug("processFlow"); while (executionIterator.hasNext()) { AuthenticationExecutionModel model = executionIterator.next(); + logger.debugv("check execution: {0} requirement: {1}", model.getAuthenticator(), model.getRequirement().toString()); + if (isProcessed(model)) { - AuthenticationProcessor.logger.debug("execution is processed"); + logger.debug("execution is processed"); if (!alternativeSuccessful && model.isAlternative() && processor.isSuccessful(model)) alternativeSuccessful = true; continue; } if (model.isAlternative() && alternativeSuccessful) { + logger.debug("Skip alternative execution"); processor.getClientSession().setExecutionStatus(model.getId(), ClientSessionModel.ExecutionStatus.SKIPPED); continue; } if (model.isAuthenticatorFlow()) { + logger.debug("execution is flow"); AuthenticationFlow authenticationFlow = processor.createFlowExecution(model.getFlowId(), model); Response flowChallenge = authenticationFlow.processFlow(); if (flowChallenge == null) { @@ -122,7 +132,7 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { throw new RuntimeException("Unable to find factory for AuthenticatorFactory: " + model.getAuthenticator() + " did you forget to declare it in a META-INF/services file?"); } Authenticator authenticator = factory.create(processor.getSession()); - AuthenticationProcessor.logger.debugv("authenticator: {0}", factory.getId()); + logger.debugv("authenticator: {0}", factory.getId()); UserModel authUser = processor.getClientSession().getAuthenticatedUser(); if (authenticator.requiresUser() && authUser == null) { @@ -138,7 +148,7 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { if (!configuredFor) { if (model.isRequired()) { if (factory.isUserSetupAllowed()) { - AuthenticationProcessor.logger.debugv("authenticator SETUP_REQUIRED: {0}", factory.getId()); + logger.debugv("authenticator SETUP_REQUIRED: {0}", factory.getId()); processor.getClientSession().setExecutionStatus(model.getId(), ClientSessionModel.ExecutionStatus.SETUP_REQUIRED); authenticator.setRequiredActions(processor.getSession(), processor.getRealm(), processor.getClientSession().getAuthenticatedUser()); continue; @@ -152,6 +162,7 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { } } AuthenticationProcessor.Result context = processor.createAuthenticatorContext(model, authenticator, executions); + logger.debug("invoke authenticator.authenticate"); authenticator.authenticate(context); Response response = processResult(context); if (response != null) return response; @@ -165,12 +176,12 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { FlowStatus status = result.getStatus(); switch (status) { case SUCCESS: - AuthenticationProcessor.logger.debugv("authenticator SUCCESS: {0}", execution.getAuthenticator()); + logger.debugv("authenticator SUCCESS: {0}", execution.getAuthenticator()); processor.getClientSession().setExecutionStatus(execution.getId(), ClientSessionModel.ExecutionStatus.SUCCESS); if (execution.isAlternative()) alternativeSuccessful = true; return null; case FAILED: - AuthenticationProcessor.logger.debugv("authenticator FAILED: {0}", execution.getAuthenticator()); + logger.debugv("authenticator FAILED: {0}", execution.getAuthenticator()); processor.logFailure(); processor.getClientSession().setExecutionStatus(execution.getId(), ClientSessionModel.ExecutionStatus.FAILED); if (result.getChallenge() != null) { @@ -178,14 +189,14 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { } throw new AuthenticationFlowException(result.getError()); case FORK: - AuthenticationProcessor.logger.debugv("reset browser login from authenticator: {0}", execution.getAuthenticator()); + logger.debugv("reset browser login from authenticator: {0}", execution.getAuthenticator()); processor.getClientSession().setNote(AuthenticationProcessor.CURRENT_AUTHENTICATION_EXECUTION, execution.getId()); throw new ForkFlowException(result.getSuccessMessage(), result.getErrorMessage()); case FORCE_CHALLENGE: processor.getClientSession().setExecutionStatus(execution.getId(), ClientSessionModel.ExecutionStatus.CHALLENGED); return sendChallenge(result, execution); case CHALLENGE: - AuthenticationProcessor.logger.debugv("authenticator CHALLENGE: {0}", execution.getAuthenticator()); + logger.debugv("authenticator CHALLENGE: {0}", execution.getAuthenticator()); if (execution.isRequired()) { processor.getClientSession().setExecutionStatus(execution.getId(), ClientSessionModel.ExecutionStatus.CHALLENGED); return sendChallenge(result, execution); @@ -203,12 +214,12 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { } return null; case FAILURE_CHALLENGE: - AuthenticationProcessor.logger.debugv("authenticator FAILURE_CHALLENGE: {0}", execution.getAuthenticator()); + logger.debugv("authenticator FAILURE_CHALLENGE: {0}", execution.getAuthenticator()); processor.logFailure(); processor.getClientSession().setExecutionStatus(execution.getId(), ClientSessionModel.ExecutionStatus.CHALLENGED); return sendChallenge(result, execution); case ATTEMPTED: - AuthenticationProcessor.logger.debugv("authenticator ATTEMPTED: {0}", execution.getAuthenticator()); + logger.debugv("authenticator ATTEMPTED: {0}", execution.getAuthenticator()); if (execution.getRequirement() == AuthenticationExecutionModel.Requirement.REQUIRED) { throw new AuthenticationFlowException(AuthenticationFlowError.INVALID_CREDENTIALS); } @@ -218,8 +229,8 @@ public class DefaultAuthenticationFlow implements AuthenticationFlow { AuthenticationProcessor.resetFlow(processor.getClientSession()); return processor.authenticate(); default: - AuthenticationProcessor.logger.debugv("authenticator INTERNAL_ERROR: {0}", execution.getAuthenticator()); - AuthenticationProcessor.logger.error("Unknown result status"); + logger.debugv("authenticator INTERNAL_ERROR: {0}", execution.getAuthenticator()); + logger.error("Unknown result status"); throw new AuthenticationFlowException(AuthenticationFlowError.INTERNAL_ERROR); } }