WildFly 14 + Hibernate 5.3.6 + Named query resulting in empty list being returned

[sergiu_pienar]

I'm trying to migrate an app from WildFly 13 (with Hibernate 5.1.14) to WildFly 14 + Hibernate 5.3.6.

In the process I've stumbled on a few problems, of which the latest is org.hibernate.Query returning an empty list when doing a query.

The same code works fine with WidlFly 13 + Hibernate 5.1.14:

Session sess = null;

try {
sess = hibernateSessionFactory.openSession();
org.hibernate.Query query1 = null;

// build the query or get the right query by its name
if (query.getQueryName() != null) {
query1 = sess.getNamedQuery(query.getQueryName());
} else {
throw new IllegalArgumentException("The query argument must provide HQL or query name!");
}

// if first and max are -1 it means it is a COUNTER
if (query.getMaxResults() == -1 && query.getFirstResult() == -1) {
query1 = sess.createQuery(DAOHelper.getCountQuery(query1.getQueryString()));
} else {
// set first and max Results
if (query.getFirstResult() != com.acme.persistence.Query.FIRST_RESULTS && query.getFirstResult() >= 0) {
query1.setFirstResult(query.getFirstResult());
}
if (query.getMaxResults() != com.acme.persistence.Query.MAX_RESULTS && query.getMaxResults() > 0) {
query1.setMaxResults(query.getMaxResults());
}
}

// parameter set
for (Parameter p : query.getParameters()) {
try {
if ((p.getType() == Parameter.TYPE_OBJECT) || p.getValue() == null) {
query1.setParameter(p.getName(), p.getValue());
} else if (p.getType() == Parameter.TYPE_LONG) {
query1.setLong(p.getName(), ((Long)p.getValue()).longValue());
} else if (p.getType() == Parameter.TYPE_STRING) {
query1.setString(p.getName(), (String)p.getValue());
} else if (p.getType() == Parameter.TYPE_TIMESTAMP) {
query1.setTimestamp(p.getName(), (Date)p.getValue());
} else if (p.getType() == Parameter.TYPE_LIST) {
query1.setParameterList(p.getName(), (List)p.getValue());
} else if (p.getType() == Parameter.TYPE_BIGDECIMAL) {
query1.setBigDecimal(p.getName(), (BigDecimal)p.getValue());
}

} catch (QueryParameterException qpex) {
DAOHelper.LOGGER.warn("Ignoring parameter '" + p.getName() + "' for the query '"
+ ((StringTools.isValidString(query.getQueryName())) ? query.getQueryName() : query.getSql())
+ "' does not recognize this one");
} catch (IllegalArgumentException iaex) {
DAOHelper.LOGGER.warn("Ignoring parameter '" + p.getName() + "' for the query '"
+ ((StringTools.isValidString(query.getQueryName())) ? query.getQueryName() : query.getSql())
+ "' does not recognize this one");
}
}

return query1.list();
} finally {
if (sess != null) {
sess.close();
}
}

I've enabled TRACE logging on both org.hibernate and com.arjuna and the relevant section is below (excerpt from the WildFly 13 server):

2018-09-11 13:36:27,575 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (default task-3) Located HQL query plan in cache (FROM com.acme.dao.client.ClientPreferences as cp
      WHERE cp.clientId = :clientId
      ORDER BY preferenceName ASC)
2018-09-11 13:36:27,575 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (default task-3) Located HQL query plan in cache (FROM com.acme.dao.client.ClientPreferences as cp
      WHERE cp.clientId = :clientId
      ORDER BY preferenceName ASC)
2018-09-11 13:36:27,575 TRACE [org.hibernate.engine.query.spi.HQLQueryPlan] (default task-3) Find: FROM com.acme.dao.client.ClientPreferences as cp
      WHERE cp.clientId = :clientId
      ORDER BY preferenceName ASC
