CI Failure (BadLogLines) in `RandomNodeOperationsTest.test_node_operations`

andijcr commented 11 months ago

https://buildkite.com/redpanda/vtools/builds/10805

This issue is an umbrella for 3 instances of bad log lines:

Can't apply override to kafka start offset -> Fixed in #15192
Failed to make reupload candidate to match the run, candidate: {source segment offsets: {term:3, base_offset:15, committed_offset:483, dirty_offset:483}, exposed_name: {15-3-v1.log}, starting_offset: 15, file_offset: 0, content_length: 5108, final_offset: 483, final_file_offset: 5108, term: 3, source names: {/var/lib/redpanda/data/kafka/fuzzy-operator-2047-ygyvas/0_6696/15-3-v1.log}}, run: {is_compacted: true, size_bytes: 5224, base_offset: 15, committed_offset: 483, base_timestamp: {timestamp: 1703239361564}, max_timestamp: {timestamp: 1703239430338}, delta_offset: 15, ntp_revision: 64, archiver_term: 4, segment_term: 3, delta_offset_end: 25, sname_format: {v3}, metadata_size_hint: 0} Discussed in https://redpandadata.slack.com/archives/C05S5SBT4CU/p1704303384062129 Builds:
- https://buildkite.com/redpanda/vtools/builds/11262
ERROR 2023-12-14 11:38:06,999 [shard 0:main] cluster - topic_table.cc:184 - Unexpected record at offset 5399 to drop non-existent lifecycle marker {kafka/fuzzy-operator-5709-agcwue} 3685 Builds:
- https://buildkite.com/redpanda/vtools/builds/11151#018c6758-5e5b-4eb6-bb5b-4009aa784930
ERROR 2023-12-18 11:13:10,469 [shard 0:au ] archival - [fiber1~3|0|19974ms] - purger.cc:168 - Permanent failures encountered while purging partition {kafka/fuzzy-operator-532-qebtjv/2}. Giving up ... Builds:
- https://ci-artifacts.dev.vectorized.cloud/vtools/11202/018c7bf3-cedc-4f4b-976c-ab7fb496f37b/vbuild/ducktape/results/2023-12-18--001/report.html

Module: rptest.tests.random_node_operations_test
Class: RandomNodeOperationsTest
Method: test_node_operations
Arguments: {
    "num_to_upgrade": 3,
    "enable_failures": false,
    "with_tiered_storage": true
}

test_id:    RandomNodeOperationsTest.test_node_operations
status:     FAIL
run time:   2061.472 seconds

<BadLogLines nodes=ip-172-31-33-161(2) example="ERROR 2023-11-25 23:15:40,652 [shard 0] cluster - ntp: {kafka/fuzzy-operator-2796-ncuizc/5} - archival_metadata_stm.cc:1229 - Can't apply override to kafka start offset 29, currently 29">
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 "/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 "/home/ubuntu/redpanda/tests/rptest/services/cluster.py", line 142, in wrapped
    redpanda.raise_on_bad_logs(
  File "/home/ubuntu/redpanda/tests/rptest/services/redpanda.py", line 1321, in raise_on_bad_logs
    raise BadLogLines(bad_lines)
rptest.services.utils.BadLogLines: <BadLogLines nodes=ip-172-31-33-161(2) example="ERROR 2023-11-25 23:15:40,652 [shard 0] cluster - ntp: {kafka/fuzzy-operator-2796-ncuizc/5} - archival_metadata_stm.cc:1229 - Can't apply override to kafka start offset 29, currently 29">

JIRA Link: CORE-1601

andijcr commented 11 months ago

not sure if this should be reported as error

mmaslankaprv commented 11 months ago

This was already fixed with: https://github.com/redpanda-data/redpanda/pull/15192

vbotbuildovich commented 10 months ago

https://buildkite.com/redpanda/vtools/builds/11151 https://buildkite.com/redpanda/vtools/builds/11151

vbotbuildovich commented 10 months ago

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

vbotbuildovich commented 10 months ago

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

vbotbuildovich commented 10 months ago

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

vbotbuildovich commented 10 months ago

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

andijcr commented 10 months ago

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

at least the last failure mode is different:

<BadLogLines nodes=ip-172-31-13-176(2),ip-172-31-5-190(7),ip-172-31-2-19(29) example="ERROR 2023-12-22 10:09:03,417 [shard 1:au  ] archival - [fiber11 kafka/fuzzy-operator-2047-ygyvas/0] - ntp_archiver_service.cc:2832 - Failed to make reupload candidate to match the run, candidate: {source segment offsets: {term:3, base_offset:15, committed_offset:483, dirty_offset:483}, exposed_name: {15-3-v1.log}, starting_offset: 15, file_offset: 0, content_length: 5108, final_offset: 483, final_file_offset: 5108, term: 3, source names: {/var/lib/redpanda/data/kafka/fuzzy-operator-2047-ygyvas/0_6696/15-3-v1.log}}, run: {is_compacted: true, size_bytes: 5224, base_offset: 15, committed_offset: 483, base_timestamp: {timestamp: 1703239361564}, max_timestamp: {timestamp: 1703239430338}, delta_offset: 15, ntp_revision: 64, archiver_term: 4, segment_term: 3, delta_offset_end: 25, sname_format: {v3}, metadata_size_hint: 0}">
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 "/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 "/home/ubuntu/redpanda/tests/rptest/services/cluster.py", line 142, in wrapped
    redpanda.raise_on_bad_logs(
  File "/home/ubuntu/redpanda/tests/rptest/services/redpanda.py", line 1325, in raise_on_bad_logs
    raise BadLogLines(bad_lines)
rptest.services.utils.BadLogLines: <BadLogLines nodes=ip-172-31-13-176(2),ip-172-31-5-190(7),ip-172-31-2-19(29) example="ERROR 2023-12-22 10:09:03,417 [shard 1:au  ] archival - [fiber11 kafka/fuzzy-operator-2047-ygyvas/0] - ntp_archiver_service.cc:2832 - Failed to make reupload candidate to match the run, candidate: {source segment offsets: {term:3, base_offset:15, committed_offset:483, dirty_offset:483}, exposed_name: {15-3-v1.log}, starting_offset: 15, file_offset: 0, content_length: 5108, final_offset: 483, final_file_offset: 5108, term: 3, source names: {/var/lib/redpanda/data/kafka/fuzzy-operator-2047-ygyvas/0_6696/15-3-v1.log}}, run: {is_compacted: true, size_bytes: 5224, base_offset: 15, committed_offset: 483, base_timestamp: {timestamp: 1703239361564}, max_timestamp: {timestamp: 1703239430338}, delta_offset: 15, ntp_revision: 64, archiver_term: 4, segment_term: 3, delta_offset_end: 25, sname_format: {v3}, metadata_size_hint: 0}">