[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16091282#comment-16091282 ] Rajini Sivaram commented on KAFKA-5595: --- [~ijuma] [~hachikuji] I have to admit I didn't look much deeper into it either. The scenario I was thinking of was where a slow broker closes a few connections because it thinks they are idle. Some connections without port reuse would show the log entry {{Attempting to send response via channel for which there is no open connection}}. One connection where the port did get reused will have a new channel. When the response to the older connection is ready, it would get sent to the newer connection with a channel in selector. And that would throw {{IllegalStateException}} if there is already a send outstanding to the newer connection. But I hadn't realized that there were 13K warnings. So I agree this is not the scenario here. > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16090205#comment-16090205 ] Jason Gustafson commented on KAFKA-5595: Ensuring connectionId uniqueness is a nice improvement, but I agree with Ismael that it seems unlikely to fix the underlying issue. We may have to be content with the Rajini's logging improvements for now and hope that they will give us some more hints the next time it happens. Seems extremely rare in any case. One other data point worth mentioning: I mentioned the "Attempting to send response via channel ..." messages above. In fact, there were about 13K of these messages within 1 second of the illegal state exceptions. > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16089143#comment-16089143 ] ASF GitHub Bot commented on KAFKA-5595: --- GitHub user rajinisivaram reopened a pull request: https://github.com/apache/kafka/pull/3530 KAFKA-5595: Ensure client connection ids are not reused too quickly When there are broker delays that cause a response to take longer than `connections.max.idle.ms`, connections may be closed by the broker (as well as by the client) before the response is processed. If the port is reused, broker may send the outstanding response to a new connection with the reused port. The new connection will end up with correlation id mismatch, requiring process restart. This is also a security exposure since clients receive response intended for the wrong connection. You can merge this pull request into a Git repository by running: $ git pull https://github.com/rajinisivaram/kafka KAFKA-5595 Alternatively you can review and apply these changes as the patch at: https://github.com/apache/kafka/pull/3530.patch To close this pull request, make a commit to your master/trunk branch with (at least) the following in the commit message: This closes #3530 commit 99f3374b5c3b0cb5efcdfe4c553aac943297b016 Author: Rajini SivaramDate: 2017-07-15T13:01:47Z KAFKA-5595: Ensure client connection ids are not reused too quickly > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16089137#comment-16089137 ] Rajini Sivaram commented on KAFKA-5595: --- I think this issue can occur when idle connections are closed by the broker. This would cause the channel to be removed when responses are still pending. And if ports are reused, it can result in the IllegalStateException. > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16089098#comment-16089098 ] Rajini Sivaram commented on KAFKA-5595: --- [~ijuma] I dont think the scenario that you described can occur. Broker mutes connections when requests are processed. Even if client disconnected, the disconnection would be processed only when the response was ready to be sent. And response is sent before any disconnections are processed. > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16089093#comment-16089093 ] ASF GitHub Bot commented on KAFKA-5595: --- Github user rajinisivaram closed the pull request at: https://github.com/apache/kafka/pull/3530 > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16088601#comment-16088601 ] ASF GitHub Bot commented on KAFKA-5595: --- GitHub user rajinisivaram opened a pull request: https://github.com/apache/kafka/pull/3530 KAFKA-5595: Ensure client connection ids are not reused too quickly On the broker, if client ports are reused when response to a closed connection is outstanding, broker may send the outstanding response to a new connection with the reused port. The new connection will end up with correlation id mismatch, requiring process restart. This is also a security exposure since clients receive response intended for the wrong connection. You can merge this pull request into a Git repository by running: $ git pull https://github.com/rajinisivaram/kafka KAFKA-5595 Alternatively you can review and apply these changes as the patch at: https://github.com/apache/kafka/pull/3530.patch To close this pull request, make a commit to your master/trunk branch with (at least) the following in the commit message: This closes #3530 commit f1f42bcb57e77cd0841b588ae91cee457ba07832 Author: Rajini SivaramDate: 2017-07-15T13:01:47Z KAFKA-5595: Ensure client connection ids are not reused too quickly > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16087916#comment-16087916 ] Rajini Sivaram commented on KAFKA-5595: --- Connection id contains remote port, it is currently logging processor id, hence the integer value 7 in the logs. I have submitted a PR to fix that. [~ijuma] Since connection id contains remote port, for the scenario you described, the port needs to get reused. Typically that shouldn't happen while still processing requests of an older connection using that port. The channel should have been closed and removed from selector before the new connection. > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16087749#comment-16087749 ] Ismael Juma commented on KAFKA-5595: I haven't checked this in detail, but a possibility: 1. There is an inflight response for client c 2. There is a disconnection and reconnection from client c causing us to lose the channel state 3. Client c sends another request 4. Because we lost the channel state and we don't drain the response queue on disconnections, we may allow 2 inflight responses for the same connection 5. Under the right set of circumstances, this could lead to the IllegalStateException reported Am I missing something? > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)
[jira] [Commented] (KAFKA-5595) Illegal state in SocketServer; attempt to send with another send in progress
[ https://issues.apache.org/jira/browse/KAFKA-5595?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16087745#comment-16087745 ] Jason Gustafson commented on KAFKA-5595: cc [~rsivaram] In case you have any ideas. > Illegal state in SocketServer; attempt to send with another send in progress > > > Key: KAFKA-5595 > URL: https://issues.apache.org/jira/browse/KAFKA-5595 > Project: Kafka > Issue Type: Bug >Reporter: Jason Gustafson > > I have seen this a couple times, but I'm not sure the conditions associated > with it. > {code} > java.lang.IllegalStateException: Attempt to begin a send operation with prior > send operation still in progress. > at > org.apache.kafka.common.network.KafkaChannel.setSend(KafkaChannel.java:138) > at org.apache.kafka.common.network.Selector.send(Selector.java:248) > at kafka.network.Processor.sendResponse(SocketServer.scala:488) > at kafka.network.Processor.processNewResponses(SocketServer.scala:466) > at kafka.network.Processor.run(SocketServer.scala:431) > at java.lang.Thread.run(Thread.java:748) > {code} > Prior to this event, I see a lot of this message in the logs (always for the > same connection id): > {code} > Attempting to send response via channel for which there is no open > connection, connection id 7 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)