[keycloak-user] Two OIDC working, but not SSO

Tech tech at psynd.net
Tue Apr 25 06:31:18 EDT 2017 

Dear experts,

we are working with Moodle, a PHP based platform, where we have been 
able to configure correctly Keycloak to implement OIDC.

To test Keycloak we cloned this application, with different URLs and we 
did the first test:

  * Connect to portal1
  * User not recognized and redirected to Keycloak through OIDC
  * Enter credentials stored into Keycloak
  * User accepted and redirected to portal1
  * Logout from portal1

After this we tested the second application:

  * Connect to portal2
  * User not recognized and redirected to Keycloak through OIDC
  * Enter credentials stored into Keycloak
  * User accepted and redirected to portal2
  * Logout from portal2

In this case I know that OIDC is working for the two applications and we 
can expect that also the SSO is working, but after the login in portal1 
we have to login again portal2, and vice-versa.

We attach below here some logs, could you please help?

Thanks





*Login to portal1*

2017-04-25 09:54:40,503 DEBUG [org.jboss.ejb.client.txn] (Periodic 
Recovery) Send recover request for transaction origin node identifier 1 
to EJB receiver with node name 79051ccf69ac
2017-04-25 09:54:45,055 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-30) new 
JtaTransactionWrapper
2017-04-25 09:54:45,056 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-30) was 
existing? false
2017-04-25 09:54:45,056 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] 
(default task-30) RESTEASY002315: PathInfo: 
/realms/demo/protocol/openid-connect/auth
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-30) 
AUTHENTICATE
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-30) 
AUTHENTICATE ONLY
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) processFlow
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) check execution: auth-cookie requirement: ALTERNATIVE
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) authenticator: auth-cookie
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) invoke authenticator.authenticate
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-30) 
Could not find cookie: KEYCLOAK_IDENTITY
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) authenticator ATTEMPTED: auth-cookie
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) check execution: auth-spnego requirement: DISABLED
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) execution is processed
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) check execution: identity-provider-redirector requirement: 
ALTERNATIVE
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) authenticator: identity-provider-redirector
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) invoke authenticator.authenticate
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) authenticator ATTEMPTED: identity-provider-redirector
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) check execution: null requirement: ALTERNATIVE
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) execution is flow
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) processFlow
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) check execution: auth-username-password-form requirement: REQUIRED
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) authenticator: auth-username-password-form
2017-04-25 09:54:45,059 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) invoke authenticator.authenticate
2017-04-25 09:54:45,060 DEBUG [freemarker.cache] (default task-30) 
TemplateLoader.findTemplateSource("template_en_US.ftl"): Not found
2017-04-25 09:54:45,060 DEBUG [freemarker.cache] (default task-30) 
TemplateLoader.findTemplateSource("template_en.ftl"): Not found
2017-04-25 09:54:45,060 DEBUG [freemarker.cache] (default task-30) 
TemplateLoader.findTemplateSource("template.ftl"): Found
2017-04-25 09:54:45,061 DEBUG [freemarker.cache] (default task-30) 
"template.ftl"("en_US", UTF-8, parsed): using cached since 
file:/opt/jboss/keycloak/themes/base/login/template.ftl hasn't changed.
2017-04-25 09:54:45,064 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-30) authenticator CHALLENGE: auth-username-password-form
2017-04-25 09:54:45,064 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-30) 
JtaTransactionWrapper  commit
2017-04-25 09:54:45,064 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-30) 
JtaTransactionWrapper end
2017-04-25 09:54:50,503 DEBUG [org.jboss.ejb.client.txn] (Periodic 
Recovery) Send recover request for transaction origin node identifier 1 
to EJB receiver with node name 79051ccf69ac




*After authentication to portal1**
*
2017-04-25 09:54:56,041 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-31) new 
JtaTransactionWrapper
2017-04-25 09:54:56,041 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-31) was 
existing? false
2017-04-25 09:54:56,042 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] 
(default task-31) RESTEASY002315: PathInfo: 
/realms/Demo/login-actions/authenticate
2017-04-25 09:54:56,042 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-31) 
authenticationAction
2017-04-25 09:54:56,042 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) processAction: dfde24fe-5e06-4dc9-8dc2-f82eedd89846
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) check: auth-cookie requirement: ALTERNATIVE
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) execution is processed
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) check: auth-spnego requirement: DISABLED
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) execution is processed
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) check: identity-provider-redirector requirement: ALTERNATIVE
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) execution is processed
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) check: null requirement: ALTERNATIVE
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) processAction: dfde24fe-5e06-4dc9-8dc2-f82eedd89846
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) check: auth-username-password-form requirement: REQUIRED
2017-04-25 09:54:56,043 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) action: auth-username-password-form
2017-04-25 09:54:56,141 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) authenticator SUCCESS: auth-username-password-form
2017-04-25 09:54:56,141 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) processFlow
2017-04-25 09:54:56,141 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) check execution: auth-otp-form requirement: OPTIONAL
2017-04-25 09:54:56,141 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) authenticator: auth-otp-form
2017-04-25 09:54:56,141 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default 
task-31) processFlow
2017-04-25 09:54:56,141 DEBUG 
[org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] 
(default task-31) Hibernate RegisteredSynchronization successfully 
registered with JTA platform
2017-04-25 09:54:56,142 DEBUG [org.hibernate.SQL] (default task-31)
     select
         roleentity0_.ID as col_0_0_
     from
         KEYCLOAK_ROLE roleentity0_
     where
         roleentity0_.CLIENT_ROLE=0
         and roleentity0_.NAME=?
         and roleentity0_.REALM=?
2017-04-25 09:54:56,142 DEBUG 
[org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default 
task-31) MySqlDS: getConnection(null, 
WrappedConnectionRequestInfo at 4570d800[userName=KeycloakUSR]) [0/20]
2017-04-25 09:54:56,143 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-31) Initiating JDBC connection release from afterStatement
2017-04-25 09:54:56,143 DEBUG [org.hibernate.SQL] (default task-31)
     select
         roleentity0_.ID as col_0_0_
     from
         KEYCLOAK_ROLE roleentity0_
     where
         roleentity0_.CLIENT_ROLE=0
         and roleentity0_.NAME=?
         and roleentity0_.REALM=?
2017-04-25 09:54:56,144 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-31) Initiating JDBC connection release from afterStatement
2017-04-25 09:54:56,144 DEBUG [org.hibernate.SQL] (default task-31)
     select
         roleentity0_.ID as col_0_0_
     from
         KEYCLOAK_ROLE roleentity0_
     where
         roleentity0_.CLIENT_ROLE=0
         and roleentity0_.NAME=?
         and roleentity0_.REALM=?
2017-04-25 09:54:56,144 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-31) Initiating JDBC connection release from afterStatement
2017-04-25 09:54:56,145 DEBUG [org.keycloak.events] (default task-31) 
type=LOGIN, realmId=Demo, clientId=moodle, 
userId=ed5ba52a-531d-4e6e-b12e-9bc0957a8c1f, ipAddress=192.168.0.27, 
auth_method=openid-connect, auth_type=code, 
redirect_uri=https://localhost/moodleiam/auth/oidc/, 
consent=no_consent_required, 
code_id=08539f13-cb1c-423e-86a3-365c29b055f1, username=testuser
2017-04-25 09:54:56,145 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-31) 
Removing old user session: session: 9a5218f8-aa9c-496c-aa00-780430f19c1b
2017-04-25 09:54:56,145 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-31) 
Create login cookie - name: KEYCLOAK_IDENTITY, path: /auth/realms/Demo, 
max-age: -1
2017-04-25 09:54:56,145 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-31) 
Expiring remember me cookie
2017-04-25 09:54:56,145 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-31) 
Expiring cookie: KEYCLOAK_REMEMBER_ME path: /auth/realms/Demo
2017-04-25 09:54:56,146 DEBUG 
[org.keycloak.protocol.oidc.OIDCLoginProtocol] (default task-31) 
redirectAccessCode: state: bIJNAcPb8Rxz8Wb
2017-04-25 09:54:56,146 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-31) 
JtaTransactionWrapper  commit
2017-04-25 09:54:56,149 DEBUG 
[org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default 
task-31) MySqlDS: returnConnection(4edba62b, false) [0/20]
2017-04-25 09:54:56,149 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-31) Initiating JDBC connection release from afterTransaction
2017-04-25 09:54:56,149 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-31) 
JtaTransactionWrapper end
2017-04-25 09:54:56,642 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-24) new 
JtaTransactionWrapper
2017-04-25 09:54:56,642 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-24) was 
existing? false
2017-04-25 09:54:56,642 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] 
(default task-24) RESTEASY002315: PathInfo: 
/realms/demo/protocol/openid-connect/token
2017-04-25 09:54:56,643 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-24) 
AUTHENTICATE CLIENT
2017-04-25 09:54:56,643 DEBUG 
[org.keycloak.authentication.ClientAuthenticationFlow] (default task-24) 
client authenticator: client-secret
2017-04-25 09:54:56,643 DEBUG 
[org.keycloak.authentication.ClientAuthenticationFlow] (default task-24) 
client authenticator SUCCESS: client-secret
2017-04-25 09:54:56,643 DEBUG 
[org.keycloak.authentication.ClientAuthenticationFlow] (default task-24) 
Client moodle authenticated by client-secret
2017-04-25 09:54:56,663 DEBUG [org.keycloak.events] (default task-24) 
type=CODE_TO_TOKEN, realmId=Demo, clientId=moodle, 
userId=ed5ba52a-531d-4e6e-b12e-9bc0957a8c1f, ipAddress=153.109.152.213, 
token_id=75173922-dd56-44ca-9255-9a5368e557f4, 
grant_type=authorization_code, refresh_token_type=Refresh, 
refresh_token_id=d7daabe5-8e73-4b8e-b108-92188e1118df, 
code_id=08539f13-cb1c-423e-86a3-365c29b055f1, 
client_auth_method=client-secret
2017-04-25 09:54:56,663 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-24) 
JtaTransactionWrapper  commit
2017-04-25 09:54:56,663 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-24) 
JtaTransactionWrapper end




