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/15 17:38:00 UTC
[jira] [Resolved] (GEODE-7284) A durable client's CacheClientProxy
is sometimes not being kept on the server when it should be
[ https://issues.apache.org/jira/browse/GEODE-7284?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Barrett Oglesby resolved GEODE-7284.
------------------------------------
Fix Version/s: 1.11.0
Resolution: Fixed
> 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
> Priority: Major
> Fix For: 1.11.0
>
> Time Spent: 40m
> Remaining Estimate: 0h
>
> 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)