NPE in my Keycloak extension
605 views
Skip to first unread message
Miguel González
Nov 15, 2020, 12:20:37 PM11/15/20
to Keycloak User
Hello
I'm developing a Keycloak extension, specifically an Authenticator (One to verify registration in my service and one to send a push notification to a mobile device)
I'm running Keycloak 11.0.2 on an Ubuntu 18.04 virtual machine. I deployed my code in an .ear file
I followed the extension from IBM, https://github.com/IBM-Security/verify-keycloak-integration
Here's my authenticator configuration:
Somehow after all logic completes I get the following error, any ideas? Do you need to see the code? I haven't uploaded it in any repo yet.
```
020-11-15 11:05:13,144 INFO [org.keycloak.integration.okay.rest.OkayRestClient] (default task-1) response: {"sessionExternalId":"280105","status":{"code":0,"message":"OK"}}
2020-11-15 11:05:28,254 WARN [org.keycloak.services] (default task-1) KC-SERVICES0013: Failed authentication: java.lang.NullPointerException
at org.keycloak.authentication.DefaultAuthenticationFlow.processResult(DefaultAuthenticationFlow.java:482)
at org.keycloak.authentication.DefaultAuthenticationFlow.processAction(DefaultAuthenticationFlow.java:161)
at org.keycloak.authentication.AuthenticationProcessor.authenticationAction(AuthenticationProcessor.java:938)
at org.keycloak.services.resources.LoginActionsService.processFlow(LoginActionsService.java:311)
at org.keycloak.services.resources.LoginActionsService.processAuthentication(LoginActionsService.java:282)
at org.keycloak.services.resources.LoginActionsService.authenticate(LoginActionsService.java:266)
at org.keycloak.services.resources.LoginActionsService.authenticateForm(LoginActionsService.java:339)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:138)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:543)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:432)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$0(ResourceMethodInvoker.java:393)
at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:395)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:364)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:150)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:104)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:440)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:229)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:135)
at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:138)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:215)
at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:245)
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:61)
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.keycloak.provider.wildfly.WildFlyRequestFilter.lambda$doFilter$0(WildFlyRequestFilter.java:41)
at org.keycloak.services.filters.AbstractRequestFilter.filter(AbstractRequestFilter.java:43)
at org.keycloak.provider.wildfly.WildFlyRequestFilter.doFilter(WildFlyRequestFilter.java:39)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:269)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:370)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at java.lang.Thread.run(Thread.java:748)
2020-11-15 11:05:28,254 WARN [org.keycloak.services] (default task-1) KC-SERVICES0013: Failed authentication: java.lang.NullPointerException
at org.keycloak.authentication.DefaultAuthenticationFlow.processResult(DefaultAuthenticationFlow.java:482)
at org.keycloak.authentication.DefaultAuthenticationFlow.processAction(DefaultAuthenticationFlow.java:161)
at org.keycloak.authentication.AuthenticationProcessor.authenticationAction(AuthenticationProcessor.java:938)
at org.keycloak.services.resources.LoginActionsService.processFlow(LoginActionsService.java:311)
at org.keycloak.services.resources.LoginActionsService.processAuthentication(LoginActionsService.java:282)
at org.keycloak.services.resources.LoginActionsService.authenticate(LoginActionsService.java:266)
at org.keycloak.services.resources.LoginActionsService.authenticateForm(LoginActionsService.java:339)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:138)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:543)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:432)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$0(ResourceMethodInvoker.java:393)
at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:395)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:364)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:150)
at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:104)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:440)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:229)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:135)
at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:138)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:215)
at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:245)
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:61)
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.keycloak.provider.wildfly.WildFlyRequestFilter.lambda$doFilter$0(WildFlyRequestFilter.java:41)
at org.keycloak.services.filters.AbstractRequestFilter.filter(AbstractRequestFilter.java:43)
at org.keycloak.provider.wildfly.WildFlyRequestFilter.doFilter(WildFlyRequestFilter.java:39)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:269)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1530)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:370)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at java.lang.Thread.run(Thread.java:748)
```
Miguel González
Nov 15, 2020, 12:39:59 PM11/15/20
to Keycloak User
I see this after that stacktrace
```
2020-11-15 11:05:28,257 WARN [org.keycloak.events] (default task-1) type=LOGIN_ERROR, realmId=master, clientId=keycloak-sso-client, userId=null, ipAddress=192.168.1.3, error=invalid_user_credentials, auth_method=openid-connect, auth_type=code, redirect_uri=http://192.168.1.3:3000/dashboard, code_id=78a07658-5820-4231-bde5-17933ec72874, authSessionParentId=78a07658-5820-4231-bde5-17933ec72874, authSessionTabId=pmm1yUCXjes
```
```
Here's the client configuration 
And the user configuration
Miguel González
Nov 15, 2020, 11:39:06 PM11/15/20
to Keycloak User
found the solution, I turned On the Email Verified flag on the user I'm testing with
But right now I hit another issue, I have an infinite redirect loop after successful login ... and nothing on the logs
regards
- Miguel
Miguel González
Nov 16, 2020, 1:25:33 AM11/16/20
to Keycloak User
Finally found some information on the log, turned on debug mode, on why it stays on a loop
```
2020-11-16 00:01:08,502 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] (default task-12) Connection manager is shutting down
2020-11-16 00:01:08,502 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] (default task-12) http-outgoing-3: Close connection
2020-11-16 00:01:08,502 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] (default task-12) Connection manager shut down
2020-11-16 00:01:08,502 INFO [org.keycloak.integration.okay.auth.push.OkayAuthenticator] (default task-12) pushNotificationState: 0
2020-11-16 00:01:08,502 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) authenticator SUCCESS: push-login-authenticator
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) Flow '2nd factor flow' successfully finished after children executions success
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) processFlow: Okay Auth
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) check execution: 'auth-username-password-form', requirement: 'REQUIRED'
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) execution 'auth-username-password-form' is processed
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) check execution: '2nd factor flow', requirement: 'REQUIRED'
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) execution '2nd factor flow' is processed
2020-11-16 00:01:08,504 DEBUG [org.hibernate.SQL] (default task-12)
select
clientscop0_.ID as ID1_13_0_,
clientscop0_.DESCRIPTION as DESCRIPT2_13_0_,
clientscop0_.NAME as NAME3_13_0_,
clientscop0_.PROTOCOL as PROTOCOL4_13_0_,
clientscop0_.REALM_ID as REALM_ID5_13_0_
from
CLIENT_SCOPE clientscop0_
where
clientscop0_.ID=?
2020-11-16 00:01:08,504 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterStatement
2020-11-16 00:01:08,504 DEBUG [org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader] (default task-12) Done entity load : org.keycloak.models.jpa.entities.ClientScopeEntity#57013fda-f913-4747-921f-03c65b6393b7
2020-11-16 00:01:08,505 DEBUG [org.hibernate.SQL] (default task-12)
select
clientscop0_.ID as ID1_13_0_,
clientscop0_.DESCRIPTION as DESCRIPT2_13_0_,
clientscop0_.NAME as NAME3_13_0_,
clientscop0_.PROTOCOL as PROTOCOL4_13_0_,
clientscop0_.REALM_ID as REALM_ID5_13_0_
from
CLIENT_SCOPE clientscop0_
where
clientscop0_.ID=?
2020-11-16 00:01:08,505 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterStatement
2020-11-16 00:01:08,505 DEBUG [org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader] (default task-12) Done entity load : org.keycloak.models.jpa.entities.ClientScopeEntity#57013fda-f913-4747-921f-03c65b6393b7
2020-11-16 00:01:08,508 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-12) Removing authSession 'a47d11c3-cf1f-4104-8a07-f978b434f115'. Expire restart cookie: true
2020-11-16 00:01:08,508 DEBUG [org.keycloak.events] (default task-12) type=LOGIN, realmId=demo, clientId=keycloak-sso-client, userId=2be387f6-8e43-4d63-a761-9c6839c687e3, ipAddress=192.168.1.3, auth_method=openid-connect, auth_type=code, redirect_uri=http://192.168.1.3:3000/dashboard, consent=persistent_consent, code_id=a47d11c3-cf1f-4104-8a07-f978b434f115, username=demouser, authSessionParentId=a47d11c3-cf1f-4104-8a07-f978b434f115, authSessionTabId=eqF7xHw4YOc
2020-11-16 00:01:08,508 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) Couldnt find cookie {0}, trying {1}
2020-11-16 00:01:08,509 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-12) Create login cookie - name: KEYCLOAK_IDENTITY, path: /auth/realms/demo/, max-age: -1
2020-11-16 00:01:08,509 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-12) Expiring remember me cookie
2020-11-16 00:01:08,509 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-12) Expiring cookie: KEYCLOAK_REMEMBER_ME path: /auth/realms/demo/
2020-11-16 00:01:08,509 DEBUG [org.keycloak.protocol.oidc.OIDCLoginProtocol] (default task-12) redirectAccessCode: state: f86d4304-ef22-4d05-8844-5459db1cd1f1
2020-11-16 00:01:08,513 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper commit
2020-11-16 00:01:08,513 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Processing flush-time cascades
2020-11-16 00:01:08,513 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Dirty checking collections
2020-11-16 00:01:08,514 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2020-11-16 00:01:08,514 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2020-11-16 00:01:08,514 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-12) Listing entities:
2020-11-16 00:01:08,514 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-12) org.keycloak.models.jpa.entities.CredentialEntity{userLabel=null, createdDate=1605463497310, salt=null, id=766185b7-f5a2-4cc6-90d8-d2859578fb0c, credentialData={"hashIterations":27500,"algorithm":"pbkdf2-sha256"}, priority=10, type=password, user=<uninitialized>, secretData={"value":"EWi6TtgMSQVwfLpwZrPuygx/ho3QUI8aFR5wIMGMmHdXqTRzAm7oXakivHO3H9BEjVt2ysQrN1u6VSPJML9tiA==","salt":"XgqicBW7KB3EqkaCqsm4Tw=="}}
2020-11-16 00:01:08,514 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterStatement
2020-11-16 00:01:08,514 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (default task-12) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2020-11-16 00:01:08,515 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-12) KeycloakDS: returnConnection(6c2f201a, false) [0/100]
2020-11-16 00:01:08,515 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterTransaction
2020-11-16 00:01:08,515 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper end
2020-11-16 00:01:09,433 DEBUG [io.undertow.request] (default I/O-1) Matched prefix path /auth for path /auth/realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,433 DEBUG [io.undertow.request.security] (default task-12) Attempting to authenticate /auth/realms/demo/protocol/openid-connect/auth, authentication required: false
2020-11-16 00:01:09,433 DEBUG [io.undertow.request.security] (default task-12) Authentication outcome was NOT_ATTEMPTED with method io.undertow.security.impl.CachedAuthenticatedSessionMechanism@7d9047fa for /auth/realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,433 DEBUG [io.undertow.request.security] (default task-12) Authentication result was ATTEMPTED for /auth/realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,433 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) new JtaTransactionWrapper
2020-11-16 00:01:09,433 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) was existing? false
2020-11-16 00:01:09,434 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) RESTEASY002315: PathInfo: /realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,434 DEBUG [org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint] (default task-12) PKCE non-supporting Client
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) Couldnt find any cookies with name AUTH_SESSION_ID, trying AUTH_SESSION_ID_LEGACY
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the cookies field
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-12) Found AUTH_SESSION_ID cookie with value a47d11c3-cf1f-4104-8a07-f978b434f115.ubuntu
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) Couldnt find any cookies with name AUTH_SESSION_ID, trying AUTH_SESSION_ID_LEGACY
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the cookies field
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-12) Found AUTH_SESSION_ID cookie with value a47d11c3-cf1f-4104-8a07-f978b434f115.ubuntu
2020-11-16 00:01:09,436 DEBUG [org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider] (default task-12) getUserSessionWithPredicate(a47d11c3-cf1f-4104-8a07-f978b434f115): remote cache not available
2020-11-16 00:01:09,436 DEBUG [org.keycloak.protocol.AuthorizationEndpointBase] (default task-12) Sent request to authz endpoint. We don't have root authentication session with ID 'a47d11c3-cf1f-4104-8a07-f978b434f115' but we have userSession.Re-created root authentication session with same ID. Client is: keycloak-sso-client . New authentication session tab ID: gvGKCMbZBIA
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationProcessor] (default task-12) AUTHENTICATE
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationProcessor] (default task-12) AUTHENTICATE ONLY
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) processFlow: Okay Auth
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) check execution: 'auth-username-password-form', requirement: 'REQUIRED'
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) authenticator: auth-username-password-form
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver] (default task-12) Going through the flow 'Okay Auth' for adding executions
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver] (default task-12) Selections when trying execution 'auth-username-password-form' : [ authSelection - auth-username-password-form]
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) invoke authenticator.authenticate: auth-username-password-form
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) TemplateLoader.findTemplateSource("template_en_US.ftl"): Not found
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) TemplateLoader.findTemplateSource("template_en.ftl"): Not found
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) TemplateLoader.findTemplateSource("template.ftl"): Found
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) "template.ftl"("en_US", UTF-8, parsed): using cached since file:/opt/keycloak/themes/base/login/template.ftl hasn't changed.
2020-11-16 00:01:09,442 DEBUG [freemarker.beans] (default task-12) Key "selectedCredential" was not found on instance of org.keycloak.forms.login.freemarker.model.AuthenticationContextBean. Introspection information for the class is: {getClass=public final native java.lang.Class java.lang.Object.getClass(), getAuthenticationSelections=public java.util.List org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAuthenticationSelections(), java.lang.Object@35d7365e={public java.lang.String java.lang.Object.toString()=[Ljava.lang.Class;@421c1650, public java.lang.String org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAttemptedUsername()=[Ljava.lang.Class;@64b4ed5b, public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showTryAnotherWayLink()=[Ljava.lang.Class;@2b43c431, public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showResetCredentials()=[Ljava.lang.Class;@1d8d9735, public java.util.List org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAuthenticationSelections()=[Ljava.lang.Class;@3f01ac42, public final native java.lang.Class java.lang.Object.getClass()=[Ljava.lang.Class;@7c1c40cc, public native int java.lang.Object.hashCode()=[Ljava.lang.Class;@49cb7132, public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showUsername()=[Ljava.lang.Class;@388e7301, public boolean java.lang.Object.equals(java.lang.Object)=[Ljava.lang.Class;@adfabee}, showResetCredentials=public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showResetCredentials(), authenticationSelections=freemarker.ext.beans.FastPropertyDescriptor@14db9059, showUsername=public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showUsername(), java.lang.Object@1e65a2d1=freemarker.ext.beans.SimpleMethod@68b3111, hashCode=public native int java.lang.Object.hashCode(), equals=public boolean java.lang.Object.equals(java.lang.Object), toString=public java.lang.String java.lang.Object.toString(), showTryAnotherWayLink=public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showTryAnotherWayLink(), attemptedUsername=freemarker.ext.beans.FastPropertyDescriptor@4dd65cba, class=freemarker.ext.beans.FastPropertyDescriptor@3aa10e35, getAttemptedUsername=public java.lang.String org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAttemptedUsername()}
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.plugins.providers.StringTextStar
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.plugins.providers.StringTextStar
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) Interceptor Context: org.jboss.resteasy.core.interception.ServerWriterInterceptorContext, Method : proceed
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) WriterInterceptor: org.jboss.resteasy.security.doseta.DigitalSigningInterceptor
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.security.doseta.i18n] (default task-12) Interceptor : org.jboss.resteasy.security.doseta.DigitalSigningInterceptor, Method : aroundWriteTo
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) Interceptor Context: org.jboss.resteasy.core.interception.ServerWriterInterceptorContext, Method : proceed
2020-11-16 00:01:09,443 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
2020-11-16 00:01:09,443 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.plugins.providers.StringTextStar
2020-11-16 00:01:09,443 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper commit
2020-11-16 00:01:09,443 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper end
2020-11-16 00:01:09,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) new JtaTransactionWrapper
2020-11-16 00:01:09,803 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) was existing? false
2020-11-16 00:01:09,803 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper commit
2020-11-16 00:01:09,803 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper end
2020-11-16 00:01:09,803 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-2) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1066/40519080
2020-11-16 00:01:13,967 DEBUG [org.jboss.as.repository] (ServerService Thread Pool -- 68) Current content hash references are {48dbacb6389511c2e582d404ff6b7181c72a186d=[ContentReference{contentIdentifier=/deployment=okay-integration.ear, hexHash=48dbacb6389511c2e582d404ff6b7181c72a186d}]}
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) new JtaTransactionWrapper
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) was existing? false
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper commit
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper end
2020-11-16 00:01:14,802 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-2) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1066/40519080
2020-11-16 00:01:08,502 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] (default task-12) http-outgoing-3: Close connection
2020-11-16 00:01:08,502 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] (default task-12) Connection manager shut down
2020-11-16 00:01:08,502 INFO [org.keycloak.integration.okay.auth.push.OkayAuthenticator] (default task-12) pushNotificationState: 0
2020-11-16 00:01:08,502 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) authenticator SUCCESS: push-login-authenticator
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) Flow '2nd factor flow' successfully finished after children executions success
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) processFlow: Okay Auth
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) check execution: 'auth-username-password-form', requirement: 'REQUIRED'
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) execution 'auth-username-password-form' is processed
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) check execution: '2nd factor flow', requirement: 'REQUIRED'
2020-11-16 00:01:08,503 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) execution '2nd factor flow' is processed
2020-11-16 00:01:08,504 DEBUG [org.hibernate.SQL] (default task-12)
select
clientscop0_.ID as ID1_13_0_,
clientscop0_.DESCRIPTION as DESCRIPT2_13_0_,
clientscop0_.NAME as NAME3_13_0_,
clientscop0_.PROTOCOL as PROTOCOL4_13_0_,
clientscop0_.REALM_ID as REALM_ID5_13_0_
from
CLIENT_SCOPE clientscop0_
where
clientscop0_.ID=?
2020-11-16 00:01:08,504 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterStatement
2020-11-16 00:01:08,504 DEBUG [org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader] (default task-12) Done entity load : org.keycloak.models.jpa.entities.ClientScopeEntity#57013fda-f913-4747-921f-03c65b6393b7
2020-11-16 00:01:08,505 DEBUG [org.hibernate.SQL] (default task-12)
select
clientscop0_.ID as ID1_13_0_,
clientscop0_.DESCRIPTION as DESCRIPT2_13_0_,
clientscop0_.NAME as NAME3_13_0_,
clientscop0_.PROTOCOL as PROTOCOL4_13_0_,
clientscop0_.REALM_ID as REALM_ID5_13_0_
from
CLIENT_SCOPE clientscop0_
where
clientscop0_.ID=?
2020-11-16 00:01:08,505 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterStatement
2020-11-16 00:01:08,505 DEBUG [org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader] (default task-12) Done entity load : org.keycloak.models.jpa.entities.ClientScopeEntity#57013fda-f913-4747-921f-03c65b6393b7
2020-11-16 00:01:08,508 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-12) Removing authSession 'a47d11c3-cf1f-4104-8a07-f978b434f115'. Expire restart cookie: true
2020-11-16 00:01:08,508 DEBUG [org.keycloak.events] (default task-12) type=LOGIN, realmId=demo, clientId=keycloak-sso-client, userId=2be387f6-8e43-4d63-a761-9c6839c687e3, ipAddress=192.168.1.3, auth_method=openid-connect, auth_type=code, redirect_uri=http://192.168.1.3:3000/dashboard, consent=persistent_consent, code_id=a47d11c3-cf1f-4104-8a07-f978b434f115, username=demouser, authSessionParentId=a47d11c3-cf1f-4104-8a07-f978b434f115, authSessionTabId=eqF7xHw4YOc
2020-11-16 00:01:08,508 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) Couldnt find cookie {0}, trying {1}
2020-11-16 00:01:08,509 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-12) Create login cookie - name: KEYCLOAK_IDENTITY, path: /auth/realms/demo/, max-age: -1
2020-11-16 00:01:08,509 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-12) Expiring remember me cookie
2020-11-16 00:01:08,509 DEBUG [org.keycloak.services.managers.AuthenticationManager] (default task-12) Expiring cookie: KEYCLOAK_REMEMBER_ME path: /auth/realms/demo/
2020-11-16 00:01:08,509 DEBUG [org.keycloak.protocol.oidc.OIDCLoginProtocol] (default task-12) redirectAccessCode: state: f86d4304-ef22-4d05-8844-5459db1cd1f1
2020-11-16 00:01:08,513 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper commit
2020-11-16 00:01:08,513 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Processing flush-time cascades
2020-11-16 00:01:08,513 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Dirty checking collections
2020-11-16 00:01:08,514 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2020-11-16 00:01:08,514 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-12) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2020-11-16 00:01:08,514 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-12) Listing entities:
2020-11-16 00:01:08,514 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-12) org.keycloak.models.jpa.entities.CredentialEntity{userLabel=null, createdDate=1605463497310, salt=null, id=766185b7-f5a2-4cc6-90d8-d2859578fb0c, credentialData={"hashIterations":27500,"algorithm":"pbkdf2-sha256"}, priority=10, type=password, user=<uninitialized>, secretData={"value":"EWi6TtgMSQVwfLpwZrPuygx/ho3QUI8aFR5wIMGMmHdXqTRzAm7oXakivHO3H9BEjVt2ysQrN1u6VSPJML9tiA==","salt":"XgqicBW7KB3EqkaCqsm4Tw=="}}
2020-11-16 00:01:08,514 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterStatement
2020-11-16 00:01:08,514 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (default task-12) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2020-11-16 00:01:08,515 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-12) KeycloakDS: returnConnection(6c2f201a, false) [0/100]
2020-11-16 00:01:08,515 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-12) Initiating JDBC connection release from afterTransaction
2020-11-16 00:01:08,515 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper end
2020-11-16 00:01:09,433 DEBUG [io.undertow.request] (default I/O-1) Matched prefix path /auth for path /auth/realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,433 DEBUG [io.undertow.request.security] (default task-12) Attempting to authenticate /auth/realms/demo/protocol/openid-connect/auth, authentication required: false
2020-11-16 00:01:09,433 DEBUG [io.undertow.request.security] (default task-12) Authentication outcome was NOT_ATTEMPTED with method io.undertow.security.impl.CachedAuthenticatedSessionMechanism@7d9047fa for /auth/realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,433 DEBUG [io.undertow.request.security] (default task-12) Authentication result was ATTEMPTED for /auth/realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,433 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) new JtaTransactionWrapper
2020-11-16 00:01:09,433 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) was existing? false
2020-11-16 00:01:09,434 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) RESTEASY002315: PathInfo: /realms/demo/protocol/openid-connect/auth
2020-11-16 00:01:09,434 DEBUG [org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint] (default task-12) PKCE non-supporting Client
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) Couldnt find any cookies with name AUTH_SESSION_ID, trying AUTH_SESSION_ID_LEGACY
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the cookies field
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-12) Found AUTH_SESSION_ID cookie with value a47d11c3-cf1f-4104-8a07-f978b434f115.ubuntu
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) Couldnt find any cookies with name AUTH_SESSION_ID, trying AUTH_SESSION_ID_LEGACY
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the requests header
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.util.CookieHelper] (default task-12) {1} cookie found in the cookies field
2020-11-16 00:01:09,435 DEBUG [org.keycloak.services.managers.AuthenticationSessionManager] (default task-12) Found AUTH_SESSION_ID cookie with value a47d11c3-cf1f-4104-8a07-f978b434f115.ubuntu
2020-11-16 00:01:09,436 DEBUG [org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider] (default task-12) getUserSessionWithPredicate(a47d11c3-cf1f-4104-8a07-f978b434f115): remote cache not available
2020-11-16 00:01:09,436 DEBUG [org.keycloak.protocol.AuthorizationEndpointBase] (default task-12) Sent request to authz endpoint. We don't have root authentication session with ID 'a47d11c3-cf1f-4104-8a07-f978b434f115' but we have userSession.Re-created root authentication session with same ID. Client is: keycloak-sso-client . New authentication session tab ID: gvGKCMbZBIA
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationProcessor] (default task-12) AUTHENTICATE
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationProcessor] (default task-12) AUTHENTICATE ONLY
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) processFlow: Okay Auth
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) check execution: 'auth-username-password-form', requirement: 'REQUIRED'
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) authenticator: auth-username-password-form
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver] (default task-12) Going through the flow 'Okay Auth' for adding executions
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.AuthenticationSelectionResolver] (default task-12) Selections when trying execution 'auth-username-password-form' : [ authSelection - auth-username-password-form]
2020-11-16 00:01:09,440 DEBUG [org.keycloak.authentication.DefaultAuthenticationFlow] (default task-12) invoke authenticator.authenticate: auth-username-password-form
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) TemplateLoader.findTemplateSource("template_en_US.ftl"): Not found
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) TemplateLoader.findTemplateSource("template_en.ftl"): Not found
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) TemplateLoader.findTemplateSource("template.ftl"): Found
2020-11-16 00:01:09,441 DEBUG [freemarker.cache] (default task-12) "template.ftl"("en_US", UTF-8, parsed): using cached since file:/opt/keycloak/themes/base/login/template.ftl hasn't changed.
2020-11-16 00:01:09,442 DEBUG [freemarker.beans] (default task-12) Key "selectedCredential" was not found on instance of org.keycloak.forms.login.freemarker.model.AuthenticationContextBean. Introspection information for the class is: {getClass=public final native java.lang.Class java.lang.Object.getClass(), getAuthenticationSelections=public java.util.List org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAuthenticationSelections(), java.lang.Object@35d7365e={public java.lang.String java.lang.Object.toString()=[Ljava.lang.Class;@421c1650, public java.lang.String org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAttemptedUsername()=[Ljava.lang.Class;@64b4ed5b, public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showTryAnotherWayLink()=[Ljava.lang.Class;@2b43c431, public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showResetCredentials()=[Ljava.lang.Class;@1d8d9735, public java.util.List org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAuthenticationSelections()=[Ljava.lang.Class;@3f01ac42, public final native java.lang.Class java.lang.Object.getClass()=[Ljava.lang.Class;@7c1c40cc, public native int java.lang.Object.hashCode()=[Ljava.lang.Class;@49cb7132, public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showUsername()=[Ljava.lang.Class;@388e7301, public boolean java.lang.Object.equals(java.lang.Object)=[Ljava.lang.Class;@adfabee}, showResetCredentials=public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showResetCredentials(), authenticationSelections=freemarker.ext.beans.FastPropertyDescriptor@14db9059, showUsername=public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showUsername(), java.lang.Object@1e65a2d1=freemarker.ext.beans.SimpleMethod@68b3111, hashCode=public native int java.lang.Object.hashCode(), equals=public boolean java.lang.Object.equals(java.lang.Object), toString=public java.lang.String java.lang.Object.toString(), showTryAnotherWayLink=public boolean org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.showTryAnotherWayLink(), attemptedUsername=freemarker.ext.beans.FastPropertyDescriptor@4dd65cba, class=freemarker.ext.beans.FastPropertyDescriptor@3aa10e35, getAttemptedUsername=public java.lang.String org.keycloak.forms.login.freemarker.model.AuthenticationContextBean.getAttemptedUsername()}
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.plugins.providers.StringTextStar
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.plugins.providers.StringTextStar
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) Interceptor Context: org.jboss.resteasy.core.interception.ServerWriterInterceptorContext, Method : proceed
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) WriterInterceptor: org.jboss.resteasy.security.doseta.DigitalSigningInterceptor
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.security.doseta.i18n] (default task-12) Interceptor : org.jboss.resteasy.security.doseta.DigitalSigningInterceptor, Method : aroundWriteTo
2020-11-16 00:01:09,442 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) Interceptor Context: org.jboss.resteasy.core.interception.ServerWriterInterceptorContext, Method : proceed
2020-11-16 00:01:09,443 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
2020-11-16 00:01:09,443 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-12) MessageBodyWriter: org.jboss.resteasy.plugins.providers.StringTextStar
2020-11-16 00:01:09,443 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper commit
2020-11-16 00:01:09,443 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default task-12) JtaTransactionWrapper end
2020-11-16 00:01:09,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) new JtaTransactionWrapper
2020-11-16 00:01:09,803 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) was existing? false
2020-11-16 00:01:09,803 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper commit
2020-11-16 00:01:09,803 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper end
2020-11-16 00:01:09,803 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-2) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1066/40519080
2020-11-16 00:01:13,967 DEBUG [org.jboss.as.repository] (ServerService Thread Pool -- 68) Current content hash references are {48dbacb6389511c2e582d404ff6b7181c72a186d=[ContentReference{contentIdentifier=/deployment=okay-integration.ear, hexHash=48dbacb6389511c2e582d404ff6b7181c72a186d}]}
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) new JtaTransactionWrapper
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) was existing? false
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper commit
2020-11-16 00:01:14,802 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2) JtaTransactionWrapper end
2020-11-16 00:01:14,802 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-2) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1066/40519080
```
Reply all
Reply to author
Forward
0 new messages