Hi Xiaojian, Thank you for your response.
Is this only about changes done in scope of GEODE-1183? Because it seems that they are performed in 1.0.0-incubating.M3. Currently we reside on Geode 1.1.0 and everything works fine. Problem occurs if we try to move to Geode 1.6.0. Moreover, we have not examined this issue neither with 1.2.0 version of Geode. If behavior change was introduced in GEODE-1183, then it should be visible in 1.1.0 and onwards, is not it ? Another thing to understand for me is whether this is expected behavior and is by design or it is a missing in the code flow that should be fixed, could you please comment on this as well? Thanks, Vahram. From: Xiaojian Zhou <[email protected]> Sent: Wednesday, October 24, 2018 8:07 PM To: [email protected] Subject: Re: Register Interest fails after clientCache creation The workaround is: restart the server one by one. Then they will recognize the clients again. On Tue, Oct 23, 2018 at 5:07 PM Xiaojian Zhou <[email protected]<mailto:[email protected]>> wrote: Hi, Bruce and Vahram, The difference between the versions is: In old version's server, if the new connection request comes, it will close current one and create a new one. But the new version (with fix of GEODE-1183), it will check if the current one is alive. If yes, then reject the incoming request. That's the root cause of the error msg. What I wonder is: after the 9.0.0 client restarted, why the server still treats the connection (proxy) alive. The client shutdown should trigger the connection (proxy) to be closed. I am still looking at the code. Regards Gester Zhou On Tue, Oct 23, 2018 at 8:43 AM Vahram Aharonyan <[email protected]<mailto:[email protected]>> wrote: Hi Bruce, Thanks for your feedback. Actually yes, on client restart we are ensuring that old process does not exist anymore and only after that start the new one. Could it be that something has changed in 1.6.0 from 1.1.0 in client cache or pool creation flows that I need to consider (Newly added or deprecated configuration parameters, etc.)? Or this does not seem to be a configuration mismatch? Thanks, Vahram. From: Bruce Schuchardt <[email protected]<mailto:[email protected]>> Sent: Tuesday, October 23, 2018 12:34 AM To: [email protected]<mailto:[email protected]> Subject: Re: Register Interest fails after clientCache creation 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<https://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fissues.apache.org%2Fjira%2Fbrowse%2FGEODE-1183&data=02%7C01%7Cvaharonyan%40vmware.com%7C3312049973d9427add1008d639cac742%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636759940439474921&sdata=awP32tUDdUR1qQmB9OUoQniwFYNfsujkPs%2B%2B3SC2xCk%3D&reserved=0> 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<https://na01.safelinks.protection.outlook.com/?url=http%3A%2F%2F10.27.72.245%3A10000&data=02%7C01%7Cvaharonyan%40vmware.com%7C3312049973d9427add1008d639cac742%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636759940439484935&sdata=sLxD3mQ8I9%2FvihPI6iBRRJ2fGOZTE%2FbSycib5I2OL2A%3D&reserved=0>): 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<https://na01.safelinks.protection.outlook.com/?url=http%3A%2F%2F10.27.72.247%3A10000&data=02%7C01%7Cvaharonyan%40vmware.com%7C3312049973d9427add1008d639cac742%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636759940439494954&sdata=TinfLgPZCNGmAgBFMM9riVwtR1w9mKZbplKcvys%2BLtM%3D&reserved=0>): 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<https://na01.safelinks.protection.outlook.com/?url=http%3A%2F%2F10.27.72.252%3A10000&data=02%7C01%7Cvaharonyan%40vmware.com%7C3312049973d9427add1008d639cac742%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636759940439504951&sdata=5UryzIkbBDl6D8%2BbXJYLbpW5xDSGwuKcRco4WeEZwvc%3D&reserved=0>): 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<https://na01.safelinks.protection.outlook.com/?url=http%3A%2F%2F10.27.72.245%3A10000&data=02%7C01%7Cvaharonyan%40vmware.com%7C3312049973d9427add1008d639cac742%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636759940439514970&sdata=qjgNMmYKr%2Frt4ezpEBHlq9nrsOrd1fDQZ4%2Fvflx%2FIGY%3D&reserved=0>): 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<https://na01.safelinks.protection.outlook.com/?url=http%3A%2F%2F10.27.72.247&data=02%7C01%7Cvaharonyan%40vmware.com%7C3312049973d9427add1008d639cac742%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636759940439524978&sdata=1qFyS%2BHWd7g4b7cDJ71Tbls6H5%2B8LxSip8tVRqPmyVU%3D&reserved=0>,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.
