influxdata / influxdata/influxdb
flakey test: `write_buffer::tests::test_check_mem_and_force_snapshot`
- Dominant language
- Rust
- Stars
- 31.7k
- Forks
- 3.7k
- Avg merge
- 13h 37m
- Merged PRs (30d)
- 8
Description
See [this CircleCI run](https://app.circleci.com/pipelines/github/influxdata/influxdb/46182/workflows/c4b4f87b-8858-4c90-a597-4f8fc1625e27/jobs/439129) for an example.
The error looks look like the following:
```
2025-06-02T21:59:29.945677Z INFO influxdb3_catalog::object_store: catalog not found, creating a new one catalog_uuid=807bd829-41e0-47cf-85f1-682ce3f053cb
2025-06-02T21:59:29.946284Z INFO influxdb3_catalog::object_store: persisted catalog checkpoint file sequence=0
2025-06-02T21:59:29.946332Z INFO influxdb3_catalog::catalog::update: create database name="_internal"
2025-06-02T21:59:29.946359Z INFO influxdb3_catalog::catalog: creating new database database_name="_internal"
2025-06-02T21:59:29.946828Z INFO influxdb3_catalog::object_store: persisted next catalog sequence put_result=PutResult { e_tag: Some("2289691b-6369de0d2e168-c3"), version: None } object_path=CatalogFilePath(Path { raw: "test_host/catalogs/00000000000000000001.catalog" })
2025-06-02T21:59:29.947009Z INFO influxdb3_catalog::catalog: created internal database
2025-06-02T21:59:29.953399Z INFO influxdb3_catalog::object_store: persisted next catalog sequence put_result=PutResult { e_tag: Some("2289691c-6369de0d2f8d8-3a3"), version: None } object_path=CatalogFilePath(Path { raw: "test_host/catalogs/00000000000000000002.catalog" })
2025-06-02T21:59:29.954425Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=1000000000 max_timestamp_ns=1000000000 wal_file_number=1
2025-06-02T21:59:29.964887Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=2000000000 max_timestamp_ns=2000000000 wal_file_number=2
2025-06-02T21:59:29.975168Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=3000000000 max_timestamp_ns=3000000000 wal_file_number=3
2025-06-02T21:59:29.985092Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=4000000000 max_timestamp_ns=4000000000 wal_file_number=4
2025-06-02T21:59:29.994736Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=5000000000 max_timestamp_ns=5000000000 wal_file_number=5
2025-06-02T21:59:30.004595Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=6000000000 max_timestamp_ns=6000000000 wal_file_number=6
2025-06-02T21:59:30.014433Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=7000000000 max_timestamp_ns=7000000000 wal_file_number=7
2025-06-02T21:59:30.025086Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=8000000000 max_timestamp_ns=8000000000 wal_file_number=8
2025-06-02T21:59:30.034715Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=9000000000 max_timestamp_ns=9000000000 wal_file_number=9
2025-06-02T21:59:30.044453Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=10000000000 max_timestamp_ns=10000000000 wal_file_number=10
2025-06-02T21:59:30.055298Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=11000000000 max_timestamp_ns=11000000000 wal_file_number=11
2025-06-02T21:59:30.065028Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=12000000000 max_timestamp_ns=12000000000 wal_file_number=12
2025-06-02T21:59:30.074973Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=13000000000 max_timestamp_ns=13000000000 wal_file_number=13
2025-06-02T21:59:30.084885Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=14000000000 max_timestamp_ns=14000000000 wal_file_number=14
2025-06-02T21:59:30.094388Z INFO influxdb3_wal::snapshot_tracker: snapshotting all before last wal period (using last wal period time) force_snapshot=false wal_periods_3_times_snapshot_size=false
2025-06-02T21:59:30.094426Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=15000000000 max_timestamp_ns=15000000000 wal_file_number=15
2025-06-02T21:59:30.104984Z INFO influxdb3_wal::snapshot_tracker: snapshotting all before last wal period (using last wal period time) force_snapshot=false wal_periods_3_times_snapshot_size=false
2025-06-02T21:59:30.105014Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=16000000000 max_timestamp_ns=16000000000 wal_file_number=16
2025-06-02T21:59:30.114455Z INFO influxdb3_wal::snapshot_tracker: snapshotting all before last wal period (using last wal period time) force_snapshot=false wal_periods_3_times_snapshot_size=false
2025-06-02T21:59:30.114490Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=17000000000 max_timestamp_ns=17000000000 wal_file_number=17
2025-06-02T21:59:30.125144Z INFO influxdb3_wal::snapshot_tracker: snapshotting all before last wal period (using last wal period time) force_snapshot=false wal_periods_3_times_snapshot_size=false
2025-06-02T21:59:30.125182Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=18000000000 max_timestamp_ns=18000000000 wal_file_number=18
2025-06-02T21:59:30.134770Z INFO influxdb3_wal::snapshot_tracker: snapshotting all before last wal period (using last wal period time) force_snapshot=false wal_periods_3_times_snapshot_size=false
2025-06-02T21:59:30.134801Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=19000000000 max_timestamp_ns=19000000000 wal_file_number=19
2025-06-02T21:59:30.144345Z INFO influxdb3_wal::snapshot_tracker: snapshotting all before last wal period (using last wal period time) force_snapshot=false wal_periods_3_times_snapshot_size=false
2025-06-02T21:59:30.144377Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=20000000000 max_timestamp_ns=20000000000 wal_file_number=20
2025-06-02T21:59:30.145136Z WARN influxdb3_write::write_buffer: forcing snapshot as buffer size > mem threshold current_buffer_size_bytes=20750 memory_threshold_bytes=50
2025-06-02T21:59:30.145174Z INFO influxdb3_wal::snapshot_tracker: snapshotting all force_snapshot=true wal_periods_3_times_snapshot_size=false
2025-06-02T21:59:30.145192Z INFO influxdb3_wal::object_store: flushing WAL buffer to object store host="test_host" n_ops=1 min_timestamp_ns=0 max_timestamp_ns=1 wal_file_number=21
2025-06-02T21:59:30.145428Z INFO influxdb3_wal::object_store: snapshotting wal snapshot_details=SnapshotDetails { snapshot_sequence_number: SnapshotSequenceNumber(1), end_time_marker: 60000000000, first_wal_sequence_number: WalFileSequenceNumber(1), last_wal_sequence_number: WalFileSequenceNumber(21), forced: true }
2025-06-02T21:59:30.145444Z INFO influxdb3_write::write_buffer::queryable_buffer: Buffering contents and persisting snapshotted data snapshot_details=SnapshotDetails { snapshot_sequence_number: SnapshotSequenceNumber(1), end_time_marker: 60000000000, first_wal_sequence_number: WalFileSequenceNumber(1), last_wal_sequence_number: WalFileSequenceNumber(21), forced: true }
2025-06-02T21:59:30.145850Z INFO influxdb3_write::write_buffer::queryable_buffer: persisting 1 chunks for wal number 21
2025-06-02T21:59:30.145965Z INFO influxdb3_write::write_buffer::queryable_buffer: Persisting 300 rows for db id 1 and table id 0 and chunk 0 to file test_host/dbs/sample-1/cpu-0/1970-01-01/00-00/0000000021.parquet
2025-06-02T21:59:30.160571Z INFO influxdb3_catalog::catalog::update: create database name="_internal"
2025-06-02T21:59:30.164134Z INFO influxdb3_write::write_buffer::queryable_buffer: Persisted parquet file: test_host/dbs/sample-1/cpu-0/1970-01-01/00-00/0000000021.parquet
test write_buffer::tests::test_check_mem_and_force_snapshot ... FAILED
failures:
failures:
write_buffer::tests::test_check_mem_and_force_snapshot
test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 52 filtered out; finished in 0.55s
stderr ───
thread 'write_buffer::tests::test_check_mem_and_force_snapshot' panicked at influxdb3_write/src/write_buffer/mod.rs:3378:10:
called `Result::unwrap()` on an `Err` value: WalError(ObjectStoreError(NotFound { path: "/tmp/influxdb_ioxBxy9pc/test_host/wal/00000000001.wal", source: Os { code: 2, kind: NotFound, message: "No such file or directory" } }))
```
I've seen similar flakes happen in our Enterprise code base where the root cause ended up being a race between some async task doing the actual object store delets and the async task attempting to query or validate some system state.
In this case it looks like the panic happens during write buffer initialization:
* https://github.com/influxdata/influxdb/blob/4c62b5273c6c887de1fb4ca72af9ad3fdcea4cd2/influxdb3_write/src/write_buffer/mod.rs#L3378
Contributor guide
Research direction
Start with influxdb3_write/src/write_buffer/mod.rs at line 3378 and the write_buffer::tests::test_check_mem_and_force_snapshot test. Reproduce the failure from the linked CircleCI run, then trace write buffer initialization alongside WAL object-store deletion and validation tasks. Done means the test no longer intermittently fails with a missing WAL file.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- rust
- Domain
- databases, testing-qa
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 42/100