IQSS / IQSS/dataverse

Last Export Time not set in some cases

Open
#11,141 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Type: Bug
Dominant language
Java
Stars
1.1k
Forks
564
Avg merge
2d 2h
Merged PRs (30d)
29

Description

I've found a few cases at QDR and on demo.dataverse.org where it appears that a dataset has been published and exports exist, but the last export time is not set. I only checked these because I was consistently seeing the following stack trace in the Jenkins tests for recent PRs:

[#|2025-01-08T15:41:52.219+0000|INFO|Payara 6.2023.8|edu.harvard.iq.dataverse.engine.command.impl.FinalizeDatasetPublicationCommand|_ThreadID=226;_ThreadName=__ejb-thread-pool11;_TimeMillis=1736350912219;_LevelValue=800;|
  Successfully published the dataset doi:10.5072/FK2/MOSOXA|#]

[#|2025-01-08T15:41:54.645+0000|INFO|Payara 6.2023.8|edu.harvard.iq.dataverse.util.FileUtil|_ThreadID=73;_ThreadName=http-thread-pool::http-listener-1(5);_TimeMillis=1736350914645;_LevelValue=800;|
  stata14-auto-withstrls.dta is a filename/extension Dataverse doesn't know about. Consider adding it to the MimeTypeDetectionByFileName.properties file.|#]

[#|2025-01-08T15:41:54.699+0000|INFO|Payara 6.2023.8|edu.harvard.iq.dataverse.ingest.IngestServiceBean|_ThreadID=73;_ThreadName=http-thread-pool::http-listener-1(5);_TimeMillis=1736350914699;_LevelValue=800;|
  Incrementing recorded storage use by 15071 bytes for dataset 3|#]

[#|2025-01-08T15:41:55.153+0000|INFO|Payara 6.2023.8|edu.harvard.iq.dataverse.ingest.IngestServiceBean|_ThreadID=73;_ThreadName=http-thread-pool::http-listener-1(5);_TimeMillis=1736350915153;_LevelValue=800;|
  Ingest of 1 tabular data file(s) is in progress.|#]

[#|2025-01-08T15:41:55.713+0000|INFO|Payara 6.2023.8|edu.harvard.iq.dataverse.ingest.IngestServiceBean|_ThreadID=228;_ThreadName=orb-thread-pool-1 (pool #1): worker-5;_TimeMillis=1736350915713;_LevelValue=800;|
  Tabular data successfully ingested; DataTable with 13 variables produced.|#]

[#|2025-01-08T15:41:55.714+0000|INFO|Payara 6.2023.8|edu.harvard.iq.dataverse.ingest.IngestServiceBean|_ThreadID=228;_ThreadName=orb-thread-pool-1 (pool #1): worker-5;_TimeMillis=1736350915714;_LevelValue=800;|
  Tab-delimited file produced: /tmp/finalTabfile.3471176006590064028.tab|#]

[#|2025-01-08T15:42:01.259+0000|WARNING|Payara 6.2023.8|org.eclipse.persistence.session./file:/usr/local/payara6/glassfish/domains/domain1/applications/dataverse/WEB-INF/classes/_VDCNet-ejbPU|_ThreadID=226;_ThreadName=__ejb-thread-pool11;_TimeMillis=1736350921259;_LevelValue=900;|
  Local Exception Stack: 
Exception [EclipseLink-4002] (Eclipse Persistence Services - 4.0.1.payara-p1.v202304041433): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: update or delete on table "datasetversion" violates foreign key constraint "fk_filemetadata_datasetversion_id" on table "filemetadata"
  Detail: Key (id)=(2) is still referenced from table "filemetadata".
Error Code: 0
Call: DELETE FROM DATASETVERSION WHERE ((ID = ?) AND (VERSION = ?))
	bind => [2 parameters bound]
Query: DeleteObjectQuery([DatasetVersion id:2])
	at org.eclipse.persistence.exceptions.DatabaseException.sqlException(DatabaseException.java:343)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.processExceptionForCommError(DatabaseAccessor.java:1805)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeDirectNoSelect(DatabaseAccessor.java:917)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeNoSelect(DatabaseAccessor.java:981)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:642)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:569)
	at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2048)
	at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:311)
	at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:280)
	at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:266)
	at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.deleteObject(DatasourceCallQueryMechanism.java:247)
	at org.eclipse.persistence.internal.queries.StatementQueryMechanism.deleteObject(StatementQueryMechanism.java:129)
	at org.eclipse.persistence.queries.DeleteObjectQuery.executeDatabaseQuery(DeleteObjectQuery.java:219)
	at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:913)
	at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:812)
	at org.eclipse.persistence.queries.ObjectLevelModifyQuery.executeInUnitOfWorkObjectLevelModifyQuery(ObjectLevelModifyQuery.java:109)
	at org.eclipse.persistence.queries.DeleteObjectQuery.executeInUnitOfWorkObjectLevelModifyQuery(DeleteObjectQuery.java:118)
	at org.eclipse.persistence.queries.ObjectLevelModifyQuery.executeInUnitOfWork(ObjectLevelModifyQuery.java:86)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:3008)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1841)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1823)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1773)
	at org.eclipse.persistence.internal.sessions.CommitManager.deleteAllObjects(CommitManager.java:363)
	at org.eclipse.persistence.internal.sessions.CommitManager.deleteAllObjects(CommitManager.java:317)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitToDatabase(UnitOfWorkImpl.java:1510)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitToDatabaseWithChangeSet(UnitOfWorkImpl.java:1597)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.issueSQLbeforeCompletion(UnitOfWorkImpl.java:3305)
	at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.issueSQLbeforeCompletion(RepeatableWriteUnitOfWork.java:368)
	at org.eclipse.persistence.transaction.AbstractSynchronizationListener.beforeCompletion(AbstractSynchronizationListener.java:163)
	at org.eclipse.persistence.transaction.JTASynchronizationListener.beforeCompletion(JTASynchronizationListener.java:70)
	at com.sun.enterprise.transaction.JavaEETransactionImpl.commit(JavaEETransactionImpl.java:496)
	at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.commit(JavaEETransactionManagerSimplified.java:960)
	at com.sun.ejb.containers.EJBContainerTransactionManager.completeNewTx(EJBContainerTransactionManager.java:666)
	at com.sun.ejb.containers.EJBContainerTransactionManager.postInvokeTx(EJBContainerTransactionManager.java:482)
	at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4601)
	at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2134)
	at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2104)
	at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:220)
	at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:90)
	at jdk.proxy74/jdk.proxy74.$Proxy388.merge(Unknown Source)
	at edu.harvard.iq.dataverse.__EJB31_Generated__DatasetServiceBean__Intf____Bean__.merge(Unknown Source)
	at edu.harvard.iq.dataverse.engine.command.impl.FinalizeDatasetPublicationCommand.onSuccess(FinalizeDatasetPublicationCommand.java:289)
	at edu.harvard.iq.dataverse.EjbDataverseEngine.completeCommand(EjbDataverseEngine.java:353)
	at edu.harvard.iq.dataverse.EjbDataverseEngine.submit(EjbDataverseEngine.java:290)
	at jdk.internal.reflect.GeneratedMethodAccessor328.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:588)
	at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:408)
	at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4835)
	at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:653)
	at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:834)
	at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:603)
	at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
	at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
	at jdk.internal.reflect.GeneratedMethodAccessor278.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:888)
	at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:833)
	at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:603)
	at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:72)
	at org.jboss.weld.module.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
	at jdk.internal.reflect.GeneratedMethodAccessor266.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:888)
	at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:833)
	at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:375)
	at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4807)
	at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4795)
	at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:212)
	at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:90)
	at jdk.proxy74/jdk.proxy74.$Proxy346.submit(Unknown Source)
	at edu.harvard.iq.dataverse.__EJB31_Generated__EjbDataverseEngine__Intf____Bean__.submit(Unknown Source)
	at edu.harvard.iq.dataverse.DatasetServiceBean.callFinalizePublishCommandAsynchronously(DatasetServiceBean.java:964)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:588)
	at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:408)
	at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4835)
	at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:653)
	at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:834)
	at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:603)
	at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
	at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
	at jdk.internal.reflect.GeneratedMethodAccessor278.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:888)
	at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:833)
	at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:603)
	at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:81)
	at org.jboss.weld.module.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
	at jdk.internal.reflect.GeneratedMethodAccessor266.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:888)
	at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:833)
	at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:375)
	at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4807)
	at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4795)
	at com.sun.ejb.containers.EjbAsyncTask.call(EjbAsyncTask.java:101)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: org.postgresql.util.PSQLException: ERROR: update or delete on table "datasetversion" violates foreign key constraint "fk_filemetadata_datasetversion_id" on table "filemetadata"
  Detail: Key (id)=(2) is still referenced from table "filemetadata".
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2733)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2420)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:372)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:517)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:194)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:155)
	at jdk.internal.reflect.GeneratedMethodAccessor300.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.postgresql.ds.PGPooledConnection$StatementHandler.invoke(PGPooledConnection.java:447)
	at jdk.proxy74/jdk.proxy74.$Proxy549.executeUpdate(Unknown Source)
	at com.sun.gjc.spi.base.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:127)
	at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeDirectNoSelect(DatabaseAccessor.java:909)
	... 106 more
|#]

What steps does it take to reproduce the issue?
Not clear - publishing is involved. In the AccessIT test, there's a file going through ingest followed by publishing, but I don't know if that's relevant.

  • When does this issue occur?
    Not with every dataset publication, but consistently in the AccessIT test (it's non-fatal as we catch/log the error in the onSuccess method but do not fail).

  • Which page(s) does it occurs on?

  • What happens?
    Not sure - from the stack trace it looks like a merge of the dataset into the context that was added in the onSuccess method to avoid having to explicitly save the lastexporttime for the dataset fails due to an attempt to delete a datasetversion. I'm not sure why that occurs. At that point, the error is just caught and the one change we expected to be saved (the lastexporttime) isn't. Since the other operations - indexing, export, etc. being done in onSuccess don't depend on that merge to have their results persisted, I don't think there are any other effects. (Presumably one of those is changing the dataset though so that the merge fails.)

  • To whom does it occur (all users, curators, superusers)?

  • What did you expect to happen?
    the lastexporttime should get updated/there should not be failed delete of a datasetversion in the log.

Which version of Dataverse are you using?
6.5/develop

Any related open or closed issues to this bug report?

Screenshots:

No matter the issue, screenshots are always welcome.

To add a screenshot, please use one of the following formats and/or methods described here:

Are you thinking about creating a pull request for this issue? not at present - the bug is concerning because it is db update failure, but a pretty minor one. Hopefully someone can provide further details as to how/when it is triggered that will point towards a solution. (If we need a solution immediately, restoring the old code that does a direct UPDATE query on the db should work.)

Help is always welcome, is this bug something you or your organization plan to fix?

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start at FinalizeDatasetPublicationCommand.java line 289 and DatasetServiceBean.java line 964, using the reported Jenkins stack trace as the entry point. Trace how publication, ingest, exports, and the datasetversion/filemetadata relationship interact, then verify that affected published datasets receive a last export time without the foreign-key deletion failure.

Written by the indexing model from the issue text.

Assessment

Tech stack
java, postgresql
Domain
backend, databases
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.