[MDEV-24088] Assertion in InnoDB's FTS code may be triggered by a repeated words fed to simple_parser plugin Created: 2020-11-02  Updated: 2022-01-25  Resolved: 2022-01-24

Status: Closed
Project: MariaDB Server
Component/s: Full-text Search, Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.2.42, 10.3.33, 10.4.23, 10.5.14, 10.6.6

Type: Bug Priority: Major
Reporter: Rinat Ibragimov (Inactive) Assignee: Sergei Golubchik
Resolution: Fixed Votes: 1
Labels: consistency, corruption, upstream

Issue Links:
Relates
relates to MDEV-25438 Assertion failed in fts_cache_node_ad... Open
relates to MDEV-19522 Assertion `val <= 4294967295u' failed... Closed
relates to MDEV-24608 Failing assertion: error == DB_SUCCES... Open

 Description   

It's possible to trigger an assertion in debug builds by executing the following statements:

INSTALL PLUGIN simple_parser SONAME 'mypluglib';
 
CREATE TABLE articles(
 
 a TEXT DEFAULT NULL,
 
 b TEXT DEFAULT NULL,
 
 FULLTEXT (a, b) WITH PARSER simple_parser
 
) ENGINE=InnoDB;
 
INSERT INTO articles VALUES ('111', '1234 1234 1234');
 
DROP TABLE articles;
 
UNINSTALL PLUGIN simple_parser;

Here is what the stack trace looks like:

Thread pointer: 0x7f9f6c000d90
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x7f9fc6bdedd0 thread_stack 0x49000
 
/work/mariadb/build/sql/mysqld(my_print_stacktrace+0x3c)[0x55c52cc99c12]
 
mysys/stacktrace.c:268(my_print_stacktrace)[0x55c52c35a24a]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x15540)[0x7f9fcd704540]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb)[0x7f9fcc8e93eb]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x12b)[0x7f9fcc8c8899]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x25769)[0x7f9fcc8c8769]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x37006)[0x7f9fcc8da006]
 
fts/fts0fts.cc:1274(fts_cache_node_add_positions(fts_cache_t*, fts_node_t*, unsigned long, ib_vector_t*))[0x55c52c85b3c9]
 
fts/fts0fts.cc:1409(fts_cache_add_doc(fts_cache_t*, fts_index_cache_t*, unsigned long, ib_rbt_t*))[0x55c52c85b849]
 
fts/fts0fts.cc:3581(fts_add_doc_by_id(fts_trx_table_t*, unsigned long, ib_vector_t*))[0x55c52c85fffa]
 
fts/fts0fts.cc:2871(fts_add(fts_trx_table_t*, fts_trx_row_t*))[0x55c52c85e63b]
 
fts/fts0fts.cc:3042(fts_commit_table(fts_trx_table_t*))[0x55c52c85edf6]
 
fts/fts0fts.cc:3090(fts_commit(trx_t*))[0x55c52c85eeed]
 
trx/trx0trx.cc:1863(trx_commit_low(trx_t*, mtr_t*))[0x55c52cab4bcc]
 
trx/trx0trx.cc:1940(trx_commit(trx_t*))[0x55c52cab4da1]
 
trx/trx0trx.cc:2164(trx_commit_for_mysql(trx_t*))[0x55c52cab5690]
 
handler/ha_innodb.cc:4424(innobase_commit_low(trx_t*))[0x55c52c744cac]
 
handler/ha_innodb.cc:4550(innobase_commit_ordered_2(trx_t*, THD*))[0x55c52c744ff8]
 
handler/ha_innodb.cc:4674(innobase_commit(handlerton*, THD*, bool))[0x55c52c74545e]
 
sql/handler.cc:1604(commit_one_phase_2(THD*, bool, THD_TRANS*, bool))[0x55c52c1db56b]
 
sql/handler.cc:1585(ha_commit_one_phase(THD*, bool))[0x55c52c1db461]
 
sql/handler.cc:1452(ha_commit_trans(THD*, bool))[0x55c52c1dad09]
 
sql/transaction.cc:510(trans_commit_stmt(THD*))[0x55c52c63659a]
 
sql/sql_parse.cc:6036(mysql_execute_command(THD*))[0x55c52c4aec16]
 
sql/sql_parse.cc:7733(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55c52c4b366f]
 
sql/sql_parse.cc:1826(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55c52c4a197e]
 
sql/sql_parse.cc:1377(do_command(THD*))[0x55c52c4a0479]
 
sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x55c52c6205d5]
 
sql/sql_connect.cc:1242(handle_one_connection)[0x55c52c62033a]
 
perfschema/pfs.cc:1871(pfs_spawn_thread)[0x55c52cc18296]
 
nptl/pthread_create.c:480(start_thread)[0x7f9fcd6f8669]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43)[0x7f9fcc9c5323]



 Comments   
Comment by Alice Sherepa [ 2020-11-02 ]

Thank you for the report! I repeated as described on 10.2-10.5

10.2 784473b986625c25a7ab5b

 
#5  0x00007ff365c5f535 in __GI_abort () at abort.c:79
 
#6  0x00007ff365c5f40f in __assert_fail_base (fmt=0x7ff365dc1ee0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55ce100bdbb0 "last_pos == 0 || pos > last_pos", file=0x55ce100bd710 "/10.2/storage/innobase/fts/fts0fts.cc", line=1269, function=<optimized out>) at assert.c:92
 
#7  0x00007ff365c6d102 in __GI___assert_fail (assertion=0x55ce100bdbb0 "last_pos == 0 || pos > last_pos", file=0x55ce100bd710 "/10.2/storage/innobase/fts/fts0fts.cc", line=1269, function=0x55ce100bfa80 <fts_cache_node_add_positions(fts_cache_t*, fts_node_t*, unsigned long, ib_vector_t*)::__PRETTY_FUNCTION__> "void fts_cache_node_add_positions(fts_cache_t*, fts_node_t*, doc_id_t, ib_vector_t*)") at assert.c:101
 
#8  0x000055ce0fb32436 in fts_cache_node_add_positions (cache=0x7ff3080ab190, node=0x7ff308036998, doc_id=1, positions=0x7ff30818eec0) at /10.2/storage/innobase/fts/fts0fts.cc:1269
 
#9  0x000055ce0fb328b2 in fts_cache_add_doc (cache=0x7ff3080ab190, index_cache=0x7ff3080ab520, doc_id=1, tokens=0x7ff30806fb80) at /10.2/storage/innobase/fts/fts0fts.cc:1403
 
#10 0x000055ce0fb36fbd in fts_add_doc_by_id (ftt=0x7ff30808e4a0, doc_id=1, fts_indexes=0x0) at /10.2/storage/innobase/fts/fts0fts.cc:3553
 
#11 0x000055ce0fb3568f in fts_add (ftt=0x7ff30808e4a0, row=0x7ff308149c30) at /10.2/storage/innobase/fts/fts0fts.cc:2846
 
#12 0x000055ce0fb35de8 in fts_commit_table (ftt=0x7ff30808e4a0) at /10.2/storage/innobase/fts/fts0fts.cc:3018
 
#13 0x000055ce0fb35edc in fts_commit (trx=0x7ff360cad140) at /10.2/storage/innobase/fts/fts0fts.cc:3067
 
#14 0x000055ce0fa0b4aa in trx_commit_low (trx=0x7ff360cad140, mtr=0x7ff36008e060) at /10.2/storage/innobase/trx/trx0trx.cc:1895
 
#15 0x000055ce0fa0b67d in trx_commit (trx=0x7ff360cad140) at /10.2/storage/innobase/trx/trx0trx.cc:1985
 
#16 0x000055ce0fa0bf28 in trx_commit_for_mysql (trx=0x7ff360cad140) at /10.2/storage/innobase/trx/trx0trx.cc:2194
 
#17 0x000055ce0f811bbc in innobase_commit_low (trx=0x7ff360cad140) at /10.2/storage/innobase/handler/ha_innodb.cc:4426
 
#18 0x000055ce0f811eff in innobase_commit_ordered_2 (trx=0x7ff360cad140, thd=0x7ff308000d50) at /10.2/storage/innobase/handler/ha_innodb.cc:4550
 
#19 0x000055ce0f812353 in innobase_commit (hton=0x55ce1259dae0, thd=0x7ff308000d50, commit_trx=false) at /10.2/storage/innobase/handler/ha_innodb.cc:4665
 
#20 0x000055ce0f61e556 in commit_one_phase_2 (thd=0x7ff308000d50, all=false, trans=0x7ff308004030, is_real_trans=true) at /10.2/sql/handler.cc:1604
 
#21 0x000055ce0f61e456 in ha_commit_one_phase (thd=0x7ff308000d50, all=false) at /10.2/sql/handler.cc:1585
 
#22 0x000055ce0f61dd11 in ha_commit_trans (thd=0x7ff308000d50, all=false) at /10.2/sql/handler.cc:1452
 
#23 0x000055ce0f508982 in trans_commit_stmt (thd=0x7ff308000d50) at /10.2/sql/transaction.cc:510
 
#24 0x000055ce0f3ac65a in mysql_execute_command (thd=0x7ff308000d50) at /10.2/sql/sql_parse.cc:6035
 
#25 0x000055ce0f3b0ff1 in mysql_parse (thd=0x7ff308000d50, rawbuf=0x7ff3080126b8 "INSERT INTO articles VALUES ('111', '1234 1234 1234')", length=53, parser_state=0x7ff36008f5f0, is_com_multi=false, is_next_command=false) at /10.2/sql/sql_parse.cc:7733
 
#26 0x000055ce0f39f499 in dispatch_command (command=COM_QUERY, thd=0x7ff308000d50, packet=0x7ff308008b11 "INSERT INTO articles VALUES ('111', '1234 1234 1234')", packet_length=53, is_com_multi=false, is_next_command=false) at /10.2/sql/sql_parse.cc:1826
 
#27 0x000055ce0f39df1e in do_command (thd=0x7ff308000d50) at /10.2/sql/sql_parse.cc:1380
 
#28 0x000055ce0f4f30c2 in do_handle_one_connection (connect=0x55ce12592e00) at /10.2/sql/sql_connect.cc:1336
 
#29 0x000055ce0f4f2e2d in handle_one_connection (arg=0x55ce12592e00) at /10.2/sql/sql_connect.cc:1241
 
#30 0x000055ce0fcf24c0 in pfs_spawn_thread (arg=0x55ce12aaec20) at /10.2/storage/perfschema/pfs.cc:1869
 
#31 0x00007ff3663b2fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#32 0x00007ff365d364cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Marko Mäkelä [ 2021-06-08 ]

I found the stack trace in this ticket while searching for fts_commit. While working on MDEV-25506 part 3, I realized that this logic that we inherited from MySQL is completely wrong:

/****************************************************************//**
 
Commits a transaction and a mini-transaction. */
 
void
 
trx_commit_low(
 
/*===========*/
 
	trx_t*	trx,	/*!< in/out: transaction */
 
	mtr_t*	mtr)	/*!< in/out: mini-transaction (will be committed),
 
			or NULL if trx made no modifications */
 
{
 
	assert_trx_nonlocking_or_in_list(trx);
 
	ut_ad(!trx_state_eq(trx, TRX_STATE_COMMITTED_IN_MEMORY));
 
	ut_ad(!mtr || mtr->is_active());
 
	ut_ad(!mtr == !trx->has_logged());
 
 
 
	/* undo_no is non-zero if we're doing the final commit. */
 
	if (trx->fts_trx != NULL && trx->undo_no != 0) {
 
		dberr_t	error;
 
 
 
		ut_a(!trx_is_autocommit_non_locking(trx));
 
 
 
		error = fts_commit(trx);
 
 
 
		/* FTS-FIXME: Temporarily tolerate DB_DUPLICATE_KEY
 
		instead of dying. This is a possible scenario if there
 
		is a crash between insert to DELETED table committing
 
		and transaction committing. The fix would be able to
 
		return error from this function */
 
		if (error != DB_SUCCESS && error != DB_DUPLICATE_KEY) {
 
			/* FTS-FIXME: once we can return values from this
 
			function, we should do so and signal an error
 
			instead of just dying. */
 
 
 
			ut_error;
 
		}
 
	}

In MDEV-25506 part 3, a new error DB_LOCK_WAIT_TIMEOUT could be triggered during some DDL operations.

If you think about that above code, it should be glaringly obvious that we are doing things completely wrong.

  1. COMMIT cannot return an error to the SQL layer.
  2. If there was a XA PREPARE of the transaction, the only allowed further action is XA COMMIT or XA ROLLBACK. The above code would attempt to change more things during XA COMMIT.
  3. If any error occurs during the fts_commit(), we would break the consistency of the transaction.

The consistency breakage could explain some strange errors in fulltext search, such as a duplicate FTS_DOC_ID.

I think that the logic needs to be moved earlier. This is not trivial. On a quick read, it would seem that for the SQL layer it needs to be done at or before innobase_commit_ordered(). That function cannot currently return an error. Besides, fts_commit() might not be fast, like the function comment promises.

Update: This problem was filed separately as MDEV-24608.

Comment by Marko Mäkelä [ 2021-07-26 ]

serg, a fix exists that would involve changing the fulltext parser API.

Comment by Sergei Golubchik [ 2022-01-09 ]

marko, please, take a look at the suggested fix, commit 11a0b10d130

Comment by Marko Mäkelä [ 2022-01-14 ]

serg, your fix looks nice and simple to me. thiru, can you review it? I think that you are more familiar with the fulltext subsystem.

Comment by Thirunarayanan Balathandayuthapani [ 2022-01-18 ]

serg Your patch stores the wrong position of the token while using simple parser.
The following test case to understand what went wrong:

11a0b10d130

INSTALL PLUGIN simple_parser SONAME 'mypluglib';
 
CREATE TABLE articles(
 
a TEXT DEFAULT NULL,
 
b TEXT DEFAULT NULL,
 
FULLTEXT (a, b) WITH PARSER simple_parser
 
) ENGINE=InnoDB;
 
set global innodb_ft_aux_table="test/articles";
 
INSERT INTO articles VALUES ('111', '1234 1234 1234');
 
SET GLOBAL innodb_optimize_fulltext_only=ON;
 
OPTIMIZE TABLE articles;
 
Table	Op	Msg_type	Msg_text
 
test.articles	optimize	status	OK
 
set global innodb_ft_aux_table="test/articles";
 
SELECT * FROM INFORMATION_SCHEMA.innodb_ft_index_table;
 
WORD	FIRST_DOC_ID	LAST_DOC_ID	DOC_COUNT	DOC_ID	POSITION
 
111	1	1	1	1	0
 
1234	1	1	1	1	4
 
1234	1	1	1	1	1
 
1234	1	1	1	1	1
 
DROP TABLE articles;
 
UNINSTALL PLUGIN simple_parser;

Same test case without simple parser:

 
 
CREATE TABLE articles(
 
a TEXT DEFAULT NULL,
 
b TEXT DEFAULT NULL,
 
FULLTEXT (a, b)
 
) ENGINE=InnoDB;
 
set global innodb_ft_aux_table="test/articles";
 
INSERT INTO articles VALUES ('111', '1234 1234 1234');
 
SET GLOBAL innodb_optimize_fulltext_only=ON;
 
OPTIMIZE TABLE articles;
 
Table	Op	Msg_type	Msg_text
 
test.articles	optimize	status	OK
 
set global innodb_ft_aux_table="test/articles";
 
SELECT * FROM INFORMATION_SCHEMA.innodb_ft_index_table;
 
WORD	FIRST_DOC_ID	LAST_DOC_ID	DOC_COUNT	DOC_ID	POSITION
 
111	1	1	1	1	0
 
1234	1	1	1	1	4
 
1234	1	1	1	1	5
 
1234	1	1	1	1	5
 
DROP TABLE articles;

Token position should store the delta offset from the previous token present in the record.

Comment by Sergei Golubchik [ 2022-01-21 ]

A position it stores isn't "wrong" as such, it's just different. A position is not part of the API, so the number stored in internal InnoDB tables is irrelevant and does not affect MATCH results.

If it were a well defined number, like "the delta offset from the previous token present in the record", then it would've been wrong. But as far as it's some internal unimportant number that doesn't affect results — it doesn't matter what it is.

Comment by Thirunarayanan Balathandayuthapani [ 2022-01-24 ]

serg Your patch is good to go. Simple parser has the MYSQL_FTPARSER_SIMPLE_MODE. 

/*
 
  Fast and simple mode.  This mode is used for indexing, and natural
 
  language queries.
 
 
 
  The parser is expected to return only those words that go into the
 
  index. Stopwords or too short/long words should not be returned. The
 
  'boolean_info' argument of mysql_add_word() does not have to be set.
 
*/
 
  MYSQL_FTPARSER_SIMPLE_MODE= 0

Position is being used only inside innodb for proximity search query. Simple parser doesn't support phrase search query at all.

Generated at Thu Feb 08 09:27:20 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.