MySQL Bugs: #78423: fts: Duplicate FTS_DOC_ID value on table / Cannot find index FTS_DOC_ID

Bug #78423	fts: Duplicate FTS_DOC_ID value on table / Cannot find index FTS_DOC_ID_INDEX
Submitted:	14 Sep 2015 2:27	Modified:	10 Oct 2015 8:27
Reporter:	Dimension Lin	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.6.16, 5.6.26	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	Duplicate FTS_DOC_ID, fts, innodb

Description:
In a prior bug, https://bugs.mysql.com/bug.php?id=70311, Shane Bester describe a scene that would cause "Duplicate FTS_DOC_ID",  but the fix would also cause the same problem as discribed in the testcase file.

How to repeat:
> We make debug_sync point here:
storage/innobase/fts/fts0fts.cc: around line 2637

2626   if (cache->first_doc_id != 0 || !fts_init_doc_id(table)) {
2627     if (!DICT_TF2_FLAG_IS_SET(table, DICT_TF2_FTS_HAS_DOC_ID)) {
2628       *doc_id = FTS_NULL_DOC_ID;
2629       return(DB_SUCCESS);                                                                                                                                                                                 
2630     }
2631 
2632     /* Otherwise, simply increment the value in cache */
2633     mutex_enter(&cache->doc_id_lock);
2634     *doc_id = ++cache->next_doc_id;
2635     mutex_exit(&cache->doc_id_lock);
2636   } else {
2637     DEBUG_SYNC_C("ib_before_get_the_first_doc_id");
2638     mutex_enter(&cache->doc_id_lock);
2639     *doc_id = cache->next_doc_id;
2640     mutex_exit(&cache->doc_id_lock);
2641   }

> And use the testcase file like this:

--source include/have_debug.inc

connect(con1, localhost, root, ,);
connect(con2, localhost, root, ,);

connection con1;
set debug_sync = 'RESET';
set debug_sync = 'ib_before_get_the_first_doc_id signal hehe wait_for second_finish';
begin;
drop table if exists t1;
create table if not exists t1(a varchar(5),fulltext key(a))engine=innodb;
--send replace into t1(a) values("aaa");

connection con2;
set debug_sync = 'now wait_for hehe';
replace into t1(a) values("aaa");
set debug_sync = 'now signal second_finish';

connection con1;
--exec cat $MYSQLTEST_VARDIR/log/mysqld.1.err 
--reap
commit;

Suggested fix:
let mutex_enter, and mutex_exit in the "if ... else ..." range, like this:
storage/innobase/fts/fts0fts.cc

2626         mutex_enter(&cache->doc_id_lock);
2627         if (cache->first_doc_id != 0 || !fts_init_doc_id(table)) {
2628                 if (!DICT_TF2_FLAG_IS_SET(table, DICT_TF2_FTS_HAS_DOC_ID)) {
2629                         *doc_id = FTS_NULL_DOC_ID;
2630                         mutex_exit(&cache->doc_id_lock);
2631                         return(DB_SUCCESS);
2632                 }
2633 
2634                 /* Otherwise, simply increment the value in cache */
2635                 *doc_id = ++cache->next_doc_id;
2636         } else {
2637                 *doc_id = cache->next_doc_id;
2638         }
2639         mutex_exit(&cache->doc_id_lock);
2640         return(DB_SUCCESS);

Sorry, this fix may cause crash.

Hello Dimension Lin,

Thank you for the report and test case.

Thanks,
Umesh

// 5.6.26

