Assertion has triggered: src/box/vy_cache.c:383: vy_cache_add: Assertion `cmp == 0' failed.

[ligurio]

Bug description

tarantool has crashed again on running test for vinyl engine

• OS: Linux
• OS Version: Ubuntu 24.04
• Architecture: amd64

Tarantool 3.3.0-entrypoint-31-g9eb397499
Target: Linux-x86_64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=TRUE
Compiler: Clang-18.1.3
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/ubuntu/tarantool=. -std=c11 -Wall -Wextra -Wno-gnu-alignof-expression -Wno-cast-function-type -O2 -g -DNDEBUG -ggdb -O2
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/ubuntu/tarantool=. -std=c++11 -Wall -Wextra -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type -O2 -g -DNDEBUG -ggdb -O2

Steps to reproduce

$ seed=$RANDOM; ./build/src/tarantool ./test/fuzz/lua/test_engine.lua --workers 6000 --test_duration $((2*60*60)) --engine vinyl --verbose --seed $seed 2>&1 | tee vinyl.log; echo $seed

seed is 8948

Actual behavior

#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007c63a884526e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007c63a88288ff in __GI_abort () at ./stdlib/abort.c:79
#5  0x000055a28cbba1a2 in crash_signal_cb (signo=<optimized out>, siginfo=<optimized out>, context=<optimized out>)
    at /home/ubuntu/tarantool/src/lib/core/crash.c:204
#6  <signal handler called>
#7  0x000055a28ca7f688 in matras_view_get_no_check (m=0x55a28d8de970, v=<optimized out>, id=<optimized out>)
    at /home/ubuntu/tarantool/src/lib/small/include/small/matras.h:414
#8  matras_view_get (m=0x55a28d8de970, v=<optimized out>, id=<optimized out>) at /home/ubuntu/tarantool/src/lib/small/include/small/matras.h:424
#9  bps_tree_vy_cache_tree_restore_block (tree=0x55a28d8de920, id=<optimized out>) at /home/ubuntu/tarantool/src/lib/salad/bps_tree.h:1863
#10 bps_tree_vy_cache_tree_get_leaf_safe (tree=<optimized out>, itr=<optimized out>) at /home/ubuntu/tarantool/src/lib/salad/bps_tree.h:2282
#11 bps_tree_vy_cache_tree_iterator_get_elem (tree=<optimized out>, itr=<optimized out>) at /home/ubuntu/tarantool/src/lib/salad/bps_tree.h:2924
#12 vy_cache_tree_iterator_get_elem (tree=<optimized out>, itr=<optimized out>) at /home/ubuntu/tarantool/src/lib/salad/bps_tree.h:2934
#13 vy_cache_gc_step (env=0x55a28d89f178) at /home/ubuntu/tarantool/src/box/vy_cache.c:192
#14 vy_cache_gc (env=0x55a28d89f178) at /home/ubuntu/tarantool/src/box/vy_cache.c:218
#15 0x000055a28ca7facc in vy_cache_add (cache=0x55a28d8de910, curr=..., prev=..., is_first=false, key=..., order=ITER_GE)
    at /home/ubuntu/tarantool/src/box/vy_cache.c:249
#16 0x000055a28ca7d261 in vy_read_iterator_cache_add (itr=itr@entry=0x7c602aba3858, entry=...)
    at /home/ubuntu/tarantool/src/box/vy_read_iterator.c:981
#17 0x000055a28ca5902e in vinyl_iterator_primary_next (base=0x7c602aba37d8, ret=0x7c6093080dd0) at /home/ubuntu/tarantool/src/box/vinyl.c:3727
#18 0x000055a28ca1dd1d in iterator_next (it=0x7c602aba37d8, ret=0x7c6093080dd0) at /home/ubuntu/tarantool/src/box/index.cc:639
#19 generic_index_count (index=<optimized out>, type=<optimized out>, key=<optimized out>, part_count=<optimized out>)
    at /home/ubuntu/tarantool/src/box/index.cc:926
#20 0x000055a28ca1cc29 in index_count (index=0x55a28d8de640, type=ITER_ALL, key=0x7c602c92a039 "\307\a\001", part_count=0)
    at /home/ubuntu/tarantool/src/box/index.h:895
#21 box_index_count (space_id=<optimized out>, index_id=<optimized out>, type=2, key=0x7c602c92a039 "\307\a\001", key_end=<optimized out>)
    at /home/ubuntu/tarantool/src/box/index.cc:486
#22 0x000055a28cb727b9 in lbox_index_count (L=0x417e2590) at /home/ubuntu/tarantool/src/box/lua/index.c:282
#23 0x000055a28cbfcbb3 in lj_BC_FUNCC () at /home/ubuntu/tarantool/build/third_party/luajit/src/lj_vm.S:811
#24 0x000055a28cc04375 in lua_pcall (L=0xffff, L@entry=0x417e2590, nargs=<optimized out>, nresults=nresults@entry=-1, errfunc=errfunc@entry=0)
    at /home/ubuntu/tarantool/third_party/luajit/src/lj_api.c:1173
#25 0x000055a28cba10df in luaT_call (L=0xffff, L@entry=0x417e2590, nargs=5, nreturns=16, nreturns@entry=-1)
    at /home/ubuntu/tarantool/src/lua/utils.c:695
#26 0x000055a28cb9a651 in lua_fiber_run_f (ap=<optimized out>) at /home/ubuntu/tarantool/src/lua/fiber.c:435
#27 0x000055a28ca0cfb9 in fiber_cxx_invoke (f=0x55a28dcd5a90, ap=0x5) at /home/ubuntu/tarantool/src/lib/core/fiber.h:1324
#28 0x000055a28cbc0915 in fiber_loop (data=<optimized out>) at /home/ubuntu/tarantool/src/lib/core/fiber.c:1162
#29 0x000055a28ce2a021 in coro_init () at /home/ubuntu/tarantool/third_party/coro/coro.c:108

Segmentation fault             
  code: 128                                                                                                                                        
  addr: (nil)                                                                                                                                      
  context: 0x55a28d85dd80
  siginfo: 0x55a28d85deb0
  rax      0x55a28dcd5a90     94156652108432
  rbx      0x80               128
  rcx      0x400005b040000d2  288230767060844754
  rdx      0x10               16
  rsi      0x5                5
  rdi      0xffff             65535
  rsp      0x7c60930808d0     136754225481936
  rbp      0x55a28d89f178     94156647690616
  r8       0x1f               31
  r9       0x200              512
  r10      0x7ff              2047
  r11      0x55a28d8de970     94156647950704
  r12      0x1f               31
  r13      0xffff             65535
  r14      0xffff             65535
  r15      0x7c6028a88568     136752440837480
  rip      0x55a28ca7f688     94156632880776
  eflags   0x10202            66050
  cs       0x33               51
  gs       0x0                0
  fs       0x0                0
  cr2      0x0                0
  err      0x0                0
  oldmask  0x0                0
  trapno   0xd                13
Current time: 1725364984
Please file a bug at https://github.com/tarantool/tarantool/issues
Attempting backtrace... Note: since the server has already crashed, 
this may fail as well
#1  0x55a28cbba24f in crash_collect+127
#2  0x55a28cbba1b3 in crash_signal_cb+179
#3  0x7c63a8845320 in __sigaction+80
#4  0x55a28ca7f688 in vy_cache_gc+536
#5  0x55a28ca7facc in vy_cache_add+92
#6  0x55a28ca7d261 in vy_read_iterator_cache_add+81
#7  0x55a28ca5902e in vinyl_iterator_primary_next+206
#8  0x55a28ca1dd1d in generic_index_count+109
#9  0x55a28ca1cc29 in box_index_count+425
#10 0x55a28cb727b9 in lbox_index_count+265
#11 0x55a28cbfcbb3 in lj_BC_FUNCC+70
#12 0x55a28cc04375 in lua_pcall+117
#13 0x55a28cba10df in luaT_call+15
#14 0x55a28cb9a651 in lua_fiber_run_f+97
#15 0x55a28ca0cfb9 in fiber_cxx_invoke(int (*)(__va_list_tag*), __va_list_tag*)+9
#16 0x55a28cbc0915 in fiber_loop+85
#17 0x55a28ce2a021 in coro_init+81

tarantool binary and coredump
https://drive.google.com/file/d/1eV00DmZxBt1T1aypHd5vszZyiMpESVRO/view?usp=sharing

Expected behavior

no crash

[ligurio]

Reproduced on debug build with command-line below

seed=8948; ./build/src/tarantool ./test/fuzz/lua/test_engine.lua --workers 6000 --test_duration $((2*60*60)) --engine vinyl --verbose --seed $seed 2>&1 | tee vinyl.log; echo $seed

and assertion is triggered:

<snipped>

2024-09-03 13:53:46.506 [1648136] main/3583/WRK #3469/..test.fuzz.lua.test_engine I> ERROR: opname "FORMAT_OP", err "Storage engine 'vinyl' does not support cross-engine transactions", args [[{"name":"field_1","type":"double"},{"name":"field_2","type":"unsigned"},{"name":"field_3","type":"uuid"},{"name":"field_4","type":"integer"},{"name":"field_5","type":"string"},{"name":"field_6","type":"number"},{"name":"field_7","type":"boolean"},{"name":"field_8","type":"decimal"},{"name":"field_9","type":"datetime"},{"name":"field_10","type":"array"},{"name":"field_11","type":"map"}]]
2024-09-03 13:53:46.507 [1648136] main/3583/WRK #3469/..test.fuzz.lua.test_engine I> ERROR: opname "INDEX_RENAME_OP", err "Storage engine 'vinyl' does not support cross-engine transactions", args [{"unique":true,"parts":[{"fieldno":8,"sort_order":"asc","type":"decimal","exclude_null":false,"is_nullable":false},{"fieldno":5,"sort_order":"asc","type":"string","exclude_null":false,"is_nullable":false},{"fieldno":1,"sort_order":"asc","type":"double","exclude_null":false,"is_nullable":false},{"fieldno":6,"sort_order":"asc","type":"number","exclude_null":false,"is_nullable":false},{"fieldno":4,"sort_order":"asc","type":"integer","exclude_null":false,"is_nullable":false},{"fieldno":7,"sort_order":"asc","type":"boolean","exclude_null":false,"is_nullable":false},{"fieldno":3,"sort_order":"asc","type":"uuid","exclude_null":false,"is_nullable":false},{"fieldno":2,"sort_order":"asc","type":"unsigned","exclude_null":false,"is_nullable":false}],"options":{"page_size":8192,"run_count_per_level":7,"run_size_ratio":5,"bloom_fpr":0.35,"range_size":1073741824},"id":0,"space_id":512,"type":"TREE","name":"idx_1"},"hqmnoyirlh"]
tarantool: ./src/box/vy_cache.c:383: vy_cache_add: Assertion `cmp == 0' failed.

Backtrace:

#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x000076b46844526e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x000076b4684288ff in __GI_abort () at ./stdlib/abort.c:79
#5  0x000076b46842881b in __assert_fail_base (fmt=0x76b4685d01e8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x6172677e3a7f "cmp == 0", file=file@entry=0x6172677e3849 "./src/box/vy_cache.c", line=line@entry=383, 
    function=function@entry=0x6172677e4078 <__PRETTY_FUNCTION__.15> "vy_cache_add") at ./assert/assert.c:94
#6  0x000076b46843b507 in __assert_fail (assertion=0x6172677e3a7f "cmp == 0", file=0x6172677e3849 "./src/box/vy_cache.c", line=383, 
    function=0x6172677e4078 <__PRETTY_FUNCTION__.15> "vy_cache_add") at ./assert/assert.c:103
#7  0x00006172671c89cb in vy_cache_add (cache=0x617268f33410, curr=..., prev=..., is_first=false, key=..., order=589505315)
    at /home/ubuntu/tarantool/src/box/vy_cache.c:383
#8  0x00006172671bab86 in vy_read_iterator_cache_add (itr=0x76b0e5af41e0, entry=...) at /home/ubuntu/tarantool/src/box/vy_read_iterator.c:981
#9  0x000061726717ad3e in vinyl_iterator_primary_next (base=0x76b0e5af4160, ret=0x76b355880c30) at /home/ubuntu/tarantool/src/box/vinyl.c:3727
#10 0x000061726710f771 in iterator_next (it=0x76b0e5af4160, ret=0x76b355880c30) at /home/ubuntu/tarantool/src/box/index.cc:639
#11 0x00006172671105d3 in generic_index_count (index=0x617268f33140, type=ITER_ALL, key=0x76b357810241 'P' <repeats 200 times>..., part_count=0)
    at /home/ubuntu/tarantool/src/box/index.cc:926
#12 0x000061726710b4e5 in index_count (index=0x617268f33140, type=ITER_ALL, key=0x76b357810241 'P' <repeats 200 times>..., part_count=0)
    at /home/ubuntu/tarantool/src/box/index.h:895
#13 0x000061726710ed13 in box_index_count (space_id=512, index_id=0, type=2, key=0x76b357810241 'P' <repeats 200 times>..., 
    key_end=0x76b357810241 'P' <repeats 200 times>...) at /home/ubuntu/tarantool/src/box/index.cc:486
#14 0x0000617267358a18 in lbox_index_count (L=0x415bd4e8) at /home/ubuntu/tarantool/src/box/lua/index.c:282
#15 0x000061726742ed87 in lj_BC_FUNCC () at buildvm_x86.dasc:811
#16 0x000061726743c8cb in lua_pcall (L=0x415bd4e8, nargs=4, nresults=-1, errfunc=0) at /home/ubuntu/tarantool/third_party/luajit/src/lj_api.c:1173
#17 0x00006172673a02de in luaT_call (L=0x415bd4e8, nargs=4, nreturns=-1) at /home/ubuntu/tarantool/src/lua/utils.c:695
#18 0x000061726739500a in lua_fiber_run_f (ap=0x76b37638eed0) at /home/ubuntu/tarantool/src/lua/fiber.c:435
#19 0x00006172670ee143 in fiber_cxx_invoke(fiber_func, typedef __va_list_tag __va_list_tag *) (f=0x617267394f4d <lua_fiber_run_f>, 
    ap=0x76b37638eed0) at /home/ubuntu/tarantool/src/lib/core/fiber.h:1324
#20 0x00006172673d0e79 in fiber_loop (data=0x0) at /home/ubuntu/tarantool/src/lib/core/fiber.c:1162
#21 0x00006172677afeb1 in coro_init () at /home/ubuntu/tarantool/third_party/coro/coro.c:108

Tarantool 3.3.0-entrypoint-35-g9519fe930
Target: Linux-x86_64-Debug
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=TRUE
Compiler: GNU-13.2.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/ubuntu/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/ubuntu/tarantool=. -std=c++11 -Wall -Wextra -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type -Werror -g -ggdb -O0

tarantool binary + vinyl.log + coredump: https://drive.google.com/file/d/1rIsCyivVevZeMgwt22uFQJSB1XeuSnpf/view?usp=sharing

[locker]

Judging by the last core dump, the problem appears to be caused by a run iterator skipping over a page. In the logs of both runs I see that the test toggles the error injection that makes a statement allocation fail:

2024-09-03 13:53:29.747 [1648136] main/6115/ERRINJ I> ERRINJ_VY_STMT_ALLOC = 0

There's a bug in the procedure that looks up a key in a page - it doesn't handle OOM caused by this error injection:

tarantool/src/box/vy_run.c

Lines 791 to 825 in 6fd4544

	/**
	* Binary search in page
	* In terms of STL, makes lower_bound for EQ,GE,LT and upper_bound for GT,LE
	* Additionally *equal_key argument is set to true if the found value is
	* equal to given key (set to false otherwise).
	* @retval position in the page
	*/
	static uint32_t
	vy_page_find_key(struct vy_page *page, struct vy_entry key,
	struct key_def *cmp_def, struct tuple_format *format,
	enum iterator_type iterator_type, bool *equal_key)
	{
	uint32_t beg = 0;
	uint32_t end = page->row_count;
	*equal_key = false;
	/* for upper bound we change zero comparison result to -1 */
	int zero_cmp = (iterator_type == ITER_GT ||
	iterator_type == ITER_LE ? -1 : 0);
	while (beg != end) {
	uint32_t mid = beg + (end - beg) / 2;
	struct vy_entry fnd_key = vy_page_stmt(page, mid, cmp_def,
	format);
	if (fnd_key.stmt == NULL)
	return end;
	int cmp = vy_entry_compare(fnd_key, key, cmp_def);
	cmp = cmp ? cmp : zero_cmp;
	*equal_key = *equal_key || cmp == 0;
	if (cmp < 0)
	beg = mid + 1;
	else
	end = mid;
	tuple_unref(fnd_key.stmt);
	}
	return end;
	}

Note that if vy_page_stmt() fails by OOM, it just returns end as if the key must be in the next page. This causes the key search to skip over to the next page:

tarantool/src/box/vy_run.c

Lines 2624 to 2661 in 6fd4544

	/**
	* Binary search in a run for the given key. Find the first position with
	* a tuple greater or equal to slice
	* @retval 0 success
	* @retval -1 read or memory error
	*/
	static NODISCARD int
	vy_slice_stream_search(struct vy_stmt_stream *virt_stream)
	{
	assert(virt_stream->iface->start == vy_slice_stream_search);
	struct vy_slice_stream *stream = (struct vy_slice_stream *)virt_stream;
	assert(stream->page == NULL);
	if (stream->slice->begin.stmt == NULL) {
	/* Already at the beginning */
	assert(stream->page_no == 0);
	assert(stream->pos_in_page == 0);
	return 0;
	}
	if (vy_slice_stream_read_page(stream) != 0)
	return -1;
	bool unused;
	stream->pos_in_page = vy_page_find_key(stream->page,
	stream->slice->begin,
	stream->cmp_def,
	stream->format,
	ITER_GE, &unused);
	if (stream->pos_in_page == stream->page->row_count) {
	/* The first tuple is in the beginning of the next page */
	vy_page_delete(stream->page);
	stream->page = NULL;
	stream->page_no++;
	stream->pos_in_page = 0;
	}
	return 0;
	}

This bug was introduced by commit ac8ce02.

In practice, a statement allocation shouldn't fail because it uses malloc() so I'm not going to mention the fix in the release notes.

[locker]

Actually, it is possible to reproduce this issue without error injections - by tuning vinyl_max_tuple_size:

box.cfg{log_level = 'warn'}

box.schema.create_space('test', {engine = 'vinyl'})
box.space.test:create_index('primary')

local pad = string.rep('x', 1024)
box.space.test:insert{1, pad}
box.space.test:insert{2, pad}
box.space.test:insert{3, pad}
box.snapshot()

box.cfg{vinyl_max_tuple_size = 512}
print('count =', box.space.test:count({2}, {iterator = 'gt'}))

os.exit(0)

The count statement prints an error to the log but still returns 0, which is obviously incorrect (should be 1):

2024-09-05 11:31:55.946 [402048] vinyl.reader.0/101/main vy_stmt.c:219 E> ER_VINYL_MAX_TUPLE_SIZE: Failed to allocate 1053 bytes for tuple: tuple is too large. Check 'vinyl_max_tuple_size' configuration option.
count = 0

This still looks rather artificial and I doubt it'd affect any of our users but okay, let's add a test and a change log.