percona 5.7.17-13 crash on UPDATE ON DUPLICATE KEY

[Kirill]

Hi!

percona 5.7.17-13 (check CentOS 7.3, Ubuntu 16.04 on default config) crash on UPDATE ON DUPLICATE KEY
percona 5.6 All ok

How to reproduce:
<---Structure DB----->
create database buk;

use buk;

CREATE TABLE tablica_s_govnom (
  pri1 int(11) UNSIGNED NOT NULL,
  DT datetime DEFAULT NULL,
  dop1 text DEFAULT NULL ,
  PRIMARY KEY (pri1),
  INDEX UK_tablica_s_govnom (DT)
)
ENGINE = INNODB
AVG_ROW_LENGTH = 16384
CHARACTER SET utf8
COLLATE utf8_general_ci
ROW_FORMAT = DYNAMIC;

INSERT INTO tablica_s_govnom(pri1,DT,dop1) VALUES(1,NOW(),'2222');
DELIMITER //
CREATE PROCEDURE Sucks_test()
BEGIN
   DECLARE pri1,pri3 int;
   DECLARE pri2,comment VARCHAR(255);
   DECLARE dop1_1,dop2,dop3 VARCHAR(255) DEFAULT '222';

   set pri1=1,pri2='1',pri3=1,comment='123';

   INSERT INTO tablica_s_govnom(pri1, DT, dop1)
      VALUES(pri1, NOW() ,dop1_1)
      ON DUPLICATE KEY UPDATE DT=NOW(), dop1=VALUES(dop1);
END//

</---Structure DB----->

<---test.sql---->
use buk;

CALL Sucks_test();
CALL Sucks_test();

</---test.sql---->

run test in loop wait 5-10sec and mysql DIE with "mysqld got signal 11 ;"
while true; do mysql < test.sql ; done

[Kirill (simakink)]

08:19:15 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=13
max_threads=152
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68317 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f6474023f00
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 = 7f64a6249d30 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xeffd8b]
/usr/sbin/mysqld(handle_fatal_signal+0x471)[0x7a0181]
/lib64/libpthread.so.0(+0xf370)[0x7f64c3d82370]
/lib64/libc.so.6(+0x14bbf0)[0x7f64c201dbf0]
/usr/sbin/mysqld(_ZN10Field_blob15copy_blob_valueEP11st_mem_root+0x84)[0x7e4f14]
/usr/sbin/mysqld(_Z25mysql_prepare_blob_valuesP3THDR4ListI4ItemEP11st_mem_root+0x2b8)[0xe47818]
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0x87d)[0xe483dd]
/usr/sbin/mysqld(_ZN14Sql_cmd_insert12mysql_insertEP3THDP10TABLE_LIST+0x82d)[0xe48e4d]
/usr/sbin/mysqld(_ZN14Sql_cmd_insert7executeEP3THD+0xe6)[0xe496a6]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x18d6)[0xcd1336]
/usr/sbin/mysqld(_ZN13sp_instr_stmt9exec_coreEP3THDPj+0x50)[0xc517b0]
/usr/sbin/mysqld(_ZN12sp_lex_instr23reset_lex_and_exec_coreEP3THDPjb+0x3a4)[0xc53414]
/usr/sbin/mysqld(_ZN12sp_lex_instr29validate_lex_and_execute_coreEP3THDPjb+0xbb)[0xc53deb]
/usr/sbin/mysqld(_ZN13sp_instr_stmt7executeEP3THDPj+0x318)[0xc55188]
/usr/sbin/mysqld(_ZN7sp_head7executeEP3THDb+0x504)[0xc4cfe4]
/usr/sbin/mysqld(_ZN7sp_head17execute_procedureEP3THDP4ListI4ItemE+0x787)[0xc50b67]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x4d26)[0xcd4786]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x60d)[0xcd75cd]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xaba)[0xcd811a]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1df)[0xcd9adf]
/usr/sbin/mysqld(handle_connection+0x2b8)[0xda1ae8]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0xf17934]
/lib64/libpthread.so.0(+0x7dc5)[0x7f64c3d7adc5]
/lib64/libc.so.6(clone+0x6d)[0x7f64c1fc973d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f6474008a60): INSERT INTO tablica_s_govnom(pri1, DT, dop1) VALUES(pri1, NOW() ,dop1_1) ON DUPLICATE KEY UPDATE DT=NOW(), dop1=VALUES(dop1)
Connection ID (thread ID): 1244
Status: NOT_KILLED

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify th...

[Sveta Smirnova (svetasmirnova)]

Thank you for the report.

Verified as described.