[umshastr@hod03]/export/umesh/server/source/78423/mysql-5.6.26/mysql-test: ./mtr 78423
Logging: ./mtr  78423
2015-09-14 06:44:19 0 [Note] /export/umesh/server/source/78423/mysql-5.6.26/sql/mysqld (mysqld 5.6.26-debug) starting as process 26822 ...
2015-09-14 06:44:19 26822 [Note] Plugin 'FEDERATED' is disabled.
2015-09-14 06:44:19 26822 [Note] Binlog end
2015-09-14 06:44:19 26822 [Note] Shutting down plugin 'CSV'
2015-09-14 06:44:19 26822 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.26
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Removing old var directory...
Creating var directory '/export/umesh/server/source/78423/mysql-5.6.26/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
set debug_sync = 'RESET';
set debug_sync = 'ib_before_get_the_first_doc_id signal hehe wait_for second_finish';
begin;
drop table if exists t1;
Warnings:
Note    1051    Unknown table 'test.t1'
create table if not exists t1(a varchar(5),fulltext key(a))engine=innodb;
replace into t1(a) values("aaa");;
set debug_sync = 'now wait_for hehe';
replace into t1(a) values("aaa");
set debug_sync = 'now signal second_finish';
CURRENT_TEST: main.78423
2015-09-14 07:44:22 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-09-14 07:44:22 0 [Note] /export/umesh/server/source/78423/mysql-5.6.26/sql/mysqld (mysqld 5.6.26-debug-log) starting as process 27175 ...
2015-09-14 07:44:22 27175 [Note] Plugin 'FEDERATED' is disabled.
2015-09-14 07:44:22 7fcc58a43740 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2015-09-14 07:44:22 27175 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-09-14 07:44:22 7fcc58a43740 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2015-09-14 07:44:22 7fcc58a43740 InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2015-09-14 07:44:22 27175 [Note] InnoDB: The InnoDB memory heap is disabled
2015-09-14 07:44:22 27175 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-09-14 07:44:22 27175 [Note] InnoDB: Memory barrier is not used
2015-09-14 07:44:22 27175 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-09-14 07:44:22 27175 [Note] InnoDB: Using Linux native AIO
2015-09-14 07:44:22 27175 [Note] InnoDB: Using CPU crc32 instructions
2015-09-14 07:44:22 27175 [Note] InnoDB: Initializing buffer pool, size = 8.0M
2015-09-14 07:44:22 27175 [Note] InnoDB: Completed initialization of buffer pool
2015-09-14 07:44:22 27175 [Note] InnoDB: Highest supported file format is Barracuda.
2015-09-14 07:44:23 27175 [Note] InnoDB: 128 rollback segment(s) are active.
2015-09-14 07:44:23 27175 [Note] InnoDB: Waiting for purge to start
2015-09-14 07:44:23 27175 [Note] InnoDB: 5.6.26 started; log sequence number 1625977
2015-09-14 07:44:23 27175 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 456f43ec-5a9b-11e5-9c5b-0010e05f3e06.
2015-09-14 07:44:23 27175 [Note] Server hostname (bind-address): '*'; port: 13000
2015-09-14 07:44:23 27175 [Note] IPv6 is available.
2015-09-14 07:44:23 27175 [Note]   - '::' resolves to '::';
2015-09-14 07:44:23 27175 [Note] Server socket created on IP: '::'.
2015-09-14 07:44:23 27175 [Note] Event Scheduler: Loaded 0 events
2015-09-14 07:44:23 27175 [Note] /export/umesh/server/source/78423/mysql-5.6.26/sql/mysqld: ready for connections.
Version: '5.6.26-debug-log'  socket: '/export/umesh/server/source/78423/mysql-5.6.26/mysql-test/var/tmp/mysqld.1.sock'  port: 13000  Source distribution
2015-09-14 07:44:23 27175 [ERROR] InnoDB: Duplicate FTS_DOC_ID value on table test/t1
2015-09-14 07:44:23 27175 [ERROR] Cannot find index FTS_DOC_ID_INDEX in InnoDB index translation table.
2015-09-14 07:44:23 27175 [Warning] Find index FTS_DOC_ID_INDEX in InnoDB index list but not its MySQL index number It could be an InnoDB internal index.
2015-09-14 07:44:23 27175 [ERROR] Cannot find index FTS_DOC_ID_INDEX in InnoDB index translation table.
2015-09-14 07:44:23 27175 [Warning] Find index FTS_DOC_ID_INDEX in InnoDB index list but not its MySQL index number It could be an InnoDB internal index.
main.78423                               [ fail ]
        Test ended at 2015-09-14 06:44:23

CURRENT_TEST: main.78423
mysqltest: At line 21: query 'reap' failed: 1022: Can't write; duplicate key in table 't1'

 - saving '/export/umesh/server/source/78423/mysql-5.6.26/mysql-test/var/log/main.78423/' to '/export/umesh/server/source/78423/mysql-5.6.26/mysql-test/var/log/main.78423/'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 4 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.78423

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases
[umshastr@hod03]/export/umesh/server/source/78423/mysql-5.6.26/mysql-test:

The suggested fix commit above is wrong. Because the cache->doc_id_lock would conflict with table->fts->cache->lock in function fts_init_doc_id. The suggested fix following may work.

storage/innobase/fts/fts0fts.cc:
2627         if (cache->first_doc_id != 0 || !fts_init_doc_id(table)) {
2628                 flag = true;
2629         }
2630         mutex_enter(&cache->doc_id_lock);
2631         if (flag) {
2632                 if (!DICT_TF2_FLAG_IS_SET(table, DICT_TF2_FTS_HAS_DOC_ID)) {
2633                         *doc_id = FTS_NULL_DOC_ID;
2634                         mutex_exit(&cache->doc_id_lock);
2635                         return(DB_SUCCESS);
2636                 }
2637 
2638                 /* Otherwise, simply increment the value in cache */
2639                 *doc_id = ++cache->next_doc_id;
2640         } else {
2641                 *doc_id = cache->next_doc_id;
2642         }
2643 
2644         mutex_exit(&cache->doc_id_lock);

Sorry, the suggested fix above from me is all wrong. And the latest fix from me below may work. In fact, when cache->first_doc_id==0, the fts_init_doc_id must return a nonzero value and the return value(max_doc_id) is cache->next_doc_id(from the logic of function fts_cmp_set_sync_doc_id). So we can set *doc_id in "if" statement and any problem of synchronization I've ever encountered can be perfectly solved.

diff --git a/storage/innobase/fts/fts0fts.cc b/storage/innobase/fts/fts0fts.cc
index 1b3977f..3fb9c30 100644
--- a/storage/innobase/fts/fts0fts.cc
+++ b/storage/innobase/fts/fts0fts.cc
@@ -2623,7 +2623,7 @@ fts_get_next_doc_id(
 	will consult the CONFIG table and user table to re-establish
 	the initial value of the Doc ID */
 
-	if (cache->first_doc_id != 0 || !fts_init_doc_id(table)) {
+	if (cache->first_doc_id != 0 || !(*doc_id = fts_init_doc_id(table))) {
 		if (!DICT_TF2_FLAG_IS_SET(table, DICT_TF2_FTS_HAS_DOC_ID)) {
 			*doc_id = FTS_NULL_DOC_ID;
 			return(DB_SUCCESS);
@@ -2633,10 +2633,6 @@ fts_get_next_doc_id(
 		mutex_enter(&cache->doc_id_lock);
 		*doc_id = ++cache->next_doc_id;
 		mutex_exit(&cache->doc_id_lock);
-	} else {
-		mutex_enter(&cache->doc_id_lock);
-		*doc_id = cache->next_doc_id;
-		mutex_exit(&cache->doc_id_lock);
 	}

Is this bug fixed? I met the same problem in 8.0.22