QueryException on map associaton when using Envers

[ahaumer]

Hi!

I have an existing JEE application (running on Wildfly 10) with about 100 entity-classes where I now want to use Envers to enable versioning of the entity data.

Migrating the whole data model to support Envers seems to work quite well so far, but I have found a handful of entity classes where a QueryException is triggered when I navigate a certain association.

I managed to create a stripped-down Hibernate/Envers test application small enough to show the problem, but without all the overhead of my "real" JEE application.

My test application produces exact the same exception on exact the same type of association and I will use this application to describe the problem here.

You can find a tar file of this application attached to this posting.  There is also a DDL SQL script you can use to set up a test database.

I'm using PostgreSQL as RDBMS, you will have to change the DDL script and the persistence.xml file in order to run the application with another database backend.

Now to the problem...

The association in question is a special map like this:

@Audited 
public class Category { 
[...]   
  private Map<Item, Value> categoryItem = new HashMap<>(); 
[...] 
}

where Item is another Entity and Value is some value-object.

I have mapped this association like this:

<hibernate-mapping package="enverstest.model" default-access="field" >
   <class name="Category" table="category">
 [...]
     <map name="categoryItem" table="category_item">
        <key column="category_id" not-null="true" />
        <map-key-many-to-many column="item_id" class="Item"/>
        <composite-element class="Value" >
          <property name="number" column="number" />
          <property name="text" column="text" />
        </composite-element>
      </map>
  </class>
 </hibernate-mapping>

This mapping works in principle. Without Envers I can save, modify and read all the data in the Category and Item entities as well as in the Value object associated with a Category entity, indexed with an Item entity.

With Envers enabled, I can create the entities and Envers fills all the auditing tables, including the category_item table with historic data.

But when I load a historic view of any Category entity using the AuditQuery#forEntiesAtRevision() API and when I then try to access the categoryItem property of the returned Category entity in some way, I get the following exception:

org.hibernate.QueryException: could not resolve property: originalId.rev_type of: enverstest.model.Item_r

This exception comes from Hibernate when it tries to translate a query created by Envers in order to load the historic data for the map from the database.

The query created by Envers looks like this:

select new list(ee__, e__)
     from category_item_r ee__,
          enverstest.model.Item_r e__
    where ee__.originalId.mapkey_id = e__.originalId.id
      and ee__.originalId.Category_id = :Category_id
      and e__.originalId.rev_begin.id <= :revision
      and ee__.originalId.rev_begin.id <= :revision
      and ee__.originalId.rev_type != :delrevisiontype
      and e__.originalId.rev_type != :delrevisiontype
      and (e__.rev_end.id > :revision or e__.rev_end is null)
      and (ee__.rev_end.id > :revision or ee__.rev_end is null)

When I annotate the categoryItem property with @NotAudited the exception is gone, but of course then versioning is disabled also.

Please see the attached tar archive for a complete test application.

In order to produce the problem, you have to set up a database manually using the provided ddl.sql script and adjust the persistence.xml file accordingly to your environment.

There is a JUnit test class CategoryTest which contains the relevant queries. If you set the variable showEnversError in this test to true, the test will throw an exception. If you set this variable to false, the test will succeed.

The test application is implemented as Maven project, a mvn test in the root directory of the project should be sufficient to run the test.

This is what I get when i run the test with showEnversError set to false:

andreas@ahnote:~/workspace/enverstest> mvn test
[INFO] Scanning for projects...
[INFO]                                                                        
[INFO] ------------------------------------------------------------------------
[INFO] Building Hibernate Envers Test 1.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[...]
------------------------------------------------------- 
T E S T S 
-------------------------------------------------------
Running enverstest.model.CategoryTest
 WARN [rManagerConnectionProviderImpl:  70] HHH10001002: Using Hibernate built-in connection pool (not for production use!)

===== Fill Database =====

===== Database filled ===== 

===== Check current entities ===== 

===== Load historic data ===== 

Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.729 sec 

Results :

