You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@geode.apache.org by "Barrett Oglesby (Jira)" <ji...@apache.org> on 2019/10/10 00:03:00 UTC
[jira] [Created] (GEODE-7284) A durable client's CacheClientProxy
is sometimes not being kept on the server when it should be
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)