geode-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Shelley Lynn Hughes-Godfrey (JIRA)" <j...@apache.org>
Subject [jira] [Created] (GEODE-6967) CI Failure: org.apache.geode.cache.query.dunit.QueryUsingPoolDUnitTest > testClientServerCompiledQueryTimeBasedCleanup FAILED
Date Tue, 16 Jul 2019 17:41:00 GMT
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)

Mime
View raw message