Hi Gester, We are using Geode 1.1.0 release branch, the latest commit in the tree is:
commit 7a4e4e69860dd64bb23282c128fc84afd3670385 (tag: rel/v1.1.0manualrev-2017-10-19, origin/release/1.1, release/1.1) And I do see that commit for GEODE-1183 is there in the git log. I've checked your recommendation on time window between client stop/start - actually it does not help as I've waited even for 30mins. Please note that on shutdown we are closing client cache and calling disconnect of Distributed system. Only server restart helps to recover which is not acceptable solution... Basically what is confusing me is that everything worked fine with both 1.1.0 and 1.2.0 and issue occurs with 1.6.0. Thanks, Vahram. From: Anthony Baker <[email protected]> Sent: Thursday, October 25, 2018 9:13 PM To: [email protected] Subject: Re: Register Interest fails after clientCache creation Gester, GEODE-1183 seems to be present in 1.0.0.M3 like Vahram pointed out. Anthony On Oct 25, 2018, at 10:06 AM, Xiaojian Zhou <[email protected]<mailto:[email protected]>> wrote: I have checked, the fix GEM-1183 exists since 9.0 (i.e. some time in geode 1.1.0, your 1.1.0 might not contain this fix). If you send me your revision number, I will confirm for you. But I'm pretty sure it's due to that behavior changes. I discussed with Bruce. There's chance that if client did not shutdown gracefully, it might cause the server still have the proxy. There should be a timeout for server to recognize the client's gone, then close the proxy. If in that case, you shutdown your client, then wait for a while, Then restart the client, it should be ok. If you restart immediately, then it was rejected. This is my guess for your scenario. You can try this workaround. Again, restart servers one by one, then restart clients. This will be another workaround. I think we can improve the product to handle your case in more elegant way. Regards Xiaojian Zhou On Thu, Oct 25, 2018 at 7:10 AM Vahram Aharonyan <[email protected]<mailto:[email protected]>> wrote: 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]<mailto:[email protected]>> Sent: Wednesday, October 24, 2018 8:07 PM To: [email protected]<mailto:[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%7C2e760ee698bc4b28f8db08d63a9d2355%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636760843929571773&sdata=8ORvCSHk1Yt4MWi3nJYd3wgbJI%2Fhk6VHgbsAl6AA%2FWg%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%7C2e760ee698bc4b28f8db08d63a9d2355%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636760843929591794&sdata=Wa43sLfqF3xl6hLz99RK1TF%2BPPc0k%2FYUOPaxNUMdJVU%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%7C2e760ee698bc4b28f8db08d63a9d2355%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636760843929601791&sdata=BhN8%2Fixv9xdLw8t2j0sRjyj1YWe5wA2INexJEEKiThs%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%7C2e760ee698bc4b28f8db08d63a9d2355%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636760843929611804&sdata=06roYGYFbMmdxf348N8XL55EEXfO73SVz8n5DEtrn0U%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%7C2e760ee698bc4b28f8db08d63a9d2355%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636760843929621806&sdata=sflwqZ10RIwgoPxYrLLamaeywJ6MC0tt9TkNltE8oUs%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%7C2e760ee698bc4b28f8db08d63a9d2355%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C1%7C0%7C636760843929631814&sdata=IgqhoJs0wAarDdX9C4unhWxxxCP43cLy37O23Mo8Vuw%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.
