[
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 <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)
