Performance Zone is brought to you in partnership with:

Tom is a passionate Java/JEE developer working remotely from home located in Poland. He is a big fan of Apache Wicket, clean code, testing and methods with names that actually say something. In his free time he blogs, tweets and organizes Confitura, the biggest Java conference in Poland. Privately husband, father and dog owner, he likes to watch and play football (soccer if you're from USA). Tomasz is a DZone MVB and is not an employee of DZone and has posted 15 posts at DZone. You can read more from them at their website. View Full User Profile

Debugging Hibernate Envers - Historical Data

10.17.2012
| 4380 views |
  • submit to reddit

Recently in our project we reported a strange bug. In one report where we display historical data provided by Hibernate Envers, users encountered duplicated records in the dropdown used for filtering. We tried to find the source of this bug, but after spending a few hours looking at the code responsible for this functionality we had to give up and ask for a dump from production database to check what actually is stored in one table. And when we got it and started investigating, it turned out that there is a bug in Hibernate Envers 3.6 that is a cause of our problems. But luckily after some investigation and invaluable help from Adam Warski (author of Envers) we were able to fix this issue.

Bug itself

Let’s consider following scenario:

  1. A transaction is started. We insert some audited entities during it and then it is rolled back.
  2. The same EntityManager is reused to start another transaction
  3. Second transaction is committed

But when we check audit tables for entities that were created and then rolled back in step one, we will notice that they are still there and were not rolled back as we expected. We were able to reproduce it in a failing test in our project, so the next step was to prepare failing test in Envers so we could verify if our fix is working.

Failing test

The simplest test cases already present in Envers are located in Simple.java class and they look quite straightforward:

public class Simple extends AbstractEntityTest {
    private Integer id1;

    public void configure(Ejb3Configuration cfg) {
        cfg.addAnnotatedClass(IntTestEntity.class);
    }

    @Test
    public void initData() {
        EntityManager em = getEntityManager();
        em.getTransaction().begin();
        IntTestEntity ite = new IntTestEntity(10);
        em.persist(ite);
        id1 = ite.getId();
        em.getTransaction().commit();

        em.getTransaction().begin();
        ite = em.find(IntTestEntity.class, id1);
        ite.setNumber(20);
        em.getTransaction().commit();
    }

    @Test(dependsOnMethods = "initData")
    public void testRevisionsCounts() {
        assert Arrays.asList(1, 2).equals(getAuditReader().getRevisions(IntTestEntity.class, id1));
    }

    @Test(dependsOnMethods = "initData")
    public void testHistoryOfId1() {
        IntTestEntity ver1 = new IntTestEntity(10, id1);
        IntTestEntity ver2 = new IntTestEntity(20, id1);

        assert getAuditReader().find(IntTestEntity.class, id1, 1).equals(ver1);
        assert getAuditReader().find(IntTestEntity.class, id1, 2).equals(ver2);
    }
}

so preparing my failing test executing scenario described above wasn’t a rocket science:

/**
 * @author Tomasz Dziurko (tdziurko at gmail dot com)
 */
public class TransactionRollbackBehaviour  extends AbstractEntityTest {
 
    public void configure(Ejb3Configuration cfg) {
        cfg.addAnnotatedClass(IntTestEntity.class);
    }
 
    @Test
    public void testAuditRecordsRollback() {
        // Given
        EntityManager em = getEntityManager();
        em.getTransaction().begin();
        IntTestEntity iteToRollback = new IntTestEntity(30);
        em.persist(iteToRollback);
        Integer rollbackedIteId = iteToRollback.getId();
        em.getTransaction().rollback();
 
        // When
        em.getTransaction().begin();
        IntTestEntity ite2 = new IntTestEntity(50);
        em.persist(ite2);
        Integer ite2Id = ite2.getId();
        em.getTransaction().commit();
 
        // Then
        List<Number> revisionsForSavedClass = getAuditReader().getRevisions(IntTestEntity.class, ite2Id);
        assertEquals(revisionsForSavedClass.size(), 1, "There should be one revision for inserted entity");
 
        List<Number> revisionsForRolledbackClass = getAuditReader().getRevisions(IntTestEntity.class, rollbackedIteId);
        assertEquals(revisionsForRolledbackClass.size(), 0, "There should be no revisions for insert that was rolled back");
    }
}

Now I could verify that tests are failing on the forked 3.6 branch and check if the fix that we had is making this test green.

The fix

After writing a failing test in our project, I placed several breakpoints in Envers code to understand better what is wrong there. But imagine being thrown in a project developed for a few years by many programmers smarter than you. I felt overwhelmed and had no idea where the  fix should be applied and what exactly is not working as expected. Luckily in my company we have Adam Warski on board. He is the initial author of Envers and actually he pointed us the solution.

The fix itself contains only one check that registers audit processes that will be executed on transaction completion only when such processes iare still in the Map<Transaction, AuditProcess> for the given transaction. It sounds complicated, but if you look at the class AuditProcessManager in this commit it should be more clear what is happening there.

Official path

Besides locating a problem and fixing it, there are some more official steps that must be performed to have fix included in Envers.

Step 1. Create JIRA issue with bug - https://hibernate.onjira.com/browse/HHH-7682

Step 2: Create local branch Envers-bugfix-HHH-7682 of forked Hibernate 3.6

Step 3: Commit and push failing test and fix to your local and remote repository on Github

Step 4: Create pull request - https://github.com/hibernate/hibernate-orm/pull/393

Step 5: Wait for merge

And that’s all. Now fix is merged into main repository and we have one bug less in the world of open source :)

 

 

 

Published at DZone with permission of Tomasz Dziurko, author and DZone MVB. (source)

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)