Method Level Security only working on first call

[WhiteKnight]

I want to use method level security on my GWT application. I'm trying to use Spring Security 3.1, as I found a working example here, but it doesn't use form-login. After reading this answer the first method call successfully obtains the SecurityContext, but then clears it before the next call:

[org.springframework.security.web.context.HttpSessionSecurityContextRepository] - Obtained a valid SecurityContext from SPRING_SECURITY_CONTEXT: 'org.springframework.security.core.context.SecurityContextImpl@6fe9f089: Authentication: org.example.MyAppName.server.auth.MyAppNameUserAuthentication@6fe9f089'
...
[org.springframework.security.access.intercept.aspectj.AspectJMethodSecurityInterceptor] - Authorization successful
...
[org.springframework.security.web.context.SecurityContextPersistenceFilter] - SecurityContextHolder now cleared, as request processing completed
...
[org.springframework.security.web.context.HttpSessionSecurityContextRepository] - SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
[org.springframework.security.web.context.SecurityContextPersistenceFilter] - SecurityContextHolder now cleared, as request processing completed
...
[org.springframework.security.web.context.HttpSessionSecurityContextRepository] - HttpSession returned null object for SPRING_SECURITY_CONTEXT

The second call happens straight after the first and just after the user logs in.

Is it because I followed the other answer and removed

<http pattern="/MyAppName/**" security="none" />

and added

<intercept-url pattern="/MyAppName/**" access="permitAll()" />

My filters are as follows:

<http pattern="/favicon.ico" security="none" />

<http access-decision-manager-ref="accessDecisionManager" use-expressions="true" auto-config="false" entry-point-ref="LoginUrlAuthenticationEntryPoint">
  <form-login login-page="/Login.html" always-use-default-target="true" default-target-url="/Main.html?gwt.codesvr=127.0.0.1:9997" />
  <intercept-url pattern="/Login.html" access="permitAll()" />
  <intercept-url pattern="/Login2.html" access="permitAll()" />
  <intercept-url pattern="/MyAppName/**" access="permitAll()" />
  <intercept-url pattern="/**" access="isAuthenticated()" />
  <logout delete-cookies="JSESSIONID" logout-success-url="/Login.html" />
  <remember-me token-validity-seconds="86400" key="key" user-service-ref="userDetailsService" />
</http>

Following the example I obtained I use AspectJ for the global method security, but would not use it if I could get that working, as I haven't used AspectJ before:

<global-method-security secured-annotations="enabled" pre-post-annotations="enabled" mode="aspectj" proxy-target-class="true" >
  <expression-handler ref="expressionHandler"/>
</global-method-security>

Thank you for taking the time to read this

Please let me know if more detail is needed.

[Rob Winch]

It sounds like you had a few problems and solved them. I'm not sure I understand what the problem you are currently facing is. Perhaps I am just missing something, but making it very clear what you are doing, what you expect to happen, and what actually happens would make it easier to assist you.

[WhiteKnight]

I've been trying to get method security working, as I already have URL security working.

When a user logs in the first annotation succeeds as it get the SecurityContext from SPRING_SECURITY_CONTEXT in HttpSession, but the next fail as SPRING_SECURITY_CONTEXT is null.

Why does this happen?

I'm new to Spring and Spring Security, but I have got two factor authentication working, so I have a basic understanding of how it works.

[Luke Taylor]

When a user logs in the first annotation succeeds as it get the SecurityContext from SPRING_SECURITY_CONTEXT in HttpSession, but the next fail as SPRING_SECURITY_CONTEXT is null.

Sounds like you are losing the session.

[WhiteKnight]

Thank you for your suggestion.

My session is set to last for 60 minutes. In my web.xml I have the following:

<session-config>
  <session-timeout>60</session-timeout>
</session-config>

Is there a way I can confirm that the session is timing out?

Four of the methods that I'm trying to secure are called from a page that is shown directly after logging in and so that calls happen one after the other, where the first one (or batch as Spring Security seems to generally handle the first 3 in a batch) succeeds, but the following calls fail. The time from log in to the failed call in one test was 4 seconds due to the debug logging.

[Luke Taylor]

It doesn't have to be a timeout - you may not be submitting the session cookie, for example. You should also be able to monitor the requests and responses in your browser to make sure the session information matches.

[WhiteKnight]

