Concurrent thread access to conversation components during conversation timeout

[andrewduckworth]

Our application is using Seam 2.0.2. During timeout processing for conversations, it appears that org.jboss.seam.core.Manager allows concurrent thread access to conversation scoped components and does not enforce normal conversation locking. This can cause major problems in components that expect single threaded behaviour and in our application that has some legacy Hibernate Session management, this can lead to multi-threaded access to the same HB session causing unpredictable results.

I have verified the issue using a simple POJO and Seam Gen. The code for the POJO is as follows, (the large sleeps are to be able to easily reproduce the race condition):

package org.domain.myseamwebproject.managertest;

import java.text.SimpleDateFormat;
import java.util.Date;

import org.jboss.seam.ScopeType;
import org.jboss.seam.annotations.Create;
import org.jboss.seam.annotations.Destroy;
import org.jboss.seam.annotations.Logger;
import org.jboss.seam.annotations.Name;
import org.jboss.seam.annotations.Observer;
import org.jboss.seam.annotations.Scope;
import org.jboss.seam.core.Conversation;
import org.jboss.seam.log.Log;

@Name("convScopedBean")
@Scope(ScopeType.CONVERSATION)
public class ConvScopedBean
{
    int activeDestroyThreads = 0;
   
    int activeTimeoutThreads = 0;
   
    @Logger
    Log log;
   
    @Create
    public void create()
    {
        log.info("Bean created {0}", beanId());
    }
   
    @Destroy
    public void destroy()
    {
        activeDestroyThreads++;
        log.info("Bean destroy starting on bean {0} in thread: {1} with {2} active destroy threads", beanId(), getCurrentThreadDetails(), activeDestroyThreads);
        try
        {
            Thread.sleep(10000);
        }
        catch (InterruptedException e)
        {
            e.printStackTrace();
        }
        log.info("Bean destroy finished on bean {0} in thread: {1} with {2} active destroy threads", beanId(), getCurrentThreadDetails(), activeDestroyThreads);
        activeDestroyThreads--;
    }

    private String getCurrentThreadDetails()
    {
        return Thread.currentThread().getName() + " id:" + Thread.currentThread().getId();
    }

    private String beanId()
    {
        return String.valueOf(System.identityHashCode(this));
    }
   
    public String getConversationId()
    {
        return Conversation.instance().getId();
    }
   
    public String getCurrentTime()
    {
        return (new SimpleDateFormat("hh:mm:ss")).format(new Date());
    }
   
    @Observer("org.jboss.seam.conversationTimeout")
    public void conversationTimeout(String cid)
    {
        activeTimeoutThreads++;
        log.info("Conversation timeout starting on bean {0} in thread: {1} with {2} active timeout threads", beanId(), getCurrentThreadDetails(), activeTimeoutThreads);
        try
        {
            Thread.sleep(10000);
        }
        catch (InterruptedException e)
        {
            e.printStackTrace();
        }
        log.info("Conversation timeout finished on bean {0} in thread: {1} with {2} active timeout threads", beanId(), getCurrentThreadDetails(), activeTimeoutThreads);
        activeTimeoutThreads--;
    }

}


On the xhtml page, I have an a4j:poll that polls getCurrentTime:

    <f:facet name="header">View Conversation</f:facet>
    <p>The current long running conversation is: #{convScopedBean.conversationId}</p>
    <p>The current time is: </p> <h:outputText id="currentTime" value="#{convScopedBean.currentTime}"/>
    <a4j:poll id="poll" interval="1000" enabled="true" reRender="poll,currentTime"/>
   
    <div class="actionButtons">
            <s:button value="Go to Home"  propagation="none" action="home"/>
        </div>

As soon as the background expired conversation starts to get destroyed during a a4j:poll event, I click the s:button to generate a concurrent request to the same bean. The following log shows that the convScopedBean has multi-threaded access:

16:53:25,763 INFO  [ConvScopedBean] Bean created 2923901
16:53:29,199 INFO  [ConvScopedBean] Bean created 7938954
16:53:54,317 INFO  [ConvScopedBean] Conversation timeout starting on bean 7938954 in thread: http-0.0.0.0-8080-3 id:79 with 1 active timeout threads
16:54:04,318 INFO  [ConvScopedBean] Conversation timeout finished on bean 7938954 in thread: http-0.0.0.0-8080-3 id:79 with 1 active timeout threads
16:54:04,321 INFO  [ConvScopedBean] Bean destroy starting on bean 12791208 in thread: http-0.0.0.0-8080-3 id:79 with 1 active destroy threads
16:54:14,322 INFO  [ConvScopedBean] Bean destroy finished on bean 12791208 in thread: http-0.0.0.0-8080-3 id:79 with 1 active destroy threads
16:55:28,896 INFO  [ConvScopedBean] Conversation timeout starting on bean 7938954 in thread: http-0.0.0.0-8080-3 id:79 with 1 active timeout threads
16:55:29,983 INFO  [Manager] destroying conversation with garbage lock: 7
16:55:29,985 INFO  [ConvScopedBean] Bean created 12033604
16:55:29,987 INFO  [ConvScopedBean] Conversation timeout starting on bean 12033604 in thread: http-0.0.0.0-8080-2 id:78 with 1 active timeout threads
16:55:31,492 INFO  [Manager] destroying conversation with garbage lock: 7
16:55:31,494 INFO  [ConvScopedBean] Bean created 7531789
16:55:31,496 INFO  [ConvScopedBean] Conversation timeout starting on bean 7531789 in thread: http-0.0.0.0-8080-1 id:77 with 1 active timeout threads
16:55:38,897 INFO  [ConvScopedBean] Conversation timeout finished on bean 7938954 in thread: http-0.0.0.0-8080-3 id:79 with 1 active timeout threads
16:55:38,900 INFO  [ConvScopedBean] Bean destroy starting on bean 2923901 in thread: http-0.0.0.0-8080-3 id:79 with 1 active destroy threads
16:55:39,988 INFO  [ConvScopedBean] Conversation timeout finished on bean 12033604 in thread: http-0.0.0.0-8080-2 id:78 with 1 active timeout threads
16:55:39,991 INFO  [ConvScopedBean] Bean destroy starting on bean 2923901 in thread: http-0.0.0.0-8080-2 id:78 with 2 active destroy threads
16:55:41,497 INFO  [ConvScopedBean] Conversation timeout finished on bean 7531789 in thread: http-0.0.0.0-8080-1 id:77 with 1 active timeout threads
16:55:41,500 INFO  [ConvScopedBean] Bean destroy starting on bean 2923901 in thread: http-0.0.0.0-8080-1 id:77 with 3 active destroy threads
16:55:48,901 INFO  [ConvScopedBean] Bean destroy finished on bean 2923901 in thread: http-0.0.0.0-8080-3 id:79 with 3 active destroy threads
16:55:49,992 INFO  [ConvScopedBean] Bean destroy finished on bean 2923901 in thread: http-0.0.0.0-8080-2 id:78 with 2 active destroy threads
16:55:50,041 INFO  [ConvScopedBean] Bean destroy starting on bean 12033604 in thread: http-0.0.0.0-8080-2 id:78 with 1 active destroy threads
16:55:51,501 INFO  [ConvScopedBean] Bean destroy finished on bean 2923901 in thread: http-0.0.0.0-8080-1 id:77 with 1 active destroy threads
16:55:51,536 INFO  [ConvScopedBean] Bean destroy starting on bean 7531789 in thread: http-0.0.0.0-8080-1 id:77 with 1 active destroy threads
16:56:00,042 INFO  [ConvScopedBean] Bean destroy finished on bean 12033604 in thread: http-0.0.0.0-8080-2 id:78 with 1 active destroy threads
16:56:01,538 INFO  [ConvScopedBean] Bean destroy finished on bean 7531789 in thread: http-0.0.0.0-8080-1 id:77 with 1 active destroy threads


Can someone tell me if this is a known issue an that @Destroy and @Observer(endConversation) need to manage their own synchronization ? I have looked at the 2.2.1 release and the same issue looks like it is still present. If it would be helpful to have the entire test application WAR, please let me know and I can send it.

Thanks for any help,

Andrew

[serkan.s.eskici.online.nl]

See http://docs.jboss.org/seam/2.0.2.SP1/reference/en-US/html/conversations.html#d0e5846

Basically, there are 2 solutions:

