search

redpanda-data / redpanda

Redpanda is a streaming data platform for developers. Kafka API compatible. 10x faster. No ZooKeeper. No JVM!
https://redpanda.com
9.62k stars 585 forks source link

CI Failure (rpk command timeout) in `InternalTopicProtectionLargeClusterTest.test_consumer_offset_topic` #16325

Closed vbotbuildovich closed 1 month ago

vbotbuildovich commented 9 months ago

https://buildkite.com/redpanda/redpanda/builds/44292

Module: rptest.tests.internal_topic_protection_test
Class: InternalTopicProtectionLargeClusterTest
Method: test_consumer_offset_topic
test_id:    InternalTopicProtectionLargeClusterTest.test_consumer_offset_topic
status:     FAIL
run time:   29.052 seconds

RpkException('command /var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-01b73192c4c3a4b49-1/redpanda/redpanda/vbuild/redpanda_installs/ci/bin/rpk topic -X brokers=docker-rp-20:9092,docker-rp-21:9092,docker-rp-22:9092,docker-rp-19:9092,docker-rp-23:9092 produce --key key1 -z none --delivery-timeout 5s -f %v test -v returned 1, output: ', '15:26:10.451  INFO  flushing\n15:26:10.451  INFO  producing to a new topic for the first time, fetching metadata to learn its partitions  {"topic": "test"}\n15:26:10.451  INFO  immediate metadata update triggered  {"why": "forced load because we are producing to a topic for the first time"}\n15:26:10.451  DEBUG  opening connection to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}\n15:26:10.452  DEBUG  connection opened to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}\n15:26:10.452  DEBUG  issuing api versions request  {"broker": "seed_0", "version": 3}\n15:26:10.452  DEBUG  wrote ApiVersions v3  {"broker": "seed_0", "bytes_written": 31, "write_wait": "25.987µs", "time_to_write": "39.529µs", "err": null}\n15:26:10.460  DEBUG  read ApiVersions v3  {"broker": "seed_0", "bytes_read": 296, "read_wait": "28.4µs", "time_to_read": "7.759377ms", "err": null}\n15:26:10.460  DEBUG  connection initialized successfully  {"addr": "docker-rp-20:9092", "broker": "seed_0"}\n15:26:10.460  DEBUG  wrote Metadata v7  {"broker": "seed_0", "bytes_written": 28, "write_wait": "8.964617ms", "time_to_write": "24.424µs", "err": null}\n15:26:10.468  DEBUG  read Metadata v7  {"broker": "seed_0", "bytes_read": 270, "read_wait": "60.419µs", "time_to_read": "7.56104ms", "err": null}\n15:26:10.468  INFO  done waiting for metadata for new topic  {"topic": "test"}\n15:26:10.468  INFO  initializing producer id\n15:26:10.468  DEBUG  opening connection to broker  {"addr": "docker-rp-22:9092", "broker": "5"}\n15:26:10.468  DEBUG  connection opened to broker  {"addr": "docker-rp-22:9092", "broker": "5"}\n15:26:10.468  DEBUG  issuing api versions request  {"broker": "5", "version": 3}\n15:26:10.468  DEBUG  wrote ApiVersions v3  {"broker": "5", "bytes_written": 31, "write_wait": "7.738µs", "time_to_write": "23.65µs", "err": null}\n15:26:10.474  DEBUG  read ApiVersions v3  {"broker": "5", "bytes_read": 296, "read_wait": "23.13µs", "time_to_read": "5.312288ms", "err": null}\n15:26:10.474  DEBUG  connection initialized successfully  {"addr": "docker-rp-22:9092", "broker": "5"}\n15:26:10.474  DEBUG  wrote InitProducerID v3  {"broker": "5", "bytes_written": 34, "write_wait": "5.985612ms", "time_to_write": "23.386µs", "err": null}\n15:26:15.475  DEBUG  read InitProducerID v3  {"broker": "5", "bytes_read": 0, "read_wait": "30.237µs", "time_to_read": "5.001081576s", "err": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout"}\n15:26:15.475  WARN  read from broker errored, killing connection after 0 successful responses (is SASL missing?)  {"addr": "docker-rp-22:9092", "broker": "5", "err": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout"}\n15:26:15.475  DEBUG  retrying request  {"tries": 1, "backoff": "238.332386ms", "request_error": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout", "response_error": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout"}\n15:26:15.715  DEBUG  opening connection to broker  {"addr": "docker-rp-23:9092", "broker": "4"}\n15:26:15.716  DEBUG  connection opened to broker  {"addr": "docker-rp-23:9092", "broker": "4"}\n15:26:15.716  DEBUG  issuing api versions request  {"broker": "4", "version": 3}\n15:26:15.716  DEBUG  wrote ApiVersions v3  {"broker": "4", "bytes_written": 31, "write_wait": "14.438µs", "time_to_write": "34.197µs", "err": null}\n15:26:15.722  DEBUG  read ApiVersions v3  {"broker": "4", "bytes_read": 296, "read_wait": "24.201µs", "time_to_read": "6.098421ms", "err": null}\n15:26:15.722  DEBUG  connection initialized successfully  {"addr": "docker-rp-23:9092", "broker": "4"}\n15:26:15.723  DEBUG  wrote InitProducerID v3  {"broker": "4", "bytes_written": 34, "write_wait": "7.963883ms", "time_to_write": "25.667µs", "err": null}\n15:26:15.808  DEBUG  read InitProducerID v3  {"broker": "4", "bytes_read": 26, "read_wait": "31.165µs", "time_to_read": "85.084219ms", "err": null}\n15:26:15.808  INFO  producer id initialization success  {"id": 1, "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 82, in wrapped
    r = f(self, *args, **kwargs)
  File "/root/tests/rptest/tests/internal_topic_protection_test.py", line 256, in test_consumer_offset_topic
    self.rpk.produce("test", key="key1", msg="Hi there")
  File "/root/tests/rptest/clients/rpk.py", line 539, in produce
    out = self._run_topic(cmd,
  File "/root/tests/rptest/clients/rpk.py", line 937, in _run_topic
    return self._execute(cmd, stdin=stdin, timeout=timeout)
  File "/root/tests/rptest/clients/rpk.py", line 1067, in _execute
    raise RpkException(
rptest.clients.rpk.RpkException: RpkException<command /var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-01b73192c4c3a4b49-1/redpanda/redpanda/vbuild/redpanda_installs/ci/bin/rpk topic -X brokers=docker-rp-20:9092,docker-rp-21:9092,docker-rp-22:9092,docker-rp-19:9092,docker-rp-23:9092 produce --key key1 -z none --delivery-timeout 5s -f %v test -v returned 1, output: ; stderr: 15:26:10.451  INFO  flushing
15:26:10.451  INFO  producing to a new topic for the first time, fetching metadata to learn its partitions  {"topic": "test"}
15:26:10.451  INFO  immediate metadata update triggered  {"why": "forced load because we are producing to a topic for the first time"}
15:26:10.451  DEBUG  opening connection to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}
15:26:10.452  DEBUG  connection opened to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}
15:26:10.452  DEBUG  issuing api versions request  {"broker": "seed_0", "version": 3}
15:26:10.452  DEBUG  wrote ApiVersions v3  {"broker": "seed_0", "bytes_written": 31, "write_wait": "25.987µs", "time_to_write": "39.529µs", "err": null}
15:26:10.460  DEBUG  read ApiVersions v3  {"broker": "seed_0", "bytes_read": 296, "read_wait": "28.4µs", "time_to_read": "7.759377ms", "err": null}
15:26:10.460  DEBUG  connection initialized successfully  {"addr": "docker-rp-20:9092", "broker": "seed_0"}
15:26:10.460  DEBUG  wrote Metadata v7  {"broker": "seed_0", "bytes_written": 28, "write_wait": "8.964617ms", "time_to_write": "24.424µs", "err": null}
15:26:10.468  DEBUG  read Metadata v7  {"broker": "seed_0", "bytes_read": 270, "read_wait": "60.419µs", "time_to_read": "7.56104ms", "err": null}
15:26:10.468  INFO  done waiting for metadata for new topic  {"topic": "test"}
15:26:10.468  INFO  initializing producer id
15:26:10.468  DEBUG  opening connection to broker  {"addr": "docker-rp-22:9092", "broker": "5"}
15:26:10.468  DEBUG  connection opened to broker  {"addr": "docker-rp-22:9092", "broker": "5"}
15:26:10.468  DEBUG  issuing api versions request  {"broker": "5", "version": 3}
15:26:10.468  DEBUG  wrote ApiVersions v3  {"broker": "5", "bytes_written": 31, "write_wait": "7.738µs", "time_to_write": "23.65µs", "err": null}
15:26:10.474  DEBUG  read ApiVersions v3  {"broker": "5", "bytes_read": 296, "read_wait": "23.13µs", "time_to_read": "5.312288ms", "err": null}
15:26:10.474  DEBUG  connection initialized successfully  {"addr": "docker-rp-22:9092", "broker": "5"}
15:26:10.474  DEBUG  wrote InitProducerID v3  {"broker": "5", "bytes_written": 34, "write_wait": "5.985612ms", "time_to_write": "23.386µs", "err": null}
15:26:15.475  DEBUG  read InitProducerID v3  {"broker": "5", "bytes_read": 0, "read_wait": "30.237µs", "time_to_read": "5.001081576s", "err": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout"}
15:26:15.475  WARN  read from broker errored, killing connection after 0 successful responses (is SASL missing?)  {"addr": "docker-rp-22:9092", "broker": "5", "err": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout"}
15:26:15.475  DEBUG  retrying request  {"tries": 1, "backoff": "238.332386ms", "request_error": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout", "response_error": "read tcp 172.16.16.28:57790->172.16.16.5:9092: i/o timeout"}
15:26:15.715  DEBUG  opening connection to broker  {"addr": "docker-rp-23:9092", "broker": "4"}
15:26:15.716  DEBUG  connection opened to broker  {"addr": "docker-rp-23:9092", "broker": "4"}
15:26:15.716  DEBUG  issuing api versions request  {"broker": "4", "version": 3}
15:26:15.716  DEBUG  wrote ApiVersions v3  {"broker": "4", "bytes_written": 31, "write_wait": "14.438µs", "time_to_write": "34.197µs", "err": null}
15:26:15.722  DEBUG  read ApiVersions v3  {"broker": "4", "bytes_read": 296, "read_wait": "24.201µs", "time_to_read": "6.098421ms", "err": null}
15:26:15.722  DEBUG  connection initialized successfully  {"addr": "docker-rp-23:9092", "broker": "4"}
15:26:15.723  DEBUG  wrote InitProducerID v3  {"broker": "4", "bytes_written": 34, "write_wait": "7.963883ms", "time_to_write": "25.667µs", "err": null}
15:26:15.808  DEBUG  read InitProducerID v3  {"broker": "4", "bytes_read": 26, "read_wait": "31.165µs", "time_to_read": "85.084219ms", "err": null}
15:26:15.808  INFO  producer id initialization success  {"id": 1, "epoch": 0}
unable to produce record: records have timed out before they were able to be produced
; returncode: 1>

JIRA Link: CORE-1736

vbotbuildovich commented 7 months ago

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

vbotbuildovich commented 6 months ago

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

vbotbuildovich commented 5 months ago

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

vbotbuildovich commented 4 months ago

https://buildkite.com/redpanda/redpanda/builds/48177 https://buildkite.com/redpanda/redpanda/builds/48883

vbotbuildovich commented 4 months ago

https://buildkite.com/redpanda/redpanda/builds/48177 https://buildkite.com/redpanda/redpanda/builds/48883

vbotbuildovich commented 4 months ago

https://buildkite.com/redpanda/redpanda/builds/48177 https://buildkite.com/redpanda/redpanda/builds/48883

vbotbuildovich commented 4 months ago

https://buildkite.com/redpanda/redpanda/builds/48177 https://buildkite.com/redpanda/redpanda/builds/48883

vbotbuildovich commented 4 months ago

https://buildkite.com/redpanda/redpanda/builds/50497 https://buildkite.com/redpanda/redpanda/builds/50550

vbotbuildovich commented 4 months ago

https://buildkite.com/redpanda/redpanda/builds/50987 https://buildkite.com/redpanda/redpanda/builds/51038

vbotbuildovich commented 4 months ago

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

piyushredpanda commented 1 month ago

Closing older-bot-filed CI issues as we transition to a more reliable system.