[
https://issues.apache.org/jira/browse/GEODE-4263?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16840798#comment-16840798
]
Bill Burcham commented on GEODE-4263:
-------------------------------------
Failed here:
[https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/DistributedTestOpenJDK11/builds/716]
{noformat}
org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest >
testRMButDisabledQueryMonitorForLowMemAndNoTimeoutSet FAILED
java.lang.AssertionError: queryExecution.getResult() threw Exception
java.lang.AssertionError: An exception occurred during asynchronous invocation.
at org.junit.Assert.fail(Assert.java:88)
at
org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest.doTestCriticalHeapAndQueryTimeout(ResourceManagerWithQueryMonitorDUnitTest.java:848)
at
org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest.doCriticalMemoryHitTest(ResourceManagerWithQueryMonitorDUnitTest.java:358)
at
org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest.testRMButDisabledQueryMonitorForLowMemAndNoTimeoutSet(ResourceManagerWithQueryMonitorDUnitTest.java:165)
java.lang.AssertionError: Suspicious strings were written to the log during
this run.
Fix the strings or use IgnoredException.addIgnoredException to ignore.
-----------------------------------------------------------------------
Found suspect string in log4j at line 1601
[fatal 2019/05/15 01:21:05.865 GMT <ServerConnection on port 27314 Thread
2> tid=1563] Server connection from
[identity(172.17.0.14(155:loner):55842:2de713b9,connection=1; port=55844] :
Unexpected Error on server
java.lang.AssertionError: query was never unlatched
at org.junit.Assert.fail(Assert.java:88)
at
org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest$PauseTestHook.doTestHook(ResourceManagerWithQueryMonitorDUnitTest.java:1306)
at
org.apache.geode.cache.query.internal.DefaultQuery.executeUsingContext(DefaultQuery.java:428)
at
org.apache.geode.cache.query.internal.DefaultQuery.execute(DefaultQuery.java:265)
at
org.apache.geode.cache.query.internal.DefaultQuery.execute(DefaultQuery.java:197)
at
org.apache.geode.internal.cache.tier.sockets.BaseCommandQuery.processQueryUsingParams(BaseCommandQuery.java:122)
at
org.apache.geode.internal.cache.tier.sockets.BaseCommandQuery.processQuery(BaseCommandQuery.java:68)
at
org.apache.geode.internal.cache.tier.sockets.command.Query.cmdExecute(Query.java:94)
at
org.apache.geode.internal.cache.tier.sockets.BaseCommand.execute(BaseCommand.java:183)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.doNormalMessage(ServerConnection.java:847)
at
org.apache.geode.internal.cache.tier.sockets.OriginalServerConnection.doOneMessage(OriginalServerConnection.java:72)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.run(ServerConnection.java:1211)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at
org.apache.geode.internal.cache.tier.sockets.AcceptorImpl.lambda$initializeServerConnectionThreadPool$3(AcceptorImpl.java:663)
at
org.apache.geode.internal.logging.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:121)
at java.base/java.lang.Thread.run(Thread.java:834)
{noformat}
I ran that test on my laptop on this May 15 commit
690c65e86f9f33ed12b34a7e6ae831fcc39a58c6 and varied the
PauseTestHook.doTestHook() latch.await() timeout in IntelliJ, from 8s, down to:
6s: 0 failures in 5 runs
5s: 5 failures in 5 runs
CIO picked me to address the failure because I edited that test file:
{noformat}
commit b040508b61839467e9bb737e1780920d4d2fe5c1
Author: Bill Burcham <[email protected]>
Date: Wed Oct 31 16:33:36 2018 -0700
GEODE-5881: simplify DefaultQuery.TestHook (#2755)
Consolidate three interface methods into one that takes an enum
to identify the "spot" in the query processing logic.
Co-authored-by: Bill Burcham <[email protected]>
Co-authored-by: Dale Emery <[email protected]>
Co-authored-by: Galen O'Sullivan <[email protected]>
{noformat}
The commit before that one is this one:
commit 4ab4d4f3961e7d827af6604f574e8ba30e8ef3c1
running at 8s (one time) the test passes:
./gradlew geode-core:distributedTest --tests
*ResourceManagerWithQueryMonitorDUnitTest.testRMButDisabledQueryMonitorForLowMemAndNoTimeoutSet
6s: 0 failures in 1 runs
5s: 2 failures in 3 runs
4s: 1 failures in 1 runs
3s: 1 failures in 1 runs
2s: 1 failures in 1 runs
5ms: 1 failures in 1 runs
That timing on the October 31 commit seems pretty consistent with today's (May
15) one. The test starts failing with the latch timeout set somewhere between
5s and 6s.
My take is that these tests (still) fail intermittently and that the failure is
due to nondeterminism affecting the timings. If we want this to never fail we
need to make it deterministic by not relying on timings.
> GEODE-4263 : [CI Failure] ResourceManagerWithQueryMonitorDUnitTest.
> testRMAndTimeoutSet
> ---------------------------------------------------------------------------------------
>
> Key: GEODE-4263
> URL: https://issues.apache.org/jira/browse/GEODE-4263
> Project: Geode
> Issue Type: Bug
> Components: querying
> Reporter: nabarun
> Priority: Major
>
> {noformat}
> java.lang.AssertionError: queryExecution.getResult() threw Exception
> java.lang.AssertionError: An exception occurred during asynchronous
> invocation.
> at org.junit.Assert.fail(Assert.java:88)
> at
> org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest.doTestCriticalHeapAndQueryTimeout(ResourceManagerWithQueryMonitorDUnitTest.java:738)
> at
> org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest.doCriticalMemoryHitTest(ResourceManagerWithQueryMonitorDUnitTest.java:321)
> at
> org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest.testRMAndTimeoutSet(ResourceManagerWithQueryMonitorDUnitTest.java:157)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.runTestClass(JUnitTestClassExecuter.java:114)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:57)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:66)
> at
> org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
> at
> org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
> at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
> at
> org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:147)
> at
> org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:129)
> at
> org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404)
> at
> org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
> at
> org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:46)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> {noformat}
> *Suspect Strings*:
> {noformat}
> java.lang.AssertionError: Suspicious strings were written to the log during
> this run.
> Fix the strings or use IgnoredException.addIgnoredException to ignore.
> -----------------------------------------------------------------------
> Found suspect string in log4j at line 486
> [fatal 2018/01/06 08:56:20.069 UTC <ServerConnection on port 29295 Thread 0>
> tid=0x10f] Server connection from
> [identity(172.17.0.6(176:loner):46904:7d2bafca,connection=1; port=46904] :
> Unexpected Error on server
> java.lang.AssertionError: query was never unlatched
> at org.junit.Assert.fail(Assert.java:88)
> at
> org.apache.geode.cache.query.dunit.ResourceManagerWithQueryMonitorDUnitTest$PauseTestHook.doTestHook(ResourceManagerWithQueryMonitorDUnitTest.java:1102)
> at
> org.apache.geode.cache.query.internal.DefaultQuery.executeUsingContext(DefaultQuery.java:555)
> at
> org.apache.geode.cache.query.internal.DefaultQuery.execute(DefaultQuery.java:384)
> at
> org.apache.geode.cache.query.internal.DefaultQuery.execute(DefaultQuery.java:318)
> at
> org.apache.geode.internal.cache.tier.sockets.BaseCommandQuery.processQueryUsingParams(BaseCommandQuery.java:107)
> at
> org.apache.geode.internal.cache.tier.sockets.BaseCommandQuery.processQuery(BaseCommandQuery.java:60)
> at
> org.apache.geode.internal.cache.tier.sockets.command.Query.cmdExecute(Query.java:92)
> at
> org.apache.geode.internal.cache.tier.sockets.BaseCommand.execute(BaseCommand.java:163)
> at
> org.apache.geode.internal.cache.tier.sockets.ServerConnection.doNormalMsg(ServerConnection.java:797)
> at
> org.apache.geode.internal.cache.tier.sockets.LegacyServerConnection.doOneMessage(LegacyServerConnection.java:85)
> at
> org.apache.geode.internal.cache.tier.sockets.ServerConnection.run(ServerConnection.java:1179)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at
> org.apache.geode.internal.cache.tier.sockets.AcceptorImpl$4$1.run(AcceptorImpl.java:641)
> at java.lang.Thread.run(Thread.java:748)
> at org.junit.Assert.fail(Assert.java:88)
> at
> org.apache.geode.test.dunit.standalone.DUnitLauncher.closeAndCheckForSuspects(DUnitLauncher.java:393)
> at
> org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.cleanupAllVms(JUnit4DistributedTestCase.java:561)
> at
> org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.doTearDownDistributedTestCase(JUnit4DistributedTestCase.java:508)
> at
> org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.tearDownDistributedTestCase(JUnit4DistributedTestCase.java:495)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
> at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.runTestClass(JUnitTestClassExecuter.java:114)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:57)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:66)
> at
> org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
> at
> org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
> at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
> at
> org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:147)
> at
> org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:129)
> at
> org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404)
> at
> org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
> at
> org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:46)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
