Current producer tests set up a zap debug logger that is quite verbose. Going through this big output when trying to identify a specific test failure (which may be unrelated to the verbose tests) is quite painful.
To address this in this PR the debug logger is only initialized when -v is specified. This allows the choice to developers to run with or without the verbose logger enabled.
It also updates make test to run go test in non verbose mode and adds an additional make target, test-verbose to run with -v.
This change is reflected in CI where the less verbose target is used, but I don't have strong opinions there. I see the debug logger as a development/bugfixing aid more than useful information to have on CI and there is the dedicated test-verbose make target for such scenarios.
We get from this:
Details
```
$ make test-verbose
make test GO_VERBOSE=-v
make[1]: Entering directory '/home/endorama/code/github.com/elastic/apm-queue'
go test -race -v -timeout=60s ./...
? github.com/elastic/apm-queue/v2 [no test files]
? github.com/elastic/apm-queue/v2/cmd/queuebench [no test files]
? github.com/elastic/apm-queue/v2/metrictest [no test files]
=== RUN TestCommonConfig
=== RUN TestCommonConfig/invalid
=== RUN TestCommonConfig/tls_or_dialer
=== RUN TestCommonConfig/valid
=== RUN TestCommonConfig/brokers_from_environment
=== RUN TestCommonConfig/saslplain_from_environment
=== RUN TestCommonConfig/saslaws_from_environment
=== RUN TestCommonConfig/saslaws_from_environment/access_key_env
=== RUN TestCommonConfig/saslaws_from_environment/credentials_file
=== RUN TestCommonConfig/tls_from_environment
=== RUN TestCommonConfig/tls_from_environment/plaintext
=== RUN TestCommonConfig/tls_from_environment/tls_default
=== RUN TestCommonConfig/tls_from_environment/tls_insecure
=== RUN TestCommonConfig/configfile_from_env
=== RUN TestCommonConfig/brokers_from_configfile
=== RUN TestCommonConfig/sasl_from_configfile
--- PASS: TestCommonConfig (0.01s)
--- PASS: TestCommonConfig/invalid (0.00s)
--- PASS: TestCommonConfig/tls_or_dialer (0.00s)
--- PASS: TestCommonConfig/valid (0.00s)
--- PASS: TestCommonConfig/brokers_from_environment (0.00s)
--- PASS: TestCommonConfig/saslplain_from_environment (0.00s)
--- PASS: TestCommonConfig/saslaws_from_environment (0.00s)
--- PASS: TestCommonConfig/saslaws_from_environment/access_key_env (0.00s)
--- PASS: TestCommonConfig/saslaws_from_environment/credentials_file (0.00s)
--- PASS: TestCommonConfig/tls_from_environment (0.00s)
--- PASS: TestCommonConfig/tls_from_environment/plaintext (0.00s)
--- PASS: TestCommonConfig/tls_from_environment/tls_default (0.00s)
--- PASS: TestCommonConfig/tls_from_environment/tls_insecure (0.00s)
--- PASS: TestCommonConfig/configfile_from_env (0.00s)
--- PASS: TestCommonConfig/brokers_from_configfile (0.00s)
--- PASS: TestCommonConfig/sasl_from_configfile (0.00s)
=== RUN TestCommonConfigFileHook
--- PASS: TestCommonConfigFileHook (0.08s)
=== RUN TestLoadConfigFile
=== RUN TestLoadConfigFile/file_does_not_exist
=== RUN TestLoadConfigFile/file_contents_are_invalid
=== RUN TestLoadConfigFile/file_contents_are_empty
=== RUN TestLoadConfigFile/file_contents_are_non-empty
--- PASS: TestLoadConfigFile (0.00s)
--- PASS: TestLoadConfigFile/file_does_not_exist (0.00s)
--- PASS: TestLoadConfigFile/file_contents_are_invalid (0.00s)
--- PASS: TestLoadConfigFile/file_contents_are_empty (0.00s)
--- PASS: TestLoadConfigFile/file_contents_are_non-empty (0.00s)
=== RUN TestNewConsumer
=== RUN TestNewConsumer/valid
=== RUN TestNewConsumer/empty
=== RUN TestNewConsumer/invalid_client_consumer_options
--- PASS: TestNewConsumer (0.00s)
--- PASS: TestNewConsumer/valid (0.00s)
--- PASS: TestNewConsumer/empty (0.00s)
--- PASS: TestNewConsumer/invalid_client_consumer_options (0.00s)
=== RUN TestConsumerHealth
=== RUN TestConsumerHealth/success
=== RUN TestConsumerHealth/failure
--- PASS: TestConsumerHealth (0.00s)
--- PASS: TestConsumerHealth/success (0.00s)
--- PASS: TestConsumerHealth/failure (0.00s)
=== RUN TestConsumerInstrumentation
--- PASS: TestConsumerInstrumentation (0.01s)
=== RUN TestConsumerDelivery
=== RUN TestConsumerDelivery/30_produced_2_poll_ALOD
logger.go:146: 2024-05-23T15:36:33.835+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.836+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.836+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-0b143763f039e5ce0cb5d36ef9bdb122"}
logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-0b143763f039e5ce0cb5d36ef9bdb122", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-0b143763f039e5ce0cb5d36ef9bdb122", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-0b143763f039e5ce0cb5d36ef9bdb122{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.838+0200 INFO 1.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.838+0200 INFO 1.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.838+0200 INFO 1.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.838+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.840+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 0, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.840+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 1, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.840+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 2, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.840+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 3, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.840+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.840+0200 INFO 1.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.840+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.840+0200 INFO 1.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-0b143763f039e5ce0cb5d36ef9bdb122"}
consumer_test.go:367: got: 4 events errored, 0 processed, want: 2 errored, 30 processed
logger.go:146: 2024-05-23T15:36:33.844+0200 INFO 2.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.844+0200 INFO 2.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.844+0200 INFO 2.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-b2ca46bcc825e6d0b05f30da0cb469a1"}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-b2ca46bcc825e6d0b05f30da0cb469a1", "instance_id": "", "generation": 3, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-b2ca46bcc825e6d0b05f30da0cb469a1", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-b2ca46bcc825e6d0b05f30da0cb469a1{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.846+0200 INFO 2.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.847+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.848+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 9}
logger.go:146: 2024-05-23T15:36:33.849+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 19}
logger.go:146: 2024-05-23T15:36:33.849+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 29}
consumer_test.go:399: got: 4 events errored, 30 processed, want: 2 errored, 30 processed
logger.go:146: 2024-05-23T15:36:33.850+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.850+0200 INFO 2.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.850+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.850+0200 INFO 2.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-b2ca46bcc825e6d0b05f30da0cb469a1"}
=== RUN TestConsumerDelivery/12_produced_1_poll_ALOD
logger.go:146: 2024-05-23T15:36:33.853+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.853+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.853+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.854+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-444f570134184db16af3d59c1e51667d"}
logger.go:146: 2024-05-23T15:36:33.854+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-444f570134184db16af3d59c1e51667d", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.854+0200 INFO 1.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.855+0200 INFO 1.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-444f570134184db16af3d59c1e51667d", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.855+0200 INFO 1.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-444f570134184db16af3d59c1e51667d{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.855+0200 INFO 1.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.855+0200 INFO 1.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.855+0200 INFO 1.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.855+0200 INFO 1.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.855+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[1{-2 e-1 ce0} 0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.856+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 0, "error": "failed processing record", "offset": 0, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.856+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.856+0200 INFO 1.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.856+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.857+0200 INFO 1.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-444f570134184db16af3d59c1e51667d"}
consumer_test.go:367: got: 1 events errored, 0 processed, want: 1 errored, 11 processed
logger.go:146: 2024-05-23T15:36:33.860+0200 INFO 2.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.861+0200 INFO 2.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.861+0200 INFO 2.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.862+0200 INFO 2.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-87051514ccc88baebaf0d4ee9810e962"}
logger.go:146: 2024-05-23T15:36:33.863+0200 INFO 2.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-87051514ccc88baebaf0d4ee9810e962", "instance_id": "", "generation": 3, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.863+0200 INFO 2.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.863+0200 INFO 2.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-87051514ccc88baebaf0d4ee9810e962", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.863+0200 INFO 2.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-87051514ccc88baebaf0d4ee9810e962{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.863+0200 INFO 2.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.863+0200 INFO 2.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.864+0200 INFO 2.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.864+0200 INFO 2.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.864+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.865+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 0, "offset": 10}
logger.go:146: 2024-05-23T15:36:33.866+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 0, "offset": 11}
consumer_test.go:399: got: 1 events errored, 12 processed, want: 1 errored, 11 processed
logger.go:146: 2024-05-23T15:36:33.867+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.867+0200 INFO 2.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.867+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.867+0200 INFO 2.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-87051514ccc88baebaf0d4ee9810e962"}
=== RUN TestConsumerDelivery/1_produced_1_poll_ALOD
logger.go:146: 2024-05-23T15:36:33.869+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.870+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.870+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-2579f18f879b0277f406669813ba2894"}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-2579f18f879b0277f406669813ba2894", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-2579f18f879b0277f406669813ba2894", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-2579f18f879b0277f406669813ba2894{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.871+0200 INFO 1.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.872+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.872+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 0, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.873+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.873+0200 INFO 1.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.873+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.873+0200 INFO 1.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-2579f18f879b0277f406669813ba2894"}
consumer_test.go:367: got: 1 events errored, 0 processed, want: 1 errored, 1 processed
logger.go:146: 2024-05-23T15:36:33.875+0200 INFO 2.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.875+0200 INFO 2.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.875+0200 INFO 2.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.876+0200 INFO 2.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-f093d15034512a757ba54b51f52ad307"}
logger.go:146: 2024-05-23T15:36:33.876+0200 INFO 2.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-f093d15034512a757ba54b51f52ad307", "instance_id": "", "generation": 3, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.876+0200 INFO 2.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.876+0200 INFO 2.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-f093d15034512a757ba54b51f52ad307", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.876+0200 INFO 2.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-f093d15034512a757ba54b51f52ad307{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.876+0200 INFO 2.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.877+0200 INFO 2.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.877+0200 INFO 2.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.877+0200 INFO 2.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.877+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.878+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 0}
consumer_test.go:399: got: 1 events errored, 1 processed, want: 1 errored, 1 processed
logger.go:146: 2024-05-23T15:36:33.879+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.880+0200 INFO 2.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.880+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.880+0200 INFO 2.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-f093d15034512a757ba54b51f52ad307"}
=== RUN TestConsumerDelivery/12_produced_10_poll_AMOD
logger.go:146: 2024-05-23T15:36:33.884+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.884+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.884+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.885+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-67a0f8a29b93187bee497bc695059102"}
logger.go:146: 2024-05-23T15:36:33.885+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-67a0f8a29b93187bee497bc695059102", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.885+0200 INFO 1.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.885+0200 INFO 1.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-67a0f8a29b93187bee497bc695059102", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.885+0200 INFO 1.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-67a0f8a29b93187bee497bc695059102{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.885+0200 INFO 1.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.886+0200 INFO 1.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.886+0200 INFO 1.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.886+0200 INFO 1.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.886+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.887+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 0, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.887+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 1, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.887+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 2, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.887+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 3, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.887+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 4, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.887+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 5, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.887+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 6, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.888+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 7, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.888+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 8, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.888+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 9, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.888+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.888+0200 INFO 1.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.888+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.888+0200 INFO 1.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-67a0f8a29b93187bee497bc695059102"}
consumer_test.go:367: got: 10 events errored, 0 processed, want: 10 errored, 2 processed
logger.go:146: 2024-05-23T15:36:33.890+0200 INFO 2.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.890+0200 INFO 2.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.891+0200 INFO 2.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.891+0200 INFO 2.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-dd691bfb5694b0ac53ba2fa152b5e508"}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-dd691bfb5694b0ac53ba2fa152b5e508", "instance_id": "", "generation": 3, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-dd691bfb5694b0ac53ba2fa152b5e508", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-dd691bfb5694b0ac53ba2fa152b5e508{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.892+0200 INFO 2.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.893+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{10 e0 ce0}]"}
consumer_test.go:399: got: 10 events errored, 2 processed, want: 10 errored, 2 processed
logger.go:146: 2024-05-23T15:36:33.895+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.895+0200 INFO 2.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.895+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.895+0200 INFO 2.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-dd691bfb5694b0ac53ba2fa152b5e508"}
=== RUN TestConsumerDelivery/30_produced_2_poll_AMOD
logger.go:146: 2024-05-23T15:36:33.901+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.901+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.901+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.902+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-65c573e53207776024805ee45c289664"}
logger.go:146: 2024-05-23T15:36:33.902+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-65c573e53207776024805ee45c289664", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.902+0200 INFO 1.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.902+0200 INFO 1.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-65c573e53207776024805ee45c289664", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.903+0200 INFO 1.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-65c573e53207776024805ee45c289664{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.903+0200 INFO 1.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.903+0200 INFO 1.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.903+0200 INFO 1.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.903+0200 INFO 1.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.903+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.905+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 0, "error": "failed processing record", "offset": 0, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.905+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 0, "error": "failed processing record", "offset": 1, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.905+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.905+0200 INFO 1.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.905+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.905+0200 INFO 1.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-65c573e53207776024805ee45c289664"}
consumer_test.go:367: got: 2 events errored, 0 processed, want: 2 errored, 26 processed
logger.go:146: 2024-05-23T15:36:33.908+0200 INFO 2.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.909+0200 INFO 2.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.909+0200 INFO 2.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.909+0200 INFO 2.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-b746d93f5efcda0ea9e1fb205fb659b7"}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-b746d93f5efcda0ea9e1fb205fb659b7", "instance_id": "", "generation": 3, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-b746d93f5efcda0ea9e1fb205fb659b7", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-b746d93f5efcda0ea9e1fb205fb659b7{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.910+0200 INFO 2.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.911+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{2 e0 ce0} 1{-2 e-1 ce0}]"}
consumer_test.go:399: got: 2 events errored, 28 processed, want: 2 errored, 26 processed
logger.go:146: 2024-05-23T15:36:33.913+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.913+0200 INFO 2.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.913+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.913+0200 INFO 2.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-b746d93f5efcda0ea9e1fb205fb659b7"}
=== RUN TestConsumerDelivery/12_produced_1_poll_AMOD
logger.go:146: 2024-05-23T15:36:33.915+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.916+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.916+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.917+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-9964600185fc6b6cf8410faf3f5b3b3a"}
logger.go:146: 2024-05-23T15:36:33.917+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-9964600185fc6b6cf8410faf3f5b3b3a", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.917+0200 INFO 1.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.917+0200 INFO 1.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-9964600185fc6b6cf8410faf3f5b3b3a", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.917+0200 INFO 1.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-9964600185fc6b6cf8410faf3f5b3b3a{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.917+0200 INFO 1.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.917+0200 INFO 1.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.918+0200 INFO 1.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.918+0200 INFO 1.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.918+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[1{-2 e-1 ce0} 0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.919+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 0, "error": "failed processing record", "offset": 0, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.919+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.919+0200 INFO 1.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.919+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.919+0200 INFO 1.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-9964600185fc6b6cf8410faf3f5b3b3a"}
consumer_test.go:367: got: 1 events errored, 0 processed, want: 1 errored, 11 processed
logger.go:146: 2024-05-23T15:36:33.923+0200 INFO 2.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.923+0200 INFO 2.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.923+0200 INFO 2.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.924+0200 INFO 2.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-9e70f4cfb4233389c2f4210e1867bde8"}
logger.go:146: 2024-05-23T15:36:33.924+0200 INFO 2.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-9e70f4cfb4233389c2f4210e1867bde8", "instance_id": "", "generation": 3, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.924+0200 INFO 2.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.925+0200 INFO 2.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-9e70f4cfb4233389c2f4210e1867bde8", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.925+0200 INFO 2.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-9e70f4cfb4233389c2f4210e1867bde8{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.925+0200 INFO 2.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.925+0200 INFO 2.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.925+0200 INFO 2.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.925+0200 INFO 2.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.925+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[1{-2 e-1 ce0} 0{1 e0 ce0}]"}
consumer_test.go:399: got: 1 events errored, 11 processed, want: 1 errored, 11 processed
logger.go:146: 2024-05-23T15:36:33.928+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.928+0200 INFO 2.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.928+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.928+0200 INFO 2.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-9e70f4cfb4233389c2f4210e1867bde8"}
=== RUN TestConsumerDelivery/12_produced_10_poll_ALOD
logger.go:146: 2024-05-23T15:36:33.932+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.933+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.933+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.933+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-c04de1e89cdb5bbfbd25cdc38d528c4a"}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-c04de1e89cdb5bbfbd25cdc38d528c4a", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-c04de1e89cdb5bbfbd25cdc38d528c4a", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-c04de1e89cdb5bbfbd25cdc38d528c4a{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.934+0200 INFO 1.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.935+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 0, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 1, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 2, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 3, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 4, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 5, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 6, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 7, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 8, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 ERROR 1.kafka.partition data loss: unable to process event {"namespace": "name_space", "topic": "topic", "partition": 1, "error": "failed processing record", "offset": 9, "headers": {}}
logger.go:146: 2024-05-23T15:36:33.936+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.936+0200 INFO 1.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.936+0200 INFO 1.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.936+0200 INFO 1.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-c04de1e89cdb5bbfbd25cdc38d528c4a"}
consumer_test.go:367: got: 10 events errored, 0 processed, want: 10 errored, 12 processed
logger.go:146: 2024-05-23T15:36:33.938+0200 INFO 2.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.939+0200 INFO 2.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.939+0200 INFO 2.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-d150f98da61d6de04df6284bda03aee3"}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-d150f98da61d6de04df6284bda03aee3", "instance_id": "", "generation": 3, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka balancing group as leader {"namespace": "name_space"}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka balance group member {"namespace": "name_space", "id": "kgo-d150f98da61d6de04df6284bda03aee3", "interests": "interested topics: [name_space-topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka balanced {"namespace": "name_space", "plan": "kgo-d150f98da61d6de04df6284bda03aee3{name_space-topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka syncing {"namespace": "name_space", "group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka synced {"namespace": "name_space", "group": "groupid", "assigned": "name_space-topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.940+0200 INFO 2.kafka.kafka new group session begun {"namespace": "name_space", "group": "groupid", "added": "name_space-topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.941+0200 INFO 2.kafka.kafka beginning heartbeat loop {"namespace": "name_space", "group": "groupid"}
logger.go:146: 2024-05-23T15:36:33.941+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "name_space-topic[1{-2 e-1 ce0} 0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.942+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 1}
logger.go:146: 2024-05-23T15:36:33.942+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 3}
logger.go:146: 2024-05-23T15:36:33.942+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 5}
logger.go:146: 2024-05-23T15:36:33.943+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 7}
logger.go:146: 2024-05-23T15:36:33.943+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 9}
logger.go:146: 2024-05-23T15:36:33.943+0200 INFO 2.kafka.partition committed {"namespace": "name_space", "topic": "topic", "partition": 1, "offset": 11}
consumer_test.go:399: got: 10 events errored, 12 processed, want: 10 errored, 12 processed
logger.go:146: 2024-05-23T15:36:33.944+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.945+0200 INFO 2.kafka.kafka heartbeat errored {"namespace": "name_space", "group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.945+0200 INFO 2.kafka.kafka assigning partitions {"namespace": "name_space", "why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.945+0200 INFO 2.kafka.kafka leaving group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-d150f98da61d6de04df6284bda03aee3"}
--- PASS: TestConsumerDelivery (0.11s)
--- PASS: TestConsumerDelivery/30_produced_2_poll_ALOD (0.02s)
--- PASS: TestConsumerDelivery/12_produced_1_poll_ALOD (0.02s)
--- PASS: TestConsumerDelivery/1_produced_1_poll_ALOD (0.01s)
--- PASS: TestConsumerDelivery/12_produced_10_poll_AMOD (0.01s)
--- PASS: TestConsumerDelivery/30_produced_2_poll_AMOD (0.02s)
--- PASS: TestConsumerDelivery/12_produced_1_poll_AMOD (0.01s)
--- PASS: TestConsumerDelivery/12_produced_10_poll_ALOD (0.02s)
=== RUN TestConsumerGracefulShutdown
=== RUN TestConsumerGracefulShutdown/AtLeastOnceDelivery
logger.go:146: 2024-05-23T15:36:33.946+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.947+0200 INFO kafka.kafka beginning to manage the group lifecycle {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery"}
logger.go:146: 2024-05-23T15:36:33.947+0200 INFO kafka.kafka joining group {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery"}
logger.go:146: 2024-05-23T15:36:33.947+0200 INFO kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery", "member_id": "kgo-127c303e62507663bb6ea7b555a7d4f7"}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka joined, balancing group {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery", "member_id": "kgo-127c303e62507663bb6ea7b555a7d4f7", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka balancing group as leader
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka balance group member {"id": "kgo-127c303e62507663bb6ea7b555a7d4f7", "interests": "interested topics: [topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka balanced {"plan": "kgo-127c303e62507663bb6ea7b555a7d4f7{topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka syncing {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka synced {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery", "assigned": "topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka new group session begun {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery", "added": "topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka beginning heartbeat loop {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery"}
logger.go:146: 2024-05-23T15:36:33.948+0200 INFO kafka.kafka assigning partitions {"why": "newly fetched offsets for group TestConsumerGracefulShutdown/AtLeastOnceDelivery", "how": "assigning everything new, keeping current assignment", "input": "topic[1{-2 e-1 ce0} 0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.949+0200 INFO kafka.partition committed {"topic": "topic", "partition": 1, "offset": 1}
logger.go:146: 2024-05-23T15:36:33.950+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.950+0200 INFO kafka.kafka heartbeat errored {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.950+0200 INFO kafka.kafka assigning partitions {"why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.950+0200 INFO kafka.kafka leaving group {"group": "TestConsumerGracefulShutdown/AtLeastOnceDelivery", "member_id": "kgo-127c303e62507663bb6ea7b555a7d4f7"}
=== RUN TestConsumerGracefulShutdown/AtMostOnceDelivery
logger.go:146: 2024-05-23T15:36:33.951+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:33.951+0200 INFO kafka.kafka beginning to manage the group lifecycle {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery"}
logger.go:146: 2024-05-23T15:36:33.951+0200 INFO kafka.kafka joining group {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery"}
logger.go:146: 2024-05-23T15:36:33.952+0200 INFO kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery", "member_id": "kgo-dc332b8c125b3e5be6b5ef58bfb49020"}
logger.go:146: 2024-05-23T15:36:33.952+0200 INFO kafka.kafka joined, balancing group {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery", "member_id": "kgo-dc332b8c125b3e5be6b5ef58bfb49020", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:33.952+0200 INFO kafka.kafka balancing group as leader
logger.go:146: 2024-05-23T15:36:33.952+0200 INFO kafka.kafka balance group member {"id": "kgo-dc332b8c125b3e5be6b5ef58bfb49020", "interests": "interested topics: [topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:33.952+0200 INFO kafka.kafka balanced {"plan": "kgo-dc332b8c125b3e5be6b5ef58bfb49020{topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:33.952+0200 INFO kafka.kafka syncing {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:33.953+0200 INFO kafka.kafka synced {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery", "assigned": "topic[0 1]"}
logger.go:146: 2024-05-23T15:36:33.953+0200 INFO kafka.kafka new group session begun {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery", "added": "topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:33.953+0200 INFO kafka.kafka beginning heartbeat loop {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery"}
logger.go:146: 2024-05-23T15:36:33.953+0200 INFO kafka.kafka assigning partitions {"why": "newly fetched offsets for group TestConsumerGracefulShutdown/AtMostOnceDelivery", "how": "assigning everything new, keeping current assignment", "input": "topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:33.954+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.954+0200 INFO kafka.kafka heartbeat errored {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:33.954+0200 INFO kafka.kafka assigning partitions {"why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:33.955+0200 INFO kafka.kafka leaving group {"group": "TestConsumerGracefulShutdown/AtMostOnceDelivery", "member_id": "kgo-dc332b8c125b3e5be6b5ef58bfb49020"}
--- PASS: TestConsumerGracefulShutdown (0.01s)
--- PASS: TestConsumerGracefulShutdown/AtLeastOnceDelivery (0.00s)
--- PASS: TestConsumerGracefulShutdown/AtMostOnceDelivery (0.00s)
=== RUN TestConsumerContextPropagation
--- PASS: TestConsumerContextPropagation (0.00s)
=== RUN TestMultipleConsumers
--- PASS: TestMultipleConsumers (0.07s)
=== RUN TestMultipleConsumerGroups
--- PASS: TestMultipleConsumerGroups (0.57s)
=== RUN TestConsumerRunError
=== RUN TestConsumerRunError/context.Cancelled
logger.go:146: 2024-05-23T15:36:34.597+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:34.597+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.597+0200 INFO kafka.kafka leaving group {"group": "groupid", "member_id": ""}
=== RUN TestConsumerRunError/consumer.Close()
logger.go:146: 2024-05-23T15:36:34.598+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:34.599+0200 INFO kafka.kafka beginning to manage the group lifecycle {"group": "groupid"}
logger.go:146: 2024-05-23T15:36:34.599+0200 INFO kafka.kafka joining group {"group": "groupid"}
logger.go:146: 2024-05-23T15:36:34.600+0200 INFO kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"group": "groupid", "member_id": "kgo-4eb3c3d8586071a262d7d64814e7f62b"}
logger.go:146: 2024-05-23T15:36:34.600+0200 INFO kafka.kafka joined, balancing group {"group": "groupid", "member_id": "kgo-4eb3c3d8586071a262d7d64814e7f62b", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:34.600+0200 INFO kafka.kafka balancing group as leader
logger.go:146: 2024-05-23T15:36:34.600+0200 INFO kafka.kafka balance group member {"id": "kgo-4eb3c3d8586071a262d7d64814e7f62b", "interests": "interested topics: [topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:34.600+0200 INFO kafka.kafka balanced {"plan": "kgo-4eb3c3d8586071a262d7d64814e7f62b{topic[0 1]}"}
logger.go:146: 2024-05-23T15:36:34.600+0200 INFO kafka.kafka syncing {"group": "groupid", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:34.601+0200 INFO kafka.kafka synced {"group": "groupid", "assigned": "topic[0 1]"}
logger.go:146: 2024-05-23T15:36:34.601+0200 INFO kafka.kafka new group session begun {"group": "groupid", "added": "topic[0 1]", "lost": ""}
logger.go:146: 2024-05-23T15:36:34.601+0200 INFO kafka.kafka beginning heartbeat loop {"group": "groupid"}
logger.go:146: 2024-05-23T15:36:34.602+0200 INFO kafka.kafka assigning partitions {"why": "newly fetched offsets for group groupid", "how": "assigning everything new, keeping current assignment", "input": "topic[0{-2 e-1 ce0} 1{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:34.603+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.603+0200 INFO kafka.kafka heartbeat errored {"group": "groupid", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.603+0200 INFO kafka.kafka assigning partitions {"why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.603+0200 INFO kafka.kafka leaving group {"group": "groupid", "member_id": "kgo-4eb3c3d8586071a262d7d64814e7f62b"}
--- PASS: TestConsumerRunError (0.01s)
--- PASS: TestConsumerRunError/context.Cancelled (0.00s)
--- PASS: TestConsumerRunError/consumer.Close() (0.01s)
=== RUN TestNewManager
--- PASS: TestNewManager (0.00s)
=== RUN TestManagerDeleteTopics
--- PASS: TestManagerDeleteTopics (0.00s)
=== RUN TestManagerMetrics
--- PASS: TestManagerMetrics (0.00s)
=== RUN TestProducerMetrics
=== RUN TestProducerMetrics/DeadlineExceeded
metrics_test.go:65: messaging.kafka.connects.count
metrics_test.go:65: messaging.kafka.disconnects.count
metrics_test.go:65: messaging.kafka.write_bytes
metrics_test.go:65: messaging.kafka.read_errors.count
metrics_test.go:65: producer.messages.count
=== RUN TestProducerMetrics/ContextCanceled
metrics_test.go:65: messaging.kafka.connects.count
metrics_test.go:65: messaging.kafka.write_bytes
metrics_test.go:65: messaging.kafka.read_bytes.count
metrics_test.go:65: producer.messages.count
=== RUN TestProducerMetrics/Unknown_error_reason
metrics_test.go:65: messaging.kafka.connect_errors.count
metrics_test.go:65: producer.messages.count
=== RUN TestProducerMetrics/Produced
metrics_test.go:65: messaging.kafka.connects.count
metrics_test.go:65: messaging.kafka.disconnects.count
metrics_test.go:65: messaging.kafka.write_bytes
metrics_test.go:65: messaging.kafka.read_bytes.count
metrics_test.go:65: messaging.kafka.produce_bytes.count
metrics_test.go:65: messaging.kafka.produce_records.count
metrics_test.go:65: producer.messages.count
metrics_test.go:65: producer.messages.bytes
metrics_test.go:65: producer.messages.uncompressed.bytes
=== RUN TestProducerMetrics/ProducedWithHeaders
metrics_test.go:65: messaging.kafka.connects.count
metrics_test.go:65: messaging.kafka.disconnects.count
metrics_test.go:65: messaging.kafka.write_bytes
metrics_test.go:65: messaging.kafka.read_bytes.count
metrics_test.go:65: messaging.kafka.produce_bytes.count
metrics_test.go:65: messaging.kafka.produce_records.count
metrics_test.go:65: producer.messages.count
metrics_test.go:65: producer.messages.bytes
metrics_test.go:65: producer.messages.uncompressed.bytes
--- PASS: TestProducerMetrics (0.02s)
--- PASS: TestProducerMetrics/DeadlineExceeded (0.00s)
--- PASS: TestProducerMetrics/ContextCanceled (0.00s)
--- PASS: TestProducerMetrics/Unknown_error_reason (0.00s)
--- PASS: TestProducerMetrics/Produced (0.01s)
--- PASS: TestProducerMetrics/ProducedWithHeaders (0.00s)
=== RUN TestConsumerMetrics
--- PASS: TestConsumerMetrics (0.01s)
=== RUN TestNewProducer
=== RUN TestNewProducer/invalid
=== RUN TestNewProducer/valid
=== RUN TestNewProducer/compression_from_environment
=== RUN TestNewProducer/invalid_compression_from_environment
--- PASS: TestNewProducer (0.00s)
--- PASS: TestNewProducer/invalid (0.00s)
--- PASS: TestNewProducer/valid (0.00s)
--- PASS: TestNewProducer/compression_from_environment (0.00s)
--- PASS: TestNewProducer/invalid_compression_from_environment (0.00s)
=== RUN TestNewProducerBasic
=== RUN TestNewProducerBasic/sync_true
=== RUN TestNewProducerBasic/sync_false
--- PASS: TestNewProducerBasic (0.02s)
--- PASS: TestNewProducerBasic/sync_true (0.01s)
--- PASS: TestNewProducerBasic/sync_false (0.01s)
=== RUN TestProducerGracefulShutdown
=== RUN TestProducerGracefulShutdown/AtLeastOnceDelivery
=== RUN TestProducerGracefulShutdown/AtLeastOnceDelivery/sync
=== NAME TestProducerGracefulShutdown
logger.go:146: 2024-05-23T15:36:34.656+0200 INFO kafka.kafka immediate metadata update triggered {"why": "from user ForceMetadataRefresh"}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:39423", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.657+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:34.657+0200 INFO kafka.kafka producing to a new topic for the first time, fetching metadata to learn its partitions {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:39423", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:39423", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:39423", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "14.833µs", "time_to_write": "13.336µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "12.062µs", "time_to_write": "15.265µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "96.171µs", "time_to_read": "6.371µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:39423", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "98.861µs", "time_to_read": "6.241µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:39423", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 22, "write_wait": "610.347µs", "time_to_write": "10.442µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 45, "write_wait": "557.732µs", "time_to_write": "10.901µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 86, "read_wait": "110.495µs", "time_to_read": "8.108µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 159, "read_wait": "77.588µs", "time_to_read": "5.924µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.657+0200 INFO kafka.kafka immediate metadata update triggered {"why": "forced load because we are producing to a topic for the first time"}
logger.go:146: 2024-05-23T15:36:34.658+0200 INFO kafka.kafka beginning to manage the group lifecycle {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka blocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.658+0200 INFO kafka.kafka joining group {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka prepared to issue find coordinator request {"coordinator_type": 0, "coordinator_keys": ["group"]}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka sharded request {"req": "FindCoordinator", "destinations": ["any"]}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka issuing api versions request {"broker": "0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "0", "bytes_written": 31, "write_wait": "12.414µs", "time_to_write": "12.501µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "0", "bytes_read": 233, "read_wait": "84.32µs", "time_to_read": "5.781µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka wrote FindCoordinator v4 {"broker": "0", "bytes_written": 27, "write_wait": "449.463µs", "time_to_write": "10.28µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka read FindCoordinator v4 {"broker": "0", "bytes_read": 43, "read_wait": "69.724µs", "time_to_read": "5.982µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.658+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.659+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.659+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.659+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 137, "write_wait": "253.739µs", "time_to_write": "13.575µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.659+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 62, "read_wait": "111.574µs", "time_to_read": "6.704µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.659+0200 INFO kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"group": "group", "member_id": "kgo-7f0f482aa69862b6fb21a9f533b723f6"}
logger.go:146: 2024-05-23T15:36:34.659+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 173, "write_wait": "19.599µs", "time_to_write": "12.82µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.659+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 195, "read_wait": "93.252µs", "time_to_read": "7.455µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.659+0200 INFO kafka.kafka joined, balancing group {"group": "group", "member_id": "kgo-7f0f482aa69862b6fb21a9f533b723f6", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:34.659+0200 INFO kafka.kafka balancing group as leader
logger.go:146: 2024-05-23T15:36:34.659+0200 INFO kafka.kafka balance group member {"id": "kgo-7f0f482aa69862b6fb21a9f533b723f6", "interests": "interested topics: [topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:34.659+0200 INFO kafka.kafka balanced {"plan": "kgo-7f0f482aa69862b6fb21a9f533b723f6{topic[0]}"}
logger.go:146: 2024-05-23T15:36:34.659+0200 INFO kafka.kafka syncing {"group": "group", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka wrote SyncGroup v5 {"broker": "0", "bytes_written": 160, "write_wait": "22.619µs", "time_to_write": "12.213µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka read SyncGroup v5 {"broker": "0", "bytes_read": 70, "read_wait": "105.108µs", "time_to_read": "5.897µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.660+0200 INFO kafka.kafka synced {"group": "group", "assigned": "topic[0]"}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka unblocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.660+0200 INFO kafka.kafka new group session begun {"group": "group", "added": "topic[0]", "lost": ""}
logger.go:146: 2024-05-23T15:36:34.660+0200 INFO kafka.kafka beginning heartbeat loop {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka entering OnPartitionsAssigned {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka sharded request {"req": "OffsetFetch", "destinations": ["0"]}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka wrote OffsetFetch v8 {"broker": "0", "bytes_written": 41, "write_wait": "22.058µs", "time_to_write": "11.545µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka read OffsetFetch v8 {"broker": "0", "bytes_read": 53, "read_wait": "118.527µs", "time_to_read": "6.823µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.660+0200 INFO kafka.kafka assigning partitions {"why": "newly fetched offsets for group group", "how": "assigning everything new, keeping current assignment", "input": "topic[0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:34.660+0200 DEBUG kafka.kafka assign requires loading offsets
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka offsets to load broker {"broker": 0, "load": {"List":{"topic":{"0":{"At":-2,"Epoch":-1,"CurrentEpoch":0}}},"Epoch":null}}
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka wrote ListOffsets v7 {"broker": "0", "bytes_written": 50, "write_wait": "26.091µs", "time_to_write": "13.356µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka read ListOffsets v7 {"broker": "0", "bytes_read": 50, "read_wait": "106.766µs", "time_to_read": "5.707µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka handled list results {"broker": "0", "using": {"topic":{"0":{"Epoch":0,"Offset":0}}}, "reloading": {}}
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.661+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "0", "bytes_written": 98, "write_wait": "282.028µs", "time_to_write": "15.498µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.668+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:42965", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:42965", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka issuing api versions request {"broker": "1", "version": 3}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "13.757µs", "time_to_write": "15.192µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "1", "bytes_read": 233, "read_wait": "87.439µs", "time_to_read": "6.773µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:42965", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "1", "bytes_written": 45, "write_wait": "487.867µs", "time_to_write": "11.303µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "1", "bytes_read": 159, "read_wait": "112.437µs", "time_to_read": "6.826µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.669+0200 INFO kafka.kafka initializing producer id
logger.go:146: 2024-05-23T15:36:34.669+0200 INFO kafka.kafka done waiting for metadata for new topic {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.669+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.670+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.670+0200 DEBUG kafka.kafka issuing api versions request {"broker": "0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.670+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "0", "bytes_written": 31, "write_wait": "17.329µs", "time_to_write": "16.581µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.670+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "0", "bytes_read": 233, "read_wait": "80.083µs", "time_to_read": "7.119µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.670+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.670+0200 DEBUG kafka.kafka wrote InitProducerID v4 {"broker": "0", "bytes_written": 34, "write_wait": "868.814µs", "time_to_write": "11.436µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.670+0200 DEBUG kafka.kafka read InitProducerID v4 {"broker": "0", "bytes_read": 26, "read_wait": "107.169µs", "time_to_read": "5.468µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.671+0200 INFO kafka.kafka producer id initialization success {"id": 6425834067608416339, "epoch": 0}
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:39423", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka wrote Produce v9 {"broker": "0", "bytes_written": 109, "write_wait": "261.971µs", "time_to_write": "16.57µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka read Produce v9 {"broker": "0", "bytes_read": 56, "read_wait": "99.173µs", "time_to_read": "6.005µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "0", "bytes_read": 144, "read_wait": "91.766µs", "time_to_read": "9.665813ms", "err": null}
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka produced {"broker": "0", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.671+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka flushed
logger.go:146: 2024-05-23T15:36:34.671+0200 DEBUG kafka.kafka updated uncommitted {"group": "group", "to": "topic[0{0=>1 r1}]"}
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka in CommitOffsetsSync {"group": "group", "with": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "0", "bytes_written": 98, "write_wait": "49.363µs", "time_to_write": "13.591µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka grabbed join/sync mu on first try
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka issuing commit {"group": "group", "uncommitted": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka wrote OffsetCommit v8 {"broker": "0", "bytes_written": 130, "write_wait": "21.394µs", "time_to_write": "13.246µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka read OffsetCommit v8 {"broker": "0", "bytes_read": 30, "read_wait": "105.634µs", "time_to_read": "5.882µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka updated committed {"group": "group", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.672+0200 DEBUG kafka.kafka left CommitOffsetsSync {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.672+0200 INFO kafka.partition committed {"topic": "topic", "partition": 0, "offset": 0}
logger.go:146: 2024-05-23T15:36:34.673+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.673+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "0", "bytes_read": 0, "read_wait": "90.54µs", "time_to_read": "1.399197ms", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.673+0200 INFO kafka.kafka heartbeat errored {"group": "group", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.673+0200 DEBUG kafka.kafka entering OnPartitionsRevoked {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.673+0200 INFO kafka.kafka assigning partitions {"why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.673+0200 INFO kafka.kafka leaving group {"group": "group", "member_id": "kgo-7f0f482aa69862b6fb21a9f533b723f6"}
logger.go:146: 2024-05-23T15:36:34.674+0200 DEBUG kafka.kafka wrote LeaveGroup v5 {"broker": "0", "bytes_written": 107, "write_wait": "27.266µs", "time_to_write": "15.37µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.674+0200 DEBUG kafka.kafka read LeaveGroup v5 {"broker": "0", "bytes_read": 58, "read_wait": "106.938µs", "time_to_read": "5.957µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.674+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.674+0200 DEBUG kafka.kafka flushed
=== RUN TestProducerGracefulShutdown/AtLeastOnceDelivery/async
=== NAME TestProducerGracefulShutdown
logger.go:146: 2024-05-23T15:36:34.674+0200 INFO kafka.kafka immediate metadata update triggered {"why": "from user ForceMetadataRefresh"}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:44381", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.675+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.675+0200 INFO kafka.kafka producing to a new topic for the first time, fetching metadata to learn its partitions {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.675+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:44381", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:44381", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:44381", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "19.196µs", "time_to_write": "15.362µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "117.815µs", "time_to_read": "7.03µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "13.575µs", "time_to_write": "14.123µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:44381", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "74.17µs", "time_to_read": "7.977µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:44381", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 22, "write_wait": "631.722µs", "time_to_write": "10.931µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 45, "write_wait": "513.702µs", "time_to_write": "11.043µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 86, "read_wait": "106.84µs", "time_to_read": "5.873µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 159, "read_wait": "79.57µs", "time_to_read": "5.602µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.675+0200 INFO kafka.kafka immediate metadata update triggered {"why": "forced load because we are producing to a topic for the first time"}
logger.go:146: 2024-05-23T15:36:34.676+0200 INFO kafka.kafka beginning to manage the group lifecycle {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka blocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.676+0200 INFO kafka.kafka joining group {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka prepared to issue find coordinator request {"coordinator_type": 0, "coordinator_keys": ["group"]}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka sharded request {"req": "FindCoordinator", "destinations": ["any"]}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:44381", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:44381", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka issuing api versions request {"broker": "0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "0", "bytes_written": 31, "write_wait": "12.491µs", "time_to_write": "15.676µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "0", "bytes_read": 233, "read_wait": "84.42µs", "time_to_read": "6.893µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:44381", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka wrote FindCoordinator v4 {"broker": "0", "bytes_written": 27, "write_wait": "474.57µs", "time_to_write": "11.54µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka read FindCoordinator v4 {"broker": "0", "bytes_read": 43, "read_wait": "100.248µs", "time_to_read": "5.635µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.676+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:44381", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.677+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:44381", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.677+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:44381", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.677+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 137, "write_wait": "274.625µs", "time_to_write": "17.971µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.677+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 62, "read_wait": "124.516µs", "time_to_read": "6.021µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.677+0200 INFO kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"group": "group", "member_id": "kgo-9747dc2169b84251461d4ed2125aff50"}
logger.go:146: 2024-05-23T15:36:34.677+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 173, "write_wait": "21.147µs", "time_to_write": "11.491µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.677+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 195, "read_wait": "96.41µs", "time_to_read": "5.621µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.677+0200 INFO kafka.kafka joined, balancing group {"group": "group", "member_id": "kgo-9747dc2169b84251461d4ed2125aff50", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:34.677+0200 INFO kafka.kafka balancing group as leader
logger.go:146: 2024-05-23T15:36:34.677+0200 INFO kafka.kafka balance group member {"id": "kgo-9747dc2169b84251461d4ed2125aff50", "interests": "interested topics: [topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:34.677+0200 INFO kafka.kafka balanced {"plan": "kgo-9747dc2169b84251461d4ed2125aff50{topic[0]}"}
logger.go:146: 2024-05-23T15:36:34.678+0200 INFO kafka.kafka syncing {"group": "group", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:34.678+0200 DEBUG kafka.kafka wrote SyncGroup v5 {"broker": "0", "bytes_written": 160, "write_wait": "21.233µs", "time_to_write": "11.985µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.678+0200 DEBUG kafka.kafka read SyncGroup v5 {"broker": "0", "bytes_read": 70, "read_wait": "80.702µs", "time_to_read": "5.579µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.678+0200 INFO kafka.kafka synced {"group": "group", "assigned": "topic[0]"}
logger.go:146: 2024-05-23T15:36:34.678+0200 DEBUG kafka.kafka unblocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.678+0200 INFO kafka.kafka new group session begun {"group": "group", "added": "topic[0]", "lost": ""}
logger.go:146: 2024-05-23T15:36:34.678+0200 INFO kafka.kafka beginning heartbeat loop {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.678+0200 DEBUG kafka.kafka entering OnPartitionsAssigned {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.678+0200 DEBUG kafka.kafka sharded request {"req": "OffsetFetch", "destinations": ["0"]}
logger.go:146: 2024-05-23T15:36:34.678+0200 DEBUG kafka.kafka wrote OffsetFetch v8 {"broker": "0", "bytes_written": 41, "write_wait": "20.58µs", "time_to_write": "12.647µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.678+0200 DEBUG kafka.kafka read OffsetFetch v8 {"broker": "0", "bytes_read": 53, "read_wait": "119.045µs", "time_to_read": "7.45µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.678+0200 INFO kafka.kafka assigning partitions {"why": "newly fetched offsets for group group", "how": "assigning everything new, keeping current assignment", "input": "topic[0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka assign requires loading offsets
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka offsets to load broker {"broker": 1, "load": {"List":{"topic":{"0":{"At":-2,"Epoch":-1,"CurrentEpoch":0}}},"Epoch":null}}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka issuing api versions request {"broker": "1", "version": 3}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "11.124µs", "time_to_write": "13.081µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "1", "bytes_read": 233, "read_wait": "96.513µs", "time_to_read": "7.423µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka wrote ListOffsets v7 {"broker": "1", "bytes_written": 50, "write_wait": "488.529µs", "time_to_write": "12.805µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka read ListOffsets v7 {"broker": "1", "bytes_read": 50, "read_wait": "89.715µs", "time_to_read": "7.684µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka handled list results {"broker": "1", "using": {"topic":{"0":{"Epoch":0,"Offset":0}}}, "reloading": {}}
logger.go:146: 2024-05-23T15:36:34.679+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.680+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.680+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.680+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "1", "bytes_written": 98, "write_wait": "310.726µs", "time_to_write": "14.026µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.686+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.686+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.686+0200 DEBUG kafka.kafka issuing api versions request {"broker": "1", "version": 3}
logger.go:146: 2024-05-23T15:36:34.686+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "21.657µs", "time_to_write": "13.79µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.686+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "1", "bytes_read": 233, "read_wait": "75.845µs", "time_to_read": "7.195µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "1", "bytes_written": 45, "write_wait": "554.393µs", "time_to_write": "10.372µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "1", "bytes_read": 159, "read_wait": "79.444µs", "time_to_read": "5.621µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.687+0200 INFO kafka.kafka done waiting for metadata for new topic {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.687+0200 INFO kafka.kafka initializing producer id
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka wrote InitProducerID v4 {"broker": "1", "bytes_written": 34, "write_wait": "22.719µs", "time_to_write": "11.861µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka read InitProducerID v4 {"broker": "1", "bytes_read": 26, "read_wait": "91.953µs", "time_to_read": "5.617µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.687+0200 INFO kafka.kafka producer id initialization success {"id": 4336320595849388572, "epoch": 0}
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.687+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:36325", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka wrote Produce v9 {"broker": "1", "bytes_written": 109, "write_wait": "289.448µs", "time_to_write": "17.4µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "1", "bytes_read": 144, "read_wait": "207.628µs", "time_to_read": "7.616531ms", "err": null}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka read Produce v9 {"broker": "1", "bytes_read": 56, "read_wait": "136.009µs", "time_to_read": "8.296µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka produced {"broker": "1", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka flushed
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka updated uncommitted {"group": "group", "to": "topic[0{0=>1 r1}]"}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "1", "bytes_written": 98, "write_wait": "45.67µs", "time_to_write": "11.773µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka in CommitOffsetsSync {"group": "group", "with": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka grabbed join/sync mu on first try
logger.go:146: 2024-05-23T15:36:34.688+0200 DEBUG kafka.kafka issuing commit {"group": "group", "uncommitted": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.689+0200 DEBUG kafka.kafka wrote OffsetCommit v8 {"broker": "0", "bytes_written": 130, "write_wait": "23.863µs", "time_to_write": "11.634µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.689+0200 DEBUG kafka.kafka read OffsetCommit v8 {"broker": "0", "bytes_read": 30, "read_wait": "98.067µs", "time_to_read": "6.593µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.689+0200 DEBUG kafka.kafka updated committed {"group": "group", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.689+0200 DEBUG kafka.kafka left CommitOffsetsSync {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.689+0200 INFO kafka.partition committed {"topic": "topic", "partition": 0, "offset": 0}
logger.go:146: 2024-05-23T15:36:34.690+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.690+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "1", "bytes_read": 0, "read_wait": "90.851µs", "time_to_read": "1.531024ms", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.690+0200 INFO kafka.kafka heartbeat errored {"group": "group", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.690+0200 DEBUG kafka.kafka entering OnPartitionsRevoked {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.690+0200 INFO kafka.kafka assigning partitions {"why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.690+0200 INFO kafka.kafka leaving group {"group": "group", "member_id": "kgo-9747dc2169b84251461d4ed2125aff50"}
logger.go:146: 2024-05-23T15:36:34.690+0200 DEBUG kafka.kafka wrote LeaveGroup v5 {"broker": "0", "bytes_written": 107, "write_wait": "29.269µs", "time_to_write": "10.91µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.690+0200 DEBUG kafka.kafka read LeaveGroup v5 {"broker": "0", "bytes_read": 58, "read_wait": "87.701µs", "time_to_read": "5.861µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.691+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.691+0200 DEBUG kafka.kafka flushed
=== RUN TestProducerGracefulShutdown/AtMostOnceDelivery
=== RUN TestProducerGracefulShutdown/AtMostOnceDelivery/sync
=== NAME TestProducerGracefulShutdown
logger.go:146: 2024-05-23T15:36:34.691+0200 INFO kafka.kafka immediate metadata update triggered {"why": "from user ForceMetadataRefresh"}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:43669", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.692+0200 INFO kafka.kafka producing to a new topic for the first time, fetching metadata to learn its partitions {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.692+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:43669", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:43669", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:43669", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "15.271µs", "time_to_write": "17.723µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "15.144µs", "time_to_write": "13.364µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "106.536µs", "time_to_read": "8.4µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "95.363µs", "time_to_read": "7.745µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:43669", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:43669", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 22, "write_wait": "691.155µs", "time_to_write": "13.838µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 45, "write_wait": "489.202µs", "time_to_write": "13.88µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 86, "read_wait": "104.247µs", "time_to_read": "7.855µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 159, "read_wait": "115.902µs", "time_to_read": "8.167µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.692+0200 INFO kafka.kafka immediate metadata update triggered {"why": "forced load because we are producing to a topic for the first time"}
logger.go:146: 2024-05-23T15:36:34.693+0200 INFO kafka.kafka beginning to manage the group lifecycle {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka blocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.693+0200 INFO kafka.kafka joining group {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka prepared to issue find coordinator request {"coordinator_type": 0, "coordinator_keys": ["group"]}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka sharded request {"req": "FindCoordinator", "destinations": ["any"]}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:34433", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:34433", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka issuing api versions request {"broker": "1", "version": 3}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "11.12µs", "time_to_write": "15.71µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "1", "bytes_read": 233, "read_wait": "98.035µs", "time_to_read": "5.947µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:34433", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka wrote FindCoordinator v4 {"broker": "1", "bytes_written": 27, "write_wait": "480.613µs", "time_to_write": "10.744µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.693+0200 DEBUG kafka.kafka read FindCoordinator v4 {"broker": "1", "bytes_read": 43, "read_wait": "91.086µs", "time_to_read": "6.737µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka issuing api versions request {"broker": "0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "0", "bytes_written": 31, "write_wait": "13.437µs", "time_to_write": "13.686µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "0", "bytes_read": 233, "read_wait": "81.556µs", "time_to_read": "7.626µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 137, "write_wait": "476.01µs", "time_to_write": "13.095µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 62, "read_wait": "95.476µs", "time_to_read": "5.174µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.694+0200 INFO kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"group": "group", "member_id": "kgo-b9837c41b2ca6cf1a38602d8335f6a83"}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 173, "write_wait": "22.588µs", "time_to_write": "11.772µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.694+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 195, "read_wait": "90.116µs", "time_to_read": "6.013µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.694+0200 INFO kafka.kafka joined, balancing group {"group": "group", "member_id": "kgo-b9837c41b2ca6cf1a38602d8335f6a83", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:34.695+0200 INFO kafka.kafka balancing group as leader
logger.go:146: 2024-05-23T15:36:34.695+0200 INFO kafka.kafka balance group member {"id": "kgo-b9837c41b2ca6cf1a38602d8335f6a83", "interests": "interested topics: [topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:34.695+0200 INFO kafka.kafka balanced {"plan": "kgo-b9837c41b2ca6cf1a38602d8335f6a83{topic[0]}"}
logger.go:146: 2024-05-23T15:36:34.695+0200 INFO kafka.kafka syncing {"group": "group", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:34.695+0200 DEBUG kafka.kafka wrote SyncGroup v5 {"broker": "0", "bytes_written": 160, "write_wait": "19.723µs", "time_to_write": "12.596µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.695+0200 DEBUG kafka.kafka read SyncGroup v5 {"broker": "0", "bytes_read": 70, "read_wait": "93.503µs", "time_to_read": "7.187µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.695+0200 INFO kafka.kafka synced {"group": "group", "assigned": "topic[0]"}
logger.go:146: 2024-05-23T15:36:34.695+0200 DEBUG kafka.kafka unblocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.695+0200 INFO kafka.kafka new group session begun {"group": "group", "added": "topic[0]", "lost": ""}
logger.go:146: 2024-05-23T15:36:34.695+0200 INFO kafka.kafka beginning heartbeat loop {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.695+0200 DEBUG kafka.kafka entering OnPartitionsAssigned {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.695+0200 DEBUG kafka.kafka sharded request {"req": "OffsetFetch", "destinations": ["0"]}
logger.go:146: 2024-05-23T15:36:34.695+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka wrote OffsetFetch v8 {"broker": "0", "bytes_written": 41, "write_wait": "235.504µs", "time_to_write": "13.507µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka read OffsetFetch v8 {"broker": "0", "bytes_read": 53, "read_wait": "94.379µs", "time_to_read": "5.878µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.696+0200 INFO kafka.kafka assigning partitions {"why": "newly fetched offsets for group group", "how": "assigning everything new, keeping current assignment", "input": "topic[0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka assign requires loading offsets
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka offsets to load broker {"broker": 0, "load": {"List":{"topic":{"0":{"At":-2,"Epoch":-1,"CurrentEpoch":0}}},"Epoch":null}}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka wrote ListOffsets v7 {"broker": "0", "bytes_written": 50, "write_wait": "21.387µs", "time_to_write": "10.95µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka read ListOffsets v7 {"broker": "0", "bytes_read": 50, "read_wait": "87.59µs", "time_to_read": "5.825µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka handled list results {"broker": "0", "using": {"topic":{"0":{"Epoch":0,"Offset":0}}}, "reloading": {}}
logger.go:146: 2024-05-23T15:36:34.696+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.697+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.697+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.697+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "0", "bytes_written": 98, "write_wait": "285.788µs", "time_to_write": "13.944µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.703+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:34433", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.703+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:34433", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.703+0200 DEBUG kafka.kafka issuing api versions request {"broker": "1", "version": 3}
logger.go:146: 2024-05-23T15:36:34.703+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "12.682µs", "time_to_write": "15.313µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.703+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "1", "bytes_read": 233, "read_wait": "81.159µs", "time_to_read": "6.889µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.704+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:34433", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.704+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "1", "bytes_written": 45, "write_wait": "989.506µs", "time_to_write": "11.867µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.704+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "1", "bytes_read": 159, "read_wait": "114.076µs", "time_to_read": "7.846µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.704+0200 INFO kafka.kafka done waiting for metadata for new topic {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.704+0200 INFO kafka.kafka initializing producer id
logger.go:146: 2024-05-23T15:36:34.704+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka issuing api versions request {"broker": "0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "0", "bytes_written": 31, "write_wait": "11.344µs", "time_to_write": "14.033µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "0", "bytes_read": 233, "read_wait": "89.961µs", "time_to_read": "6.175µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka wrote InitProducerID v4 {"broker": "0", "bytes_written": 34, "write_wait": "468.531µs", "time_to_write": "10.607µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka read InitProducerID v4 {"broker": "0", "bytes_read": 26, "read_wait": "80.028µs", "time_to_read": "5.366µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.705+0200 INFO kafka.kafka producer id initialization success {"id": 2012240115850608259, "epoch": 0}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:43669", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.705+0200 DEBUG kafka.kafka wrote Produce v9 {"broker": "0", "bytes_written": 109, "write_wait": "316.096µs", "time_to_write": "17.133µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "0", "bytes_read": 144, "read_wait": "96.561µs", "time_to_read": "8.668409ms", "err": null}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka read Produce v9 {"broker": "0", "bytes_read": 56, "read_wait": "125.964µs", "time_to_read": "8.178µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka produced {"broker": "0", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.706+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka flushed
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka updated uncommitted {"group": "group", "to": "topic[0{0=>1 r1}]"}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka in CommitOffsetsSync {"group": "group", "with": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka grabbed join/sync mu on first try
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka issuing commit {"group": "group", "uncommitted": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "0", "bytes_written": 98, "write_wait": "56.644µs", "time_to_write": "11.418µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka wrote OffsetCommit v8 {"broker": "0", "bytes_written": 130, "write_wait": "29.294µs", "time_to_write": "11.349µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka read OffsetCommit v8 {"broker": "0", "bytes_read": 30, "read_wait": "109.891µs", "time_to_read": "5.932µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.706+0200 DEBUG kafka.kafka updated committed {"group": "group", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.707+0200 DEBUG kafka.kafka left CommitOffsetsSync {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.708+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.708+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "0", "bytes_read": 0, "read_wait": "128.535µs", "time_to_read": "1.284766ms", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.708+0200 INFO kafka.kafka heartbeat errored {"group": "group", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.708+0200 DEBUG kafka.kafka entering OnPartitionsRevoked {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.708+0200 INFO kafka.kafka assigning partitions {"why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.708+0200 INFO kafka.kafka leaving group {"group": "group", "member_id": "kgo-b9837c41b2ca6cf1a38602d8335f6a83"}
logger.go:146: 2024-05-23T15:36:34.708+0200 DEBUG kafka.kafka wrote LeaveGroup v5 {"broker": "0", "bytes_written": 107, "write_wait": "22.727µs", "time_to_write": "12.493µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.708+0200 DEBUG kafka.kafka read LeaveGroup v5 {"broker": "0", "bytes_read": 58, "read_wait": "109.025µs", "time_to_read": "7.147µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.708+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.708+0200 DEBUG kafka.kafka flushed
=== RUN TestProducerGracefulShutdown/AtMostOnceDelivery/async
=== NAME TestProducerGracefulShutdown
logger.go:146: 2024-05-23T15:36:34.709+0200 INFO kafka.kafka immediate metadata update triggered {"why": "from user ForceMetadataRefresh"}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:35553", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.709+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.709+0200 INFO kafka.kafka immediate metadata update triggered {"why": "querying metadata for consumer initialization"}
logger.go:146: 2024-05-23T15:36:34.709+0200 INFO kafka.kafka producing to a new topic for the first time, fetching metadata to learn its partitions {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:35553", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:35553", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:35553", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka issuing api versions request {"broker": "seed_0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "17.103µs", "time_to_write": "14.479µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "12.353µs", "time_to_write": "13.942µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "109.014µs", "time_to_read": "10.049µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "seed_0", "bytes_read": 233, "read_wait": "79.246µs", "time_to_read": "5.944µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:35553", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.709+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:35553", "broker": "seed_0"}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 22, "write_wait": "709.999µs", "time_to_write": "11.768µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "seed_0", "bytes_written": 45, "write_wait": "549.899µs", "time_to_write": "14.036µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 86, "read_wait": "84.364µs", "time_to_read": "5.594µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "seed_0", "bytes_read": 159, "read_wait": "116.805µs", "time_to_read": "5.745µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.710+0200 INFO kafka.kafka immediate metadata update triggered {"why": "forced load because we are producing to a topic for the first time"}
logger.go:146: 2024-05-23T15:36:34.710+0200 INFO kafka.kafka beginning to manage the group lifecycle {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka blocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.710+0200 INFO kafka.kafka joining group {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka prepared to issue find coordinator request {"coordinator_type": 0, "coordinator_keys": ["group"]}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka sharded request {"req": "FindCoordinator", "destinations": ["any"]}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:33047", "broker": "2"}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:33047", "broker": "2"}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka issuing api versions request {"broker": "2", "version": 3}
logger.go:146: 2024-05-23T15:36:34.710+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "2", "bytes_written": 31, "write_wait": "17.423µs", "time_to_write": "16.753µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "2", "bytes_read": 233, "read_wait": "116.618µs", "time_to_read": "9.251µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:33047", "broker": "2"}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka wrote FindCoordinator v4 {"broker": "2", "bytes_written": 27, "write_wait": "588.648µs", "time_to_write": "10.794µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka read FindCoordinator v4 {"broker": "2", "bytes_read": 43, "read_wait": "78.97µs", "time_to_read": "5.508µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka issuing api versions request {"broker": "0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "0", "bytes_written": 31, "write_wait": "13.562µs", "time_to_write": "14.518µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "0", "bytes_read": 233, "read_wait": "83.837µs", "time_to_read": "6.521µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.711+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 137, "write_wait": "483.554µs", "time_to_write": "11.201µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.712+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 62, "read_wait": "108.83µs", "time_to_read": "7.941µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"group": "group", "member_id": "kgo-cdac814240feb576d530dbfd90f72755"}
logger.go:146: 2024-05-23T15:36:34.712+0200 DEBUG kafka.kafka wrote JoinGroup v9 {"broker": "0", "bytes_written": 173, "write_wait": "22.801µs", "time_to_write": "12.734µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.712+0200 DEBUG kafka.kafka read JoinGroup v9 {"broker": "0", "bytes_read": 195, "read_wait": "88.45µs", "time_to_read": "6.751µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka joined, balancing group {"group": "group", "member_id": "kgo-cdac814240feb576d530dbfd90f72755", "instance_id": "", "generation": 1, "balance_protocol": "cooperative-sticky", "leader": true}
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka balancing group as leader
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka balance group member {"id": "kgo-cdac814240feb576d530dbfd90f72755", "interests": "interested topics: [topic], previously owned: "}
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka balanced {"plan": "kgo-cdac814240feb576d530dbfd90f72755{topic[0]}"}
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka syncing {"group": "group", "protocol_type": "consumer", "protocol": "cooperative-sticky"}
logger.go:146: 2024-05-23T15:36:34.712+0200 DEBUG kafka.kafka wrote SyncGroup v5 {"broker": "0", "bytes_written": 160, "write_wait": "24.764µs", "time_to_write": "13.173µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.712+0200 DEBUG kafka.kafka read SyncGroup v5 {"broker": "0", "bytes_read": 70, "read_wait": "92.55µs", "time_to_read": "5.62µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka synced {"group": "group", "assigned": "topic[0]"}
logger.go:146: 2024-05-23T15:36:34.712+0200 DEBUG kafka.kafka unblocking commits from join&sync
logger.go:146: 2024-05-23T15:36:34.712+0200 INFO kafka.kafka new group session begun {"group": "group", "added": "topic[0]", "lost": ""}
logger.go:146: 2024-05-23T15:36:34.713+0200 INFO kafka.kafka beginning heartbeat loop {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka entering OnPartitionsAssigned {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka sharded request {"req": "OffsetFetch", "destinations": ["0"]}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka wrote OffsetFetch v8 {"broker": "0", "bytes_written": 41, "write_wait": "261.869µs", "time_to_write": "26.487µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka read OffsetFetch v8 {"broker": "0", "bytes_read": 53, "read_wait": "102.423µs", "time_to_read": "6.109µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.713+0200 INFO kafka.kafka assigning partitions {"why": "newly fetched offsets for group group", "how": "assigning everything new, keeping current assignment", "input": "topic[0{-2 e-1 ce0}]"}
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka assign requires loading offsets
logger.go:146: 2024-05-23T15:36:34.713+0200 DEBUG kafka.kafka offsets to load broker {"broker": 1, "load": {"List":{"topic":{"0":{"At":-2,"Epoch":-1,"CurrentEpoch":0}}},"Epoch":null}}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka issuing api versions request {"broker": "1", "version": 3}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "11.58µs", "time_to_write": "13.037µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "1", "bytes_read": 233, "read_wait": "68.218µs", "time_to_read": "5.95µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka wrote ListOffsets v7 {"broker": "1", "bytes_written": 50, "write_wait": "417.225µs", "time_to_write": "10.493µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka read ListOffsets v7 {"broker": "1", "bytes_read": 50, "read_wait": "68.39µs", "time_to_read": "5.385µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka handled list results {"broker": "1", "using": {"topic":{"0":{"Epoch":0,"Offset":0}}}, "reloading": {}}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.714+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.715+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "1", "bytes_written": 98, "write_wait": "295.749µs", "time_to_write": "12.718µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka issuing api versions request {"broker": "0", "version": 3}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "0", "bytes_written": 31, "write_wait": "11.293µs", "time_to_write": "13.146µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "0", "bytes_read": 233, "read_wait": "81.25µs", "time_to_read": "7.06µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:35553", "broker": "0"}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka wrote Metadata v12 {"broker": "0", "bytes_written": 45, "write_wait": "487.747µs", "time_to_write": "11.591µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.721+0200 DEBUG kafka.kafka read Metadata v12 {"broker": "0", "bytes_read": 159, "read_wait": "73.396µs", "time_to_read": "5.521µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.721+0200 INFO kafka.kafka done waiting for metadata for new topic {"topic": "topic"}
logger.go:146: 2024-05-23T15:36:34.721+0200 INFO kafka.kafka initializing producer id
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka wrote InitProducerID v4 {"broker": "0", "bytes_written": 34, "write_wait": "24.316µs", "time_to_write": "10.918µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka read InitProducerID v4 {"broker": "0", "bytes_read": 26, "read_wait": "96.35µs", "time_to_read": "6.997µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.722+0200 INFO kafka.kafka producer id initialization success {"id": 8982604641119692596, "epoch": 0}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka opening connection to broker {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka connection opened to broker {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka issuing api versions request {"broker": "1", "version": 3}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "10.589µs", "time_to_write": "14.417µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka read ApiVersions v3 {"broker": "1", "bytes_read": 233, "read_wait": "71.42µs", "time_to_read": "9.379µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka connection initialized successfully {"addr": "127.0.0.1:37547", "broker": "1"}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka wrote Produce v9 {"broker": "1", "bytes_written": 109, "write_wait": "506.442µs", "time_to_write": "11.188µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka read Produce v9 {"broker": "1", "bytes_read": 56, "read_wait": "76.404µs", "time_to_read": "5.799µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.722+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "1", "bytes_read": 144, "read_wait": "96.357µs", "time_to_read": "7.834941ms", "err": null}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka produced {"broker": "1", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka flushed
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka updated uncommitted {"group": "group", "to": "topic[0{0=>1 r1}]"}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka in CommitOffsetsSync {"group": "group", "with": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka grabbed join/sync mu on first try
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka wrote Fetch v13 {"broker": "1", "bytes_written": 98, "write_wait": "57.176µs", "time_to_write": "10.987µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka issuing commit {"group": "group", "uncommitted": {"topic":{"0":{"Epoch":0,"Offset":1}}}}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka wrote OffsetCommit v8 {"broker": "0", "bytes_written": 130, "write_wait": "20.504µs", "time_to_write": "11.844µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka read OffsetCommit v8 {"broker": "0", "bytes_read": 30, "read_wait": "90.889µs", "time_to_read": "5.836µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka updated committed {"group": "group", "to": "topic[0{0=>1}]"}
logger.go:146: 2024-05-23T15:36:34.723+0200 DEBUG kafka.kafka left CommitOffsetsSync {"group": "group"}
logger.go:146: 2024-05-23T15:36:34.724+0200 INFO kafka.kafka assigning partitions {"why": "invalidating all assignments in LeaveGroup", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.725+0200 DEBUG kafka.kafka read Fetch v13 {"broker": "1", "bytes_read": 0, "read_wait": "93.254µs", "time_to_read": "1.430709ms", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.725+0200 INFO kafka.kafka heartbeat errored {"group": "group", "err": "context canceled"}
logger.go:146: 2024-05-23T15:36:34.725+0200 DEBUG kafka.kafka entering OnPartitionsRevoked {"with": {"topic":[0]}}
logger.go:146: 2024-05-23T15:36:34.725+0200 INFO kafka.kafka assigning partitions {"why": "clearing assignment at end of group management session", "how": "unassigning everything", "input": ""}
logger.go:146: 2024-05-23T15:36:34.725+0200 INFO kafka.kafka leaving group {"group": "group", "member_id": "kgo-cdac814240feb576d530dbfd90f72755"}
logger.go:146: 2024-05-23T15:36:34.725+0200 DEBUG kafka.kafka wrote LeaveGroup v5 {"broker": "0", "bytes_written": 107, "write_wait": "23.425µs", "time_to_write": "11.71µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.725+0200 DEBUG kafka.kafka read LeaveGroup v5 {"broker": "0", "bytes_read": 58, "read_wait": "93.118µs", "time_to_read": "5.727µs", "err": null}
logger.go:146: 2024-05-23T15:36:34.725+0200 INFO kafka.kafka flushing
logger.go:146: 2024-05-23T15:36:34.725+0200 DEBUG kafka.kafka flushed
--- PASS: TestProducerGracefulShutdown (0.07s)
--- PASS: TestProducerGracefulShutdown/AtLeastOnceDelivery (0.03s)
--- PASS: TestProducerGracefulShutdown/AtLeastOnceDelivery/sync (0.02s)
--- PASS: TestProducerGracefulShutdown/AtLeastOnceDelivery/async (0.02s)
--- PASS: TestProducerGracefulShutdown/AtMostOnceDelivery (0.03s)
--- PASS: TestProducerGracefulShutdown/AtMostOnceDelivery/sync (0.02s)
--- PASS: TestProducerGracefulShutdown/AtMostOnceDelivery/async (0.02s)
=== RUN TestProducerConcurrentClose
--- PASS: TestProducerConcurrentClose (0.00s)
=== RUN TestNewTopicCreator
--- PASS: TestNewTopicCreator (0.00s)
=== RUN TestTopicCreatorCreateTopics
topiccreator_test.go:217: kafka topic already exists
topiccreator_test.go:217: kafka topic already exists
topiccreator_test.go:217: created kafka topic
topiccreator_test.go:217: updated partitions for kafka topic
topiccreator_test.go:217: altered configuration for kafka topic
--- PASS: TestTopicCreatorCreateTopics (0.31s)
PASS
ok github.com/elastic/apm-queue/v2/kafka 2.700s
=== RUN TestNewConsumer
=== RUN TestNewConsumer/empty_config
=== RUN TestNewConsumer/invalid_delivery_type
--- PASS: TestNewConsumer (0.00s)
--- PASS: TestNewConsumer/empty_config (0.00s)
--- PASS: TestNewConsumer/invalid_delivery_type (0.00s)
=== RUN TestConsumerConsume
--- PASS: TestConsumerConsume (0.06s)
=== RUN TestNewManager
--- PASS: TestNewManager (0.00s)
=== RUN TestNewManagerDefaultProject
--- PASS: TestNewManagerDefaultProject (0.00s)
=== RUN TestManagerCreateReservation
--- PASS: TestManagerCreateReservation (0.00s)
=== RUN TestManagerCreateSubscription
--- PASS: TestManagerCreateSubscription (0.01s)
=== RUN TestManagerDeleteReservation
--- PASS: TestManagerDeleteReservation (0.00s)
=== RUN TestManagerDeleteTopic
--- PASS: TestManagerDeleteTopic (0.00s)
=== RUN TestManagerDeleteSubscription
--- PASS: TestManagerDeleteSubscription (0.00s)
=== RUN TestManagerListReservations
--- PASS: TestManagerListReservations (0.00s)
=== RUN TestManagerListReservationTopics
--- PASS: TestManagerListReservationTopics (0.00s)
=== RUN TestManagerListTopicSubscriptions
--- PASS: TestManagerListTopicSubscriptions (0.00s)
=== RUN TestManagerMetrics
--- PASS: TestManagerMetrics (0.00s)
=== RUN TestNewProducer
--- PASS: TestNewProducer (0.00s)
=== RUN TestProducerProduce
--- PASS: TestProducerProduce (0.02s)
=== RUN TestProducerConcurrentClose
--- PASS: TestProducerConcurrentClose (0.00s)
=== RUN TestManagerNewTopicCreator
--- PASS: TestManagerNewTopicCreator (0.00s)
=== RUN TestTopicCreatorCreateTopics
--- PASS: TestTopicCreatorCreateTopics (0.00s)
PASS
ok github.com/elastic/apm-queue/v2/pubsublite (cached)
=== RUN TestWrap
--- PASS: TestWrap (0.00s)
PASS
ok github.com/elastic/apm-queue/v2/pubsublite/internal/pubsubabs (cached)
=== RUN TestConsumer
=== RUN TestConsumer/with_no_message
=== RUN TestConsumer/with_no_attributes
=== RUN TestConsumer/with_attributes_that_don't_match_a_parent_span
=== RUN TestConsumer/with_attributes_that_matches_a_parent_span
=== RUN TestConsumer/with_an_event_time_attribute
--- PASS: TestConsumer (0.00s)
--- PASS: TestConsumer/with_no_message (0.00s)
--- PASS: TestConsumer/with_no_attributes (0.00s)
--- PASS: TestConsumer/with_attributes_that_don't_match_a_parent_span (0.00s)
--- PASS: TestConsumer/with_attributes_that_matches_a_parent_span (0.00s)
--- PASS: TestConsumer/with_an_event_time_attribute (0.00s)
=== RUN TestConsumerMultipleEvents
--- PASS: TestConsumerMultipleEvents (0.00s)
=== RUN TestPublisher
=== RUN TestPublisher/failure_with_no_attributes
=== RUN TestPublisher/success_with_otel_attributes
=== RUN TestPublisher/success_with_otel_attributes#01
--- PASS: TestPublisher (0.00s)
--- PASS: TestPublisher/failure_with_no_attributes (0.00s)
--- PASS: TestPublisher/success_with_otel_attributes (0.00s)
--- PASS: TestPublisher/success_with_otel_attributes#01 (0.00s)
PASS
ok github.com/elastic/apm-queue/v2/pubsublite/internal/telemetry (cached)
=== RUN TestDetachedContext
--- PASS: TestDetachedContext (0.00s)
=== RUN TestEnrichedContext
--- PASS: TestEnrichedContext (0.00s)
PASS
ok github.com/elastic/apm-queue/v2/queuecontext (cached)
2024-05-23T15:36:33.735+0200 INFO systemtest/main_test.go:42 skipping system tests, pass -run-system-tests to enable
ok github.com/elastic/apm-queue/v2/systemtest 1.395s
make[1]: Leaving directory '/home/endorama/code/github.com/elastic/apm-queue'
```
to this:
$ make test
go test -race -timeout=60s ./...
? github.com/elastic/apm-queue/v2 [no test files]
? github.com/elastic/apm-queue/v2/cmd/queuebench [no test files]
? github.com/elastic/apm-queue/v2/metrictest [no test files]
ok github.com/elastic/apm-queue/v2/kafka 3.150s
ok github.com/elastic/apm-queue/v2/pubsublite (cached)
ok github.com/elastic/apm-queue/v2/pubsublite/internal/pubsubabs (cached)
ok github.com/elastic/apm-queue/v2/pubsublite/internal/telemetry (cached)
ok github.com/elastic/apm-queue/v2/queuecontext (cached)
ok github.com/elastic/apm-queue/v2/systemtest 1.664s
Current producer tests set up a zap debug logger that is quite verbose. Going through this big output when trying to identify a specific test failure (which may be unrelated to the verbose tests) is quite painful.
To address this in this PR the debug logger is only initialized when
-vis specified. This allows the choice to developers to run with or without the verbose logger enabled. It also updatesmake testto run go test in non verbose mode and adds an additional make target,test-verboseto run with-v.This change is reflected in CI where the less verbose target is used, but I don't have strong opinions there. I see the debug logger as a development/bugfixing aid more than useful information to have on CI and there is the dedicated
test-verbosemake target for such scenarios.We get from this:
Details
``` $ make test-verbose make test GO_VERBOSE=-v make[1]: Entering directory '/home/endorama/code/github.com/elastic/apm-queue' go test -race -v -timeout=60s ./... ? github.com/elastic/apm-queue/v2 [no test files] ? github.com/elastic/apm-queue/v2/cmd/queuebench [no test files] ? github.com/elastic/apm-queue/v2/metrictest [no test files] === RUN TestCommonConfig === RUN TestCommonConfig/invalid === RUN TestCommonConfig/tls_or_dialer === RUN TestCommonConfig/valid === RUN TestCommonConfig/brokers_from_environment === RUN TestCommonConfig/saslplain_from_environment === RUN TestCommonConfig/saslaws_from_environment === RUN TestCommonConfig/saslaws_from_environment/access_key_env === RUN TestCommonConfig/saslaws_from_environment/credentials_file === RUN TestCommonConfig/tls_from_environment === RUN TestCommonConfig/tls_from_environment/plaintext === RUN TestCommonConfig/tls_from_environment/tls_default === RUN TestCommonConfig/tls_from_environment/tls_insecure === RUN TestCommonConfig/configfile_from_env === RUN TestCommonConfig/brokers_from_configfile === RUN TestCommonConfig/sasl_from_configfile --- PASS: TestCommonConfig (0.01s) --- PASS: TestCommonConfig/invalid (0.00s) --- PASS: TestCommonConfig/tls_or_dialer (0.00s) --- PASS: TestCommonConfig/valid (0.00s) --- PASS: TestCommonConfig/brokers_from_environment (0.00s) --- PASS: TestCommonConfig/saslplain_from_environment (0.00s) --- PASS: TestCommonConfig/saslaws_from_environment (0.00s) --- PASS: TestCommonConfig/saslaws_from_environment/access_key_env (0.00s) --- PASS: TestCommonConfig/saslaws_from_environment/credentials_file (0.00s) --- PASS: TestCommonConfig/tls_from_environment (0.00s) --- PASS: TestCommonConfig/tls_from_environment/plaintext (0.00s) --- PASS: TestCommonConfig/tls_from_environment/tls_default (0.00s) --- PASS: TestCommonConfig/tls_from_environment/tls_insecure (0.00s) --- PASS: TestCommonConfig/configfile_from_env (0.00s) --- PASS: TestCommonConfig/brokers_from_configfile (0.00s) --- PASS: TestCommonConfig/sasl_from_configfile (0.00s) === RUN TestCommonConfigFileHook --- PASS: TestCommonConfigFileHook (0.08s) === RUN TestLoadConfigFile === RUN TestLoadConfigFile/file_does_not_exist === RUN TestLoadConfigFile/file_contents_are_invalid === RUN TestLoadConfigFile/file_contents_are_empty === RUN TestLoadConfigFile/file_contents_are_non-empty --- PASS: TestLoadConfigFile (0.00s) --- PASS: TestLoadConfigFile/file_does_not_exist (0.00s) --- PASS: TestLoadConfigFile/file_contents_are_invalid (0.00s) --- PASS: TestLoadConfigFile/file_contents_are_empty (0.00s) --- PASS: TestLoadConfigFile/file_contents_are_non-empty (0.00s) === RUN TestNewConsumer === RUN TestNewConsumer/valid === RUN TestNewConsumer/empty === RUN TestNewConsumer/invalid_client_consumer_options --- PASS: TestNewConsumer (0.00s) --- PASS: TestNewConsumer/valid (0.00s) --- PASS: TestNewConsumer/empty (0.00s) --- PASS: TestNewConsumer/invalid_client_consumer_options (0.00s) === RUN TestConsumerHealth === RUN TestConsumerHealth/success === RUN TestConsumerHealth/failure --- PASS: TestConsumerHealth (0.00s) --- PASS: TestConsumerHealth/success (0.00s) --- PASS: TestConsumerHealth/failure (0.00s) === RUN TestConsumerInstrumentation --- PASS: TestConsumerInstrumentation (0.01s) === RUN TestConsumerDelivery === RUN TestConsumerDelivery/30_produced_2_poll_ALOD logger.go:146: 2024-05-23T15:36:33.835+0200 INFO 1.kafka.kafka immediate metadata update triggered {"namespace": "name_space", "why": "querying metadata for consumer initialization"} logger.go:146: 2024-05-23T15:36:33.836+0200 INFO 1.kafka.kafka beginning to manage the group lifecycle {"namespace": "name_space", "group": "groupid"} logger.go:146: 2024-05-23T15:36:33.836+0200 INFO 1.kafka.kafka joining group {"namespace": "name_space", "group": "groupid"} logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka join returned MemberIDRequired, rejoining with response's MemberID {"namespace": "name_space", "group": "groupid", "member_id": "kgo-0b143763f039e5ce0cb5d36ef9bdb122"} logger.go:146: 2024-05-23T15:36:33.837+0200 INFO 1.kafka.kafka joined, balancing group {"namespace": "name_space", "group": "groupid", "member_id": "kgo-0b143763f039e5ce0cb5d36ef9bdb122", "instance_id": "to this: