Login returns indefinitely HttpSession returned null object for SPRING_SECURITY_CONTEXT

[gitthubble]

Login returns indefinitely "HttpSession returned null object for SPRING_SECURITY_CONTEXT" unless I do logout.
Happens occasionally. Not known how to reproduce. Seems to be we have this problem after upgrade to spring-security-4.0.3.RELEASE
I m pasting spring-security debug log.

11:39:36,223 [http-apr-9080-exec-7] DEBUG DefaultSavedRequest added to Session: DefaultSavedRequest[http://localhost:9080/application]
11:39:36,223 [http-apr-9080-exec-7] DEBUG Calling Authentication entry point.
11:39:36,223 [http-apr-9080-exec-7] DEBUG Redirecting to 'http://localhost:9080/application/screens/Login'
11:39:36,223 [http-apr-9080-exec-7] DEBUG SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
11:39:36,223 [http-apr-9080-exec-7] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:36,223 [http-apr-9080-exec-8] DEBUG Checking match of request : '/screens/login'; against '/screens/login'
11:39:36,223 [http-apr-9080-exec-8] DEBUG /screens/Login has an empty filter list
11:39:37,567 [http-apr-9080-exec-9] DEBUG Checking match of request : '/securitycheck'; against '/screens/login'
11:39:37,567 [http-apr-9080-exec-9] DEBUG Checking match of request : '/securitycheck'; against '/resources/**'
11:39:37,567 [http-apr-9080-exec-9] DEBUG Checking match of request : '/securitycheck'; against '/extjs/**'
11:39:37,567 [http-apr-9080-exec-9] DEBUG Checking match of request : '/securitycheck'; against '/services/**'
11:39:37,567 [http-apr-9080-exec-9] DEBUG /SecurityCheck at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:37,567 [http-apr-9080-exec-9] DEBUG HttpSession returned null object for SPRING_SECURITY_CONTEXT
11:39:37,567 [http-apr-9080-exec-9] DEBUG No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@15dff038. A new one will be created.
11:39:37,567 [http-apr-9080-exec-9] DEBUG /SecurityCheck at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:37,567 [http-apr-9080-exec-9] DEBUG /SecurityCheck at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:37,567 [http-apr-9080-exec-9] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:37,567 [http-apr-9080-exec-9] DEBUG /SecurityCheck at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:37,567 [http-apr-9080-exec-9] DEBUG Checking match of request : '/securitycheck'; against '/screens/logout'
11:39:37,567 [http-apr-9080-exec-9] DEBUG /SecurityCheck at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:37,567 [http-apr-9080-exec-9] DEBUG Checking match of request : '/securitycheck'; against '/securitycheck'
11:39:37,567 [http-apr-9080-exec-9] DEBUG SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
11:39:37,567 [http-apr-9080-exec-9] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:37,567 [http-apr-9080-exec-10] DEBUG Checking match of request : '/securitycheck'; against '/screens/login'
11:39:37,567 [http-apr-9080-exec-10] DEBUG Checking match of request : '/securitycheck'; against '/resources/**'
11:39:37,567 [http-apr-9080-exec-10] DEBUG Checking match of request : '/securitycheck'; against '/extjs/**'
11:39:37,567 [http-apr-9080-exec-10] DEBUG Checking match of request : '/securitycheck'; against '/services/**'
11:39:37,567 [http-apr-9080-exec-10] DEBUG /SecurityCheck at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:37,567 [http-apr-9080-exec-10] DEBUG HttpSession returned null object for SPRING_SECURITY_CONTEXT
11:39:37,567 [http-apr-9080-exec-10] DEBUG No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@15dff038. A new one will be created.
11:39:37,567 [http-apr-9080-exec-10] DEBUG /SecurityCheck at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:37,567 [http-apr-9080-exec-10] DEBUG /SecurityCheck at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:37,567 [http-apr-9080-exec-10] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:37,567 [http-apr-9080-exec-10] DEBUG /SecurityCheck at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:37,567 [http-apr-9080-exec-10] DEBUG Checking match of request : '/securitycheck'; against '/screens/logout'
11:39:37,567 [http-apr-9080-exec-10] DEBUG /SecurityCheck at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:37,567 [http-apr-9080-exec-10] DEBUG Checking match of request : '/securitycheck'; against '/securitycheck'
11:39:37,567 [http-apr-9080-exec-10] DEBUG SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
11:39:37,567 [http-apr-9080-exec-10] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:37,567 [http-apr-9080-exec-1] DEBUG Checking match of request : '/securitycheck'; against '/screens/login'
11:39:37,567 [http-apr-9080-exec-1] DEBUG Checking match of request : '/securitycheck'; against '/resources/**'
11:39:37,567 [http-apr-9080-exec-1] DEBUG Checking match of request : '/securitycheck'; against '/extjs/**'
11:39:37,567 [http-apr-9080-exec-1] DEBUG Checking match of request : '/securitycheck'; against '/services/**'
11:39:37,567 [http-apr-9080-exec-1] DEBUG /SecurityCheck at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:37,567 [http-apr-9080-exec-1] DEBUG HttpSession returned null object for SPRING_SECURITY_CONTEXT
11:39:37,567 [http-apr-9080-exec-1] DEBUG No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@15dff038. A new one will be created.
11:39:37,567 [http-apr-9080-exec-1] DEBUG /SecurityCheck at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:37,567 [http-apr-9080-exec-1] DEBUG /SecurityCheck at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:37,567 [http-apr-9080-exec-1] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:37,567 [http-apr-9080-exec-1] DEBUG /SecurityCheck at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:37,567 [http-apr-9080-exec-1] DEBUG Checking match of request : '/securitycheck'; against '/screens/logout'
11:39:37,567 [http-apr-9080-exec-1] DEBUG /SecurityCheck at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:37,567 [http-apr-9080-exec-1] DEBUG Checking match of request : '/securitycheck'; against '/securitycheck'
11:39:37,708 [http-apr-9080-exec-1] DEBUG Authentication attempt using app.modules.util.auth.DatabaseAuthenticationProvider
11:39:37,739 [http-apr-9080-exec-1] DEBUG Redirecting to DefaultSavedRequest Url: http://localhost:9080/application
11:39:37,739 [http-apr-9080-exec-1] DEBUG Redirecting to 'http://localhost:9080/application'
11:39:37,739 [http-apr-9080-exec-1] DEBUG SecurityContext 'org.springframework.security.core.context.SecurityContextImpl@df98084: Authentication: app.modules.util.auth.UserAuthentication@df98084' stored to HttpSession: 'org.apache.catalina.session.StandardSessionFacade@15dff038
11:39:37,739 [http-apr-9080-exec-1] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/screens/login'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/resources/**'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/extjs/**'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/services/**'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG No HttpSession currently exists
11:39:37,739 [http-apr-9080-exec-2] DEBUG No SecurityContext was available from the HttpSession: null. A new one will be created.
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/screens/logout'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/securitycheck'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 6 of 11 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 7 of 11 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 8 of 11 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@9055e4a6: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@957e: RemoteIpAddress: 127.0.0.1; SessionId: null; Granted Authorities: ROLE_ANONYMOUS'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 9 of 11 in additional filter chain; firing Filter: 'SessionManagementFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 10 of 11 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
11:39:37,739 [http-apr-9080-exec-2] DEBUG  at position 11 of 11 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/servlet/shortavailability/**'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/screens/manageusers'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/screens/managepermissions'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Checking match of request : ''; against '/screens/home'
11:39:37,739 [http-apr-9080-exec-2] DEBUG Secure object: FilterInvocation: URL: ; Attributes: [hasAnyRole('Administrator','User')]
11:39:37,739 [http-apr-9080-exec-2] DEBUG Previously Authenticated: org.springframework.security.authentication.AnonymousAuthenticationToken@9055e4a6: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@957e: RemoteIpAddress: 127.0.0.1; SessionId: null; Granted Authorities: ROLE_ANONYMOUS
11:39:37,739 [http-apr-9080-exec-2] DEBUG Voter: org.springframework.security.web.access.expression.WebExpressionVoter@480af767, returned: -1
11:39:37,739 [http-apr-9080-exec-2] DEBUG Access is denied (user is anonymous); redirecting to authentication entry point
org.springframework.security.access.AccessDeniedException: Access is denied
    at org.springframework.security.access.vote.AffirmativeBased.decide(AffirmativeBased.java:83)
    at org.springframework.security.access.intercept.AbstractSecurityInterceptor.beforeInvocation(AbstractSecurityInterceptor.java:232)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:123)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:90)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:122)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:169)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:48)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:205)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:120)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:53)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:91)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:213)
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:176)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at app.util.WebappInfoProvider.doFilter(WebappInfoProvider.java:41)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2517)
    at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2506)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
11:39:37,739 [http-apr-9080-exec-2] DEBUG DefaultSavedRequest added to Session: DefaultSavedRequest[http://localhost:9080/application]
11:39:37,739 [http-apr-9080-exec-2] DEBUG Calling Authentication entry point.
11:39:37,755 [http-apr-9080-exec-2] DEBUG Redirecting to 'http://localhost:9080/application/screens/Login'
11:39:37,755 [http-apr-9080-exec-2] DEBUG SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
11:39:37,755 [http-apr-9080-exec-2] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:37,755 [http-apr-9080-exec-3] DEBUG Checking match of request : '/screens/login'; against '/screens/login'
11:39:37,755 [http-apr-9080-exec-3] DEBUG /screens/Login has an empty filter list
11:39:42,442 [http-apr-9080-exec-4] DEBUG Checking match of request : '/screens/logout'; against '/screens/login'
11:39:42,442 [http-apr-9080-exec-4] DEBUG Checking match of request : '/screens/logout'; against '/resources/**'
11:39:42,442 [http-apr-9080-exec-4] DEBUG Checking match of request : '/screens/logout'; against '/extjs/**'
11:39:42,442 [http-apr-9080-exec-4] DEBUG Checking match of request : '/screens/logout'; against '/services/**'
11:39:42,442 [http-apr-9080-exec-4] DEBUG /screens/Logout at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:42,442 [http-apr-9080-exec-4] DEBUG HttpSession returned null object for SPRING_SECURITY_CONTEXT
11:39:42,442 [http-apr-9080-exec-4] DEBUG No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@4bb26fb1. A new one will be created.
11:39:42,442 [http-apr-9080-exec-4] DEBUG /screens/Logout at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:42,442 [http-apr-9080-exec-4] DEBUG /screens/Logout at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:42,442 [http-apr-9080-exec-4] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:42,442 [http-apr-9080-exec-4] DEBUG /screens/Logout at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:42,442 [http-apr-9080-exec-4] DEBUG Checking match of request : '/screens/logout'; against '/screens/logout'
11:39:42,442 [http-apr-9080-exec-4] DEBUG Logging out user 'null' and transferring to logout destination
11:39:42,442 [http-apr-9080-exec-4] DEBUG Invalidating session: 738F4699178D36D04E3C38703DE0991F
11:39:42,442 [http-apr-9080-exec-4] DEBUG Using default Url: /screens/Login
11:39:42,442 [http-apr-9080-exec-4] DEBUG Redirecting to '/application/screens/Login'
11:39:42,442 [http-apr-9080-exec-4] DEBUG SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
11:39:42,442 [http-apr-9080-exec-4] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:42,442 [http-apr-9080-exec-5] DEBUG Checking match of request : '/screens/login'; against '/screens/login'
11:39:42,442 [http-apr-9080-exec-5] DEBUG /screens/Login has an empty filter list
11:39:45,145 [http-apr-9080-exec-6] DEBUG Checking match of request : '/securitycheck'; against '/screens/login'
11:39:45,145 [http-apr-9080-exec-6] DEBUG Checking match of request : '/securitycheck'; against '/resources/**'
11:39:45,145 [http-apr-9080-exec-6] DEBUG Checking match of request : '/securitycheck'; against '/extjs/**'
11:39:45,145 [http-apr-9080-exec-6] DEBUG Checking match of request : '/securitycheck'; against '/services/**'
11:39:45,145 [http-apr-9080-exec-6] DEBUG /SecurityCheck at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:45,145 [http-apr-9080-exec-6] DEBUG No HttpSession currently exists
11:39:45,145 [http-apr-9080-exec-6] DEBUG No SecurityContext was available from the HttpSession: null. A new one will be created.
11:39:45,145 [http-apr-9080-exec-6] DEBUG /SecurityCheck at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:45,145 [http-apr-9080-exec-6] DEBUG /SecurityCheck at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:45,145 [http-apr-9080-exec-6] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:45,145 [http-apr-9080-exec-6] DEBUG /SecurityCheck at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:45,145 [http-apr-9080-exec-6] DEBUG Checking match of request : '/securitycheck'; against '/screens/logout'
11:39:45,145 [http-apr-9080-exec-6] DEBUG /SecurityCheck at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:45,145 [http-apr-9080-exec-6] DEBUG Checking match of request : '/securitycheck'; against '/securitycheck'
11:39:45,145 [http-apr-9080-exec-6] DEBUG SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
11:39:45,145 [http-apr-9080-exec-6] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:45,145 [http-apr-9080-exec-7] DEBUG Checking match of request : '/securitycheck'; against '/screens/login'
11:39:45,145 [http-apr-9080-exec-7] DEBUG Checking match of request : '/securitycheck'; against '/resources/**'
11:39:45,145 [http-apr-9080-exec-7] DEBUG Checking match of request : '/securitycheck'; against '/extjs/**'
11:39:45,145 [http-apr-9080-exec-7] DEBUG Checking match of request : '/securitycheck'; against '/services/**'
11:39:45,145 [http-apr-9080-exec-7] DEBUG /SecurityCheck at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:45,145 [http-apr-9080-exec-7] DEBUG No HttpSession currently exists
11:39:45,145 [http-apr-9080-exec-7] DEBUG No SecurityContext was available from the HttpSession: null. A new one will be created.
11:39:45,145 [http-apr-9080-exec-7] DEBUG /SecurityCheck at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:45,145 [http-apr-9080-exec-7] DEBUG /SecurityCheck at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:45,145 [http-apr-9080-exec-7] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:45,145 [http-apr-9080-exec-7] DEBUG /SecurityCheck at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:45,145 [http-apr-9080-exec-7] DEBUG Checking match of request : '/securitycheck'; against '/screens/logout'
11:39:45,145 [http-apr-9080-exec-7] DEBUG /SecurityCheck at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:45,145 [http-apr-9080-exec-7] DEBUG Checking match of request : '/securitycheck'; against '/securitycheck'
11:39:45,145 [http-apr-9080-exec-7] DEBUG SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
11:39:45,145 [http-apr-9080-exec-7] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:45,145 [http-apr-9080-exec-8] DEBUG Checking match of request : '/securitycheck'; against '/screens/login'
11:39:45,145 [http-apr-9080-exec-8] DEBUG Checking match of request : '/securitycheck'; against '/resources/**'
11:39:45,145 [http-apr-9080-exec-8] DEBUG Checking match of request : '/securitycheck'; against '/extjs/**'
11:39:45,145 [http-apr-9080-exec-8] DEBUG Checking match of request : '/securitycheck'; against '/services/**'
11:39:45,145 [http-apr-9080-exec-8] DEBUG /SecurityCheck at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:45,145 [http-apr-9080-exec-8] DEBUG No HttpSession currently exists
11:39:45,145 [http-apr-9080-exec-8] DEBUG No SecurityContext was available from the HttpSession: null. A new one will be created.
11:39:45,145 [http-apr-9080-exec-8] DEBUG /SecurityCheck at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:45,145 [http-apr-9080-exec-8] DEBUG /SecurityCheck at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:45,145 [http-apr-9080-exec-8] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:45,145 [http-apr-9080-exec-8] DEBUG /SecurityCheck at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:45,145 [http-apr-9080-exec-8] DEBUG Checking match of request : '/securitycheck'; against '/screens/logout'
11:39:45,145 [http-apr-9080-exec-8] DEBUG /SecurityCheck at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:45,145 [http-apr-9080-exec-8] DEBUG Checking match of request : '/securitycheck'; against '/securitycheck'
11:39:45,301 [http-apr-9080-exec-8] DEBUG Authentication attempt using app.modules.util.auth.DatabaseAuthenticationProvider
11:39:45,333 [http-apr-9080-exec-8] DEBUG Using default Url: /screens/Home
11:39:45,333 [http-apr-9080-exec-8] DEBUG Redirecting to '/application/screens/Home'
11:39:45,333 [http-apr-9080-exec-8] DEBUG HttpSession being created as SecurityContext is non-default
11:39:45,333 [http-apr-9080-exec-8] DEBUG SecurityContext 'org.springframework.security.core.context.SecurityContextImpl@21ce8bee: Authentication: app.modules.util.auth.UserAuthentication@21ce8bee' stored to HttpSession: 'org.apache.catalina.session.StandardSessionFacade@6c5e3473
11:39:45,333 [http-apr-9080-exec-8] DEBUG SecurityContextHolder now cleared, as request processing completed
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/screens/login'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/resources/**'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/extjs/**'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/services/**'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Obtained a valid SecurityContext from SPRING_SECURITY_CONTEXT: 'org.springframework.security.core.context.SecurityContextImpl@21ce8bee: Authentication: app.modules.util.auth.UserAuthentication@21ce8bee'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 2 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@71e87e8e
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/screens/logout'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 5 of 11 in additional filter chain; firing Filter: 'CompositeAuthenticationFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/securitycheck'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 6 of 11 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 7 of 11 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 8 of 11 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG SecurityContextHolder not populated with anonymous token, as it already contained: 'app.modules.util.auth.UserAuthentication@21ce8bee'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 9 of 11 in additional filter chain; firing Filter: 'SessionManagementFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 10 of 11 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
11:39:45,333 [http-apr-9080-exec-9] DEBUG /screens/Home at position 11 of 11 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/servlet/shortavailability/**'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/screens/manageusers'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/screens/managepermissions'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Checking match of request : '/screens/home'; against '/screens/home'
11:39:45,333 [http-apr-9080-exec-9] DEBUG Secure object: FilterInvocation: URL: /screens/Home; Attributes: [isAuthenticated()]
11:39:45,333 [http-apr-9080-exec-9] DEBUG Previously Authenticated: app.modules.util.auth.UserAuthentication@21ce8bee
11:39:45,333 [http-apr-9080-exec-9] DEBUG Voter: org.springframework.security.web.access.expression.WebExpressionVoter@480af767, returned: 1
11:39:45,333 [http-apr-9080-exec-9] DEBUG Authorization successful

Please notice that the section with the time 11:39:37,567
3 different threads printing same log.
Similar log as from The section with time 11:39:37,567 repeats several times until I do logout and login, I just pasted the last piece to make it shorter here.

[rwinch]

Thanks for the report. What version did you update from?

Can you please describe in more detail what is happening (step by step), what you expect to happen (step by step), and provide any configuration details?

[gitthubble]

Spring-security upgraded from spring-security-3.1.3.
Application is deployed on Tomcat 7.
Spring-4.2.4.RELEASE.
Usecase:

1. Application shows login screen if user is not logged-in yet or session expired or Tomcat restarted etc.
2. After clicking login user is redirected to home screen or the screen which he is on.
   But now:
3. Application shows login screen if user is not logged-in yet or session expired or Tomcat restarted etc.
4. After clicking login redirects to login screen again
5. Again clicking login... after each login attempt it repeats login screen indefinitely *unless logout is done * (see the section with time 11:39:42,442 for logout), after logout, login attempts works fine as expected.
6. As a result not able login.

Some piece from config:

    <sec:http pattern="/screens/Login" security="none"/>
    <sec:http pattern="/resources/**" security="none"/>
    <sec:http pattern="/extjs/**" security="none"/>
    <sec:http use-expressions="true"
              auto-config="false"
              entry-point-ref="loginUrlAuthenticationEntryPoint"
              access-decision-manager-ref="accessDecisionManager">
        <sec:intercept-url pattern="/servlet/shortavailability/**" access="denyAll"/>
        <sec:intercept-url pattern="/screens/ManageUsers" access="hasRole('Access Manager')" />
        <sec:intercept-url pattern="/screens/ManagePermissions" access="hasRole('Access Manager')" />
        <sec:intercept-url pattern="/screens/Home" access="isAuthenticated()" />
        <sec:intercept-url pattern="/**" access="hasAnyRole('Administrator','User')" />
        <sec:logout logout-url="/screens/Logout" invalidate-session="true" logout-success-url="/screens/Login"/>
        <sec:custom-filter ref="authenticationFilter" position="FORM_LOGIN_FILTER" />
        <sec:csrf disabled="true" />
    </sec:http>

Sorry for messing up the format again

[rwinch]

@gitthubble Thanks for the response! Does this happen all the time or is it periodically?

Sorry for messing up the format again

Not a big deal. If you want to get up to speed, you can read about formatting at https://guides.github.com/features/mastering-markdown/

[gitthubble]

Does this happen all the time or is it periodically?

It happens occasionally, cannot reproduce on demand.

[rwinch]

What does the bean authenticationFilter look like? If it is using a custom class, what does that look like?
What does the request for a login look like?

[gitthubble]

It extends AbstractAuthenticationProcessingFilter

@Override
    public Authentication attemptAuthentication(HttpServletRequest request,
                                                HttpServletResponse response)
            throws AuthenticationException, IOException, ServletException {
...
...
Authentication authentication = authenticator.authenticate(request, response);

                if (authentication != null) {
                    try {
                        final AuthenticationManager authenticationManager = getAuthenticationManager();
                        return authenticationManager.authenticate(authentication);
                    }
                    catch (AuthenticationException e) {
                        authentication.setAuthenticated(false);
                        throw e;
                    }
                    catch (Exception e) {
                        authentication.setAuthenticated(false);
                        throw new AuthenticationServiceException(e.getMessage(), e);
                    }
                }
...
...

[rwinch]

What sort of credentials does it use? What does authenticator look like? What does the HTTP request look like? What does the response look like?

[gitthubble]

This request response sample for successful login.

RESPONSE
HTTP/1.1 302 Found

Server: Apache-Coyote/1.1

Set-Cookie: JSESSIONID=7BC94F97B8CBA165B3A7915C21482B6F; Path=/application101/; HttpOnly

Location: /application101/screens/Home

Content-Length: 0

Date: Fri, 08 Apr 2016 15:27:07 GMT

REQUEST
POST /application101/SecurityCheck HTTP/1.1

Host: localhost:8080

User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Accept-Language: en-GB,en;q=0.5

Accept-Encoding: gzip, deflate

Referer: http://localhost:8080/application101/screens/Login

Cookie: JSESSIONID=EB3B4D5D67F258F978E13385F55D7222

Connection: keep-alive

Authorization: NTLM TlRMTVNTUAADAAAAGAAYAHwAAABAA...

[rwinch]

And the other questions? I'm guessing you are using NTLM then?

[gitthubble]

Yes in this case NTLM is used.

[gitthubble]

Authenticator looks like:

    public Authentication authenticate(HttpServletRequest request, HttpServletResponse response)
            throws IOException, ServletException {
        AuthorizationHeader authorizationHeader = new AuthorizationHeader(request);

        if (authorizationHeader.isNull()) {
            negotiateSecurityFilterEntryPoint.commence(
                    request,
                    response,
                    null);
        }
        else {
            negotiateSecurityFilter.doFilter(request, response, new DummyFilterChain());
        }

        return SecurityContextHolder.getContext().getAuthentication();
    }

[rwinch]

I'm going to need all your code that is necessary for authentication.

[gitthubble]

If you mean the AuthorizationHeader, NegotiateSecurityFilter, NegotiateSecurityFilterEntryPoint above it is waffle-spring-security3-1.5