Tests run: 1, Failures: 0, Errors: 0, Skipped: 0 

[INFO] ------------------------------------------------------------------------ 
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 8.817 s
[INFO] Finished at: 2017-06-23T14:03:28+02:00
[INFO] Final Memory: 18M/182M
[INFO] ------------------------------------------------------------------------

And this is what I get when i run the test with showEnversError set to true:

andreas@ahnote:~/workspace/enverstest> mvn test 
[INFO] Scanning for projects... 
[INFO]                                                                          
[INFO] ------------------------------------------------------------------------ 
[INFO] Building Hibernate Envers Test 1.0-SNAPSHOT 
[INFO] ------------------------------------------------------------------------ 
[...] 
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 5.499 sec <<< FAILURE! 
testEnvers(enverstest.model.CategoryTest)  Time elapsed: 5.389 sec  <<< ERROR! 
java.lang.IllegalArgumentException: org.hibernate.QueryException: could not resolve property: originalId.rev_type of: enverstest.model.Item_r [select new list(ee__, e__) from category_item_r ee__, enverstest.model.Item_r e__ where ee__.originalId.Category_id = :Category_id and e__.originalId.rev_begin.id <= :revision and ee__.originalId.rev_begin.id <= :revision and ee__.originalId.rev_type != :delrevisiontype and e__.originalId.rev_type != :delrevisiontype and (ee__.originalId.mapkey_id = e__.originalId.id or (ee__.originalId.mapkey_id is null and e__.originalId.id is null)) and (e__.rev_end.id > :revision or e__.rev_end is null) and (ee__.rev_end.id > :revision or ee__.rev_end is null)]         
         at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:131)         
         at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:155)         
         at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:162)         
         at org.hibernate.internal.AbstractSharedSessionContract.createQuery(AbstractSharedSessionContract.java:663)
         at org.hibernate.internal.AbstractSharedSessionContract.createQuery(AbstractSharedSessionContract.java:102)
         at org.hibernate.envers.internal.entities.mapper.relation.query.AbstractRelationQueryGenerator.getQuery(AbstractRelationQueryGenerator.java:55)
         at org.hibernate.envers.internal.entities.mapper.relation.lazy.initializor.AbstractCollectionInitializor.initialize(AbstractCollectionInitializor.java:49)
         at org.hibernate.envers.internal.entities.mapper.relation.lazy.proxy.MapProxy.checkInit(MapProxy.java:34)
         at org.hibernate.envers.internal.entities.mapper.relation.lazy.proxy.MapProxy.get(MapProxy.java:64)
         at enverstest.model.Category.getValue(Category.java:50)
         at enverstest.model.CategoryTest.testEnvers(CategoryTest.java:139)
         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.lang.reflect.Method.invoke(Method.java:498)
         at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
         at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
         at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
         at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
         at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
         at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
         at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
         at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
         at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
         at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
         at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
         at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
         at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
         at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
         at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
         at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252)
         at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141)
         at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112)
         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.lang.reflect.Method.invoke(Method.java:498)
         at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
         at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
         at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
         at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
         at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75) 
Caused by: org.hibernate.QueryException: could not resolve property: originalId.rev_type of: enverstest.model.Item_r [select new list(ee__, e__) from category_item_r ee__, enverstest.model.Item_r e__ where ee__.originalId.Category_id = :Category_id and e__.originalId.rev_begin.id <= :revision and ee__.originalId.rev_begin.id <= :revision and ee__.originalId.rev_type != :delrevisiontype and e__.originalId.rev_type != :delrevisiontype and (ee__.originalId.mapkey_id = e__.originalId.id or (ee__.originalId.mapkey_id is null and e__.originalId.id is null)) and (e__.rev_end.id > :revision or e__.rev_end is null) and (ee__.rev_end.id > :revision or ee__.rev_end is null)]
         at org.hibernate.QueryException.generateQueryException(QueryException.java:120)
         at org.hibernate.QueryException.wrapWithQueryString(QueryException.java:103)
         at org.hibernate.hql.internal.ast.QueryTranslatorImpl.doCompile(QueryTranslatorImpl.java:217)
         at org.hibernate.hql.internal.ast.QueryTranslatorImpl.compile(QueryTranslatorImpl.java:141)
         at org.hibernate.engine.query.spi.HQLQueryPlan.(HQLQueryPlan.java:115)
         at org.hibernate.engine.query.spi.HQLQueryPlan.(HQLQueryPlan.java:77)
         at org.hibernate.engine.query.spi.QueryPlanCache.getHQLQueryPlan(QueryPlanCache.java:153)
         at org.hibernate.internal.AbstractSharedSessionContract.getQueryPlan(AbstractSharedSessionContract.java:546)
         at org.hibernate.internal.AbstractSharedSessionContract.createQuery(AbstractSharedSessionContract.java:655)
         ... 38 more 
Caused by: org.hibernate.QueryException: could not resolve property: originalId.rev_type of: enverstest.model.Item_r
         at org.hibernate.persister.entity.AbstractPropertyMapping.propertyException(AbstractPropertyMapping.java:62)
         at org.hibernate.persister.entity.AbstractPropertyMapping.toColumns(AbstractPropertyMapping.java:77)
         at org.hibernate.persister.entity.BasicEntityPropertyMapping.toColumns(BasicEntityPropertyMapping.java:43)
         at org.hibernate.persister.entity.AbstractEntityPersister.toColumns(AbstractEntityPersister.java:1829)
         at org.hibernate.hql.internal.ast.tree.FromElementType.toColumns(FromElementType.java:442)
         at org.hibernate.hql.internal.ast.tree.FromElementType.toColumns(FromElementType.java:408)
         at org.hibernate.hql.internal.ast.tree.FromElement.toColumns(FromElement.java:516)
         at org.hibernate.hql.internal.ast.tree.DotNode.getColumns(DotNode.java:123)
         at org.hibernate.hql.internal.ast.tree.DotNode.initText(DotNode.java:250)
         at org.hibernate.hql.internal.ast.tree.DotNode.resolve(DotNode.java:225)
         at org.hibernate.hql.internal.ast.tree.FromReferenceNode.resolve(FromReferenceNode.java:114)
         at org.hibernate.hql.internal.ast.tree.DotNode.resolveFirstChild(DotNode.java:167)
         at org.hibernate.hql.internal.ast.HqlSqlWalker.lookupProperty(HqlSqlWalker.java:694)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.addrExpr(HqlSqlBaseWalker.java:5003)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.expr(HqlSqlBaseWalker.java:1286)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.exprOrSubquery(HqlSqlBaseWalker.java:4707)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.comparisonExpr(HqlSqlBaseWalker.java:4199)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.logicalExpr(HqlSqlBaseWalker.java:2138)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.logicalExpr(HqlSqlBaseWalker.java:2066)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.logicalExpr(HqlSqlBaseWalker.java:2063)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.logicalExpr(HqlSqlBaseWalker.java:2063)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.logicalExpr(HqlSqlBaseWalker.java:2063)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.whereClause(HqlSqlBaseWalker.java:815)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.query(HqlSqlBaseWalker.java:609)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.selectStatement(HqlSqlBaseWalker.java:313)
         at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.statement(HqlSqlBaseWalker.java:261)
         at org.hibernate.hql.internal.ast.QueryTranslatorImpl.analyze(QueryTranslatorImpl.java:266)
         at org.hibernate.hql.internal.ast.QueryTranslatorImpl.doCompile(QueryTranslatorImpl.java:189)
         ... 44 more

Results :  

