Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Cannot Reproduce
-
10.2.12, 10.3.4, 10.1.34, 10.2.14, 10.3.6, 10.3.7, 10.1.42
-
None
-
Ubuntu Xenial
Description
CREATE TABLE `user` ( |
`id` int(11) unsigned NOT NULL, |
`revision_date` int(14) NOT NULL, |
`revision_author` int(11) unsigned NOT NULL, |
`creation_date` int(14) NOT NULL, |
`creation_author` int(11) unsigned NOT NULL, |
`deleted` tinyint(1) NOT NULL, |
`user` varchar(250) NOT NULL, |
`password` varchar(255) NOT NULL, |
`name` varchar(250) NOT NULL, |
`surname` varchar(250) NOT NULL, |
`lastlogin` int(14) NOT NULL, |
`lastip` varchar(32) NOT NULL, |
`email` varchar(60) NOT NULL, |
PRIMARY KEY (`id`), |
KEY `id` (`id`,`deleted`), |
KEY `deleted` (`deleted`), |
FULLTEXT KEY `user` (`user`,`name`,`surname`) |
) ENGINE=InnoDB DEFAULT CHARSET=utf8 TRANSACTIONAL=0 |
|
|
UPDATE user SET id = 275, revision_date = 1517476994, revision_author = 1, creation_date = 1475149574, creation_author = 1, user = "8502", name = "SOFIA", surname = "ORTONA - TEDESCO", email = "" WHERE id = 275 |
|
|
Can't write; duplicate key in table 'user' |
I have an issue on InnoDB with both MariaDB versions 10.3.4 and 10.2.12
This problem is very difficult for me to reproduce since it doesn't always happen. As you can see, that error can't be true because the ID 275 is already set for that row, so I don't know why it is failing. Also, this is a pretty busy server, and this error pops up randomly on INSERTs and UPDATEs of various tables, but only 2-3 times a day (there are about 10.000 writes every day)
I don't even know how to debug it properly since that particular error message is associated with the creation of foreign keys. The table is referenced on other tables, but the error should occur on creation of them, not by writing rows.
The query is run inside a transaction. Please let me know if you need anything else to help diagnose the issue.
Attachments
Issue Links
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Open
-
-
-
- Closed
-
-
-
- Closed
-
(3 relates to)
Activity
| Field | Original Value | New Value |
|---|---|---|
| Priority | Minor [ 4 ] | Major [ 3 ] |
| Link |
This issue relates to |
| Link |
This issue relates to |
| Link |
This issue relates to |
| Affects Version/s | 10.3.6 [ 23003 ] |
| Fix Version/s | 10.4 [ 22408 ] |
| Fix Version/s | 10.4 [ 22408 ] |
johnkiller, I wonder if the duplicate could be reported for the hidden FTS_DOC_ID column? If you rebuild the table without any FULLTEXT INDEX, will you still get the errors? There was a related bug fix in MDEV-12676, but that fix is present in 10.3.6.
Note that the hidden FTS_DOC_ID nor the hidden unique FTS_DOC_ID_INDEX(FTS_DOC_ID) will not be dropped when you drop the fulltext indexes. You must rebuild the table, for example by specifying the FORCE keyword in the ALTER TABLE statement.
I'll try to disable fulltext and rebuild the tables, then report back if it happens again.
As I said, this is not always reproducible, so it may take a couple of days before it happens.
Also, I have set "ft_min_word_len = 3" in my.cnf, if that could help.
Thanks
Hi, after 4 days it seems that the error disappeared. What can I do now? Thanks
johnkiller, do you mean that the bug stopped repeating even before you dropped the fulltext index?
I do not think that duplicate key errors should be related to any FOREIGN KEY constraints, with the exception of ON UPDATE CASCADE that causes an update of a unique index or the primary key in a child table.
My best guess is that the error is somehow related to fulltext index, but because it is only a guess, I would want to verify it. InnoDB fulltext indexes are internally implemented in hidden tables. In most of these tables, the unique index (primary key) is on the FTS_DOC_ID column. The main table is indexed by (word,first_doc_id) where first_doc_id is a FTS_DOC_ID. The only exception are the CONFIG tables, where I believe the key to be one of the few hard-coded strings defined in include/fts0priv.h. So, if the problem is in the fulltext index, it should likely be either due to the FTS_DOC_ID or due to a bug in the management of the inverted index.
I mean that after doing what you requested (disabling fulltext & rebuild) has stopped producing the error. I'm not 100% sure because the error is random. Thanks
| Component/s | Full-text Search [ 10104 ] |
johnkiller, thank you for clarifying. I believe that the InnoDB fulltext index code is the most likely culprit. Now the only remaining problem is that we need to reproduce the issue.
| Assignee | Matthias Leich [ mleich ] |
| Fix Version/s | 10.2 [ 14601 ] | |
| Fix Version/s | 10.3 [ 22126 ] |
Updated to 10.3.7 and the issue is still present. Issuing a SHOW WARNINGS produces this:
stdClass Object
(
[Level] => Error
[Code] => 1022
[Message] => Can't write; duplicate key in table 'subject'
)
Repeating the query then works as expected. Is there a way to enable more logging so I can help better? For example, is there a way to see the exact index that is failing, even if it's a system column?
I've tried to run a loop of inserts and updates but I can't reliably reproduce this issue
| Affects Version/s | 10.3.7 [ 23005 ] |
I got this error once when running ./mtr --parallel=auto --force --big-test --max-test-fail=0:
CURRENT_TEST: innodb_fts.fulltext2
|
mysqltest: At line 225: query 'update t1 set a='ab c d'' failed: 1022: Can't write; duplicate key in table 't1'
|
| Affects Version/s | 10.1.34 [ 23100 ] |
| Fix Version/s | 10.0 [ 16000 ] | |
| Fix Version/s | 10.1 [ 16100 ] |
| Link |
This issue relates to |
I tried to reproduce the problem based on innodb_fts.fulltext2 (see Marko's comment) with some brute force test.
But none of the setup combinations
- 10.2 or 10.3 (both compiled with debug)
- overloaded CPU or overloaded CPU+HDD
replayed the problem.
| Attachment | custom.cnf [ 45713 ] |
custom.cnf
This is my configuration. Some settings (like ft_min_word_len) affects the fulltext search, maybe this helps.
I am now giving up with the brute force tests based on innodb_fts.fulltext2. Even using most of the settings in custom.cnf did not replay.
Is there a way for me to get more debug info? I continue to get this error at least twice a day on 2 different servers, both in production.
Hi Gianni Angelozzi,
I assume that there is some problem with FOREIGN KEYs.
The duplicate key error message thrown because of PRIMARY KEY or
UNIQUE INDEX look different. In such cases the corresponding key
would be mentioned in the error message.
I am just experimenting in order to see how the messages for
violations of FOREIGN KEY relationship look like.
Regards
Matthias
Some news:
- No replay with some RQG test working on a table with similar layout like mentioned on top, 100000 rows and 12 concurrent
sessions updating rows like mentioned on top in transactions. Some statements failed because of error 1213 (deadlock)
or 1205 (Lock wait timeout). All other passed. (Debug build and also ASAN build) - My tests with MTR, InnoDB table, sometimes forreign keys, unique indices, PRIMARY KEYs gave all time error messages
mentioning the constraint/foreign key/... violated. (10.2 used). There was never a ER_DUP_ENTRY error message. - Some search over our MTR tests showed a crowd of tests where statements are expected to harvest ER_DUP_ENTRY
or ER_DUP_KEY. The reason seems to be that older software versions gave often the less detailed ER_DUP_KEY message and now the better ER_DUP_ENTRY.
Aside of tests using partitioned tables/engines like federated, merge, blackhole which seem to be mostly irrelevant
suite/perfschema/t/dml_setup_objects.test looked quite interesting.
Some table is using the ENGINE=PERFORMANCE_SCHEMA which needs to invoke whatever (I assume its some builtin
storage engine extended by additional properties) storage engine. One attempt to insert some record leads to ER_DUP_KEY.
Also some other statements report violations of FOREIGN KEY. Both things happen even though the table definition does not
mention any unique constraints or foreign keys. So it looks as if we could have hidden structures (not presented in SHOW TABLE) acting as unique constraint. And in case that gets violated than ER_DUP_KEY and not the better ER_DUP_ENTRY gets reported. - One thing which springs into the eye when looking on the table definition is
CREATE TABLE `user` (
`id` int(11) unsigned NOT NULL,
...
`user` varchar(250) NOT NULL,
...
PRIMARY KEY (`id`),
KEY `id` (`id`,`deleted`),
FULLTEXT KEY `user`
...
the heavy reuse of the same name for different objects like table, full text index, index etc.
And I found in the Web several reports about hitting ER_DUP_KEY mostly when trying to alter the table definition.
The workaround which usually finally helped was to make names unique per database.
It would be interesting to know if making the name of fulltext and normal indexes unique could somehow improve the situation.
Hi Gianni Angelozzi,
you mention 'The table is referenced on other tables, but the error should occur on creation of them,
not by writing rows.'. You are of course right with this statement and in addition the error message should
tell in which object (foreign key/unique index/primary key) the duplicate happened.
Would you please upload the definition of these tables?
In case there are triggers involved than some information about them would be of interest too.
There are some other ways to get more debug info but they have usually very unfortunate properties
(extreme slow throughput and similar) at runtime.
Many thanks in advance
Matthias
CREATE TABLE `user` ( |
`id` int(11) UNSIGNED NOT NULL, |
`revision_date` int(14) NOT NULL, |
`revision_author` int(11) UNSIGNED NOT NULL, |
`creation_date` int(14) NOT NULL, |
`creation_author` int(11) UNSIGNED NOT NULL, |
`deleted` tinyint(1) NOT NULL, |
`user` varchar(250) NOT NULL, |
`password` varchar(255) NOT NULL, |
`name` varchar(250) NOT NULL, |
`surname` varchar(250) NOT NULL, |
`lastlogin` int(14) NOT NULL, |
`lastip` varchar(32) NOT NULL, |
`lastpsw` int(14) NOT NULL, |
`email` varchar(60) NOT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8; |
|
|
CREATE TABLE `user_by_b2bmaster_to_b2b_master` ( |
`user_id` int(11) UNSIGNED NOT NULL, |
`b2b_master` int(11) UNSIGNED NOT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8; |
|
|
CREATE TABLE `user_by_b2bstore_to_b2b_store` ( |
`user_id` int(11) UNSIGNED NOT NULL, |
`b2b_store` int(11) UNSIGNED NOT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8; |
|
|
CREATE TABLE `user_by_group_to_user_group` ( |
`user_id` int(11) UNSIGNED NOT NULL, |
`user_group` int(11) UNSIGNED NOT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8; |
|
|
CREATE TABLE `user_group` ( |
`id` int(11) UNSIGNED NOT NULL, |
`revision_date` int(14) NOT NULL, |
`revision_author` int(11) UNSIGNED NOT NULL, |
`creation_date` int(14) NOT NULL, |
`creation_author` int(11) UNSIGNED NOT NULL, |
`deleted` tinyint(1) NOT NULL, |
`name` varchar(250) NOT NULL, |
`b2bmaster` tinyint(1) NOT NULL, |
`b2bstore` tinyint(1) NOT NULL, |
`special` tinyint(1) NOT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8; |
|
|
CREATE TABLE `user_group_by_permission_to_user_group_permission` ( |
`user_group_id` int(11) UNSIGNED NOT NULL, |
`user_group_permission` int(11) UNSIGNED NOT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8; |
|
|
CREATE TABLE `user_group_permission` ( |
`id` int(11) UNSIGNED NOT NULL, |
`revision_date` int(14) NOT NULL, |
`revision_author` int(11) UNSIGNED NOT NULL, |
`creation_date` int(14) NOT NULL, |
`creation_author` int(11) UNSIGNED NOT NULL, |
`name` varchar(250) NOT NULL, |
`description` varchar(250) NOT NULL, |
`group` varchar(250) NOT NULL, |
`groupname` varchar(250) NOT NULL, |
`folder` varchar(250) NOT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8; |
|
|
ALTER TABLE `user` |
ADD PRIMARY KEY (`id`), |
ADD KEY `id` (`id`,`deleted`), |
ADD KEY `deleted` (`deleted`); |
ALTER TABLE `user` ADD FULLTEXT KEY `ft_user` (`user`,`name`,`surname`); |
|
|
ALTER TABLE `user_by_b2bmaster_to_b2b_master` |
ADD PRIMARY KEY (`user_id`,`b2b_master`), |
ADD KEY `user_id` (`user_id`), |
ADD KEY `b2b_master` (`b2b_master`); |
|
|
ALTER TABLE `user_by_b2bstore_to_b2b_store` |
ADD PRIMARY KEY (`user_id`,`b2b_store`), |
ADD KEY `user_id` (`user_id`), |
ADD KEY `b2b_store` (`b2b_store`); |
|
|
ALTER TABLE `user_by_group_to_user_group` |
ADD PRIMARY KEY (`user_id`,`user_group`), |
ADD KEY `user_id` (`user_id`), |
ADD KEY `user_group` (`user_group`); |
|
|
ALTER TABLE `user_group` |
ADD PRIMARY KEY (`id`), |
ADD KEY `id` (`id`,`deleted`), |
ADD KEY `deleted` (`deleted`); |
ALTER TABLE `user_group` ADD FULLTEXT KEY `ft_user_group` (`name`); |
|
|
ALTER TABLE `user_group_by_permission_to_user_group_permission` |
ADD PRIMARY KEY (`user_group_id`,`user_group_permission`), |
ADD KEY `user_group_id` (`user_group_id`), |
ADD KEY `user_group_permission` (`user_group_permission`); |
|
|
ALTER TABLE `user_group_permission` |
ADD PRIMARY KEY (`id`); |
ALTER TABLE `user_group_permission` ADD FULLTEXT KEY `ft_user_group_permission` (`name`,`description`); |
|
|
ALTER TABLE `user_by_b2bmaster_to_b2b_master` |
ADD CONSTRAINT `f1_user_by_b2bmaster_to_b2b_master` FOREIGN KEY (`user_id`) REFERENCES `user` (`id`) ON DELETE CASCADE ON UPDATE CASCADE, |
ADD CONSTRAINT `f2_user_by_b2bmaster_to_b2b_master` FOREIGN KEY (`b2b_master`) REFERENCES `b2b_master` (`id`) ON DELETE CASCADE ON UPDATE CASCADE; |
|
|
ALTER TABLE `user_by_b2bstore_to_b2b_store` |
ADD CONSTRAINT `f1_user_by_b2bstore_to_b2b_store` FOREIGN KEY (`user_id`) REFERENCES `user` (`id`) ON DELETE CASCADE ON UPDATE CASCADE, |
ADD CONSTRAINT `f2_user_by_b2bstore_to_b2b_store` FOREIGN KEY (`b2b_store`) REFERENCES `b2b_store` (`id`) ON DELETE CASCADE ON UPDATE CASCADE; |
|
|
ALTER TABLE `user_by_group_to_user_group` |
ADD CONSTRAINT `f1_user_by_group_to_user_group` FOREIGN KEY (`user_id`) REFERENCES `user` (`id`) ON DELETE CASCADE ON UPDATE CASCADE, |
ADD CONSTRAINT `f2_user_by_group_to_user_group` FOREIGN KEY (`user_group`) REFERENCES `user_group` (`id`) ON DELETE CASCADE ON UPDATE CASCADE; |
|
|
ALTER TABLE `user_group_by_permission_to_user_group_permission` |
ADD CONSTRAINT `f1_user_group_by_permission_to_user_group_permission` FOREIGN KEY (`user_group_id`) REFERENCES `user_group` (`id`) ON DELETE CASCADE ON UPDATE CASCADE, |
ADD CONSTRAINT `f2_user_group_by_permission_to_user_group_permission` FOREIGN KEY (`user_group_permission`) REFERENCES `user_group_permission` (`id`) ON DELETE CASCADE ON UPDATE CASCADE; |
I have many tables but they are very similar. There are no triggers, no views, nothing fancy. However almost all of them have a FULLTEXT index, possibily with multiple columns.
About the performance issue, I have a server that I don't care if it's slow, so if you can tell me how to enable some more debugging I can try it there.
Thanks
Many thanks for the table definitions sent.
I am discussing with Marko if we could generate some server binary giving more debugging
information on which object the duplicate was hit.
| Attachment | MDEV-15237.patch [ 45788 ] |
Hi Gianni Angelozzi,
would you please
1. Apply the uploaded patch to some fresh cloned 10.2 source and compile a binary with debug.
2. Add --plugin-load=sql_errlog.so to the [mysqld] section in your my.cnf file
or just start the server with "--plugin-load=sql_errlog.so"
(https://mariadb.com/kb/en/library/sql-error-log-plugin/)
This will collect errors sent to clients in a log file 'sql_errors.log' located within the server data directory.
The entries there in combination with the additional entries (caused by the patch) in the server error log
might help to identify in which operation of the workflow of executing a
INSERT or UPDATE in your tables 'users' or 'subject' ....
the trouble occurs.
3. Run your application on a testing box till the problem showed a few times up.
My hope is that we either get some
- more or less cryptic entry written by InnoDB which could be used for searching within the InnoDB internal data dictionary
or - [ERROR] get_dup_key: nnn which maybe than points to some temporary shortage of free resources.
What the patch does:
- The error messages sent by the server to the client will be not changed.
- In case the InnoDB storage engine hits a duplicate key on whatever object than it will most probably write a message based on its internal 'knowledge'.
Examples: - [ERROR] err_index (0) for uidx:test/city
Client gets ERROR 23000: Duplicate entry 'Castelo de Vide' for key 'uidx' ... - [ERROR] err_index (0) for PRIMARY:mysqld.1/#sql2f87_15_2
Client gets ERROR 23000: Duplicate entry '20' for key 'PRIMARY'
The table was defined CREATE TEMPORARY TABLE t1 (..., PRIMARY KEY ...)
which explains the strange schema and table name reported by InnoDB. - [ERROR] err_index (0) for PRIMARY:test/t1#P#pNeg#SP#subp1
The table test . t1 is partitioned ...
into the server error log. - In case the duplicate key does not happen within InnoDB than some routine in the upper layer will often
but not all time write messages like
[ERROR] get_dup_key: nnn.
into the server error log.
Example:
[ERROR] get_dup_key: 135
Client gets ERROR HY000: The table '... var/tmp/mysqld.1/#sql_1568_0' is full
This means some internal temporary table (usually MyISAM/Aria storage engine)
with limited size (server system variables tmp_disk_table_size,
tmp_memory_table_size) and used internally for complex queries was full. - The server error log might grow fast.
- In case you let our regression tests run then MTR will report a batch of fails like
Found warnings/errors in server log file!
Test ended at 2018-06-21 13:48:30
line
2018-06-21 13:48:29 140547810891520 [ERROR] err_index (0) for a:test/t1
^ Found warnings in .../var/1/log/mysqld.1.err
ok
but that is to be expected with the patch and harmless.
Many thanks in advance.
Hi,
I've successfully compiled the binary with your patch and I'm now waiting for the error to appear. Let's hope it's not an Heisenbug 
Hi,
After some time running in debug mode, the error didn't come up, so I switched to a normal build with your patch applied.
This popped up in /var/log/syslog:
Jul 10 15:04:46 logico_ac mysqld[28840]: 2018-07-10 15:04:46 140332408940288 [ERROR] InnoDB: Duplicate FTS_DOC_ID value on table `logico_ac`.`anl_method`
|
Jul 10 15:04:46 logico_ac mysqld[28840]: 2018-07-10 15:04:46 140332408940288 [ERROR] Cannot find index FTS_DOC_ID_INDEX in InnoDB index translation table.
|
Jul 10 15:04:46 logico_ac mysqld[28840]: 2018-07-10 15:04:46 140332408940288 [Warning] Found index FTS_DOC_ID_INDEX in InnoDB index list but not its MariaDB index number. It could be an InnoDB internal index.
|
Jul 10 15:04:46 logico_ac mysqld[28840]: 2018-07-10 15:04:46 140332408940288 [ERROR] err_index (-1) for FTS_DOC_ID_INDEX:logico_ac/anl_method
|
This was in /var/lib/mysql/sql_errors.log:
2018-07-10 15:04:46 root[root] @ localhost [] ERROR 1022: Can't write; duplicate key in table 'anl_method' : INSERT INTO `anl_method` SET `id` = 1055, `revision_id` = 1, `revision_date` = 1531235086, `revision_author` = 7, `creation_date` = 1531235086, `creation_author` = 7, `tmp` = "", `code` = "EXT", `name` = "Metodi di Analisi per i Fertilizzanti - met. X.2", `official` = "", `date_start` = "1530403200", `date_end` = "0", `notes` = "" |
Do you need anything else?
Hi,
many thanks for your input. Would you please keep the files with the snippets above
and if possible a raw backup (the files when the server is not running) of the database
at some safe place.
So it seems now more clear that the sporadic trouble comes from the fulltext indexes.
Now the InnoDB developers need to discuss these results and how to proceed.
Based on your experiences (... a retry of the same insert or update usually passes) and
my latest experiences with RQG based tests (certain bad effects do not show up except the
testing box is under under excessive load) I fear we are in the region of a Heisenbug.
Hi,
I'm keeping an eye on syslog, and I've noticed that it's now cluttered with
Jul 26 14:09:51 logico_ac mysqld[1137]: 2018-07-26 14:09:51 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:12:35 logico_ac mysqld[1137]: 2018-07-26 14:12:35 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:13:28 logico_ac mysqld[1137]: 2018-07-26 14:13:28 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:17:02 logico_ac mysqld[1137]: 2018-07-26 14:17:02 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:17:20 logico_ac mysqld[1137]: 2018-07-26 14:17:20 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:22:16 logico_ac mysqld[1137]: 2018-07-26 14:22:16 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:22:30 logico_ac mysqld[1137]: 2018-07-26 14:22:30 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:22:30 logico_ac mysqld[1137]: 2018-07-26 14:22:30 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:23:11 logico_ac mysqld[1137]: 2018-07-26 14:23:11 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:24:28 logico_ac mysqld[1137]: 2018-07-26 14:24:28 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:24:33 logico_ac mysqld[1137]: 2018-07-26 14:24:33 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:25:50 logico_ac mysqld[1137]: 2018-07-26 14:25:50 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:27:48 logico_ac mysqld[1137]: 2018-07-26 14:27:48 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:28:05 logico_ac mysqld[1137]: 2018-07-26 14:28:05 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:28:10 logico_ac mysqld[1137]: 2018-07-26 14:28:10 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:28:23 logico_ac mysqld[1137]: 2018-07-26 14:28:23 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:28:30 logico_ac mysqld[1137]: 2018-07-26 14:28:30 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:28:42 logico_ac mysqld[1137]: 2018-07-26 14:28:42 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:28:48 logico_ac mysqld[1137]: 2018-07-26 14:28:48 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:29:57 logico_ac mysqld[1137]: 2018-07-26 14:29:57 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:30:05 logico_ac mysqld[1137]: 2018-07-26 14:30:05 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:30:46 logico_ac mysqld[1137]: 2018-07-26 14:30:46 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:30:50 logico_ac mysqld[1137]: 2018-07-26 14:30:50 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:31:34 logico_ac mysqld[1137]: 2018-07-26 14:31:34 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:32:16 logico_ac mysqld[1137]: 2018-07-26 14:32:16 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:32:31 logico_ac mysqld[1137]: 2018-07-26 14:32:31 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:33:33 logico_ac mysqld[1137]: 2018-07-26 14:33:33 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:34:01 logico_ac mysqld[1137]: 2018-07-26 14:34:01 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:34:16 logico_ac mysqld[1137]: 2018-07-26 14:34:16 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
Jul 26 14:34:26 logico_ac mysqld[1137]: 2018-07-26 14:34:26 139747516819200 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table.
|
If I issue
ALTER TABLE `user` ENGINE=InnoDB; |
should the error go away?
Yes, because ALTER TABLE `user` ENGINE=InnoDB will rebuild all storage structures belonging to that table.
I came from ticket MDEV-12676
I have this line in /var/log/mariadb.log few hundred times. (MariaDB-server-10.1.37-1.el7.centos.x86_64)
2018-12-04 13:28:27 7f8413ffb700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
Since there is no name of the table which is responsible for this error, I'm a bit baffled. There are many databases and tables. How I can find the right one?
Hi Karl, if you have a FULLTEXT search index on a INNODB table, I'm afraid that this is the same bug I've encountered here.
I've since stopped using FULLTEXT search since the erros breaks Galera replication, so I don't know if in recent versions of MariaDB this error is still present or not.
The table that has the error is an internal index of InnoDB, it's not your fault or something that you can fix by yourself. Thanks.
| Link |
This issue relates to |
| Fix Version/s | 10.4 [ 22408 ] |
| Affects Version/s | 10.2.14 [ 22911 ] |
| Support case ID | 28999 | not-28999 |
Just a quick update.
I've tested 10.4.11 and the bug is still present.
Also since my production database has grown in size and traffic (about 20gb of data, 3 galera cluster nodes) the error appears more frequently (and breaks replication)
Folks, it's happening for Ubuntu Trusty (a little old, yeah) when running the MariaDB Server 10.2.18-MariaDB-10.2.18+maria~trusty-log.
2020-04-12 11:16:37 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-12 17:11:58 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-12 17:15:08 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-12 17:15:36 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-12 17:15:57 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-12 22:57:08 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-12 22:57:27 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-12 22:57:39 140382549571328 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
Bianchi
| Affects Version/s | 10.1.42 [ 23407 ] |
Folks, it's happening also on CentOS Linux release 7.7.1908 (Core) running the 10.1.42-MariaDB for Linux on x86_64.
2020-04-16 13:20:11 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:12 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:13 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:13 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
2020-04-16 13:20:13 7ee682bfa700 InnoDB: Error (Duplicate key) writing word node to FTS auxiliary index table. |
| Fix Version/s | 10.0 [ 16000 ] |
| Fix Version/s | 10.1 [ 16100 ] |
CentOS Linux 8.2.2004 / Server-Version: 10.3.17-MariaDB-log
Afer two years, every few minutes I have still this errors in my logfile /var/log/mariadb.log
2020-11-06 12:40:56 0 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-11-06 12:43:27 0 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-11-06 12:45:43 0 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
2020-11-06 12:47:15 0 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table. |
Hi,
sorry for the long time without response.
Would it be possible to send me a complete logical dump of your database and some sample SQL's?
Please feel free to scramble sensitive data in strings as needed
Without some sample data and sample SQL's the chances to replay these problems are extreme low.
Many thanks in advance
Regards
Matthias
We are seeing this issue on Ubuntu 18.04.5 LTS LXC container with latest MariaDB 10.3.28 version. I'll check to see if we can share the information required for the investigation.
jrioux if there data and configuration is shareable and not exceptionally large - an upload would be appreciated https://mariadb.com/kb/en/meta/mariadb-ftp-server/
Otherwise the same information mleich has requested from other users.
| Workflow | MariaDB v3 [ 85477 ] | MariaDB v4 [ 140633 ] |
This might share a root cause with MDEV-24608.
The fts_commit() call at transaction commit time is modifying persistent data related to fulltext indexes. If XA PREPARE is being used, either explicitly by the application, or implicitly by the use of the binlog (which internally generates distributed transactions of the form MySQLXid), problems could arise.
| Link | This issue relates to MDEV-24608 [ MDEV-24608 ] |
| Assignee | Matthias Leich [ mleich ] | Thirunarayanan Balathandayuthapani [ thiru ] |
| Fix Version/s | 10.2 [ 14601 ] |
It seems that MDEV-25581 would convert the error message to a server crash, as reported in MDEV-29335.
johnkiller or jrioux or anyone who can reproduce this error, we would greatly appreciate something that would allow us to reproduce and fix this bug.
| Link |
This issue relates to |
| Link |
This issue relates to |
| Fix Version/s | 10.5 [ 23123 ] | |
| Fix Version/s | 10.6 [ 24028 ] | |
| Fix Version/s | 10.7 [ 24805 ] | |
| Fix Version/s | 10.8 [ 26121 ] | |
| Fix Version/s | 10.9 [ 26905 ] | |
| Fix Version/s | 10.10 [ 27530 ] | |
| Priority | Major [ 3 ] | Critical [ 2 ] |
We unfortunately had to move to another engine because of this issue. I cannot reproduce it anymore.
It is possible that this bug was fixed in MDEV-29342. Given that this bug has been open so long, with relatively few votes and watchers, I think that we must wait several months for any feedback.
An unscheduled release of MariaDB Server 10.6.10, 10.7.6, 10.8.5, 10.9.3 is expected to be available soon. For older major versions, releases including the fix of MDEV-29342 should become available in the next scheduled quarterly release (October or November 2022).
| Status | Open [ 1 ] | Needs Feedback [ 10501 ] |
| Status | Needs Feedback [ 10501 ] | Open [ 1 ] |
| Fix Version/s | N/A [ 14700 ] | |
| Fix Version/s | 10.3 [ 22126 ] | |
| Fix Version/s | 10.4 [ 22408 ] | |
| Fix Version/s | 10.5 [ 23123 ] | |
| Fix Version/s | 10.6 [ 24028 ] | |
| Fix Version/s | 10.7 [ 24805 ] | |
| Fix Version/s | 10.8 [ 26121 ] | |
| Fix Version/s | 10.9 [ 26905 ] | |
| Fix Version/s | 10.10 [ 27530 ] | |
| Resolution | Cannot Reproduce [ 5 ] | |
| Status | Open [ 1 ] | Closed [ 6 ] |
| Zendesk Related Tickets | 151586 |
i am still seeing this error in 10.6.12 in a 3 node galera cluster. When duplicate key happens, the galera cluster will slow down and eventually unable to serve.
240716 14:05:11 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended |
240716 14:05:37 mysqld_safe Starting mariadbd daemon with databases from /var/lib/mysql |
240716 14:05:37 mysqld_safe WSREP: Running position recovery with --disable-log-error --pid-file='/var/lib/mysql/server-h3-recover.pid' |
240716 14:05:39 mysqld_safe WSREP: Recovered position 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:39 0 [Note] Starting MariaDB 10.6.12-MariaDB source revision 4c79e15cc3716f69c044d4287ad2160da8101cdc as process 28412 |
2024-07-16 14:05:39 0 [Note] WSREP: Loading provider /usr/lib64/galera/libgalera_smm.so initial position: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:39 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so' |
2024-07-16 14:05:39 0 [Note] WSREP: wsrep_load(): Galera 26.4.14(rf27da2a) by Codership Oy <info@codership.com> loaded successfully. |
2024-07-16 14:05:39 0 [Note] WSREP: CRC-32C: using 64-bit x86 acceleration. |
2024-07-16 14:05:39 0 [Warning] WSREP: SSL compression is not effective. The option socket.ssl_compression is deprecated and will be removed in future releases. |
2024-07-16 14:05:39 0 [Note] WSREP: Found saved state: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849, safe_to_bootstrap: 0 |
2024-07-16 14:05:39 0 [Note] WSREP: GCache DEBUG: opened preamble: |
Version: 2 |
UUID: 67210f6b-52bc-11ed-8997-d697d3148f87 |
Seqno: 87943436 - 88711849 |
Offset: 1749575000 |
Synced: 1 |
2024-07-16 14:05:39 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: 67210f6b-52bc-11ed-8997-d697d3148f87, offset: 1749575000 |
2024-07-16 14:05:39 0 [Note] WSREP: GCache::RingBuffer initial scan... 0.0% ( 0/2147483672 bytes) complete. |
2024-07-16 14:05:42 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (2147483672/2147483672 bytes) complete. |
2024-07-16 14:05:42 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 87943436-88711849 |
2024-07-16 14:05:42 0 [Note] WSREP: GCache::RingBuffer unused buffers scan... 0.0% ( 0/2147055560 bytes) complete. |
2024-07-16 14:05:42 0 [Note] WSREP: Recovering GCache ring buffer: found 1/768415 locked buffers |
2024-07-16 14:05:42 0 [Note] WSREP: Recovering GCache ring buffer: free space: 428280/2147483648 |
2024-07-16 14:05:42 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...100.0% (2147055560/2147055560 bytes) complete. |
2024-07-16 14:05:42 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = tdmint-h3; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT10S; evs.inactive_timeout = PT60S; evs.install_timeout = PT60S; evs.join_retrans_period = PT1S; evs.keepalive_period = PT3S; evs.max_install_timeouts = 3; evs.send_window = 512; evs.stats_report_period = PT1M; evs.suspect_timeout = PT30S; evs.user_send_window = 512; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.keep_plaintext_size = 1G; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 1G; gcache.recover = yes; gcache.size = 2G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.fc_single_primary = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_l |
2024-07-16 14:05:42 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:42 0 [Note] WSREP: ####### Assign initial position for certification: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849, protocol version: -1 |
2024-07-16 14:05:42 0 [Note] WSREP: Start replication |
2024-07-16 14:05:42 0 [Note] WSREP: Connecting with bootstrap option: 0 |
2024-07-16 14:05:42 0 [Note] WSREP: Setting GCS initial position to 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:42 0 [Note] WSREP: Using CRC-32 (backward-compatible) for message checksums. |
2024-07-16 14:05:42 0 [Note] WSREP: backend: asio |
2024-07-16 14:05:42 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 |
2024-07-16 14:05:42 0 [Note] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory) |
2024-07-16 14:05:42 0 [Note] WSREP: restore pc from disk failed |
2024-07-16 14:05:42 0 [Note] WSREP: GMCast version 0 |
2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') listening at ssl://0.0.0.0:4567 |
2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') multicast: , ttl: 1 |
2024-07-16 14:05:42 0 [Note] WSREP: EVS version 1 |
2024-07-16 14:05:42 0 [Note] WSREP: gcomm: connecting to group 'accdbcluster', peer '57.3.12.100:,57.3.12.101:,57.3.12.107:' |
2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') Found matching local endpoint for a connection, blacklisting address ssl://57.3.12.107:4567 |
2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') connection established to 29aeda1c-8bc1 ssl://57.3.12.101:4567 |
2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') turning message relay requesting on, nonlive peers: |
2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') connection established to 49695eda-b162 ssl://57.3.12.100:4567 |
2024-07-16 14:05:43 0 [Note] WSREP: EVS version upgrade 0 -> 1 |
2024-07-16 14:05:43 0 [Note] WSREP: declaring 29aeda1c-8bc1 at ssl://57.3.12.101:4567 stable |
2024-07-16 14:05:43 0 [Note] WSREP: declaring 49695eda-b162 at ssl://57.3.12.100:4567 stable |
2024-07-16 14:05:43 0 [Note] WSREP: PC protocol upgrade 0 -> 1 |
2024-07-16 14:05:43 0 [Note] WSREP: Node 29aeda1c-8bc1 state prim |
2024-07-16 14:05:43 0 [Note] WSREP: view(view_id(PRIM,29aeda1c-8bc1,14) memb { |
29aeda1c-8bc1,4 |
49695eda-b162,3 |
7d3f1c69-bd93,7 |
} joined {
|
} left {
|
} partitioned {
|
})
|
2024-07-16 14:05:43 0 [Note] WSREP: save pc into disk |
2024-07-16 14:05:43 0 [Note] WSREP: gcomm: connected |
2024-07-16 14:05:43 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636 |
2024-07-16 14:05:43 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0) |
2024-07-16 14:05:43 0 [Note] WSREP: Opened channel 'accdbcluster' |
2024-07-16 14:05:43 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3 |
2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. |
2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 |
2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 0 (tdmint-h2) |
2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 1 (tdmint-h1) |
2024-07-16 14:05:43 1 [Note] WSREP: Starting rollbacker thread 1 |
2024-07-16 14:05:43 2 [Note] WSREP: Starting applier thread 2 |
2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 2 (tdmint-h3) |
2024-07-16 14:05:43 0 [Note] WSREP: Quorum results: |
version = 6, |
component = PRIMARY,
|
conf_id = 11, |
members = 2/3 (joined/total), |
act_id = 88711850, |
last_appl. = 88711807, |
protocols = 2/10/4 (gcs/repl/appl), |
vote policy= 0, |
group UUID = 67210f6b-52bc-11ed-8997-d697d3148f87 |
2024-07-16 14:05:43 0 [Note] WSREP: Flow-control interval: [28, 28] |
2024-07-16 14:05:43 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 88711851) |
2024-07-16 14:05:43 2 [Note] WSREP: ####### processing CC 88711851, local, ordered |
2024-07-16 14:05:43 2 [Note] WSREP: Process first view: 67210f6b-52bc-11ed-8997-d697d3148f87 my uuid: 7d3f1c69-437c-11ef-bd93-1be78d6491dc |
2024-07-16 14:05:43 2 [Note] WSREP: Server tdmint-h3 connected to cluster at position 67210f6b-52bc-11ed-8997-d697d3148f87:88711851 with ID 7d3f1c69-437c-11ef-bd93-1be78d6491dc |
2024-07-16 14:05:43 2 [Note] WSREP: Server status change disconnected -> connected |
2024-07-16 14:05:43 2 [Note] WSREP: ####### My UUID: 7d3f1c69-437c-11ef-bd93-1be78d6491dc |
2024-07-16 14:05:43 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes |
2024-07-16 14:05:43 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:43 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1 |
2024-07-16 14:05:43 2 [Note] WSREP: State transfer required: |
Group state: 67210f6b-52bc-11ed-8997-d697d3148f87:88711851 |
Local state: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:43 2 [Note] WSREP: Server status change connected -> joiner |
2024-07-16 14:05:43 0 [Note] WSREP: Joiner monitor thread started to monitor |
2024-07-16 14:05:43 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address 'tdmint-h3' --datadir '/var/lib/mysql/' --parent 28412 --progress 0 --mysqld-args --basedir=/opt --datadir=/var/lib/mysql --plugin-dir=/opt/lib64/mysql/plugin --user=mysql --wsrep_provider=/usr/lib64/galera/libgalera_smm.so --wsrep_on=ON --log-error=/var/lib/mysql/mysql.err --pid-file=/var/lib/mysql/mysql.pid --wsrep_start_position=67210f6b-52bc-11ed-8997-d697d3148f87:88711849' |
WSREP_SST: [INFO] mariabackup SST started on joiner (20240716 14:05:44.005) |
WSREP_SST: [INFO] SSL configuration: CA='', CAPATH='', CERT='/var/lib/mysql/galera_cert.pem', KEY='/var/lib/mysql/galera_key.pem', MODE='DISABLED', encrypt='3' (20240716 14:05:44.127) |
WSREP_SST: [INFO] Streaming with mbstream (20240716 14:05:44.278) |
WSREP_SST: [INFO] Using socat as streamer (20240716 14:05:44.280) |
WSREP_SST: [INFO] Using openssl based encryption with socat: with key and crt (20240716 14:05:44.294) |
WSREP_SST: [INFO] Decrypting with cert='/var/lib/mysql/galera_cert.pem', key='/var/lib/mysql/galera_key.pem', verify=0 (20240716 14:05:44.324) |
WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u openssl-listen:4444,reuseaddr,cert='/var/lib/mysql/galera_cert.pem',key='/var/lib/mysql/galera_key.pem',verify=0 stdio | '/opt//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20240716 14:05:44.366) |
2024-07-16 14:05:44 2 [Note] WSREP: ####### IST uuid:67210f6b-52bc-11ed-8997-d697d3148f87 f: 88711850, l: 88711851, STRv: 3 |
2024-07-16 14:05:44 2 [Note] WSREP: IST receiver addr using ssl://h3-tdmint:4568 |
2024-07-16 14:05:44 2 [Note] WSREP: IST receiver using ssl |
2024-07-16 14:05:44 2 [Note] WSREP: Prepared IST receiver for 88711850-88711851, listening at: ssl://57.3.12.107:4568 |
2024-07-16 14:05:44 0 [Note] WSREP: Member 2.7 (tdmint-h3) requested state transfer from '*any*'. Selected 1.3 (tdmint-h1)(SYNCED) as donor. |
2024-07-16 14:05:44 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 88711851) |
2024-07-16 14:05:44 2 [Note] WSREP: Requesting state transfer: success, donor: 1 |
WSREP_SST: [INFO] 'xtrabackup_ist' received from donor: Running IST (20240716 14:05:45.351) |
WSREP_SST: [INFO] Galera co-ords from recovery: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 0 (20240716 14:05:45.356) |
WSREP_SST: [INFO] Total time on joiner: 0 seconds (20240716 14:05:45.358) |
WSREP_SST: [INFO] mariabackup IST completed on joiner (20240716 14:05:45.361) |
WSREP_SST: [INFO] Removing the sst_in_progress file (20240716 14:05:45.364) |
WSREP_SST: [INFO] Cleaning up temporary directories (20240716 14:05:45.368) |
2024-07-16 14:05:45 0 [Note] WSREP: 1.3 (tdmint-h1): State transfer to 2.7 (tdmint-h3) complete. |
2024-07-16 14:05:45 0 [Note] WSREP: Member 1.3 (tdmint-h1) synced with group. |
2024-07-16 14:05:45 3 [Note] WSREP: SST received |
2024-07-16 14:05:45 3 [Note] WSREP: Server status change joiner -> initializing |
2024-07-16 14:05:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.7 |
2024-07-16 14:05:45 0 [Note] InnoDB: Number of pools: 1 |
2024-07-16 14:05:45 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions |
2024-07-16 14:05:45 0 [Note] InnoDB: Using Linux native AIO |
2024-07-16 14:05:45 0 [Note] InnoDB: Initializing buffer pool, total size = 3221225472, chunk size = 134217728 |
2024-07-16 14:05:45 0 [Note] InnoDB: Completed initialization of buffer pool |
2024-07-16 14:05:45 0 [Note] InnoDB: 128 rollback segments are active. |
2024-07-16 14:05:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables |
2024-07-16 14:05:45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... |
2024-07-16 14:05:45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. |
2024-07-16 14:05:45 0 [Note] InnoDB: 10.6.12 started; log sequence number 201028063150; transaction id 210746763 |
2024-07-16 14:05:45 0 [Note] InnoDB: Loading buffer pool(s) from /db/mysql/ib_buffer_pool |
2024-07-16 14:05:45 0 [Note] Plugin 'FEEDBACK' is disabled. |
2024-07-16 14:05:45 0 [Note] Server socket created on IP: '0.0.0.0'. |
2024-07-16 14:05:45 0 [Note] Server socket created on IP: '::'. |
2024-07-16 14:05:45 0 [Note] WSREP: wsrep_init_schema_and_SR (nil) |
2024-07-16 14:05:46 0 [Note] WSREP: Server initialized |
2024-07-16 14:05:46 0 [Note] WSREP: Server status change initializing -> initialized |
2024-07-16 14:05:46 3 [Note] WSREP: Recovered position from storage: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:46 3 [Note] WSREP: Recovered view from SST: |
id: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
status: primary
|
protocol_version: 4 |
capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
|
final: no |
own_index: -1 |
members(3): |
0: 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2 |
1: 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1 |
2: 63a42fae-8953-11ee-adad-56d15056d25c, tdmint-h3 |
|
|
2024-07-16 14:05:46 0 [Note] /opt/sbin/mariadbd: ready for connections. |
Version: '10.6.12-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server |
2024-07-16 14:05:46 7 [Note] WSREP: Recovered cluster id 67210f6b-52bc-11ed-8997-d697d3148f87 |
2024-07-16 14:05:46 3 [Note] WSREP: SST received: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:46 3 [Note] WSREP: SST succeeded for position 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:46 0 [Note] WSREP: Joiner monitor thread ended with total time 3 sec |
2024-07-16 14:05:46 2 [Note] WSREP: Installed new state from SST: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 |
2024-07-16 14:05:46 2 [Note] WSREP: Receiving IST: 2 writesets, seqnos 88711850-88711851 |
2024-07-16 14:05:46 0 [Note] WSREP: ####### IST applying starts with 88711850 |
2024-07-16 14:05:46 0 [Note] WSREP: ####### IST current seqno initialized to 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Receiving IST... 0.0% ( 0/44 events) complete. |
2024-07-16 14:05:46 0 [Note] WSREP: IST preload starting at 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:46 0 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:88711807, protocol version: 5 |
2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5) |
2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711838 -> 88711839 |
2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 |
2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5) |
2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711839 -> 88711840 |
2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 |
2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5) |
2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711840 -> 88711841 |
2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 |
2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5) |
2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711848 -> 88711849 |
2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 |
2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5) |
2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711849 -> 88711850 |
2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from ist: 87943437 |
2024-07-16 14:05:46 2 [Note] WSREP: ================================================ |
View:
|
id: 67210f6b-52bc-11ed-8997-d697d3148f87:88711850 |
status: primary
|
protocol_version: 4 |
capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
|
final: no |
own_index: -1 |
members(2): |
0: 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2 |
1: 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1 |
=================================================
|
2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5) |
2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711850 -> 88711851 |
2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed. |
2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 88711808 |
2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from ist: 87943437 |
2024-07-16 14:05:46 2 [Note] WSREP: ================================================ |
View:
|
id: 67210f6b-52bc-11ed-8997-d697d3148f87:88711851 |
status: primary
|
protocol_version: 4 |
capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
|
final: no |
own_index: 2 |
members(3): |
0: 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2 |
1: 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1 |
2: 7d3f1c69-437c-11ef-bd93-1be78d6491dc, tdmint-h3 |
=================================================
|
2024-07-16 14:05:46 0 [Note] WSREP: Receiving IST...100.0% (44/44 events) complete. |
2024-07-16 14:05:46 2 [Note] WSREP: Server status change initialized -> joined |
2024-07-16 14:05:46 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') turning message relay requesting off |
2024-07-16 14:05:46 2 [Note] WSREP: Draining apply monitors after IST up to 88711851 |
2024-07-16 14:05:46 2 [Note] WSREP: IST received: 67210f6b-52bc-11ed-8997-d697d3148f87:88711851 |
2024-07-16 14:05:46 2 [Note] WSREP: Lowest cert index boundary for CC from sst: 88711808 |
2024-07-16 14:05:46 2 [Note] WSREP: Min available from gcache for CC from sst: 87943437 |
2024-07-16 14:05:46 0 [Note] WSREP: 2.7 (tdmint-h3): State transfer from 1.3 (tdmint-h1) complete. |
2024-07-16 14:05:46 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 88711851) |
2024-07-16 14:05:46 0 [Note] WSREP: Processing event queue:... -nan% (0/0 events) complete. |
2024-07-16 14:05:46 0 [Note] WSREP: Member 2.7 (tdmint-h3) synced with group. |
2024-07-16 14:05:46 0 [Note] WSREP: Processing event queue:...100.0% (1/1 events) complete. |
2024-07-16 14:05:46 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 88711851) |
2024-07-16 14:05:46 2 [Note] WSREP: Server tdmint-h3 synced with group |
2024-07-16 14:05:46 2 [Note] WSREP: Server status change joined -> synced |
2024-07-16 14:05:46 2 [Note] WSREP: Synchronized with group, ready for connections |
2024-07-16 14:05:48 0 [Note] InnoDB: Buffer pool(s) load completed at 240716 14:05:48 |
2024-07-16 14:07:09 105 [Warning] Access denied for user 'monitor'@'localhost' (using password: YES) |
2024-07-16 14:08:57 143 [Warning] Aborted connection 143 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:57 144 [Warning] Aborted connection 144 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 65 [Warning] Aborted connection 65 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 64 [Warning] Aborted connection 64 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 63 [Warning] Aborted connection 63 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 66 [Warning] Aborted connection 66 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 98 [Warning] Aborted connection 98 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 99 [Warning] Aborted connection 99 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 100 [Warning] Aborted connection 100 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 101 [Warning] Aborted connection 101 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 208 [Warning] Aborted connection 208 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:08:58 209 [Warning] Aborted connection 209 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) |
2024-07-16 14:17:01 400 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:04 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:04 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:10 390 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:10 392 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:10 392 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
2024-07-16 14:17:11 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ |
Also, if the problem was a duplicate key, shouldn't the error message also display the problematic ID ?