assertion in controller log flush

[rockwotj]

While adding a test in #15178 one of the CI repeat runs triggered an interesting assertion on the controller log.

ERROR 2023-11-28 23:33:58,399 [shard 0:clus] assert - Assert failure: (/var/lib/buildkite-agent/builds/buildkite-amd64-builders-i-06d5b3e313f2a38a6-1/redpanda/redpanda/src/v/raft/consensus.cc:2648) 'lstats.committed_offset >= _flushed_offset' Raft incorrectly tracking flushed log offset. Expected offset: 32,  current log offsets: {start_offset:0, committed_offset:31, committed_offset_term:2, dirty_offset:32, dirty_offset_term:2}, log: {offsets: {start_offset:0, committed_offset:31, committed_offset_term:2, dirty_offset:32, dirty_offset_term:2}, is_closed: false, segments: [{size: 2, [{offset_tracker:{term:1, base_offset:0, committed_offset:31, dirty_offset:31}, compacted_segment=0, finished_self_compaction=0, finished_windowed_compaction=0, generation={68}, reader={/var/lib/redpanda/data/redpanda/controller/0_0/0-1-v1.log, (7165 bytes)}, writer=nullptr, cache={cache_size=32}, compaction_index:nullopt, closed=0, tombstone=0, index={file:/var/lib/redpanda/data/redpanda/controller/0_0/0-1-v1.base_index, offsets:{0}, index:{header_bitflags:0, base_offset:{0}, max_offset:{31}, base_timestamp:{timestamp: 1701214408289}, max_timestamp:{timestamp: 1701214421105}, batch_timestamps_are_monotonic:1, with_offset:false, non_data_timestamps:0, broker_timestamp:{{timestamp: 1701214433663}}, index(1,1,1)}, step:32768, needs_persistence:0}}{offset_tracker:{term:2, base_offset:32, committed_offset:31, dirty_offset:32}, compacted_segment=0, finished_self_compaction=0, finished_windowed_compaction=0, generation={1}, reader={/var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.log, (0 bytes)}, writer={no_of_chunks:64, closed:0, fallocation_offset:33554432, committed_offset:0, inflight_writes:0, dispatched_writes:0, bytes_flush_pending:154}, cache={cache_size=1}, compaction_index:nullopt, closed=0, tombstone=0, index={file:/var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.base_index, offsets:{32}, index:{header_bitflags:0, base_offset:{32}, max_offset:{32}, base_timestamp:{timestamp: 1701214433285}, max_timestamp:{timestamp: 1701214433285}, batch_timestamps_are_monotonic:1, with_offset:true, non_data_timestamps:0, broker_timestamp:{{timestamp: 1701214438365}}, index(1,1,1)}, step:32768, needs_persistence:1}}]}], config: {ntp: {redpanda/controller/0}, base_dir: /var/lib/redpanda/data, overrides: nullptr, revision: 0, initial_revision: 0}}

Full logs: https://ci-artifacts.dev.vectorized.cloud/redpanda/41890/018c17eb-df1b-4ff9-8001-afcf2c7791e4/vbuild/ducktape/results/final/DataTransformsTest/test_identity/transactional=True/124/RedpandaService-0-140696509786832/docker-rp-21/redpanda.log
Full test results: https://ci-artifacts.dev.vectorized.cloud/redpanda/41890/018c17eb-df1b-4ff9-8001-afcf2c7791e4/vbuild/ducktape/results/final/DataTransformsTest/test_identity/transactional=True/124/

[rockwotj]

From @mmaslankaprv:

Raft flushed log, i see there was an append to a segment then it looks that Raft called flush() on disk_log_impl but it didn't advance the committed_offset

[mmaslankaprv]

The log entries from the node that crashed:

