When looking through some logs after a glassfish server was being unresponsive, I came upon this error :
{{[#|2016-06-02T08:37:51.737+0200|WARNING|oracle-
glassfish3.1.2|org.restlet.Component.ServiceDispatcher|_ThreadID=165;_ThreadName=http-thread-pool-37860(5);|Exception or error caught in status service
javax.ejb.EJBException
at com.sun.ejb.containers.BaseContainer.processSystemException(BaseContainer.java:5236)
at com.sun.ejb.containers.BaseContainer.checkExceptionNoTx(BaseContainer.java:5065)
at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4900)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2046)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1995)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:222)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:89)
at com.sun.proxy.$Proxy228.getKpiValuesFlat(Unknown Source)
at com.business.renderer.TopSuppliers.getData(TopSuppliers.java:174)
at com.business.renderer.TopSuppliers.getDataAsJSONTopSuppliers.java:179)
at com.business.renderer.TopSuppliers.render(TopSuppliers.java:107)
at com.ui.renderer.engine.AbstractRenderingEngine.render(AbstractRenderingEngine.java:140)
at com.services.filter.ContainerAdapter.represent(ContainerAdapter.java:311)
at org.restlet.resource.Resource.getRepresentation(Resource.java:259)
at org.restlet.resource.Resource.handleGet(Resource.java:425)
at org.restlet.resource.Finder.handle(Finder.java:470)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.routing.Router.doHandle(Router.java:497)
at org.restlet.routing.Router.handle(Router.java:737)
at com.servlets.ServiceDispatcher$1.handle(ServiceDispatcher.java:55)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.engine.application.StatusFilter.doHandle(StatusFilter.java:151)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.engine.ChainHelper.handle(ChainHelper.java:111)
at org.restlet.engine.application.ApplicationHelper.handle(ApplicationHelper.java:72)
at org.restlet.Application.handle(Application.java:388)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.routing.Router.doHandle(Router.java:497)
at org.restlet.routing.Router.handle(Router.java:737)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.routing.Router.doHandle(Router.java:497)
at org.restlet.routing.Router.handle(Router.java:737)
at org.restlet.routing.Filter.doHandle(Filter.java:156)
at org.restlet.routing.Filter.handle(Filter.java:203)
at org.restlet.engine.ChainHelper.handle(ChainHelper.java:111)
at org.restlet.Component.handle(Component.java:387)
at org.restlet.Server.handle(Server.java:488)
at org.restlet.engine.ServerHelper.handle(ServerHelper.java:71)
at org.restlet.engine.http.HttpServerHelper.handle(HttpServerHelper.java:150)
at org.restlet.ext.servlet.ServerServlet.service(ServerServlet.java:1037)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1554)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:339)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at com.jamonapi.JAMonFilter.doFilter(JAMonFilter.java:59)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:278)
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.core.StandardPipeline.doInvoke(StandardPipeline.java:655)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:595)
at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:334)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:230)
at com.sun.enterprise.v3.services.impl.ContainerMapper$AdapterCallable.call(ContainerMapper.java:311)
at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:189)
at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:850)
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:747)
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1032)
at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:231)
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: Exception [EclipseLink-2004] (Eclipse Persistence Services - 2.3.4.v20151027-346465e): org.eclipse.persistence.exceptions.ConcurrencyException
Exception Description: A signal was attempted before wait() on ConcurrencyManager. This normally means that an attempt was made to
commit or rollback a transaction before it was started, or to rollback a transaction twice.
at org.eclipse.persistence.exceptions.ConcurrencyException.signalAttemptedBeforeWait(ConcurrencyException.java:84)
at org.eclipse.persistence.internal.helper.ConcurrencyManager.releaseReadLock(ConcurrencyManager.java:489)
at org.eclipse.persistence.internal.identitymaps.CacheKey.releaseReadLock(CacheKey.java:386)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.cloneAndRegisterObject(UnitOfWorkImpl.java:1018)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.cloneAndRegisterObject(UnitOfWorkImpl.java:929)
at org.eclipse.persistence.internal.sessions.UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent(UnitOfWorkIdentityMapAccessor.java:181)
at org.eclipse.persistence.internal.sessions.UnitOfWorkIdentityMapAccessor.getFromIdentityMap(UnitOfWorkIdentityMapAccessor.java:120)
at org.eclipse.persistence.internal.sessions.IdentityMapAccessor.getFromIdentityMap(IdentityMapAccessor.java:380)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.registerExistingObject(UnitOfWorkImpl.java:3899)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.registerExistingObject(UnitOfWorkImpl.java:3854)
at org.eclipse.persistence.mappings.CollectionMapping.buildElementUnitOfWorkClone(CollectionMapping.java:267)
at org.eclipse.persistence.mappings.CollectionMapping.buildElementClone(CollectionMapping.java:279)
at org.eclipse.persistence.internal.queries.ContainerPolicy.addNextValueFromIteratorInto(ContainerPolicy.java:213)
at org.eclipse.persistence.mappings.CollectionMapping.buildCloneForPartObject(CollectionMapping.java:205)
at org.eclipse.persistence.internal.indirection.UnitOfWorkQueryValueHolder.buildCloneFor(UnitOfWorkQueryValueHolder.java:51)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiateImpl(UnitOfWorkValueHolder.java:161)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiate(UnitOfWorkValueHolder.java:222)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.indirection.IndirectList.buildDelegate(IndirectList.java:244)
at org.eclipse.persistence.indirection.IndirectList.getDelegate(IndirectList.java:414)
at org.eclipse.persistence.indirection.IndirectList$1.<init>(IndirectList.java:542)
at org.eclipse.persistence.indirection.IndirectList.listIterator(IndirectList.java:541)
at org.eclipse.persistence.indirection.IndirectList.iterator(IndirectList.java:505)
at com.business.frontend.facade.impl.FrontEndBFBean.combineAllContainerKpis(FrontEndBFBean.java:515)
at com.business.frontend.facade.impl.FrontEndBFBean.getKpiValuesFlat(FrontEndBFBean.java:405)
at sun.reflect.GeneratedMethodAccessor237.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:5409)
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.GeneratedMethodAccessor170.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:5381)
at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5369)
at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:214)
... 75 more
On further inspection I notised the lines :
_ThreadID=165;_ThreadName=http-thread-pool-37860(5);
and
Exception [EclipseLink-2004] (Eclipse Persistence Services - 2.3.4.v20151027-346465e)
My initial thought were that that the HTTP thread timeouted waiting for the DB call to complete, and then the HTTP thread interrupted the EclipseLink leaving behind a ConcurrencyManager in an unexpected state (with a DeferredLock not in fact released after use). I made a small app, testing my hypothesis by tweking the server settings and making long calls to the DB and terminating the http call before the DB call was ready, but this doesn't seem to reproduce the problem. There is also the fact that the method called when the exception occurs does not use any kind of JPA(ORM), the call uses JDBC. Most of the application uses EclipseLink and JPA, but not this part. Also it is not uncommon for the application to be under heavy database usage.
So I was thinking, what can be the reason behind this error appart from the descriptive (This normally means that an attempt was made to
commit or rollback a transaction before it was started, or to rollback a transaction twice), I'm pretty sure the code is not doing such a thing.
So it must be some lazy loading conflict, but I have no idea what conditions can cause this problem.
I have no idea where to investigate from this point forward. Any ideas are well welcomed :)
In this error case, the exact reason for the concurrency exception isn't known - we can only see the one thread accessing the context, by triggering a lazy relationship on an entity. How this entity was read in and what happened in other threads that might also be using this EntityManager the entity was read from (directly or indirectly by accessing entities read from it) requires tracking down, but can usually be avoided.
EntityManagers are not meant to be accessed by multiple threads, and so do not handle concurrent access. Entities read in from EntityManagers have many hooks to the context they were read from; these hooks allow for lazy relationships, change tracking etc to occur transparent to the application. This has the consequence though that these entities too cannot be concurrently accessed - they should not be cached or passed around by the application without careful consideration. In many cases, applications might be better off letting JPA handle caching, and access entities as needed from a context.