[
https://issues.apache.org/jira/browse/GEODE-8004?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17090468#comment-17090468
]
Juan Ramos edited comment on GEODE-8004 at 4/23/20, 10:19 AM:
--------------------------------------------------------------
[~alberto.bustamante.reyes] [~bschuchardt]: I've managed to reproduce one of
the two regressions with extra logging, analysis and details below.
The client gets an unexpected {{PING}} message when it's expecting a simple
{{ACK}}.
{noformat}
[info 2020/04/22 14:13:48.020 PDT <poolTimer-edgeDescript-50> tid=0xc4] [JUAN]:
Sending ping to ServerLocation
rs-GEM-2885-0819axi32xlarge-hydra-client-11:22831 and MemberId
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001[info
2020/04/22 14:13:48.020 PDT <poolTimer-edgeDescript-50> tid=0xc4] [JUAN]:
Sending ping to ServerLocation
rs-GEM-2885-0819axi32xlarge-hydra-client-11:22831 and MemberId
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001java.lang.Throwable
at
org.apache.geode.cache.client.internal.LiveServerPinger$PingTask.run2(LiveServerPinger.java:91)
at
org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1329)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at
org.apache.geode.internal.ScheduledThreadPoolExecutorWithKeepAlive$DelegatingScheduledFuture.run(ScheduledThreadPoolExecutorWithKeepAlive.java:276)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
[error 2020/04/22 14:13:48.023 PDT <poolTimer-edgeDescript-50> tid=0xc4]
Unexpected error in pool task
<org.apache.geode.cache.client.internal.LiveServerPinger$PingTask@1f658665>org.apache.geode.InternalGemFireError:
Unexpected message type PING at
org.apache.geode.cache.client.internal.AbstractOp.processAck(AbstractOp.java:264)
at
org.apache.geode.cache.client.internal.PingOp$PingOpImpl.processResponse(PingOp.java:82)
at
org.apache.geode.cache.client.internal.AbstractOp.processResponse(AbstractOp.java:222)
at
org.apache.geode.cache.client.internal.AbstractOp.attemptReadResponse(AbstractOp.java:207)
at
org.apache.geode.cache.client.internal.AbstractOp.attempt(AbstractOp.java:382)
at
org.apache.geode.cache.client.internal.ConnectionImpl.execute(ConnectionImpl.java:268)
at
org.apache.geode.cache.client.internal.pooling.PooledConnection.execute(PooledConnection.java:352)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeWithPossibleReAuthentication(OpExecutorImpl.java:753)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOnServer(OpExecutorImpl.java:332)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOn(OpExecutorImpl.java:303)
at
org.apache.geode.cache.client.internal.PoolImpl.executeOn(PoolImpl.java:839) at
org.apache.geode.cache.client.internal.PingOp.execute(PingOp.java:38) at
org.apache.geode.cache.client.internal.LiveServerPinger$PingTask.run2(LiveServerPinger.java:92)
at
org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1329)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at
org.apache.geode.internal.ScheduledThreadPoolExecutorWithKeepAlive$DelegatingScheduledFuture.run(ScheduledThreadPoolExecutorWithKeepAlive.java:276)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
{noformat}
The above happens whenever {{this}} member receives a {{ping}} from the client
and detects that it should be redirected to other member, but the other member
is not part of the distributed system anymore (see
[this|https://github.com/apache/geode/commit/dd23ee8200cba67cea82e57e2e4ccedcdf9e8266#diff-a5e7140e8b90ce74e7ba8a703be7b2ddR94]).
FYI: *I'm not using the same {{ServerLocation}} for multiple servers so this
shouldn't happen at all.*
—
Below are the logs from the server while receiving, handling and replying the
{{ping}} message:
{noformat}
(1) [info 2020/04/22 14:13:48.021 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Server connection from
[identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2;
port=39942]: rcv tx: -1 from /10.32.110.142:39942 timeout: 0 rcvTime: 33282
(2) [info 2020/04/22 14:13:48.021 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Redirecting ping request from
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v9>:41001
to
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001
because myID.equals(targetServer) = false.
(3) [info 2020/04/22 14:13:48.021 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Received a Ping request from
identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2
intended for
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001.
Forwarding the ping...
(4) [warn 2020/04/22 14:13:48.022 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] Unable to ping non-member
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001
for client
identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2
(5) [info 2020/04/22 14:13:48.022 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Server connection from
[identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2;
port=39942]: rpl tx: -1
{noformat}
As you can see in step 2, [this
comparison|https://github.com/apache/geode/commit/dd23ee8200cba67cea82e57e2e4ccedcdf9e8266#diff-a5e7140e8b90ce74e7ba8a703be7b2ddR55]
returns {{false}} because the {{viewId}} changed for the member: {{myID =
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v9>:41001}}
and {{targetServer =
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001}}
are not equals and, as such, the server tries to redirect the ping to and "old
version" of itself. Since that "old version" is not part of the membership view
anymore, the server returns an "error" to the client and the client can't
handle the error.
I believe this should be fixed in two steps:
- The member shouldn't try to redirect the ping an "old version of itself",
the comparison should be smart enough to detect that {{targetServer}} and
{{thisServer}} are the same for this scenario ([~bschuchardt], what do you
think?).
- Whenever {{thisServer}} needs to actually redirect the {{ping}} and it fails
(for whatever reason), it must return something that the client can handle
nicely, otherwise it will keep showing {{Unexpected message type PING}}.
was (Author: jujoramos):
[~alberto.bustamante.reyes] [~bschuchardt]: I've managed to reproduce one of
the two regressions with extra logging, analysis and details below.
The client gets an unexpected {{PING}} message when it's expecting a simple
{{ACK}}.
{noformat}
org.apache.geode.InternalGemFireError: Unexpected message type PING
at
org.apache.geode.cache.client.internal.AbstractOp.processAck(AbstractOp.java:264)
at
org.apache.geode.cache.client.internal.PingOp$PingOpImpl.processResponse(PingOp.java:82)
at
org.apache.geode.cache.client.internal.AbstractOp.processResponse(AbstractOp.java:222)
at
org.apache.geode.cache.client.internal.AbstractOp.attemptReadResponse(AbstractOp.java:207)
at
org.apache.geode.cache.client.internal.AbstractOp.attempt(AbstractOp.java:382)
at
org.apache.geode.cache.client.internal.ConnectionImpl.execute(ConnectionImpl.java:268)
at
org.apache.geode.cache.client.internal.pooling.PooledConnection.execute(PooledConnection.java:352)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeWithPossibleReAuthentication(OpExecutorImpl.java:753)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOnServer(OpExecutorImpl.java:332)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOn(OpExecutorImpl.java:303)
at
org.apache.geode.cache.client.internal.PoolImpl.executeOn(PoolImpl.java:839)
at org.apache.geode.cache.client.internal.PingOp.execute(PingOp.java:38)
at
org.apache.geode.cache.client.internal.LiveServerPinger$PingTask.run2(LiveServerPinger.java:92)
at
org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1329)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at
org.apache.geode.internal.ScheduledThreadPoolExecutorWithKeepAlive$DelegatingScheduledFuture.run(ScheduledThreadPoolExecutorWithKeepAlive.java:276)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
{noformat}
The above happens whenever {{this}} member receives a {{ping}} from the client
and detects that it should be redirected to other member, but the other member
is not part of the distributed system anymore (see
[this|https://github.com/apache/geode/commit/dd23ee8200cba67cea82e57e2e4ccedcdf9e8266#diff-a5e7140e8b90ce74e7ba8a703be7b2ddR94]).
FYI: *I'm not using the same {{ServerLocation}} for multiple servers so this
shouldn't happen at all.*
---
Below are the logs from the server while receiving, handling and replying the
{{ping}} message:
{noformat}
(1) [info 2020/04/22 14:13:48.021 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Server connection from
[identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2;
port=39942]: rcv tx: -1 from /10.32.110.142:39942 timeout: 0 rcvTime: 33282
(2) [info 2020/04/22 14:13:48.021 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Redirecting ping request from
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v9>:41001
to
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001
because myID.equals(targetServer) = false.
(3) [info 2020/04/22 14:13:48.021 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Received a Ping request from
identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2
intended for
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001.
Forwarding the ping...
(4) [warn 2020/04/22 14:13:48.022 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] Unable to ping non-member
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001
for client
identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2
(5) [info 2020/04/22 14:13:48.022 PDT <ServerConnection on port 22831 Thread 5>
tid=0x21a] [JUAN]: Server connection from
[identity(rs-GEM-2885-0819axi32xlarge-hydra-client-11(edgegemfire4_host1_12745:12745:loner):56396:c4a7b9a3:edgegemfire4_host1_12745,connection=2;
port=39942]: rpl tx: -1
{noformat}
As you can see in step 2, [this
comparison|https://github.com/apache/geode/commit/dd23ee8200cba67cea82e57e2e4ccedcdf9e8266#diff-a5e7140e8b90ce74e7ba8a703be7b2ddR55]
returns {{false}} because the {{viewId}} changed for the member: {{myID =
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v9>:41001}}
and {{targetServer =
rs-GEM-2885-0819axi32xlarge-hydra-client-11(bridgegemfire1_host1_12575:12575)<ec><v5>:41001}}
are not equals and, as such, the server tries to redirect the ping to and "old
version" of itself. Since that "old version" is not part of the membership view
anymore, the server returns an "error" to the client and the client can't
handle the error.
I believe this should be fixed in two steps:
- The member shouldn't try to redirect the ping an "old version of itself", the
comparison should be smart enough to detect that {{targetServer}} and
{{thisServer}} are the same for this scenario ([~bschuchardt], what do you
think?).
- Whenever {{thisServer}} needs to actually redirect the {{ping}} and it fails
(for whatever reason), it must return something that the client can handle
nicely, otherwise it will keep showing {{Unexpected message type PING}}.
> Regression Introduced Through GEODE-7565
> ----------------------------------------
>
> Key: GEODE-8004
> URL: https://issues.apache.org/jira/browse/GEODE-8004
> Project: Geode
> Issue Type: Bug
> Components: client/server
> Reporter: Juan Ramos
> Assignee: Juan Ramos
> Priority: Major
> Labels: GeodeCommons
>
> Intermittent errors were observed while executing some internal tests and
> commit
> [dd23ee8|https://github.com/apache/geode/commit/dd23ee8200cba67cea82e57e2e4ccedcdf9e8266]
> was determined to be responsible. As of yet, no local reproduction of the
> issue is available, but work is ongoing to provide a test that can be used to
> debug the issue (a [PR|https://github.com/apache/geode/pull/4974] to revert
> of the original commit has been opened and will be merged shortly, though,
> this ticket is to investigate the root cause so the original commit can be
> merged again into {{develop}}).
> ---
> It seems that a server is trying to read an {{ack}} response and, instead, it
> receives a {{PING}} message:
> {noformat}
> [error 2020/04/18 23:44:22.758 PDT <poolTimer-edgeDescript-31> tid=0x165]
> Unexpected error in pool task
> <org.apache.geode.cache.client.internal.LiveServerPinger$PingTask@3483b110>
> org.apache.geode.InternalGemFireError: Unexpected message type PING
> at
> org.apache.geode.cache.client.internal.AbstractOp.processAck(AbstractOp.java:264)
> at
> org.apache.geode.cache.client.internal.PingOp$PingOpImpl.processResponse(PingOp.java:82)
> at
> org.apache.geode.cache.client.internal.AbstractOp.processResponse(AbstractOp.java:222)
> at
> org.apache.geode.cache.client.internal.AbstractOp.attemptReadResponse(AbstractOp.java:207)
> at
> org.apache.geode.cache.client.internal.AbstractOp.attempt(AbstractOp.java:382)
> at
> org.apache.geode.cache.client.internal.ConnectionImpl.execute(ConnectionImpl.java:268)
> at
> org.apache.geode.cache.client.internal.pooling.PooledConnection.execute(PooledConnection.java:352)
> at
> org.apache.geode.cache.client.internal.OpExecutorImpl.executeWithPossibleReAuthentication(OpExecutorImpl.java:753)
> at
> org.apache.geode.cache.client.internal.OpExecutorImpl.executeOnServer(OpExecutorImpl.java:332)
> at
> org.apache.geode.cache.client.internal.OpExecutorImpl.executeOn(OpExecutorImpl.java:303)
> at
> org.apache.geode.cache.client.internal.PoolImpl.executeOn(PoolImpl.java:839)
> at org.apache.geode.cache.client.internal.PingOp.execute(PingOp.java:38)
> at
> org.apache.geode.cache.client.internal.LiveServerPinger$PingTask.run2(LiveServerPinger.java:90)
> at
> org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1329)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> at
> org.apache.geode.internal.ScheduledThreadPoolExecutorWithKeepAlive$DelegatingScheduledFuture.run(ScheduledThreadPoolExecutorWithKeepAlive.java:276)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> {noformat}
> Around the same time, another member of the distributed system logs the
> following warning, which seems to be related to the original changes as well:
> {noformat}
> [warn 2020/04/18 23:44:22.757 PDT <ServerConnection on port 29019 Thread 1>
> tid=0x298] Unable to ping non-member
> rs-FullRegression19040559a2i32xlarge-hydra-client-63(bridgegemfire1_host1_4749:4749)<ec><v39>:41003
> for client
> identity(rs-FullRegression19040559a2i32xlarge-hydra-client-63(edgegemfire3_host1_1071:1071:loner):50046:5a182991:edgegemfire3_host1_1071,connection=2
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