*Login to portal2**
*
2017-04-25 09:56:17,566 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-6) new 
JtaTransactionWrapper
2017-04-25 09:56:17,566 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-6) was 
existing? false
2017-04-25 09:56:17,567 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] 
(default task-6) RESTEASY002315: PathInfo: 
/realms/demo/protocol/openid-connect/auth
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-6) 
AUTHENTICATE
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-6) 
AUTHENTICATE ONLY
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
processFlow
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
check execution: auth-cookie requirement: ALTERNATIVE
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
authenticator: auth-cookie
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
invoke authenticator.authenticate
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-6) 
Could not find cookie: KEYCLOAK_IDENTITY
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
authenticator ATTEMPTED: auth-cookie
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
check execution: auth-spnego requirement: DISABLED
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
execution is processed
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
check execution: identity-provider-redirector requirement: ALTERNATIVE
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
authenticator: identity-provider-redirector
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
invoke authenticator.authenticate
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
authenticator ATTEMPTED: identity-provider-redirector
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
check execution: null requirement: ALTERNATIVE
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
execution is flow
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
processFlow
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
check execution: auth-username-password-form requirement: REQUIRED
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
authenticator: auth-username-password-form
2017-04-25 09:56:17,569 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
invoke authenticator.authenticate
2017-04-25 09:56:17,572 DEBUG [freemarker.cache] (default task-6) 
TemplateLoader.findTemplateSource("template_en_US.ftl"): Not found
2017-04-25 09:56:17,572 DEBUG [freemarker.cache] (default task-6) 
TemplateLoader.findTemplateSource("template_en.ftl"): Not found
2017-04-25 09:56:17,572 DEBUG [freemarker.cache] (default task-6) 
TemplateLoader.findTemplateSource("template.ftl"): Found
2017-04-25 09:56:17,572 DEBUG [freemarker.cache] (default task-6) 
"template.ftl"("en_US", UTF-8, parsed): using cached since 
file:/opt/jboss/keycloak/themes/base/login/template.ftl hasn't changed.
2017-04-25 09:56:17,573 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-6) 
authenticator CHALLENGE: auth-username-password-form
2017-04-25 09:56:17,573 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-6) 
JtaTransactionWrapper  commit
2017-04-25 09:56:17,573 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-6) 
JtaTransactionWrapper end