INFO  2023-11-28 23:33:58,354 [shard 0:main] storage - segment.cc:765 - Creating new segment /var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.log
TRACE 2023-11-28 23:33:58,354 [shard 0:main] storage - segment_reader.cc:95 - ::get segment file /var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.log, refcount=0
DEBUG 2023-11-28 23:33:58,357 [shard 0:main] storage - segment_reader.cc:99 - Opening segment file /var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.log
TRACE 2023-11-28 23:33:58,360 [shard 0:main] storage - segment_reader.cc:122 - ::put segment file /var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.log, refcount=1
DEBUG 2023-11-28 23:33:58,360 [shard 0:main] storage - segment_reader.cc:126 - Closing segment file /var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.log
TRACE 2023-11-28 23:33:58,367 [shard 0:main] raft - [group_id:0, {redpanda/controller/0}] consensus.cc:2987 - Updating follower stats with config {current: {voters: {{id: {1}, revision: {0}}, {id: {2}, revision: {0}}, {id: {3}, revision: {0}}}, learners: {}}, old:{nullopt}, revision: 11, update: {nullopt}, version: 6}}
TRACE 2023-11-28 23:33:58,368 [shard 0:main] raft - [group_id:0, {redpanda/controller/0}] configuration_manager.cc:161 - Adding configuration at offset 32 index 8: {current: {voters: {{id: {1}, revision: {0}}, {id: {2}, revision: {0}}, {id: {3}, revision: {0}}}, learners: {}}, old:{nullopt}, revision: 11, update: {nullopt}, version: 6}}
TRACE 2023-11-28 23:33:58,399 [shard 0:clus] raft - [group_id:0, {redpanda/controller/0}] consensus.cc:2639 - flushed offset updated: 32
ERROR 2023-11-28 23:33:58,399 [shard 0:clus] assert - Assert failure: (/var/lib/buildkite-agent/builds/buildkite-amd64-builders-i-06d5b3e313f2a38a6-1/redpanda/redpanda/src/v/raft/consensus.cc:2648) 'lstats.committed_offset >= _flushed_offset' Raft incorrectly tracking flushed log offset. Expected offset: 32,  current log offsets: {start_offset:0, committed_offset:31, committed_offset_term:2, dirty_offset:32, dirty_offset_term:2}, log: {offsets: {start_offset:0, committed_offset:31, committed_offset_term:2, dirty_offset:32, dirty_offset_term:2}, is_closed: false, segments: [{size: 2, [{offset_tracker:{term:1, base_offset:0, committed_offset:31, dirty_offset:31}, compacted_segment=0, finished_self_compaction=0, finished_windowed_compaction=0, generation={68}, reader={/var/lib/redpanda/data/redpanda/controller/0_0/0-1-v1.log, (7165 bytes)}, writer=nullptr, cache={cache_size=32}, compaction_index:nullopt, closed=0, tombstone=0, index={file:/var/lib/redpanda/data/redpanda/controller/0_0/0-1-v1.base_index, offsets:{0}, index:{header_bitflags:0, base_offset:{0}, max_offset:{31}, base_timestamp:{timestamp: 1701214408289}, max_timestamp:{timestamp: 1701214421105}, batch_timestamps_are_monotonic:1, with_offset:false, non_data_timestamps:0, broker_timestamp:{{timestamp: 1701214433663}}, index(1,1,1)}, step:32768, needs_persistence:0}}{offset_tracker:{term:2, base_offset:32, committed_offset:31, dirty_offset:32}, compacted_segment=0, finished_self_compaction=0, finished_windowed_compaction=0, generation={1}, reader={/var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.log, (0 bytes)}, writer={no_of_chunks:64, closed:0, fallocation_offset:33554432, committed_offset:0, inflight_writes:0, dispatched_writes:0, bytes_flush_pending:154}, cache={cache_size=1}, compaction_index:nullopt, closed=0, tombstone=0, index={file:/var/lib/redpanda/data/redpanda/controller/0_0/32-2-v1.base_index, offsets:{32}, index:{header_bitflags:0, base_offset:{32}, max_offset:{32}, base_timestamp:{timestamp: 1701214433285}, max_timestamp:{timestamp: 1701214433285}, batch_timestamps_are_monotonic:1, with_offset:true, non_data_timestamps:0, broker_timestamp:{{timestamp: 1701214438365}}, index(1,1,1)}, step:32768, needs_persistence:1}}]}], config: {ntp: {redpanda/controller/0}, base_dir: /var/lib/redpanda/data, overrides: nullptr, revision: 0, initial_revision: 0}}

From the logs we can see that the write was successful as the new segment is created. The log entry: flushed offset updated:... is printed only after explicitly calling _log->flush()

[Lazin]

This is a tricky bug. We're recording a dirty_offset of the log, then we're calling log.flush() and asserting that new committed_offset is equal to recorded dirty_offset (or greater). This check fails the assertion.

This is only possible if the data is flushed partially. I tried to reproduce this by doing concurrent log append/flush operations with embedded sleeps in various places but wasn't able to reproduce yet.

[Lazin]

Upd. I wasn't able to reproduce this yet. The theory is that we have a concurrent truncation and append entries request. The 'flush' picked up the first segment out of two (one just added) and flushed it expecting committed offset to move forward. But the data batch was added to the second segment (it has one batch and it's not persisted yet). This violates Raft consistency guarantees so it makes total sense to terminate. I will improve logging in case this will reproduce in CI again.

[rockwotj]

Duplicate happened in transforms, why does this seem to only happen with wasm enabled??

#16007

[rockwotj]

That one was for the controller log too.