Spring 3.2 Long polling causing spring security context to be cleared
Hi all,
I am dealing with the wierdest of issues and having trouble to pin point the cause. I am using Spring 3.2 Milestone 1 to implement a service with long polling (long polling blog example). However for some reason Spring Security 3.1.2 that i use clears the SPRING_SECURITY_CONTEXT immediately after the first deffered result either expires (asynctimeout has been reached and tomcat responds with http.200) or some response is send back to the client. Using Spring Security 3.1.0 this only happens under certain circumstances (HTTPS) but with 3.1.2 it happens always (after the first DefferedResult is fulfilled)!
Here is the debug output of the relevant part of the log
Code:
DEBUG: org.springframework.security.web.util.AntPathRequestMatcher - Checking match of request : '/updates/events'; against '/login*'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
DEBUG: org.springframework.security.web.context.HttpSessionSecurityContextRepository - Obtained a valid SecurityContext from SPRING_SECURITY_CONTEXT: 'org.springframework.security.core.context.SecurityContextImpl@fc783ee2: Authentication: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fc783ee2: Principal: org.springframework.security.core.userdetails.User@33ca09: Username: nvrs; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ADMIN; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@0: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 46EC76439E921FE347EC48ECF71C1258; Granted Authorities: ADMIN'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 2 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 3 of 11 in additional filter chain; firing Filter: 'UsernamePasswordAuthenticationFilter'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 4 of 11 in additional filter chain; firing Filter: 'BasicAuthenticationFilter'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 5 of 11 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 6 of 11 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 7 of 11 in additional filter chain; firing Filter: 'RememberMeAuthenticationFilter'
DEBUG: org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter - SecurityContextHolder not populated with remember-me token, as it already contained: 'org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fc783ee2: Principal: org.springframework.security.core.userdetails.User@33ca09: Username: nvrs; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ADMIN; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@0: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 46EC76439E921FE347EC48ECF71C1258; Granted Authorities: ADMIN'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 8 of 11 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
DEBUG: org.springframework.security.web.authentication.AnonymousAuthenticationFilter - SecurityContextHolder not populated with anonymous token, as it already contained: 'org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fc783ee2: Principal: org.springframework.security.core.userdetails.User@33ca09: Username: nvrs; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ADMIN; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@0: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 46EC76439E921FE347EC48ECF71C1258; Granted Authorities: ADMIN'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 9 of 11 in additional filter chain; firing Filter: 'SessionManagementFilter'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 10 of 11 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 at position 11 of 11 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
DEBUG: org.springframework.security.web.util.AntPathRequestMatcher - Checking match of request : '/updates/events'; against '/updates/**'
DEBUG: org.springframework.security.web.access.intercept.FilterSecurityInterceptor - Secure object: FilterInvocation: URL: /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526; Attributes: [hasAnyRole('ADMIN','MANAGER','INTERNAL')]
DEBUG: org.springframework.security.web.access.intercept.FilterSecurityInterceptor - Previously Authenticated: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@fc783ee2: Principal: org.springframework.security.core.userdetails.User@33ca09: Username: nvrs; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ADMIN; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@0: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 46EC76439E921FE347EC48ECF71C1258; Granted Authorities: ADMIN
DEBUG: org.springframework.security.access.vote.AffirmativeBased - Voter: org.springframework.security.web.access.expression.WebExpressionVoter@52bf21bf, returned: 1
DEBUG: org.springframework.security.web.access.intercept.FilterSecurityInterceptor - Authorization successful
DEBUG: org.springframework.security.web.access.intercept.FilterSecurityInterceptor - RunAsManager did not change Authentication object
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481959526 reached end of additional filter chain; proceeding with original chain
DEBUG: org.springframework.security.web.access.ExceptionTranslationFilter - Chain processed normally
DEBUG: org.springframework.security.web.context.SecurityContextPersistenceFilter - SecurityContextHolder now cleared, as request processing completed
DEBUG: org.springframework.security.web.access.ExceptionTranslationFilter - Chain processed normally
DEBUG: org.springframework.security.web.context.SecurityContextPersistenceFilter - SecurityContextHolder now cleared, as request processing completed
DEBUG: org.springframework.security.web.access.ExceptionTranslationFilter - Chain processed normally
DEBUG: org.springframework.security.web.context.SecurityContextPersistenceFilter - SecurityContextHolder now cleared, as request processing completed
DEBUG: org.springframework.security.web.util.AntPathRequestMatcher - Checking match of request : '/updates/events'; against '/login*'
DEBUG: org.springframework.security.web.util.AntPathRequestMatcher - Checking match of request : '/updates/events'; against '/resources/css/**'
DEBUG: org.springframework.security.web.util.AntPathRequestMatcher - Checking match of request : '/updates/events'; against '/resources/images/**'
DEBUG: org.springframework.security.web.util.AntPathRequestMatcher - Checking match of request : '/updates/events'; against '/resources/*'
DEBUG: org.springframework.security.web.FilterChainProxy - /updates/events?clientId=nvrs1346481959144×tamp=0&_=1346481985081 at position 1 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
DEBUG: org.springframework.security.web.context.HttpSessionSecurityContextRepository - HttpSession returned null object for SPRING_SECURITY_CONTEXT
DEBUG: org.springframework.security.web.context.HttpSessionSecurityContextRepository - No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@61ed10f7. A new one will be created.
If you look carefully at the output you will see the first long poll request "/update" is processed correctly - granted access but after that the spring security context gets cleared as you may see from the line "HttpSession returned null object for SPRING_SECURITY_CONTEXT".
I would like to point out here that i have no custom filters and when i process the long poll request i just store the DefferedResult to a Map with the sessionId as a key for accessing it and sending a result to the client in case a JMS message is received.
Edit: The problem is present for Spring framework 3.2 M1 and the latest 3.2 snapshot build in combination with Spring Security 3.1.2 and its latest snapshot