Synchronous operations getting InterruptedException

Java SDK
1

We are using Couchbase to cache session information. All of our Couchbase access for this is synchronous, with multiple retries in case of exceptions.

Multiple times each day we see a cache read or write fail with the message:

“java.lang.RuntimeException: Interrupted while waiting for subscription to complete.”

From reading I have done elsewhere, this happens because the sync operations are wrappers around the async operations, and that got an InterruptedException that was repackaged as a RuntimeException.

Our code looks like this:

public static Object getValue(String key, int exp)
{
    int retries = 5;
    Exception saveE = null;
    for (int i = 0 ; i < retries ; i++)
    {
        try
        {
            if(useCouchbase)
            {
                SerializableDocument doc = bucket.getAndTouch(key, exp, SerializableDocument.class);
                if(null != doc)
                {
                    return doc.content();
                }
                return null;
            }
            else
            {
                return unitTestCache.get(key);
            }
        }
        catch(Exception e)
        {
            saveE = e;
        }
    }
    sendCacheFailureEmail(saveE, "Could not retrieve entry for: " + key);
    return null;
}

and what we see are the failure emails that are sent at the bottom of the method, so we must have gotten an exception each time we tried the operation. We only report the last one, but they’re always the same thing. We get the same sorts of failures (at a lower frequency) from upset calls.

Our code is deployed in Glassfish and it’s single threaded, so the Couchbase operations happen on the main thread. Certainly I don’t know of anything we are doing that is interrupting the thread. Each of our sessions is a series of synchronous calls to our Thrift-based servers, so only one server instance accesses a particular bucket at any one time.

Here is a typical stack trace:

java.lang.RuntimeException: Interrupted while waiting for subscription to complete.
at com.couchbase.client.java.util.Blocking.blockForSingle(Blocking.java:79)
at com.couchbase.client.java.CouchbaseBucket.getAndTouch(CouchbaseBucket.java:299)
at com.couchbase.client.java.CouchbaseBucket.getAndTouch(CouchbaseBucket.java:294)
at com.paceap.eden.jpa.support.CacheOperations.getValue(CacheOperations.java:182)
at com.paceap.eden.session.SessionManager.getSession(SessionManager.java:214)
at sun.reflect.GeneratedMethodAccessor220.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1052)
at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1124)
at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:5388)
at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:619)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:162)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:144)
at sun.reflect.GeneratedMethodAccessor166.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:861)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:370)
at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:5360)
at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5348)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:214)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:89)
at com.sun.proxy.$Proxy206.getSession(Unknown Source)
at com.paceap.eden.session.EJB31_Generated__SessionManager__Intf____Bean.getSession(Unknown Source)
at com.paceap.eden.support.ActivationUtilities.validateSession(ActivationUtilities.java:1515)
at com.paceap.eden.activation.AccountOperations.getLibraryWithFilters(AccountOperations.java:664)
at com.paceap.eden.activation.ActivationHandler.getLibraryWithFilters(ActivationHandler.java:1756)
at sun.reflect.GeneratedMethodAccessor325.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1052)
at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1124)
at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:5388)
at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:619)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
at com.paceap.eden.ejb.TXRetryCommitInterceptor.manageTransaction(TXRetryCommitInterceptor.java:64)
at sun.reflect.GeneratedMethodAccessor266.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:861)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:162)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:144)
at sun.reflect.GeneratedMethodAccessor166.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:861)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:370)
at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:5360)
at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5348)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:214)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:89)
at com.sun.proxy.$Proxy189.getLibraryWithFilters(Unknown Source)
at com.paceap.eden.thrift.activate.backend.ActivationBackend$Processor$getLibraryWithFilters.process(ActivationBackend.java:5186)
at com.paceap.eden.thrift.activate.backend.ActivationBackend$Processor.process(ActivationBackend.java:4919)
at com.paceap.eden.servlets.ActivationServlet.doPost(ActivationServlet.java:186)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:688)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1550)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:281)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:655)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:595)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:161)
at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:331)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231)
at com.sun.enterprise.v3.services.impl.ContainerMapper$AdapterCallable.call(ContainerMapper.java:317)
at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:195)
at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:860)
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:757)
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1056)
at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:229)
at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1325)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:282)
at com.couchbase.client.java.util.Blocking.blockForSingle(Blocking.java:74)
… 88 more

I don’t see much of anything on this topic when I google for it, in particular I haven’t seen anyone who is using sync operations say they see it. That makes me think it must have something to do with our setup, but that’s about all I know at this point.

Can anyone help?

Thanks,
Rush

2

I haven’t heard of an InterruptionException in the SDK before either… You are right, the sync API calls the async API with a CountDownLatch, and it looks like the latch.await gets interrupted.

Any idea on what could interrupt the main thread? Do you see any other form of logs from Glassfish/Grizzly before the stack trace? It is not looking like this StackOverflow question is it?

(btw, which version of Glassfish are you using?)

3

Thank you very much for the helpful reply.

As it turns out, we are running Glassfish 3.1.2.2 and if I grep the logs for “GRIZZLY0023:” I find quite a few of them that correlate nicely in time with the failure emails we have received. Sadly, our logs don’t record the RuntumeException we are seeing, that only goes in the email, but I’m pretty sure this explains at least a subset of what we are seeing.

We will do the library replacement that is suggested and also look at the http timeouts and I’ll post again if we still see problems after that.