You are viewing a plain text version of this content. The canonical link for it is here.
Posted to jira@kafka.apache.org by "Eran Levy (Jira)" <ji...@apache.org> on 2020/11/05 09:43:00 UTC
[jira] [Comment Edited] (KAFKA-10643) Static membership -
repetitive PreparingRebalance with updating metadata for member reason
[ https://issues.apache.org/jira/browse/KAFKA-10643?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17226608#comment-17226608 ]
Eran Levy edited comment on KAFKA-10643 at 11/5/20, 9:42 AM:
-------------------------------------------------------------
[~ableegoldman] thanks, sorry for the delayed response, was waiting for it to happen again to make sure I provide the correct logs.
re the DisconnectException - thanks.
Im concerned on specifically 2 issues which they might not be related to each other:
First issue - rebalancing suddenly triggers and it takes a long time to finish (I suspect that it might related to some network issue):
1. Attached are the logs for the broker and client (client name: d-8)
2. It happened again on 4/11 14:53
3. You can see in the client logs that last line of normal process logged on: 14:52:33.998. Right after that 14:53:32.030 - the only logs that show up with some time between them are the kafka-producer-network-thread logs which looks very suspicious. Only around 15:00:32.147 I can see logs related to the state store.
5. In the broker logs around 15:00:18 I see that re this client d-8 - reason: removing member d-8-2-00941765-25cb-4161-b3ca-f941785d9bc4 on heartbeat expiration
6. right after that I see that all the other client d-2 and others with the following log: "...in group d has failed, removing it from the group..."
7. for the same broker (you can see in the broker logs attached) I see some logs around its eth1 - that logs around this time - "Nov 4 15:08:02 ip-3-3-3-3 ec2net: [rewrite_rules] Rewriting rules for eth1"
It looks like d-8 hasnt responses for heartbeats right? do you observe anything else that happening here?
What I see from the client network metrics is that container_network_receive_bytes_total and container_network_transmit_bytes_total are very very low since 14:53.
in addition to what wrote above re static membership, etc - the session timeout ms is {{180000}}
Second Issue -
Im bit worried on something that i see happening all the time since we started static membership - It looks like that there is some specific client (not always the same client, it can be d-0, d-1, etc) that its StreamThreads are getting into repetitive preparing for rebalancing stage with the following logs:
{"timestamp":"2020-11-05T09:32:03.361Z","level":"INFO","thread":"***-27d55923-f5a4-4af9-b277-09436b6aecb7-StreamThread-1","logger":"org.apache.kafka.streams.KafkaStreams","message":"stream-client [***-27d55923-f5a4-4af9-b277-09436b6aecb7] State transition from RUNNING to REBALANCING","context":"default"} \{"timestamp":"2020-11-05T09:35:53.081Z","level":"INFO","thread":"***-27d55923-f5a4-4af9-b277-09436b6aecb7-StreamThread-1","logger":"org.apache.kafka.streams.processor.internals.StreamThread","message":"stream-thread [***-27d55923-f5a4-4af9-b277-09436b6aecb7-StreamThread-1] State transition from PARTITIONS_ASSIGNED to RUNNING","context":"default"} \{"timestamp":"2020-11-05T09:32:21.737Z","level":"INFO","thread":"***-12cc6d3d-e8f2-43ad-9319-729c3a7427b8-StreamThread-1","logger":"org.apache.kafka.streams.KafkaStreams","message":"stream-client [***-12cc6d3d-e8f2-43ad-9319-729c3a7427b8] State transition from REBALANCING to RUNNING","context":"default"} \{"timestamp":"2020-11-05T09:32:19.803Z","level":"INFO","thread":"main","logger":"org.apache.kafka.streams.processor.internals.assignment.AssignorConfiguration","message":"stream-thread [***-12cc6d3d-e8f2-43ad-9319-729c3a7427b8-StreamThread-6-consumer] Cooperative rebalancing enabled now","context":"default"}
was (Author: eran-levy):
[^client-4-11.csv][~ableegoldman] thanks, sorry for the delayed response, was waiting for it to happen again to make sure I provide the correct logs.
re the DisconnectException - thanks.
Im concerned on specifically 2 issues which they might not be related to each other:
First issue - rebalancing suddenly triggers and it takes a long time to finish (I suspect that it might related to some network issue):
1. Attached are the logs for the broker and client (client name: d-8)
2. It happened again on 4/11 14:53
3. You can see in the client logs that last line of normal process logged on: 14:52:33.998. Right after that 14:53:32.030 - the only logs that show up with some time between them are the kafka-producer-network-thread logs which looks very suspicious. Only around 15:00:32.147 I can see logs related to the state store.
5. In the broker logs around 15:00:18 I see that re this client d-8 - reason: removing member d-8-2-00941765-25cb-4161-b3ca-f941785d9bc4 on heartbeat expiration
6. right after that I see that all the other client d-2 and others with the following log: "...in group d has failed, removing it from the group..."
7. for the same broker (you can see in the broker logs attached) I see some logs around its eth1 - that logs around this time - "Nov 4 15:08:02 ip-3-3-3-3 ec2net: [rewrite_rules] Rewriting rules for eth1"
It looks like d-8 hasnt responses for heartbeats right? do you observe anything else that happening here?
What I see from the client network metrics is that container_network_receive_bytes_total and container_network_transmit_bytes_total are very very low since 14:53.
in addition to what wrote above re static membership, etc - the session timeout ms is {{180000}}
Second Issue - Im bit worried on something that i see happening all the time since we started static membership - It looks like that there is some specific client (not always the same client, it can be d-0, d-1, etc) that its StreamThreads are getting into repetitive preparing for rebalancing stage with the following logs:
{"timestamp":"2020-11-05T09:32:03.361Z","level":"INFO","thread":"***-27d55923-f5a4-4af9-b277-09436b6aecb7-StreamThread-1","logger":"org.apache.kafka.streams.KafkaStreams","message":"stream-client [***-27d55923-f5a4-4af9-b277-09436b6aecb7] State transition from RUNNING to REBALANCING","context":"default"}
{"timestamp":"2020-11-05T09:35:53.081Z","level":"INFO","thread":"***-27d55923-f5a4-4af9-b277-09436b6aecb7-StreamThread-1","logger":"org.apache.kafka.streams.processor.internals.StreamThread","message":"stream-thread [***-27d55923-f5a4-4af9-b277-09436b6aecb7-StreamThread-1] State transition from PARTITIONS_ASSIGNED to RUNNING","context":"default"}
{"timestamp":"2020-11-05T09:32:21.737Z","level":"INFO","thread":"***-12cc6d3d-e8f2-43ad-9319-729c3a7427b8-StreamThread-1","logger":"org.apache.kafka.streams.KafkaStreams","message":"stream-client [***-12cc6d3d-e8f2-43ad-9319-729c3a7427b8] State transition from REBALANCING to RUNNING","context":"default"}
{"timestamp":"2020-11-05T09:32:19.803Z","level":"INFO","thread":"main","logger":"org.apache.kafka.streams.processor.internals.assignment.AssignorConfiguration","message":"stream-thread [***-12cc6d3d-e8f2-43ad-9319-729c3a7427b8-StreamThread-6-consumer] Cooperative rebalancing enabled now","context":"default"}
> Static membership - repetitive PreparingRebalance with updating metadata for member reason
> ------------------------------------------------------------------------------------------
>
> Key: KAFKA-10643
> URL: https://issues.apache.org/jira/browse/KAFKA-10643
> Project: Kafka
> Issue Type: Bug
> Components: streams
> Affects Versions: 2.6.0
> Reporter: Eran Levy
> Priority: Major
> Attachments: broker-4-11.csv, client-4-11.csv
>
>
> Kafka streams 2.6.0, brokers version 2.6.0. Kafka nodes are healthy, kafka streams app is healthy.
> Configured with static membership.
> Every 10 minutes (I assume cause of topic.metadata.refresh.interval.ms), I see the following group coordinator log for different stream consumers:
> INFO [GroupCoordinator 2]: Preparing to rebalance group **--**-stream in state PreparingRebalance with old generation 12244 (__consumer_offsets-45) (reason: Updating metadata for member ****-stream-11-1-013edd56-ed93-4370-b07c-1c29fbe72c9a) (kafka.coordinator.group.GroupCoordinator)
> and right after that the following log:
> INFO [GroupCoordinator 2]: Assignment received from leader for group **-**-stream for generation 12246 (kafka.coordinator.group.GroupCoordinator)
>
> Looked a bit on the kafka code and Im not sure that I get why such a thing happening - is this line described the situation that happens here re the "reason:"?[https://github.com/apache/kafka/blob/7ca299b8c0f2f3256c40b694078e422350c20d19/core/src/main/scala/kafka/coordinator/group/GroupCoordinator.scala#L311]
> I also dont see it happening too often in other kafka streams applications that we have.
> The only thing suspicious that I see around every hour that different pods of that kafka streams application throw this exception:
> {"timestamp":"2020-10-25T06:44:20.414Z","level":"INFO","thread":"**-**-stream-94561945-4191-4a07-ac1b-07b27e044402-StreamThread-1","logger":"org.apache.kafka.clients.FetchSessionHandler","message":"[Consumer clientId=**-**-stream-94561945-4191-4a07-ac1b-07b27e044402-StreamThread-1-restore-consumer, groupId=null] Error sending fetch request (sessionId=34683236, epoch=2872) to node 3:","context":"default","exception":"org.apache.kafka.common.errors.DisconnectException: null\n"}
> I came across this strange behaviour after stated to investigate a strange stuck rebalancing state after one of the members left the group and caused the rebalance to stuck - the only thing that I found is that maybe because that too often preparing to rebalance states, the app might affected of this bug - KAFKA-9752 ?
> I dont understand why it happens, it wasn't before I applied static membership to that kafka streams application (since around 2 weeks ago).
> Will be happy if you can help me
>
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)