CI Failure (TimeoutError - Consumer failed to consume up to offsets) in NodesDecommissioningTest.test_flipping_decommission_recommission

[andijcr]

  1 FAIL test: NodesDecommissioningTest.test_flipping_decommission_recommission.node_is_alive=True (1/15 runs)
  2   failure at 2023-04-05T07:05:19.256Z: TimeoutError("Consumer failed to consume up to offsets {TopicPartition(topic='topic-tpnyowjkkn', partition=    1): 1738380, TopicPartition(topic='topic-tpnyowjkkn', partition=0): 1704936, TopicPartition(topic='topic-tpnyowjkkn', partition=3): 1784103, Topic    Partition(topic='topic-tpnyowjkkn', partition=4): 1753952, TopicPartition(topic='topic-tpnyowjkkn', partition=2): 1683733, TopicPartition(topic='t    opic-tpnyowjkkn', partition=7): 1664207, TopicPartition(topic='topic-tpnyowjkkn', partition=6): 1721468, TopicPartition(topic='topic-tpnyowjkkn',     partition=5): 1700680} after waiting 240s, last committed offsets: {1: {TopicPartition(topic='topic-tpnyowjkkn', partition=4): 1753953, TopicParti    tion(topic='topic-tpnyowjkkn', partition=3): 1784104, TopicPartition(topic='topic-tpnyowjkkn', partition=1): 1738381, TopicPartition(topic='topic-    tpnyowjkkn', partition=6): 1721469, TopicPartition(topic='topic-tpnyowjkkn', partition=2): 1683734, TopicPartition(topic='topic-tpnyowjkkn', parti    tion=7): 1664208, TopicPartition(topic='topic-tpnyowjkkn', partition=5): 1675364, TopicPartition(topic='topic-tpnyowjkkn', partition=0): 1691287}}    .")

https://buildkite.com/redpanda/redpanda/builds/26478#01875003-90e9-4daf-8719-d61d2f561037

Module: rptest.tests.nodes_decommissioning_test
Class:  NodesDecommissioningTest
Method: test_flipping_decommission_recommission
Arguments:
{
  "node_is_alive": true
}

