SOLVED: Hibernate - concurrent access to versioned resources

[jharrop]

I've spent the last week grappling with what I have reported as  http://issues.alfresco.com/browse/ALFCOM-1683

Basically, when 2 clients access the same versioned resources in the Alfresco repository (via Web service + JCR API in my case), the database deadlocks.  I'm using 2.9 community sources from subversion, and have been experiencing this and related issues for over 4 months.

I was using MySQL, but this week I've also tried Postgres and HSQL.  I get problems whichever one I use.

I have attached a simple test case to that bug report, which simulates concurrent access by creating a number of threads which manipulate the content.  Things fail badly if several threads access at once.  I say badly, because (i) RetryingTransactionHelper doesn't actually retry in this case, and (ii) you have to restart the database before you can get reproducible behaviour.

In the case of HSQL:

Could not synchronize database state with sessionorg.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction‍‍

A 2 second delay between threads avoids this.

However, when I run it under MySQL  although the initial thread which creates the content makes a node versionable, to my surprise, each subsequent thread
throws

 javax.jcr.UnsupportedRepositoryOperationException: Node workspace://SpacesStore/667bf743-2e29-11dd-93d2-0108c9249316 is not versionable at org.alfresco.jcr.item.NodeImpl.getBaseVersion.‍‍

  It doesn't seem to matter how long you wait before trying (I've tried up to 20 seconds).  At this stage, I don't

I'd be very grateful for thoughts/suggestions how to work around these issues.

kind regards

Jason

[jharrop]

http://issues.alfresco.com/secure/attachment/11410/ALFCOM1683.java is a revised test case.   The last paragraph of this post explains where I had gone wrong in the previous version.

This version demonstrates the StaleObjectStateException on MySQL.

Invoke it with something like http://localhost:8080/alfresco/testcase?firstsleep=2500&sleep=500&threads=10

My experience is that any thread invoked before the preceding ones have finished will result in a StaleObjectStateException.  I see http://issues.alfresco.com/browse/CHK-1507 "teaches RetryingTransactionXXX to recognize StaleStateException", but nothing is retried in this case.

The problem with the first version of ALFCOM1683.java was that it relied on Alfresco to set up an implicit transaction around the test setup (which creates a directory, adds a file to it, and makes it versionable). HSQL was fine with this. Previous experience had taught me you need to use RetryingTransactionHelper, rather than relying on an implicit transaction, but I overlooked this since everything seemed to work.  But not with MySQL.  In the case of MySQL, the dir and file are created, and the file versioned for the purposes of that thread, but if there is an implicit transaction around versionable, it must get silently rolled back, because the subsequent threads insist it is not versionable.

[jharrop]

The solution to this was obvious, in the end.

The RetryingTransactionHelper was not retrying, because I was catching all exceptions in my  RetryingTransactionCallback ops:

Once I made sure the callback threw exceptions,  the RetryingTransactionHelper retries on StaleObjectStateException.

Because I was catching the relevant exception, my

                    txn.getStatus() == Status.STATUS_MARKED_ROLLBACK‍‍

which tells RetryingTransactionHelper not to retry.

Before I realised the error of my ways, I had added

      server.transaction.mode.default=PROPAGATION_REQUIRED, +org.springframework.orm.hibernate3.HibernateOptimisticLockingFailureException‍

to transaction.properties.

This had the desired effect - org.springframework.transaction.interceptor.RuleBasedTransactionAttribute now ruled that the transaction should not be rolled back.  But doing that is not necessary, provided you don't catch the exception! And nor is it sufficient .. you still have to throw the exception in order for RetryingTransactionHelper to do its thing.  So forget it.

In summary, the key thing is to make sure the callback throws exceptions, and that your exception is one of the RETRY_EXCEPTIONS defined in RetryingTransactionHelper.

Hope this experience is helpful to someone.

The debug in RetryingTransactionHelper can be improved a little.  Each time the transaction is retried, a new transaction is actually created.  So where it logs the txn and iteration, the iteration increments, but the txn is always different. It is easy enough to log the transaction the retry is replacing, and worth doing in order to convince yourself things are working properly.

http://issues.alfresco.com/secure/attachment/11411/ALFCOM1683.java is an updated version of the test case, with the main issue now solved. 

