CI Failure (Failure in librdkafka test case 0041) in LibrdkafkaTest.test_librdkafka

[nvartolomei]

https://buildkite.com/redpanda/redpanda/builds/38660#018b1bd3-f013-46b6-96e3-bb71e8d3ed5b

Module: rptest.tests.librdkafka_test
Class:  LibrdkafkaTest
Method: test_librdkafka
Arguments:
{
  "test_num": 41
}

test_id:    rptest.tests.librdkafka_test.LibrdkafkaTest.test_librdkafka.test_num=41
status:     FAIL
run time:   11.919 seconds


    AssertionError('Failure in librdkafka test case 0041')
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 264, 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 82, in wrapped
    r = f(self, *args, **kwargs)
  File "/root/tests/rptest/utils/mode_checks.py", line 63, in f
    return func(*args, **kwargs)
  File "/root/tests/rptest/tests/librdkafka_test.py", line 85, in test_librdkafka
    assert tc.error is None, f"Failure in librdkafka test case {test_num:04}"
AssertionError: Failure in librdkafka test case 0041

[nvartolomei]

I'm able to reproduce it quite easily in debug mode at d6b8984 and latest dev 8d57443 (for which rdkafka tests are actually disabled). ~1/5 test runs in debug mode.

The test is also marked ok_to_fail but for some reason it is a real failure not a OFAIL as I'd expect.

[NyaliaLui]

librdkafka test logs

�[0m�[36m[0041_fetch_max_bytes        /  1.120s] CONSUME: consumer_start: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0] at offset -2
�[0m�[36m[0041_fetch_max_bytes        /  1.120s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expect msg #0..2000 at offset -1
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] FIRST MSG: duration 502.457ms
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #0 (0/2000): got msg #28
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #1 (1/2000): got msg #29
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #2 (2/2000): got msg #30
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507librdkafka test logs


�[0m�[36m[0041_fetch_max_bytes        /  1.120s] CONSUME: consumer_start: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0] at offset -2
�[0m�[36m[0041_fetch_max_bytes        /  1.120s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expect msg #0..2000 at offset -1
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] FIRST MSG: duration 502.457ms
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #0 (0/2000): got msg #28
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #1 (1/2000): got msg #29
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #2 (2/2000): got msg #30
�[0m�[36m[0041_fetch_max_bytes        /  1.622s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #3 (3/2000): got msg #31

...

�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #96 (96/2000): got msg #124
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #97 (97/2000): got msg #125
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #98 (98/2000): got msg #0
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #99 (99/2000): got msg #1
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #100 (100/2000): got msg #2

...


�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #124 (124/2000): got msg #26
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #125 (125/2000): got msg #27
�[0m�[36m[0041_fetch_max_bytes        /  1.986s] ALL MSGS: duration 865.913ms
�[0m�[36m[0041_fetch_max_bytes        /  1.986s] TEST FAILURE
�[0m�[31m### Test "0041_fetch_max_bytes" failed at test.c:2701:test_consume_msgs() at Tue Oct 10 23:42:15 2023: ###
CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: 126 failures
```ax_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #96 (96/2000): got msg #124
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #97 (97/2000): got msg #125
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #98 (98/2000): got msg #0
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #99 (99/2000): got msg #1
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #100 (100/2000): got msg #2

...


�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #124 (124/2000): got msg #26
�[0m�[36m[0041_fetch_max_bytes        /  1.623s] CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: expected msg #125 (125/2000): got msg #27
�[0m�[36m[0041_fetch_max_bytes        /  1.986s] ALL MSGS: duration 865.913ms
�[0m�[36m[0041_fetch_max_bytes        /  1.986s] TEST FAILURE
�[0m�[31m### Test "0041_fetch_max_bytes" failed at test.c:2701:test_consume_msgs() at Tue Oct 10 23:42:15 2023: ###
CONSUME: consume_msgs: rdkafkatest_rnd2cdfb4f507182ae1_0041_fetch_max_bytes [0]: 126 failures

[NyaliaLui]

https://buildkite.com/redpanda/redpanda/builds/38691
https://buildkite.com/redpanda/redpanda/builds/38687
https://buildkite.com/redpanda/redpanda/builds/38686
https://buildkite.com/redpanda/redpanda/builds/38683
https://buildkite.com/redpanda/redpanda/builds/38683
https://buildkite.com/redpanda/redpanda/builds/38658
https://buildkite.com/redpanda/redpanda/builds/38642

[piyushredpanda]

Closing this also as the offending PR was reverted.