search

IQSS / dataverse

Open source research data repository software
http://dataverse.org
Other
857 stars 481 forks source link

Small Tabular File Publish OptimisticLockException #4733

Open matthew-a-dunlap opened 6 years ago

matthew-a-dunlap commented 6 years ago

To reproduce: Create and publish a dataset (no content was used in testing). After publish, then upload a small tabular file (csv was used). Then click publish from the dataset page. In some cases, the timing will be such that clicking publish will trigger no action for the user and in the back-end an optimistic lock exception will be thrown.

The timing on this has been a bit hard to nail down but seems to happen more often when auxdata/metadata is attached to the tabular file. For example, prov and file descriptions.

When this issue takes place, refreshing the page allows publish to happen as normal. No data is lost from the error.

Connects to #4731, where the issue was originally found.

matthew-a-dunlap commented 6 years ago

An example of the OptimisticLockException

[2018-06-04T12:52:39.657-0400] [glassfish 4.1] [SEVERE] [] [javax.enterprise.resource.webcontainer.jsf.context] [tid: _ThreadID=31 _ThreadName=http-listener-1(4)] [timeMillis: 1528131159657] [levelValue: 1000] [[
  javax.faces.el.EvaluationException: javax.ejb.EJBException
        at javax.faces.component.MethodBindingMethodExpressionAdapter.invoke(MethodBindingMethodExpressionAdapter.java:101)
        at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:102)
        at javax.faces.component.UICommand.broadcast(UICommand.java:315)
        at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:790)
        at javax.faces.component.UIViewRoot.processDecodes(UIViewRoot.java:931)
        at com.sun.faces.lifecycle.ApplyRequestValuesPhase.execute(ApplyRequestValuesPhase.java:78)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
        at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:198)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:646)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:344)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.glassfish.tyrus.servlet.TyrusServletFilter.doFilter(TyrusServletFilter.java:295)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.ocpsoft.rewrite.servlet.RewriteFilter.doFilter(RewriteFilter.java:226)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:316)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
        at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
        at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
        at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:174)
        at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:415)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:282)
        at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
        at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:201)
        at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:175)
        at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
        at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
        at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:565)
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:545)
        at java.lang.Thread.run(Thread.java:748)
Caused by: javax.ejb.EJBException
        at com.sun.ejb.containers.EJBContainerTransactionManager.processSystemException(EJBContainerTransactionManager.java:748)
        at com.sun.ejb.containers.EJBContainerTransactionManager.completeNewTx(EJBContainerTransactionManager.java:698)
        at com.sun.ejb.containers.EJBContainerTransactionManager.postInvokeTx(EJBContainerTransactionManager.java:503)
        at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4566)
        at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2074)
        at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2044)
        at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:220)
        at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
        at com.sun.proxy.$Proxy248.submit(Unknown Source)
        at edu.harvard.iq.dataverse.__EJB31_Generated__EjbDataverseEngine__Intf____Bean__.submit(Unknown Source)
        at edu.harvard.iq.dataverse.DatasetPage.releaseDataset(DatasetPage.java:1938)
        at edu.harvard.iq.dataverse.DatasetPage.releaseMajor(DatasetPage.java:1783)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.sun.el.parser.AstValue.invoke(AstValue.java:289)
        at com.sun.el.MethodExpressionImpl.invoke(MethodExpressionImpl.java:304)
        at org.jboss.weld.util.el.ForwardingMethodExpression.invoke(ForwardingMethodExpression.java:40)
        at org.jboss.weld.el.WeldMethodExpression.invoke(WeldMethodExpression.java:50)
        at com.sun.faces.facelets.el.TagMethodExpression.invoke(TagMethodExpression.java:105)
        at javax.faces.component.MethodBindingMethodExpressionAdapter.invoke(MethodBindingMethodExpressionAdapter.java:87)
        ... 44 more
Caused by: javax.persistence.OptimisticLockException: Exception [EclipseLink-5010] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [[DatasetVersion id:16]] cannot be merged because it has changed or been deleted since it was last read. 
Class> edu.harvard.iq.dataverse.DatasetVersion
        at org.eclipse.persistence.internal.jpa.EntityManagerImpl.mergeInternal(EntityManagerImpl.java:544)
        at org.eclipse.persistence.internal.jpa.EntityManagerImpl.merge(EntityManagerImpl.java:519)
        at com.sun.enterprise.container.common.impl.EntityManagerWrapper.merge(EntityManagerWrapper.java:305)
        at edu.harvard.iq.dataverse.engine.command.impl.PublishDatasetCommand.execute(PublishDatasetCommand.java:92)
        at edu.harvard.iq.dataverse.engine.command.impl.PublishDatasetCommand.execute(PublishDatasetCommand.java:31)
        at edu.harvard.iq.dataverse.EjbDataverseEngine.submit(EjbDataverseEngine.java:223)
        at sun.reflect.GeneratedMethodAccessor1253.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1081)
        at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1153)
        at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4786)
        at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:656)
        at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
        at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
        at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:46)
        at org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
        at sun.reflect.GeneratedMethodAccessor98.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
        at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
        at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
        at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
        at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
        at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
        at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
        at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:369)
        at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4758)
        at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4746)
        at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:212)
        ... 59 more
Caused by: Exception [EclipseLink-5010] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [[DatasetVersion id:16]] cannot be merged because it has changed or been deleted since it was last read. 
Class> edu.harvard.iq.dataverse.DatasetVersion
        at org.eclipse.persistence.exceptions.OptimisticLockException.objectChangedSinceLastMerge(OptimisticLockException.java:152)
        at org.eclipse.persistence.internal.sessions.MergeManager.mergeChangesOfCloneIntoWorkingCopy(MergeManager.java:578)
        at org.eclipse.persistence.internal.sessions.MergeManager.mergeChanges(MergeManager.java:313)
        at org.eclipse.persistence.mappings.CollectionMapping.mergeIntoObject(CollectionMapping.java:1645)
        at org.eclipse.persistence.internal.descriptors.ObjectBuilder.mergeIntoObject(ObjectBuilder.java:4132)
        at org.eclipse.persistence.internal.sessions.MergeManager.mergeChangesOfCloneIntoWorkingCopy(MergeManager.java:594)
        at org.eclipse.persistence.internal.sessions.MergeManager.mergeChanges(MergeManager.java:313)
        at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.mergeCloneWithReferences(UnitOfWorkImpl.java:3521)
        at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.mergeCloneWithReferences(RepeatableWriteUnitOfWork.java:384)
        at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.mergeCloneWithReferences(UnitOfWorkImpl.java:3481)
        at org.eclipse.persistence.internal.jpa.EntityManagerImpl.mergeInternal(EntityManagerImpl.java:542)
        ... 92 more
]]
djbrooke commented 4 years ago

I'm going to close this one, as we've made some modifications (focused on locks releasing and other changes) to the locking code over the last year+ and I expect this has been fixed.

@matthew-a-dunlap if you're reading this I hope you're well! :)

vjorlikowski commented 1 year ago

Sadly, this issue is still occurring for us, with small CSVs. Backtrace excerpt:


ESC[36mdataverse        |ESC[0m Exception Description: The object [[DatasetVersion id:2]] cannot be merged because it has changed or been deleted since it was last read. 
ESC[36mdataverse        |ESC[0m Class> edu.harvard.iq.dataverse.DatasetVersion
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.EJBContainerTransactionManager.processSystemException(EJBContainerTransactionManager.java:723)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.EJBContainerTransactionManager.completeNewTx(EJBContainerTransactionManager.java:652)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.EJBContainerTransactionManager.postInvokeTx(EJBContainerTransactionManager.java:482)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4592)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2125)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2095)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:220)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:90)
ESC[36mdataverse        |ESC[0m         at com.sun.proxy.$Proxy362.submit(Unknown Source)
ESC[36mdataverse        |ESC[0m         at edu.harvard.iq.dataverse.__EJB31_Generated__EjbDataverseEngineInner__Intf____Bean__.submit(Unknown Source)
ESC[36mdataverse        |ESC[0m         at edu.harvard.iq.dataverse.EjbDataverseEngine.submit(EjbDataverseEngine.java:274)
ESC[36mdataverse        |ESC[0m         at jdk.internal.reflect.GeneratedMethodAccessor1214.invoke(Unknown Source)
ESC[36mdataverse        |ESC[0m         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
ESC[36mdataverse        |ESC[0m         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
ESC[36mdataverse        |ESC[0m         at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:588)
ESC[36mdataverse        |ESC[0m         at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:408)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4826)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:665)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:834)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:615)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
ESC[36mdataverse        |ESC[0m         at jdk.internal.reflect.GeneratedMethodAccessor313.invoke(Unknown Source)
ESC[36mdataverse        |ESC[0m         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
ESC[36mdataverse        |ESC[0m         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:888)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:833)
ESC[36mdataverse        |ESC[0m         at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:615)```
donsizemore commented 1 year ago

@vjorlikowski is testing Dataverse 5.8 using dataverse-docker.