[KAFKA-5417] Clients get inconsistent connection states when SASL/SSL… #3282

dongeforever · 2017-06-09T13:47:43Z

… connection is marked CONECTED and DISCONNECTED at the same time

details are in:
https://issues.apache.org/jira/browse/KAFKA-5417

dongeforever · 2017-06-09T13:49:26Z

@guozhangwang please have a check at your convinence

ijuma · 2017-06-09T14:15:05Z

asfbot · 2017-06-09T14:46:21Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk7-scala2.11/5104/
Test PASSed (JDK 7 and Scala 2.11).

asfbot · 2017-06-09T15:00:31Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk8-scala2.12/5088/
Test PASSed (JDK 8 and Scala 2.12).

junrao · 2017-06-09T16:26:06Z

@dongeforever : Thanks for the finding. Great catch. The patch looks good. Perhaps we could add a comment in ConnectionState about state transition (e.g., we can transition from any of CONNECTING, CHECKING_API_VERSIONS, READY directly to DISCONNECTED).

ijuma · 2017-06-09T22:05:07Z

clients/src/main/java/org/apache/kafka/common/network/Selector.java

+        Iterator<String> connectedIt = connected.iterator();
+        while (connectedIt.hasNext()) {
+            if (disconnected.containsKey(connectedIt.next())) {
+                log.warn("Channel {} is marked connected and disconnected at the same time");


What does this warning indicate? Should users be doing something about it? If not, maybe it should be logged at a lower level?

Yeah. It is an internal class though. Users need to do nothing. I will update it.

rajinisivaram · 2017-06-12T08:30:29Z

clients/src/main/java/org/apache/kafka/common/network/Selector.java

+        while (connectedIt.hasNext()) {
+            if (disconnected.containsKey(connectedIt.next())) {
+                log.warn("Channel {} is marked connected and disconnected at the same time");
+                connectedIt.remove();


Since this channel was added to the connected set only in this poll(), no one knows about this channel yet. So perhaps we should remove it from disconnected as well to avoid notifying disconnection of an unknown channel?

I was debating the same thing. Won't NetworkClient keep the node under the CONNECTING state though? It seems like either approach involves a change in the contract that could affect users who are not expecting it. It's an internal class though, so we just need to make sure that the affected Kafka code is updated (if necessary).

It would be nice to include a test for this so that we can verify that things truly work under this scenario.

@ijuma Yes, you are right, NetworkClient does need to be notified. Ignore my previous comment.

@ijuma I want to add a test, but unfortunately it is hard to mock such a network environment.
I have tested it many times in my company's LVS Proxy env.
Do you have some suggestions about it?

Maybe we could keep it simple and add a test for Selector.pollSelectedKeys where SelectionKey and the channel returned by the SelectionKey are mocked. What do you think?

asfbot · 2017-06-13T04:52:25Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk7-scala2.11/5218/
Test PASSed (JDK 7 and Scala 2.11).

asfbot · 2017-06-13T04:52:54Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk8-scala2.12/5202/
Test PASSed (JDK 8 and Scala 2.12).

ijuma · 2017-06-13T12:16:05Z

clients/src/main/java/org/apache/kafka/common/network/Selector.java

+        Iterator<String> connectedIt = connected.iterator();
+        while (connectedIt.hasNext()) {
+            if (disconnected.containsKey(connectedIt.next())) {
+                log.debug("Channel {} is marked connected and disconnected at the same time");


The channel is not being passed to log.debug.

@ijuma Thanks. It has been polished

asfbot · 2017-06-14T04:23:27Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk7-scala2.11/5284/
Test PASSed (JDK 7 and Scala 2.11).

asfbot · 2017-06-14T04:33:57Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk8-scala2.12/5268/
Test FAILed (JDK 8 and Scala 2.12).

hachikuji · 2017-06-14T23:05:34Z

clients/src/main/java/org/apache/kafka/common/network/Selector.java

@@ -335,6 +335,15 @@ public void poll(long timeout) throws IOException {
        // we use the time at the end of select to ensure that we don't close any connections that
        // have just been processed in pollSelectionKeys
        maybeCloseOldestConnection(endSelect);
+
+        Iterator<String> connectedIt = connected.iterator();


It might be a little cleaner to avoid the inconsistency in the first place rather than fixing it after the fact. Have you considered calling connected.remove(channel) when we add the channel to disconnected in doClose?

@dongeforever, what do you think?

@hachikuji @ijuma Agreed to avoid inconsistency in the first place. And it may be a little better to do it in close rather than in doClose, for doClose maybe a delayed operation and close is the first place to notify the ConnectionStates.

@ijuma @hachikuji what do you think about the updated version?

asfgit · 2017-06-22T04:31:50Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk7-scala2.11/5603/
Test FAILed (JDK 7 and Scala 2.11).

asfgit · 2017-06-22T04:34:21Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk8-scala2.12/5589/
Test PASSed (JDK 8 and Scala 2.12).

asfgit · 2017-06-26T06:31:07Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk7-scala2.11/5695/
Test PASSed (JDK 7 and Scala 2.11).

asfgit · 2017-06-26T06:44:37Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk8-scala2.12/5681/
Test FAILed (JDK 8 and Scala 2.12).

hachikuji · 2017-06-26T16:59:29Z

clients/src/main/java/org/apache/kafka/common/network/Selector.java

@@ -555,6 +555,9 @@ private void close(KafkaChannel channel, boolean processOutstanding) {

        channel.disconnect();

+        //avoid inconsistent connection states, see KAFKA-5417
+        connected.remove(channel.id());


I was debating whether doClose is the more appropriate spot for this since that is where we actually close the channel and add the id to the disconnected collection. We have this "closing" state below in which we await pending receives before closing the channel. I am not sure if it is better to allow a connection in that state to be reported as connected or not. It probably doesn't matter too much for the specific bug reported since we wouldn't have any pending receives, but I guess we should still make sure this the state transitions are consistent. Thoughts?

IMO, there is not too much difference to do it in "doClose" and "close". Maybe both are ok.
Any channel in "connected" will be reported as connected.
Since it is going to close such channel, it is better to prevent it to be marked as connected than close it after it has been actually marked.

Yeah, I can't think of a strong reason for either option, so I guess we can leave it here.

hachikuji · 2017-06-28T19:19:57Z

@dongeforever Don't forget about Jun's comment from above:

Perhaps we could add a comment in ConnectionState about state transition (e.g., we can transition from any of CONNECTING, CHECKING_API_VERSIONS, READY directly to DISCONNECTED).

We also should try to come up with a reasonable test case. Ismael suggested previously:

Maybe we could keep it simple and add a test for Selector.pollSelectedKeys where SelectionKey and the channel returned by the SelectionKey are mocked.

Would that work?

dongeforever · 2017-07-05T06:02:49Z

@hachikuji It seems that Kafka dose not introduce any mock framework such as mockito.
So without mock framework, could you give me any advice to write such a unit test?

rajinisivaram · 2017-07-05T08:47:38Z

@dongeforever You can use easymock/powermock for the unit tests. There are already tests in clients which use these.

ijuma · 2017-07-18T12:17:01Z

@dongeforever, do you think you'll be able to provide a test? If not, we can help.

dongeforever · 2017-07-19T03:39:54Z

@ijuma Thank you. A little busy these days. But I want to try it by myself firstly. And I will go back for your help if there is trouble.

ijuma · 2017-08-17T09:03:28Z

@dongeforever any luck writing the test? We are planning to do a 0.11.0.1 release soon and it would be good to include this fix.

asfgit · 2017-08-17T09:16:42Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk7-scala2.11/6841/
Test FAILed (JDK 7 and Scala 2.11).

asfgit · 2017-08-17T10:16:43Z

Refer to this link for build results (access rights to CI server needed):
https://builds.apache.org/job/kafka-pr-jdk8-scala2.12/6827/
Test PASSed (JDK 8 and Scala 2.12).

… connection is marked CONECTED and DISCONNECTED at the same time

dongeforever · 2017-08-23T06:03:21Z

@ijuma Sorry for being so late. I have added a unit test, named as "testAvoidInconsisConnectionStates" in SelectorTest, for this issue.

IMO, the easiest way is to test the private method "pollSelectionKeys" with a mocked SelectionKey and mocked KafkaChannel.
You could get more details in that unit test.
Please feel free to reach out with any question.

ijuma

Thanks for the test. I've made some minor changes (avoid reflection, tweak comments, remove some unnecessary code) and merged to trunk and 0.11.0.

If prepare throws an exception in the same poll when the connection is established, the channel id should be in `disconnected`, but not in `connected`. Author: dongeforever <dongeforever@apache.org> Reviewers: Ismael Juma <ismael@juma.me.uk> Closes #3282 from dongeforever/KAFKA-5417 (cherry picked from commit ea21752) Signed-off-by: Ismael Juma <ismael@juma.me.uk>

ijuma · 2017-08-23T13:57:45Z

Sorry, I made a mistake during merging and didn't mention all the reviewers (Jun, Jason, Rajini).

dongeforever · 2017-08-24T02:44:26Z

@ijuma Thanks

ijuma reviewed Jun 9, 2017

View reviewed changes

rajinisivaram reviewed Jun 12, 2017

View reviewed changes

dongeforever force-pushed the KAFKA-5417 branch from 7cad7ad to ee90417 Compare June 13, 2017 03:39

ijuma reviewed Jun 13, 2017

View reviewed changes

dongeforever force-pushed the KAFKA-5417 branch from ee90417 to e20fd3e Compare June 14, 2017 03:24

hachikuji reviewed Jun 14, 2017

View reviewed changes

hachikuji reviewed Jun 26, 2017

View reviewed changes

[KAFKA-5417] Clients get inconsistent connection states when SASL/SSL…

927cf04

… connection is marked CONECTED and DISCONNECTED at the same time

dongeforever force-pushed the KAFKA-5417 branch from e0d0d6b to 927cf04 Compare August 23, 2017 06:03

ijuma approved these changes Aug 23, 2017

View reviewed changes

asfgit closed this in ea21752 Aug 23, 2017

[KAFKA-5417] Clients get inconsistent connection states when SASL/SSL… #3282

[KAFKA-5417] Clients get inconsistent connection states when SASL/SSL… #3282

Conversation

dongeforever commented Jun 9, 2017

dongeforever commented Jun 9, 2017

ijuma commented Jun 9, 2017

asfbot commented Jun 9, 2017

asfbot commented Jun 9, 2017

junrao commented Jun 9, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asfbot commented Jun 13, 2017

asfbot commented Jun 13, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asfbot commented Jun 14, 2017

asfbot commented Jun 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asfgit commented Jun 22, 2017

asfgit commented Jun 22, 2017

asfgit commented Jun 26, 2017

asfgit commented Jun 26, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hachikuji commented Jun 28, 2017

dongeforever commented Jul 5, 2017

rajinisivaram commented Jul 5, 2017

ijuma commented Jul 18, 2017

dongeforever commented Jul 19, 2017

ijuma commented Aug 17, 2017

asfgit commented Aug 17, 2017

asfgit commented Aug 17, 2017

dongeforever commented Aug 23, 2017

ijuma left a comment

Choose a reason for hiding this comment

ijuma commented Aug 23, 2017 • edited Loading

dongeforever commented Aug 24, 2017

ijuma commented Aug 23, 2017 •

edited

Loading