*After authentication to portal2**
*
2017-04-25 09:56:29,001 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-4) new 
JtaTransactionWrapper
2017-04-25 09:56:29,001 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-4) was 
existing? false
2017-04-25 09:56:29,001 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] 
(default task-4) RESTEASY002315: PathInfo: 
/realms/Demo/login-actions/authenticate
2017-04-25 09:56:29,002 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-4) 
authenticationAction
2017-04-25 09:56:29,002 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
processAction: dfde24fe-5e06-4dc9-8dc2-f82eedd89846
2017-04-25 09:56:29,002 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
check: auth-cookie requirement: ALTERNATIVE
2017-04-25 09:56:29,002 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
execution is processed
2017-04-25 09:56:29,002 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
check: auth-spnego requirement: DISABLED
2017-04-25 09:56:29,002 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
execution is processed
2017-04-25 09:56:29,004 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
check: identity-provider-redirector requirement: ALTERNATIVE
2017-04-25 09:56:29,004 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
execution is processed
2017-04-25 09:56:29,004 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
check: null requirement: ALTERNATIVE
2017-04-25 09:56:29,004 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
processAction: dfde24fe-5e06-4dc9-8dc2-f82eedd89846
2017-04-25 09:56:29,004 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
check: auth-username-password-form requirement: REQUIRED
2017-04-25 09:56:29,004 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
action: auth-username-password-form
2017-04-25 09:56:29,099 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
authenticator SUCCESS: auth-username-password-form
2017-04-25 09:56:29,100 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
processFlow
2017-04-25 09:56:29,100 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
check execution: auth-otp-form requirement: OPTIONAL
2017-04-25 09:56:29,100 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
authenticator: auth-otp-form
2017-04-25 09:56:29,100 DEBUG 
[org.keycloak.authentication.DefaultAuthenticationFlow] (default task-4) 
processFlow
2017-04-25 09:56:29,100 DEBUG 
[org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] 
(default task-4) Hibernate RegisteredSynchronization successfully 
registered with JTA platform
2017-04-25 09:56:29,100 DEBUG [org.hibernate.SQL] (default task-4)
     select
         roleentity0_.ID as col_0_0_
     from
         KEYCLOAK_ROLE roleentity0_
     where
         roleentity0_.CLIENT_ROLE=0
         and roleentity0_.NAME=?
         and roleentity0_.REALM=?
2017-04-25 09:56:29,101 DEBUG 
[org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default 
task-4) MySqlDS: getConnection(null, 
WrappedConnectionRequestInfo at 4570d800[userName=KeycloakUSR]) [0/20]
2017-04-25 09:56:29,102 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-4) Initiating JDBC connection release from afterStatement
2017-04-25 09:56:29,103 DEBUG [org.hibernate.SQL] (default task-4)
     select
         roleentity0_.ID as col_0_0_
     from
         KEYCLOAK_ROLE roleentity0_
     where
         roleentity0_.CLIENT_ROLE=0
         and roleentity0_.NAME=?
         and roleentity0_.REALM=?
2017-04-25 09:56:29,103 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-4) Initiating JDBC connection release from afterStatement
2017-04-25 09:56:29,103 DEBUG [org.hibernate.SQL] (default task-4)
     select
         roleentity0_.ID as col_0_0_
     from
         KEYCLOAK_ROLE roleentity0_
     where
         roleentity0_.CLIENT_ROLE=0
         and roleentity0_.NAME=?
         and roleentity0_.REALM=?