Tests in error:   
  testEnvers(enverstest.model.CategoryTest): org.hibernate.QueryException: could not resolve property: originalId.rev_type of: enverstest.model.Item_r [select new list(ee__, e__) from category_item_r ee__, enverstest.model.Item_r e__ where ee__.originalId.Category_id = :Category_id and e__.originalId.rev_begin.id <= :revision and ee__.originalId.rev_begin.id <= :revision and ee__.originalId.rev_type != :delrevisiontype and e__.originalId.rev_type != :delrevisiontype and (ee__.originalId.mapkey_id = e__.originalId.id or (ee__.originalId.mapkey_id is null and e__.originalId.id is null)) and (e__.rev_end.id > :revision or e__.rev_end is null) and (ee__.rev_end.id > :revision or ee__.rev_end is null)] 
 
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0

I tested this with Hibernate 5.0.12.Final as well as with Hibernate 5.2.10.Final. With both versions I get the same behaviour.

To me this looks like Envers is producing illegal Hibernate queries.

But why?

Is there a bug in my mapping, in the way I use Envers, or is this even a bug in Envers?

How can I make this association work with Envers?

Any idea, anyone?

Thanks!

- andreas

Message was edited by: Andreas Haumer in order to make it more readable (I hope it works now. This editor really needs a pre-view function and a better support for code fragments...)

[ahaumer]

Hi again!

I think I might have found a workaround for the problem I described in the posting above.

Looking through all of my mappings I found that I have several similar map properties which work with Envers. All working map properties are using the element tag, all map properties using the composite-element tag throw a org.hibernate.QueryException when the property is first read in my Java code.

So today I tried to implement a CompositeUserType and mapped the problematic property with an element tag instead of a composite-element tag like this:

<map name="categoryItem" table="category_item">
  <key column="category_id" not-null="true" />
  <map-key-many-to-many column="item_id" class="Item"/>
  <element type="enverstest.type.ValueType" >
    <column name="number" />
    <column name="text"/>
  </element>
</map>

The custom user type enverstest.type.ValueType implements the org.hibernate.usertype.CompositeUserType interface.

And with this mapping everything works, no QueryException occurs when I access the property categoryItem in my Java code!

It seems, the exception occurs with collection-mappings using the composite-element tag, only.

And it seems it only occurs with map collections, as I have other collection mappings using the composite-element tag (like lists) where the exception does not occur when I look at historic data.

To me this is beginning to look more like an Envers bug.

Please give me a reply if you think my reasoning is flawed or if you have any other idea of what might be wrong here in the first place.

You can find all the code in the attached enverstest-v2 tar archive.

[ahaumer]

Hi!

Today I tried to implement the CompositeUserType workaround in my application, but I found another problem!

In my case, the CompositeUserType has to support nullable properties, i.e. some of the columns inside the composite type may contain null values, some might not.

With this setup, I now get a javax.persistence.EntityNotFoundException when Envers tries to retrieve a row from the audit table where some property is null, even if the row is perfectly stored in the audit table.

The reason for this exception is another problematic query: Envers tries to query a row with a null value, but for that it uses an illegal where clause.

I changed my small enverstest application to demonstrate this problem, too.

Here I get the following query when Envers tries to select a row from the audit table where the column number has a null value:

select category_i0_.rev_begin as rev_begi1_2_0_, 
        category_i0_.category_id as category2_2_0_, 
        category_i0_.number as number3_2_0_, 
        category_i0_.text as text4_2_0_, 
        category_i0_.item_id as item_id5_2_0_, 
        category_i0_.rev_type as rev_type6_2_0_, 
        category_i0_.rev_end as rev_end7_2_0_ 
   from category_item_r category_i0_ 
  where category_i0_.rev_begin=12
    and category_i0_.category_id=14 
    and category_i0_.number=null 
    and category_i0_.text='The Value'
    and category_i0_.item_id=14

Here, the value of number is to be null, but you can not query for a null value with a where-clause of category_i0_.number=null and so I get an empty resultset and thus an EntityNotFoundException

Envers should use category_i0_.number is null instead to retrieve this row where the number column has a value of null.

How can I make Envers use a correct query in this case?

Please see the attachment for the complete code of my modified test application.

[ahaumer]

Hi!

I have now created a bug report in the Hibernate JIRA for this issue.

See https://hibernate.atlassian.net/browse/HHH-11841