CI Failure (`RpkException: unable to produce record: records have timed out before they were able to be produced`) in `ConsumerGroupBalancingTest.test_coordinator_nodes_balance`

vbotbuildovich commented 5 months ago

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

vbotbuildovich commented 5 months ago

*https://buildkite.com/redpanda/redpanda/builds/46665

vbotbuildovich commented 5 months ago

*https://buildkite.com/redpanda/redpanda/builds/46694

vbotbuildovich commented 5 months ago

*https://buildkite.com/redpanda/redpanda/builds/46964

vbotbuildovich commented 5 months ago

*https://buildkite.com/redpanda/redpanda/builds/47059

vbotbuildovich commented 5 months ago

*https://buildkite.com/redpanda/vtools/builds/12656

vbotbuildovich commented 4 months ago