Spring login error when trying to enforce 1 session only

[SpringMan2011]

I am quite new to Spring Security (despite my username!) but am trying to understand what the problem is with our login.

We are using Spring security 2.5 and have a Flex Application that talks to the mySQL database via Java and Toplink. Our basic login page authenticates to a main page. We want to enforce only 1 session per user and we enforce that with this line in the applicationSecurity.xml.

<concurrent-session-control max-sessions="1"
expired-url="/login_page.html"/>

Everything is working fine for the most part - we have a 1 scenario where we are unable to login successfully and get a nasty null error.

Since we want to enforce only 1 session - if I am logged in in 1 browser and then open a new browser and try to go to the main page, it should terminate the 1st session and create a new session. Accessing the main page in the new browser should boot us back to the login page. This is happening - however, when I try to log in from the new browser login page, I always get a null error. It seems like perhaps the old sessionId is not being released or something. I am having trouble figuring out what exactly is happening.

Here is the debug output from the log when we try to go straight to the main page from a new browser right where we get booted back to the login page - Notice the the reference to SessionId: 3DD2A69652966B47EF55797516040C05


(post continues )

[SpringMan2011]

14:41:07,933 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/main_page.html'; to: '/main_page.html'
14:41:07,933 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/main_page.html'; to: '/main_page.html'
14:41:07,933 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/main_page.html'; pattern is /login_page.*; matched=false
14:41:07,933 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/main_page.html'; pattern is /login_page.*; matched=false
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/main_page.html'; to: '/main_page.html'
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/main_page.html'; to: '/main_page.html'
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/main_page.html'; pattern is /**; matched=true
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/main_page.html'; pattern is /**; matched=true
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.ConcurrentSessionFilter[ order=100; ]'
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.ConcurrentSessionFilter[ order=100; ]'
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
14:41:07,934 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
14:41:07,934 DEBUG HttpSessionEventPublisher,http-8080-7:67 - Publishing event: org.springframework.security.ui.session.HttpSessionCreatedEvent[source=org.apache.catalina.session.StandardSessionFacade@24928347]
14:41:07,934 DEBUG HttpSessionEventPublisher,http-8080-7:67 - Publishing event: org.springframework.security.ui.session.HttpSessionCreatedEvent[source=org.apache.catalina.session.StandardSessionFacade@24928347]
14:41:07,935 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:286 - HttpSession returned null object for SPRING_SECURITY_CONTEXT
14:41:07,935 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:286 - HttpSession returned null object for SPRING_SECURITY_CONTEXT
14:41:07,935 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:209 - New SecurityContext instance will be associated with SecurityContextHolder
14:41:07,935 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:209 - New SecurityContext instance will be associated with SecurityContextHolder
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 3 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.logout.LogoutFilter[ order=300; ]'
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 3 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.logout.LogoutFilter[ order=300; ]'
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 4 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.webapp.AuthenticationProcessingFilter[ order=700; ]'
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 4 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.webapp.AuthenticationProcessingFilter[ order=700; ]'
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 5 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.basicauth.BasicProcessingFilter[ order=1000; ]'
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 5 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.basicauth.BasicProcessingFilter[ order=1000; ]'
14:41:07,935 DEBUG BasicProcessingFilter,http-8080-7:114 - Authorization header: null
14:41:07,935 DEBUG BasicProcessingFilter,http-8080-7:114 - Authorization header: null
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 6 of 11 in additional filter chain; firing Filter: 'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
14:41:07,935 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 6 of 11 in additional filter chain; firing Filter: 'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
14:41:07,936 DEBUG SavedRequestAwareWrapper,http-8080-7:117 - Wrapper not replaced; SavedRequest was: null
14:41:07,936 DEBUG SavedRequestAwareWrapper,http-8080-7:117 - Wrapper not replaced; SavedRequest was: null
14:41:07,936 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 7 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.rememberme.RememberMeProcessingFilter[ order=1200; ]'
14:41:07,936 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 7 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.rememberme.RememberMeProcessingFilter[ order=1200; ]'
14:41:07,936 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 8 of 11 in additional filter chain; firing Filter: 'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
14:41:07,936 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 8 of 11 in additional filter chain; firing Filter: 'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
14:41:07,936 DEBUG AnonymousProcessingFilter,http-8080-7:93 - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.providers.anonymous.AnonymousAuthenticationToken@69edfa5f: Principal: roleAnonymous; Password: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationDetails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ANONYMOUS'
14:41:07,936 DEBUG AnonymousProcessingFilter,http-8080-7:93 - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.providers.anonymous.AnonymousAuthenticationToken@69edfa5f: Principal: roleAnonymous; Password: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationDetails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ANONYMOUS'