12:21:55 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=4
max_threads=152
thread_count=3
connection_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61227 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f9fe8129180
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 = 7fa034faee18 thread_stack 0x40000
/home/sveta/build/ps-5.7/bin/mysqld(my_print_stacktrace+0x47)[0x19d067d]
/home/sveta/build/ps-5.7/bin/mysqld(handle_fatal_signal+0x440)[0xf56959]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fa03c5db390]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6(__dynamic_cast+0x23)[0x7fa03c2ce413]
/home/sveta/build/ps-5.7/bin/mysqld(_Z9down_castIP10Field_blobP5FieldET_T0_+0x30)[0x10022b7]
/home/sveta/build/ps-5.7/bin/mysqld(_Z25mysql_prepare_blob_valuesP3THDR4ListI4ItemEP11st_mem_root+0x2ad)[0x18a5fe1]
/home/sveta/build/ps-5.7/bin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0x67e)[0x18a985a]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN14Sql_cmd_insert12mysql_insertEP3THDP10TABLE_LIST+0xf09)[0x18a6fc9]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN14Sql_cmd_insert7executeEP3THD+0x19f)[0x18ae0bb]
/home/sveta/build/ps-5.7/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x320a)[0x166b9bd]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN13sp_instr_stmt9exec_coreEP3THDPj+0x7a)[0x15aa494]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN12sp_lex_instr23reset_lex_and_exec_coreEP3THDPjb+0x627)[0x15a8fa1]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN12sp_lex_instr29validate_lex_and_execute_coreEP3THDPjb+0x16a)[0x15a9b30]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN13sp_instr_stmt7executeEP3THDPj+0x2db)[0x15aa0f9]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN7sp_head7executeEP3THDb+0x7a4)[0x15a1f5a]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN7sp_head17execute_procedureEP3THDP4ListI4ItemE+0x94f)[0x15a4157]
/home/sveta/build/ps-5.7/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x67d1)[0x166ef84]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN13sp_instr_stmt9exec_coreEP3THDPj+0x7a)[0x15aa494]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN12sp_lex_instr23reset_lex_and_exec_coreEP3THDPjb+0x627)[0x15a8fa1]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN12sp_lex_instr29validate_lex_and_execute_coreEP3THDPjb+0x16a)[0x15a9b30]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN13sp_instr_stmt7executeEP3THDPj+0x2db)[0x15aa0f9]
/home/sveta/build/ps-5.7/bin/mysqld(_ZN7sp_head7executeEP3THDb+0x7a4)[0x15a1f5a]
/home/sveta/build/ps-5.7/b...

[Sveta Smirnova (svetasmirnova)]

Upstream and 5.6 are not affected

[Sveta Smirnova (svetasmirnova)]

I tested with 5.7.18

[Laurynas Biveinis (laurynas-biveinis)]

Upstream is affected in my testing, MySQL 5.7.18, with the provided testcase (AddressSanitizer build):

ASAN:DEADLYSIGNAL
=================================================================
==24845==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000 (pc 0x7fffb603ca59 bp 0x70000c2985d0 sp 0x70000c298540 T25)
==24845==The signal is caused by a READ memory access.
==24845==Hint: address points to the zero page.
    #0 0x7fffb603ca58 in __dynamic_cast (libc++abi.dylib:x86_64+0x25a58)
    #1 0x108c42945 in Field_blob* down_cast<Field_blob*, Field*>(Field*) template_utils.h:78
    #2 0x109624db8 in mysql_prepare_blob_values(THD*, List<Item>&, st_mem_root*) sql_insert.cc:398
    #3 0x10962a6b6 in write_record(THD*, TABLE*, COPY_INFO*, COPY_INFO*) sql_insert.cc:1655
    #4 0x109626f7a in Sql_cmd_insert::mysql_insert(THD*, TABLE_LIST*) sql_insert.cc:769
    #5 0x109634596 in Sql_cmd_insert::execute(THD*) sql_insert.cc:3102
    #6 0x1096ba007 in mysql_execute_command(THD*, bool) sql_parse.cc:3607
    #7 0x109524b68 in sp_instr_stmt::exec_core(THD*, unsigned int*) sp_instr.cc:983
    #8 0x109521960 in sp_lex_instr::reset_lex_and_exec_core(THD*, unsigned int*, bool) sp_instr.cc:411
    #9 0x1095230b8 in sp_lex_instr::validate_lex_and_execute_core(THD*, unsigned int*, bool) sp_instr.cc:711
    #10 0x109523b14 in sp_instr_stmt::execute(THD*, unsigned int*) sp_instr.cc:894
    #11 0x109517299 in sp_head::execute(THD*, bool) sp_head.cc:789
    #12 0x10951aff4 in sp_head::execute_procedure(THD*, List<Item>*) sp_head.cc:1522
    #13 0x1096b779a in mysql_execute_command(THD*, bool) sql_parse.cc:4593
    #14 0x109524b68 in sp_instr_stmt::exec_core(THD*, unsigned int*) sp_instr.cc:983
    #15 0x109521960 in sp_lex_instr::reset_lex_and_exec_core(THD*, unsigned int*, bool) sp_instr.cc:411
    #16 0x1095230b8 in sp_lex_instr::validate_lex_and_execute_core(THD*, unsigned int*, bool) sp_instr.cc:711
    #17 0x109523b14 in sp_instr_stmt::execute(THD*, unsigned int*) sp_instr.cc:894
    #18 0x109517299 in sp_head::execute(THD*, bool) sp_head.cc:789
    #19 0x10951aff4 in sp_head::execute_procedure(THD*, List<Item>*) sp_head.cc:1522
    #20 0x1096b779a in mysql_execute_command(THD*, bool) sql_parse.cc:4593
    #21 0x1096b15cf in mysql_parse(THD*, Parser_state*) sql_parse.cc:5612
    #22 0x1096ad97c in dispatch_command(THD*, COM_DATA const*, enum_server_command) sql_parse.cc:1461
    #23 0x1096afc34 in do_command(THD*) sql_parse.cc:999
    #24 0x1098f52b3 in handle_connection connection_handler_per_thread.cc:300
    #25 0x10a23aea2 in pfs_spawn_thread pfs.cc:2188
    #26 0x7fffb764793a in _pthread_body (libsystem_pthread.dylib:x86_64+0x393a)
    #27 0x7fffb7647886 in _pthread_start (libsystem_pthread.dylib:x86_64+0x3886)
    #28 0x7fffb764708c in thread_start (libsystem_pthread.dylib:x86_64+0x308c)

