Spring Security
  1. Spring Security
  2. SEC-2111

Disable auto save of SecurityContext when response committed after startAsync invoked

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 3.2.0.M1
    • Fix Version/s: 3.2.0.M2
    • Component/s: None
    • Labels:
      None

      Description

      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.

      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
      

        Issue Links

          Activity

          Hide
          Rob Winch added a comment -

          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?
          Show
          Rob Winch added a comment - 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?
          Hide
          Moosh Ben added a comment - - edited

          Hi Rob,

          1. 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)
          2. 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();
            }
            
            
          1. All future request are logged out
          2. 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.
          3. My workaround for now is this (works perfectly): <http pattern="/deferred" security="none" />
          Show
          Moosh Ben added a comment - - edited 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): <http pattern="/deferred" security="none" />
          Hide
          Moosh Ben added a comment -

          Hi Rob,
          Were you able to reproduce this?

          Show
          Moosh Ben added a comment - Hi Rob, Were you able to reproduce this?
          Hide
          Rob Winch added a comment -

          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).

          Show
          Rob Winch added a comment - 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).
          Hide
          Rob Winch added a comment - - edited

          @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.

          Show
          Rob Winch added a comment - - edited @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.
          Hide
          Moosh Ben added a comment -

          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

          Show
          Moosh Ben added a comment - 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
          Hide
          Moosh Ben added a comment -

          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

          Show
          Moosh Ben added a comment - 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
          Hide
          Moosh Ben added a comment -

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

          Show
          Moosh Ben added a comment - We have been using your fix for the last week and it seems to work perfectly. Thanks!
          Hide
          Rob Winch added a comment -

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

          Show
          Rob Winch added a comment - Thanks for the bug report and for ensuring to follow up! Given your feedback, I am going to mark this as fixed.

            People

            • Assignee:
              Rob Winch
              Reporter:
              Moosh Ben
            • Votes:
              1 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: