[MDEV-15304] Server crash in print_keydup_error / key_unpack or unexpected ER_DUP_KEY Created: 2018-02-13  Updated: 2018-06-13  Resolved: 2018-05-18

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - RocksDB
Affects Version/s: 10.2
Fix Version/s: 10.2.16

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 1
Labels: upstream

Issue Links:
Relates
relates to MDEV-14141 mysqld got exception 0xc0000005 Closed
relates to MDEV-14970 MariaDB crashed with signal 11 and Ar... Closed
relates to MDEV-15485 Server crashes in read_sep_field / wr... Closed
relates to MDEV-15237 "Can't write; duplicate key in table"... Closed

 Description   

Note: the test case fails for me all the time right now, but it's still non-deterministic. Try several times if it doesn't fail for you.

INSTALL SONAME 'ha_rocksdb';
 
CREATE TABLE t1 (a INT, KEY(a)) ENGINE=RocksDB;
INSERT INTO t1 VALUES (1),(2);
	
CREATE TABLE t2 (b INT) ENGINE=RocksDB;
CREATE OR REPLACE VIEW v2 AS SELECT * FROM t2;
 
CREATE OR REPLACE TABLE t3 (c INT) ENGINE=RocksDB;
BEGIN;
 
--connect (con1,localhost,root,,test)
SET lock_wait_timeout= 2;
--delimiter $
CREATE TRIGGER tr BEFORE UPDATE ON t3 FOR EACH ROW 
BEGIN
  DELETE FROM t1; 
  DELETE FROM non_existing_table; 
END $
--delimiter ;
--send
	ALTER TABLE t1 FORCE;
 
--connection default
DELETE FROM v2 WHERE b < 1;
--error ER_BAD_FIELD_ERROR
UPDATE t3 SET unknown_column = NULL;
 
--connection con1
--reap
INSERT INTO t1 VALUES (3);
 
# Cleanup
--disconnect con1
--connection default
COMMIT;
DROP VIEW v2;
DROP TABLE t1, t2, t3;
UNINSTALL SONAME 'ha_rocksdb';

Till recently (I suppose till changes Monty made in scope of MDEV-14970 / MDEV-14141, although I didn't bisect), the test case above caused the crash:

10.2.12

#3  <signal handler called>
#4  0x000055d7081bc333 in key_unpack (to=0x7fa5e017e7a0, table=0x7fa5d0371c70, key=0x7fa5d03765d0) at /data/src/10.2-bug/sql/key.cc:432
#5  0x000055d7080caf56 in print_keydup_error (table=0x7fa5d0371c70, key=0x7fa5d03765d0, msg=0x55d70abcf1f4 "Duplicate entry '%-.64s' for key '%-.192s'", errflag=0) at /data/src/10.2-bug/sql/handler.cc:3334
#6  0x000055d7080cb094 in print_keydup_error (table=0x7fa5d0371c70, key=0x7fa5d03765d0, errflag=0) at /data/src/10.2-bug/sql/handler.cc:3356
#7  0x000055d7080cb2e8 in handler::print_error (this=0x7fa5d0372878, error=121, errflag=0) at /data/src/10.2-bug/sql/handler.cc:3433
#8  0x000055d707e2fc00 in write_record (thd=0x7fa5ac000b00, table=0x7fa5d0371c70, info=0x7fa5e01804a0) at /data/src/10.2-bug/sql/sql_insert.cc:1958
#9  0x000055d707e2d471 in mysql_insert (thd=0x7fa5ac000b00, table_list=0x7fa5ac011208, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /data/src/10.2-bug/sql/sql_insert.cc:1057
#10 0x000055d707e54af7 in mysql_execute_command (thd=0x7fa5ac000b00) at /data/src/10.2-bug/sql/sql_parse.cc:4415
#11 0x000055d707e5fa6e in mysql_parse (thd=0x7fa5ac000b00, rawbuf=0x7fa5ac011128 "INSERT INTO t1 VALUES (3)", length=25, parser_state=0x7fa5e0181200, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:7900
#12 0x000055d707e4d97c in dispatch_command (command=COM_QUERY, thd=0x7fa5ac000b00, packet=0x7fa5ac008941 "INSERT INTO t1 VALUES (3)", packet_length=25, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:1805
#13 0x000055d707e4c2da in do_command (thd=0x7fa5ac000b00) at /data/src/10.2-bug/sql/sql_parse.cc:1360
#14 0x000055d707f9a225 in do_handle_one_connection (connect=0x55d70adddcc0) at /data/src/10.2-bug/sql/sql_connect.cc:1335
#15 0x000055d707f99fb2 in handle_one_connection (arg=0x55d70adddcc0) at /data/src/10.2-bug/sql/sql_connect.cc:1241
#16 0x000055d7083b936e in pfs_spawn_thread (arg=0x55d70ac0d730) at /data/src/10.2-bug/storage/perfschema/pfs.cc:1863
#17 0x00007fa5e7bc6494 in start_thread (arg=0x7fa5e0182700) at pthread_create.c:333
#18 0x00007fa5e5fac93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Now it causes ER_DUP_KEY on a table which has no unique keys:

mysqltest: At line 31: query 'INSERT INTO t1 VALUES (3)' failed: 1022: Can't write; duplicate key in table 't1'



 Comments   
Comment by Sergei Petrunia [ 2018-04-08 ]

Tried on the upstream. I got this error:

mysqltest: At line 30: query 'reap' failed: 1205: Lock wait timeout exceeded; try restarting transaction: Timeout on table metadata: test.t1

If I add --error 0,ER_LOCK_WAIT_TIMEOUT before the reap command, then I dont get this ER_DUP_KEY error.

On the current MariaDB 10.2, I get the error fairly reliably

mysqltest: At line 31: query 'INSERT INTO t1 VALUES (3)' failed: 1022: Can't write; duplicate key in table 't1'

Comment by Sergei Petrunia [ 2018-05-17 ]

Changed the last INSERT int the test to use 1+2:

INSERT INTO t1 VALUES (1+2);

and now I can see that the error originates here:

(gdb) p/x m_pk_descr->m_index_number
  $34 = 0x105

(gdb) wher
  #0  myrocks::ha_rocksdb::check_and_lock_unique_pk (this=0x7fffbc032298, key_id=@0x7fffe84b9078: 1, row_info=..., found=0x7fffe84b9077, pk_changed=0x7fffe84b90cb) at /home/psergey/dev-git/10.2-r11/storage/rocksdb/ha_rocksdb.cc:9202
  #1  0x00007fffeb5ef5bc in myrocks::ha_rocksdb::check_uniqueness_and_lock (this=0x7fffbc032298, row_info=..., pk_changed=0x7fffe84b90cb) at /home/psergey/dev-git/10.2-r11/storage/rocksdb/ha_rocksdb.cc:9355
  #2  0x00007fffeb5f07f9 in myrocks::ha_rocksdb::update_write_row (this=0x7fffbc032298, old_data=0x0, new_data=0x7fffbc030668 "\375\003", skip_unique_check=false) at /home/psergey/dev-git/10.2-r11/storage/rocksdb/ha_rocksdb.cc:9689
  #3  0x00007fffeb5eeacf in myrocks::ha_rocksdb::write_row (this=0x7fffbc032298, buf=0x7fffbc030668 "\375\003") at /home/psergey/dev-git/10.2-r11/storage/rocksdb/ha_rocksdb.cc:9084
  #4  0x0000555555d89b99 in handler::ha_write_row (this=0x7fffbc032298, buf=0x7fffbc030668 "\375\003") at /home/psergey/dev-git/10.2-r11/sql/handler.cc:5958
  #5  0x0000555555ae6b62 in write_record (thd=0x7fffc0000ba0, table=0x7fffbc031690, info=0x7fffe84b94a0) at /home/psergey/dev-git/10.2-r11/sql/sql_insert.cc:1929
  #6  0x0000555555ae4619 in mysql_insert (thd=0x7fffc0000ba0, table_list=0x7fffc0011210, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/psergey/dev-git/10.2-r11/sql/sql_insert.cc:1057
  #7  0x0000555555b0bef0 in mysql_execute_command (thd=0x7fffc0000ba0) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:4434
  #8  0x0000555555b17052 in mysql_parse (thd=0x7fffc0000ba0, rawbuf=0x7fffc0011128 "INSERT INTO t1 VALUES (1+2)", length=27, parser_state=0x7fffe84ba200, is_com_multi=false, is_next_command=false) at /home/psergey/dev-git/10.2-r11/sql/sql_parse.cc:7940

We try to lock an index tuple for the internal (hidden) PK. The value we are
trying to lock is:

(gdb) p row_info.new_pk_slice
  $32 = {data_ = 0x7fffbc01b5b0 "", size_ = 12}
(gdb) x/12c row_info.new_pk_slice.data_
  0x7fffbc01b5b0:	0 '\000'	0 '\000'	1 '\001'	5 '\005'	0 '\000'	0 '\000'	0 '\000'	0 '\000'
  0x7fffbc01b5b8:	0 '\000'	0 '\000'	0 '\000'	1 '\001'
(gdb) p/x m_pk_descr->m_index_number
  $34 = 0x105

The hidden PK val is stored here:

(gdb) p m_tbl_def->m_hidden_pk_val
  $35 = {<std::__atomic_base<long long>> = {_M_i = 2}, <No data fields>}

Comment by Sergei Petrunia [ 2018-05-18 ]

Filed as https://github.com/facebook/mysql-5.6/issues/834

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