Here is the output of http://localhost:8080/alfresco/testcase?firstsleep=2500&sleep=200&threads=6 for anyone interested (6 threads, 200 ms apart, update versioned content via JCR).

  creating objects .. in thread http-8080-Processor25objects created ..checked out and checked inCreated d1130158940 / f336495314firstsleeptime: 2500 mssleepTime: 200 mswill kick off 6 in seriesloop 1.. .. Transaction 1 thread.start().. sleeping for 200 ms.. .. Transaction 1 RetryingTransactionHelper().doInTransaction .. Thread-73.. sleptdone loop 1loop 2.. .. Transaction 2 thread.start().. sleeping for 200 ms.. .. Transaction 2 RetryingTransactionHelper().doInTransaction .. Thread-74.. sleptdone loop 2loop 3.. .. Transaction 3 thread.start().. sleeping for 200 ms.. .. Transaction 3 RetryingTransactionHelper().doInTransaction .. Thread-75.. sleptdone loop 3loop 4.. .. Transaction 4 thread.start().. sleeping for 200 ms.. .. Transaction 4 RetryingTransactionHelper().doInTransaction .. Thread-76.. sleptdone loop 4loop 5.. .. Transaction 5 thread.start().. sleeping for 200 ms.. .. Transaction 5 RetryingTransactionHelper().doInTransaction .. Thread-77.. sleptdone loop 5loop 6.. .. Transaction 6 thread.start().. sleeping for 200 ms.. sleptdone loop 6sleeping 20000ms before letting doGet complete ….. .. Transaction 6 RetryingTransactionHelper().doInTransaction .. Thread-78Thread-76callback completed without errorThread-74Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-75Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-73Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-77Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-78Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retry.. .. transaction 4 done in 3201ms.. .. Transaction 2 RetryingTransactionHelper().doInTransaction .. Thread-746read current content: Thread-76 aka 4 was here... .. Transaction 5 RetryingTransactionHelper().doInTransaction .. Thread-776read current content: Thread-76 aka 4 was here... .. Transaction 3 RetryingTransactionHelper().doInTransaction .. Thread-75.. .. Transaction 1 RetryingTransactionHelper().doInTransaction .. Thread-73.. .. Transaction 6 RetryingTransactionHelper().doInTransaction .. Thread-786read current content: Thread-76 aka 4 was here.6read current content: Thread-76 aka 4 was here.6read current content: Thread-76 aka 4 was here.Thread-74callback completed without errorThread-77Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-73Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-75Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-78Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retry.. .. transaction 2 done in 7373ms.. .. Transaction 1 RetryingTransactionHelper().doInTransaction .. Thread-73.. .. Transaction 3 RetryingTransactionHelper().doInTransaction .. Thread-75.. .. Transaction 6 RetryingTransactionHelper().doInTransaction .. Thread-78.. .. Transaction 5 RetryingTransactionHelper().doInTransaction .. Thread-776read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.6read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.6read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.6read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.Thread-75callback completed without errorThread-73Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-78Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-77Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retry.. .. transaction 3 done in 10411ms.. .. Transaction 5 RetryingTransactionHelper().doInTransaction .. Thread-776read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.Thread-75 aka 3 was here... .. Transaction 1 RetryingTransactionHelper().doInTransaction .. Thread-736read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.Thread-75 aka 3 was here... .. Transaction 6 RetryingTransactionHelper().doInTransaction .. Thread-786read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.Thread-75 aka 3 was here.Thread-77callback completed without error.. .. transaction 5 done in 12486msThread-73Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retryThread-78Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retry.. .. Transaction 1 RetryingTransactionHelper().doInTransaction .. Thread-736read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.Thread-75 aka 3 was here.Thread-77 aka 5 was here... .. Transaction 6 RetryingTransactionHelper().doInTransaction .. Thread-786read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.Thread-75 aka 3 was here.Thread-77 aka 5 was here.Thread-73callback completed without errorThread-78Caught Object of class [org.alfresco.repo.domain.hibernate.NodeImpl] with identifier [3500]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.alfresco.repo.domain.hibernate.NodeImpl#3500] .. up to RTH to retry.. .. transaction 1 done in 15477ms.. .. Transaction 6 RetryingTransactionHelper().doInTransaction .. Thread-786read current content: Thread-76 aka 4 was here.Thread-74 aka 2 was here.Thread-75 aka 3 was here.Thread-77 aka 5 was here.Thread-73 aka 1 was here.Thread-78callback completed without error.. .. transaction 6 done in 18345msfinished .. also check server logs for errors‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[jdunkelberger]

Thanks for this post! Google picked it up.

I think I may be having the same fundamental issue with catching exceptions too eagerly (in order to produce useful faces error messages).