Debugging Hibernate Envers - Historical Data

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