crash with HA_ERR_FOUND_DUPP_KEY when PRIMARY KEY contains UTF8

[Gea-Suan Lin]

OS: Debian 6.0
Software: Percona XtraDB Cluster 5.5.30-30.2
Cluster: Two mysqld (db-test-1 & db-test-2) & one garbd (db-test-3)
my.cnf in db-test-1: https://gist.github.com/gslin/5565994

Sometimes we've got HA_ERR_FOUND_DUPP_KEY error in our production server cluster regularly. And I've sucessfully reproduced in test cluster:

130513 11:15:25 [ERROR] Slave SQL: Could not execute Write_rows event on table t.tag_raw; Duplicate entry '0-61-53-中文測試' for key 'PRIMARY', Error_code: 1062; handler
 error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 114, Error_code: 1062
130513 11:15:25 [Warning] WSREP: RBR event 2 Write_rows apply warning: 121, 137399
130513 11:15:25 [ERROR] WSREP: Failed to apply trx: source: 6aaa649a-a85b-11e2-0800-08cc46d2f954 version: 2 local: 0 state: APPLYING flags: 1 conn_id: 29194 trx_id: 4182
09 seqnos (l: 80461, g: 137399, s: 137398, d: 137066, ts: 1368414925476586582)
130513 11:15:25 [ERROR] WSREP: Failed to apply app buffer: seqno: 137399, status: WSREP_FATAL
         at galera/src/replicator_smm.cpp:apply_wscoll():52
         at galera/src/replicator_smm.cpp:apply_trx_ws():118
130513 11:15:25 [ERROR] WSREP: Node consistency compromized, aborting...
130513 11:15:25 [Note] WSREP: Closing send monitor...
130513 11:15:25 [Note] WSREP: Closed send monitor.
130513 11:15:25 [Note] WSREP: gcomm: terminating thread
130513 11:15:25 [Note] WSREP: gcomm: joining thread
130513 11:15:25 [Note] WSREP: gcomm: closing backend
130513 11:15:25 [Note] WSREP: view(view_id(NON_PRIM,6aaa649a-a85b-11e2-0800-08cc46d2f954,9) memb {
        f8ad3fe6-bb7a-11e2-0800-f4b38a5a046c,
} joined {
} left {
} partitioned {
        6aaa649a-a85b-11e2-0800-08cc46d2f954,
        986d80ee-a85f-11e2-0800-fa13f167bc00,
})
130513 11:15:25 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
130513 11:15:25 [Note] WSREP: view((empty))
130513 11:15:25 [Note] WSREP: gcomm: closed
130513 11:15:25 [Note] WSREP: Flow-control interval: [16, 16]
130513 11:15:25 [Note] WSREP: Received NON-PRIMARY.
130513 11:15:25 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 137399)
130513 11:15:25 [Note] WSREP: Received self-leave message.
130513 11:15:25 [Note] WSREP: Flow-control interval: [0, 0]
130513 11:15:25 [Note] WSREP: Received SELF-LEAVE. Closing connection.
130513 11:15:25 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 137399)
130513 11:15:25 [Note] WSREP: RECV thread exiting 0: Success
130513 11:15:25 [Note] WSREP: recv_thread() joined.
130513 11:15:25 [Note] WSREP: Closing slave action queue.
130513 11:15:25 [Note] WSREP: /usr/sbin/mysqld: Terminated.
Aborted
130513 11:15:25 mysqld_safe Number of processes running now: 0
130513 11:15:25 mysqld_safe WSREP: not restarting wsrep node automatically
130513 11:15:25 mysqld_safe mysqld from pid file /var/lib/mysql/db-test-2.pid ended

Database schema & two scripts to reproduce (running these two scripts at the same time):

> SHOW CREATE TABLE tag_raw \G
*************************** 1. row ***************************
       Table: tag_raw
