search

confluentinc / confluent-kafka-python

Confluent's Kafka Python Client
http://docs.confluent.io/current/clients/confluent-kafka-python
Other
3.73k stars 882 forks source link

Consumers get revoked juste after been assigned for 3 consecutives days every week #1684

Open razieldrake opened 7 months ago

razieldrake commented 7 months ago

Description

Hello!

I need some help about identfying and apply a solution about a strange behaviour that appear recently in our Kafka.

We are using python confluent-kafka for several year in my appliction in conjunction with Azur Event Hub. It's been working fine for 2 years with no major trouble till one day, about a month ago, our local consumers ("local" means our consumer that we are using for dev and test before pushing branch on test instance) totally broke down. The consumers will try to connect to broker, they will be assign correctly and juste after assignment, parititions are revoked for a reason that i'm not able to identify. As the consumers fail and stop every time from Monday to Thursday, i was thinking about change in our infra but that is not the case. On this topic we have a 48 hours retention for kafka message, and it almost match the duration the failing Kafka Consumer. I do not know if it's related. When Consumer act normally , our consumers work as they have always worked and there is no way to make the bug happens Azur Event Hub provide some logs for the broker side but i haven' find anything valuables.

As mention, i need some help for identifying what cause this and what i can do about it! Thanks in advance

