Recover from error

[omegerard]

Hi,


In a space called "Backend" I collected a number of documents (from which PDFs were automatically created in a sister space).  That was done last month.

Last Saturday I added a few other documents to the same collection, again with the rule in the background for creating PDF versions in a sister space.

Something must have gone wrong with the automatic PDF generation. What is worse, the "backend" space cannot be accessed any longer. That is, when I go there with the standard web interface, I get the error message:

A system error happened during the operation: Multiple primary associations: child: workspace://SpacesStore/8d458058-d236-11da-9b82-4dd383a768b7 first primary assoc: ChildAssoc[ parent=workspace://SpacesStore/c2a27e84-cf85-11da-909e-e9c04a70233d, child=workspace://SpacesStore/8d458058-d236-11da-9b82-4dd383a768b7, name={http://www.alfresco.org/model/content/1.0}move, isPrimary=true] second primary assoc: ChildAssoc[ parent=workspace://SpacesStore/e7bdf8be-b975-11da-b1a6-29800f959992, child=workspace://SpacesStore/8d458058-d236-11da-9b82-4dd383a768b7, name={http://www.alfresco.org/model/content/1.0}move, isPrimary=true]

How can I repair/bypass the error so that I can access the documents again? I tried with both the CIFS and the webdav interface, but that did not work out (as expected).

Regards

Ludo

[derek]

Hi,

That is a very odd situation.  If you could reproduce it, then we'd appreciate a JIRA entry.

Change one of the associations to be non-primary.

select * from child_assoc where parent_guid = 'c2a27e84-cf85-11da-909e-e9c04a70233d' and child_guid = '8d458058-d236-11da-9b82-4dd383a768b7'
‍‍‍

Identify the one you want to change and

update child_assoc set isPrimary = 'false' where id = XXX
‍‍‍

Sorry about that, but it should only be during node creation and moving that the association primary flag is set.  And since each Node gets a GUID when created, I am not sure how this happened.

BTW: Please back up your database before doing this.

Regards

[derek]

Hi,

Could you check if your default table type is InnoDB in MySQL ?

My guess is that there is a bug in the move action when the destination file exists, and that this caused a rollback of the transaction.  Except, if the tables are MyISAM, then there wouldn't be a full rollback.  It gets more complicated because Hibernate will have thrown away some changes but others might have been flushed, leaving the database in a rather questionable state.

You can use

SHOW ENGINES;
‍‍‍

in MySQL to see what your default is.  Use

alter table applied_patch engine=INNODB;
alter table child_assoc engine=INNODB;
alter table externalkeys engine=INNODB;
alter table node engine=INNODB;
alter table node_aspects engine=INNODB;
alter table node_assoc engine=INNODB;
alter table node_permission engine=INNODB;
alter table node_perm_entry engine=INNODB;
alter table node_properties engine=INNODB;
alter table node_status engine=INNODB;
alter table permission_ref engine=INNODB;
alter table recipient engine=INNODB;
alter table store engine=INNODB;
alter table version_count engine=INNODB;
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

to convert the existing tables.

If that's not it, then we're back to trying to reproduce the issue otherwise.

Regards

[omegerard]

Could you check if your default table type is InnoDB in MySQL ?

Apparently not:

mysql> show engines ;
+————+———+—————————————————————-+
| Engine     | Support | Comment                                                        |
+————+———+—————————————————————-+
| MyISAM     | DEFAULT | Default engine as of MySQL 3.23 with great performance         |
| MEMORY     | YES     | Hash based, stored in memory, useful for temporary tables      |
| InnoDB     | YES     | Supports transactions, row-level locking, and foreign keys     |
| BerkeleyDB | NO      | Supports transactions and page-level locking                   |
| BLACKHOLE  | NO      | /dev/null storage engine (anything you write to it disappears) |
| EXAMPLE    | NO      | Example storage engine                                         |
| ARCHIVE    | NO      | Archive storage engine                                         |
| CSV        | NO      | CSV storage engine                                             |
| ndbcluster | NO      | Clustered, fault-tolerant, memory-based tables                 |
| FEDERATED  | NO      | Federated MySQL storage engine                                 |
| MRG_MYISAM | YES     | Collection of identical MyISAM tables                          |
| ISAM       | NO      | Obsolete storage engine                                        |
+————+———+—————————————————————-+
12 rows in set (0.00 sec)
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