[SpringMan2011]

14:41:07,936 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 9 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
14:41:07,936 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 9 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
14:41:07,937 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 10 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
14:41:07,937 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 10 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
14:41:07,937 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 11 of 11 in additional filter chain; firing Filter: 'org.springframework.security.intercept.web.FilterSecurityInterceptor@7399f9eb'
14:41:07,937 DEBUG FilterChainProxy,http-8080-7:366 - /main_page.html at position 11 of 11 in additional filter chain; firing Filter: 'org.springframework.security.intercept.web.FilterSecurityInterceptor@7399f9eb'
14:41:07,937 DEBUG DefaultFilterInvocationDefinitionSource,http-8080-7:196 - Converted URL to lowercase, from: '/main_page.html'; to: '/main_page.html'
14:41:07,937 DEBUG DefaultFilterInvocationDefinitionSource,http-8080-7:196 - Converted URL to lowercase, from: '/main_page.html'; to: '/main_page.html'
14:41:07,937 DEBUG DefaultFilterInvocationDefinitionSource,http-8080-7:224 - Candidate is: '/main_page.html'; pattern is /main_page.*; matched=true
14:41:07,937 DEBUG DefaultFilterInvocationDefinitionSource,http-8080-7:224 - Candidate is: '/main_page.html'; pattern is /main_page.*; matched=true
14:41:07,938 DEBUG AbstractSecurityInterceptor,http-8080-7:250 - Secure object: FilterInvocation: URL: /main_page.html; ConfigAttributes: [ROLE_REQUESTER]
14:41:07,938 DEBUG AbstractSecurityInterceptor,http-8080-7:250 - Secure object: FilterInvocation: URL: /main_page.html; ConfigAttributes: [ROLE_REQUESTER]
14:41:07,938 DEBUG AbstractSecurityInterceptor,http-8080-7:313 - Previously Authenticated: org.springframework.security.providers.anonymous.AnonymousAuthenticationToken@69edfa5f: Principal: roleAnonymous; Password: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationDetails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ANONYMOUS
14:41:07,938 DEBUG AbstractSecurityInterceptor,http-8080-7:313 - Previously Authenticated: org.springframework.security.providers.anonymous.AnonymousAuthenticationToken@69edfa5f: Principal: roleAnonymous; Password: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationDetails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ANONYMOUS
14:41:07,938 DEBUG ExceptionTranslationFilter,http-8080-7:158 - Access is denied (user is anonymous); redirecting to authentication entry point
org.springframework.security.AccessDeniedException: Access is denied
	at org.springframework.security.vote.AffirmativeBased.decide(AffirmativeBased.java:68)
	at org.springframework.security.intercept.AbstractSecurityInterceptor.beforeInvocation(AbstractSecurityInterceptor.java:262)
	at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:106)
	at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.ui.SessionFixationProtectionFilter.doFilterHttp(SessionFixationProtectionFilter.java:67)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.ui.rememberme.RememberMeProcessingFilter.doFilterHttp(RememberMeProcessingFilter.java:109)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter.doFilterHttp(SecurityContextHolderAwareRequestFilter.java:91)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.ui.basicauth.BasicProcessingFilter.doFilterHttp(BasicProcessingFilter.java:173)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:271)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.ui.logout.LogoutFilter.doFilterHttp(LogoutFilter.java:89)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.concurrent.ConcurrentSessionFilter.doFilterHttp(ConcurrentSessionFilter.java:99)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:371)
	at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:174)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:183)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:138)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:857)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
	at java.lang.Thread.run(Thread.java:680)
14:41:07,938 DEBUG ExceptionTranslationFilter,http-8080-7:158 - Access is denied (user is anonymous); redirecting to authentication entry point

[SpringMan2011]