Create Table: CREATE TABLE `tag_raw` (
  `obj_type` varchar(16) NOT NULL DEFAULT '' COMMENT 'obj_type',
  `obj_id` varchar(20) NOT NULL COMMENT 'obj_type編號',
  `tag` varchar(255) NOT NULL,
  `msno` bigint(20) NOT NULL DEFAULT '0' COMMENT 'user id',
  `terr_id` int(11) NOT NULL COMMENT '地區編號',
  PRIMARY KEY (`obj_type`,`obj_id`,`msno`,`tag`),
  KEY `obj_id` (`obj_id`),
  KEY `tag` (`tag`),
  KEY `msno` (`msno`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=COMPRESSED
1 row in set (0.00 sec)

gslin@goingmarry [~/work/galera] [11:22] cat ti.php
<?php

$db = new PDO('mysql:host=db-test-1;dbname=t', 'test', 'test');

$pi = $db->prepare('INSERT INTO `tag_raw` (`obj_type`, `obj_id`, `tag`, `msno`, `terr_id`) VALUES (?, ?, ?, ?, ?);');

for ($i = 0;; $i++) {
    $obj_type = 0;
    $obj_id = rand(1, 100);
    $tag = '中文測試'; // UTF-8
    $msno = rand(1, 100);
    $terr_id = 0;

    $pi->execute(array($obj_type, $obj_id, $tag, $msno, $terr_id));

    if (0 == $i % 1000) {
        printf("%d\n", $i);
    }
}

gslin@goingmarry [~/work/galera] [11:22] cat td.php
<?php

$db = new PDO('mysql:host=db-test-1;dbname=t', 'test', 'test');

$ps = $db->prepare('SELECT COUNT(*) FROM `tag_raw`;');

for ($i = 0;; $i++) {
    $ps->execute();
    list($c) = $ps->fetch(PDO::FETCH_NUM);

    if ($c > 100) {
        $sql = sprintf('DELETE FROM `tag_raw` ORDER BY `obj_type`, `obj_id`, `tag`, `msno` LIMIT %d;', $c / 2);
        $db->query($sql);
        printf("%d: %s\n", $i, $sql);
    }

    sleep(1);
}

[Alex Yurchenko (ayurchen)]

Looks like a combination of parallel applying AND COMPRESSED table. Most probably not all keys collected correctly. So in multi-master case this should lead to inconsistency.

[Gea-Suan Lin (gslin)]

Thanks!

I've test for ROW_FORMAT=DYNAMIC, and it will not fix this issue:

130513 20:15:50 [ERROR] Slave SQL: Could not execute Write_rows event on table t.tag_raw; Duplicate entry '0-65-17-中文測試' for key 'PRIMARY', Error_code: 1062; handler
 error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 114, Error_code: 1062
130513 20:15:50 [Warning] WSREP: RBR event 2 Write_rows apply warning: 121, 259584
130513 20:15:50 [ERROR] WSREP: Failed to apply trx: source: 6aaa649a-a85b-11e2-0800-08cc46d2f954 version: 2 local: 0 state: APPLYING flags: 1 conn_id: 29646 trx_id: 6885
90 seqnos (l: 3068, g: 259584, s: 259583, d: 259455, ts: 1368447350638588082)
130513 20:15:50 [ERROR] WSREP: Failed to apply app buffer: seqno: 259584, status: WSREP_FATAL
         at galera/src/replicator_smm.cpp:apply_wscoll():52
         at galera/src/replicator_smm.cpp:apply_trx_ws():118
130513 20:15:50 [ERROR] WSREP: Node consistency compromized, aborting...
130513 20:15:50 [Note] WSREP: Closing send monitor...
130513 20:15:50 [Note] WSREP: Closed send monitor.
130513 20:15:50 [Note] WSREP: gcomm: terminating thread
130513 20:15:50 [Note] WSREP: gcomm: joining thread
130513 20:15:50 [Note] WSREP: gcomm: closing backend
130513 20:15:50 [Note] WSREP: view(view_id(NON_PRIM,6aaa649a-a85b-11e2-0800-08cc46d2f954,13) memb {
        a524b69a-bbc6-11e2-0800-b438b8bdfa95,
} joined {
} left {
} partitioned {
        6aaa649a-a85b-11e2-0800-08cc46d2f954,
        986d80ee-a85f-11e2-0800-fa13f167bc00,
})
130513 20:15:50 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
130513 20:15:50 [Note] WSREP: view((empty))

> SHOW CREATE TABLE tag_raw \G
*************************** 1. row ***************************
       Table: tag_raw
Create Table: CREATE TABLE `tag_raw` (
  `obj_type` varchar(16) NOT NULL DEFAULT '' COMMENT 'obj_type',
  `obj_id` varchar(20) NOT NULL COMMENT 'obj_type編號',
  `tag` varchar(255) NOT NULL,
  `msno` bigint(20) NOT NULL DEFAULT '0' COMMENT 'user id',
  `terr_id` int(11) NOT NULL COMMENT '地區編號',
  PRIMARY KEY (`obj_type`,`obj_id`,`msno`,`tag`),
  KEY `obj_id` (`obj_id`),
  KEY `tag` (`tag`),
  KEY `msno` (`msno`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC
1 row in set (0.00 sec)

[Teemu Ollakka (teemu-ollakka)]

It looks like tmp_length is not adjusted properly after memcpy() in wsrep_innobase_mysql_sort(), which may cause reading uninitialized bytes from tmp_str buffer in charset->coll->strnxfrm(). This could cause constructing invalid key for wsrep.

[Gea-Suan Lin (gslin)]

I have another simple version, which affect UNIQUE KEY with UTF8 column too.

CREATE TABLE `test` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `c` varchar(32) DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `c` (`c`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

$ cat insert.php
<?php

$db = new PDO('mysql:host=db-test-1;dbname=t', 'test', 'test');

$p = $db->prepare('INSERT INTO test (c) VALUES (?);');

for ($i = 0;; $i++) {
    $p->execute(array('中文測試' . rand(1, 10000)));
    if (0 == $i % 1000) {
        printf("%d\n", $i);
    }
}

$ps = $db->prepare('SELECT COUNT(*) FROM `test`;');

$ cat delete.php
<?php

$db = new PDO('mysql:host=db-test-1;dbname=t', 'test', 'test');

$ps = $db->prepare('SELECT COUNT(*) FROM `test`;');

for ($i = 0;; $i++) {
    $ps->execute();
    list($c) = $ps->fetch(PDO::FETCH_NUM);

    if ($c > 100) {
        $sql = sprintf('DELETE FROM `test` ORDER BY `c` LIMIT %d;', $c / 2);
        $db->query($sql);
        printf("%d: %s\n", $i, $sql);
    }

    sleep(1);
}

[Seppo Jaakola (seppo-jaakola)]

Teemu pointed directly at the root cause for this problem. I'm testing with a fix for this problem, and regression test is passing now. You can expect a fix to be pushed within short.

[Seppo Jaakola (seppo-jaakola)]

Fix pushed in revision: http://bazaar.launchpad.net/~codership/codership-mysql/5.5-23/revision/3867

[Seppo Jaakola (seppo-jaakola)]

Fix was released in: https://launchpad.net/codership-mysql/5.5/5.5.31-23.7.5

[Seppo Jaakola (seppo-jaakola)]

Regression happened for wsrep-5.6 branch. Fix pushed in revision:
http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/4107

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1345