[
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 <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}
was:
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}
> 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
> Assignee: nabarun
> Priority: Major
> Time Spent: 10m
> Remaining Estimate: 0h
>
> 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 <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)