The cookie (JSESSIONID) stays constant after logging in and even after the failed method call and the JSESSIONID is in the HTTP POSTs in the log. The SecurityContext changes from my custom authentication object to null.

Following from your suggestion I created a HttpSessionListener and the session is created after login, but not destroy afterwards, even after the failed method call. I can confirm that the destroy session entry is being logged, as the session is recreated after the user passes the second factor of authentication.

[Luke Taylor]

I don't really know what you're describing here. What does the second-factor do? Unless you can produce a clear sequence of requests that are sent and the corresponding log output it's very difficult to say what's wrong. For example, perhaps you are sending multiple concurrent requests through the security filters before the user is fully authenticated and there is a race-condition wrt accessing the SecurityContext? Monitor the request from your browser and how they are processed through the filter chain (which is listed in detail in the debug log).

[WhiteKnight]

Thank you for your continued assistance.

I've removed the second factor of authentication to simplify the process.

Now the use logs in:

17:13:11,709 DEBUG [org.springframework.security.authentication.ProviderManager] - Authentication attempt using com.example.MyAppName.server.auth.MyAppNameAuthenticationProvider
14-Jul-2011 17:13:11 com.example.MyAppName.server.SessionListener sessionCreated
SEVERE: Session Created
17:13:12,308 DEBUG [org.springframework.web.context.support.XmlWebApplicationContext] - Publishing event in Root WebApplicationContext: org.springframework.security.authentication.event.AuthenticationSuccessEvent[source=com.example.MyAppName.server.auth.MyAppNameUserAuthentication@6b499c6]

After a few calls to get HTML and other page related content the first method is called:

17:13:13,888 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 1 of 10 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
17:13:13,888 DEBUG [org.springframework.security.web.context.HttpSessionSecurityContextRepository] - Obtained a valid SecurityContext from SPRING_SECURITY_CONTEXT: 'org.springframework.security.core.context.SecurityContextImpl@6b499c6: Authentication: com.example.MyAppName.server.auth.MyAppNameUserAuthentication@6b499c6'
17:13:13,888 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 2 of 10 in additional filter chain; firing Filter: 'LogoutFilter'
17:13:13,888 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 3 of 10 in additional filter chain; firing Filter: 'UsernamePasswordAuthenticationFilter'
17:13:13,888 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 4 of 10 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
17:13:13,892 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 5 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
17:13:13,892 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 6 of 10 in additional filter chain; firing Filter: 'RememberMeAuthenticationFilter'
17:13:13,893 DEBUG [org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter] - SecurityContextHolder not populated with remember-me token, as it already contained: 'com.example.MyAppName.server.auth.MyAppNameUserAuthentication@6b499c6'
17:13:13,893 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 7 of 10 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
17:13:13,895 DEBUG [org.springframework.security.web.authentication.AnonymousAuthenticationFilter] - SecurityContextHolder not populated with anonymous token, as it already contained: 'com.example.MyAppName.server.auth.MyAppNameUserAuthentication@6b499c6'
17:13:13,895 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 8 of 10 in additional filter chain; firing Filter: 'SessionManagementFilter'
17:13:13,895 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
17:13:13,895 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
17:13:13,896 DEBUG [org.springframework.security.web.util.AntPathRequestMatcher] - Checking match of request : '/myappname/myappnameservice'; against '/favicon.ico'
17:13:13,896 DEBUG [org.springframework.security.web.util.AntPathRequestMatcher] - Checking match of request : '/myappname/myappnameservice'; against '/login.html'
17:13:13,896 DEBUG [org.springframework.security.web.util.AntPathRequestMatcher] - Checking match of request : '/myappname/myappnameservice'; against '/j_spring_security_check'
17:13:13,896 DEBUG [org.springframework.security.web.util.AntPathRequestMatcher] - Checking match of request : '/myappname/myappnameservice'; against '/myappname/**'
17:13:13,896 DEBUG [org.springframework.security.web.access.intercept.FilterSecurityInterceptor] - Secure object: FilterInvocation: URL: /myappname/myAppNameService; Attributes: [permitAll()]
17:13:13,896 DEBUG [org.springframework.security.web.access.intercept.FilterSecurityInterceptor] - Previously Authenticated: com.example.MyAppName.server.auth.MyAppNameUserAuthentication@6b499c6
17:13:13,896 DEBUG [org.springframework.security.access.vote.UnanimousBased] - Voter: com.example.MyAppName.server.auth.TwoFactorAuthenticationVoter@2324fb16, returned: 0
17:13:13,896 DEBUG [org.springframework.security.access.vote.UnanimousBased] - Voter: org.springframework.security.access.vote.RoleVoter@50e07360, returned: 0
17:13:13,896 DEBUG [org.springframework.security.access.vote.UnanimousBased] - Voter: org.springframework.security.access.vote.AuthenticatedVoter@3fb6cd1b, returned: 0
17:13:13,896 DEBUG [org.springframework.security.access.vote.UnanimousBased] - Voter: org.springframework.security.web.access.expression.WebExpressionVoter@27b47740, returned: 1
17:13:13,896 DEBUG [org.springframework.security.web.access.intercept.FilterSecurityInterceptor] - Authorization successful
17:13:13,896 DEBUG [org.springframework.security.web.access.intercept.FilterSecurityInterceptor] - RunAsManager did not change Authentication object
17:13:13,896 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService reached end of additional filter chain; proceeding with original chain
17:13:13,907 DEBUG [org.springframework.security.access.prepost.PrePostAnnotationSecurityMetadataSource] - Looking for Pre/Post annotations for method 'secureMethod1' on target class 'class com.example.MyAppName.server.MyAppNameServiceImpl'
17:13:13,914 DEBUG [org.springframework.security.access.prepost.PrePostAnnotationSecurityMetadataSource] - No expression annotations found
17:13:13,915 DEBUG [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] - Adding security method [CacheKey[com.example.MyAppName.server.MyAppNameServiceImpl; public com.example.MyAppName.shared.Type1 com.example.MyAppName.server.MyAppNameServiceImpl.secureMethod1()]] with attributes [ROLE_USER]
17:13:13,915 DEBUG [org.springframework.security.access.intercept.aspectj.AspectJMethodSecurityInterceptor] - Secure object: org.springframework.security.access.intercept.aspectj.MethodInvocationAdapter@1fed9fff; Attributes: [ROLE_USER]
17:13:13,917 DEBUG [org.springframework.security.access.intercept.aspectj.AspectJMethodSecurityInterceptor] - Previously Authenticated: com.example.MyAppName.server.auth.MyAppNameUserAuthentication@6b499c6
17:13:13,918 DEBUG [org.springframework.security.access.vote.AffirmativeBased] - Voter: org.springframework.security.access.prepost.PreInvocationAuthorizationAdviceVoter@4f54fbfe, returned: 0
17:13:13,918 DEBUG [org.springframework.security.access.vote.AffirmativeBased] - Voter: org.springframework.security.access.vote.RoleVoter@546c0962, returned: 1
17:13:13,918 DEBUG [org.springframework.security.access.intercept.aspectj.AspectJMethodSecurityInterceptor] - Authorization successful
17:13:13,918 DEBUG [org.springframework.security.access.intercept.aspectj.AspectJMethodSecurityInterceptor] - RunAsManager did not change Authentication object
...
17:13:14,051 DEBUG [org.springframework.security.web.context.HttpSessionSecurityContextRepository] - SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
17:13:14,051 DEBUG [org.springframework.security.web.context.SecurityContextPersistenceFilter] - SecurityContextHolder now cleared, as request processing completed
17:13:14,051 DEBUG [org.springframework.web.filter.RequestContextFilter] - Cleared thread-bound request context: POST /myappname/myAppNameService HTTP/1.1

Then the next method is called:

17:13:14,678 DEBUG [org.springframework.security.web.FilterChainProxy] - /myappname/myAppNameService at position 1 of 10 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
17:13:14,678 DEBUG [org.springframework.security.web.context.HttpSessionSecurityContextRepository] - HttpSession returned null object for SPRING_SECURITY_CONTEXT
17:13:14,678 DEBUG [org.springframework.security.web.context.HttpSessionSecurityContextRepository] - No SecurityContext was available from the HttpSession: org.mortbay.jetty.servlet.HashSessionManager$Session:1t7zqd181e5jf@492609590. A new one will be created.

Both method calls are on the same page and happen straight after the user has logged in and require no further interaction from the user.

I tried to provide as much of the log as possible, without providing unrelated data. I can supply a complete log or more of the log if that would be better.

[Luke Taylor]

The line:

SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.

implies that the SecurityContext has been cleared by the time the request completes, either during the request or by another thread. So what happens between 17:13:13,918 and 17:13:14,051 may be relevant.