org.infinispan.util.concurrent.TimeoutException when using async servlet in HA mode

[nkuroczycki]

Hi,

I have noticed that I'm receiving the infinispan exceptions when using asynchronous servlets in conjunction with a standalone-ha profile. This was working in 8.1.0.CR1, but since taking 8.1.0.Final I see the stacktrace below.

Is there a workaround or is this a known issue (couldn't find anything on the forum)?

Thanks,

Nathan

Details...

I have managed to simplify the test case into the following async servlet...

    @Override
    public void doGet(final HttpServletRequest request, final HttpServletResponse response) throws ServletException,
        IOException
    {
        final AsyncContext asyncContext = request.startAsync();
        asyncContext.start(new Runnable()
        {
            public void run()
            {
                System.out.println("Date=" + new Date().toString());
                asyncContext.complete();
            }
        });
    }

The web.xml of the war has the <distributable/> tag and the servlet element has <async-supported>true</async-supported> present.

[exec] 14:21:48,430 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-4) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [mCEfhC-hhlkW0WK_L1m9kl4P] for requestor [GlobalTransaction:<CLUSTER_NODE_001/web>:15:local]! Lock held by [GlobalTransaction:<CLUSTER_NODE_001/web>:14:local]

     [exec] at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198)

     [exec] at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171)

     [exec] at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:169)

     [exec] at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.lockAndRegisterBackupLock(PessimisticLockingInterceptor.java:291)

     [exec] at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitReplaceCommand(PessimisticLockingInterceptor.java:179)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112)

     [exec] at org.infinispan.commands.AbstractVisitor.visitReplaceCommand(AbstractVisitor.java:42)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

     [exec] at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255)

     [exec] at org.infinispan.interceptors.TxInterceptor.visitReplaceCommand(TxInterceptor.java:201)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112)

     [exec] at org.infinispan.commands.AbstractVisitor.visitReplaceCommand(AbstractVisitor.java:42)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

     [exec] at org.infinispan.statetransfer.StateTransferInterceptor.handleNonTxWriteCommand(StateTransferInterceptor.java:206)

     [exec] at org.infinispan.statetransfer.StateTransferInterceptor.visitReplaceCommand(StateTransferInterceptor.java:161)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

     [exec] at org.infinispan.interceptors.CacheMgmtInterceptor.updateStoreStatistics(CacheMgmtInterceptor.java:148)

     [exec] at org.infinispan.interceptors.CacheMgmtInterceptor.visitReplaceCommand(CacheMgmtInterceptor.java:139)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

     [exec] at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110)

     [exec] at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73)

     [exec] at org.infinispan.commands.AbstractVisitor.visitReplaceCommand(AbstractVisitor.java:42)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

     [exec] at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:66)

     [exec] at org.infinispan.commands.AbstractVisitor.visitReplaceCommand(AbstractVisitor.java:42)

     [exec] at org.infinispan.commands.write.ReplaceCommand.acceptVisitor(ReplaceCommand.java:55)

     [exec] at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333)

     [exec] at org.infinispan.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1306)

     [exec] at org.infinispan.CacheImpl.replaceInternal(CacheImpl.java:943)

     [exec] at org.infinispan.CacheImpl.replace(CacheImpl.java:936)

     [exec] at org.infinispan.DecoratedCache.replace(DecoratedCache.java:451)

     [exec] at org.infinispan.AbstractDelegatingCache.replace(AbstractDelegatingCache.java:246)

     [exec] at org.jboss.as.clustering.infinispan.invoker.Mutator$MutateOperation.invoke(Mutator.java:50)

     [exec] at org.jboss.as.clustering.infinispan.invoker.SimpleCacheInvoker.invoke(SimpleCacheInvoker.java:34)

     [exec] at org.jboss.as.clustering.infinispan.invoker.RetryingCacheInvoker.invoke(RetryingCacheInvoker.java:82)

     [exec] at org.wildfly.clustering.web.infinispan.CacheEntryMutator.mutate(CacheEntryMutator.java:59)

     [exec] at org.wildfly.clustering.web.infinispan.session.InfinispanSession.close(InfinispanSession.java:94)

     [exec] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager$SchedulableSession.close(InfinispanSessionManager.java:378)

     [exec] at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:71)

     [exec] at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:719) [undertow-servlet-1.0.15.Final.jar:1.0.15.Final]

     [exec] at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:522) [undertow-servlet-1.0.15.Final.jar:1.0.15.Final]

     [exec] at io.undertow.servlet.spec.AsyncContextImpl$3.run(AsyncContextImpl.java:294) [undertow-servlet-1.0.15.Final.jar:1.0.15.Final]

     [exec] at io.undertow.servlet.spec.AsyncContextImpl$6.run(AsyncContextImpl.java:432) [undertow-servlet-1.0.15.Final.jar:1.0.15.Final]

     [exec] at io.undertow.servlet.spec.AsyncContextImpl$TaskDispatchRunnable.run(AsyncContextImpl.java:517) [undertow-servlet-1.0.15.Final.jar:1.0.15.Final]

     [exec] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_51]

     [exec] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_51]

     [exec] at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_51]

[pferraro]

This should be fixed in WildFly 8.1.0.Final.

[nkuroczycki]

Unfortunately that does not seem to be the case - the above test case will throw the specified exception in WF 8.1.0.Final.

Reverting back to Undertow 1.0.5.Final addresses the issue. Not sure of the relevance and it could be a coincidence, but after further investigation and debugging it seems reverting the changes for the following issue in Undertow 1.0.15.Final prevents the exception being thrown. However, that in-itself reintroduces a bug...

[WFLY-3295] AsyncContext#start runs in caller thread - JBoss Issue Tracker

[pferraro]

Sorry I missed your response.

We don't actually have any async servlet tests in our clustering testsuite.  I'll reproduce this issue today and should have a fix by the end of day today.

[pferraro]

I've submitted a fix here: WFLY-3715 Async servlets cause lock timeouts for distrubutable sessions by pferraro · Pull Request #6580 · wildfly/wildf…

[grkjava]

Same issue i'm getting on wildly 8.1.0 Final, Is there any workaround to fix this issue.

-Ravi

[nkuroczycki]

Thanks Paul - I hope to trial the fix at some point soon.

Thanks,

Nathan

[pferraro]

This is a known issue in 8.1.0.Final.  The fix was too extensive to port to 8.x, but is included in 9.0.0.Alpha1.

[grkjava]

Thanks Paul, is there any workaround in 8.1.0.Final?

I'm using standalone, recently we started upgrading it to 8.1.0.Final. Again upgrading it to 9.0.0.Alpha1 is very difficult now and it will impact on our project deliverable.

Could you please help on this issue and provide some workaround.

Best Regards,

Ravi Kumar

[scarpent]

Any word on this one? I'm seeing this in 8.1.0 also.

[pferraro]

See my previous comment: Re: org.infinispan.util.concurrent.TimeoutException when using async servlet in HA mode