Shelley Lynn Hughes-Godfrey created GEODE-6967: --------------------------------------------------
Summary: CI Failure: org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest > testClientServerCompiledQueryTimeBasedCleanup FAILED Key: GEODE-6967 URL: https://issues.apache.org/jira/browse/GEODE-6967 Project: Geode Issue Type: Bug Components: querying Reporter: Shelley Lynn Hughes-Godfrey This failure occurred during CI on develop: {noformat} org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest > testClientServerCompiledQueryTimeBasedCleanup FAILED org.apache.geode.test.dunit.RMIException: While invoking org.apache.geode.test.dunit.NamedRunnable.run in VM 0 running on Host dfe4c2133987 with 4 VMs at org.apache.geode.test.dunit.VM.executeMethodOnObject(VM.java:579) at org.apache.geode.test.dunit.VM.invoke(VM.java:393) at org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest.testClientServerCompiledQueryTimeBasedCleanup(QueryUsingPoolDUnitTest.java:963) Caused by: java.lang.AssertionError: expected:<0> but was:<5> at org.junit.Assert.fail(Assert.java:88) at org.junit.Assert.failNotEquals(Assert.java:834) at org.junit.Assert.assertEquals(Assert.java:645) at org.junit.Assert.assertEquals(Assert.java:631) at org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest.lambda$testClientServerCompiledQueryTimeBasedCleanup$bb17a952$6(QueryUsingPoolDUnitTest.java:966) {noformat} Artifacts can be found here: {noformat} =-=-=-=-=-=-=-=-=-=-=-=-=-=-= Test Results URI =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= http://files.apachegeode-ci.info/builds/apache-develop-main/1.10.0-SNAPSHOT.0448/test-results/distributedTest/1563239162/ =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Test report artifacts from this job are available at: http://files.apachegeode-ci.info/builds/apache-develop-main/1.10.0-SNAPSHOT.0448/test-artifacts/1563239162/distributedtestfiles-OpenJDK11-1.10.0-SNAPSHOT.0448.tgz {noformat} In this test, vm0 is a cacheServer vm1 and vm2 are clients. The test sets the clearQueryTimeout to 2 seconds. {noformat} DefaultQuery.setTestCompiledQueryClearTime(2 * 1000); {noformat} The test successfully executes compiled queries from both clients and then the server validates that compiledQueryCount is reset (compiled queries are cleared in the server ) within 60 seconds. vm1 then re-executes compiled queries and vm2 asynchronously executes queries while both clients close their cache. After the clients complete their cache close, the server fails when it attempts to verify the compiledQueryCount stat has been reset to 0 (due to client cache close). While the vm2 is attempting to close the cache, we still see async queries for vm2; the servers compileQueryCount is not 0 (but 5). Also, we see a 3 second delay in taking statSamples in the server which may have contributed to this timing issue. {noformat} [vm2] [info 2019/07/16 00:46:48.558 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT DISTINCT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1 ORDER BY id [vm2] [info 2019/07/16 00:46:48.561 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :(SELECT DISTINCT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1).size [vm2] [info 2019/07/16 00:46:48.563 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id = $1 and Ticker = $2 [vm2] [info 2019/07/16 00:46:48.564 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1 and Ticker = $2 [vm0] [warn 2019/07/16 00:46:52.724 GMT <StatSampler> tid=0x1cf] Statistics sampling thread detected a wakeup delay of 3093 ms, indicating a possible resource issue. Check the GC, memory, and CPU statistics. [vm2] [info 2019/07/16 00:46:52.694 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT itr.value FROM /root/testClientServerCompiledQueryTimeBasedCleanup.entries itr where itr.key = $1 [vm0] [info 2019/07/16 00:46:53.289 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] Got result: null [vm0] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(validate Compiled query) (took 5663 ms) [vm1] [info 2019/07/16 00:46:53.470 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(closeClient) [vm1] [info 2019/07/16 00:46:53.495 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Close Client. ### [vm1] [info 2019/07/16 00:46:53.496 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] GemFireCache[id = 461736604; isClosing = true; isShutDownAll = false; created = Tue Jul 16 00:46:43 GMT 2019; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm1] [info 2019/07/16 00:46:53.508 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] Destroying connection pool testClientServerQueriesWithParams [vm2] [info 2019/07/16 00:46:53.525 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT DISTINCT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1 ORDER BY id [vm1] [info 2019/07/16 00:46:53.533 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] Got result: null [vm1] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(closeClient) (took 37 ms) [vm2] [info 2019/07/16 00:46:53.534 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT DISTINCT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1 ORDER BY id [vm2] [info 2019/07/16 00:46:53.549 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :(SELECT DISTINCT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1).size [vm2] [info 2019/07/16 00:46:53.554 GMT <RMI TCP Connection(2)-172.17.0.3> tid=0x6e] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(closeClient) [vm2] [info 2019/07/16 00:46:53.555 GMT <RMI TCP Connection(2)-172.17.0.3> tid=0x6e] ### Close Client. ### [vm2] [info 2019/07/16 00:46:53.556 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id = $1 and Ticker = $2 [vm2] [info 2019/07/16 00:46:53.556 GMT <RMI TCP Connection(2)-172.17.0.3> tid=0x6e] GemFireCache[id = 856737090; isClosing = true; isShutDownAll = false; created = Tue Jul 16 00:46:43 GMT 2019; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm2] [info 2019/07/16 00:46:53.559 GMT <RMI TCP Connection(2)-172.17.0.3> tid=0x6e] Destroying connection pool testClientServerQueriesWithParams [vm2] [info 2019/07/16 00:46:53.563 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] ### Executing Query :SELECT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1 and Ticker = $2 [vm2] [info 2019/07/16 00:46:53.570 GMT <RMI TCP Connection(2)-172.17.0.3> tid=0x6e] Got result: null [vm2] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(closeClient) (took 14 ms) [vm0] [info 2019/07/16 00:46:53.579 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(validate compiled query) [vm0] [info 2019/07/16 00:46:53.586 GMT <RMI TCP Connection(1)-172.17.0.3> tid=0x22] Got result: EXCEPTION_OCCURRED [vm0] java.lang.AssertionError: expected:<0> but was:<5> [vm0] at org.junit.Assert.fail(Assert.java:88) [vm0] at org.junit.Assert.failNotEquals(Assert.java:834) [vm0] at org.junit.Assert.assertEquals(Assert.java:645) [vm0] at org.junit.Assert.assertEquals(Assert.java:631) [vm0] at org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest.lambda$testClientServerCompiledQueryTimeBasedCleanup$bb17a952$6(QueryUsingPoolDUnitTest.java:966) {noformat} -- This message was sent by Atlassian JIRA (v7.6.14#76016)