SEC-2111: Disable auto save of SecurityContext when response committed after startAsync invoked

[spring-projects-issues]

Moosh Ben (Migrated from SEC-2111) said:

Updated Description

Previously Spring Security would disable automatically saving the SecurityContext when the Thread was different than the Thread that created the SaveContextOnUpdateOrErrorResponseWrapper. This worked for many cases, but could cause issues when a timeout occurred. The problem is that a Thread can be reused to process the timeout since the Threads are pooled. This means that a timeout of a request trigger an apparent logout as described in the following workflow:

  - The SecurityContext was established on the SecurityContextHolder
  - An Async request was made
  - The SecurityContextHolder would be cleared out
  - The Async request times out
  - The Async request would be dispatched back to the container upon
    timing out. If the container reused the same Thread to process the
    timeout as the original request, Spring Security would attempt to
    save the SecurityContext when the response was committed. Since the
    SecurityContextHolder was still cleared out it removes the
    SecurityContext from the HttpSession

Spring Security should prevent the SecurityContext from automatically being saved when the response is committed as soon as ServletRequest#startAsync() or ServletRequest#startAsync(ServletRequest,ServletResponse) is called as apposed to looking at the Thread equality.

h1. Original Description

I still see the same behavior on DeferredResult controllers. (after some time there is an auto logout)
It doesn't always happen as it used to before 3.2.0.M1 .

Logs are just before logging out occurs and are related to an AJAX call to a deferredResult method.

Logs:
2013-01-01 16:20:08,019 DEBUG yContextPersistenceFilter:97 - SecurityContextHolder now cleared, as request processing completed
...
2013-01-01 16:21:32,649 DEBUG eToSessionResponseWrapper:140 - Skip saving SecurityContext since processing the HttpServletResponse on a different Thread than the original HttpServletRequest
...
2013-01-01 16:22:01,650 DEBUG SecurityContextRepository:269 - SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
...
2013-01-01 16:22:03,660 DEBUG AntPathRequestMatcher :116 - Checking match of request : '/deferred'; against '/resources/**'
...
2013-01-01 16:22:03,661 DEBUG SecurityContextRepository:139 - HttpSession returned null object for SPRING_SECURITY_CONTEXT
2013-01-01 16:22:03,661 DEBUG SecurityContextRepository:85 - No SecurityContext was available from the HttpSession: org.apache.catalina.session.StandardSessionFacade@5b3cc94b. A new one will be created.
...
2013-01-01 16:22:03,664 DEBUG ymousAuthenticationFilter:102 - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@90541710: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 6D46ACB5AEA101C58A838529A3F6ED1D; Granted Authorities: ROLE_ANONYMOUS'
...
2013-01-01 16:22:03,667 DEBUG FilterSecurityInterceptor:310 - Previously Authenticated: org.springframework.security.authentication.AnonymousAuthenticationToken@90541710: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@166c8: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 6D46ACB5AEA101C58A838529A3F6ED1D; Granted Authorities: ROLE_ANONYMOUS
...
2013-01-01 16:22:03,668 DEBUG AffirmativeBased :65 - Voter: org.springframework.security.web.access.expression.WebExpressionVoter@52d9eb97, returned: -1
...
2013-01-01 16:22:03,668 DEBUG xceptionTranslationFilter:165 - Access is denied (user is anonymous); redirecting to authentication entry point
org.springframework.security.access.AccessDeniedException: Access is denied

[spring-projects-issues]

Rob Winch said:

A few specific questions:

• When you state "(after some time there is an auto logout)", is there activity during this time or is it after some time of no activity?
• How are you processing the DeferredResult? Please be sure to include what Thread is processing the DeferredResult and where you obtain the Thread. Note that Spring Security does not provides automatic integration with a DeferredResult as it does a Callable or WebAsyncTask. Therefore, you should not see the Security Context automatically on other Threads that process the DeferredResult.
• Is it just a single request that appears to be logged out or is it all future requests.
• Do you have the logs just prior to the "auto logout" occurring?

[spring-projects-issues]

Moosh Ben said:

Hi Rob,

During this time there is no activity other than an ongoing connection to a deferred result controller.

#* An AJAX connection is made to ??/deferred??
#* If a message is received via ??/deferred?? then, the AJAX will terminate with success.
#* If there's no message for 2 minutes it will be terminated by spring (using ??AsyncSupportConfigurer??)
#* After termination or a success of the received message, an AJAX connection to ??/deferred?? will be initiated again
#* As it appears after some calls to ??/deferred?? one of these calls seem to create the logout phenomenon (as you can see in the logs)

