Hi, still trying to implement saml to work seamlesly with Google workspace as IDP.
Saml is now working mostly as expected. But it acts strange sometimes.
It will log some users normally. But after while it happens that it wont log user for no reason again. Next day it works again just fine. This is error log which appears if user is not logged.
qtp515715487-2761] com.haulmont.addon.saml.saml.authentication.SamlAuthenticationFailureHandler - Failed to login by saml
org.springframework.security.authentication.AuthenticationServiceException: Error validating SAML message
at org.springframework.security.saml.SAMLAuthenticationProvider.authenticate(SAMLAuthenticationProvider.java:101) ~[shared/:na]
at org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:174) ~[shared/:na]
at org.springframework.security.saml.SAMLProcessingFilter.attemptAuthentication(SAMLProcessingFilter.java:92) ~[shared/:na]
at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:212) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:66) ~[shared/:na]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56) ~[shared/:na]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177) ~[shared/:na]
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358) ~[shared/:na]
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271) ~[shared/:na]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634) ~[app.jar:na]
at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:108) ~[shared/:na]
at com.haulmont.addon.saml.web.security.saml.SamlLoginHttpRequestFilter.doFilter(SamlLoginHttpRequestFilter.java:81) ~[classes/:na]
at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113) ~[shared/:na]
at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:74) ~[shared/:na]
at com.haulmont.cuba.web.sys.CubaHttpFilter.doFilter(CubaHttpFilter.java:93) ~[classes/:na]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642) ~[app.jar:na]
at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:228) ~[app.jar:na]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:572) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[app.jar:na]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[app.jar:na]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[app.jar:na]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1612) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) ~[app.jar:na]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1582) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[app.jar:na]
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[app.jar:na]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[app.jar:na]
at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[app.jar:na]
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[app.jar:na]
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) ~[app.jar:na]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) ~[app.jar:na]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) ~[app.jar:na]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[app.jar:na]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[app.jar:na]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:540) ~[app.jar:na]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:395) ~[app.jar:na]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161) ~[app.jar:na]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[app.jar:na]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[app.jar:na]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) ~[app.jar:na]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773) ~[app.jar:na]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905) ~[app.jar:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: org.opensaml.common.SAMLException: Response doesn't have any valid assertion which would pass subject validation
at org.springframework.security.saml.websso.WebSSOProfileConsumerImpl.processAuthenticationResponse(WebSSOProfileConsumerImpl.java:265) ~[shared/:na]
at org.springframework.security.saml.SAMLAuthenticationProvider.authenticate(SAMLAuthenticationProvider.java:88) ~[shared/:na
The log message is very similar to the one you have provided in your recent post, where i proposed to increase cuba.addon.saml.maxAuthenticationAgeSec property value. Considering that the problem reproduces only occasionally, it is very likely to be a solution.
The problem can also be related to incorrect entityId configuration.
Make sure that entityId in SAML Connection:
is the same as the one specified in SP configuration in IdP.
@shalyganov problem is that this error sometime appears sometime not. For example. I just made small change in app and deployed, no app is throwing this error in log and wont log me in with same user it did correctly log me before.
Also some userrs experience that app is normally logging them in half day and wont log second half. Next day app logs them just fine.
It seems to me that some king of temporary credential sorage (i dont know if it exist) stores user credentials an after some time it is full and probably wont accept more, or …
@shalyganov also, just to mention. Another SAML apps using Google as IDP in our domain and they are not affected by same problem, so i guess it must be internal misconfiguration or some bug in cuba which i´d like to address before setting SAML for rest of our cuba apps.
@shalyganov Hi, i was doing some research regarding saml. IDP (Google) was double-checked that it is not misconfigured.
Yet, i still see issue as i mentioned before. Few aditional info is that.
If i regurally open app, it is not logging of automatically.
If i only visit page for example once a day. App is loggedout and cuba throws exception as i mentioned before.
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.ws.message.decoder.BaseMessageDecoder - Evaluating security policy of type 'org.opensaml.ws.security.provider.BasicSecurityPolicy' for decoded message
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule - Evaluating simple signature rule of type: org.opensaml.saml2.binding.security.SAML2HTTPPostSimpleSignRule
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule - HTTP request was not signed via simple signature mechanism, skipping
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.security.SAMLSignatureProfileValidator - Saw Enveloped signature transform
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.security.SAMLSignatureProfileValidator - Saw Exclusive C14N signature transform
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule - Attempting to verify signature on signed SAML protocol message using context issuer message type: {urn:oasis:names:tc:SAML:2.0:protocol}Response
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.security.MetadataCredentialResolver - Forcing on-demand metadata provider refresh if necessary
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.security.MetadataCredentialResolver - Attempting to retrieve credentials from cache using index: [https://accounts.google.com/o/saml2?idpid=C045ag7y5,{urn:oasis:names:tc:SAML:2.0:metadata}IDPSSODescriptor,urn:oasis:names:tc:SAML:2.0:protocol,SIGNING]
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.security.MetadataCredentialResolver - Unable to retrieve credentials from cache using index: [https://accounts.google.com/o/saml2?idpid=C045ag7y5,{urn:oasis:names:tc:SAML:2.0:metadata}IDPSSODescriptor,urn:oasis:names:tc:SAML:2.0:protocol,SIGNING]
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.security.MetadataCredentialResolver - Attempting to retrieve credentials from metadata for entity: https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.security.MetadataCredentialResolver - Retrieving metadata for entity 'https://accounts.google.com/o/saml2?idpid=C045ag7y5' in role '{urn:oasis:names:tc:SAML:2.0:metadata}IDPSSODescriptor' for protocol 'urn:oasis:names:tc:SAML:2.0:protocol'
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.saml2.metadata.provider.ChainingMetadataProvider - Checking child metadata provider for entity descriptor with entity ID: https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.saml2.metadata.provider.AbstractMetadataProvider - Searching for entity descriptor with an entity ID of https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.saml2.metadata.provider.AbstractMetadataProvider - Metadata document did not contain a descriptor for entity https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.saml2.metadata.provider.AbstractMetadataProvider - Metadata document did not contain any role descriptors of type {urn:oasis:names:tc:SAML:2.0:metadata}IDPSSODescriptor for entity https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.saml2.metadata.provider.AbstractMetadataProvider - Metadata document does not contain a role of type {urn:oasis:names:tc:SAML:2.0:metadata}IDPSSODescriptor supporting protocol urn:oasis:names:tc:SAML:2.0:protocol for entity https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.saml2.metadata.provider.ChainingMetadataProvider - Checking child metadata provider for entity descriptor with entity ID: https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.saml2.metadata.provider.AbstractMetadataProvider - Searching for entity descriptor with an entity ID of https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Found 0 key names: []
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Processing KeyInfo child with qname: {http://www.w3.org/2000/09/xmldsig#}X509Data
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Provider org.opensaml.xml.security.keyinfo.provider.RSAKeyValueProvider doesn't handle objects of type {http://www.w3.org/2000/09/xmldsig#}X509Data, skipping
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Provider org.opensaml.xml.security.keyinfo.provider.DSAKeyValueProvider doesn't handle objects of type {http://www.w3.org/2000/09/xmldsig#}X509Data, skipping
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Processing KeyInfo child {http://www.w3.org/2000/09/xmldsig#}X509Data with provider org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider
2021-02-18 13:22:08.794 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Attempting to extract credential from an X509Data
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Found 1 X509Certificates
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Found 0 X509CRLs
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Single certificate was present, treating as end-entity certificate
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Credentials successfully extracted from child {http://www.w3.org/2000/09/xmldsig#}X509Data by provider org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - A total of 1 credentials were resolved
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry - Registry could not locate evaluable criteria for criteria class org.opensaml.xml.security.keyinfo.KeyInfoCriteria
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.security.MetadataCredentialResolver - Added new credential collection to cache with key: [https://accounts.google.com/o/saml2?idpid=C045ag7y5,{urn:oasis:names:tc:SAML:2.0:metadata}IDPSSODescriptor,urn:oasis:names:tc:SAML:2.0:protocol,SIGNING]
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry - Registry could not locate evaluable criteria for criteria class org.opensaml.security.MetadataCriteria
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry - Registry located evaluable criteria class org.opensaml.xml.security.credential.criteria.EvaluableEntityIDCredentialCriteria for criteria class org.opensaml.xml.security.criteria.EntityIDCriteria
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry - Registry located evaluable criteria class org.opensaml.xml.security.credential.criteria.EvaluableUsageCredentialCriteria for criteria class org.opensaml.xml.security.criteria.UsageCriteria
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry - Registry located evaluable criteria class org.opensaml.xml.security.credential.criteria.EvaluableKeyAlgorithmCredentialCriteria for criteria class org.opensaml.xml.security.criteria.KeyAlgorithmCriteria
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.impl.BaseSignatureTrustEngine - Attempting to verify signature and establish trust using KeyInfo-derived credentials
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Found 0 key names: []
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Processing KeyInfo child with qname: {http://www.w3.org/2000/09/xmldsig#}X509Data
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Provider org.opensaml.xml.security.keyinfo.provider.RSAKeyValueProvider doesn't handle objects of type {http://www.w3.org/2000/09/xmldsig#}X509Data, skipping
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Provider org.opensaml.xml.security.keyinfo.provider.DSAKeyValueProvider doesn't handle objects of type {http://www.w3.org/2000/09/xmldsig#}X509Data, skipping
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Processing KeyInfo child {http://www.w3.org/2000/09/xmldsig#}X509Data with provider org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider
2021-02-18 13:22:08.795 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Attempting to extract credential from an X509Data
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Found 1 X509Certificates
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Found 0 X509CRLs
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider - Single certificate was present, treating as end-entity certificate
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - Credentials successfully extracted from child {http://www.w3.org/2000/09/xmldsig#}X509Data by provider org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver - A total of 1 credentials were resolved
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry - Registry could not locate evaluable criteria for criteria class org.opensaml.xml.security.keyinfo.KeyInfoCriteria
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.SignatureValidator - Attempting to validate signature using key from supplied credential
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.SignatureValidator - Creating XMLSignature object
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.SignatureValidator - Validating signature with signature algorithm URI: http://www.w3.org/2001/04/xmldsig-more#rsa-sha256
2021-02-18 13:22:08.796 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.SignatureValidator - Validation credential key algorithm 'RSA', key instance class 'sun.security.rsa.RSAPublicKeyImpl'
2021-02-18 13:22:08.797 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.SignatureValidator - Signature validated with key from supplied credential
2021-02-18 13:22:08.797 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.impl.BaseSignatureTrustEngine - Signature validation using candidate credential was successful
2021-02-18 13:22:08.797 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.impl.BaseSignatureTrustEngine - Successfully verified signature using KeyInfo-derived credential
2021-02-18 13:22:08.797 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.impl.BaseSignatureTrustEngine - Attempting to establish trust of KeyInfo-derived credential
2021-02-18 13:22:08.797 DEBUG [qtp2053591126-7905] org.opensaml.xml.security.trust.ExplicitKeyTrustEvaluator - Successfully validated untrusted credential against trusted key
2021-02-18 13:22:08.797 DEBUG [qtp2053591126-7905] org.opensaml.xml.signature.impl.BaseSignatureTrustEngine - Successfully established trust of KeyInfo-derived credential
2021-02-18 13:22:08.797 INFO [qtp2053591126-7905] org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule - Validation of protocol message signature succeeded, message type: {urn:oasis:names:tc:SAML:2.0:protocol}Response
2021-02-18 13:22:08.798 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule - Authentication via protocol message signature succeeded for context issuer entity ID https://accounts.google.com/o/saml2?idpid=C045ag7y5
2021-02-18 13:22:08.798 DEBUG [qtp2053591126-7905] org.opensaml.ws.message.decoder.BaseMessageDecoder - Successfully decoded message.
2021-02-18 13:22:08.798 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder - Checking SAML message intended destination endpoint against receiver endpoint
2021-02-18 13:22:08.798 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder - Intended message destination endpoint: https://desktop.xxx.xx:8443/app/saml/SSO
2021-02-18 13:22:08.798 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder - Actual message receiver endpoint: https://desktop.xxx.xx:8443/app/saml/SSO
2021-02-18 13:22:08.798 DEBUG [qtp2053591126-7905] org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder - SAML message intended destination endpoint matched recipient endpoint
2021-02-18 13:22:08.802 ERROR [qtp2053591126-7905] com.haulmont.addon.saml.saml.authentication.SamlAuthenticationFailureHandler - Failed to login by saml
org.springframework.security.authentication.AuthenticationServiceException: Error validating SAML message
at org.springframework.security.saml.SAMLAuthenticationProvider.authenticate(SAMLAuthenticationProvider.java:101) ~[shared/:na]
at org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:174) ~[shared/:na]
at org.springframework.security.saml.SAMLProcessingFilter.attemptAuthentication(SAMLProcessingFilter.java:92) ~[shared/:na]
at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:212) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:66) ~[shared/:na]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56) ~[shared/:na]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214) ~[shared/:na]
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177) ~[shared/:na]
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358) ~[shared/:na]
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271) ~[shared/:na]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634) ~[app.jar:na]
at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:108) ~[shared/:na]
at com.haulmont.addon.saml.web.security.saml.SamlLoginHttpRequestFilter.doFilter(SamlLoginHttpRequestFilter.java:81) ~[classes/:na]
at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113) ~[shared/:na]
at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:74) ~[shared/:na]
at com.haulmont.cuba.web.sys.CubaHttpFilter.doFilter(CubaHttpFilter.java:93) ~[classes/:na]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642) ~[app.jar:na]
at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:228) ~[app.jar:na]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:572) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[app.jar:na]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[app.jar:na]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[app.jar:na]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1612) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[app.jar:na]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) ~[app.jar:na]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1582) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[app.jar:na]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[app.jar:na]
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[app.jar:na]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[app.jar:na]
at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[app.jar:na]
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[app.jar:na]
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) ~[app.jar:na]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) ~[app.jar:na]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) ~[app.jar:na]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[app.jar:na]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[app.jar:na]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:540) ~[app.jar:na]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:395) ~[app.jar:na]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161) ~[app.jar:na]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[app.jar:na]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[app.jar:na]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[app.jar:na]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) ~[app.jar:na]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773) ~[app.jar:na]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905) ~[app.jar:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: org.opensaml.common.SAMLException: Response doesn't have any valid assertion which would pass subject validation
at org.springframework.security.saml.websso.WebSSOProfileConsumerImpl.processAuthenticationResponse(WebSSOProfileConsumerImpl.java:265) ~[shared/:na]
at org.springframework.security.saml.SAMLAuthenticationProvider.authenticate(SAMLAuthenticationProvider.java:88) ~[shared/:na]
... 67 common frames omitted
Caused by: org.springframework.security.authentication.CredentialsExpiredException: Authentication statement is too old to be used with value 2021-02-17T13:21:10.000Z
at org.springframework.security.saml.websso.WebSSOProfileConsumerImpl.verifyAuthenticationStatement(WebSSOProfileConsumerImpl.java:574) ~[shared/:na]
at org.springframework.security.saml.websso.WebSSOProfileConsumerImpl.verifyAssertion(WebSSOProfileConsumerImpl.java:342) ~[shared/:na]
at org.springframework.security.saml.websso.WebSSOProfileConsumerImpl.processAuthenticationResponse(WebSSOProfileConsumerImpl.java:250) ~[shared/:na]
... 68 common frames omitted
2021-02-18 13:22:08.810 DEBUG [qtp2053591126-7905] com.haulmont.addon.saml.saml.authentication.SamlAuthenticationFailureHandler - Using default Url: /
2021-02-18 13:22:09.019 DEBUG [qtp2053591126-7859] com.haulmont.cuba.web.App - Initializing application
2021-02-18 13:22:09.023 DEBUG [qtp2053591126-7859/app/anonymous] com.haulmont.cuba.web.DefaultApp - connectionStateChanged connected: true, authenticated: false
2021-02-18 13:22:09.023 DEBUG [qtp2053591126-7859/app/anonymous] com.haulmont.cuba.web.App - Closing all windows in all UIs
2021-02-18 13:22:09.033 DEBUG [qtp2053591126-7859/app-core/admin] com.haulmont.cuba.core.app.RdbmsStore - loadList: metaClass=samladdon$SamlConnection, view=com.haulmont.addon.saml.entity.SamlConnection/_minimal, query=Query{queryString='select e from samladdon$SamlConnection e where e.active = true order by e.ssoPath', condition=null, sort=null, firstResult=0, maxResults=0}
2021-02-18 13:24:23.449 DEBUG [cuba_core_scheduler-6] com.haulmont.cuba.core.app.queryresults.QueryResultsManager - Delete query results for inactive user sessions