14:41:07,939 DEBUG ExceptionTranslationFilter,http-8080-7:200 - Authentication entry point being called; SavedRequest added to Session: SavedRequest[http://localhost:8080/etmui/main_page.html]
14:41:07,939 DEBUG ExceptionTranslationFilter,http-8080-7:200 - Authentication entry point being called; SavedRequest added to Session: SavedRequest[http://localhost:8080/etmui/main_page.html]
14:41:07,940 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:255 - SecurityContextHolder now cleared, as request processing completed
14:41:07,940 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:255 - SecurityContextHolder now cleared, as request processing completed
14:41:07,941 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/login_page.html'; to: '/login_page.html'
14:41:07,941 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/login_page.html'; to: '/login_page.html'
14:41:07,942 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/login_page.html'; pattern is /login_page.*; matched=true
14:41:07,942 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/login_page.html'; pattern is /login_page.*; matched=true
14:41:07,942 DEBUG FilterChainProxy,http-8080-7:164 - has an empty filter list
14:41:07,942 DEBUG FilterChainProxy,http-8080-7:164 - has an empty filter list
14:41:07,946 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/history/history.css'; to: '/history/history.css'
14:41:07,946 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/history/history.css'; to: '/history/history.css'
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/history/history.css'; pattern is /login_page.*; matched=false
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/history/history.css'; pattern is /login_page.*; matched=false
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/history/history.css'; to: '/history/history.css'
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:194 - Converted URL to lowercase, from: '/history/history.css'; to: '/history/history.css'
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/history/history.css'; pattern is /**; matched=true
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:201 - Candidate is: '/history/history.css'; pattern is /**; matched=true
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionC ontextIntegrationFilter[ order=200; ]'
14:41:07,947 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionC ontextIntegrationFilter[ order=200; ]'
14:41:07,947 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:286 - HttpSession returned null object for SPRING_SECURITY_CONTEXT
14:41:07,947 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:286 - HttpSession returned null object for SPRING_SECURITY_CONTEXT
14:41:07,947 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/ac_oetags.js'; to: '/ac_oetags.js'
14:41:07,947 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/ac_oetags.js'; to: '/ac_oetags.js'
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/ac_oetags.js'; pattern is /login_page.*; matched=false
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/ac_oetags.js'; pattern is /login_page.*; matched=false
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/ac_oetags.js'; to: '/ac_oetags.js'
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/ac_oetags.js'; to: '/ac_oetags.js'
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/ac_oetags.js'; pattern is /**; matched=true
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/ac_oetags.js'; pattern is /**; matched=true
14:41:07,948 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:209 - New SecurityContext instance will be associated with SecurityContextHolder
14:41:07,948 DEBUG HttpSessionContextIntegrationFilter,http-8080-7:209 - New SecurityContext instance will be associated with SecurityContextHolder
14:41:07,949 DEBUG FilterChainProxy,http-8080-10:194 - Converted URL to lowercase, from: '/history/history.js'; to: '/history/history.js'
14:41:07,949 DEBUG FilterChainProxy,http-8080-10:194 - Converted URL to lowercase, from: '/history/history.js'; to: '/history/history.js'
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:366 - /AC_OETags.js at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'
14:41:07,948 DEBUG FilterChainProxy,http-8080-6:366 - /AC_OETags.js at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'
14:41:07,949 DEBUG FilterChainProxy,http-8080-10:201 - Candidate is: '/history/history.js'; pattern is /login_page.*; matched=false
14:41:07,949 DEBUG FilterChainProxy,http-8080-10:201 - Candidate is: '/history/history.js'; pattern is /login_page.*; matched=false
14:41:07,949 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 3 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.logout.LogoutFilt er[ order=300; ]'
14:41:07,949 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 3 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.logout.LogoutFilt er[ order=300; ]'
14:41:07,949 DEBUG FilterChainProxy,http-8080-10:194 - Converted URL to lowercase, from: '/history/history.js'; to: '/history/history.js'
14:41:07,949 DEBUG FilterChainProxy,http-8080-10:194 - Converted URL to lowercase, from: '/history/history.js'; to: '/history/history.js'
14:41:07,949 DEBUG FilterChainProxy,http-8080-6:366 - /AC_OETags.js at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionC ontextIntegrationFilter[ order=200; ]'
14:41:07,949 DEBUG FilterChainProxy,http-8080-6:366 - /AC_OETags.js at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionC ontextIntegrationFilter[ order=200; ]'
14:41:07,950 DEBUG FilterChainProxy,http-8080-10:201 - Candidate is: '/history/history.js'; pattern is /**; matched=true
14:41:07,950 DEBUG FilterChainProxy,http-8080-10:201 - Candidate is: '/history/history.js'; pattern is /**; matched=true
14:41:07,950 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 4 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.webapp.Authentica tionProcessingFilter[ order=700; ]'
14:41:07,950 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 4 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.webapp.Authentica tionProcessingFilter[ order=700; ]'
14:41:07,950 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 5 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.basicauth.BasicPr ocessingFilter[ order=1000; ]'
14:41:07,950 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 5 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.basicauth.BasicPr ocessingFilter[ order=1000; ]'
14:41:07,951 DEBUG BasicProcessingFilter,http-8080-7:114 - Authorization header: null
14:41:07,951 DEBUG BasicProcessingFilter,http-8080-7:114 - Authorization header: null
14:41:07,951 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 6 of 11 in additional filter chain; firing Filter: 'org.springframework.security.wrapper.SecurityCont extHolderAwareRequestFilter[ order=1100; ]'
14:41:07,951 DEBUG FilterChainProxy,http-8080-7:366 - /history/history.css at position 6 of 11 in additional filter chain; firing Filter: 'org.springframework.security.wrapper.SecurityCont extHolderAwareRequestFilter[ order=1100; ]'
14:41:07,951 DEBUG SavedRequest,http-8080-7:314 - pathInfo: both null (property equals)
14:41:07,951 DEBUG SavedRequest,http-8080-7:314 - pathInfo: both null (property equals)
14:41:07,951 DEBUG SavedRequest,http-8080-7:314 - queryString: both null (property equals)
14:41:07,951 DEBUG SavedRequest,http-8080-7:314 - queryString: both null (property equals)
14:41:07,950 DEBUG FilterChainProxy,http-8080-10:366 - /history/history.js at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'
14:41:07,950 DEBUG FilterChainProxy,http-8080-10:366 - /history/history.js at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'

[SpringMan2011]

OK, this is going to take forever with the message text limit...here are some relevant lines:

14:41:07,955 DEBUG AnonymousProcessingFilter,http-8080-7:93 - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.providers.anonymous. AnonymousAuthenticationToken@69edfa5f: Principal: roleAnonymous; Password: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationD etails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ANONYMOUS'
14:41:07,955 DEBUG AnonymousProcessingFilter,http-8080-7:93 - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.providers.anonymous. AnonymousAuthenticationToken@69edfa5f: Principal: roleAnonymous; Password: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationD etails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ANONYMOUS'

Notice the Session Id...

[SpringMan2011]

Now when I am booted back to the login page, I see this in the url:

http://localhost:8080/myapp/login_pa...797 516040C05


So, shouldn't that session be destroyed now? But when I go to log back in, I get a login error and here is the output of the debug trace - notice that the same session id appears:


Here are some relevant lines from the debug output:

14:42:46,912 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/j_spring_security_check'; to: '/j_spring_security_check'
14:42:46,912 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/j_spring_security_check'; to: '/j_spring_security_check'
14:42:46,912 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/j_spring_security_check'; pattern is /login_page.*; matched=false
14:42:46,912 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/j_spring_security_check'; pattern is /login_page.*; matched=false
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/j_spring_security_check'; to: '/j_spring_security_check'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:194 - Converted URL to lowercase, from: '/j_spring_security_check'; to: '/j_spring_security_check'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/j_spring_security_check'; pattern is /**; matched=true
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:201 - Candidate is: '/j_spring_security_check'; pattern is /**; matched=true
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 1 of 11 in additional filter chain; firing Filter: 'org.springframework.security.concurrent.Concurren tSessionFilter[ order=100; ]'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionC ontextIntegrationFilter[ order=200; ]'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 2 of 11 in additional filter chain; firing Filter: 'org.springframework.security.context.HttpSessionC ontextIntegrationFilter[ order=200; ]'
14:42:46,913 DEBUG HttpSessionContextIntegrationFilter,http-8080-6:286 - HttpSession returned null object for SPRING_SECURITY_CONTEXT
14:42:46,913 DEBUG HttpSessionContextIntegrationFilter,http-8080-6:286 - HttpSession returned null object for SPRING_SECURITY_CONTEXT
14:42:46,913 DEBUG HttpSessionContextIntegrationFilter,http-8080-6:209 - New SecurityContext instance will be associated with SecurityContextHolder
14:42:46,913 DEBUG HttpSessionContextIntegrationFilter,http-8080-6:209 - New SecurityContext instance will be associated with SecurityContextHolder
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 3 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.logout.LogoutFilt er[ order=300; ]'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 3 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.logout.LogoutFilt er[ order=300; ]'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 4 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.webapp.Authentica tionProcessingFilter[ order=700; ]'
14:42:46,913 DEBUG FilterChainProxy,http-8080-6:366 - /j_spring_security_check at position 4 of 11 in additional filter chain; firing Filter: 'org.springframework.security.ui.webapp.Authentica tionProcessingFilter[ order=700; ]'
14:42:46,914 DEBUG AuthenticationProcessingFilter,http-8080-6:245 - Request is to process authentication
n

[SpringMan2011]

14:42:46,914 DEBUG ProviderManager,http-8080-6:190 - Authentication attempt using org.springframework.security.providers.dao.DaoAuth enticationProvider
14:42:46,914 DEBUG ProviderManager,http-8080-6:190 - Authentication attempt using org.springframework.security.providers.dao.DaoAuth enticationProvider
14:42:46,915 DEBUG SessionRegistryImpl,http-8080-6:123 - Registering session 3DD2A69652966B47EF55797516040C05, for principal user@myCompany.com
14:42:46,915 DEBUG SessionRegistryImpl,http-8080-6:123 - Registering session 3DD2A69652966B47EF55797516040C05, for principal user@myCompany.com
14:42:46,916 DEBUG AuthenticationProcessingFilter,http-8080-6:351 - Authentication success: org.springframework.security.providers.UsernamePas swordAuthenticationToken@52244b5c: Principal: org.springframework.security.userdetails.User@0: Username: user@myCompany.com; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_ADMINISTRATOR, ROLE_APPROVERPassword: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationD etails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ADMINISTRATOR, ROLE_APPROVER
14:42:46,916 DEBUG AuthenticationProcessingFilter,http-8080-6:351 - Authentication success: org.springframework.security.providers.UsernamePas swordAuthenticationToken@52244b5c: Principal: org.springframework.security.userdetails.User@0: Username: user@myCompany.com; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_ADMINISTRATOR, ROLE_APPROVERPassword: [PROTECTED]; Authenticated: true; Details: org.springframework.security.ui.WebAuthenticationD etails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1%0; SessionId: 3DD2A69652966B47EF55797516040C05; Granted Authorities: ROLE_ADMINISTRATOR, ROLE_APPROVER

and then just a few lines later, I can see the session being invalidated (but shouldn't have this already happened?)

14:42:46,916 DEBUG SessionUtils,http-8080-6:39 - Invalidating session with Id '3DD2A69652966B47EF55797516040C05' and migrating attributes.
14:42:46,916 DEBUG SessionUtils,http-8080-6:39 - Invalidating session with Id '3DD2A69652966B47EF55797516040C05' and migrating attributes.
14:42:46,916 DEBUG HttpSessionEventPublisher,http-8080-6:83 - Publishing event: org.springframework.security.ui.session.HttpSessio nDestroyedEvent[source=org.apache.catalina.session.StandardSession Facade@24928347]
14:42:46,916 DEBUG HttpSessionEventPublisher,http-8080-6:83 - Publishing event: org.springframework.security.ui.session.HttpSessio nDestroyedEvent[source=org.apache.catalina.session.StandardSession Facade@24928347]
14:42:46,916 DEBUG SessionRegistryImpl,http-8080-6:152 - Removing session 3DD2A69652966B47EF55797516040C05 from set of registered sessions
14:42:46,916 DEBUG SessionRegistryImpl,http-8080-6:152 - Removing session 3DD2A69652966B47EF55797516040C05 from set of registered sessions
14:42:46,916 DEBUG SessionRegistryImpl,http-8080-6:164 - Removing session 3DD2A69652966B47EF55797516040C05 from principal's set of registered sessions
14:42:46,916 DEBUG SessionRegistryImpl,http-8080-6:164 - Removing session 3DD2A69652966B47EF55797516040C05 from principal's set of registered sessions

Can anybody tell me what exactly is happening? Could this be an issue with Tomcat holding on to the old session value? I should be able to just log back in since that session should be destroyed.