Eclipse Community Forums
Forum Search:

Search      Help    Register    Login    Home
Home » Eclipse Projects » EclipseLink » Unexpected entity version number
Unexpected entity version number [message #507187] Tue, 12 January 2010 07:26 Go to next message
Marcin Kwapisz is currently offline Marcin Kwapisz
Messages: 14
Registered: January 2010
Junior Member
Hi,

I wrote several test for JPA (eclipselink 2.0) scenarios like concurrent update with optimistic locking.

I use DerbyDB and DBUnit to initialize a database before each test.
 @Before
    public void setUp() throws MalformedURLException, DataSetException, DatabaseUnitException, SQLException {
        FlatXmlDataSetBuilder builder = new FlatXmlDataSetBuilder();
        builder.setColumnSensing(true);
        dataset = builder.build(new File(initDataSourceFile));
        //Clean and initialize database
        DatabaseOperation.CLEAN_INSERT.execute(connection, dataset);
        EntityManagerFactory emFactory = Persistence.createEntityManagerFactory(testPUName, properties);
        testEm = emFactory.createEntityManager();
        logger.log(Level.INFO, "+++ Test begin");
    }

There are two test methods that use two entity managers (testEm created in setUp and additional one created in the test method) to simulate concurrent update operations:
@Test
    public void concurrentUpdate() {
        EntityManagerFactory emf = Persistence.createEntityManagerFactory(testPUName, properties);
        EntityManager concurrentTestEm = emf.createEntityManager();

        Query firstQuery = testEm.createNamedQuery("Student.getByID");
        firstQuery.setParameter("id", 2);

        Query secondQuery = concurrentTestEm.createNamedQuery("Student.getByID");
        secondQuery.setParameter("id", 2);

        Student student, student2;

        //Start two transaction, each on different entity manager
        try {
            testEm.getTransaction().begin();
            concurrentTestEm.getTransaction().begin();
            student = (Student) firstQuery.getSingleResult();
            student.setImie("Wiesław");
            student2 = (Student) secondQuery.getSingleResult();
            student2.setImie("Kacper");
            testEm.getTransaction().commit();
            //the following operation should fail
            concurrentTestEm.getTransaction().commit();
            //Error, concurrent update was possible
            fail("Concurrent update was possible");
        } catch (javax.persistence.RollbackException ex) {
            //Oczekujemy javax.persistence.OptimisticLockException opakowany w {@link javax.persistence.RollbackException}
            Throwable cause = ex.getCause();
            if ((cause != null) && (cause instanceof javax.persistence.OptimisticLockException)) {
                logger.log(Level.INFO, "**** OK - Expected optimistic lock exception occured");
            } else {
                logger.log(Level.WARNING, "Błąd", ex);
                fail("Unexpected exception, should be javax.persistence.OptimisticLockException");
            }
        } finally {
            concurrentTestEm.close();
        }

        //Dump DB
        dumpDb=true;
    }

    @Test
    public void concurrentDeleteAndUpdate() {
        EntityManagerFactory emf = Persistence.createEntityManagerFactory(testPUName, properties);
        EntityManager concurrentTestEm = emf.createEntityManager();

        Query firstQuery = testEm.createNamedQuery("Student.getByID");
        firstQuery.setParameter("id", 2);

        Query secondQuery = concurrentTestEm.createNamedQuery("Student.getByID");
        secondQuery.setParameter("id", 3);

        Student student, student2;

        //Start two transaction, each on different entity manager
        try {
            testEm.getTransaction().begin();
            concurrentTestEm.getTransaction().begin();

            student = (Student) firstQuery.getSingleResult();
            student2 = (Student) secondQuery.getSingleResult();

            testEm.remove(student);
            //Concurrent update exception is thrown during commit. It was not expected here.
            //Student entity version is 2, but should be 1
            //When concurrentUpdate() test is commented, this will fail
            //Running test in debug mode and setting breakpoint in concurrenUpdate,
            //will cause this test to fail
            testEm.getTransaction().commit();

            student2.setImie("Kacper");
            //the following operation should fail
            concurrentTestEm.getTransaction().commit();
            //Error, concurrent update was possible
            fail("Concurrent update was possible");
        } catch (javax.persistence.RollbackException ex) {
     
            Throwable cause = ex.getCause();
            if ((cause != null) && (cause instanceof javax.persistence.OptimisticLockException)) {
                logger.log(Level.INFO, "**** OK - Expected optimistic lock exception occured");
            } else {
                logger.log(Level.WARNING, "Błąd", ex);
                fail("Unexpected exception, should be javax.persistence.OptimisticLockException");
            }
        } finally {
            concurrentTestEm.close();
        }

        //Dump DB
        dumpDb=true;
    }

And the problem is with the concurrentDeleteAndUpdate test method. This test method succeedes but should fail. If you look carefully you will find that there is no concurrent update. I changed secondQuery id parameter to 3 intentionally to show this unexpected for me behaviour. firstQuery.getSingleResult returns student entity with version set to 2, but should be 1.


  1. When I run test suite in debug mode and set breakpoint in concurrentUpdate and then continue the test, the concurrentDeleteAndUpdate fails (student version is 1)
  2. If I comment the first test method (concurrentUpdate) concurrentDeleteAndUpdate fails (as expected).


What is wrong with my test methods? You can download maven project with these tests from:
http://zskl.zsk.p.lodz.pl/~mkwapisz/jpatest/entitytest.zip

Thanks in advance for your help
Regards
Marcin Kwapisz
icon8.gif  Re: Unexpected entity version number [message #507297 is a reply to message #507187] Tue, 12 January 2010 20:03 Go to previous messageGo to next message
Marcin Kwapisz is currently offline Marcin Kwapisz
Messages: 14
Registered: January 2010
Junior Member
I have run these tests against OpenJPA 2.0.0-m3 and everything works perfectly. So the only conclusions are:


  1. there is a bug in eclipselink
  2. something is wrong with my eclipselink configuration


Regards
Marcin Kwapisz
Re: Unexpected entity version number [message #507501 is a reply to message #507187] Wed, 13 January 2010 17:12 Go to previous messageGo to next message
Chris Delahunt is currently offline Chris Delahunt
Messages: 1023
Registered: July 2009
Senior Member
Hello,

I dont see any problems with the tests directly, can you post the logs from running them both? This will show the EclipseLink build/version being used as well as the SQL it is issuing which can show if the version field is being used in the updates or not. Be sure to set the eclipselink.logging.level property to FINE or FINEST to see the sql getting used.

Best Regards,
Chris
Re: Unexpected entity version number [message #507593 is a reply to message #507501] Thu, 14 January 2010 00:14 Go to previous messageGo to next message
Marcin Kwapisz is currently offline Marcin Kwapisz
Messages: 14
Registered: January 2010
Junior Member
Hello,
You can download the test project using the link from my first post. This is maven project so there should be no problems with running the test suite. You can check configuration and dependency versions in pom.xml and of course try to reproduce the problem. Uncomment the first line of JPATest.setUpClass to run the test using in-memory database.

There is another very interesting thing. I have run the test suite in debug mode. When a breakpoint is set within the try block of the first test method (concurrentUpdate) and then the test is continued, the second test method (concurrentUpdateAndDelete) works as expected (query reads Student entity with version 1).

2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.JPATest setUp
INFO: +++ Początek testu
[EL Fine]: 2010-01-14 00:43:51.609--ServerSession(2456372)--Connection(3075861)--T hread(Thread[main,5,main])--SELECT TS_ID, WD_NAZWA, CZ_IMIE, ADR_EMAIL, WERSJA, CZ_NAZWISKO, AL_ALBUM FROM TESTDB.STUDENT WHERE (TS_ID = ?)
bind => [2]
[EL Fine]: 2010-01-14 00:43:51.609--ServerSession(2456372)--Connection(3075861)--T hread(Thread[main,5,main])--SELECT TS_ID, WD_NAZWA, CZ_IMIE, ADR_EMAIL, WERSJA, CZ_NAZWISKO, AL_ALBUM FROM TESTDB.STUDENT WHERE (TS_ID = ?)
bind => [2]
[EL Fine]: 2010-01-14 00:43:51.609--ClientSession(10808772)--Connection(3075861)-- Thread(Thread[main,5,main])--UPDATE TESTDB.STUDENT SET CZ_IMIE = ?, WERSJA = ? WHERE ((TS_ID = ?) AND (WERSJA = ?))
bind => [Wiesław, 2, 2, 1]
[EL Fine]: 2010-01-14 00:43:51.609--ClientSession(23398687)--Connection(3075861)-- Thread(Thread[main,5,main])--UPDATE TESTDB.STUDENT SET CZ_IMIE = ?, WERSJA = ? WHERE ((TS_ID = ?) AND (WERSJA = ?))
bind => [Kacper, 2, 2, 1]
[EL Warning]: 2010-01-14 00:43:51.609--UnitOfWork(9089012)--Thread(Thread[main,5,main ])--Exception [EclipseLink-5006] (Eclipse Persistence Services - 2.0.0.v20091127-r5931): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [pl.lodz.p.ck.egzaminy.entities.Student[id=2, ver=2]] cannot be updated because it has changed or been deleted since it was last read.
Class> pl.lodz.p.ck.egzaminy.entities.Student Primary Key> [2]
[EL Warning]: 2010-01-14 00:43:51.609--UnitOfWork(9089012)--Thread(Thread[main,5,main ])--javax.persistence.OptimisticLockException: Exception [EclipseLink-5006] (Eclipse Persistence Services - 2.0.0.v20091127-r5931): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [pl.lodz.p.ck.egzaminy.entities.Student[id=2, ver=2]] cannot be updated because it has changed or been deleted since it was last read.
Class> pl.lodz.p.ck.egzaminy.entities.Student Primary Key> [2]
2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.StudentTest concurrentUpdate
INFO: **** OK - Expected optimistic lock exception occured
2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.JPATest tearDown
INFO: +++ Koniec testu
2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.JPATest setUp
INFO: +++ Początek testu
[EL Fine]: 2010-01-14 00:43:51.625--ServerSession(2456372)--Connection(3075861)--T hread(Thread[main,5,main])--SELECT TS_ID, WD_NAZWA, CZ_IMIE, ADR_EMAIL, WERSJA, CZ_NAZWISKO, AL_ALBUM FROM TESTDB.STUDENT WHERE (TS_ID = ?)
bind => [2]
2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.StudentTest concurrentUpdateAndDelete
INFO: pl.lodz.p.ck.egzaminy.entities.Student[id=2, ver=2]
[EL Fine]: 2010-01-14 00:43:51.625--ServerSession(2456372)--Connection(3075861)--T hread(Thread[main,5,main])--SELECT TS_ID, WD_NAZWA, CZ_IMIE, ADR_EMAIL, WERSJA, CZ_NAZWISKO, AL_ALBUM FROM TESTDB.STUDENT WHERE (TS_ID = ?)
bind => [3]
2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.StudentTest concurrentUpdateAndDelete
INFO: pl.lodz.p.ck.egzaminy.entities.Student[id=3, ver=1]
[EL Fine]: 2010-01-14 00:43:51.625--ClientSession(12090673)--Connection(3075861)-- Thread(Thread[main,5,main])--DELETE FROM TESTDB.STUDENT WHERE ((TS_ID = ?) AND (WERSJA = ?))
bind => [2, 2]
[EL Warning]: 2010-01-14 00:43:51.625--UnitOfWork(3023915)--Thread(Thread[main,5,main ])--Exception [EclipseLink-5003] (Eclipse Persistence Services - 2.0.0.v20091127-r5931): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [pl.lodz.p.ck.egzaminy.entities.Student[id=2, ver=2]] cannot be deleted because it has changed or been deleted since it was last read.
Class> pl.lodz.p.ck.egzaminy.entities.Student Primary Key> [2]
[EL Warning]: 2010-01-14 00:43:51.625--UnitOfWork(3023915)--Thread(Thread[main,5,main ])--javax.persistence.OptimisticLockException: Exception [EclipseLink-5003] (Eclipse Persistence Services - 2.0.0.v20091127-r5931): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [pl.lodz.p.ck.egzaminy.entities.Student[id=2, ver=2]] cannot be deleted because it has changed or been deleted since it was last read.
Class> pl.lodz.p.ck.egzaminy.entities.Student Primary Key> [2]
2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.StudentTest concurrentUpdateAndDelete
INFO: **** OK - Expected optimistic lock exception occured
2010-01-14 00:43:51 pl.lodz.p.ck.egzaminy.entities.JPATest tearDown
Re: Unexpected entity version number [message #507719 is a reply to message #507593] Thu, 14 January 2010 13:22 Go to previous messageGo to next message
Chris Delahunt is currently offline Chris Delahunt
Messages: 1023
Registered: July 2009
Senior Member
Hello,

I find it odd that the logs are showing the update statements from the first method using the same connection - this might explain why the delete fails. If they are appart of the same transaction, then when the second statement fails it will rollback the version number change. What I don't understand is how, since the code should be starting two distinct transactions. Can you change the logging to finest? This should show the transaction begin/end in the logs.

Best Regards,
Chris
Re: Unexpected entity version number [message #507936 is a reply to message #507719] Fri, 15 January 2010 09:07 Go to previous messageGo to next message
Marcin Kwapisz is currently offline Marcin Kwapisz
Messages: 14
Registered: January 2010
Junior Member
Hello,
I think I have found the "problem". It is not a bug, it is a feature of jpa2 called second level cache. See chapter 3.7 of the JSR317 spec. Setting shared-cache-mode to "none" fo persistence unit solves the unexpected entity version number problem. The default value for eclipselink must be "all", I think.

Regards
Marcin Kwapisz
Re: Unexpected entity version number [message #508007 is a reply to message #507936] Fri, 15 January 2010 14:44 Go to previous messageGo to next message
Chris Delahunt is currently offline Chris Delahunt
Messages: 1023
Registered: July 2009
Senior Member
Ah, I didn't notice your setup/tear down methods using a connection directly. Yes, JPA providers are allowed to use a second level cache, and EclipseLink has always done so - JPA2 just added api allowing standard configuration. Because your tests clear out the database between tests, you might also close the EntityManagers and factories, clearing out the cache. In production, a second level cache can greatly increases performance,but it all depends on how often changes are made outside of the application.

EclipseLink offers a number of other features to help reduce having problems with stale data in such as invalidation and cache coordination.

Best Regards,
Chris
Re: Unexpected entity version number [message #508178 is a reply to message #508007] Sun, 17 January 2010 10:03 Go to previous message
Marcin Kwapisz is currently offline Marcin Kwapisz
Messages: 14
Registered: January 2010
Junior Member
Hello,
There is EntityManagerFactory#getCache()#evictAll() method that can be called in the setUp method.

Regards
Marcin Kwapisz
Previous Topic:Cascade.Persist problems
Next Topic:FileNotFoundException: tempToDelete.xml (Access is denied)
Goto Forum:
  


Current Time: Mon Sep 22 16:20:35 GMT 2014

Powered by FUDForum. Page generated in 0.09554 seconds
.:: Contact :: Home ::.

Powered by: FUDforum 3.0.2.
Copyright ©2001-2010 FUDforum Bulletin Board Software