2018-09-11 13:36:27,575 TRACE [org.hibernate.engine.spi.QueryParameters] (default task-3) Named parameters: {clientId=2}
2018-09-11 13:36:27,575 DEBUG [org.hibernate.SQL] (default task-3) select clientpref0_.preferenceId as preferen1_13_, clientpref0_.clientId as clientId2_13_, clientpref0_.preferenceName as preferen3_13_, clientpref0_.type as type4_13_, clientpref0_.description as descript5_13_, clientpref0_.ranges as ranges6_13_, clientpref0_.asText as asText7_13_, clientpref0_.asNumber as asNumber8_13_, clientpref0_.asDate as asDate9_13_, clientpref0_.editLevel as editLev10_13_ from ClientPreference_2 clientpref0_ where clientpref0_.clientId=? order by clientpref0_.preferenceName ASC
2018-09-11 13:36:27,575 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-3) Registering statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@49a4de96]
2018-09-11 13:36:27,575 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default task-3) Registering last query statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@49a4de96]
2018-09-11 13:36:27,575 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-3) binding parameter [1] as [BIGINT] - [2]
2018-09-11 13:36:27,575 TRACE [org.hibernate.loader.Loader] (default task-3) Bound [2] parameters total
2018-09-11 13:36:27,576 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-3) Registering result set [com.mysql.jdbc.JDBC4ResultSet@7012c0be]
2018-09-11 13:36:27,576 TRACE [org.hibernate.loader.Loader] (default task-3) Processing result set
2018-09-11 13:36:27,576 DEBUG [org.hibernate.loader.Loader] (default task-3) Result set row: 0

The WildFly 14 logs are exactly the same but the result set is empty:

2018-09-11 13:39:10,921 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (default task-1) Located HQL query plan in cache (FROM com.acme.dao.client.ClientPreferences as cp
      WHERE cp.clientId = :clientId
      ORDER BY preferenceName ASC)
2018-09-11 13:39:10,921 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (default task-1) Located HQL query plan in cache (FROM com.acme.dao.client.ClientPreferences as cp
      WHERE cp.clientId = :clientId
      ORDER BY preferenceName ASC)
2018-09-11 13:39:10,921 TRACE [org.hibernate.engine.query.spi.HQLQueryPlan] (default task-1) Find: FROM com.acme.dao.client.ClientPreferences as cp
      WHERE cp.clientId = :clientId
      ORDER BY preferenceName ASC
2018-09-11 13:39:10,921 TRACE [org.hibernate.engine.spi.QueryParameters] (default task-1) Named parameters: {clientId=2}
2018-09-11 13:39:10,921 DEBUG [org.hibernate.SQL] (default task-1) select clientpref0_.preferenceId as preferen1_13_, clientpref0_.clientId as clientId2_13_, clientpref0_.preferenceName as preferen3_13_, clientpref0_.type as type4_13_, clientpref0_.description as descript5_13_, clientpref0_.ranges as ranges6_13_, clientpref0_.asText as asText7_13_, clientpref0_.asNumber as asNumber8_13_, clientpref0_.asDate as asDate9_13_, clientpref0_.editLevel as editLev10_13_ from ClientPreference_2 clientpref0_ where clientpref0_.clientId=? order by clientpref0_.preferenceName ASC
2018-09-11 13:39:10,921 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Registering statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@511f6ce2]
2018-09-11 13:39:10,921 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default task-1) Registering last query statement [org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@511f6ce2]
2018-09-11 13:39:10,921 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [BIGINT] - [2]
2018-09-11 13:39:10,921 TRACE [org.hibernate.loader.Loader] (default task-1) Bound [2] parameters total
2018-09-11 13:39:10,922 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Registering result set [com.mysql.jdbc.JDBC4ResultSet@20811fe1]
2018-09-11 13:39:10,922 TRACE [org.hibernate.loader.Loader] (default task-1) Processing result set
2018-09-11 13:39:10,922 TRACE [org.hibernate.loader.Loader] (default task-1) Done processing result set (0 rows)

The only difference between WF13 and WF14 is in hibernate's session factory where I set hibernate.allow_update_outside_transaction to true.

[smarlow]

Hi,

https://github.com/hibernate/hibernate-orm/blob/5.3/migration-guide.adoc mentions some of the changes that went into Hibernate ORM 5.2+ that sound like they might be impacting your application.  There are also new configuration settings, but before we get into configuration options though, lets talk about the Hibernate ORM (native) bytecode transformer that you could try enabling for this application.  The Hibernate transformer will only update the in-memory copy of your application.  As per the above linked documentation, you could try that for this case, by restarting the WildFly app server with the following options:

./standalone.sh -DHibernate51CompatibilityTransformer=true

If you want to see the actual transformed application code, specify the output folder of where the *.asm files should be written to (you should create that folder in advance):

./standalone.sh -DHibernate51CompatibilityTransformer=true -DHibernate51CompatibilityTransformer.showTransformedClassFolder=/tmp