1. Give the concurrent-request-timeout parameter a bigger value in your pages.xml or (globally) in your components.xml.


2. Or use @Asynchronous.

[andrewduckworth]

Thanks for the reply Serkan, however I don't think it answers my question. What I was trying to highlight was that Seam does not act according to my understanding of the documentation in this case and *is* allowing concurrent access to the conversation scoped component. If you look at section "4.1.10. Concurrency model" in the documentation it states that:

"Finally, Seam enforces a single thread per conversation per process model for the conversation context by serializing concurrent requests in the same long-running conversation context. "

and

"This concurrency model means that AJAX clients can safely use volatile session and conversational state, without the need for any special work on the part of the developer. "

This appears to be circumvented during the conversation destroy process because the Manager component will proceed with destroying the conversation even when it cannot obtain a lock on it. The following code is an excerpt from Manager, you will notice that even when it cannot lock, it will proceed with the destroy assuming the lock was never released by some previous request, when in fact the lock may be held by another thread actively destroying the conversation.

   public void conversationTimeout(Map<String, Object> session)
   {
      long currentTime = System.currentTimeMillis();
      ConversationEntries conversationEntries = ConversationEntries.getInstance();
      if (conversationEntries!=null)
      {
         List<ConversationEntry> entries = new ArrayList<ConversationEntry>( conversationEntries.getConversationEntries() );
         for (ConversationEntry conversationEntry: entries)
         {
            boolean locked = conversationEntry.lockNoWait(); //we had better not wait for it, or we would be waiting for ALL other requests
            try
            {
               long delta = currentTime - conversationEntry.getLastRequestTime();
               if ( delta > conversationEntry.getTimeout() )
               {
                  if ( locked )
                  {
                     if ( log.isDebugEnabled() )
                     {
                        log.debug("conversation timeout for conversation: " + conversationEntry.getId());
                     }
                  }
                  else
                  {
                     //if we could not acquire the lock, someone has left a garbage lock lying around
                     //the reason garbage locks can exist is that we don't require a servlet filter to
                     //exist - but if we do use SeamExceptionFilter, it will clean up garbage and this
                     //case should never occur
                    
                     //NOTE: this is slightly broken - in theory there is a window where a new request
                     //      could have come in and got the lock just before us but called touch() just
                     //      after we check the timeout - but in practice this would be extremely rare,
                     //      and that request will get an IllegalMonitorStateException when it tries to
                     //      unlock() the CE
                     log.info("destroying conversation with garbage lock: " + conversationEntry.getId());
                  }
                  if ( Events.exists() )
                  {
                     Events.instance().raiseEvent("org.jboss.seam.conversationTimeout", conversationEntry.getId());
                  }
                  destroyConversation( conversationEntry.getId(), session );
               }
            }
            finally
            {
               if (locked) conversationEntry.unlock();
            }
         }
      }
   }

[serkan.s.eskici.online.nl]

Seam actually serializes the threads for conversation scoped beans, however in some cases the default value of concurrent-request-timeout parameter is too short and that's why you'll get an exception.

You just have to re-finetune this parameter and then it should work. But remember than, that you won't get true asynchronousity (if that's needed).

[marcelkolsteren]

Hi Andrew,

I'm a little late, but I still would like to react on the issue you brought up. Yesterday I ran into another symptom of the problematic implementation of conversation timeout. The symptom is memory leakage. I agree that the timeout implementation is harmful and not compliant with the documentation.

The memory leakage that we observed could be reproduced by pressing and holding the refresh button of the browser. In this scenario, multiple HTTP threads handle the GET requests in parallel, where each GET request is starting a new conversation. Because our conversation timeout is quite short, conversations were getting removed by the timeout mechanism, even while the first request for those conversations was still running! The thread that triggers the conversation timeout just ignores the conversation lock and cleans the conversation data. However, the thread that owns the lock still manages to write the conversation to the session after the timeout has been processed. This results in a conversation that partially dangles in the session, not picked up by the timeout mechanism any more, and not eligible for garbage collection. So it stays in memory until the session expires (we could prove that by making heap dumps).

We solved the issue by installing our own extension of the (Faces)Manager, which replaces the conversationTimeout method with a variant that only expires a conversation if it can acquire the lock on the conversation entry.