My guess is that there is a bug in the move action when the destination file exists, and that this caused a rollback of the transaction.

Makes sense since I tried to automatically create a PDF twice from the same document.

Use … to convert the existing tables.

Done that.

Change one of the associations to be non-primary.

I applied the code but it produced only one row.

Identify the one you want to change and … update child_assoc

Done that for the one entry.

To no avail. I still get the same error message.

If that's not it, then we're back to trying to reproduce the issue otherwise.

I understand that you want to know what went wrong. I want to know it as well, but my primary concern is now to get access to the other documents in that space. Any suggestions how I can do that? Has my Alfresco database become shaky?

Regards

Ludo

[omegerard]

I tried to reproduce the error.

1. I copied a file into a space that contains a rule for converting all incoming documents into pdf (and for moving those pdfs in a "sister" space)

2. The conversion did not work because openoffice was not working properly (or not at all)

3. I removed the file from the space I copied it in and I started Alfresco properly, verifying that indeed openoffice was "connected".

4. I copied the same document in the same space again. Result


- the conversion into pfd was successful
- an error was nonetheless reported in the logfile. I'm going to post the error here. Sorry for any inconvience that might bring for the occasional reader.

13:11:58,308 ERROR [hibernate.jdbc.AbstractBatcher] Exception executing batch:
org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1
        at org.hibernate.jdbc.BatchingBatcher.checkRowCount(BatchingBatcher.java:93)
        at org.hibernate.jdbc.BatchingBatcher.checkRowCounts(BatchingBatcher.java:79)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:58)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:195)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:230)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:145)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:296)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1009)
        at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:356)
        at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
        at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:584)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:496)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:469)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.doCommitTransactionAfterReturning(TransactionAspectSupport.java:266)
        at org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:396)
        at org.alfresco.repo.transaction.TransactionUtil.executeInTransaction(TransactionUtil.java:178)
        at org.alfresco.repo.transaction.TransactionUtil.executeInNonPropagatingUserTransaction(TransactionUtil.java:108)
        at org.alfresco.repo.action.AsynchronousActionExecutionQueueImpl$ActionExecutionWrapper.run(AsynchronousActionExecutionQueueImpl.java:275)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:595)
13:11:58,313 ERROR [event.def.AbstractFlushingEventListener] Could not synchronize database state with session
org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1
        at org.hibernate.jdbc.BatchingBatcher.checkRowCount(BatchingBatcher.java:93)
        at org.hibernate.jdbc.BatchingBatcher.checkRowCounts(BatchingBatcher.java:79)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:58)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:195)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:230)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:145)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:296)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1009)
        at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:356)
        at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
        at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:584)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:496)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:469)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.doCommitTransactionAfterReturning(TransactionAspectSupport.java:266)
        at org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:396)
        at org.alfresco.repo.transaction.TransactionUtil.executeInTransaction(TransactionUtil.java:178)
        at org.alfresco.repo.transaction.TransactionUtil.executeInNonPropagatingUserTransaction(TransactionUtil.java:108)
        at org.alfresco.repo.action.AsynchronousActionExecutionQueueImpl$ActionExecutionWrapper.run(AsynchronousActionExecutionQueueImpl.java:275)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:595)