Here is a code example of how our code looks like. Please note that logging out occurs after a connection timeout and not after a message is sent.

Controller:

@RequestMapping(value = "/deferred",produces = "application/json; charset=utf-8")
@ResponseBody
public DeferredResult<List<Message>> getMessages(@RequestParam(defaultValue = "-1") Long index) {
    DeferredResult<List<Message>> deferredResult = new DeferredResult<List<Message>>(null, Collections.emptyList());
    messageDispatcher.registerDeferredResult(deferredResult, index);
    return deferredResult;
}

DeferredResult Service:

public class MessageDispatcher
{
    public void registerDeferredResult(final DeferredResult<List<Message>> deferredResult, Long index) {
        deferredResults.put(deferredResult);
    }

    public void sendMessaage(Message msg) {
        List<Message> msgList = new ArrayList<Message>();
        msgList.add(msg);

        for (Iterator<DeferredResult<List<Message>>> i = deferredResults.keySet().iterator(); i.hasNext();) {
            DeferredResult<List<Message>> deferredResult = i.next();
            deferredResult.setResult(msgList);
            i.remove();
        }
    }
}

@configuration class:

@Override
public void configureAsyncSupport(AsyncSupportConfigurer configurer) {
    configurer.setDefaultTimeout(120*1000L);
}

Send message controller:

@RequestMapping(value = "/send")
@ResponseBody
public String refreshApplication() throws Exception
{   
    Callable<String> asyncFunc = new Callable<String>() {
        @Override
        public String call() {
            messageDispatcher.sendMessaage(new Message("ok"));              
            return null;
        }
    };

    myService.AsyncSend(asyncFunc);

    return "view";
}

Async Service (myservice):

@Async
public void AsyncSend(Callable<String> asyncFunc) {
    asyncFunc.call();
}

All future request are logged out

As for logs I'm not sure there is anything interesting prior to the logout, in any case I have trouble attaching full logs, if required I will produce logs again without doing anything prior to the logout so you can have clean logs.

My workaround for now is this (works perfectly): ????

[spring-projects-issues]

Moosh Ben said:

Hi Rob,
Were you able to reproduce this?

[spring-projects-issues]

Rob Winch said:

Thank you for the details on how to reproduce the problem I was able to reproduce the issue and understand what is happening. The updates to prevent the logout were to disable automatically saving the SecurityContext when the response was committed if the response was committed on a different Thread than the original request. This works fine except for when the Thread that created the request is reused (since it is in a Thread Pool) to handle a timeout. The only time it causes a problem is when the Thread was reused, so that is why you only experienced intermittent issues.

I have a few ideas on how to resolve the issue, but haven't come to any conclusions on how best to do it just yet. I will post here when I have a snapshot with a fix available (likely within the next week).

[spring-projects-issues]

Rob Winch said:

@mooshben - I have pushed a fix out to to master and it should be deployed to the snapshot repository. A tip on reproducing the issue more consistently is to change the number of threads processing requests to 1. By doing this you ensure that once a timeout occurs the same Thread processes the timeout as was processing the original request and thus you should be able to reproduce the issue consistently. You can try this configuration before updating to the spring-security-web snapshot to ensure that you are consistently able to reproduce the issue. For example, if you are using Tomcat update your connector definition to state maxThreads=1 as shown in the server.xml snippet below:

<Connector connectionTimeout="20000" 
           port="8080"
           protocol="HTTP/1.1"
           redirectPort="8443"
           maxThreads="1"/>

Once you can consistently reproduce the issue update to use spring-security-web-3.2.0.CI-SNAPSHOT.jar and you should see that the issue is gone. I have confirmed this locally with my own sample application but it would not hurt to get validation from you to ensure I have found the correct issue.

Update the spring-security-web dependency to use spring-security-web-3.2.0.CI-SNAPSHOT.jar and you should see the issue is fixed.

[spring-projects-issues]

Moosh Ben said:

Hi Rob,
I missed your last comment.
I will try and reproduce the issue as your suggestion and will use the latest snapshot to confirm the issue was resolved.
Will post here once it's done.

Thanks

[spring-projects-issues]

Moosh Ben said:

I was unable to reproduce it using maxThreads="1" .
In any case I have updated to CI-SNAPSHOT and I should be able to figure out if it was fixed pretty quickly.

Thanks

[spring-projects-issues]

Moosh Ben said:

We have been using your fix for the last week and it seems to work perfectly.
Thanks!

[spring-projects-issues]

Rob Winch said:

Thanks for the bug report and for ensuring to follow up! Given your feedback, I am going to mark this as fixed.

[spring-projects-issues]

This issue relates to #2223