2017-04-25 09:56:29,104 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-4) Initiating JDBC connection release from afterStatement
2017-04-25 09:56:29,104 DEBUG [org.keycloak.events] (default task-4) 
type=LOGIN, realmId=Demo, clientId=moodle2, 
userId=ed5ba52a-531d-4e6e-b12e-9bc0957a8c1f, ipAddress=192.168.0.27, 
auth_method=openid-connect, auth_type=code, 
redirect_uri=https://localhost/moodle2iam/auth/oidc/, 
consent=no_consent_required, 
code_id=cffeac69-54fc-4d19-be81-36f0f19ce1ef, username=testuser
2017-04-25 09:56:29,104 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-4) 
Removing old user session: session: 431cecf6-5a6b-4bbc-9467-3f52eff8090f
2017-04-25 09:56:29,105 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-4) 
Create login cookie - name: KEYCLOAK_IDENTITY, path: /auth/realms/Demo, 
max-age: -1
2017-04-25 09:56:29,105 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-4) 
Expiring remember me cookie
2017-04-25 09:56:29,105 DEBUG 
[org.keycloak.services.managers.AuthenticationManager] (default task-4) 
Expiring cookie: KEYCLOAK_REMEMBER_ME path: /auth/realms/Demo
2017-04-25 09:56:29,105 DEBUG 
[org.keycloak.protocol.oidc.OIDCLoginProtocol] (default task-4) 
redirectAccessCode: state: WUCTMXokISFDbFN
2017-04-25 09:56:29,105 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-4) 
JtaTransactionWrapper  commit
2017-04-25 09:56:29,106 DEBUG 
[org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default 
task-4) MySqlDS: returnConnection(4edba62b, false) [0/20]
2017-04-25 09:56:29,106 DEBUG 
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] 
(default task-4) Initiating JDBC connection release from afterTransaction
2017-04-25 09:56:29,106 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-4) 
JtaTransactionWrapper end
2017-04-25 09:56:29,626 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-13) new 
JtaTransactionWrapper
2017-04-25 09:56:29,626 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-13) was 
existing? false
2017-04-25 09:56:29,627 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] 
(default task-13) RESTEASY002315: PathInfo: 
/realms/demo/protocol/openid-connect/token
2017-04-25 09:56:29,627 DEBUG 
[org.keycloak.authentication.AuthenticationProcessor] (default task-13) 
AUTHENTICATE CLIENT
2017-04-25 09:56:29,627 DEBUG 
[org.keycloak.authentication.ClientAuthenticationFlow] (default task-13) 
client authenticator: client-secret
2017-04-25 09:56:29,627 DEBUG 
[org.keycloak.authentication.ClientAuthenticationFlow] (default task-13) 
client authenticator SUCCESS: client-secret
2017-04-25 09:56:29,627 DEBUG 
[org.keycloak.authentication.ClientAuthenticationFlow] (default task-13) 
Client moodle2 authenticated by client-secret
2017-04-25 09:56:29,656 DEBUG [org.keycloak.events] (default task-13) 
type=CODE_TO_TOKEN, realmId=Demo, clientId=moodle2, 
userId=ed5ba52a-531d-4e6e-b12e-9bc0957a8c1f, ipAddress=153.109.152.213, 
token_id=ff9b3385-1362-4559-ad53-05317755b280, 
grant_type=authorization_code, refresh_token_type=Refresh, 
refresh_token_id=356011d7-e9fa-4c90-9368-a7627a445bc7, 
code_id=cffeac69-54fc-4d19-be81-36f0f19ce1ef, 
client_auth_method=client-secret
2017-04-25 09:56:29,656 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-13) 
JtaTransactionWrapper  commit
2017-04-25 09:56:29,656 DEBUG 
[org.keycloak.transaction.JtaTransactionWrapper] (default task-13) 
JtaTransactionWrapper end
2017-04-25 09:56:29,660 DEBUG [io.undertow.request.io] (default I/O-1) 
Error reading request: java.io.IOException: Connection reset by peer
         at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
         at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
         at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
         at sun.nio.ch.IOUtil.read(IOUtil.java:192)
         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
         at org.xnio.nio.NioSocketConduit.read(NioSocketConduit.java:282)
         at 
io.undertow.protocols.ssl.SslConduit.doUnwrap(SslConduit.java:658)
         at io.undertow.protocols.ssl.SslConduit.read(SslConduit.java:530)
         at 
org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127)
         at 
io.undertow.server.protocol.http.HttpReadListener.handleEventWithNoRunningRequest(HttpReadListener.java:152)
         at 
io.undertow.server.protocol.http.HttpReadListener.handleEvent(HttpReadListener.java:130)
         at 
io.undertow.server.protocol.http.HttpReadListener.handleEvent(HttpReadListener.java:56)
         at 
org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
         at 
org.xnio.conduits.ReadReadyHandler$ChannelListenerHandler.readReady(ReadReadyHandler.java:66)
         at 
io.undertow.protocols.ssl.SslConduit$SslReadReadyHandler.readReady(SslConduit.java:1059)
         at 
org.xnio.nio.NioSocketConduit.handleReady(NioSocketConduit.java:88)
         at org.xnio.nio.WorkerThread.run(WorkerThread.java:559)

More information about the keycloak-user mailing list