redpanda
redpanda copied to clipboard
Published
20 hours ago •
redpanda-data
redpanda-data
CI Failure (`RpkException: unable to produce record: records have timed out before they were able to be produced`) in `ConsumerGroupBalancingTest.test_coordinator_nodes_balance`
https://buildkite.com/redpanda/redpanda/builds/46357
Module: rptest.tests.consumer_group_balancing_test
Class: ConsumerGroupBalancingTest
Method: test_coordinator_nodes_balance
test_id: ConsumerGroupBalancingTest.test_coordinator_nodes_balance
status: FAIL
run time: 19.148 seconds
RpkException('command /var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-0ed3e41583d71dc2e-1/redpanda/redpanda/vbuild/redpanda_installs/ci/bin/rpk topic -X brokers=docker-rp-7:9092,docker-rp-14:9092,docker-rp-22:9092,docker-rp-9:9092,docker-rp-20:9092 produce --key test_key -z none --delivery-timeout 5s -f %v topic-cyylpyflxq -p 0 -v returned 1, output: ', '13:28:45.089 INFO flushing\n13:28:45.090 INFO producing to a new topic for the first time, fetching metadata to learn its partitions {"topic": "topic-cyylpyflxq"}\n13:28:45.089 INFO immediate metadata update triggered {"why": "forced load because we are producing to a topic for the first time"}\n13:28:45.090 DEBUG opening connection to broker {"addr": "docker-rp-7:9092", "broker": "seed_0"}\n13:28:45.090 DEBUG connection opened to broker {"addr": "docker-rp-7:9092", "broker": "seed_0"}\n13:28:45.090 DEBUG issuing api versions request {"broker": "seed_0", "version": 3}\n13:28:45.090 DEBUG wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "18.603µs", "time_to_write": "15.764µs", "err": null}\n13:28:45.091 DEBUG read ApiVersions v3 {"broker": "seed_0", "bytes_read": 296, "read_wait": "21.456µs", "time_to_read": "232.816µs", "err": null}\n13:28:45.091 DEBUG connection initialized successfully {"addr": "docker-rp-7:9092", "broker": "seed_0"}\n13:28:45.091 DEBUG wrote Metadata v7 {"broker": "seed_0", "bytes_written": 40, "write_wait": "980.988µs", "time_to_write": "16.573µs", "err": null}\n13:28:45.091 DEBUG read Metadata v7 {"broker": "seed_0", "bytes_read": 264, "read_wait": "20.711µs", "time_to_read": "104.187µs", "err": null}\n13:28:45.091 INFO done waiting for metadata for new topic {"topic": "topic-cyylpyflxq"}\n13:28:45.091 INFO initializing producer id\n13:28:45.091 DEBUG opening connection to broker {"addr": "docker-rp-20:9092", "broker": "5"}\n13:28:45.091 DEBUG connection opened to broker {"addr": "docker-rp-20:9092", "broker": "5"}\n13:28:45.091 DEBUG issuing api versions request {"broker": "5", "version": 3}\n13:28:45.091 DEBUG wrote ApiVersions v3 {"broker": "5", "bytes_written": 31, "write_wait": "3.955µs", "time_to_write": "13.736µs", "err": null}\n13:28:45.091 DEBUG read ApiVersions v3 {"broker": "5", "bytes_read": 296, "read_wait": "9.877µs", "time_to_read": "198.463µs", "err": null}\n13:28:45.091 DEBUG connection initialized successfully {"addr": "docker-rp-20:9092", "broker": "5"}\n13:28:45.091 DEBUG wrote InitProducerID v3 {"broker": "5", "bytes_written": 34, "write_wait": "571.356µs", "time_to_write": "9.65µs", "err": null}\n13:28:50.095 DEBUG read InitProducerID v3 {"broker": "5", "bytes_read": 0, "read_wait": "20.509µs", "time_to_read": "5.003717781s", "err": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout"}\n13:28:50.095 WARN read from broker errored, killing connection after 0 successful responses (is SASL missing?) {"addr": "docker-rp-20:9092", "broker": "5", "err": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout"}\n13:28:50.095 DEBUG retrying request {"tries": 1, "backoff": "209.267263ms", "request_error": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout", "response_error": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout"}\n13:28:50.305 DEBUG opening connection to broker {"addr": "docker-rp-22:9092", "broker": "1"}\n13:28:50.305 DEBUG connection opened to broker {"addr": "docker-rp-22:9092", "broker": "1"}\n13:28:50.305 DEBUG issuing api versions request {"broker": "1", "version": 3}\n13:28:50.305 DEBUG wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "8.501µs", "time_to_write": "29.48µs", "err": null}\n13:28:50.306 DEBUG read ApiVersions v3 {"broker": "1", "bytes_read": 296, "read_wait": "21.62µs", "time_to_read": "158.767µs", "err": null}\n13:28:50.306 DEBUG connection initialized successfully {"addr": "docker-rp-22:9092", "broker": "1"}\n13:28:50.306 DEBUG wrote InitProducerID v3 {"broker": "1", "bytes_written": 34, "write_wait": "943.138µs", "time_to_write": "15.612µs", "err": null}\n13:28:50.306 DEBUG read InitProducerID v3 {"broker": "1", "bytes_read": 26, "read_wait": "27.979µs", "time_to_read": "106.553µs", "err": null}\n13:28:50.306 INFO producer id initialization success {"id": 2, "epoch": 0}\nunable to produce record: records have timed out before they were able to be produced\n', 1, '')
Traceback (most recent call last):
File "/usr/local/lib/python3.10/dist-packages/ducktape/tests/runner_client.py", line 184, in _do_run
data = self.run_test()
File "/usr/local/lib/python3.10/dist-packages/ducktape/tests/runner_client.py", line 269, in run_test
return self.test_context.function(self.test)
File "/root/tests/rptest/services/cluster.py", line 104, in wrapped
r = f(self, *args, **kwargs)
File "/root/tests/rptest/tests/consumer_group_balancing_test.py", line 46, in test_coordinator_nodes_balance
rpk.produce(topic=topic.name,
File "/root/tests/rptest/clients/rpk.py", line 566, in produce
out = self._run_topic(cmd,
File "/root/tests/rptest/clients/rpk.py", line 964, in _run_topic
return self._execute(cmd, stdin=stdin, timeout=timeout)
File "/root/tests/rptest/clients/rpk.py", line 1094, in _execute
raise RpkException(
rptest.clients.rpk.RpkException: RpkException<command /var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-0ed3e41583d71dc2e-1/redpanda/redpanda/vbuild/redpanda_installs/ci/bin/rpk topic -X brokers=docker-rp-7:9092,docker-rp-14:9092,docker-rp-22:9092,docker-rp-9:9092,docker-rp-20:9092 produce --key test_key -z none --delivery-timeout 5s -f %v topic-cyylpyflxq -p 0 -v returned 1, output: ; stderr: 13:28:45.089 INFO flushing
13:28:45.090 INFO producing to a new topic for the first time, fetching metadata to learn its partitions {"topic": "topic-cyylpyflxq"}
13:28:45.089 INFO immediate metadata update triggered {"why": "forced load because we are producing to a topic for the first time"}
13:28:45.090 DEBUG opening connection to broker {"addr": "docker-rp-7:9092", "broker": "seed_0"}
13:28:45.090 DEBUG connection opened to broker {"addr": "docker-rp-7:9092", "broker": "seed_0"}
13:28:45.090 DEBUG issuing api versions request {"broker": "seed_0", "version": 3}
13:28:45.090 DEBUG wrote ApiVersions v3 {"broker": "seed_0", "bytes_written": 31, "write_wait": "18.603µs", "time_to_write": "15.764µs", "err": null}
13:28:45.091 DEBUG read ApiVersions v3 {"broker": "seed_0", "bytes_read": 296, "read_wait": "21.456µs", "time_to_read": "232.816µs", "err": null}
13:28:45.091 DEBUG connection initialized successfully {"addr": "docker-rp-7:9092", "broker": "seed_0"}
13:28:45.091 DEBUG wrote Metadata v7 {"broker": "seed_0", "bytes_written": 40, "write_wait": "980.988µs", "time_to_write": "16.573µs", "err": null}
13:28:45.091 DEBUG read Metadata v7 {"broker": "seed_0", "bytes_read": 264, "read_wait": "20.711µs", "time_to_read": "104.187µs", "err": null}
13:28:45.091 INFO done waiting for metadata for new topic {"topic": "topic-cyylpyflxq"}
13:28:45.091 INFO initializing producer id
13:28:45.091 DEBUG opening connection to broker {"addr": "docker-rp-20:9092", "broker": "5"}
13:28:45.091 DEBUG connection opened to broker {"addr": "docker-rp-20:9092", "broker": "5"}
13:28:45.091 DEBUG issuing api versions request {"broker": "5", "version": 3}
13:28:45.091 DEBUG wrote ApiVersions v3 {"broker": "5", "bytes_written": 31, "write_wait": "3.955µs", "time_to_write": "13.736µs", "err": null}
13:28:45.091 DEBUG read ApiVersions v3 {"broker": "5", "bytes_read": 296, "read_wait": "9.877µs", "time_to_read": "198.463µs", "err": null}
13:28:45.091 DEBUG connection initialized successfully {"addr": "docker-rp-20:9092", "broker": "5"}
13:28:45.091 DEBUG wrote InitProducerID v3 {"broker": "5", "bytes_written": 34, "write_wait": "571.356µs", "time_to_write": "9.65µs", "err": null}
13:28:50.095 DEBUG read InitProducerID v3 {"broker": "5", "bytes_read": 0, "read_wait": "20.509µs", "time_to_read": "5.003717781s", "err": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout"}
13:28:50.095 WARN read from broker errored, killing connection after 0 successful responses (is SASL missing?) {"addr": "docker-rp-20:9092", "broker": "5", "err": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout"}
13:28:50.095 DEBUG retrying request {"tries": 1, "backoff": "209.267263ms", "request_error": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout", "response_error": "read tcp 172.16.16.28:59608->172.16.16.20:9092: i/o timeout"}
13:28:50.305 DEBUG opening connection to broker {"addr": "docker-rp-22:9092", "broker": "1"}
13:28:50.305 DEBUG connection opened to broker {"addr": "docker-rp-22:9092", "broker": "1"}
13:28:50.305 DEBUG issuing api versions request {"broker": "1", "version": 3}
13:28:50.305 DEBUG wrote ApiVersions v3 {"broker": "1", "bytes_written": 31, "write_wait": "8.501µs", "time_to_write": "29.48µs", "err": null}
13:28:50.306 DEBUG read ApiVersions v3 {"broker": "1", "bytes_read": 296, "read_wait": "21.62µs", "time_to_read": "158.767µs", "err": null}
13:28:50.306 DEBUG connection initialized successfully {"addr": "docker-rp-22:9092", "broker": "1"}
13:28:50.306 DEBUG wrote InitProducerID v3 {"broker": "1", "bytes_written": 34, "write_wait": "943.138µs", "time_to_write": "15.612µs", "err": null}
13:28:50.306 DEBUG read InitProducerID v3 {"broker": "1", "bytes_read": 26, "read_wait": "27.979µs", "time_to_read": "106.553µs", "err": null}
13:28:50.306 INFO producer id initialization success {"id": 2, "epoch": 0}
unable to produce record: records have timed out before they were able to be produced
; returncode: 1>
JIRA Link: CORE-1887
*https://buildkite.com/redpanda/redpanda/builds/48024 *https://buildkite.com/redpanda/redpanda/builds/48064 *https://buildkite.com/redpanda/vtools/builds/13072
This is failing again in v24.1 -- @michael-redpanda -- if this is indeed an infra issue should we move this over to plateng? https://ci-artifacts.dev.vectorized.cloud/redpanda/48184/018f0d2f-952a-4ddc-84f6-9d03bbe5255a/vbuild/ducktape/results/2024-04-23--001/report.html
*https://buildkite.com/redpanda/redpanda/builds/50527 *https://buildkite.com/redpanda/redpanda/builds/50700 *https://buildkite.com/redpanda/redpanda/builds/50784
*https://buildkite.com/redpanda/vtools/builds/15093 *https://buildkite.com/redpanda/redpanda/builds/50805
*https://buildkite.com/redpanda/redpanda/builds/51248 *https://buildkite.com/redpanda/redpanda/builds/51254
Closing older-bot-filed CI issues as we transition to a more reliable system.