ER_INVALID_VYLOG_FILE: Invalid VYLOG file: Run 9455 forgotten but not registered #10128
Description
Bug description
- OS: Linux
- OS Version: Ubuntu 22.04
- Architecture: amd64
Tarantool 3.2.0-entrypoint-69-gbde28f0faa
Target: Linux-x86_64-Debug
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=TRUE
Compiler: GNU-11.4.0
C_FLAGS: -fexceptions -funwind-tables -fasynchronous-unwind-tables -fno-common -msse2 -Wformat -Wformat-security -Werror=format-security -fstack-protector-strong -fPIC -fmacro-prefix-map=/home/sergeyb/sources/MRG/tarantool=. -std=c11 -Wall -Wextra -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type -Werror -g -ggdb -O0
CXX_FLAGS: -fexceptions -funwind-tables -fasynchronous-unwind-tables -fno-common -msse2 -Wformat -Wformat-security -Werror=format-security -fstack-protector-strong -fPIC -fmacro-prefix-map=/home/sergeyb/sources/MRG/tarantool=. -std=c++11 -Wall -Wextra -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type -Werror -g -ggdb -O0
Steps to reproduce
none
(test randomly generate a lot GET/SELECT/UPSERT/UPDATE/DELETE/REPLACE operations)
Actual behavior
tarantool produce errors like: "Run 9455 forgotten but not registered" in tarantool.log:
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: create_run{lsm_id=2, run_id=9465, dump_lsn=327051, dump_count=1, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: create_run{lsm_id=2, run_id=9469, dump_lsn=327133, dump_count=1, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_range{lsm_id=2, range_id=3, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9457, slice_id=9458, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9459, slice_id=9460, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9461, slice_id=9462, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9463, slice_id=9464, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9465, slice_id=9466, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9467, slice_id=9468, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9469, slice_id=9470, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: insert_slice{range_id=3, run_id=9471, slice_id=9472, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: snapshot{}
2024-06-11 10:35:47.772 [89800] main/126/WRK #13/..vinyl I> ERROR: Duplicate key exists in unique index "idx_1" in space "test_1" with old tuple - [802178120823, 2.97289e+11, 191140122811, 3.60836e+11, [1, 2, 3, 4, 5, 6, 7], 987831012649] and new tuple - [802178120823, 2.97289e+11, 191140122811, 3.60836e+11, [1, 2, 3, 4, 5, 6, 7], 987831012649]
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: forget_run{run_id=9455, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: prepare_run{lsm_id=2, run_id=9473, }
2024-06-11 10:35:47.772 [89800] coio V> load vylog record: forget_run{run_id=9455, }
2024-06-11 10:35:47.772 [89800] main/339/WRK #226/..vinyl I> ["REPLACE_OP",[[628227398792,199843486237.94,828045758318,180221877335.33,[1,2,3,4,5,6,7],"436057987805"]]]
2024-06-11 10:35:47.772 [89800] coio vy_log.c:2274 E> failed to process vylog record: forget_run{run_id=9455, }
2024-06-11 10:35:47.772 [89800] main/370/WRK #257/..vinyl I> ["SELECT_OP",[[145895600423.05,432540625438,510211626117]]]
2024-06-11 10:35:47.772 [89800] main/260/WRK #147 vy_log.c:1931 E> ER_INVALID_VYLOG_FILE: Invalid VYLOG file: Run 9455 forgotten but not registered
2024-06-11 10:35:47.772 [89800] main/260/WRK #147 vy_log.c:2482 E> failed to load `./00000000000000327164.vylog'
2024-06-11 10:35:47.772 [89800] main/168/WRK #55/..vinyl I> ["UPDATE_OP",[[986106292998.9,349043095885,959857557665],[["-",4,775042531968.77]]]]
2024-06-11 10:35:47.772 [89800] main/202/WRK #89/..vinyl I> ["UPSERT_OP",[[673554335391,90127229087.226,700449174830,360237900959.4,[1],"708762623333"],[["-",2,747265070170.86]]]]
Full log with log_level = verbose: gh-10128.zip
Expected behavior
no errors in the log