Barrett Oglesby created GEODE-7284:
--------------------------------------
Summary: A durable client's CacheClientProxy is sometimes not
being kept on the server when it should be
Key: GEODE-7284
URL: https://issues.apache.org/jira/browse/GEODE-7284
Project: Geode
Issue Type: Bug
Components: client queues
Reporter: Barrett Oglesby
A durable client's CacheClientProxy is sometimes not being kept on the server
when it should be
When a durable client is killed, logging for it on the server should look like:
{noformat}
[info 2019/10/09 16:40:42.426 PDT <ServerConnection on port 59235 Thread 190>
tid=0x110] CacheClientNotifier: Keeping proxy for durable client named client-9
for 300 seconds
CacheClientProxy[identity(192.168.1.4(client:36729:loner):59887:9507e5b2:client,connection=2,durableAttributes=DurableClientAttributes[id=client-9;
timeout=300]); port=59892; primary=true; version=GEODE 1.11.0].
[info 2019/10/09 16:40:42.413 PDT <Client Message Dispatcher for
192.168.1.4(client:36478:loner):59353:71a9e3b2:client (client-9)> tid=0x6e]
CacheClientProxy[identity(192.168.1.4(client:36729:loner):59887:9507e5b2:client,connection=2,durableAttributes=DurableClientAttributes[id=client-9;
timeout=300]); port=59892; primary=true; version=GEODE 1.11.0] : Pausing
processing
{noformat}
Sometimes, the logging looks like: (with log-level=fine):
{noformat}
[info 2019/10/09 16:40:42.429 PDT <Client Message Dispatcher for
192.168.1.4(client:36458:loner):59317:baa2e3b2:client (client-5)> tid=0x60]
CacheClientProxy[identity(192.168.1.4(client:36717:loner):59851:3301e5b2:client,connection=2,durableAttributes=DurableClientAttributes[id=client-5;
timeout=300]); port=59856; primary=true; version=GEODE 1.11.0] : Pausing
processing
[debug 2019/10/09 16:40:42.428 PDT <ServerConnection on port 59235 Thread 176>
tid=0x102] CacheClientNotifier: Not keeping proxy for non-durable client:
CacheClientProxy[identity(192.168.1.4(client:36717:loner):59851:3301e5b2:client,connection=2,durableAttributes=DurableClientAttributes[id=client-5;
timeout=300]); port=59856; primary=true; version=GEODE 1.11.0]
{noformat}
On one hand, the Client Message Dispatcher is pausing, but on the other hand,
the CacheClientProxy is not being kept.
Thats because of this RejectedExecutionException thrown attempting to
asynchronously close the CacheClientProxy's socket:
{noformat}
java.util.concurrent.RejectedExecutionException
at
java.base/java.util.concurrent.ForkJoinPool.externalPush(ForkJoinPool.java:1880)
at
java.base/java.util.concurrent.ForkJoinPool.externalSubmit(ForkJoinPool.java:1921)
at
java.base/java.util.concurrent.ForkJoinPool.submit(ForkJoinPool.java:2497)
at
java.base/java.util.concurrent.ForkJoinPool.submit(ForkJoinPool.java:178)
at
org.apache.geode.internal.net.SocketCloser.asyncExecute(SocketCloser.java:163)
at
org.apache.geode.internal.net.SocketCloser.asyncClose(SocketCloser.java:191)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.closeSocket(CacheClientProxy.java:955)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.closeTransientFields(CacheClientProxy.java:963)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.pauseDispatching(CacheClientProxy.java:839)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.close(CacheClientProxy.java:788)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientNotifier.closeDeadProxies(CacheClientNotifier.java:1563)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientNotifier.unregisterClient(CacheClientNotifier.java:567)
at
org.apache.geode.internal.cache.tier.sockets.ClientHealthMonitor.unregisterClient(ClientHealthMonitor.java:255)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.handleTermination(ServerConnection.java:961)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.handleTermination(ServerConnection.java:882)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.run(ServerConnection.java:1223)
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:674)
at
org.apache.geode.internal.logging.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:119)
at java.base/java.lang.Thread.run(Thread.java:834)
{noformat}
This JDK11 stack shows the ForkJoinPool in a closed state.
Thats because each CacheClientProxy closes its SocketCloser executor here:
{noformat}
[warn 2019/10/09 16:55:36.611 PDT <ServerConnection on port 60093 Thread 5>
tid=0x46] XXX SocketCloser.releaseResourcesForAddress address=192.168.1.4;
executorService=java.util.concurrent.ForkJoinPool@15099e74[Running, parallelism
= 1, size = 1, active = 0, running = 0, steals = 1, tasks = 0, submissions = 0]
java.lang.Exception
at
org.apache.geode.internal.net.SocketCloser.releaseResourcesForAddress(SocketCloser.java:135)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.closeOtherTransientFields(CacheClientProxy.java:979)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.closeTransientFields(CacheClientProxy.java:969)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.pauseDispatching(CacheClientProxy.java:839)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientProxy.close(CacheClientProxy.java:788)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientNotifier.closeDeadProxies(CacheClientNotifier.java:1563)
at
org.apache.geode.internal.cache.tier.sockets.CacheClientNotifier.unregisterClient(CacheClientNotifier.java:567)
at
org.apache.geode.internal.cache.tier.sockets.ClientHealthMonitor.unregisterClient(ClientHealthMonitor.java:255)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.handleTermination(ServerConnection.java:961)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.handleTermination(ServerConnection.java:882)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.run(ServerConnection.java:1223)
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:674)
at
org.apache.geode.internal.logging.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:119)
at java.base/java.lang.Thread.run(Thread.java:834)
{noformat}
The address in that log message is the CacheClientProxy's _remoteHostAddress.
Currently, the _remoteHostAddress is set in
CacheClientProxy.initializeTransientFields like:
{noformat}
this._remoteHostAddress = socket.getInetAddress().getHostAddress();
{noformat}
So, the _remoteHostAddress will be the same for all CacheClientProxies
representing clients on the same host.
When those clients are killed, all the CacheClientProxies are closing the same
ForkJoinPool. This is causing the RejectedExecutionException for other clients
closing at the same time.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
