Occasional CredentialsExpiredException

[glebshalyganov]

Environment

• Platform version: 7.2
• Addon version: 0.5.0
• GSuite as IDP

Description of the bug or enhancement

From time to time application fails to login user via SAML showing the following error:

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

Looks like this error usually appears after long time from last login via Google IDP.
Increasing the cuba.addon.saml.maxAuthenticationAgeSec doesn't seem to help.
Another thing is that logging out from Google before logging into SAML app helps to overcome the problem.