[v22.3.x] CI Failure (-1 returned from timequery) in TestReadReplicaTimeQuery.test_timequery

[andrwng]

NOTE: this is on v22.3.x PR

https://buildkite.com/redpanda/redpanda/builds/24576#0186bd42-62d2-47f2-a129-74fc9a3a3c1d

Module: rptest.tests.timequery_test
Class:  TestReadReplicaTimeQuery
Method: test_timequery

test_id:    rptest.tests.timequery_test.TestReadReplicaTimeQuery.test_timequery
status:     FAIL
run time:   43.435 seconds


    AssertionError('Expected offset -1, got 40')
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 "/root/tests/rptest/tests/timequery_test.py", line 466, in test_timequery
    self.query_timestamp(base_ts + ix, kcat1, kcat2)
  File "/root/tests/rptest/tests/timequery_test.py", line 443, in query_timestamp
    assert offset_src == offset_rr, f"Expected offset {offset_src}, got {offset_rr}"
AssertionError: Expected offset -1, got 40

[andrwng]

From docker-rp-13

INFO  2023-03-07 18:52:24,428 [shard 1] raft - [group_id:1, {kafka/panda-topic/0}] vote_stm.cc:280 - became the leader term: 2
...
TRACE 2023-03-07 18:52:26,202 [shard 1] raft - [group_id:1, {kafka/panda-topic/0}] consensus.cc:510 - Updated node {id: {2}, revision: {16}} match 352 and next 353 indices
TRACE 2023-03-07 18:52:26,203 [shard 1] raft - [group_id:1, {kafka/panda-topic/0}] consensus.cc:655 - Linearizable offset: 352
DEBUG 2023-03-07 18:52:26,203 [shard 1] cluster - partition.cc:431 - timequery (raft) {kafka/panda-topic/0} t={timestamp: 1664453149120} max_offset(k)=349
TRACE 2023-03-07 18:52:26,204 [shard 1] raft - [group_id:1, {kafka/panda-topic/0}] consensus.cc:308 - Append entries response: {node_id: {id: {1}, revision: {16}}, target_node_id{id: {3}, revision: {16}}, group: {1}, term:{2}, last_dirty_log_index:{352}, last_flushed_log_index:{352}, last_term_base_offset:{-9223372036854775808}, result: success}
TRACE 2023-03-07 18:52:26,204 [shard 1] raft - [group_id:1, {kafka/panda-topic/0}] consensus.cc:390 - Updated node {id: {1}, revision: {16}} last committed log index: 352
TRACE 2023-03-07 18:52:26,204 [shard 1] raft - [group_id:1, {kafka/panda-topic/0}] consensus.cc:510 - Updated node {id: {1}, revision: {16}} match 352 and next 353 indices
TRACE 2023-03-07 18:52:26,207 [shard 0] kafka - request_context.h:168 - [172.16.48.27:57122] sending 2:list_offsets for {rdkafka}, response {throttle_time_ms=0 topics={{name={panda-topic} partitions={{partition_index=0 error_code={ error_code: none [0] } old_style_offsets={} timestamp={timestamp: missing} offset=-1 leader_epoch=-1}}}}}

It does look like this node is the leader, though this is the only timequery the node services before the test is shutdown, so perhaps this is an issue with leadership change. Later down, it does look like a segment does exist with the requested timestamp.

DEBUG 2023-03-07 18:52:27,744 [shard 0] storage - disk_log_impl.cc:128 - closing log {offsets: {start_offset:0, committed_offset:313, committed_offset_term:1, dirty_offset:313, dirty_offset_term:1, last_term_start_offset:0}, max_collectible_offset: -9223372036854775808, is_closed: false, segments: [{size: 1, [{offset_tracker:{term:1, base_offset:0, committed_offset:313, dirty_offset:313}, compacted_segment=0, finished_self_compaction=0, generation={74}, reader={/var/lib/redpanda/data/kafka/panda-topic/2_16/0-1-v1.log, (332885 bytes)}, writer={no_of_chunks:64, closed:0, fallocation_offset:1064960, committed_offset:332885, bytes_flush_pending:0}, cache={cache_size=37}, compaction_index:nullopt, closed=0, tombstone=0, index={file:/var/lib/redpanda/data/kafka/panda-topic/2_16/0-1-v1.base_index, offsets:{0}, index:{header_bitflags:0, base_offset:{0}, max_offset:{313}, base_timestamp:{timestamp: 1664453149000}, max_timestamp:{timestamp: 1664453149999}, index(9,9,9)}, step:32768, needs_persistence:1}}]}], config: {ntp: {kafka/panda-topic/2}, base_dir: /var/lib/redpanda/data, overrides: {compaction_strategy: {nullopt}, cleanup_policy_bitflags: {delete}, segment_size: {nullopt}, retention_bytes: {}, retention_time_ms: {}, recovery_enabled: false, retention_local_target_bytes: {}, retention_local_target_ms: {}}, revision: 16, initial_revision: 16}}

{timestamp: 1664453149000}, max_timestamp:{timestamp: 1664453149999} vs 1664453149120

[mmaslankaprv]

seen the same here:https://buildkite.com/redpanda/redpanda/builds/26916#01877486-6765-42bd-8356-0ae153bc4b81