4:09 a.m.
Hi All,
I'm using KeyCloack keycloak-4.8.3.Final with Java build
1.8.0_151-b12 as SAML Identity provider. My client sends signed SAML
AuthnRequests using the HTTP POST Web Browser SSO profile, and keycloack fails verifying
the siganture (different digests).
By dumping the SAMLRequest message with wireshark in the keycloack
machine and validating its signature with Oxygen 12, the signature is
fine. However keycloack has an issue verifying it, with the attached log.
This is usually a canonicalization problem. I could provide the TCPDumps
to reproduce the error.
Any idea?
Thanks a lot!
2019-02-04 17:10:38,458 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-02-04 17:10:38,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-02-04 17:10:38,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-02-04 17:10:38,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-02-04 17:10:38,459 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$783/1903918206
2019-02-04 17:10:43,458 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-02-04 17:10:43,458 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-02-04 17:10:43,458 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-02-04 17:10:43,458 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-02-04 17:10:43,458 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$783/1903918206
2019-02-04 17:10:48,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-02-04 17:10:48,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-02-04 17:10:48,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-02-04 17:10:48,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-02-04 17:10:48,459 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$783/1903918206
2019-02-04 17:10:53,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-02-04 17:10:53,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-02-04 17:10:53,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-02-04 17:10:53,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-02-04 17:10:53,460 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$783/1903918206
2019-02-04 17:10:58,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-02-04 17:10:58,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-02-04 17:10:58,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-02-04 17:10:58,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-02-04 17:10:58,460 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$783/1903918206
2019-02-04 17:10:59,520 DEBUG [io.undertow.request] (default I/O-3) Matched prefix path
/auth for path /auth/realms/master/protocol/saml
2019-02-04 17:10:59,521 DEBUG [io.undertow.request.security] (default task-97) Attempting
to authenticate /auth/realms/master/protocol/saml, authentication required: false
2019-02-04 17:10:59,521 DEBUG [io.undertow.request.security] (default task-97)
Authentication outcome was NOT_ATTEMPTED with method
io.undertow.security.impl.CachedAuthenticatedSessionMechanism@7238f9bf for
/auth/realms/master/protocol/saml
2019-02-04 17:10:59,521 DEBUG [io.undertow.request.security] (default task-97)
Authentication result was ATTEMPTED for /auth/realms/master/protocol/saml
2019-02-04 17:10:59,521 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default
task-97) new JtaTransactionWrapper
2019-02-04 17:10:59,521 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default
task-97) was existing? false
2019-02-04 17:10:59,522 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
RESTEASY002315: PathInfo: /realms/master/protocol/saml
2019-02-04 17:10:59,522 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl]
(default task-97) Hibernate RegisteredSynchronization successfully registered with JTA
platform
2019-02-04 17:10:59,523 DEBUG [org.keycloak.protocol.saml.SamlService] (default task-97)
SAML POST
2019-02-04 17:10:59,524 DEBUG [org.keycloak.saml.SAMLRequestParser] (default task-97) SAML
POST Binding
2019-02-04 17:10:59,524 DEBUG [org.keycloak.saml.SAMLRequestParser] (default task-97)
<?xml version="1.0" encoding="UTF-8"?><saml2p:AuthnRequest
xmlns:saml2p="urn:oasis:names:tc:SAML:2.0:protocol"
AssertionConsumerServiceURL="https://kv-pfg:8543/SpiritHealthPortal/SamlReceiver"
Destination="http://kv-sws:8080/auth/realms/master/protocol/saml"
ForceAuthn="true" ID="46faa8d7-fd71-4c00-8badask-97)
setElement(ds:CanonicalizationMethod, "null")
2019-02-04 17:10:59,529 DEBUG [org.apache.jcp.xml.dsig.internal.dom.ApacheCanonicalizer]
(default task-97) Created transform for algorithm:
http://www.w3.org/2001/10/xml-exc-c14n#
2019-02-04 17:10:59,529 DEBUG [org.apache.jcp.xml.dsig.internal.dom.ApacheCanonicalizer]
(default task-97) isNodeSet() = true
2019-02-04 17:10:59,529 DEBUG [org.apache.jcp.xml.dsig.internal.dom.DOMSignedInfo]
(default task-97) Canonicalized SignedInfo:
2019-02-04 17:10:59,529 DEBUG [org.apache.jcp.xml.dsig.internal.dom.DOMSignedInfo]
(default task-97) <ds:SignedInfo
xmlns:ds="http://www.w3.org/2000/09/xmldsig#"><ds:Canonic...
Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"></ds:...
Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"></...
URI="#46faa8d7-fd71-4c00-8bad-921a5bd9e5c8"><ds:Transforms><ds:Transform
Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature&quo...
Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"></ds:...
Algorithm="http://www.w3.org/2001/04/xmlenc#sha256"></ds:...
2019-02-04 17:10:59,529 DEBUG [org.apache.jcp.xml.dsig.internal.dom.DOMSignedInfo]
(default task-97) Data to be
signed/verified:PGRzOlNpZ25lZEluZm8geG1sbnM6ZHM9Imh0dHA6Ly93d3cudzMub3JnLzIwMDAvMDkveG1sZHNpZyMiPjxkczpDYW5vbmljYWxpemF0aW9uTWV0aG9kIEFsZ29yaXRobT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS8xMC94bWwtZXhjLWMxNG4jIj48L2RzOkNhbm9uaWNhbGl6YXRpb25NZXRob2Q+PGRzOlNpZ25hdHVyZU1ldGhvZCBBbGdvcml0aG09Imh0dHA6Ly93d3cudzMub3JnLzIwMDAvMDkveG1sZHNpZyNyc2Etc2hhMSI+PC9kczpTaWduYXR1cmVNZXRob2Q+PGRzOlJlZmVyZW5jZSBVUkk9IiM0NmZhYThkNy1mZDcxLTRjMDAtOGJhZC05MjFhNWJkOWU1YzgiPjxkczpUcmFuc2Zvcm1zPjxkczpUcmFuc2Zvcm0gQWxnb3JpdGhtPSJodHRwOi8vd3d3LnczLm9yZy8yMDAwLzA5L3htbGRzaWcjZW52ZWxvcGVkLXNpZ25hdHVyZSI+PC9kczpUcmFuc2Zvcm0+PGRzOlRyYW5zZm9ybSBBbGdvcml0aG09Imh0dHA6Ly93d3cudzMub3JnLzIwMDEvMTAveG1sLWV4Yy1jMTRuIyI+PC9kczpUcmFuc2Zvcm0+PC9kczpUcmFuc2Zvcm1zPjxkczpEaWdlc3RNZXRob2QgQWxnb3JpdGhtPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGVuYyNzaGEyNTYiPjwvZHM6RGlnZXN0TWV0aG9kPjxkczpEaWdlc3RWYWx1ZT5iY0FJRnJRNklZd2FrMXRGOU1RZ2NveEJGbTVwV3krMHhKeGx0MEM4bXpVPTwvZHM6RGlnZXN0VmFsdWU+PC9kczpSZWZlcmVuY2U+PC9kczpTaWduZWRJbmZvPg==
2019-02-04 17:10:59,530 ERROR [org.keycloak.protocol.saml.SamlService] (default task-97)
request validation failed: org.keycloak.common.VerificationException: Invalid signature on
document
at
org.keycloak.protocol.saml.SamlProtocolUtils.verifyDocumentSignature(SamlProtocolUtils.java:83)
at
org.keycloak.protocol.saml.SamlProtocolUtils.verifyDocumentSignature(SamlProtocolUtils.java:68)
at
org.keycloak.protocol.saml.SamlService$PostBindingProtocol.verifySignature(SamlService.java:501)
at
org.keycloak.protocol.saml.SamlService$BindingProtocol.handleSamlRequest(SamlService.java:244)
at
org.keycloak.protocol.saml.SamlService$BindingProtocol.execute(SamlService.java:491)
at org.keycloak.protocol.saml.SamlService.postBinding(SamlService.java:581)
at sun.reflect.GeneratedMethodAccessor871.invoke(Unknown Source)
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:140)
at
org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:509)
at
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:399)
at
org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$0(ResourceMethodInvoker.java:363)
at
org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:365)
at
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:337)
at
org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:137)
at
org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:100)
at
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:443)
at
org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:233)
at
org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:139)
at
org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
at
org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:142)
at
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:219)
at
org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:227)
at
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
at
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at
io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at
org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:90)
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.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:292)
at
io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
at
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
at
io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
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:1502)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
at
org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
at
io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
at
io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
at
io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360)
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:1985)
at
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487)
at
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378)
at java.lang.Thread.run(Thread.java:748)
2019-02-04 17:10:59,531 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener]
(default task-97) Generated identifier: d4e07837-2fa9-4a74-9971-5847bbe24e88, using
strategy: org.hibernate.id.Assigned
2019-02-04 17:10:59,532 WARN [org.keycloak.events] (default task-97) type=LOGIN_ERROR,
realmId=master, clientId=null, userId=null, ipAddress=10.10.10.54,
error=invalid_signature
2019-02-04 17:10:59,532 DEBUG [freemarker.cache] (default task-97) Couldn't find
template in cache for "error.ftl"("en_US", UTF-8, parsed); will try to
load it.
2019-02-04 17:10:59,532 DEBUG [freemarker.cache] (default task-97)
TemplateLoader.findTemplateSource("error_en_US.ftl"): Not found
2019-02-04 17:10:59,532 DEBUG [freemarker.cache] (default task-97)
TemplateLoader.findTemplateSource("error_en.ftl"): Not found
2019-02-04 17:10:59,532 DEBUG [freemarker.cache] (default task-97)
TemplateLoader.findTemplateSource("error.ftl"): Found
2019-02-04 17:10:59,532 DEBUG [freemarker.cache] (default task-97) Loading template for
"error.ftl"("en_US", UTF-8, parsed) from
"file:/opt/keycloak/themes/base/login/error.ftl"
2019-02-04 17:10:59,533 DEBUG [freemarker.cache] (default task-97) Couldn't find
template in cache for "template.ftl"("en_US", UTF-8, parsed); will try
to load it.
2019-02-04 17:10:59,534 DEBUG [freemarker.cache] (default task-97)
TemplateLoader.findTemplateSource("template_en_US.ftl"): Not found
2019-02-04 17:10:59,534 DEBUG [freemarker.cache] (default task-97)
TemplateLoader.findTemplateSource("template_en.ftl"): Not found
2019-02-04 17:10:59,534 DEBUG [freemarker.cache] (default task-97)
TemplateLoader.findTemplateSource("template.ftl"): Found
2019-02-04 17:10:59,534 DEBUG [freemarker.cache] (default task-97) Loading template for
"template.ftl"("en_US", UTF-8, parsed) from
"file:/opt/keycloak/themes/base/login/template.ftl"
2019-02-04 17:10:59,538 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default
task-97) JtaTransactionWrapper commit
2019-02-04 17:10:59,538 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener]
(default task-97) Processing flush-time cascades
2019-02-04 17:10:59,538 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener]
(default task-97) Dirty checking collections
2019-02-04 17:10:59,538 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener]
(default task-97) Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects
2019-02-04 17:10:59,538 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener]
(default task-97) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2019-02-04 17:10:59,538 DEBUG [org.hibernate.internal.util.EntityPrinter] (default
task-97) Listing entities:
2019-02-04 17:10:59,538 DEBUG [org.hibernate.internal.util.EntityPrinter] (default
task-97) org.keycloak.events.jpa.EventEntity{clientId=null, realmId=master,
ipAddress=10.10.10.54, id=d4e07837-2fa9-4a74-9971-5847bbe24e88, sessionId=null,
time=1549296659531, error=invalid_signature, type=LOGIN_ERROR, userId=null,
detailsJson=null}
2019-02-04 17:10:59,539 DEBUG [org.hibernate.SQL] (default task-97)
insert
into
EVENT_ENTITY
(CLIENT_ID, DETAILS_JSON, ERROR, IP_ADDRESS, REALM_ID, SESSION_ID, EVENT_TIME,
TYPE, USER_ID, ID)
values
(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2019-02-04 17:10:59,539 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool]
(default task-97) KeycloakDS: getConnection(null,
WrappedConnectionRequestInfo@2116b544[userName=keycloak]) [0/15]
2019-02-04 17:10:59,544 DEBUG [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl]
(default task-97) Skipping aggressive release due to manual disabling
2019-02-04 17:10:59,544 DEBUG
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-97)
Initiating JDBC connection release from afterStatement
2019-02-04 17:10:59,546 DEBUG
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-97)
Initiating JDBC connection release from afterTransaction
2019-02-04 17:10:59,546 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool]
(default task-97) KeycloakDS: returnConnection(27223045, false) [0/15]
2019-02-04 17:10:59,547 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (default
task-97) JtaTransactionWrapper end
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
MessageBodyWriter: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
MessageBodyWriter: org.jboss.resteasy.plugins.providers.ByteArrayProvider
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
MessageBodyWriter: org.jboss.resteasy.plugins.providers.ByteArrayProvider
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
Interceptor Context: org.jboss.resteasy.core.interception.ServerWriterInterceptorContext,
Method : proceed
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
WriterInterceptor: org.jboss.resteasy.security.doseta.DigitalSigningInterceptor
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.security.doseta.i18n] (default task-97)
Interceptor : org.jboss.resteasy.security.doseta.DigitalSigningInterceptor, Method :
aroundWriteTo
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
Interceptor Context: org.jboss.resteasy.core.interception.ServerWriterInterceptorContext,
Method : proceed
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
MessageBodyWriter: org.jboss.resteasy.spi.ResteasyProviderFactory$SortedKey
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
MessageBodyWriter: org.jboss.resteasy.plugins.providers.ByteArrayProvider
2019-02-04 17:10:59,547 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n] (default task-97)
Provider : org.jboss.resteasy.plugins.providers.ByteArrayProvider, Method : writeTo
2019-02-04 17:11:03,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-02-04 17:11:03,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-02-04 17:11:03,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-02-04 17:11:03,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-02-04 17:11:03,459 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$783/1903918206
2019-02-04 17:11:08,459 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
new JtaTransactionWrapper
2019-02-04 17:11:08,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
was existing? false
2019-02-04 17:11:08,460 DEBUG
[org.keycloak.models.sessions.infinispan.changes.sessions.PersisterLastSessionRefreshStore]
(Timer-2) Updating 0 userSessions with lastSessionRefresh: 1549296608
2019-02-04 17:11:08,460 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl]
(Timer-2) Hibernate RegisteredSynchronization successfully registered with JTA platform
2019-02-04 17:11:08,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper commit
2019-02-04 17:11:08,460 DEBUG
[org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (Timer-2) Initiating
JDBC connection release from afterTransaction
2019-02-04 17:11:08,460 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-2)
JtaTransactionWrapper end
2019-02-04 17:11:08,460 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner]
(Timer-2) Executed scheduled task
AbstractLastSessionRefreshStoreFactory$$Lambda$783/1903918206