[
https://issues.apache.org/jira/browse/GEODE-10298?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17536946#comment-17536946
]
Eric Shu commented on GEODE-10298:
----------------------------------
>From the test code and failed test run logs, this exception thrown is not
>caused by message sent by the failed test. As the locator is just being
>created.
{noformat}
The failed test run showing the logged exception thrown.
[vm0] [info 2022/05/10 18:57:14.088 UTC <RMI TCP Connection(1)-10.0.2.167>
tid=0x20] Reinitializing JarDeploymentService with new working directory:
/home/geode/geode/geode-wan/build/distributedTest/test-worker-000837/dunit/vm0
[vm0] [fatal 2022/05/10 18:57:14.216 UTC <locator request thread 1> tid=0xe2]
Exception in processing request from 10.0.2.167
[vm0] java.lang.Exception: Improperly configured client detected - use
addPoolLocator to configure its locators instead of addPoolServer.
[vm0] at
org.apache.geode.distributed.internal.ProtocolCheckerImpl.checkProtocol(ProtocolCheckerImpl.java:31)
[vm0] at
org.apache.geode.distributed.internal.tcpserver.TcpServer.lambda$processRequest$0(TcpServer.java:342)
[vm0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm0] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm0] at java.lang.Thread.run(Thread.java:750)
[vm0] [info 2022/05/10 18:57:14.468 UTC <RMI TCP Connection(1)-10.0.2.167>
tid=0x20] Initialized cache service
org.apache.geode.management.internal.cli.remote.OnlineCommandProcessor
{noformat}
I have run the test with added logs and know that the locator is just being
started from the stack trace (logged from my own run of the test. There is no
peer or client being started in the test yet, and should not be able to send
any message at that time.
{noformat}
[vm0] [info 2022/05/11 16:39:21.759 PDT <RMI TCP Connection(1)-10.204.72.58>
tid=0x13] initializeServices stack
[vm0] java.lang.Exception
[vm0] at
org.apache.geode.internal.cache.GemFireCacheImpl.initializeServices(GemFireCacheImpl.java:1499)
[vm0] at
org.apache.geode.internal.cache.GemFireCacheImpl.initialize(GemFireCacheImpl.java:1429)
[vm0] at
org.apache.geode.internal.cache.InternalCacheBuilder.create(InternalCacheBuilder.java:191)
[vm0] at
org.apache.geode.distributed.internal.InternalLocator.startCache(InternalLocator.java:780)
[vm0] at
org.apache.geode.distributed.internal.InternalLocator.startDistributedSystem(InternalLocator.java:769)
[vm0] at
org.apache.geode.distributed.internal.InternalLocator.startLocator(InternalLocator.java:400)
[vm0] at
org.apache.geode.distributed.internal.InternalLocator.startLocator(InternalLocator.java:346)
[vm0] at org.apache.geode.distributed.Locator.startLocator(Locator.java:269)
[vm0] at
org.apache.geode.distributed.Locator.startLocatorAndDS(Locator.java:213)
[vm0] at
org.apache.geode.cache.client.internal.LocatorTestBase.startLocator(LocatorTestBase.java:140)
[vm0] at
org.apache.geode.cache.client.internal.LocatorTestBase.lambda$startLocatorInVM$e4d36eca$1(LocatorTestBase.java:146)
[vm0] at
org.apache.geode.test.dunit.internal.IdentifiableCallable.call(IdentifiableCallable.java:41)
[vm0] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[vm0] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[vm0] at java.lang.reflect.Method.invoke(Method.java:498)
[vm0] at
org.apache.geode.test.dunit.internal.MethodInvoker.executeObject(MethodInvoker.java:123)
[vm0] at
org.apache.geode.test.dunit.internal.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:78)
[vm0] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[vm0] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[vm0] at java.lang.reflect.Method.invoke(Method.java:498)
[vm0] at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
[vm0] at sun.rmi.transport.Transport$1.run(Transport.java:200)
[vm0] at sun.rmi.transport.Transport$1.run(Transport.java:197)
[vm0] at java.security.AccessController.doPrivileged(Native Method)
[vm0] at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
[vm0] at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573)
[vm0] at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
[vm0] at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
[vm0] at java.security.AccessController.doPrivileged(Native Method)
[vm0] at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
[vm0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm0] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm0] at java.lang.Thread.run(Thread.java:748)
{noformat}
Suspect the locator was using a port recycled by another server and a client
from another test is trying to send message to the shunned server.
After discussing this with Dale and using "progress" script, I was able to find
out the server in the other test.
{noformat}
[setup] START TEST ConnectionPoolDUnitTest.basicTestLifetimeExpire
[vm1] [info 2022/05/10 18:57:10.158 UTC <RMI TCP
Connection(1)-10.0.2.167> tid=0x20] Cache server connection listener bound
to address
heavy-lifter-460e97d0-8427-52aa-92d6-daf4a9eb5f31.c.apachegeode-ci.internal-0.0.0.0/0.0.0.0:33475
with backlog 1280.
[vm1] [info 2022/05/10 18:57:10.191 UTC <RMI TCP
Connection(1)-10.0.2.167> tid=0x20] CacheServer Configuration: port=33475
max-connections=800 max-threads=0 notify-by-subscription=true
socket-buffer-size=32768 maximum-time-between-pings=60000
maximum-message-count=230000 message-time-to-live=180 eviction-policy=none
capacity=1 overflow directory=. groups=[] loadProbe=ConnectionCountProbe
loadPollInterval=5000 tcpNoDelay=true
[vm1] [info 2022/05/10 18:57:10.223 UTC <RMI TCP
Connection(1)-10.0.2.167> tid=0x20] Cache server on port 33475 is shutting
down.
And the client received the message from the locator of the failed test:
[vm2] [warn 2022/05/10 18:57:14.216 UTC
<poolLoadConditioningMonitor-testPool1> tid=0x3a] LoadConditioningTask
<org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl$LifetimeExpireConnectionsTask@66a16f09>
encountered exception
[vm2] org.apache.geode.GemFireConfigException: Improperly configured client
detected. Server at
heavy-lifter-460e97d0-8427-52aa-92d6-daf4a9eb5f31.c.apachegeode-ci.internal:33475
is actually a locator. Use addPoolLocator to configure locators.
[vm2] at
org.apache.geode.cache.client.internal.ClientSideHandshakeImpl.handshakeWithServer(ClientSideHandshakeImpl.java:201)
[vm2] at
org.apache.geode.cache.client.internal.ConnectionImpl.connect(ConnectionImpl.java:107)
[vm2] at
org.apache.geode.cache.client.internal.ConnectionConnector.connectClientToServer(ConnectionConnector.java:75)
[vm2] at
org.apache.geode.cache.client.internal.ConnectionFactoryImpl.createClientToServerConnection(ConnectionFactoryImpl.java:120)
[vm2] at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.createLifetimeReplacementConnection(ConnectionManagerImpl.java:764)
[vm2] at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.access$1500(ConnectionManagerImpl.java:70)
[vm2] at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl$ConnectionMap.checkLifetimes(ConnectionManagerImpl.java:1183)
[vm2] at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl$LifetimeExpireConnectionsTask.run(ConnectionManagerImpl.java:647)
[vm2] at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[vm2] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[vm2] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
[vm2] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
[vm2] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm2] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm2] at java.lang.Thread.run(Thread.java:750)
{noformat}
So this is not a product issue. It is a test isolation issue -- need to find
out if we can prevent a new test to reuse a just cycled port number.
> [CI Failure] GatewayReceiverAutoConnectionSourceDUnitTest >
> testBridgeServerAndGatewayReceiverClientAndServerWithGroup FAILED
> -----------------------------------------------------------------------------------------------------------------------------
>
> Key: GEODE-10298
> URL: https://issues.apache.org/jira/browse/GEODE-10298
> Project: Geode
> Issue Type: Bug
> Components: wan
> Affects Versions: 1.15.0
> Reporter: Nabarun Nag
> Assignee: Eric Shu
> Priority: Major
> Labels: needsTriage
> Fix For: 1.16.0
>
>
> {noformat}
> GatewayReceiverAutoConnectionSourceDUnitTest >
> testBridgeServerAndGatewayReceiverClientAndServerWithGroup FAILED
> 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 'dunit_suspect-vm0.log' at line 417
> [fatal 2022/05/10 18:57:14.216 UTC <locator request thread 1> tid=226]
> Exception in processing request from 10.0.2.167
> java.lang.Exception: Improperly configured client detected - use
> addPoolLocator to configure its locators instead of addPoolServer.
> at
> org.apache.geode.distributed.internal.ProtocolCheckerImpl.checkProtocol(ProtocolCheckerImpl.java:31)
> at
> org.apache.geode.distributed.internal.tcpserver.TcpServer.lambda$processRequest$0(TcpServer.java:342)
> 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:750)
> at org.junit.Assert.fail(Assert.java:89)
> at
> org.apache.geode.test.dunit.internal.DUnitLauncher.closeAndCheckForSuspects(DUnitLauncher.java:422)
> at
> org.apache.geode.test.dunit.internal.DUnitLauncher.closeAndCheckForSuspects(DUnitLauncher.java:438)
> at
> org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.cleanupAllVms(JUnit4DistributedTestCase.java:552)
> at
> org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.doTearDownDistributedTestCase(JUnit4DistributedTestCase.java:499)
> at
> org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.tearDownDistributedTestCase(JUnit4DistributedTestCase.java:482)
> 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:59)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
> at
> org.junit.internal.runners.statements.RunAfters.invokeMethod(RunAfters.java:46)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
> at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
> at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
> at
> org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
> at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
> at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
> at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
> at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
> at
> org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
> at
> org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
> at
> org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
> at
> org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
> at
> org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
> at
> org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
> at
> org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
> at
> org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
> at
> org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
> at
> org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
> at
> org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:99)
> at
> org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:79)
> at
> org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:75)
> at
> org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61)
> 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:36)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
> at
> org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
> at com.sun.proxy.$Proxy2.stop(Unknown Source)
> at
> org.gradle.api.internal.tasks.testing.worker.TestWorker.stop(TestWorker.java:133)
> 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:36)
> at
> org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:182)
> at
> org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:164)
> at
> org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:414)
> at
> org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
> at
> org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at
> org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:56)
> at java.lang.Thread.run(Thread.java:750){noformat}
--
This message was sent by Atlassian Jira
(v8.20.7#820007)