Sveta, can you finish processing this as upstream bug?

[Sveta Smirnova (svetasmirnova)]

Done.

Re-tested upstream once more without option -DWITH_ASAN=1 - no crash, with -DWITH_ASAN=1 - crash happens.

[Laurynas Biveinis (laurynas-biveinis)]

Oracle confirmed crash on 5.7.18, which is no longer reproducible on yet-unreleased 5.7.20. Will track this bug at the upstream merges.

[Yura Sorokin (yura-sorokin)]

Fixed by Oracle in 5.7.19 and 8.0.2

Incorrect behavior could occur for INSERT statements executed in stored-program or prepared-statement context, if the VALUES part of an ON DUPLICATE KEY UPDATE clause referred to a BLOB value in the INSERT column list. (Bug #24538207, Bug #25361251, Bug #25530880, Bug #25684790)

[Yura Sorokin (yura-sorokin)]

Fixed in the 5.7.19 upstream merge PR
https://github.com/percona/percona-server/pull/1892

[markus_albe (markus-albe)]

This is happening on

2017-10-24T13:03:59.288946-05:00 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.19-17 started;

The top of the stack trace is identical, and the query is an INSERT with a TEXT column involved, but stored procedures are not involved (am waiting for input regarding how the query gets executed).

/bin/mysql/percona5.7.19/bin/mysqld(my_print_stacktrace+0x2c)[0xed36bc]
/bin/mysql/percona5.7.19/bin/mysqld(handle_fatal_signal+0x461)[0x7a26e1]
/lib64/libpthread.so.0[0x3798c0f7e0]
/lib64/libc.so.6(memcpy+0xd2)[0x37980898d2]
/bin/mysql/percona5.7.19/bin/mysqld(Field_blob::copy_blob_value(st_mem_root*)+0x75)[0x7e62e5]
/bin/mysql/percona5.7.19/bin/mysqld(mysql_prepare_blob_values(THD*, List<Item>&, st_mem_root*)+0x2b8)[0xe1c748]
/bin/mysql/percona5.7.19/bin/mysqld(write_record(THD*, TABLE*, COPY_INFO*, COPY_INFO*)+0x9c0)[0xe1d450]
/bin/mysql/percona5.7.19/bin/mysqld(Sql_cmd_insert::mysql_insert(THD*, TABLE_LIST*)+0x825)[0xe1dec5]
/bin/mysql/percona5.7.19/bin/mysqld(Sql_cmd_insert::execute(THD*)+0xc2)[0xe1e702]
/bin/mysql/percona5.7.19/bin/mysqld(mysql_execute_command(THD*, bool)+0x18d7)[0xcad217]
/bin/mysql/percona5.7.19/bin/mysqld(mysql_parse(THD*, Parser_state*)+0x5d5)[0xcb3385]
/bin/mysql/percona5.7.19/bin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0xaba)[0xcb3eca]
/bin/mysql/percona5.7.19/bin/mysqld(do_command(THD*)+0x1b7)[0xcb5917]
/bin/mysql/percona5.7.19/bin/mysqld(handle_connection+0x2a0)[0xd79a60]
/bin/mysql/percona5.7.19/bin/mysqld(pfs_spawn_thread+0x1b4)[0x123cf24]
/lib64/libpthread.so.0[0x3798c07aa1]
/lib64/libc.so.6(clone+0x6d)[0x37980e8aad]

Table looks like
CREATE TABLE `t` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`f_id` int(11) NOT NULL,
`l` varchar(512) NOT NULL,
`t` varchar(128) NOT NULL,
`a` varchar(128) DEFAULT NULL,
`t2` text,
`s` text,
`c` datetime DEFAULT '0000-00-00 00:00:00',
`m` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
PRIMARY KEY (`id`),
UNIQUE KEY `rss_id_unique` (`l`,`f_id`) USING BTREE,
KEY `Index_3` (`c`),
KEY `Index_4` (`f_id`)
) ENGINE=InnoDB AUTO_INCREMENT=663473641 DEFAULT CHARSET=latin1

[Marcelo Altmann (marcelo.altmann)]

Last stack trace is equal to https://bugs.mysql.com/bug.php?id=79243 , which was fixed on 5.7.21

[Shahriyar Rzayev (rzayev-sehriyar)]

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