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