Description of problem: I have a CLI script that calls an operation on resource and then it immediately starts querying for operation schedule id to check the result. From time to time my it fails. Version-Release number of selected component (if applicable): JON 3.1.1.CR2 How reproducible: 5-10% Steps to Reproduce: 1. run a CLI script, that invokes "discovery" operation and starts checking operation result Actual results: This is what I get in CLI: Exception in thread "main" org.rhq.enterprise.client.script.CLIScriptException: javax.script.ScriptException: sun.org.mozilla.javascript.internal.WrappedException: Wrapped javax.ejb.EJBException: [Warning] java.lang.IllegalArgumentException: PageList was passed an empty collection but 'totalSize' was 1, PageControl[page=0, size=1, sort[startTime DESC]] (<Unknown source>#980) in <Unknown source> at line number 980 at org.rhq.enterprise.client.commands.ScriptCommand.executeScriptFile(ScriptCommand.java:298) at org.rhq.enterprise.client.commands.ScriptCommand.execute(ScriptCommand.java:108) at org.rhq.enterprise.client.ClientMain$StartupConfiguration.process(ClientMain.java:141) at org.rhq.enterprise.client.ClientMain.main(ClientMain.java:161) Caused by: javax.script.ScriptException: sun.org.mozilla.javascript.internal.WrappedException: Wrapped javax.ejb.EJBException: [Warning] java.lang.IllegalArgumentException: PageList was passed an empty collection but 'totalSize' was 1, PageControl[page=0, size=1, sort[startTime DESC]] Expected results: No exception Additional info:
Created attachment 611285 [details] server.log
Targeting for consideration in jon312. If we have an automated way to cause this to fail 5-10% of the time, that's hopefully sufficient to give us some insight.
I think is related to https://bugzilla.redhat.com/show_bug.cgi?id=773626.
Libor - can you attach your script that you used?
Seems virtually the same as Bug 972756
Created attachment 788074 [details] reproducer script Here is a repro-script. It does not retrieve operation history, but just asks for resources instead. When using "retrieve operation history" test I was not able to reproduce it even on JON 3.1.2 (we're randomly hitting this issue on this version). Test works the way that it: creates a new resource (network interface on as7) and very often (with 10ms sleep time) asks server for createResourceHistory and then for new child resource presence => here it fails That file is large because it contains whole rhqapi.js, important part is at the bottom. I am able to hit this bug with this script on RHQ 4.8 anytime when I run it around attempt 3-6.
I can reproduce (after fixing Bug 972756, which seems to be completely independent, even if the symptoms are similar) it with the supplied script, thanks Libor. I think the underlying issue is a design problem, as the org.rhq.enterprise.server.util.CriteriaQueryRunner#execute method is not transactional and does this: results = new PageList<T>(getCollection(), getCount(), pageControl); which means it first fires a query for the collection and then another one for the count. When now a resource creation/deletion/... report is coming in after the SQL for getCollection() was fired and before getCount() has started, then the results may differ. So basically we should either - use a more clever query to return count and collection in one go or - use a transaction, so that the database keeps the state consistent. This may not be enough for other cases of this "PageList .. " error --- server log --- Caused by: java.lang.IllegalArgumentException: PageList was passed an empty collection but 'totalSize' was 1, PageControl[page=0, size=-1] at org.rhq.core.domain.util.PageList.<init>(PageList.java:87) [rhq-core-domain-ejb3.jar:4.9.0-SNAPSHOT] at org.rhq.enterprise.server.util.CriteriaQueryRunner.execute(CriteriaQueryRunner.java:70) [rhq-server.jar:4.9.0-SNAPSHOT] at org.rhq.enterprise.server.resource.ResourceManagerBean.findResourcesByCriteria(ResourceManagerBean.java:2595) [rhq-server.jar:4.9.0-SNAPSHOT]
The org.rhq.enterprise.server.util.CriteriaQueryRunner#execute is not transactional in and of itself, because the runner is not an EJB. That said, the runner is called from SLSBs. The SLSB method in question for the repro script is ResourceManagerBean#findResourcesByCriteria, which doesn't specify a transaction attribute and therefore defaults to "REQUIRED". Hence the criteria DOES run in a transaction. The problem is that our datasource, RHQDS, specifies the transaction isolation level as TRANSACTION_READ_COMMITTED. That isolation level allows for "phantom reads", i.e. a single select can return different number of rows depending on other concurrently committed transactions. Therefore I cannot see many ways forward with this. I'd argue against upping the transaction isolation, because that has high performance cost and has to be set datasource-wide. The only other option is to detect this particular error inside the criteria runner and re-run the getCollection() and getCount() until the sizes match or somehow cleverly rewrite the queries such that they return the count and the results within 1 query.
commit dc6a1fedea3bfa9efdfde446d1712d353a591778 Author: Lukas Krejci <lkrejci> Date: Thu Aug 29 18:34:45 2013 +0200 [BZ 855674] - Get rid of the dreaded "PageList was passed an empty collection but 'totalSize' was X" exception. The main part of the fix is just the realization that the "error" condition for which the exception was thrown is actually no error but can be triggered by the mere fact that we use READ_COMMITTED isolation level. The fact that a user can go past the last page of a result is actually also not an error and can be triggered by for example a massive change in the available data between the user asking for first and second page. I think it is better to stop treating all such conditions as errors and instead provide the user with means of detecting such states. For that a new method on pagelist was introduced: PageList.isConsistent(), which calls out to PageControl.isConsistentWith() that check if the data and total size of the page list are consistent with the page control. This in turn is used by the CriteriaQueryRunner to re-attempt the queries if it finds the inconsistency (which is most possibly caused by the phantom read due to our transaction isolation level).
commit e82330bd6af45fe519f2eb85e81ca02a97b1eb04 Author: Lukas Krejci <lkrejci> Date: Tue Sep 3 18:42:50 2013 +0200 [BZ 855674] - Refactored the phantom-read detection out of CriteriaQueryRunner This was to make it testable but more importantly reusable by ordinary SLSB methods (that don't use criteria queries). Also added unit tests for the phantom-read detection (now placed in QueryUtility in server jar) and for PageControl in domain jar.
repro script does not hit this issue anymore on JON 3.2.ER1