[jira] [Updated] (GEODE-6967) CI Failure: org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest > testClientServerCompiledQueryTimeBasedCleanup FAILED
[ https://issues.apache.org/jira/browse/GEODE-6967?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Shelley Lynn Hughes-Godfrey updated GEODE-6967: --- Description: This failure occurred during CI on develop: https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/DistributedTestOpenJDK11/builds/882 {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 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 tid=0x22] ### Executing Query :(SELECT DISTINCT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1).size [vm2] [info 2019/07/16 00:46:48.563 GMT tid=0x22] ### Executing Query :SELECT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id = $1 and Ticker = $2 [vm2] [info 2019/07/16 00:46:48.564 GMT tid=0x22] ### Executing Query :SELECT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1 and Ticker = $2 [vm0] [warn 2019/07/16 00:46:52.724 GMT 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 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 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 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 tid=0x22] ### Close Client. ### [vm1] [info 2019/07/16 00:46:53.496 GMT 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 tid=0x22] Destroying connection pool testClientServerQueriesWithParams [vm2] [info 2019/07/16 00:46:53.525 GMT tid=0x22] ### Executing Query :SELECT DISTINCT * FROM /root/testClientServerCompiledQueryTimeBasedCleanup W
[jira] [Updated] (GEODE-6967) CI Failure: org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest > testClientServerCompiledQueryTimeBasedCleanup FAILED
[ https://issues.apache.org/jira/browse/GEODE-6967?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Shelley Lynn Hughes-Godfrey updated GEODE-6967: --- Affects Version/s: 1.10.0 > 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 >Affects Versions: 1.10.0 >Reporter: Shelley Lynn Hughes-Godfrey >Priority: Major > > 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 > 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 > tid=0x22] ### Executing Query :(SELECT DISTINCT * FROM > /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1).size > [vm2] [info 2019/07/16 00:46:48.563 GMT > tid=0x22] ### Executing Query :SELECT * FROM > /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id = $1 and Ticker > = $2 > [vm2] [info 2019/07/16 00:46:48.564 GMT > tid=0x22] ### Executing Query :SELECT * FROM > /root/testClientServerCompiledQueryTimeBasedCleanup WHERE id < $1 and Ticker > = $2 > [vm0] [warn 2019/07/16 00:46:52.724 GMT 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 > 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 > 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 > tid=0x22] Received method: org.apache.geode.test.dunit.NamedRunnable.run with > 0 args on object: runnable(closeClient