When you later restart the server, with just "./standalone.sh", your application will not be transformed.

You might also want to enable TRACE debugging for logging category "org.jboss.as.hibernate.transformer", to log exactly what modifications are made to your application (you only need to run with the TRACE logging once, just to help you understand which classes were modified, which is a hint as to which application classes you may want to rewrite for Hibernate ORM 5.3+).

Note that the transformer is deprecated, so you should plan to rewrite for ORM 5.3 in the future.

Scott

[sergiu_pienar]

Hi Scott,

I enabled the transformer and added TRACE for org.jobss.as.hibernate.transformer. The only relevant entires in the transformer log are as below:

class 'com/acme/util/dao/DAOHelper', is calling org.hibernate.Query.setFirstResult, which must be changed to call setHibernateFirstResult() so setting a value < 0 results in pagination starting with the 0th row as was done in Hibernate ORM 5.1 (instead of throwing IllegalArgumentException as specified by JPA).
2018-09-12 08:57:37,596 DEBUG [org.jboss.as.hibernate.transformer] (MSC service thread 1-4) Deprecated Hibernate51CompatibilityTransformer transformed application classes in 'deployment.acme-all-5.4.1.4.ear.acme-all-ejbs.jar', class 'com/acme/util/dao/DAOHelper', is calling org.hibernate.Query.setMaxResults, which must be changed to call setHibernateMaxResults() so that values <= 0 are treated the same as uninitialized.  Review Hibernate ORM migration doc

I did apply those changes but to no avail.

Also, running the app with the

-DHibernate51CompatibilityTransformer=true

argument but that did not change anything, I'm still getting an empty list upon the call.

[smarlow]

Hi,

Thanks for reporting this issue!  I have a few more questions:

1. From the example code you posted above, are you calling query1.setFirstResult(query.getFirstResult())?  What is the query.getFirstResult() value?

2. Also from the example code, are you calling query1.setMaxResults(query.getMaxResults())?  What is the query.getMaxResults() value?

3. Did you modify the application code for ORM 5.3, as suggested by the transformer output?  Or are you letting the transformer handle that for you?  I'm just trying to follow what you have changed, from the example code above.

Scott

[sergiu_pienar]

Hi,

1.) and 2.) -> The query.getFirstResult() and query.getMaxResults() have a value of -100 thus the if block doesn't validate so I'm not actually setting the query1.setFirstResult() nor query1.setMaxResults().

3.) I did modify the code, of course to no use, since the statements in the if block are not reached.

I thought at some time that not having query1.setHibernateFirstResult() or query1.setHibernateMaxResults() would be the issue but it seems as this is not the case as the if block is never entered.

I tried the following:

a.) start the appserver with the -DHibernate51CompatibilityTransformer=true argument, run the query. The result list was empty, as it if had no impact on the app.

b.) change the code as per the transformer suggestions, built, deployed, run the query. The result list is empty.

Thank you for your time and interest.

[smarlow]

Hi,

gbadner and myself just discussed this issue.  Gail asked if you could provide a standalone test case that reproduces this.  Beyond that, we have a few more questions for you, to help us understand more:

1. You mentioned that the problem doesn't occur with WildFly 13, could you try with WildFly 13 again and start the app server (standalone.sh) with the "-Dee8.preview.mode=true" option, so that Hibernate ORM 5.3 is used.  This might tell us if the problem was introduced later in Hibernate ORM 5.3.
2. With WildFly 14, to verify that the row with clientId=2, is in the database, could you try just returning all rows (remove the clientId parameter from the query), or verify some other way.
3. Also with WildFly 14, could you try using session.createQuery(String) to create the query to see if that returns the non-empty result set.

Thanks,

Scott

[sergiu_pienar]

Hi Scott,

Unfortunately for me this seems to have been a stupid configuration issue - with the WF14 looking into another DB (compared to the WF13 DB) that did not have the clientId=2 row in the DB.

I have an ant task that creates the DB structure and entries for each platform that I run wildfly on. The fact that the WF14 did not had the proper entries was due to WildFly 14 + Hibernate 5.3.6 results in Caused by: javax.persistence.TransactionRequiredException: Executing an update/delete query  where the updates statements would fail to populate the DB with its proper entries.

I never looked closely at the ant log output nor did I tried checking in mysql whether that row with clientId=2 actually existed for I never thought that the DB population would fail.

Sorry for wasting you time on this issue.