Hi Vahram,
Are you sure your old client process is gone when you try to connect the
new one? It looks like the server should be doing a liveness check on
the old "proxy" for the client and disallows the new connection if the
old one is still around and its socket is still connected to the old
client process.
The work for JIRA ticket GEODE-1183 introduced the server-side behavior
you're seeing.
https://issues.apache.org/jira/browse/GEODE-1183
On 10/22/18 8:09 AM, Vahram Aharonyan wrote:
Hi All,
We are trying to move from Geode 1.1.0 to 1.6.0 and examining problems
with registering interest on regions after client restart. Please note
that issue occurs only if server nodes and locator of the cluster are
powered on client is been restarted. On the first boot of servers,
client is successful in registering interest without any problem.
Snippet from client log:
[warning 2018/10/22 19:01:21.299 AMT
Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0
<queueTimer-ControllerPool> tid=0x34] Cache Client Updater Thread on
localhost(Server-b90ea8f2-8864-4c19-b4fb-b93f8499c674:22375)<ec><v3>:10002
port 10000 (10.27.72.245:10000): Caught following exception while
attempting to create a server-to-client communication socket and will
exit: org.apache.geode.cache.client.ServerRefusedConnectionException:
<null inet_addr hostname><ec>:10000 refused connection: A previous
connection attempt from this client is still being processed:
identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1
[warning 2018/10/22 19:01:21.520 AMT
Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0
<queueTimer-ControllerPool> tid=0x34] Cache Client Updater Thread on
localhost(Server-17488aac-6fbd-43d1-8f91-c6d06c3947c0:30157)<ec><v1>:10002
port 10000 (10.27.72.247:10000): Caught following exception while
attempting to create a server-to-client communication socket and will
exit: org.apache.geode.cache.client.ServerRefusedConnectionException:
<null inet_addr hostname><ec>:10000 refused connection: A previous
connection attempt from this client is still being processed:
identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1
[warning 2018/10/22 19:01:41.134 AMT
Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0
<queueTimer-ControllerPool> tid=0x34] Cache Client Updater Thread on
localhost(Server-0145f530-79a8-449e-9ca9-e0487cfe2934:31321)<ec><v2>:10002
port 10000 (10.27.72.252:10000): Caught following exception while
attempting to create a server-to-client communication socket and will
exit: org.apache.geode.cache.client.ServerRefusedConnectionException:
<null inet_addr hostname><ec>:10000 refused connection: A previous
connection attempt from this client is still being processed:
identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1
[warning 2018/10/22 19:01:41.350 AMT
Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0
<queueTimer-ControllerPool> tid=0x34] Cache Client Updater Thread on
localhost(Server-b90ea8f2-8864-4c19-b4fb-b93f8499c674:22375)<ec><v3>:10002
port 10000 (10.27.72.245:10000): Caught following exception while
attempting to create a server-to-client communication socket and will
exit: org.apache.geode.cache.client.ServerRefusedConnectionException:
<null inet_addr hostname><ec>:10000 refused connection: A previous
connection attempt from this client is still being processed:
identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1
And on the server side:
[warning 2018/10/22 19:04:41.992 AMT
Server-17488aac-6fbd-43d1-8f91-c6d06c3947c0 <ServerConnection on port
10000 Thread 80> tid=0x5e0] Server connection from
[identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1;
port=50484]: Unexpected IOException:
java.net.SocketException: Socket Closed
at
java.net.AbstractPlainSocketImpl.setOption(AbstractPlainSocketImpl.java:212)
at java.net.Socket.setSoTimeout(Socket.java:1141)
at
sun.security.ssl.BaseSSLSocketImpl.setSoTimeout(BaseSSLSocketImpl.java:631)
at
sun.security.ssl.SSLSocketImpl.setSoTimeout(SSLSocketImpl.java:2565)
at
org.apache.geode.internal.cache.tier.sockets.Message.readHeaderAndBody(Message.java:661)
at
org.apache.geode.internal.cache.tier.sockets.Message.receiveWithHeaderReadTimeout(Message.java:1125)
at
org.apache.geode.internal.cache.tier.sockets.Message.receive(Message.java:1136)
at
org.apache.geode.internal.cache.tier.sockets.Message.receive(Message.java:1145)
at
org.apache.geode.internal.cache.tier.sockets.BaseCommand.readRequest(BaseCommand.java:851)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.doNormalMsg(ServerConnection.java:792)
at
org.apache.geode.internal.cache.tier.sockets.OriginalServerConnection.doOneMessage(OriginalServerConnection.java:85)
at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.run(ServerConnection.java:1248)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at
org.apache.geode.internal.cache.tier.sockets.AcceptorImpl$4$1.run(AcceptorImpl.java:644)
at java.lang.Thread.run(Thread.java:748)
[warning 2018/10/22 19:04:41.992 AMT
Server-17488aac-6fbd-43d1-8f91-c6d06c3947c0 <ServerConnection on port
10000 Thread 80> tid=0x5e0] ClientHealthMonitor: Unregistering client
with member id
identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1
due to: Socket Closed
[info 2018/10/22 19:05:02.034 AMT
Server-17488aac-6fbd-43d1-8f91-c6d06c3947c0 <Client Queue
Initialization Thread 1> tid=0x4b8] :Cache server: Initializing
primary server-to-client communication socket:
62ca4c8d[TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256:
Socket[addr=/10.27.72.247,port=50516,localport=10000]]
[warning 2018/10/22 19:05:02.034 AMT
Server-17488aac-6fbd-43d1-8f91-c6d06c3947c0 <Client Queue
Initialization Thread 1> tid=0x4b8] A previous connection attempt
from this client is still being processed:
identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1
[warning 2018/10/22 19:05:02.034 AMT
Server-17488aac-6fbd-43d1-8f91-c6d06c3947c0 <Client Queue
Initialization Thread 1> tid=0x4b8] CacheClientNotifier:
Unsuccessfully registered client with identifier
identity(localhost(Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0:21127:loner):57327:6cb13d9c:Client-17488aac-6fbd-43d1-8f91-c6d06c3947c0,connection=1
and response code 60
Could it be we are missing something on PoolCreation or client/server
configuration for Geode 1.6.0? Things were working fine with 1.1.0
version.
Thanks,
Vahram.