test_id:    rptest.tests.nodes_decommissioning_test.NodesDecommissioningTest.test_flipping_decommission_recommission.node_is_alive=True
status:     FAIL
run time:   8 minutes 13.698 seconds


    TimeoutError("Consumer failed to consume up to offsets {TopicPartition(topic='topic-tpnyowjkkn', partition=1): 1738380, TopicPartition(topic='topic-tpnyowjkkn', partition=0): 1704936, TopicPartition(topic='topic-tpnyowjkkn', partition=3): 1784103, TopicPartition(topic='topic-tpnyowjkkn', partition=4): 1753952, TopicPartition(topic='topic-tpnyowjkkn', partition=2): 1683733, TopicPartition(topic='topic-tpnyowjkkn', partition=7): 1664207, TopicPartition(topic='topic-tpnyowjkkn', partition=6): 1721468, TopicPartition(topic='topic-tpnyowjkkn', partition=5): 1700680} after waiting 240s, last committed offsets: {1: {TopicPartition(topic='topic-tpnyowjkkn', partition=4): 1753953, TopicPartition(topic='topic-tpnyowjkkn', partition=3): 1784104, TopicPartition(topic='topic-tpnyowjkkn', partition=1): 1738381, TopicPartition(topic='topic-tpnyowjkkn', partition=6): 1721469, TopicPartition(topic='topic-tpnyowjkkn', partition=2): 1683734, TopicPartition(topic='topic-tpnyowjkkn', partition=7): 1664208, TopicPartition(topic='topic-tpnyowjkkn', partition=5): 1675364, TopicPartition(topic='topic-tpnyowjkkn', partition=0): 1691287}}.")
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/ducktape/tests/runner_client.py", line 135, in run
    data = self.run_test()
  File "/usr/local/lib/python3.10/dist-packages/ducktape/tests/runner_client.py", line 227, in run_test
    return self.test_context.function(self.test)
  File "/usr/local/lib/python3.10/dist-packages/ducktape/mark/_mark.py", line 481, in wrapper
    return functools.partial(f, *args, **kwargs)(*w_args, **w_kwargs)
  File "/root/tests/rptest/services/cluster.py", line 49, in wrapped
    r = f(self, *args, **kwargs)
  File "/root/tests/rptest/tests/nodes_decommissioning_test.py", line 622, in test_flipping_decommission_recommission
    self.run_validation(enable_idempotence=False, consumer_timeout_sec=240)
  File "/root/tests/rptest/tests/end_to_end.py", line 267, in run_validation
    self.run_consumer_validation(
  File "/root/tests/rptest/tests/end_to_end.py", line 288, in run_consumer_validation
    self.await_consumed_offsets(last_acked_offsets,
  File "/root/tests/rptest/tests/end_to_end.py", line 219, in await_consumed_offsets
    wait_until(
  File "/usr/local/lib/python3.10/dist-packages/ducktape/utils/util.py", line 57, in wait_until
    raise TimeoutError(err_msg() if callable(err_msg) else err_msg) from last_exception
ducktape.errors.TimeoutError: Consumer failed to consume up to offsets {TopicPartition(topic='topic-tpnyowjkkn', partition=1): 1738380, TopicPartition(topic='topic-tpnyowjkkn', partition=0): 1704936, TopicPartition(topic='topic-tpnyowjkkn', partition=3): 1784103, TopicPartition(topic='topic-tpnyowjkkn', partition=4): 1753952, TopicPartition(topic='topic-tpnyowjkkn', partition=2): 1683733, TopicPartition(topic='topic-tpnyowjkkn', partition=7): 1664207, TopicPartition(topic='topic-tpnyowjkkn', partition=6): 1721468, TopicPartition(topic='topic-tpnyowjkkn', partition=5): 1700680} after waiting 240s, last committed offsets: {1: {TopicPartition(topic='topic-tpnyowjkkn', partition=4): 1753953, TopicPartition(topic='topic-tpnyowjkkn', partition=3): 1784104, TopicPartition(topic='topic-tpnyowjkkn', partition=1): 1738381, TopicPartition(topic='topic-tpnyowjkkn', partition=6): 1721469, TopicPartition(topic='topic-tpnyowjkkn', partition=2): 1683734, TopicPartition(topic='topic-tpnyowjkkn', partition=7): 1664208, TopicPartition(topic='topic-tpnyowjkkn', partition=5): 1675364, TopicPartition(topic='topic-tpnyowjkkn', partition=0): 1691287}}.

test fails at the validation step. the last log lines before the timeout are

[DEBUG - 2023-04-05 06:37:05,438 - end_to_end - has_finished_consuming - lineno:210]: waiting for partition TopicPartition(topic='topic-tpnyowjkkn', partition=0) offset 1704936 to be committed, last committed offset: 1691287, last committed timestamp: 2023-04-05 06:37:05.434838, last consumed timestamp: 2023-04-05 06:37:05.434838
[DEBUG - 2023-04-05 06:37:05,538 - end_to_end - has_finished_consuming - lineno:210]: waiting for partition TopicPartition(topic='topic-tpnyowjkkn', partition=0) offset 1704936 to be committed, last committed offset: 1691287, last committed timestamp: 2023-04-05 06:37:05.530065, last consumed timestamp: 2023-04-05 06:37:05.530065
[DEBUG - 2023-04-05 06:37:05,639 - end_to_end - has_finished_consuming - lineno:210]: waiting for partition TopicPartition(topic='topic-tpnyowjkkn', partition=0) offset 1704936 to be committed, last committed offset: 1691287, last committed timestamp: 2023-04-05 06:37:05.633235, last consumed timestamp: 2023-04-05 06:37:05.633235
[DEBUG - 2023-04-05 06:37:05,739 - end_to_end - has_finished_consuming - lineno:210]: waiting for partition TopicPartition(topic='topic-tpnyowjkkn', partition=0) offset 1704936 to be committed, last committed offset: 1691287, last committed timestamp: 2023-04-05 06:37:05.732827, last consumed timestamp: 2023-04-05 06:37:05.732827
[DEBUG - 2023-04-05 06:37:05,841 - end_to_end - has_finished_consuming - lineno:210]: waiting for partition TopicPartition(topic='topic-tpnyowjkkn', partition=0) offset 1704936 to be committed, last committed offset: 1691287, last committed timestamp: 2023-04-05 06:37:05.839932, last consumed timestamp: 2023-04-05 06:37:05.839932
[DEBUG - 2023-04-05 06:37:05,941 - end_to_end - has_finished_consuming - lineno:210]: waiting for partition TopicPartition(topic='topic-tpnyowjkkn', partition=0) offset 1704936 to be committed, last committed offset: 1691287, last committed timestamp: 2023-04-05 06:37:05.936361, last consumed timestamp: 2023-04-05 06:37:05.936361
[DEBUG - 2023-04-05 06:37:06,042 - end_to_end - has_finished_consuming - lineno:210]: waiting for partition TopicPartition(topic='topic-tpnyowjkkn', partition=0) offset 1704936 to be committed, last committed offset: 1691287, last committed timestamp: 2023-04-05 06:37:06.030570, last consumed timestamp: 2023-04-05 06:37:06.030570

there is a similar to issue #9290 but in that case the validation of the producer node fails

[michael-redpanda]

Instance from a PR: https://buildkite.com/redpanda/redpanda/builds/26669#01875c29-09a8-4992-a989-13d672cb5eb7

[jcsp]

https://buildkite.com/redpanda/redpanda/builds/26807#01876eff-8c67-434b-940a-323548e61797

[VladLazar]

https://buildkite.com/redpanda/redpanda/builds/26952#01877684-2cdf-4c03-a81c-e41072cb7d0c

[dotnwat]

https://buildkite.com/redpanda/redpanda/builds/27276#01878dd6-bfa6-422a-a65d-28aa8e0ca123

[dotnwat]

https://buildkite.com/redpanda/redpanda/builds/27367#0187941d-081e-4625-bc1a-764973553d2e

[dotnwat]

https://buildkite.com/redpanda/redpanda/builds/27415#0187961b-c9b8-409b-9556-fd27ce296c96
https://buildkite.com/redpanda/vtools/builds/7160#018795fb-7975-49bb-b7e0-cd1a9555e042

[dotnwat]

https://buildkite.com/redpanda/redpanda/builds/27545#01879b85-c690-40bc-bfbc-bed7ffa0bd96