13:11:58,369 ERROR [util.transaction.SpringAwareUserTransaction] Transaction didn't commit
org.springframework.orm.hibernate3.HibernateOptimisticLockingFailureException: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1
org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1
        at org.hibernate.jdbc.BatchingBatcher.checkRowCount(BatchingBatcher.java:93)
        at org.hibernate.jdbc.BatchingBatcher.checkRowCounts(BatchingBatcher.java:79)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:58)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:195)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:230)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:145)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:296)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1009)
        at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:356)
        at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
        at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:584)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:496)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:469)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.doCommitTransactionAfterReturning(TransactionAspectSupport.java:266)
        at org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:396)
        at org.alfresco.repo.transaction.TransactionUtil.executeInTransaction(TransactionUtil.java:178)
        at org.alfresco.repo.transaction.TransactionUtil.executeInNonPropagatingUserTransaction(TransactionUtil.java:108)
        at org.alfresco.repo.action.AsynchronousActionExecutionQueueImpl$ActionExecutionWrapper.run(AsynchronousActionExecutionQueueImpl.java:275)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:595)
org.alfresco.error.AlfrescoRuntimeException: Unexpected rollback of exception:
Transaction didn't commit: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1
        at org.alfresco.repo.transaction.TransactionUtil.executeInTransaction(TransactionUtil.java:184)
        at org.alfresco.repo.transaction.TransactionUtil.executeInNonPropagatingUserTransaction(TransactionUtil.java:108)
        at org.alfresco.repo.action.AsynchronousActionExecutionQueueImpl$ActionExecutionWrapper.run(AsynchronousActionExecutionQueueImpl.java:275)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:595)
Caused by: javax.transaction.RollbackException: Transaction didn't commit: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 0 actual row count: 0 expected: 1
        at org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:403)
        at org.alfresco.repo.transaction.TransactionUtil.executeInTransaction(TransactionUtil.java:178)
        … 5 more

‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Hope this helps (and sustains your hypothesis).

Ludo

[derek]

Hi, Ludo

When you said "to no avail", did you check the IDs of the associations that it was complaining about?  There may be several nodes affected as you spoke of "a few other documents".

The database is not "shaky".  The node persistence code does a gratuitous data integrity check and throws a DataIntegrityViolation upon discovering two primary parents.  My theory at the time was that that condition would only arise if I made a coding error in the NodeService internals.  In retrospect, it was overkill and I have changed that to be a WARN log message.  Having two primary parents is not that serious.

If you are happy to remove the affected documents altogether, then the next step is to remove those nodes.  Identify the node GUID at the child end of the association in question and

delete from child_assoc where child_guid = 'XXX' or parent_guid = 'XXX';
delete from node_assoc where target_guid = 'XXX' or source_guid = 'XXX';
delete from node_aspects where guid = 'XXX';
delete from node_properties where guid = 'XXX';
update node_status set deleted = 1 where guid = 'XXX';
delete from node where guid = 'XXX';
‍‍‍‍‍‍‍‍

Please check the table and column names.  This will remove the node and orphan any child nodes of XXX.  These nodes will no longer be reachable.  If they are, then there will be a new message to contend with, but I can't think of any process that would do that.

You could delete all the children in that folder by identifying the folder and

select * from child_assoc where parent_guid = 'XXX';
‍‍‍

I also forgot to mention that you have to restart the server or else Hibernate will complain when it finds that the cache and the database our out of synch.

Regards

[omegerard]

Hi Derek

Thanks once again for your help.

When you said "to no avail", did you check the IDs of the associations that it was complaining about? There may be several nodes affected as you spoke of "a few other documents".

Yes I did check the IDs. They were alsways the same.

I also forgot to mention that you have to restart the server or else Hibernate will complain when it finds that the cache and the database our out of synch.

Aah … that did the trick!

I should have known that.

Alfresco isn't complaining any longer and I can access the documents.

Thanks

Ludo

[derek]

Hi,

I'm glad it came right.  Feel free to raise any issues with the move/copy actions - but at least the data should remain consistent now.

Regards

[ps]

Derek,

Any idea if there is/was a Jira entry for this issue. I am working with Alfresco 1.3 with Oracle and have run into this issue with the workflow move action a couple of times, that I had to manually fix the data when it got corrupt.

Was wondering if this has been fixed with later releases of Alfresco…

Thanks,

PS

[derek]

The quickest way to find out is to upgrade.  There are many reasons why the 1.4 is better than 1.3.