[GEODE-7284] A durable client's CacheClientProxy is sometimes not being kept on the server when it should be

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.11.0
• Component/s: client queues
• Assignee: Unassigned
• Reporter: Barrett Oglesby
• Created: 10/Oct/19 00:02
• Updated: 30/Dec/19 18:50
• Resolved: 15/Oct/19 17:37

Description

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:

[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

Sometimes, the logging looks like: (with log-level=fine):

[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]

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:

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)

This JDK11 stack shows the ForkJoinPool in a closed state.

Thats because each CacheClientProxy closes its SocketCloser executor here:

[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)

The address in that log message is the CacheClientProxy's _remoteHostAddress.

Currently, the _remoteHostAddress is set in CacheClientProxy.initializeTransientFields like:

this._remoteHostAddress = socket.getInetAddress().getHostAddress();

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.

Issue Links

• links to: GitHub Pull Request #4141