Click HERE for consumer, brokers, cgrp logs %7|1701266706.939|MEMBERID|sim-ordotest2#consumer-1| [thrd:app]: Group "sim-ordotest2": updating member id "(not-set)" -> "" %7|1701266706.939|BROKER|sim-ordotest2#consumer-1| [thrd:app]: GroupCoordinator: Added new broker with NodeId -1 %7|1701266706.939|BRKMAIN|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Enter main broker thread %7|1701266706.939|BROKER|sim-ordotest2#consumer-1| [thrd:app]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Added new broker with NodeId -1 %7|1701266706.940|BRKMAIN|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Enter main broker thread %7|1701266706.940|CGRPSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed state init -> query-coord (join-state init) %7|1701266706.940|INIT|sim-ordotest2#consumer-1| [thrd:app]: librdkafka v2.3.0 (0x20300ff) sim-ordotest2#consumer-1 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer,http,oidc, SSL ZLIB SNAPPY ZSTD CURL SASL_SCRAM SASL_OAUTHBEARER PLUGINS HDRHISTOGRAM, debug 0x2102) %7|1701266706.940|BRKMAIN|sim-ordotest2#consumer-1| [thrd::0/internal]: :0/internal: Enter main broker thread %7|1701266706.940|CONNECT|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Selected for cluster connection: coordinator query (broker has 0 connection attempt(s)) %7|1701266706.940|CGRPQUERY|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": no broker available for coordinator query: intervaled in state query-coord %7|1701266706.940|CONNECT|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Received CONNECT op %7|1701266706.941|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker changed state INIT -> TRY_CONNECT %7|1701266706.940|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op SUBSCRIBE in state query-coord (join-state init) %7|1701266706.941|SUBSCRIBE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": subscribe to new subscription of 1 topics (join-state init) %7|1701266706.941|CONNECT|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: broker in state TRY_CONNECT connecting %7|1701266706.941|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker changed state TRY_CONNECT -> CONNECT %7|1701266706.941|CONNECT|sim-ordotest2#consumer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: coordinator query %7|1701266706.942|CGRPQUERY|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": no broker available for coordinator query: intervaled in state query-coord Timestamp="2023-11-29 15:05:06,943" Message="Waiting for event on topic test2" keyType="WAITING_EVENT" keyValue="test2" Application="TTCR" Component="TTCR-Scheduler" From="SIM" LogLevel="INFO" %7|1701266706.972|CONNECT|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Connecting to ipv4#hidden.ip.1:9093 (sasl_ssl) with socket 932 %7|1701266707.018|CONNECT|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Connected to ipv4#hidden.ip.1:9093 %7|1701266707.018|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker changed state CONNECT -> SSL_HANDSHAKE %7|1701266707.114|CONNECTED|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Connected (#1) %7|1701266707.114|FEATURE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion %7|1701266707.118|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker changed state SSL_HANDSHAKE -> APIVERSION_QUERY %7|1701266707.149|FEATURE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Updated enabled protocol features to ApiVersion,BrokerBalancedConsumer,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,SaslAuthReq %7|1701266707.150|AUTH|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Auth in state APIVERSION_QUERY (handshake supported) %7|1701266707.151|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker changed state APIVERSION_QUERY -> AUTH_HANDSHAKE %7|1701266707.190|SASLMECHS|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker supported SASL mechanisms: PLAIN,OAUTHBEARER %7|1701266707.191|AUTH|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported) %7|1701266707.192|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker changed state AUTH_HANDSHAKE -> AUTH_REQ %7|1701266707.240|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Broker changed state AUTH_REQ -> UP %7|1701266707.240|CGRPQUERY|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: Group "sim-ordotest2": querying for coordinator: intervaled in state query-coord %7|1701266707.242|CGRPSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed state query-coord -> wait-coord (join-state init) %7|1701266707.356|UPDATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/bootstrap: NodeId changed from -1 to 0 %7|1701266707.356|UPDATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Name changed from sasl_ssl://hidden.url.windows.net:9093/bootstrap to sasl_ssl://hidden.url.windows.net:9093/0 %7|1701266707.358|LEADER|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Mapped 0 partition(s) to broker %7|1701266707.358|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Broker changed state UP -> UPDATE %7|1701266707.359|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Broker changed state UPDATE -> UP %7|1701266707.359|CLUSTERID|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/0: ClusterId update "" -> "hidden.url.windows.net" %7|1701266707.359|CONTROLLERID|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/0: ControllerId update -1 -> 0 %7|1701266707.360|CGRPCOORD|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/0: Group "sim-ordotest2" coordinator is hidden.url.windows.net:9093 id 0 %7|1701266707.360|CGRPCOORD|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changing coordinator -1 -> 0 %7|1701266707.360|COORDSET|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" coordinator set to broker sasl_ssl://hidden.url.windows.net:9093/0 %7|1701266707.360|CGRPSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed state wait-coord -> wait-broker-transport (join-state init) %7|1701266707.361|NODENAME|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator: Broker nodename changed from "" to "hidden.url.windows.net:9093" %7|1701266707.361|NODEID|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator: Broker nodeid changed from -1 to 0 %7|1701266707.361|CGRPQUERY|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/0: Group "sim-ordotest2": querying for coordinator: intervaled in state wait-broker-transport %7|1701266707.361|CONNECT|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Received CONNECT op %7|1701266707.362|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state INIT -> TRY_CONNECT %7|1701266707.362|CONNECT|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: broker in state TRY_CONNECT connecting %7|1701266707.362|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state TRY_CONNECT -> CONNECT %7|1701266707.363|CONNECT|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Connecting to ipv4#hidden.ip.1:9093 (sasl_ssl) with socket 968 %7|1701266707.392|CGRPCOORD|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/0: Group "sim-ordotest2" coordinator is hidden.url.windows.net:9093 id 0 %7|1701266707.413|CONNECT|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Connected to ipv4#hidden.ip.1:9093 %7|1701266707.413|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state CONNECT -> SSL_HANDSHAKE %7|1701266707.493|CONNECTED|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Connected (#1) %7|1701266707.494|FEATURE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Updated enabled protocol features +ApiVersion to ApiVersion %7|1701266707.495|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state SSL_HANDSHAKE -> APIVERSION_QUERY %7|1701266707.525|FEATURE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Updated enabled protocol features to ApiVersion,BrokerBalancedConsumer,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,SaslAuthReq %7|1701266707.525|AUTH|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Auth in state APIVERSION_QUERY (handshake supported) %7|1701266707.527|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state APIVERSION_QUERY -> AUTH_HANDSHAKE %7|1701266707.559|SASLMECHS|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Broker supported SASL mechanisms: PLAIN,OAUTHBEARER %7|1701266707.559|AUTH|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator/0: Auth in state AUTH_HANDSHAKE (handshake supported) %7|1701266707.560|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state AUTH_HANDSHAKE -> AUTH_REQ %7|1701266707.598|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state AUTH_REQ -> UP %7|1701266707.598|CGRPSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed state wait-broker-transport -> up (join-state init) %7|1701266707.599|JOIN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": join with 0 subscribed topic(s) %7|1701266707.600|CGRPMETADATA|sim-ordotest2#consumer-1| [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old) %7|1701266707.600|JOIN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": postponing join until up-to-date metadata is available %7|1701266707.601|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state init -> wait-metadata (state up) %7|1701266707.601|DUMP|sim-ordotest2#consumer-1| [thrd:main]: Assignment dump (started_cnt=0, wait_stop_cnt=0) %7|1701266707.601|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266707.601|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266707.602|DUMP_QRY|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266707.602|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266707.603|ASSIGNDONE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": assignment operations done in join-state wait-metadata (rebalance rejoin=false) %7|1701266707.630|SUBSCRIPTION|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": effective subscription list changed from 0 to 1 topic(s): %7|1701266707.630|SUBSCRIPTION|sim-ordotest2#consumer-1| [thrd:main]: Topic test2 with 2 partition(s) %7|1701266707.632|REJOIN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": subscription updated from metadata change: rejoining group in state wait-metadata %7|1701266707.632|GRPLEADER|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": resetting group leader info: group (re)join %7|1701266707.633|REJOIN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" (re)joining in join-state wait-metadata with 0 assigned partition(s): Metadata for subscribed topic(s) has changed %7|1701266707.633|REBALANCE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" initiating rebalance (NONE) in state up (join-state wait-metadata) with 0 assigned partition(s): Metadata for subscribed topic(s) has changed %7|1701266707.634|REJOIN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": Rejoining group without an assignment: Metadata for subscribed topic(s) has changed %7|1701266707.634|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state wait-metadata -> init (state up) %7|1701266707.635|JOIN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": join with 1 subscribed topic(s) %7|1701266707.635|CGRPMETADATA|sim-ordotest2#consumer-1| [thrd:main]: consumer join: metadata for subscription is up to date (5ms old) %7|1701266707.636|JOIN|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/0: Joining group "sim-ordotest2" with 1 subscribed topic(s) and member id "" %7|1701266707.636|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state init -> wait-join (state up) %7|1701266710.715|JOINGROUP|sim-ordotest2#consumer-1| [thrd:main]: JoinGroup response: GenerationId 119, Protocol range, LeaderId hidden.url.windows.net:c:sim-ordotest2:I:sim-ordotest2-2c7926c5667f4186b64c0ab44e2206fe (me), my MemberId hidden.url.windows.net:c:sim-ordotest2:I:sim-ordotest2-2c7926c5667f4186b64c0ab44e2206fe, member metadata count 1: (no error) %7|1701266710.715|MEMBERID|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": updating member id "" -> "hidden.url.windows.net:c:sim-ordotest2:I:sim-ordotest2-2c7926c5667f4186b64c0ab44e2206fe" %7|1701266710.716|JOINGROUP|sim-ordotest2#consumer-1| [thrd:main]: I am elected leader for group "sim-ordotest2" with 1 member(s) %7|1701266710.716|GRPLEADER|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": resetting group leader info: JoinGroup response clean-up %7|1701266710.716|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state wait-join -> wait-metadata (state up) %7|1701266710.752|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" running range assignor for 1 member(s) and 1 eligible subscribed topic(s): %7|1701266710.752|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Member "hidden.url.windows.net:c:sim-ordotest2:I:sim-ordotest2-2c7926c5667f4186b64c0ab44e2206fe" (me) with 0 owned partition(s) and 1 subscribed topic(s): %7|1701266710.752|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: test2 [-1] %7|1701266710.753|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: range: Topic test2 with 2 partition(s) and 1 subscribing member(s), single-topic non-rack-aware assignment for 2 leftover partitions %7|1701266710.753|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" range assignment for 1 member(s) finished in 0.905ms: %7|1701266710.753|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Member "hidden.url.windows.net:c:sim-ordotest2:I:sim-ordotest2-2c7926c5667f4186b64c0ab44e2206fe" (me) assigned 2 partition(s): %7|1701266710.753|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] %7|1701266710.753|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] %7|1701266710.753|ASSIGNOR|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": "range" assignor run for 1 member(s) %7|1701266710.754|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state wait-metadata -> wait-sync (state up) %7|1701266710.867|SYNCGROUP|sim-ordotest2#consumer-1| [thrd:main]: SyncGroup response: Success (29 bytes of MemberState data) %7|1701266710.867|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266710.867|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset INVALID %7|1701266710.867|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset INVALID %7|1701266710.868|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state wait-sync -> wait-assign-call (state up) %7|1701266710.869|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": delegating assign of 2 partition(s) to application on queue rd_kafka_cgrp_new: new assignment %7|1701266710.869|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": setting group assignment to 2 partition(s) %7|1701266710.870|GRPASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266710.870|GRPASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset INVALID %7|1701266710.870|GRPASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset INVALID %7|1701266710.871|HEARTBEAT|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Heartbeat for group "sim-ordotest2" generation id 119 Timestamp="2023-11-29 15:05:10,887" Message="Partition assigned: :TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}, custom_offset:{} partition: 0 offset: -1001 error: None" keyType="KAFKA" keyValue="PARTITION_ASSIGNED" Application="TTCR" Component="TTCR-Scheduler" From="SIM" LogLevel="INFO" %7|1701266710.903|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op OFFSET_FETCH in state up (join-state wait-assign-call) %7|1701266710.904|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Group sim-ordotest2 OffsetFetchRequest(v7) for 1/1 partition(s) %7|1701266710.905|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Fetch committed offsets for 1/1 partition(s) %7|1701266710.950|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: Topic test2 [0]: setting default offset INVALID (leader epoch -1) Timestamp="2023-11-29 15:05:10,966" Message="Partition assigned: :TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}, custom_offset:{TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}: [TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}]} partition: 1 offset: -1001 error: None" keyType="KAFKA" keyValue="PARTITION_ASSIGNED" Application="TTCR" Component="TTCR-Scheduler" From="SIM" LogLevel="INFO" %7|1701266710.981|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op OFFSET_FETCH in state up (join-state wait-assign-call) %7|1701266710.982|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Group sim-ordotest2 OffsetFetchRequest(v7) for 1/1 partition(s) %7|1701266710.983|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Fetch committed offsets for 1/1 partition(s) %7|1701266711.026|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: Topic test2 [1]: setting default offset INVALID (leader epoch -1) %7|1701266711.043|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op GET_REBALANCE_PROTOCOL in state up (join-state wait-assign-call) %7|1701266711.043|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op ASSIGN in state up (join-state wait-assign-call) %7|1701266711.044|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": new assignment of 2 partition(s) in join-state wait-assign-call %7|1701266711.045|CLEARASSIGN|sim-ordotest2#consumer-1| [thrd:main]: No current assignment to clear %7|1701266711.048|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: Added 2 partition(s) to assignment which now consists of 2 partition(s) where of 2 are in pending state and 0 are being queried %7|1701266711.049|PAUSE|sim-ordotest2#consumer-1| [thrd:main]: Resuming fetchers for 2 assigned partition(s): assign called %7|1701266711.048|TOPBRK|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Topic test2 [0]: joining broker (rktp 0000018C8E89ABC0, 0 message(s) queued) %7|1701266711.049|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state wait-assign-call -> steady (state up) %7|1701266711.050|DUMP|sim-ordotest2#consumer-1| [thrd:main]: Assignment dump (started_cnt=0, wait_stop_cnt=0) %7|1701266711.051|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266711.051|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset STORED %7|1701266711.050|TOPBRK|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Topic test2 [1]: joining broker (rktp 0000018C8E8965C0, 0 message(s) queued) %7|1701266711.052|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset STORED %7|1701266711.053|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266711.054|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset STORED %7|1701266711.054|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset STORED %7|1701266711.054|DUMP_QRY|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.055|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.055|SRVPEND|sim-ordotest2#consumer-1| [thrd:main]: Querying committed offset for pending assigned partition test2 [1] %7|1701266711.056|SRVPEND|sim-ordotest2#consumer-1| [thrd:main]: Querying committed offset for pending assigned partition test2 [0] %7|1701266711.056|OFFSETFETCH|sim-ordotest2#consumer-1| [thrd:main]: Fetching committed offsets for 2 pending partition(s) in assignment %7|1701266711.057|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Group sim-ordotest2 OffsetFetchRequest(v7) for 2/2 partition(s) %7|1701266711.057|OFFSET|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Fetch committed offsets for 2/2 partition(s) %7|1701266711.058|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: Current assignment of 2 partition(s) with 2 pending adds, 2 offset queries, 0 partitions awaiting stop and 0 offset commits in progress %7|1701266711.091|OFFSETFETCH|sim-ordotest2#consumer-1| [thrd:main]: Adding test2 [0] back to pending list with offset 12286 %7|1701266711.091|OFFSETFETCH|sim-ordotest2#consumer-1| [thrd:main]: Adding test2 [1] back to pending list with offset INVALID %7|1701266711.092|DUMP|sim-ordotest2#consumer-1| [thrd:main]: Assignment dump (started_cnt=0, wait_stop_cnt=0) %7|1701266711.093|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266711.096|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset STORED %7|1701266711.097|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset STORED %7|1701266711.097|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266711.098|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset 12286 %7|1701266711.098|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset INVALID %7|1701266711.099|DUMP_QRY|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.099|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.100|SRVPEND|sim-ordotest2#consumer-1| [thrd:main]: Starting pending assigned partition test2 [1] at offset INVALID (leader epoch -1) %7|1701266711.100|SRVPEND|sim-ordotest2#consumer-1| [thrd:main]: Starting pending assigned partition test2 [0] at offset 12286 (leader epoch -1) %7|1701266711.101|ASSIGNDONE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": assignment operations done in join-state steady (rebalance rejoin=false) %7|1701266711.102|FETCH|sim-ordotest2#consumer-1| [thrd:main]: Partition test2 [0] start fetching at offset 12286 (leader epoch -1) %7|1701266711.102|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op PARTITION_JOIN in state up (join-state steady) for test2 [1] %7|1701266711.103|PARTADD|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": add test2 [1] %7|1701266711.104|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op PARTITION_JOIN in state up (join-state steady) for test2 [0] %7|1701266711.104|PARTADD|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": add test2 [0] %7|1701266711.377|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op GET_ASSIGNMENT in state up (join-state steady) %7|1701266711.408|CLOSE|sim-ordotest2#consumer-1| [thrd:app]: Closing consumer %7|1701266711.408|CLOSE|sim-ordotest2#consumer-1| [thrd:app]: Waiting for close events %7|1701266711.408|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op TERMINATE in state up (join-state steady) %7|1701266711.413|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Terminating group "sim-ordotest2" in state up with 2 partition(s) %7|1701266711.414|UNSUBSCRIBE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": unsubscribe from current subscription of size 1 (leave group=true, has joined=true, hidden.url.windows.net:c:sim-ordotest2:I:sim-ordotest2-2c7926c5667f4186b64c0ab44e2206fe, join-state steady) %7|1701266711.414|SUBSCRIPTION|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": clearing subscribed topics list (1) %7|1701266711.415|SUBSCRIPTION|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": effective subscription list changed from 1 to 0 topic(s): %7|1701266711.416|GRPLEADER|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": resetting group leader info: unsubscribe %7|1701266711.416|REBALANCE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" initiating rebalance (EAGER) in state up (join-state steady) with 2 assigned partition(s): unsubscribe %7|1701266711.416|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state steady -> wait-unassign-call (state up) %7|1701266711.417|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": delegating revoke of 2 partition(s) to application on queue rd_kafka_consumer_close: unsubscribe %7|1701266711.417|PAUSE|sim-ordotest2#consumer-1| [thrd:main]: Pausing fetchers for 2 assigned partition(s): rebalance %7|1701266711.418|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": clearing group assignment %7|1701266711.419|DUMP|sim-ordotest2#consumer-1| [thrd:main]: Assignment dump (started_cnt=2, wait_stop_cnt=0) %7|1701266711.420|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266711.420|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset STORED %7|1701266711.421|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset STORED %7|1701266711.422|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.422|DUMP_QRY|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.423|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.428|ASSIGNDONE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": assignment operations done in join-state wait-unassign-call (rebalance rejoin=false) %7|1701266711.428|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for assign call, 2 toppar(s), 0 commit(s) (state up, join-state wait-unassign-call) before terminating %7|1701266711.429|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for assign call, 2 toppar(s), 0 commit(s) (state up, join-state wait-unassign-call) before terminating %7|1701266711.429|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for assign call, 2 toppar(s), 0 commit(s) (state up, join-state wait-unassign-call) before terminating Timestamp="2023-11-29 15:05:11,423" Message="Partition revoked: :TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}, custom_offset:{TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}: [TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}], TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}: [TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}]} partition: 0 offset: -1001 error: None" keyType="KAFKA" keyValue="PARTITION_REVOKED" Application="TTCR" Component="TTCR-Scheduler" From="SIM" LogLevel="INFO" Timestamp="2023-11-29 15:05:11,439" Message="Partition revoked: :TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}, custom_offset:{TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}: [TopicPartition{topic=test2,partition=%I32d,offset=%s,leader_epoch=%s,error=%s}]} partition: 1 offset: -1001 error: None" keyType="KAFKA" keyValue="PARTITION_REVOKED" Application="TTCR" Component="TTCR-Scheduler" From="SIM" LogLevel="INFO" %7|1701266711.454|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op GET_REBALANCE_PROTOCOL in state up (join-state wait-unassign-call) %7|1701266711.455|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for assign call, 2 toppar(s), 0 commit(s) (state up, join-state wait-unassign-call) before terminating %7|1701266711.455|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op ASSIGN in state up (join-state wait-unassign-call) %7|1701266711.458|ASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": Consumer is terminating: treating assign as unassign %7|1701266711.459|CLEARASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Clearing current assignment of 2 partition(s) %7|1701266711.459|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state wait-unassign-call -> wait-unassign-to-complete (state up) %7|1701266711.460|DUMP|sim-ordotest2#consumer-1| [thrd:main]: Assignment dump (started_cnt=2, wait_stop_cnt=0) %7|1701266711.460|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.461|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.461|DUMP_QRY|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.462|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: List with 2 partition(s): %7|1701266711.462|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: test2 [0] offset STORED %7|1701266711.463|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: test2 [1] offset STORED %7|1701266711.463|REMOVE|sim-ordotest2#consumer-1| [thrd:main]: Removing test2 [0] from assignment (started=true, pending=false, queried=false, stored offset=12287) %7|1701266711.463|REMOVE|sim-ordotest2#consumer-1| [thrd:main]: Removing test2 [1] from assignment (started=true, pending=false, queried=false, stored offset=INVALID) %7|1701266711.464|REMOVE|sim-ordotest2#consumer-1| [thrd:main]: Served 2 removed partition(s), with 1 offset(s) to commit %7|1701266711.464|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: Current assignment of 0 partition(s) with 0 pending adds, 0 offset queries, 2 partitions awaiting stop and 0 offset commits in progress %7|1701266711.464|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for 2 toppar(s), assignment in progress, 0 commit(s) (state up, join-state wait-unassign-to-complete) before terminating %7|1701266711.465|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for 2 toppar(s), assignment in progress, 0 commit(s) (state up, join-state wait-unassign-to-complete) before terminating %7|1701266711.465|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op PARTITION_LEAVE in state up (join-state wait-unassign-to-complete) for test2 [0] %7|1701266711.465|PARTDEL|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": delete test2 [0] %7|1701266711.466|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for 1 toppar(s), assignment in progress, 0 commit(s) (state up, join-state wait-unassign-to-complete) before terminating %7|1701266711.466|CGRPOP|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" received op PARTITION_LEAVE in state up (join-state wait-unassign-to-complete) for test2 [1] %7|1701266711.467|PARTDEL|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": delete test2 [1] %7|1701266711.467|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for 0 toppar(s), assignment in progress, 0 commit(s) (state up, join-state wait-unassign-to-complete) before terminating %7|1701266711.467|STOPSERVE|sim-ordotest2#consumer-1| [thrd:main]: All partitions awaiting stop are now stopped: serving assignment %7|1701266711.468|DUMP|sim-ordotest2#consumer-1| [thrd:main]: Assignment dump (started_cnt=0, wait_stop_cnt=0) %7|1701266711.468|DUMP_ALL|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.468|DUMP_PND|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.469|DUMP_QRY|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.469|DUMP_REM|sim-ordotest2#consumer-1| [thrd:main]: List with 0 partition(s): %7|1701266711.470|ASSIGNDONE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": assignment operations done in join-state wait-unassign-to-complete (rebalance rejoin=false) %7|1701266711.474|UNASSIGN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": unassign done in state up (join-state wait-unassign-to-complete) %7|1701266711.474|MEMBERID|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": updating member id "hidden.url.windows.net:c:sim-ordotest2:I:sim-ordotest2-2c7926c5667f4186b64c0ab44e2206fe" -> "" %7|1701266711.475|LEAVE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": leave (in state up) %7|1701266711.475|LEAVE|sim-ordotest2#consumer-1| [thrd:main]: sasl_ssl://hidden.url.windows.net:9093/0: Leaving group %7|1701266711.476|NOREJOIN|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": Not rejoining group without an assignment: Unassignment done: no subscribed topics %7|1701266711.476|CGRPJOINSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed join state wait-unassign-to-complete -> init (state up) %7|1701266711.477|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": waiting for 0 toppar(s), 0 commit(s), wait-leave, (state up, join-state init) before terminating %7|1701266711.509|LEAVEGROUP|sim-ordotest2#consumer-1| [thrd:main]: LeaveGroup response received in state up %7|1701266711.509|CGRPSTATE|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" changed state up -> term (join-state init) %7|1701266711.511|ASSIGNMENT|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2": clearing group assignment %7|1701266711.511|COORDCLEAR|sim-ordotest2#consumer-1| [thrd:main]: Group "sim-ordotest2" broker sasl_ssl://hidden.url.windows.net:9093/0 is no longer coordinator %7|1701266711.513|NODENAME|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Broker nodename changed from "hidden.url.windows.net:9093" to "" %7|1701266711.514|NODEID|sim-ordotest2#consumer-1| [thrd:main]: GroupCoordinator/0: Broker nodeid changed from 0 to -1 %7|1701266711.514|CGRPTERM|sim-ordotest2#consumer-1| [thrd:main]: Consumer group sub-system terminated (will enqueue reply) %7|1701266711.516|FAIL|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Closing connection due to nodename change (after 3917ms in state UP) (_TRANSPORT) %7|1701266711.516|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state UP -> DOWN %7|1701266711.516|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state DOWN -> INIT %7|1701266711.516|CLOSE|sim-ordotest2#consumer-1| [thrd:app]: Consumer closed %7|1701266711.519|DESTROY|sim-ordotest2#consumer-1| [thrd:app]: Terminating instance (destroy flags none (0x0)) %7|1701266711.517|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state INIT -> TRY_CONNECT %7|1701266711.519|DESTROY|sim-ordotest2#consumer-1| [thrd:main]: Destroy internal %7|1701266711.520|DESTROY|sim-ordotest2#consumer-1| [thrd:main]: Removing all topics %7|1701266711.520|DESTROY|sim-ordotest2#consumer-1| [thrd:main]: Sending TERMINATE to sasl_ssl://hidden.url.windows.net:9093/0 %7|1701266711.521|DESTROY|sim-ordotest2#consumer-1| [thrd:main]: Sending TERMINATE to GroupCoordinator %7|1701266711.520|TOPBRK|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Topic test2 [0]: leaving broker (0 messages in xmitq, next broker (none), rktp 0000018C8E89ABC0) %7|1701266711.522|TOPBRK|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Topic test2 [0]: no next broker, failing 0 message(s) in partition queue %7|1701266711.522|TOPBRK|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Topic test2 [1]: leaving broker (0 messages in xmitq, next broker (none), rktp 0000018C8E8965C0) %7|1701266711.521|TERM|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Received TERMINATE op in state TRY_CONNECT: 2 refcnts, 0 toppar(s), 0 active toppar(s), 0 outbufs, 0 waitresps, 0 retrybufs %7|1701266711.521|TERM|sim-ordotest2#consumer-1| [thrd::0/internal]: :0/internal: Received TERMINATE op in state INIT: 2 refcnts, 0 toppar(s), 0 active toppar(s), 0 outbufs, 0 waitresps, 0 retrybufs %7|1701266711.522|TOPBRK|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Topic test2 [1]: no next broker, failing 0 message(s) in partition queue %7|1701266711.524|TERM|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Received TERMINATE op in state UP: 8 refcnts, 0 toppar(s), 0 active toppar(s), 0 outbufs, 4 waitresps, 0 retrybufs %7|1701266711.524|FAIL|sim-ordotest2#consumer-1| [thrd::0/internal]: :0/internal: Client is terminating (after 4584ms in state INIT) (_DESTROY) %7|1701266711.525|STATE|sim-ordotest2#consumer-1| [thrd::0/internal]: :0/internal: Broker changed state INIT -> DOWN %7|1701266711.525|BRKTERM|sim-ordotest2#consumer-1| [thrd::0/internal]: :0/internal: terminating: broker still has 2 refcnt(s), 0 buffer(s), 0 partition(s) %7|1701266711.526|TERMINATE|sim-ordotest2#consumer-1| [thrd::0/internal]: :0/internal: Handle is terminating in state DOWN: 1 refcnts (0000018C8E8A1860), 0 toppar(s), 0 active toppar(s), 0 outbufs, 0 waitresps, 0 retrybufs: failed 0 request(s) in retry+outbuf %7|1701266711.526|FAIL|sim-ordotest2#consumer-1| [thrd::0/internal]: :0/internal: Broker handle is terminating (after 0ms in state DOWN) (_DESTROY) %7|1701266711.523|FAIL|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Client is terminating (after 3ms in state TRY_CONNECT) (_DESTROY) %7|1701266711.527|STATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state TRY_CONNECT -> DOWN %7|1701266711.527|BRKTERM|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: terminating: broker still has 2 refcnt(s), 0 buffer(s), 0 partition(s) %7|1701266711.527|CONNECT|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: broker in state DOWN connecting %7|1701266711.527|CONNECT|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: broker has no address yet: postponing connect %7|1701266711.528|TERMINATE|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Handle is terminating in state DOWN: 1 refcnts (0000018C8E90C620), 0 toppar(s), 0 active toppar(s), 0 outbufs, 0 waitresps, 0 retrybufs: failed 0 request(s) in retry+outbuf %7|1701266711.524|FAIL|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Client is terminating (after 4165ms in state UP) (_DESTROY) %7|1701266711.528|FAIL|sim-ordotest2#consumer-1| [thrd:GroupCoordinator]: GroupCoordinator: Broker handle is terminating (after 1ms in state DOWN) (_DESTROY) %7|1701266711.529|STATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Broker changed state UP -> DOWN %7|1701266711.529|REQERR|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: ListOffsetsRequest failed: Local: Broker handle destroyed: actions Permanent %7|1701266711.529|REQERR|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: ListOffsetsRequest failed: Local: Broker handle destroyed: actions Permanent %7|1701266711.530|BRKTERM|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: terminating: broker still has 2 refcnt(s), 0 buffer(s), 0 partition(s) %7|1701266711.530|TERMINATE|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Handle is terminating in state DOWN: 1 refcnts (0000018C8E895C80), 0 toppar(s), 0 active toppar(s), 0 outbufs, 0 waitresps, 0 retrybufs: failed 0 request(s) in retry+outbuf %7|1701266711.531|FAIL|sim-ordotest2#consumer-1| [thrd:sasl_ssl://hidden.url.windows.net:9093/bootstrap]: sasl_ssl://hidden.url.windows.net:9093/0: Broker handle is terminating (after 1ms in state DOWN) (_DESTROY) %7|1701266711.537|MEMBERID|sim-ordotest2#consumer-1| [thrd:app]: Group "sim-ordotest2": updating member id "" -> "(not-set)"
Click here for Azur Event Hub OperationnalLog attached { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "187f2a61-442c-4c33-9c02-06a878aaec36", "requestId": "FE0E1152EBBC0B05000000050B1DB179_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "Join.Start", "clientId": "sim-ordotest2", "message": "Start join group for new member: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, groupInstanceId: , current group size: 0, API version: 5, session timeout: 60000ms, rebalance timeout: 600000ms.", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:53.401 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "cbca64ad-ee34-4d74-9bf3-b2f3f379003b", "requestId": "FE0E1152EBBC0B05000000050B1DB179_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "SetState", "clientId": "sim-ordotest2", "message": "groupId: sim-ordotest2, requesting memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, current state: Down, new state: Joining, gen:117, consumer count: 0", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:53.401 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "00000000-0000-0000-0000-000000000000", "requestId": "FE0E1152EBBC0B05000000050B1DB179_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "SetState", "clientId": "sim-ordotest2", "message": "groupId: sim-ordotest2, requesting memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, current state: Joining, new state: Balancing, gen:117, consumer count: 1", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:56.401 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "00000000-0000-0000-0000-000000000000", "requestId": "FE0E1152EBBC0B05000000050B1DB179_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "Join.Complete", "clientId": "sim-ordotest2", "message": "Join request completed for client sim-ordotest2, on generation 118, memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, groupInstanceId: , with leader hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab. Final group size: 1", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:56.401 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "09cba289-61f0-4da4-903c-12c4cdadf35b", "requestId": "FE0E1152EBBC0E03000000070B1DB17C_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "Sync.Start", "clientId": "sim-ordotest2", "message": "Start sync for member memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, groupInstanceId: , for generation 118, currently at generation 118, group size: 1", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:56.557 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "09cba289-61f0-4da4-903c-12c4cdadf35b", "requestId": "FE0E1152EBBC0E03000000070B1DB17C_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "SetState", "clientId": "sim-ordotest2", "message": "groupId: sim-ordotest2, requesting memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, current state: Balancing, new state: Stable, gen:118, consumer count: 1", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:56.557 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "09cba289-61f0-4da4-903c-12c4cdadf35b", "requestId": "FE0E1152EBBC0E03000000070B1DB17C_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "Sync.Complete", "clientId": "sim-ordotest2", "message": "memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, groupInstanceId: Sync completed. 1 consumers joined sim-ordotest2 for generation 118. HasAssignmentData: True", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:56.557 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "46492075-2d0c-46a4-a297-7b5221b67096", "requestId": "FE0E1152EBBC0D010000000C0B1DB17D_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "Leave.Start", "clientId": "sim-ordotest2", "message": "memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, groupInstanceId: leave group sim-ordotest2, current generation: 118", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:57.104 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "09cba289-61f0-4da4-903c-12c4cdadf35b", "requestId": "FE0E1152EBBC0D010000000C0B1DB17D_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "Leave.Complete", "clientId": "sim-ordotest2", "message": "memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, groupInstanceId: left group sim-ordotest2, generation: 118, group size: 0", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:57.104 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "09cba289-61f0-4da4-903c-12c4cdadf35b", "requestId": "FE0E1152EBBC0D010000000C0B1DB17D_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "Leave.Reset", "clientId": "sim-ordotest2", "message": "Resetting group sim-ordotest2 at generation 118 after all consumers left. Requesting memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab. Total number of consumers that left: 1", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:57.104 PM +00:00", "category": "KafkaCoordinatorLogs"} { "Environment": "PROD", "Region": "West Europe", "ScaleUnit": "PROD-AM3-504", "TaskName": "CoordinatorInfoUserLog", "ActivityId": "09cba289-61f0-4da4-903c-12c4cdadf35b", "requestId": "FE0E1152EBBC0D010000000C0B1DB17D_sim-ordotest2", "resourceId": "/SUBSCRIPTIONS/AF9E03C5-A53C-46D2-B838-479EC365AB6B/RESOURCEGROUPS/hiddenNamespace/PROVIDERS/MICROSOFT.EVENTHUB/NAMESPACES/hiddenNamespace", "operation": "SetState", "clientId": "sim-ordotest2", "message": "groupId: sim-ordotest2, requesting memberId: hiddenNamespace.servicebus.windows.net:c:sim-ordotest2:I:sim-ordotest2-5170963daa2849d098cbcf3d109fe4ab, current state: Stable, new state: Down, gen:118, consumer count: 0", "namespaceName": "hiddenNamespace.servicebus.windows.net", "subscriptionId": "af9e03c5-a53c-46d2-b838-479ec365ab6b", "eventTimestamp": "11/29/2023 12:15:57.104 PM +00:00", "category": "KafkaCoordinatorLogs"}

How to reproduce

Unable to reproduce on demand

Checklist

Please provide the following information: