Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sometimes consumer have no partition assigned to it after rebalance #366

Closed
vtolstov opened this issue Feb 21, 2023 · 31 comments · Fixed by #384
Closed

sometimes consumer have no partition assigned to it after rebalance #366

vtolstov opened this issue Feb 21, 2023 · 31 comments · Fixed by #384
Labels
bug Something isn't working

Comments

@vtolstov
Copy link
Contributor

vtolstov commented Feb 21, 2023

i'm try latest 1.12.1 and older 1.4.2 both have the same effect
kafka 2.4 and i cant upgrade it

  1. i have 48-60 partitions in topic and all pods consumes messages.
  2. i have 48-60 pods
  3. i'm run helm upgrade to all pods that consumes from this topic
  4. most of the pods consumes successful but some of them have no partitions assigned
  5. picture looks like 40 partitions have consumers, and some partitions does not have any consumers.
  6. my debug on says that this consumer id does not have any partition assigments
  7. if i'm restart such pods - all works fine
@twmb
Copy link
Owner

twmb commented Feb 21, 2023

Would you be able to capture the info level logs of the consumer leader during rebalance? It currently logs the assignment it is giving to all members, so if the assignment looks correct, then something about the members is broken.

@twmb twmb added the waiting label Feb 22, 2023
@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 22, 2023

im add debug to OnAssigned
and saw
{"level":"debug","@timestamp":"2023-02-21T15:17:57.574+0300","caller":"[email protected]/util.go:85","msg":"[kgo] assigned map[string][]int32{}"}
so consumer have no partitions...

logs from leader contains this messages

prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d{notify.v3[6]}, prod-5a8523a0-e0ff-4086-af95-78f680707a11{notify.v3[16]}, prod-833b1385-4433-43e6-95fd-5d22c53fe36a{notify.v3[24 25]}, prod-bec4095c-8fff-406e-bab0-888b274b7599{notify.v3[13 40]}, prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea{notify.v3[8 37]}, prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d{notify.v3[1]}, prod-377b682e-335c-4bab-974f-25b2467bd45f{notify.v3[19]}, prod-ba944249-fbc5-46c3-a57c-7edb9dcbe25a{}, prod-c038aab5-46da-4d0b-be62-78476ce5f2f4{}, prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f{notify.v3[15 34]}, prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204{}, prod-21324d70-b1fc-44b5-91e2-d493d618b02a{}, prod-4b988e95-184f-413e-b6db-a1222cfa0a21{}, prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5{notify.v3[20 42]}, prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d{}, prod-ded4db59-deb9-49b9-97ab-b04f459acde2{notify.v3[10 39]}, prod-49321a12-bd30-484d-9d35-159d693e95d7{notify.v3[4]}, prod-e8b6365b-75c4-4c3c-90be-259a9eac449d{}, prod-575c17bc-d78a-4ad7-aef9-1a38b332a916{}, prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6{notify.v3[11 12]}, prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628{notify.v3[3 31]}, prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975{}, prod-cfe31e81-952a-42be-b1e0-ea5a31d238fc{}, prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af{notify.v3[7 30]}, prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9{notify.v3[17 44]}, prod-f9b53533-0bff-403f-b3ed-8c12711a17d4{notify.v3[21 47]}, prod-26e5bbe3-645e-4fa2-bcd5-82f93ccd7c40{}, prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56{notify.v3[2]}, prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158{notify.v3[9]}, prod-3ad691d8-1311-4cfe-8705-7488c62db865{notify.v3[23]}, prod-7de0b455-683e-4c79-9e62-9f93cd5a8170{notify.v3[22 46]}, prod-02ece2b4-28d5-43bc-8921-746b089c0128{notify.v3[0]}, prod-0b294f5c-9f78-4566-856b-39bc8e255912{notify.v3[18]}, prod-58698f86-8bff-4d24-a4fd-e9cc8049771b{notify.v3[14]}, prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9{notify.v3[5 35]}

as you see many consumers does not have any assigned partitions....
between successful case then all consumers have assigned partitions and logs from above - spent only 1 minute.

@vtolstov
Copy link
Contributor Author

i can create some workaround for such case like OnAssigned check how much partitions assigned to consumer and if no - restart pod, but this is looks very ugly.

@twmb
Copy link
Owner

twmb commented Feb 22, 2023

What is the full log from the leader?

@twmb
Copy link
Owner

twmb commented Feb 22, 2023

And the few logs before that -- particularly, log lines that contain "interests".

@vtolstov
Copy link
Contributor Author

i dont have any lines contains word interests

@vtolstov
Copy link
Contributor Author

Feb 21, 2023 @ 15:14:54.270	{"level":"info","@timestamp":"2023-02-21T15:14:54.270+0300","caller":"logger/logger.go:108","msg":"[kgo] connected to to kafka cluster version unknown custom version at least v2.7"}
Feb 21, 2023 @ 15:14:54.270	{"level":"info","ts":1676981694.2704318,"caller":"logger/zap.go:138","msg":"Broker [kgo] Connected to vm-kafka-ump04p.mbrd.ru:9092,vm-kafka-ump02p.mbrd.ru:9092,vm-kafka-ump05p.mbrd.ru:9092,vm-kafka-ump03p.mbrd.ru:9092,vm-kafka-ump01p.mbrd.ru:9092,vm-kafka-ump06p.mbrd.ru:9092"}
Feb 21, 2023 @ 15:14:54.270	{"level":"info","ts":1676981694.270906,"caller":"logger/zap.go:138","msg":"Register [memory] Registering node: pullers-553328c9-1c7e-4fa7-a503-e88474d619cd"}
Feb 21, 2023 @ 15:14:54.271	{"level":"info","ts":1676981694.2715344,"caller":"[email protected]/kgo.go:317","msg":"beginning autocommit loop","group":"pullstandby"}
Feb 21, 2023 @ 15:14:54.271	{"level":"info","ts":1676981694.271024,"caller":"logger/zap.go:138","msg":"Subscribing to topic: notify.v3"}
Feb 21, 2023 @ 15:14:54.271	{"level":"info","ts":1676981694.2717695,"caller":"[email protected]/kgo.go:317","msg":"immediate metadata update triggered","why":"querying metadata for consumer initialization"}
Feb 21, 2023 @ 15:14:54.333	{"level":"info","ts":1676981694.3337176,"caller":"[email protected]/kgo.go:317","msg":"beginning to manage the group lifecycle","group":"pullstandby"}
Feb 21, 2023 @ 15:14:54.333	{"level":"info","ts":1676981694.333772,"caller":"[email protected]/kgo.go:317","msg":"joining group","group":"pullstandby"}
Feb 21, 2023 @ 15:14:54.365	{"level":"info","ts":1676981694.3655846,"caller":"[email protected]/kgo.go:317","msg":"join returned MemberIDRequired, rejoining with response's MemberID","group":"pullstandby"}
Feb 21, 2023 @ 15:14:57.257	{"level":"info","ts":1676981697.2577465,"caller":"[email protected]/kgo.go:317","msg":"joined","group":"pullstandby","member_id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d","instance_id":"<nil>"}
Feb 21, 2023 @ 15:14:57.257	{"level":"info","ts":1676981697.257798,"caller":"[email protected]/kgo.go:317","msg":"syncing","group":"pullstandby","protocol_type":"consumer"}
Feb 21, 2023 @ 15:14:57.267	{"level":"info","ts":1676981697.2673867,"caller":"[email protected]/kgo.go:317","msg":"synced","group":"pullstandby"}
Feb 21, 2023 @ 15:14:57.267	{"level":"info","ts":1676981697.2675006,"caller":"[email protected]/kgo.go:317","msg":"beginning heartbeat loop","group":"pullstandby"}
Feb 21, 2023 @ 15:15:33.271	{"level":"info","ts":1676981733.2709644,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","why":"revoking all assignments because we are not cooperative","how":"unassigning everything"}
Feb 21, 2023 @ 15:15:33.271	{"level":"info","ts":1676981733.2710292,"caller":"[email protected]/kgo.go:317","msg":"immediate metadata update triggered","why":"waitmeta after heartbeat error"}
Feb 21, 2023 @ 15:15:33.271	{"level":"info","ts":1676981733.2708793,"caller":"[email protected]/kgo.go:317","msg":"heartbeat errored","group":"pullstandby"}
Feb 21, 2023 @ 15:15:33.271	{"level":"info","ts":1676981733.270993,"caller":"[email protected]/kgo.go:317","msg":"eager consumer revoking prior assigned partitions","group":"pullstandby"}
Feb 21, 2023 @ 15:15:33.281	{"level":"info","ts":1676981733.2810307,"caller":"[email protected]/kgo.go:317","msg":"joining group","group":"pullstandby"}
Feb 21, 2023 @ 15:16:12.285	{"level":"info","ts":1676981772.284892,"caller":"[email protected]/kgo.go:317","msg":"syncing","group":"pullstandby","protocol_type":"consumer"}
Feb 21, 2023 @ 15:16:12.285	{"level":"info","ts":1676981772.28486,"caller":"[email protected]/kgo.go:317","msg":"joined","member_id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d","instance_id":"<nil>","group":"pullstandby"}
Feb 21, 2023 @ 15:16:57.284	{"level":"info","ts":1676981817.2846646,"caller":"[email protected]/kgo.go:317","msg":"sync failed with RebalanceInProgress, rejoining","group":"pullstandby"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.30417,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042185,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-58698f86-8bff-4d24-a4fd-e9cc8049771b"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.304335,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.304017,"caller":"[email protected]/kgo.go:317","msg":"joined, balancing group","group":"pullstandby","member_id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d","instance_id":"<nil>"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042026,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3043272,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-ded4db59-deb9-49b9-97ab-b04f459acde2"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3041825,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-377b682e-335c-4bab-974f-25b2467bd45f"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3044817,"caller":"[email protected]/kgo.go:317","msg":"syncing","protocol_type":"consumer","group":"pullstandby"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3041124,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-02ece2b4-28d5-43bc-8921-746b089c0128"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3040483,"caller":"[email protected]/kgo.go:317","msg":"balancing group as leader"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3041382,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-0b294f5c-9f78-4566-856b-39bc8e255912"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042254,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-5a8523a0-e0ff-4086-af95-78f680707a11"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.304345,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-f9b53533-0bff-403f-b3ed-8c12711a17d4"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3044434,"caller":"[email protected]/kgo.go:317","msg":"balanced","plan":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d{notify.v3[1 32]}, prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56{notify.v3[2 33]}, prod-49321a12-bd30-484d-9d35-159d693e95d7{notify.v3[4 27]}, prod-ded4db59-deb9-49b9-97ab-b04f459acde2{notify.v3[10 39]}, prod-bec4095c-8fff-406e-bab0-888b274b7599{notify.v3[13 40]}, prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158{notify.v3[9 36]}, prod-3ad691d8-1311-4cfe-8705-7488c62db865{notify.v3[23 41]}, prod-58698f86-8bff-4d24-a4fd-e9cc8049771b{notify.v3[14 38]}, prod-7de0b455-683e-4c79-9e62-9f93cd5a8170{notify.v3[22 46]}, prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6{notify.v3[11 12]}, prod-833b1385-4433-43e6-95fd-5d22c53fe36a{notify.v3[24 25]}, prod-0b294f5c-9f78-4566-856b-39bc8e255912{notify.v3[18 43]}, prod-377b682e-335c-4bab-974f-25b2467bd45f{notify.v3[19 45]}, prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d{notify.v3[6 29]}, prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5{notify.v3[20 42]}, prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9{notify.v3[5 35]}, prod-f9b53533-0bff-403f-b3ed-8c12711a17d4{notify.v3[21 47]}, prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9{notify.v3[17 44]}, prod-02ece2b4-28d5-43bc-8921-746b089c0128{notify.v3[0 28]}, prod-5a8523a0-e0ff-4086-af95-78f680707a11{notify.v3[16 26]}, prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628{notify.v3[3 31]}, prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af{notify.v3[7 30]}, prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f{notify.v3[15 34]}, prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea{notify.v3[8 37]}"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3041494,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042834,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.30429,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042755,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042355,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.304317,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.30419,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ad691d8-1311-4cfe-8705-7488c62db865"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3043098,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042095,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-49321a12-bd30-484d-9d35-159d693e95d7"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3041267,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.304266,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-833b1385-4433-43e6-95fd-5d22c53fe36a"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042986,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-bec4095c-8fff-406e-bab0-888b274b7599"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042552,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6"}
Feb 21, 2023 @ 15:16:57.304	{"level":"info","ts":1676981817.3042426,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7de0b455-683e-4c79-9e62-9f93cd5a8170"}
Feb 21, 2023 @ 15:16:57.347	{"level":"info","ts":1676981817.3467789,"caller":"[email protected]/kgo.go:317","msg":"synced","group":"pullstandby"}
Feb 21, 2023 @ 15:16:57.347	{"level":"info","ts":1676981817.3469324,"caller":"[email protected]/kgo.go:317","msg":"beginning heartbeat loop","group":"pullstandby"}
Feb 21, 2023 @ 15:16:57.359	{"level":"info","ts":1676981817.3595927,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","why":"newly fetched offsets for group pullstandby","how":"assigning everything new, keeping current assignment"}
Feb 21, 2023 @ 15:16:57.359	{"level":"info","ts":1676981817.359679,"caller":"[email protected]/kgo.go:317","msg":"metadata update triggered","why":"loading offsets in new session from assign"}
Feb 21, 2023 @ 15:16:57.450	{"level":"info","ts":1676981817.4502654,"caller":"[email protected]/kgo.go:317","msg":"producing to a new topic for the first time, fetching metadata to learn its partitions","topic":"deposit.v3"}
Feb 21, 2023 @ 15:16:57.450	{"level":"info","ts":1676981817.4502497,"caller":"[email protected]/kgo.go:317","msg":"immediate metadata update triggered","why":"forced load because we are producing to a new topic for the first time"}
Feb 21, 2023 @ 15:16:57.465	{"level":"info","ts":1676981817.4653776,"caller":"[email protected]/kgo.go:317","msg":"done waiting for metadata for new topic","topic":"deposit.v3"}
Feb 21, 2023 @ 15:16:57.485	{"level":"info","ts":1676981817.4654515,"caller":"[email protected]/kgo.go:317","msg":"skipping producer id initialization because the client was configured to disable idempotent writes"}
Feb 21, 2023 @ 15:16:57.526	{"level":"info","ts":1676981817.526676,"caller":"[email protected]/kgo.go:317","msg":"producing to a new topic for the first time, fetching metadata to learn its partitions","topic":"loanind.v3"}
Feb 21, 2023 @ 15:16:57.526	{"level":"info","ts":1676981817.5263426,"caller":"[email protected]/kgo.go:317","msg":"immediate metadata update triggered","why":"forced load because we are producing to a new topic for the first time"}
Feb 21, 2023 @ 15:16:57.535	{"level":"info","ts":1676981817.5350637,"caller":"[email protected]/kgo.go:317","msg":"done waiting for metadata for new topic","topic":"loanind.v3"}
Feb 21, 2023 @ 15:17:51.349	{"level":"info","ts":1676981871.349017,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","why":"revoking all assignments because we are not cooperative","how":"unassigning everything"}
Feb 21, 2023 @ 15:17:51.349	{"level":"info","ts":1676981871.3489091,"caller":"[email protected]/kgo.go:317","msg":"heartbeat errored","group":"pullstandby"}
Feb 21, 2023 @ 15:17:51.349	{"level":"info","ts":1676981871.3494205,"caller":"[email protected]/kgo.go:317","msg":"eager consumer revoking prior assigned partitions","group":"pullstandby"}
Feb 21, 2023 @ 15:17:51.349	{"level":"info","ts":1676981871.349047,"caller":"[email protected]/kgo.go:317","msg":"immediate metadata update triggered","why":"waitmeta after heartbeat error"}
Feb 21, 2023 @ 15:17:51.354	{"level":"info","ts":1676981871.3544266,"caller":"[email protected]/kgo.go:317","msg":"joining group","group":"pullstandby"}
Feb 21, 2023 @ 15:17:51.385	{"level":"info","ts":1676981871.3858058,"caller":"[email protected]/kgo.go:317","msg":"joined, balancing group","group":"pullstandby","member_id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d","instance_id":"<nil>"}
Feb 21, 2023 @ 15:17:51.385	{"level":"info","ts":1676981871.385856,"caller":"[email protected]/kgo.go:317","msg":"balancing group as leader"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860447,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860624,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-377b682e-335c-4bab-974f-25b2467bd45f"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3861804,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7de0b455-683e-4c79-9e62-9f93cd5a8170"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3863373,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3859587,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-02ece2b4-28d5-43bc-8921-746b089c0128"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.386253,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3862703,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.386307,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-bec4095c-8fff-406e-bab0-888b274b7599"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3863227,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-cfe31e81-952a-42be-b1e0-ea5a31d238fc"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3863907,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3864048,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-f9b53533-0bff-403f-b3ed-8c12711a17d4"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3859935,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860722,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ad691d8-1311-4cfe-8705-7488c62db865"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860955,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-49321a12-bd30-484d-9d35-159d693e95d7"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3861215,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-575c17bc-d78a-4ad7-aef9-1a38b332a916"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.38616,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-5a8523a0-e0ff-4086-af95-78f680707a11"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3862925,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3862998,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-ba944249-fbc5-46c3-a57c-7edb9dcbe25a"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3863294,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3863976,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e8b6365b-75c4-4c3c-90be-259a9eac449d"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3865516,"caller":"[email protected]/kgo.go:317","msg":"balanced","plan":"prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d{notify.v3[6]}, prod-5a8523a0-e0ff-4086-af95-78f680707a11{notify.v3[16]}, prod-833b1385-4433-43e6-95fd-5d22c53fe36a{notify.v3[24 25]}, prod-bec4095c-8fff-406e-bab0-888b274b7599{notify.v3[13 40]}, prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea{notify.v3[8 37]}, prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d{notify.v3[1]}, prod-377b682e-335c-4bab-974f-25b2467bd45f{notify.v3[19]}, prod-ba944249-fbc5-46c3-a57c-7edb9dcbe25a{}, prod-c038aab5-46da-4d0b-be62-78476ce5f2f4{}, prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f{notify.v3[15 34]}, prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204{}, prod-21324d70-b1fc-44b5-91e2-d493d618b02a{}, prod-4b988e95-184f-413e-b6db-a1222cfa0a21{}, prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5{notify.v3[20 42]}, prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d{}, prod-ded4db59-deb9-49b9-97ab-b04f459acde2{notify.v3[10 39]}, prod-49321a12-bd30-484d-9d35-159d693e95d7{notify.v3[4]}, prod-e8b6365b-75c4-4c3c-90be-259a9eac449d{}, prod-575c17bc-d78a-4ad7-aef9-1a38b332a916{}, prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6{notify.v3[11 12]}, prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628{notify.v3[3 31]}, prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975{}, prod-cfe31e81-952a-42be-b1e0-ea5a31d238fc{}, prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af{notify.v3[7 30]}, prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9{notify.v3[17 44]}, prod-f9b53533-0bff-403f-b3ed-8c12711a17d4{notify.v3[21 47]}, prod-26e5bbe3-645e-4fa2-bcd5-82f93ccd7c40{}, prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56{notify.v3[2]}, prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158{notify.v3[9]}, prod-3ad691d8-1311-4cfe-8705-7488c62db865{notify.v3[23]}, prod-7de0b455-683e-4c79-9e62-9f93cd5a8170{notify.v3[22 46]}, prod-02ece2b4-28d5-43bc-8921-746b089c0128{notify.v3[0]}, prod-0b294f5c-9f78-4566-856b-39bc8e255912{notify.v3[18]}, prod-58698f86-8bff-4d24-a4fd-e9cc8049771b{notify.v3[14]}, prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9{notify.v3[5 35]}"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3866107,"caller":"[email protected]/kgo.go:317","msg":"syncing","group":"pullstandby","protocol_type":"consumer"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.386002,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-0b294f5c-9f78-4566-856b-39bc8e255912"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860116,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-21324d70-b1fc-44b5-91e2-d493d618b02a"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860838,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.386146,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-58698f86-8bff-4d24-a4fd-e9cc8049771b"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3861706,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3861935,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3862157,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-833b1385-4433-43e6-95fd-5d22c53fe36a"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3864126,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860204,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-26e5bbe3-645e-4fa2-bcd5-82f93ccd7c40"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3860323,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3861074,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-4b988e95-184f-413e-b6db-a1222cfa0a21"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3862393,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.386315,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-c038aab5-46da-4d0b-be62-78476ce5f2f4"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.3863697,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea"}
Feb 21, 2023 @ 15:17:51.386	{"level":"info","ts":1676981871.386383,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-ded4db59-deb9-49b9-97ab-b04f459acde2"}
Feb 21, 2023 @ 15:17:51.397	{"level":"info","ts":1676981871.3976204,"caller":"[email protected]/kgo.go:317","msg":"synced","group":"pullstandby"}
Feb 21, 2023 @ 15:17:51.398	{"level":"info","ts":1676981871.397773,"caller":"[email protected]/kgo.go:317","msg":"beginning heartbeat loop","group":"pullstandby"}
Feb 21, 2023 @ 15:17:51.400	{"level":"info","ts":1676981871.400127,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","how":"assigning everything new, keeping current assignment","why":"newly fetched offsets for group pullstandby"}
Feb 21, 2023 @ 15:17:54.400	{"level":"info","ts":1676981874.4004445,"caller":"[email protected]/kgo.go:317","msg":"heartbeat errored","group":"pullstandby"}
Feb 21, 2023 @ 15:17:54.400	{"level":"info","ts":1676981874.400545,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","why":"revoking all assignments because we are not cooperative","how":"unassigning everything"}
Feb 21, 2023 @ 15:17:54.400	{"level":"info","ts":1676981874.4005287,"caller":"[email protected]/kgo.go:317","msg":"immediate metadata update triggered","why":"waitmeta after heartbeat error"}
Feb 21, 2023 @ 15:17:54.400	{"level":"info","ts":1676981874.4006095,"caller":"[email protected]/kgo.go:317","msg":"eager consumer revoking prior assigned partitions","group":"pullstandby"}
Feb 21, 2023 @ 15:17:54.404	{"level":"info","ts":1676981874.404544,"caller":"[email protected]/kgo.go:317","msg":"joining group","group":"pullstandby"}
Feb 21, 2023 @ 15:17:54.460	{"level":"info","ts":1676981874.4604058,"caller":"[email protected]/kgo.go:317","msg":"joined, balancing group","group":"pullstandby","member_id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d","instance_id":"<nil>"}
Feb 21, 2023 @ 15:17:54.460	{"level":"info","ts":1676981874.4604352,"caller":"[email protected]/kgo.go:317","msg":"balancing group as leader"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4614685,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e072e17c-73be-4501-8c0d-18d08c0767b3"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.460966,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4611008,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-5a8523a0-e0ff-4086-af95-78f680707a11"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.461164,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-833b1385-4433-43e6-95fd-5d22c53fe36a"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4612005,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4613202,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-bec4095c-8fff-406e-bab0-888b274b7599"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4609036,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4609542,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-26e5bbe3-645e-4fa2-bcd5-82f93ccd7c40"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4613624,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-cfe31e81-952a-42be-b1e0-ea5a31d238fc"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4611216,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7de0b455-683e-4c79-9e62-9f93cd5a8170"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4617505,"caller":"[email protected]/kgo.go:317","msg":"syncing","group":"pullstandby","protocol_type":"consumer"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4612508,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4609933,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4611537,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4613745,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4610183,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4612792,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4610915,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-58698f86-8bff-4d24-a4fd-e9cc8049771b"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4615252,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4610007,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-377b682e-335c-4bab-974f-25b2467bd45f"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.461484,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e8b6365b-75c4-4c3c-90be-259a9eac449d"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4610837,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-575c17bc-d78a-4ad7-aef9-1a38b332a916"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4616852,"caller":"[email protected]/kgo.go:317","msg":"balanced","plan":"prod-377b682e-335c-4bab-974f-25b2467bd45f{notify.v3[19]}, prod-833b1385-4433-43e6-95fd-5d22c53fe36a{notify.v3[24 25]}, prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628{notify.v3[3 31]}, prod-c038aab5-46da-4d0b-be62-78476ce5f2f4{notify.v3[43]}, prod-cfe31e81-952a-42be-b1e0-ea5a31d238fc{notify.v3[45]}, prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d{}, prod-26e5bbe3-645e-4fa2-bcd5-82f93ccd7c40{notify.v3[32]}, prod-21324d70-b1fc-44b5-91e2-d493d618b02a{notify.v3[26]}, prod-5a8523a0-e0ff-4086-af95-78f680707a11{notify.v3[16]}, prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5{notify.v3[20]}, prod-02ece2b4-28d5-43bc-8921-746b089c0128{notify.v3[0]}, prod-49321a12-bd30-484d-9d35-159d693e95d7{notify.v3[4]}, prod-4b988e95-184f-413e-b6db-a1222cfa0a21{notify.v3[36]}, prod-ded4db59-deb9-49b9-97ab-b04f459acde2{notify.v3[10 39]}, prod-3ad691d8-1311-4cfe-8705-7488c62db865{notify.v3[23]}, prod-bec4095c-8fff-406e-bab0-888b274b7599{notify.v3[13 40]}, prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f{notify.v3[15 34]}, prod-e8b6365b-75c4-4c3c-90be-259a9eac449d{notify.v3[28]}, prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d{notify.v3[6]}, prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea{notify.v3[8 37]}, prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af{notify.v3[7 30]}, prod-7de0b455-683e-4c79-9e62-9f93cd5a8170{notify.v3[22 46]}, prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9{notify.v3[5 35]}, prod-ba944249-fbc5-46c3-a57c-7edb9dcbe25a{notify.v3[38]}, prod-e072e17c-73be-4501-8c0d-18d08c0767b3{notify.v3[27]}, prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d{notify.v3[1]}, prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6{notify.v3[11 12]}, prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975{notify.v3[33]}, prod-f9b53533-0bff-403f-b3ed-8c12711a17d4{notify.v3[21 47]}, prod-575c17bc-d78a-4ad7-aef9-1a38b332a916{notify.v3[41]}, prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56{notify.v3[2]}, prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158{notify.v3[9]}, prod-58698f86-8bff-4d24-a4fd-e9cc8049771b{notify.v3[14]}, prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9{notify.v3[17 44]}, prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204{notify.v3[29]}, prod-0b294f5c-9f78-4566-856b-39bc8e255912{notify.v3[18]}"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4608798,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-02ece2b4-28d5-43bc-8921-746b089c0128"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4609122,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-0b294f5c-9f78-4566-856b-39bc8e255912"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.461267,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4610326,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-49321a12-bd30-484d-9d35-159d693e95d7"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.461065,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-4b988e95-184f-413e-b6db-a1222cfa0a21"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4611106,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4614923,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-f9b53533-0bff-403f-b3ed-8c12711a17d4"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4610107,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ad691d8-1311-4cfe-8705-7488c62db865"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4613965,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-ded4db59-deb9-49b9-97ab-b04f459acde2"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4609416,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-21324d70-b1fc-44b5-91e2-d493d618b02a"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4613461,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-c038aab5-46da-4d0b-be62-78476ce5f2f4"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4613822,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4612858,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-ba944249-fbc5-46c3-a57c-7edb9dcbe25a"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4614766,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9"}
Feb 21, 2023 @ 15:17:54.461	{"level":"info","ts":1676981874.4613893,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea"}
Feb 21, 2023 @ 15:17:54.468	{"level":"info","ts":1676981874.468329,"caller":"[email protected]/kgo.go:317","msg":"synced","group":"pullstandby"}
Feb 21, 2023 @ 15:17:54.468	{"level":"info","ts":1676981874.4688773,"caller":"[email protected]/kgo.go:317","msg":"beginning heartbeat loop","group":"pullstandby"}
Feb 21, 2023 @ 15:17:54.470	{"level":"info","ts":1676981874.4707584,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","why":"newly fetched offsets for group pullstandby","how":"assigning everything new, keeping current assignment"}
Feb 21, 2023 @ 15:17:57.471	{"level":"info","ts":1676981877.4710164,"caller":"[email protected]/kgo.go:317","msg":"heartbeat errored","group":"pullstandby"}
Feb 21, 2023 @ 15:17:57.471	{"level":"info","ts":1676981877.471338,"caller":"[email protected]/kgo.go:317","msg":"eager consumer revoking prior assigned partitions","group":"pullstandby"}
Feb 21, 2023 @ 15:17:57.471	{"level":"info","ts":1676981877.4712567,"caller":"[email protected]/kgo.go:317","msg":"immediate metadata update triggered","why":"waitmeta after heartbeat error"}
Feb 21, 2023 @ 15:17:57.471	{"level":"info","ts":1676981877.4710898,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","why":"revoking all assignments because we are not cooperative","how":"unassigning everything"}
Feb 21, 2023 @ 15:17:57.472	{"level":"info","ts":1676981877.4728072,"caller":"[email protected]/kgo.go:317","msg":"joining group","group":"pullstandby"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5646768,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-21324d70-b1fc-44b5-91e2-d493d618b02a"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5646863,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-26e5bbe3-645e-4fa2-bcd5-82f93ccd7c40"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5647068,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5647333,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5647428,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-49321a12-bd30-484d-9d35-159d693e95d7"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.564715,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-377b682e-335c-4bab-974f-25b2467bd45f"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.564474,"caller":"[email protected]/kgo.go:317","msg":"joined, balancing group","group":"pullstandby","member_id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d","instance_id":"<nil>"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5646613,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5646691,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-0b294f5c-9f78-4566-856b-39bc8e255912"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5646963,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5645642,"caller":"[email protected]/kgo.go:317","msg":"balancing group as leader"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.564648,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-02ece2b4-28d5-43bc-8921-746b089c0128"}
Feb 21, 2023 @ 15:17:57.564	{"level":"info","ts":1676981877.5647254,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ad691d8-1311-4cfe-8705-7488c62db865"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5647702,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-58698f86-8bff-4d24-a4fd-e9cc8049771b"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649824,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e8b6365b-75c4-4c3c-90be-259a9eac449d"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5647533,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-4b988e95-184f-413e-b6db-a1222cfa0a21"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.564763,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-575c17bc-d78a-4ad7-aef9-1a38b332a916"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5648007,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7de0b455-683e-4c79-9e62-9f93cd5a8170"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5648587,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-a29736b3-86cf-46f8-b2e5-9a07857f580c"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5648696,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5648909,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-bec4095c-8fff-406e-bab0-888b274b7599"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649104,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-cfe31e81-952a-42be-b1e0-ea5a31d238fc"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.564933,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649538,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-ded4db59-deb9-49b9-97ab-b04f459acde2"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.565163,"caller":"[email protected]/kgo.go:317","msg":"syncing","group":"pullstandby","protocol_type":"consumer"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.56478,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-5a8523a0-e0ff-4086-af95-78f680707a11"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5648222,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-833b1385-4433-43e6-95fd-5d22c53fe36a"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5648518,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649624,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e072e17c-73be-4501-8c0d-18d08c0767b3"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5650022,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5647905,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.564832,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.564842,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.564881,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-ba944249-fbc5-46c3-a57c-7edb9dcbe25a"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649004,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-c038aab5-46da-4d0b-be62-78476ce5f2f4"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649168,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5651197,"caller":"[email protected]/kgo.go:317","msg":"balanced","plan":"prod-21324d70-b1fc-44b5-91e2-d493d618b02a{notify.v3[26]}, prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158{notify.v3[9]}, prod-6fc9619a-bd9f-4c1b-9043-f19e0d63a6b5{notify.v3[20]}, prod-cfe31e81-952a-42be-b1e0-ea5a31d238fc{notify.v3[45]}, prod-e072e17c-73be-4501-8c0d-18d08c0767b3{notify.v3[27]}, prod-02ece2b4-28d5-43bc-8921-746b089c0128{notify.v3[0]}, prod-4b988e95-184f-413e-b6db-a1222cfa0a21{notify.v3[36]}, prod-83dfaaec-e9af-4a6c-bff4-c28c3a47b628{notify.v3[3 31]}, prod-a29736b3-86cf-46f8-b2e5-9a07857f580c{notify.v3[42]}, prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204{notify.v3[29]}, prod-575c17bc-d78a-4ad7-aef9-1a38b332a916{notify.v3[41]}, prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6{notify.v3[11 12]}, prod-e8b6365b-75c4-4c3c-90be-259a9eac449d{notify.v3[28]}, prod-f9b53533-0bff-403f-b3ed-8c12711a17d4{notify.v3[21 47]}, prod-0b294f5c-9f78-4566-856b-39bc8e255912{notify.v3[18]}, prod-274d1555-e49c-42d3-bbfd-8c3ef5886d56{notify.v3[2]}, prod-3ad691d8-1311-4cfe-8705-7488c62db865{notify.v3[23]}, prod-7de0b455-683e-4c79-9e62-9f93cd5a8170{notify.v3[22]}, prod-9508e2aa-96c5-491c-9ae1-b0a92bc0dab9{notify.v3[5 35]}, prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975{notify.v3[33]}, prod-08cdbfb5-901d-4585-b6c6-5a3cdad6dd7d{notify.v3[1]}, prod-377b682e-335c-4bab-974f-25b2467bd45f{notify.v3[19]}, prod-49321a12-bd30-484d-9d35-159d693e95d7{notify.v3[4]}, prod-5a8523a0-e0ff-4086-af95-78f680707a11{notify.v3[16]}, prod-833b1385-4433-43e6-95fd-5d22c53fe36a{notify.v3[24 25]}, prod-bec4095c-8fff-406e-bab0-888b274b7599{notify.v3[13 40]}, prod-26e5bbe3-645e-4fa2-bcd5-82f93ccd7c40{notify.v3[32]}, prod-c038aab5-46da-4d0b-be62-78476ce5f2f4{notify.v3[43]}, prod-8c2abbc6-8f0b-464a-9268-fd977eb6d7af{notify.v3[7 30]}, prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f{notify.v3[15 34]}, prod-ded4db59-deb9-49b9-97ab-b04f459acde2{notify.v3[10 39]}, prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9{notify.v3[17 44]}, prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d{notify.v3[6]}, prod-58698f86-8bff-4d24-a4fd-e9cc8049771b{notify.v3[14]}, prod-ba944249-fbc5-46c3-a57c-7edb9dcbe25a{notify.v3[38]}, prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d{}, prod-dc5f85f6-5f52-4a21-9cfd-ef8229a539ea{notify.v3[8 37]}"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.564812,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649261,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d94cdb0d-77ce-4673-81b8-6d1417ebb99f"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649729,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-e65fbff2-bee1-44bd-b651-e1b47bbed3a9"}
Feb 21, 2023 @ 15:17:57.565	{"level":"info","ts":1676981877.5649927,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-f9b53533-0bff-403f-b3ed-8c12711a17d4"}
Feb 21, 2023 @ 15:17:57.573	{"level":"info","ts":1676981877.5731091,"caller":"[email protected]/kgo.go:317","msg":"synced","group":"pullstandby"}
Feb 21, 2023 @ 15:17:57.573	{"level":"info","ts":1676981877.5733993,"caller":"[email protected]/kgo.go:317","msg":"beginning heartbeat loop","group":"pullstandby"}
Feb 21, 2023 @ 15:17:57.575	{"level":"info","ts":1676981877.575206,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","how":"assigning everything new, keeping current assignment","why":"newly fetched offsets for group pullstandby"}

@vtolstov
Copy link
Contributor Author

that's all logs from pod

@vtolstov
Copy link
Contributor Author

i'm use franz-go in framework and use this top level code https://github.com/unistack-org/micro-broker-kgo/blob/v3/util.go
but i don't think that it contains errors with consumer assignment ....

@twmb
Copy link
Owner

twmb commented Feb 23, 2023

There are multiple things confusing here.

First, the log itself includes an "interests" field,

g.cl.cfg.logger.Log(LogLevelInfo, "balance group member", "id", member.MemberID, "interests", strInterests)

this is key to seeing what all members are interested in consuming -- without these logs, I can't recreate the inputs to the balance plan. In your logs, I see this:

Feb 21, 2023 @ 15:17:54.461     {"level":"info","ts":1676981874.4609933,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-35ee4b9e-1cf5-4415-b5fa-941fdea56158"}
Feb 21, 2023 @ 15:17:54.461     {"level":"info","ts":1676981874.4611537,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-7e0c4c97-15b7-4847-873e-e4eafa964ec6"}
Feb 21, 2023 @ 15:17:54.461     {"level":"info","ts":1676981874.4613745,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-d00841bb-2e4e-4a8c-a6f4-1d0b5eb7003d"}
Feb 21, 2023 @ 15:17:54.461     {"level":"info","ts":1676981874.4610183,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-3ec4a5c0-8dc5-417d-ae63-a3d3e33dbb8d"}
Feb 21, 2023 @ 15:17:54.461     {"level":"info","ts":1676981874.4612792,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-b8fb26fc-ecdb-4d17-a5b0-b6ba971be975"}
Feb 21, 2023 @ 15:17:54.461     {"level":"info","ts":1676981874.4610915,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-58698f86-8bff-4d24-a4fd-e9cc8049771b"}
Feb 21, 2023 @ 15:17:54.461     {"level":"info","ts":1676981874.4615252,"caller":"[email protected]/kgo.go:317","msg":"balance group member","id":"prod-fcd97f8e-d213-4d0e-b593-79db0bfb1204"}

Also, in your code, I see that you're using the balancers CooperativeSticky and Sticky. If all group members are cooperative-sticky, then I shouldn't see the following log:

Feb 21, 2023 @ 15:15:33.271     {"level":"info","ts":1676981733.2709644,"caller":"[email protected]/kgo.go:317","msg":"assigning partitions","why":"revoking all assignments because we are not cooperative","how":"unassigning everything"}

Something in your group is different -- if everything is cooperative, then that log wouldn't exist.

@vtolstov
Copy link
Contributor Author

can you provide next steps for me?

@vtolstov
Copy link
Contributor Author

does interests string exists in proper place in 1.4.2 ?

@twmb
Copy link
Owner

twmb commented Feb 23, 2023

That "interests" string exists since the log line was introduced.

Please upgrade to 1.12.1, but be aware of this (the only) behavior change in 1.5.1: https://github.com/twmb/franz-go/blob/master/CHANGELOG.md#v151

@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 24, 2023

Please upgrade to 1.12.1

i'm try this version and its behaviour the same, i'm try to reproduce it with logs and sent results

@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 25, 2023

i'm use 1.12.1 and slightly modified goroutine per partition example, what does it mean in logs:

heartbeat errored again while waiting for user revoke to finish

and this

in default commit: unable to commit offsets for topic partition","group":"TestAssign","topic":"mytopic","stacktrace":"github.com/twmb/franz-go/pkg/kgo.(*wrappedLogger).Log\n\t/Users/vtolstov/go/pkg/mod/github.com/twmb/[email protected]/pkg/kgo/logger.go:123\ngithub.com/twmb/franz-go/pkg/kgo.(*groupConsumer).defaultCommitCallback\n\t/Users/vtolstov/go/pkg/mod/github.com/twmb/[email protected]/pkg/kgo/consumer_group.go:1999\ngithub.com/twmb/franz-go/pkg/kgo.(*groupConsumer).commitAcrossRebalance.func4\n\t/Users/vtolstov/go/pkg/mod/github.com/twmb/[email protected]/pkg/kgo/consumer_group.go:274

my tests contains 48 partitions in topic, about 200000 messages per partition and i'm run 8 instances of service to handle partitions. when i'm start in single instance all works fine.

if i'm start one instance that does 4 different consumers - all partitions handled fine.
i'f im start another instance that try to do another 4 different consumers - first instance stops to work with

heartbeat errored again while waiting for user revoke to finish

and this

in default commit: unable to commit offsets for topic partition","group":"TestAssign","topic":"mytopic","stacktrace":"github.com/twmb/franz-go/pkg/kgo.(*wrappedLogger).Log\n\t/Users/vtolstov/go/pkg/mod/github.com/twmb/[email protected]/pkg/kgo/logger.go:123\ngithub.com/twmb/franz-go/pkg/kgo.(*groupConsumer).defaultCommitCallback\n\t/Users/vtolstov/go/pkg/mod/github.com/twmb/[email protected]/pkg/kgo/consumer_group.go:1999\ngithub.com/twmb/franz-go/pkg/kgo.(*groupConsumer).commitAcrossRebalance.func4\n\t/Users/vtolstov/go/pkg/mod/github.com/twmb/[email protected]/pkg/kgo/consumer_group.go:274

@twmb
Copy link
Owner

twmb commented Feb 25, 2023

heartbeat errored again while waiting for user revoke to finish -- what's the rest of the log line? The log line is this:

915:			g.cfg.logger.Log(LogLevelInfo, "heartbeat errored again while waiting for user revoke to finish", "group", g.cfg.group, "err", err)

What's the rest of the unable to commit message?

1999                                 g.cfg.logger.Log(LogLevelError, "in default commit: unable to commit offsets for topic partition",
2000                                         "group", g.cfg.group,
2001                                         "topic", topic.Topic,
2002                                         "partition", partition.Partition,
2003                                         "error", err)

Both of these are missing the error field. It's impossible to help if the output is truncated.

@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 26, 2023

sorry my logger eats messages:

[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 1, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 13, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 21, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 25, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 29, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 33, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 37, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member

and

[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.

@vtolstov
Copy link
Contributor Author

but i'm not restart old consumer , why coordinator is not aware of it

@twmb
Copy link
Owner

twmb commented Feb 27, 2023

So, it looks like you're taking so long to process records (or finish the rebalance callbacks) that the broker is kicking your member from the group.

@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 27, 2023 via email

@twmb
Copy link
Owner

twmb commented Feb 27, 2023

Could you add a prefix func to the basic formatter,

func() string { return time.Now().Format(time. StampMilli) }

And then post some of the logs? That may help see if something is taking too long (not sure what, yet)

@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 27, 2023

Feb 27 09:17:05.883[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.883[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.883[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.883[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.886[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 46.459µs, time_to_read: 21.058916ms, err: <nil>
Feb 27 09:17:05.886[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.886[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.922[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 63, read_wait: 33.875µs, time_to_read: 56.203583ms, err: <nil>
Feb 27 09:17:05.922[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 55.568375ms, time_to_read: 6.292µs, err: <nil>
Feb 27 09:17:05.922[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.922[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:05.922[DEBUG] updated committed; group: TestAssign, to: mytopic[20{308727=>308744}, 37{329136=>329157}, 47{305262=>305279}]
Feb 27 09:17:05.947[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 17.534542ms, time_to_read: 63.545667ms, err: <nil>
Feb 27 09:17:05.947[DEBUG] updated committed; group: TestAssign, to: mytopic[5{349834=>349852}]
Feb 27 09:17:05.947[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 17.31875ms, time_to_read: 63.823583ms, err: <nil>
Feb 27 09:17:05.947[DEBUG] updated committed; group: TestAssign, to: mytopic[34{310129=>310150}]
Feb 27 09:17:05.947[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 20.033875ms, time_to_read: 61.369333ms, err: <nil>
Feb 27 09:17:05.947[DEBUG] updated committed; group: TestAssign, to: mytopic[23{348198=>348215}]
Feb 27 09:17:06.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:06.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:06.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:06.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 349875}]]
Feb 27 09:17:06.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310170}]]
Feb 27 09:17:06.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:06.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348238}]]
Feb 27 09:17:06.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 28.541µs, time_to_write: 131µs, err: <nil>
Feb 27 09:17:06.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 27.792µs, time_to_write: 41µs, err: <nil>
Feb 27 09:17:06.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 44.625µs, time_to_write: 216.375µs, err: <nil>
Feb 27 09:17:06.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308763} 37:{163 329176} 47:{179 305298}]]
Feb 27 09:17:06.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 498, write_wait: 25.75µs, time_to_write: 33.459µs, err: <nil>
{"level":"debug","@timestamp":"2023-02-27T09:17:06.890+0300","caller":"broker-kgo/subscriber.go:162","msg":"killing, topic mytopic partition 37"}
Feb 27 09:17:06.923[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 48.458µs, time_to_read: 57.025917ms, err: <nil>
Feb 27 09:17:06.923[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 190.209µs, time_to_read: 56.988416ms, err: <nil>
Feb 27 09:17:06.924[DEBUG] updated committed; group: TestAssign, to: mytopic[34{310150=>310170}]
Feb 27 09:17:06.923[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 63, read_wait: 37.125µs, time_to_read: 56.9675ms, err: <nil>
Feb 27 09:17:06.924[DEBUG] updated committed; group: TestAssign, to: mytopic[20{308744=>308763}, 37{329157=>329176}, 47{305279=>305298}]
Feb 27 09:17:06.924[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 42.5µs, time_to_read: 57.15825ms, err: <nil>
Feb 27 09:17:06.924[DEBUG] updated committed; group: TestAssign, to: mytopic[23{348215=>348238}]
Feb 27 09:17:06.924[DEBUG] updated committed; group: TestAssign, to: mytopic[5{349852=>349875}]
Feb 27 09:17:07.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:07.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:07.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 349894}]]
Feb 27 09:17:07.867[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308784} 37:{163 329177} 47:{179 305323}]]
Feb 27 09:17:07.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:07.867[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348258}]]
Feb 27 09:17:07.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 24.708µs, time_to_write: 54.292µs, err: <nil>
Feb 27 09:17:07.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 498, write_wait: 32.291µs, time_to_write: 149.625µs, err: <nil>
Feb 27 09:17:07.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:07.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 48.625µs, time_to_write: 262.958µs, err: <nil>
Feb 27 09:17:07.867[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310188}]]
Feb 27 09:17:07.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 22.292µs, time_to_write: 33.917µs, err: <nil>
Feb 27 09:17:07.918[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 56.958µs, time_to_read: 50.599375ms, err: <nil>
Feb 27 09:17:07.918[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 87.625µs, time_to_read: 50.682875ms, err: <nil>
Feb 27 09:17:07.918[DEBUG] updated committed; group: TestAssign, to: mytopic[5{349875=>349894}]
Feb 27 09:17:07.918[DEBUG] updated committed; group: TestAssign, to: mytopic[23{348238=>348258}]
Feb 27 09:17:07.918[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 48.666µs, time_to_read: 50.532459ms, err: <nil>
Feb 27 09:17:07.918[DEBUG] updated committed; group: TestAssign, to: mytopic[34{310170=>310188}]
Feb 27 09:17:07.919[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 63, read_wait: 125.209µs, time_to_read: 52.373625ms, err: <nil>
Feb 27 09:17:07.919[DEBUG] updated committed; group: TestAssign, to: mytopic[20{308763=>308784}, 37{329176=>329177}, 47{305298=>305323}]
Feb 27 09:17:08.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:08.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:08.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 124.667µs, time_to_write: 73.541µs, err: <nil>
Feb 27 09:17:08.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 138.291µs, time_to_write: 35.375µs, err: <nil>
Feb 27 09:17:08.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:08.865[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 239.917µs, time_to_write: 133.083µs, err: <nil>
Feb 27 09:17:08.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:08.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:08.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:08.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 349910}]]
Feb 27 09:17:08.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308806} 47:{179 305350}]]
Feb 27 09:17:08.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 66.709µs, time_to_write: 47.208µs, err: <nil>
Feb 27 09:17:08.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 23.417µs, time_to_write: 27.041µs, err: <nil>
Feb 27 09:17:08.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:08.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348284}]]
Feb 27 09:17:08.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310210}]]
Feb 27 09:17:08.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 16µs, time_to_write: 33.5µs, err: <nil>
Feb 27 09:17:08.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:08.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 19.875µs, time_to_write: 22.167µs, err: <nil>
Feb 27 09:17:08.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 150.083µs, time_to_write: 31.292µs, err: <nil>
Feb 27 09:17:08.884[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 49.375µs, time_to_read: 19.503167ms, err: <nil>
Feb 27 09:17:08.884[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 113.709µs, time_to_read: 20.322958ms, err: <nil>
Feb 27 09:17:08.885[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.885[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.885[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.885[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.885[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 76.667µs, time_to_read: 20.655083ms, err: <nil>
Feb 27 09:17:08.885[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.885[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.984[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 18.794292ms, time_to_read: 99.465833ms, err: <nil>
Feb 27 09:17:08.984[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 18.020458ms, time_to_read: 99.48575ms, err: <nil>
Feb 27 09:17:08.984[DEBUG] updated committed; group: TestAssign, to: mytopic[23{348258=>348284}]
Feb 27 09:17:08.984[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 18.641959ms, time_to_read: 99.204ms, err: <nil>
Feb 27 09:17:08.984[DEBUG] updated committed; group: TestAssign, to: mytopic[34{310188=>310210}]
Feb 27 09:17:08.984[DEBUG] updated committed; group: TestAssign, to: mytopic[5{349894=>349910}]
Feb 27 09:17:08.998[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 41.708µs, time_to_read: 131.84625ms, err: <nil>
Feb 27 09:17:08.998[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 131.469375ms, time_to_read: 16.625µs, err: <nil>
Feb 27 09:17:08.998[DEBUG] heartbeat complete; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.998[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: REBALANCE_IN_PROGRESS: The group is rebalancing, so a rejoin is needed.
Feb 27 09:17:08.998[DEBUG] updated committed; group: TestAssign, to: mytopic[20{308784=>308806}, 47{305323=>305350}]
Feb 27 09:17:09.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:09.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:09.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348304}]]
Feb 27 09:17:09.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 349931}]]
Feb 27 09:17:09.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:09.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 36.416µs, time_to_write: 129.75µs, err: <nil>
Feb 27 09:17:09.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 37.375µs, time_to_write: 179.792µs, err: <nil>
Feb 27 09:17:09.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:09.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310231}]]
Feb 27 09:17:09.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308831} 47:{179 305370}]]
Feb 27 09:17:09.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 17.334µs, time_to_write: 29.208µs, err: <nil>
Feb 27 09:17:09.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 15.084µs, time_to_write: 34.833µs, err: <nil>
Feb 27 09:17:09.956[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 32.75µs, time_to_read: 90.064667ms, err: <nil>
Feb 27 09:17:09.956[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 107.625µs, time_to_read: 89.875792ms, err: <nil>
Feb 27 09:17:09.956[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 266.584µs, time_to_read: 89.893125ms, err: <nil>
Feb 27 09:17:09.956[DEBUG] updated committed; group: TestAssign, to: mytopic[23{348284=>348304}]
Feb 27 09:17:09.956[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 127.042µs, time_to_read: 89.785375ms, err: <nil>
Feb 27 09:17:09.956[DEBUG] updated committed; group: TestAssign, to: mytopic[34{310210=>310231}]
Feb 27 09:17:09.956[DEBUG] updated committed; group: TestAssign, to: mytopic[20{308806=>308831}, 47{305350=>305370}]
Feb 27 09:17:09.956[DEBUG] updated committed; group: TestAssign, to: mytopic[5{349910=>349931}]
Feb 27 09:17:10.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:10.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:10.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:10.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310251}]]
Feb 27 09:17:10.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:10.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308850} 47:{179 305390}]]
Feb 27 09:17:10.867[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348328}]]
Feb 27 09:17:10.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 48.625µs, time_to_write: 144.416µs, err: <nil>
Feb 27 09:17:10.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 25.042µs, time_to_write: 101µs, err: <nil>
Feb 27 09:17:10.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 26.958µs, time_to_write: 58.417µs, err: <nil>
Feb 27 09:17:10.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 349949}]]
Feb 27 09:17:10.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 46.917µs, time_to_write: 34.042µs, err: <nil>
Feb 27 09:17:10.982[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 70.875µs, time_to_read: 115.402875ms, err: <nil>
Feb 27 09:17:10.982[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 86.209µs, time_to_read: 115.464458ms, err: <nil>
Feb 27 09:17:10.982[DEBUG] updated committed; group: TestAssign, to: mytopic[34{310231=>310251}]
Feb 27 09:17:10.982[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 124.041µs, time_to_read: 115.442209ms, err: <nil>
Feb 27 09:17:10.982[DEBUG] updated committed; group: TestAssign, to: mytopic[23{348304=>348328}]
Feb 27 09:17:10.982[DEBUG] updated committed; group: TestAssign, to: mytopic[20{308831=>308850}, 47{305370=>305390}]
Feb 27 09:17:10.983[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 42.958µs, time_to_read: 115.611333ms, err: <nil>
Feb 27 09:17:10.983[DEBUG] updated committed; group: TestAssign, to: mytopic[5{349931=>349949}]
Feb 27 09:17:11.862[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:11.862[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 51.042µs, time_to_write: 68.958µs, err: <nil>
Feb 27 09:17:11.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:11.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 58µs, time_to_write: 29.917µs, err: <nil>
Feb 27 09:17:11.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:11.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 20.208µs, time_to_write: 73.667µs, err: <nil>
Feb 27 09:17:11.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:11.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348346}]]
Feb 27 09:17:11.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:11.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 30.541µs, time_to_write: 15.209µs, err: <nil>
Feb 27 09:17:11.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310273}]]
Feb 27 09:17:11.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:11.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 14.75µs, time_to_write: 14.875µs, err: <nil>
Feb 27 09:17:11.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308866} 47:{179 305413}]]
Feb 27 09:17:11.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:11.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 21.792µs, time_to_write: 16.125µs, err: <nil>
Feb 27 09:17:11.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 349970}]]
Feb 27 09:17:11.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 29.584µs, time_to_write: 80.875µs, err: <nil>
Feb 27 09:17:11.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:11.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 20.5µs, time_to_write: 16.5µs, err: <nil>
Feb 27 09:17:11.959[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 156.708µs, time_to_read: 95.2255ms, err: <nil>
Feb 27 09:17:11.959[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.959[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.959[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 62.958µs, time_to_read: 97.14275ms, err: <nil>
Feb 27 09:17:11.959[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.959[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.960[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 36.5µs, time_to_read: 94.557708ms, err: <nil>
Feb 27 09:17:11.960[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 308866, commit_epoch: 170, error_code: 25
Feb 27 09:17:11.960[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305413, commit_epoch: 179, error_code: 25
Feb 27 09:17:11.960[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:11.960[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.960[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.962[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 147.916µs, time_to_read: 97.754875ms, err: <nil>
Feb 27 09:17:11.962[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.962[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.983[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 93.715ms, time_to_read: 23.158708ms, err: <nil>
Feb 27 09:17:11.983[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 349970, commit_epoch: 183, error_code: 25
Feb 27 09:17:11.983[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:11.983[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.983[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 93.95725ms, time_to_read: 22.45225ms, err: <nil>
Feb 27 09:17:11.983[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.983[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.983[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 93.895ms, time_to_read: 23.437917ms, err: <nil>
Feb 27 09:17:11.983[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310273, commit_epoch: 167, error_code: 25
Feb 27 09:17:11.983[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:11.983[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:11.985[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 96.823833ms, time_to_read: 22.44125ms, err: <nil>
Feb 27 09:17:11.985[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348346, commit_epoch: 182, error_code: 25
Feb 27 09:17:11.985[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:11.985[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:12.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:12.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:12.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:12.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348361}]]
Feb 27 09:17:12.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 349986}]]
Feb 27 09:17:12.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:12.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 22.958µs, time_to_write: 43.917µs, err: <nil>
Feb 27 09:17:12.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310287}]]
Feb 27 09:17:12.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 19.459µs, time_to_write: 38.333µs, err: <nil>
Feb 27 09:17:12.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308886} 47:{179 305432}]]
Feb 27 09:17:12.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 14.375µs, time_to_write: 25.25µs, err: <nil>
Feb 27 09:17:12.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 9.917µs, time_to_write: 20.375µs, err: <nil>
Feb 27 09:17:12.938[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 17.958µs, time_to_read: 71.921792ms, err: <nil>
Feb 27 09:17:12.938[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 31.667µs, time_to_read: 72.033416ms, err: <nil>
Feb 27 09:17:12.938[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 308886, commit_epoch: 170, error_code: 25
Feb 27 09:17:12.938[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305432, commit_epoch: 179, error_code: 25
Feb 27 09:17:12.938[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 349986, commit_epoch: 183, error_code: 25
Feb 27 09:17:12.938[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:12.938[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:12.938[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:12.938[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 21.75µs, time_to_read: 71.998584ms, err: <nil>
Feb 27 09:17:12.938[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:12.938[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:12.938[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310287, commit_epoch: 167, error_code: 25
Feb 27 09:17:12.938[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:12.938[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:12.939[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 45.333µs, time_to_read: 72.249417ms, err: <nil>
Feb 27 09:17:12.939[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348361, commit_epoch: 182, error_code: 25
Feb 27 09:17:12.939[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:12.939[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:13.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:13.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:13.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:13.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348381}]]
Feb 27 09:17:13.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:13.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308904} 47:{179 305447}]]
Feb 27 09:17:13.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350009}]]
Feb 27 09:17:13.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 24.708µs, time_to_write: 85.292µs, err: <nil>
Feb 27 09:17:13.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 43.875µs, time_to_write: 177.958µs, err: <nil>
Feb 27 09:17:13.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 24.333µs, time_to_write: 29.334µs, err: <nil>
Feb 27 09:17:13.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310311}]]
Feb 27 09:17:13.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 17.5µs, time_to_write: 28.917µs, err: <nil>
Feb 27 09:17:13.907[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 28.333µs, time_to_read: 41.075917ms, err: <nil>
Feb 27 09:17:13.907[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 85.708µs, time_to_read: 41.311292ms, err: <nil>
Feb 27 09:17:13.907[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 308904, commit_epoch: 170, error_code: 25
Feb 27 09:17:13.907[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305447, commit_epoch: 179, error_code: 25
Feb 27 09:17:13.907[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 39.625µs, time_to_read: 41.24775ms, err: <nil>
Feb 27 09:17:13.907[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348381, commit_epoch: 182, error_code: 25
Feb 27 09:17:13.907[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:13.907[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:13.907[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:13.907[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310311, commit_epoch: 167, error_code: 25
Feb 27 09:17:13.907[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:13.907[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:13.907[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:13.907[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:13.907[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 107µs, time_to_read: 41.571916ms, err: <nil>
Feb 27 09:17:13.908[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350009, commit_epoch: 183, error_code: 25
Feb 27 09:17:13.908[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:13.908[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.862[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:14.863[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 37.042µs, time_to_write: 56.708µs, err: <nil>
Feb 27 09:17:14.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:14.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 18µs, time_to_write: 18.833µs, err: <nil>
Feb 27 09:17:14.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:14.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 12.209µs, time_to_write: 20.791µs, err: <nil>
Feb 27 09:17:14.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:14.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348399}]]
Feb 27 09:17:14.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 14.084µs, time_to_write: 23.833µs, err: <nil>
Feb 27 09:17:14.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:14.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:14.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310329}]]
Feb 27 09:17:14.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308927} 47:{179 305470}]]
Feb 27 09:17:14.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 12.042µs, time_to_write: 20.625µs, err: <nil>
Feb 27 09:17:14.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 10.666µs, time_to_write: 20.5µs, err: <nil>
Feb 27 09:17:14.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:14.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350030}]]
Feb 27 09:17:14.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 9.875µs, time_to_write: 17.667µs, err: <nil>
Feb 27 09:17:14.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:14.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 18.375µs, time_to_write: 29.75µs, err: <nil>
Feb 27 09:17:14.930[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 47.834µs, time_to_read: 67.602291ms, err: <nil>
Feb 27 09:17:14.930[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.930[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.937[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 31µs, time_to_read: 73.516125ms, err: <nil>
Feb 27 09:17:14.937[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.937[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.937[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 22.375µs, time_to_read: 71.886042ms, err: <nil>
Feb 27 09:17:14.937[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 21.584µs, time_to_read: 73.180708ms, err: <nil>
Feb 27 09:17:14.937[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 308927, commit_epoch: 170, error_code: 25
Feb 27 09:17:14.937[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305470, commit_epoch: 179, error_code: 25
Feb 27 09:17:14.937[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.937[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.937[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:14.937[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:14.937[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:15.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:15.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:15.866[DEBUG] canceling prior commit to issue another; group: TestAssign
Feb 27 09:17:15.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:15.866[DEBUG] canceling prior commit to issue another; group: TestAssign
Feb 27 09:17:15.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:15.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308952} 47:{179 305491}]]
Feb 27 09:17:15.866[DEBUG] canceling prior commit to issue another; group: TestAssign
Feb 27 09:17:15.866[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 0, read_wait: 71.8725ms, time_to_read: 928.948292ms, err: context canceled
Feb 27 09:17:15.866[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 0, read_wait: 72.119167ms, time_to_read: 928.844208ms, err: context canceled
Feb 27 09:17:15.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 19.667µs, time_to_write: 40.958µs, err: <nil>
Feb 27 09:17:15.866[DEBUG] default commit canceled; group: TestAssign
Feb 27 09:17:15.866[DEBUG] default commit canceled; group: TestAssign
Feb 27 09:17:15.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310351}]]
Feb 27 09:17:15.866[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 0, read_wait: 64.782333ms, time_to_read: 936.000375ms, err: context canceled
Feb 27 09:17:15.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348413}]]
Feb 27 09:17:15.866[DEBUG] opening connection to broker; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:15.866[DEBUG] opening connection to broker; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:15.866[DEBUG] default commit canceled; group: TestAssign
Feb 27 09:17:15.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350047}]]
Feb 27 09:17:15.866[DEBUG] opening connection to broker; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:16.021[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 71.177625ms, time_to_read: 1.083270667s, err: <nil>
Feb 27 09:17:16.021[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 154.523917ms, time_to_read: 8.333µs, err: <nil>
Feb 27 09:17:16.021[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.021[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.021[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 308952, commit_epoch: 170, error_code: 25
Feb 27 09:17:16.021[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305491, commit_epoch: 179, error_code: 25
Feb 27 09:17:16.021[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.021[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.021[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.255[DEBUG] connection opened to broker; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:16.255[DEBUG] issuing SASLHandshakeRequest; broker: 3
Feb 27 09:17:16.255[DEBUG] wrote SASLHandshake v1; broker: 3, bytes_written: 68, write_wait: 17.208µs, time_to_write: 45.875µs, err: <nil>
Feb 27 09:17:16.293[DEBUG] connection opened to broker; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:16.293[DEBUG] issuing SASLHandshakeRequest; broker: 3
Feb 27 09:17:16.293[DEBUG] wrote SASLHandshake v1; broker: 3, bytes_written: 68, write_wait: 18µs, time_to_write: 21.458µs, err: <nil>
Feb 27 09:17:16.297[DEBUG] connection opened to broker; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:16.297[DEBUG] issuing SASLHandshakeRequest; broker: 3
Feb 27 09:17:16.297[DEBUG] wrote SASLHandshake v1; broker: 3, bytes_written: 68, write_wait: 11.709µs, time_to_write: 26.291µs, err: <nil>
Feb 27 09:17:16.318[DEBUG] read SASLHandshake v1; broker: 3, bytes_read: 21, read_wait: 37.417µs, time_to_read: 62.564042ms, err: <nil>
Feb 27 09:17:16.318[DEBUG] beginning sasl authentication; broker: 3, addr: vm-kafka-ump03tn.mbrd.ru:9092, mechanism: PLAIN, authenticate: true
Feb 27 09:17:16.318[DEBUG] issuing SASLAuthenticate; broker: 3, version: 2, step: 0
Feb 27 09:17:16.318[DEBUG] wrote SASLAuthenticate v2; broker: 3, bytes_written: 89, write_wait: 22.125µs, time_to_write: 26.292µs, err: <nil>
Feb 27 09:17:16.366[DEBUG] read SASLHandshake v1; broker: 3, bytes_read: 21, read_wait: 29.375µs, time_to_read: 72.993625ms, err: <nil>
Feb 27 09:17:16.366[DEBUG] beginning sasl authentication; broker: 3, addr: vm-kafka-ump03tn.mbrd.ru:9092, mechanism: PLAIN, authenticate: true
Feb 27 09:17:16.366[DEBUG] issuing SASLAuthenticate; broker: 3, version: 2, step: 0
Feb 27 09:17:16.366[DEBUG] read SASLHandshake v1; broker: 3, bytes_read: 21, read_wait: 265.334µs, time_to_read: 69.273083ms, err: <nil>
Feb 27 09:17:16.366[DEBUG] beginning sasl authentication; broker: 3, addr: vm-kafka-ump03tn.mbrd.ru:9092, mechanism: PLAIN, authenticate: true
Feb 27 09:17:16.366[DEBUG] issuing SASLAuthenticate; broker: 3, version: 2, step: 0
Feb 27 09:17:16.366[DEBUG] wrote SASLAuthenticate v2; broker: 3, bytes_written: 89, write_wait: 23.917µs, time_to_write: 30.458µs, err: <nil>
Feb 27 09:17:16.366[DEBUG] wrote SASLAuthenticate v2; broker: 3, bytes_written: 89, write_wait: 6.417µs, time_to_write: 20.25µs, err: <nil>
Feb 27 09:17:16.443[DEBUG] read SASLAuthenticate v2; broker: 3, bytes_read: 22, read_wait: 29.25µs, time_to_read: 76.736959ms, err: <nil>
Feb 27 09:17:16.443[DEBUG] connection initialized successfully; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:16.443[DEBUG] read SASLAuthenticate v2; broker: 3, bytes_read: 22, read_wait: 33.625µs, time_to_read: 125.26175ms, err: <nil>
Feb 27 09:17:16.443[DEBUG] connection initialized successfully; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:16.444[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 577.189959ms, time_to_write: 28.041µs, err: <nil>
Feb 27 09:17:16.443[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 577.031042ms, time_to_write: 68.75µs, err: <nil>
Feb 27 09:17:16.447[DEBUG] read SASLAuthenticate v2; broker: 3, bytes_read: 22, read_wait: 18.375µs, time_to_read: 81.052208ms, err: <nil>
Feb 27 09:17:16.448[DEBUG] connection initialized successfully; addr: vm-kafka-ump03tn.mbrd.ru:9092, broker: 3
Feb 27 09:17:16.448[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 581.218792ms, time_to_write: 30.333µs, err: <nil>
Feb 27 09:17:16.504[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 290.208µs, time_to_read: 60.44225ms, err: <nil>
Feb 27 09:17:16.504[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348413, commit_epoch: 182, error_code: 25
Feb 27 09:17:16.504[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.504[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.505[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 159.75µs, time_to_read: 61.026417ms, err: <nil>
Feb 27 09:17:16.505[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310351, commit_epoch: 167, error_code: 25
Feb 27 09:17:16.505[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.505[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.510[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 132.958µs, time_to_read: 61.969334ms, err: <nil>
Feb 27 09:17:16.510[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350047, commit_epoch: 183, error_code: 25
Feb 27 09:17:16.510[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.510[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:16.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:16.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350064}]]
Feb 27 09:17:16.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:16.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348433}]]
Feb 27 09:17:16.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 5.958µs, time_to_write: 43.667µs, err: <nil>
Feb 27 09:17:16.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:16.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310370}]]
Feb 27 09:17:16.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308970} 47:{179 305511}]]
Feb 27 09:17:16.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 5.083µs, time_to_write: 10.042µs, err: <nil>
Feb 27 09:17:16.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 16.375µs, time_to_write: 44.417µs, err: <nil>
Feb 27 09:17:16.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 5.375µs, time_to_write: 10.084µs, err: <nil>
Feb 27 09:17:16.917[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 8.625µs, time_to_read: 50.630041ms, err: <nil>
Feb 27 09:17:16.917[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 308970, commit_epoch: 170, error_code: 25
Feb 27 09:17:16.917[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305511, commit_epoch: 179, error_code: 25
Feb 27 09:17:16.917[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.917[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.917[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.917[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 18.958µs, time_to_read: 51.071167ms, err: <nil>
Feb 27 09:17:16.918[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348433, commit_epoch: 182, error_code: 25
Feb 27 09:17:16.918[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.918[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.917[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 60.25µs, time_to_read: 51.089167ms, err: <nil>
Feb 27 09:17:16.918[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350064, commit_epoch: 183, error_code: 25
Feb 27 09:17:16.918[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.918[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:16.917[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 9.458µs, time_to_read: 51.097917ms, err: <nil>
Feb 27 09:17:16.918[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310370, commit_epoch: 167, error_code: 25
Feb 27 09:17:16.918[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:16.918[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.862[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:17.862[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 25.708µs, time_to_write: 47.292µs, err: <nil>
Feb 27 09:17:17.863[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:17.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 9µs, time_to_write: 13.166µs, err: <nil>
Feb 27 09:17:17.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:17.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 6.708µs, time_to_write: 12µs, err: <nil>
Feb 27 09:17:17.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:17.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348454}]]
Feb 27 09:17:17.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 8.083µs, time_to_write: 15.125µs, err: <nil>
Feb 27 09:17:17.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:17.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310392}]]
Feb 27 09:17:17.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:17.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 308993} 47:{179 305532}]]
Feb 27 09:17:17.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 19.208µs, time_to_write: 12.208µs, err: <nil>
Feb 27 09:17:17.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 6.333µs, time_to_write: 8.667µs, err: <nil>
Feb 27 09:17:17.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:17.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350085}]]
Feb 27 09:17:17.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 5.834µs, time_to_write: 16.083µs, err: <nil>
Feb 27 09:17:17.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:17.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 5.75µs, time_to_write: 10.542µs, err: <nil>
Feb 27 09:17:17.924[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 10.5µs, time_to_read: 58.286541ms, err: <nil>
Feb 27 09:17:17.924[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 308993, commit_epoch: 170, error_code: 25
Feb 27 09:17:17.924[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305532, commit_epoch: 179, error_code: 25
Feb 27 09:17:17.924[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:17.924[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.924[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.924[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 28.583µs, time_to_read: 61.621167ms, err: <nil>
Feb 27 09:17:17.924[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.924[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.924[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 29.459µs, time_to_read: 60.933375ms, err: <nil>
Feb 27 09:17:17.924[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.924[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.925[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 15.167µs, time_to_read: 60.926875ms, err: <nil>
Feb 27 09:17:17.925[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.925[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.958[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 59.258209ms, time_to_read: 33.420291ms, err: <nil>
Feb 27 09:17:17.958[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310392, commit_epoch: 167, error_code: 25
Feb 27 09:17:17.958[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:17.958[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.958[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 58.739167ms, time_to_read: 33.945583ms, err: <nil>
Feb 27 09:17:17.958[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350085, commit_epoch: 183, error_code: 25
Feb 27 09:17:17.958[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:17.958[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.958[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 59.910084ms, time_to_read: 33.173875ms, err: <nil>
Feb 27 09:17:17.958[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348454, commit_epoch: 182, error_code: 25
Feb 27 09:17:17.958[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:17.958[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.958[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 57.617ms, time_to_read: 34.607417ms, err: <nil>
Feb 27 09:17:17.958[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:17.958[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:18.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:18.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:18.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:18.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348473}]]
Feb 27 09:17:18.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310408}]]
Feb 27 09:17:18.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350108}]]
Feb 27 09:17:18.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 58.792µs, time_to_write: 49.417µs, err: <nil>
Feb 27 09:17:18.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 62.917µs, time_to_write: 35µs, err: <nil>
Feb 27 09:17:18.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:18.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309014} 47:{179 305555}]]
Feb 27 09:17:18.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 34.375µs, time_to_write: 186.917µs, err: <nil>
Feb 27 09:17:18.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 52µs, time_to_write: 41.417µs, err: <nil>
Feb 27 09:17:18.932[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 101.291µs, time_to_read: 66.137084ms, err: <nil>
Feb 27 09:17:18.932[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 50.083µs, time_to_read: 65.9965ms, err: <nil>
Feb 27 09:17:18.932[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348473, commit_epoch: 182, error_code: 25
Feb 27 09:17:18.932[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:18.932[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:18.932[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350108, commit_epoch: 183, error_code: 25
Feb 27 09:17:18.932[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:18.932[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:18.933[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 44µs, time_to_read: 66.784833ms, err: <nil>
Feb 27 09:17:18.933[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310408, commit_epoch: 167, error_code: 25
Feb 27 09:17:18.933[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:18.933[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:18.933[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 42µs, time_to_read: 66.715666ms, err: <nil>
Feb 27 09:17:18.933[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309014, commit_epoch: 170, error_code: 25
Feb 27 09:17:18.933[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305555, commit_epoch: 179, error_code: 25
Feb 27 09:17:18.933[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:18.933[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:18.933[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:19.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:19.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:19.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:19.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309037} 47:{179 305575}]]
Feb 27 09:17:19.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350123}]]
Feb 27 09:17:19.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 38.584µs, time_to_write: 128.75µs, err: <nil>
Feb 27 09:17:19.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 51.417µs, time_to_write: 186µs, err: <nil>
Feb 27 09:17:19.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:19.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310426}]]
Feb 27 09:17:19.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348492}]]
Feb 27 09:17:19.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 25.666µs, time_to_write: 49.459µs, err: <nil>
Feb 27 09:17:19.867[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 32.625µs, time_to_write: 173.542µs, err: <nil>
Feb 27 09:17:19.953[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 492.25µs, time_to_read: 85.695708ms, err: <nil>
Feb 27 09:17:19.953[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 43.833µs, time_to_read: 86.558125ms, err: <nil>
Feb 27 09:17:19.953[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309037, commit_epoch: 170, error_code: 25
Feb 27 09:17:19.953[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305575, commit_epoch: 179, error_code: 25
Feb 27 09:17:19.953[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:19.953[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348492, commit_epoch: 182, error_code: 25
Feb 27 09:17:19.953[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:19.953[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:19.953[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:19.953[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:19.953[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 129.875µs, time_to_read: 86.701083ms, err: <nil>
Feb 27 09:17:19.953[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310426, commit_epoch: 167, error_code: 25
Feb 27 09:17:19.953[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:19.953[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:19.953[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 70.916µs, time_to_read: 87.137584ms, err: <nil>
Feb 27 09:17:19.953[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350123, commit_epoch: 183, error_code: 25
Feb 27 09:17:19.953[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:19.953[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.863[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:20.863[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 59.458µs, time_to_write: 23.333µs, err: <nil>
Feb 27 09:17:20.863[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:20.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 30.292µs, time_to_write: 74.375µs, err: <nil>
Feb 27 09:17:20.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:20.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 23.5µs, time_to_write: 64.542µs, err: <nil>
Feb 27 09:17:20.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:20.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348513}]]
Feb 27 09:17:20.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:20.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310446}]]
Feb 27 09:17:20.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 22.959µs, time_to_write: 24.416µs, err: <nil>
Feb 27 09:17:20.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 16.834µs, time_to_write: 19.25µs, err: <nil>
Feb 27 09:17:20.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:20.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309054} 47:{179 305596}]]
Feb 27 09:17:20.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:20.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350144}]]
Feb 27 09:17:20.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 17.417µs, time_to_write: 35.625µs, err: <nil>
Feb 27 09:17:20.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 25.458µs, time_to_write: 29µs, err: <nil>
Feb 27 09:17:20.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:20.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 19.042µs, time_to_write: 39.833µs, err: <nil>
Feb 27 09:17:20.897[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 103.541µs, time_to_read: 32.387834ms, err: <nil>
Feb 27 09:17:20.897[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.897[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.897[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 44.458µs, time_to_read: 31.369459ms, err: <nil>
Feb 27 09:17:20.897[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309054, commit_epoch: 170, error_code: 25
Feb 27 09:17:20.897[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305596, commit_epoch: 179, error_code: 25
Feb 27 09:17:20.897[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:20.897[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.897[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.900[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 288.209µs, time_to_read: 37.341208ms, err: <nil>
Feb 27 09:17:20.900[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.900[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.904[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 54.541µs, time_to_read: 39.885875ms, err: <nil>
Feb 27 09:17:20.904[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.904[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.924[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 38.457ms, time_to_read: 20.293333ms, err: <nil>
Feb 27 09:17:20.924[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 35.040167ms, time_to_read: 23.535ms, err: <nil>
Feb 27 09:17:20.924[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310446, commit_epoch: 167, error_code: 25
Feb 27 09:17:20.924[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350144, commit_epoch: 183, error_code: 25
Feb 27 09:17:20.924[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:20.924[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.924[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:20.924[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.947[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 30.820125ms, time_to_read: 50.409792ms, err: <nil>
Feb 27 09:17:20.947[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.947[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:20.948[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 31.565209ms, time_to_read: 50.812ms, err: <nil>
Feb 27 09:17:20.948[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348513, commit_epoch: 182, error_code: 25
Feb 27 09:17:20.948[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:20.948[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
{"level":"debug","@timestamp":"2023-02-27T09:17:21.614+0300","caller":"broker-kgo/subscriber.go:162","msg":"killing, topic mytopic partition 47"}
Feb 27 09:17:21.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:21.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:21.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:21.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310465}]]
Feb 27 09:17:21.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:21.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348533}]]
Feb 27 09:17:21.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309076} 47:{179 305613}]]
Feb 27 09:17:21.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 28.084µs, time_to_write: 162.916µs, err: <nil>
Feb 27 09:17:21.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 46.583µs, time_to_write: 207.5µs, err: <nil>
Feb 27 09:17:21.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350164}]]
Feb 27 09:17:21.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 32.667µs, time_to_write: 145.833µs, err: <nil>
Feb 27 09:17:21.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 95.75µs, time_to_write: 38.875µs, err: <nil>
Feb 27 09:17:21.888[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 65.542µs, time_to_read: 21.36025ms, err: <nil>
Feb 27 09:17:21.888[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 66.834µs, time_to_read: 21.483625ms, err: <nil>
Feb 27 09:17:21.888[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348533, commit_epoch: 182, error_code: 25
Feb 27 09:17:21.888[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:21.888[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:21.888[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 157.292µs, time_to_read: 21.325042ms, err: <nil>
Feb 27 09:17:21.888[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310465, commit_epoch: 167, error_code: 25
Feb 27 09:17:21.888[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:21.888[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:21.888[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309076, commit_epoch: 170, error_code: 25
Feb 27 09:17:21.888[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:21.888[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:21.888[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:21.888[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:21.888[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 53.083µs, time_to_read: 21.678833ms, err: <nil>
Feb 27 09:17:21.889[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350164, commit_epoch: 183, error_code: 25
Feb 27 09:17:21.889[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:21.889[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:22.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:22.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:22.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350186}]]
Feb 27 09:17:22.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:22.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309092} 47:{179 305613}]]
Feb 27 09:17:22.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348555}]]
Feb 27 09:17:22.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 27.583µs, time_to_write: 41.792µs, err: <nil>
Feb 27 09:17:22.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 49.125µs, time_to_write: 142.125µs, err: <nil>
Feb 27 09:17:22.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:22.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 29.791µs, time_to_write: 133.334µs, err: <nil>
Feb 27 09:17:22.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310484}]]
Feb 27 09:17:22.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 22.875µs, time_to_write: 54.542µs, err: <nil>
Feb 27 09:17:22.885[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 184.333µs, time_to_read: 19.157958ms, err: <nil>
Feb 27 09:17:22.885[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 104.292µs, time_to_read: 19.245333ms, err: <nil>
Feb 27 09:17:22.885[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309092, commit_epoch: 170, error_code: 25
Feb 27 09:17:22.885[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:22.885[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:22.885[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:22.885[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:22.885[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350186, commit_epoch: 183, error_code: 25
Feb 27 09:17:22.885[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:22.885[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:22.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 62.541µs, time_to_read: 20.673459ms, err: <nil>
Feb 27 09:17:22.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 120.833µs, time_to_read: 20.332167ms, err: <nil>
Feb 27 09:17:22.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348555, commit_epoch: 182, error_code: 25
Feb 27 09:17:22.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:22.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:22.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310484, commit_epoch: 167, error_code: 25
Feb 27 09:17:22.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:22.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.862[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:23.862[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 103.375µs, time_to_write: 120.417µs, err: <nil>
Feb 27 09:17:23.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:23.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:23.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 152.708µs, time_to_write: 57.708µs, err: <nil>
Feb 27 09:17:23.865[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 128.417µs, time_to_write: 526.458µs, err: <nil>
Feb 27 09:17:23.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:23.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348573}]]
Feb 27 09:17:23.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 23.209µs, time_to_write: 43.708µs, err: <nil>
Feb 27 09:17:23.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:23.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:23.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309114} 47:{179 305613}]]
Feb 27 09:17:23.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350203}]]
Feb 27 09:17:23.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 32.458µs, time_to_write: 23.042µs, err: <nil>
Feb 27 09:17:23.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:23.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 21.583µs, time_to_write: 96.334µs, err: <nil>
Feb 27 09:17:23.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310506}]]
Feb 27 09:17:23.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:23.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 19.459µs, time_to_write: 22.875µs, err: <nil>
Feb 27 09:17:23.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 22.416µs, time_to_write: 21.5µs, err: <nil>
Feb 27 09:17:23.881[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 113.375µs, time_to_read: 18.611166ms, err: <nil>
Feb 27 09:17:23.881[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.881[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.884[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 638.084µs, time_to_read: 19.359541ms, err: <nil>
Feb 27 09:17:23.884[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.884[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.893[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 59.166µs, time_to_read: 27.589042ms, err: <nil>
Feb 27 09:17:23.893[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309114, commit_epoch: 170, error_code: 25
Feb 27 09:17:23.893[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:23.893[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:23.893[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.893[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.895[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 74.167µs, time_to_read: 30.035417ms, err: <nil>
Feb 27 09:17:23.895[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.895[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.899[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 15.801042ms, time_to_read: 17.906375ms, err: <nil>
Feb 27 09:17:23.899[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350203, commit_epoch: 183, error_code: 25
Feb 27 09:17:23.899[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:23.899[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.900[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 27.17075ms, time_to_read: 7.034834ms, err: <nil>
Feb 27 09:17:23.900[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.900[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.900[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 18.283208ms, time_to_read: 16.050333ms, err: <nil>
Feb 27 09:17:23.900[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310506, commit_epoch: 167, error_code: 25
Feb 27 09:17:23.900[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:23.900[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:23.901[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 29.869625ms, time_to_read: 5.723375ms, err: <nil>
Feb 27 09:17:23.901[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348573, commit_epoch: 182, error_code: 25
Feb 27 09:17:23.901[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:23.901[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:24.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:24.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:24.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:24.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309134} 47:{179 305613}]]
Feb 27 09:17:24.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350223}]]
Feb 27 09:17:24.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348595}]]
Feb 27 09:17:24.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 18.875µs, time_to_write: 27.25µs, err: <nil>
Feb 27 09:17:24.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 13.958µs, time_to_write: 23.75µs, err: <nil>
Feb 27 09:17:24.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:24.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 46.917µs, time_to_write: 25.042µs, err: <nil>
Feb 27 09:17:24.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310529}]]
Feb 27 09:17:24.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 10.458µs, time_to_write: 17.667µs, err: <nil>
Feb 27 09:17:24.886[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 27.959µs, time_to_read: 20.561375ms, err: <nil>
Feb 27 09:17:24.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350223, commit_epoch: 183, error_code: 25
Feb 27 09:17:24.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:24.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:24.886[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 78.625µs, time_to_read: 20.342458ms, err: <nil>
Feb 27 09:17:24.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310529, commit_epoch: 167, error_code: 25
Feb 27 09:17:24.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:24.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:24.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 42.125µs, time_to_read: 20.7595ms, err: <nil>
Feb 27 09:17:24.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 24.916µs, time_to_read: 20.790875ms, err: <nil>
Feb 27 09:17:24.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348595, commit_epoch: 182, error_code: 25
Feb 27 09:17:24.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309134, commit_epoch: 170, error_code: 25
Feb 27 09:17:24.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:24.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:24.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:24.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:24.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:24.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:25.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:25.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:25.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:25.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310552}]]
Feb 27 09:17:25.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348611}]]
Feb 27 09:17:25.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350242}]]
Feb 27 09:17:25.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 49.041µs, time_to_write: 144.5µs, err: <nil>
Feb 27 09:17:25.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 31.542µs, time_to_write: 181.041µs, err: <nil>
Feb 27 09:17:25.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:25.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 24.083µs, time_to_write: 36.25µs, err: <nil>
Feb 27 09:17:25.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309155} 47:{179 305613}]]
Feb 27 09:17:25.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 26.875µs, time_to_write: 47µs, err: <nil>
Feb 27 09:17:25.890[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 224.625µs, time_to_read: 24.115625ms, err: <nil>
Feb 27 09:17:25.890[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 37.5µs, time_to_read: 24.162667ms, err: <nil>
Feb 27 09:17:25.890[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350242, commit_epoch: 183, error_code: 25
Feb 27 09:17:25.890[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 75.667µs, time_to_read: 24.199208ms, err: <nil>
Feb 27 09:17:25.890[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:25.890[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348611, commit_epoch: 182, error_code: 25
Feb 27 09:17:25.890[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:25.890[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:25.890[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:25.890[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310552, commit_epoch: 167, error_code: 25
Feb 27 09:17:25.890[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:25.890[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:25.891[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 47.916µs, time_to_read: 25.052917ms, err: <nil>
Feb 27 09:17:25.891[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309155, commit_epoch: 170, error_code: 25
Feb 27 09:17:25.891[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:25.891[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:25.891[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:25.891[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.862[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:26.862[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 74.167µs, time_to_write: 141.792µs, err: <nil>
Feb 27 09:17:26.863[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:26.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 36.333µs, time_to_write: 246.459µs, err: <nil>
Feb 27 09:17:26.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:26.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:26.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:26.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310570}]]
Feb 27 09:17:26.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:26.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350267}]]
Feb 27 09:17:26.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:26.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 87.167µs, time_to_write: 514.375µs, err: <nil>
Feb 27 09:17:26.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309174} 47:{179 305613}]]
Feb 27 09:17:26.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:26.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 34.667µs, time_to_write: 197.875µs, err: <nil>
Feb 27 09:17:26.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348635}]]
Feb 27 09:17:26.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 62.083µs, time_to_write: 54.833µs, err: <nil>
Feb 27 09:17:26.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 138.292µs, time_to_write: 33.333µs, err: <nil>
Feb 27 09:17:26.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 988.042µs, time_to_write: 32.5µs, err: <nil>
Feb 27 09:17:26.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 14.834µs, time_to_write: 31.708µs, err: <nil>
Feb 27 09:17:26.881[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 1.411875ms, time_to_read: 18.009625ms, err: <nil>
Feb 27 09:17:26.881[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.881[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.881[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 46.708µs, time_to_read: 17.688042ms, err: <nil>
Feb 27 09:17:26.882[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.882[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.883[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 1.211708ms, time_to_read: 16.825959ms, err: <nil>
Feb 27 09:17:26.883[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.883[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.884[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 304.334µs, time_to_read: 17.665458ms, err: <nil>
Feb 27 09:17:26.884[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309174, commit_epoch: 170, error_code: 25
Feb 27 09:17:26.884[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:26.884[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:26.884[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.884[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.898[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 15.562458ms, time_to_read: 16.73775ms, err: <nil>
Feb 27 09:17:26.898[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350267, commit_epoch: 183, error_code: 25
Feb 27 09:17:26.898[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:26.898[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.899[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 16.577583ms, time_to_read: 16.316334ms, err: <nil>
Feb 27 09:17:26.899[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348635, commit_epoch: 182, error_code: 25
Feb 27 09:17:26.899[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:26.899[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 15.318333ms, time_to_read: 17.652667ms, err: <nil>
Feb 27 09:17:26.899[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310570, commit_epoch: 167, error_code: 25
Feb 27 09:17:26.899[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.899[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:26.899[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.900[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 17.940708ms, time_to_read: 16.156209ms, err: <nil>
Feb 27 09:17:26.900[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:26.900[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:27.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:27.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:27.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:27.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350288}]]
Feb 27 09:17:27.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:27.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309198} 47:{179 305613}]]
Feb 27 09:17:27.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 20.875µs, time_to_write: 107.208µs, err: <nil>
Feb 27 09:17:27.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310586}]]
Feb 27 09:17:27.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 44.625µs, time_to_write: 131.208µs, err: <nil>
Feb 27 09:17:27.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348653}]]
Feb 27 09:17:27.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 19.875µs, time_to_write: 26.708µs, err: <nil>
Feb 27 09:17:27.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 26.917µs, time_to_write: 33.375µs, err: <nil>
Feb 27 09:17:27.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 72.75µs, time_to_read: 21.967917ms, err: <nil>
Feb 27 09:17:27.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 69.541µs, time_to_read: 21.769917ms, err: <nil>
Feb 27 09:17:27.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348653, commit_epoch: 182, error_code: 25
Feb 27 09:17:27.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:27.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:27.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 28.167µs, time_to_read: 21.942875ms, err: <nil>
Feb 27 09:17:27.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309198, commit_epoch: 170, error_code: 25
Feb 27 09:17:27.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:27.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:27.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310586, commit_epoch: 167, error_code: 25
Feb 27 09:17:27.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:27.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:27.887[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 110.042µs, time_to_read: 21.9285ms, err: <nil>
Feb 27 09:17:27.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:27.887[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350288, commit_epoch: 183, error_code: 25
Feb 27 09:17:27.887[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:27.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:27.887[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:28.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:28.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:28.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:28.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310611}]]
Feb 27 09:17:28.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350307}]]
Feb 27 09:17:28.866[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:28.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348675}]]
Feb 27 09:17:28.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 47.334µs, time_to_write: 101.791µs, err: <nil>
Feb 27 09:17:28.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 26.166µs, time_to_write: 43.917µs, err: <nil>
Feb 27 09:17:28.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 47.541µs, time_to_write: 188.959µs, err: <nil>
Feb 27 09:17:28.866[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309220} 47:{179 305613}]]
Feb 27 09:17:28.866[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 29.542µs, time_to_write: 29.333µs, err: <nil>
Feb 27 09:17:28.890[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 168.5µs, time_to_read: 24.227334ms, err: <nil>
Feb 27 09:17:28.891[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 43.75µs, time_to_read: 24.326291ms, err: <nil>
Feb 27 09:17:28.891[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310611, commit_epoch: 167, error_code: 25
Feb 27 09:17:28.891[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:28.890[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 39.125µs, time_to_read: 24.169833ms, err: <nil>
Feb 27 09:17:28.891[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309220, commit_epoch: 170, error_code: 25
Feb 27 09:17:28.891[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:28.891[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:28.891[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:28.891[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:28.891[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:28.891[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350307, commit_epoch: 183, error_code: 25
Feb 27 09:17:28.891[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:28.891[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:28.907[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 44.333µs, time_to_read: 40.675875ms, err: <nil>
Feb 27 09:17:28.907[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348675, commit_epoch: 182, error_code: 25
Feb 27 09:17:28.907[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:28.907[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.862[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:29.863[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 94.542µs, time_to_write: 141.333µs, err: <nil>
Feb 27 09:17:29.863[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:29.863[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 35.209µs, time_to_write: 38.041µs, err: <nil>
Feb 27 09:17:29.864[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:29.864[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 29.583µs, time_to_write: 220.083µs, err: <nil>
Feb 27 09:17:29.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:29.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:29.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:29.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[5:{183 350328}]]
Feb 27 09:17:29.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[34:{167 310630}]]
Feb 27 09:17:29.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 25.5µs, time_to_write: 24.416µs, err: <nil>
Feb 27 09:17:29.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[23:{182 348698}]]
Feb 27 09:17:29.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:29.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 19.792µs, time_to_write: 23.875µs, err: <nil>
Feb 27 09:17:29.865[DEBUG] issuing commit; group: TestAssign, uncommitted: map[mytopic:map[20:{170 309240} 47:{179 305613}]]
Feb 27 09:17:29.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 294, write_wait: 31.292µs, time_to_write: 48.041µs, err: <nil>
Feb 27 09:17:29.865[DEBUG] wrote OffsetCommit v8; broker: 3, bytes_written: 396, write_wait: 20.958µs, time_to_write: 42.292µs, err: <nil>
Feb 27 09:17:29.866[DEBUG] heartbeating; group: TestAssign
Feb 27 09:17:29.866[DEBUG] wrote Heartbeat v4; broker: 3, bytes_written: 164, write_wait: 204.917µs, time_to_write: 61.916µs, err: <nil>
Feb 27 09:17:29.881[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 1.018458ms, time_to_read: 18.0585ms, err: <nil>
Feb 27 09:17:29.881[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.881[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.883[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 76.667µs, time_to_read: 19.5935ms, err: <nil>
Feb 27 09:17:29.883[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.883[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.884[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 56, read_wait: 46.917µs, time_to_read: 18.834083ms, err: <nil>
Feb 27 09:17:29.884[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 20, commit_from: 308850, commit_to: 309240, commit_epoch: 170, error_code: 25
Feb 27 09:17:29.884[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 47, commit_from: 305390, commit_to: 305613, commit_epoch: 179, error_code: 25
Feb 27 09:17:29.884[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:29.884[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 20, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.884[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 47, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.885[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 121.584µs, time_to_read: 21.095541ms, err: <nil>
Feb 27 09:17:29.885[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.885[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.901[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 16.284375ms, time_to_read: 19.389375ms, err: <nil>
Feb 27 09:17:29.901[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 17.991083ms, time_to_read: 17.72325ms, err: <nil>
Feb 27 09:17:29.901[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 5, commit_from: 349949, commit_to: 350328, commit_epoch: 183, error_code: 25
Feb 27 09:17:29.901[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:29.901[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 5, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.901[DEBUG] read OffsetCommit v8; broker: 3, bytes_read: 49, read_wait: 20.104792ms, time_to_read: 15.509125ms, err: <nil>
Feb 27 09:17:29.901[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 34, commit_from: 310251, commit_to: 310630, commit_epoch: 167, error_code: 25
Feb 27 09:17:29.901[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:29.901[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 34, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.901[WARN] unable to commit offset for topic partition; group: TestAssign, topic: mytopic, partition: 23, commit_from: 348328, commit_to: 348698, commit_epoch: 182, error_code: 25
Feb 27 09:17:29.901[DEBUG] updated committed; group: TestAssign, to: mytopic[]
Feb 27 09:17:29.901[ERROR] in default commit: unable to commit offsets for topic partition; group: TestAssign, topic: mytopic, partition: 23, error: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.908[DEBUG] read Heartbeat v4; broker: 3, bytes_read: 16, read_wait: 18.330584ms, time_to_read: 23.804125ms, err: <nil>
Feb 27 09:17:29.908[DEBUG] heartbeat complete; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:29.908[INFO] heartbeat errored again while waiting for user revoke to finish; group: TestAssign, err: UNKNOWN_MEMBER_ID: The coordinator is not aware of this member.
Feb 27 09:17:30.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:30.865[DEBUG] autocommitting; group: TestAssign
Feb 27 09:17:30.865[DEBUG] autocommitting; group: TestAssign

@vtolstov
Copy link
Contributor Author

what is the recommended size of num for PollRecords ?
I'm test - if i'm specify 10 - all works fine, if i'm specify 1000 - i have a problems described above

@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 27, 2023

also what channel size to specify? (now i'm set chan size with number of assigned partitions)


func (s *subscriber) assigned(_ context.Context, c *kgo.Client, assigned map[string][]int32) {
	for topic, partitions := range assigned {
		for _, partition := range partitions {
			pc := &consumer{
				c:         c,
				topic:     topic,
				partition: partition,

				quit:    make(chan struct{}),
				done:    make(chan struct{}),
				recs:    make(chan kgo.FetchTopicPartition, len(partitions)),
				handler: s.handler,
				kopts:   s.kopts,
				opts:    s.opts,
			}
			s.consumers[tp{topic, partition}] = pc
			go pc.consume()
		}
	}
}

@vtolstov
Copy link
Contributor Author

after sometime i'm start another consumer and on assign it receives no partitions

Feb 27 10:25:59.005[DEBUG] read JoinGroup v7; broker: 3, bytes_read: 219, read_wait: 16.25µs, time_to_read: 5.018675375s, err: <nil>
Feb 27 10:25:59.005[INFO] joined; group: TestAssign, member_id: TestAssign-ea3c2858-0fbb-481a-8dea-bb7d959fe6ab-36c282b1-f006-48b1-b35e-f8521a7669d1, instance_id: <nil>, generation: 350, leader: false
Feb 27 10:25:59.005[INFO] syncing; group: TestAssign, protocol_type: consumer, protocol: cooperative-sticky
Feb 27 10:25:59.005[DEBUG] wrote SyncGroup v5; broker: 3, bytes_written: 193, write_wait: 19µs, time_to_write: 10.875µs, err: <nil>
Feb 27 10:25:59.005[DEBUG] read JoinGroup v7; broker: 3, bytes_read: 219, read_wait: 18.458µs, time_to_read: 5.023210458s, err: <nil>
Feb 27 10:25:59.005[INFO] joined; group: TestAssign, member_id: TestAssign-f1aa291d-e025-452f-9c08-00308e2ca773-0a756746-d3c7-4d6c-9924-e57aef39ed63, instance_id: <nil>, generation: 350, leader: false
Feb 27 10:25:59.005[INFO] syncing; group: TestAssign, protocol_type: consumer, protocol: cooperative-sticky
Feb 27 10:25:59.005[DEBUG] wrote SyncGroup v5; broker: 3, bytes_written: 193, write_wait: 10.375µs, time_to_write: 8.083µs, err: <nil>
Feb 27 10:25:59.005[DEBUG] read JoinGroup v7; broker: 3, bytes_read: 219, read_wait: 15.125µs, time_to_read: 5.065116333s, err: <nil>
Feb 27 10:25:59.005[INFO] joined; group: TestAssign, member_id: TestAssign-8b609f3b-9886-4e1f-8806-1ddc01d8313b-f85fd36a-ea89-4f9e-9986-71907a6753ce, instance_id: <nil>, generation: 350, leader: false
Feb 27 10:25:59.005[INFO] syncing; group: TestAssign, protocol_type: consumer, protocol: cooperative-sticky
Feb 27 10:25:59.005[DEBUG] wrote SyncGroup v5; broker: 3, bytes_written: 193, write_wait: 8µs, time_to_write: 10.208µs, err: <nil>
Feb 27 10:25:59.012[DEBUG] read JoinGroup v7; broker: 3, bytes_read: 219, read_wait: 18.875µs, time_to_read: 4.998113333s, err: <nil>
Feb 27 10:25:59.012[INFO] joined; group: TestAssign, member_id: TestAssign-de8effce-c33d-46ff-8646-eb072d8ba118-3cf3aff1-f31b-4f50-a35a-19c40b07444c, instance_id: <nil>, generation: 350, leader: false
Feb 27 10:25:59.012[INFO] syncing; group: TestAssign, protocol_type: consumer, protocol: cooperative-sticky
Feb 27 10:25:59.012[DEBUG] wrote SyncGroup v5; broker: 3, bytes_written: 193, write_wait: 12.75µs, time_to_write: 13.125µs, err: <nil>
Feb 27 10:25:59.102[DEBUG] autocommitting; group: TestAssign
Feb 27 10:25:59.102[DEBUG] autocommitting; group: TestAssign
Feb 27 10:25:59.102[DEBUG] autocommitting; group: TestAssign
Feb 27 10:25:59.102[DEBUG] autocommitting; group: TestAssign
Feb 27 10:25:59.110[DEBUG] read SyncGroup v5; broker: 3, bytes_read: 55, read_wait: 15.75µs, time_to_read: 104.542542ms, err: <nil>
Feb 27 10:25:59.110[INFO] synced; group: TestAssign, assigned: 
Feb 27 10:25:59.110[INFO] new group session begun; group: TestAssign, added: , lost: 
Feb 27 10:25:59.110[DEBUG] entering OnPartitionsAssigned; with: map[]
Feb 27 10:25:59.110[INFO] beginning heartbeat loop; group: TestAssign
Feb 27 10:25:59.112[DEBUG] read SyncGroup v5; broker: 3, bytes_read: 55, read_wait: 9.417µs, time_to_read: 106.340375ms, err: <nil>
Feb 27 10:25:59.112[INFO] synced; group: TestAssign, assigned: 
Feb 27 10:25:59.112[INFO] new group session begun; group: TestAssign, added: , lost: 
Feb 27 10:25:59.112[DEBUG] entering OnPartitionsAssigned; with: map[]
Feb 27 10:25:59.112[INFO] beginning heartbeat loop; group: TestAssign
Feb 27 10:25:59.112[DEBUG] read SyncGroup v5; broker: 3, bytes_read: 55, read_wait: 15.25µs, time_to_read: 99.546625ms, err: <nil>
Feb 27 10:25:59.112[INFO] synced; group: TestAssign, assigned: 
Feb 27 10:25:59.112[INFO] new group session begun; group: TestAssign, added: , lost: 
Feb 27 10:25:59.112[DEBUG] entering OnPartitionsAssigned; with: map[]
Feb 27 10:25:59.112[INFO] beginning heartbeat loop; group: TestAssign
Feb 27 10:25:59.112[DEBUG] read SyncGroup v5; broker: 3, bytes_read: 55, read_wait: 9.625µs, time_to_read: 106.520458ms, err: <nil>
Feb 27 10:25:59.112[INFO] synced; group: TestAssign, assigned: 
Feb 27 10:25:59.112[INFO] new group session begun; group: TestAssign, added: , lost: 
Feb 27 10:25:59.112[DEBUG] entering OnPartitionsAssigned; with: map[]
Feb 27 10:25:59.112[INFO] beginning heartbeat loop; group: TestAssign

but admin command says that this member id not present in group!

client:TestAssign-0509ceed-c471-4ddd-b33f-fad23f61cb95	partitions: 0
client:TestAssign-08c1a231-684c-410c-a999-5b1a5b2cc81a	partitions: 1
client:TestAssign-4d9ae2ea-5f61-42e5-8423-50b0fde08736	partitions: 2
client:TestAssign-afba9077-0d30-4f5f-a4ba-6c5ac4a4b9f0	partitions: 3
client:TestAssign-b7886f1d-2305-4199-8582-6ab2d4dc96e2	partitions: 4
client:TestAssign-6b47444c-69c9-4568-9009-7c33f334327a	partitions: 5
client:TestAssign-bf25186c-072b-4a7d-a075-85508ca2b603	partitions: 6
client:TestAssign-e656f59b-3122-47b1-9fe0-170644a82855	partitions: 7
client:TestAssign-09e22162-6154-4cf8-b96a-856059178fe5	partitions: 8
client:TestAssign-85f0c6ec-e97a-43f5-a77c-5ac1c944ef40	partitions: 9
client:TestAssign-ef7d7e80-8862-4661-886a-ddde3e37a268	partitions: 10
client:TestAssign-997f027c-ad7b-4c29-a239-ca9eee6e134a	partitions: 11
client:TestAssign-997f027c-ad7b-4c29-a239-ca9eee6e134a	partitions: 12
client:TestAssign-bf25186c-072b-4a7d-a075-85508ca2b603	partitions: 13
client:TestAssign-4d9ae2ea-5f61-42e5-8423-50b0fde08736	partitions: 14
client:TestAssign-0509ceed-c471-4ddd-b33f-fad23f61cb95	partitions: 15
client:TestAssign-08c1a231-684c-410c-a999-5b1a5b2cc81a	partitions: 16
client:TestAssign-6b47444c-69c9-4568-9009-7c33f334327a	partitions: 17
client:TestAssign-afba9077-0d30-4f5f-a4ba-6c5ac4a4b9f0	partitions: 18
client:TestAssign-b7886f1d-2305-4199-8582-6ab2d4dc96e2	partitions: 19
client:TestAssign-ef7d7e80-8862-4661-886a-ddde3e37a268	partitions: 20
client:TestAssign-09e22162-6154-4cf8-b96a-856059178fe5	partitions: 21
client:TestAssign-e656f59b-3122-47b1-9fe0-170644a82855	partitions: 22
client:TestAssign-85f0c6ec-e97a-43f5-a77c-5ac1c944ef40	partitions: 23
client:TestAssign-85f0c6ec-e97a-43f5-a77c-5ac1c944ef40	partitions: 24
client:TestAssign-afba9077-0d30-4f5f-a4ba-6c5ac4a4b9f0	partitions: 25
client:TestAssign-4d9ae2ea-5f61-42e5-8423-50b0fde08736	partitions: 26
client:TestAssign-997f027c-ad7b-4c29-a239-ca9eee6e134a	partitions: 27
client:TestAssign-bf25186c-072b-4a7d-a075-85508ca2b603	partitions: 28
client:TestAssign-6b47444c-69c9-4568-9009-7c33f334327a	partitions: 29
client:TestAssign-0509ceed-c471-4ddd-b33f-fad23f61cb95	partitions: 30
client:TestAssign-08c1a231-684c-410c-a999-5b1a5b2cc81a	partitions: 31
client:TestAssign-e656f59b-3122-47b1-9fe0-170644a82855	partitions: 32
client:TestAssign-ef7d7e80-8862-4661-886a-ddde3e37a268	partitions: 33
client:TestAssign-b7886f1d-2305-4199-8582-6ab2d4dc96e2	partitions: 34
client:TestAssign-09e22162-6154-4cf8-b96a-856059178fe5	partitions: 35

@twmb
Copy link
Owner

twmb commented Feb 27, 2023

The first group of logs doesn't start early enough, but I'm assuming currently that your revoke callback is taking too long. The first log lines already indicate a rebalance is in progress at 9:17:05, then at 9:17:11, you start getting UNKNOWN_MEMBER_ID, which is due to your revoke callback not being done yet. In fact, your revoke still isn't done in that entire set of logs. Maybe it's a deadlock on your side.

what is the recommended size of num for PollRecords

Up to you

after sometime i'm start another consumer and on assign it receives no partitions

Not sure, but given the other issues above, it's not worth looking into this issue because it could just be a fallout of the other problems.

@vtolstov
Copy link
Contributor Author

ok if i'm run goroutine per partition example with mark commit offsets - does it enough to reproduce problems ?

@twmb
Copy link
Owner

twmb commented Feb 27, 2023

Not sure, this looks like an application side problem.

@vtolstov
Copy link
Contributor Author

vtolstov commented Feb 28, 2023

consumer1.log
consumer2.log
i'm start two instance of consumers each subscribe 4 times (so each must handle 6 partitions)
assignment before i'm stop tests:

client:TestAssign-7a601878-dcac-4bd0-abf0-947d282d925c	partitions: 0
client:TestAssign-bc87faa1-289d-4441-bd90-c7aa14adc13e	partitions: 1
client:TestAssign-f7b22fe6-d9e0-4bfc-a8c5-b2bec5826b4c	partitions: 2
client:TestAssign-c0d9f00e-297e-4673-9042-12b7e7a5bdc8	partitions: 3
client:TestAssign-c0d9f00e-297e-4673-9042-12b7e7a5bdc8	partitions: 4
client:TestAssign-bc87faa1-289d-4441-bd90-c7aa14adc13e	partitions: 5
client:TestAssign-7a601878-dcac-4bd0-abf0-947d282d925c	partitions: 6
client:TestAssign-f7b22fe6-d9e0-4bfc-a8c5-b2bec5826b4c	partitions: 7
client:TestAssign-f7b22fe6-d9e0-4bfc-a8c5-b2bec5826b4c	partitions: 8
client:TestAssign-bc87faa1-289d-4441-bd90-c7aa14adc13e	partitions: 9
client:TestAssign-c0d9f00e-297e-4673-9042-12b7e7a5bdc8	partitions: 10
client:TestAssign-7a601878-dcac-4bd0-abf0-947d282d925c	partitions: 11
client:TestAssign-7a601878-dcac-4bd0-abf0-947d282d925c	partitions: 12
client:TestAssign-bc87faa1-289d-4441-bd90-c7aa14adc13e	partitions: 13
client:TestAssign-f7b22fe6-d9e0-4bfc-a8c5-b2bec5826b4c	partitions: 14
client:TestAssign-c0d9f00e-297e-4673-9042-12b7e7a5bdc8	partitions: 15
client:TestAssign-c0d9f00e-297e-4673-9042-12b7e7a5bdc8	partitions: 16
client:TestAssign-bc87faa1-289d-4441-bd90-c7aa14adc13e	partitions: 17
client:TestAssign-7a601878-dcac-4bd0-abf0-947d282d925c	partitions: 18
client:TestAssign-f7b22fe6-d9e0-4bfc-a8c5-b2bec5826b4c	partitions: 19
client:TestAssign-f7b22fe6-d9e0-4bfc-a8c5-b2bec5826b4c	partitions: 20
client:TestAssign-bc87faa1-289d-4441-bd90-c7aa14adc13e	partitions: 21
client:TestAssign-c0d9f00e-297e-4673-9042-12b7e7a5bdc8	partitions: 22
client:TestAssign-7a601878-dcac-4bd0-abf0-947d282d925c	partitions: 23

logs from consumer1 and consumer2 instances in attached files

@twmb
Copy link
Owner

twmb commented Feb 28, 2023

Those full logs help -- I see a bug -- can you remove Sticky() from your balancers, to make it just CooperativeSticky? On this line: https://github.com/unistack-org/micro-broker-kgo/blob/adb5c9bfc9fe9c100e6f090a0e5ea73344ed2ece/kgo.go#L385

The bug is that some logic in the client is thinking the group is eager, because there is an eager balancer option. The group is rebalancing as coopartive (i.e. only getting partial assignments) while the client is revoking all partitions.

@vtolstov
Copy link
Contributor Author

vtolstov commented Mar 1, 2023

thanks, you suggestion works fine for me. now all consumers always get assignment and process messages.

@twmb twmb added bug Something isn't working and removed waiting labels Mar 1, 2023
twmb added a commit that referenced this issue Mar 11, 2023
The previous cooperative check was wrong: if you used multiple group
balancers, if any were eager, the client would think you were eager
consuming.

However this bug did not affect all areas of group balancing, which
actually made the bug worse. If everything in the code went eager, then
the bug would just be "you saw more stop the world than was intended".
Instead, if the chosen balancer was cooperative, then cooperative
balancing would occur for eager consumers. On rebalance, partitions
would be lost, and then a cooperative rebalance would not occur, meaning
the partitions would be stuck until another rebalance.

We fix this by saving if we are cooperative based on the rebalancer that
is actually chosen.

This is an upgrade path that should happen once -- once to cooperative
-- but we can downgrade if the user adds a random eager balancer. This
is not supported per KIP-429 so we just warn log and continue as best we
can (likely with duplicate consumption).

Closes #366.
twmb added a commit that referenced this issue Mar 11, 2023
The previous cooperative check was wrong: if you used multiple group
balancers, if any were eager, the client would think you were eager
consuming.

However this bug did not affect all areas of group balancing, which
actually made the bug worse. If everything in the code went eager, then
the bug would just be "you saw more stop the world than was intended".
Instead, if the chosen balancer was cooperative, then cooperative
balancing would occur for eager consumers. On rebalance, partitions
would be lost, and then a cooperative rebalance would not occur, meaning
the partitions would be stuck until another rebalance.

We fix this by saving if we are cooperative based on the rebalancer that
is actually chosen.

This is an upgrade path that should happen once -- once to cooperative
-- but we can downgrade if the user adds a random eager balancer. This
is not supported per KIP-429 so we just warn log and continue as best we
can (likely with duplicate consumption).

Closes #366.
@twmb twmb closed this as completed in #384 Mar 13, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants