Bug #74026 Assertion `! is_set() || m_can_overwrite_status' failed.

• Submitted: 22 Sep 2014 23:52
• Modified: 15 Nov 2016 7:27
• Reporter: Roel Van de Paar
• Status: Duplicate
• Category: MySQL Server: DDL
• Severity: S1 (Critical)
• Version: 5.6.20, 5.6.34, 5.7.16
• OS: Any
• CPU Architecture: Any

[22 Sep 2014 23:52] Roel Van de Paar

Description:
(gdb) bt
#0  0x00007fd9b921b771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000a9035e in my_write_core (sig=6) at /bzr/mysql-5.6/mysys/stacktrace.c:422
#2  0x0000000000723688 in handle_fatal_signal (sig=6) at /bzr/mysql-5.6/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007fd9b8027989 in raise () from /lib64/libc.so.6
#5  0x00007fd9b8029098 in abort () from /lib64/libc.so.6
#6  0x00007fd9b80208f6 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007fd9b80209a2 in __assert_fail () from /lib64/libc.so.6
#8  0x000000000079bd6a in Diagnostics_area::set_error_status (this=0x2646be8, sql_errno=5, message=0x7fd9068f46b0 "Out of memory (Needed 2056 bytes)", sqlstate=0xf06981 "HY000", error_condition=0x0) at /bzr/mysql-5.6/sql/sql_error.cc:521
#9  0x0000000000785f0f in THD::raise_condition (this=0x2643810, sql_errno=5, sqlstate=0xf06981 "HY000", level=Sql_condition::WARN_LEVEL_ERROR, msg=0x7fd9068f46b0 "Out of memory (Needed 2056 bytes)") at /bzr/mysql-5.6/sql/sql_class.cc:1280
#10 0x000000000061bca6 in my_message_sql (error=5, str=0x7fd9068f46b0 "Out of memory (Needed 2056 bytes)", MyFlags=1124) at /bzr/mysql-5.6/sql/mysqld.cc:3310
#11 0x0000000000a873a1 in my_error (nr=5, MyFlags=1124) at /bzr/mysql-5.6/mysys/my_error.c:185
#12 0x0000000000a8a6a1 in my_malloc (size=2056, my_flags=48) at /bzr/mysql-5.6/mysys/my_malloc.c:56
#13 0x0000000000e18264 in _lf_dynarray_lvalue (array=0x1804140 <digest_hash>, idx=160) at /bzr/mysql-5.6/mysys/lf_dynarray.c:126
#14 0x0000000000e19263 in lf_hash_search (hash=0x1804140 <digest_hash>, pins=0x7fd8e4008080, key=0x7fd9068f4ad0, keylen=212) at /bzr/mysql-5.6/mysys/lf_hash.c:457
#15 0x0000000000aaee39 in find_or_create_digest (thread=0x7fd9a38bac40, digest_storage=0x264520c, schema_name=0x2645618 "test", '\217' <repeats 188 times>, "\004", schema_name_length=4) at /bzr/mysql-5.6/storage/perfschema/pfs_digest.cc:217
#16 0x0000000000ae4cd3 in end_statement_v1 (locker=0x2645168, stmt_da=0x2646be8) at /bzr/mysql-5.6/storage/perfschema/pfs.cc:4805
#17 0x00000000007c8fd6 in inline_mysql_end_statement (locker=0x2645168, stmt_da=0x2646be8) at /bzr/mysql-5.6/include/mysql/psi/mysql_statement.h:223
#18 0x00000000007cdaae in dispatch_command (command=COM_QUERY, thd=0x2643810, packet=0x8302891 "", packet_length=44) at /bzr/mysql-5.6/sql/sql_parse.cc:1778
#19 0x00000000007cb646 in do_command (thd=0x2643810) at /bzr/mysql-5.6/sql/sql_parse.cc:1034
#20 0x0000000000793a61 in do_handle_one_connection (thd_arg=0x2643810) at /bzr/mysql-5.6/sql/sql_connect.cc:982
#21 0x000000000079354a in handle_one_connection (arg=0x2643810) at /bzr/mysql-5.6/sql/sql_connect.cc:898
#22 0x0000000000ade888 in pfs_spawn_thread (arg=0x81a9630) at /bzr/mysql-5.6/storage/perfschema/pfs.cc:1860
#23 0x00007fd9b9216df3 in start_thread () from /lib64/libpthread.so.0
#24 0x00007fd9b80e83dd in clone () from /lib64/libc.so.6

2014-09-23 19:37:48 20826 [Note] Event Scheduler: Loaded 0 events
2014-09-23 19:37:48 20826 [Note] /sda/mysql-5.6.20-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.6.20-debug'  socket: '/sda/mysql-5.6.20-linux-x86_64-debug/socket.sock'  port: 17011  MySQL Community Server (GPL)
mysqld: /bzr/mysql-5.6/sql/sql_error.cc:521: void Diagnostics_area::set_error_status(uint, const char*, const char*, const Sql_condition*): Assertion `! is_set() || m_can_overwrite_status' failed.
09:37:50 UTC - mysqld got signal 6 ;

This issue was very apparent in our RQG runs (see https://bugs.launchpad.net/percona-server/+bug/1264164 ). It was only recenly that I found a testcase which also sig6 asserts mysqld with an indentical stack and assert message. I am not convinved yet this is a debug-only issue yet, so the testcase should not be taken as a measure of how serious this issue is or not. True enough, because of the use of SET GLOBAL debug testcase this can currently only be reproduced in debug for the time being, but this does not validate the issue is debug-only (until proven otherwise). Normally the issue is sporadic, but this particular occurence seems to crash mysqld consitently. Note from the launchpad bug report this crash can be created on many different statements. More details there also.

Some extra TLC on this bug would be appreciated, as this has been close to a QA blocker for us. 

Shane, some help with a gypsy run/code-based-justification that these issues are all alike (and not another "protocol::end_statement"-like situation where each underlying issue is different) in this area would also be very appreciated!

How to repeat:
1. SET GLOBAL debug='+d,simulate_out_of_memory';
   Query reports "OK", but...
2. Exit client - server should already have terminated.

And as mentioned, note this is just an example testcase but that the actual assert can be seen on many different queries. See LP bug report.

[22 Sep 2014 23:53] Roel Van de Paar

Will also try to upload a hacked reducer testcase

[23 Sep 2014 0:00] Roel Van de Paar

reducer10.sh

Attachment: reducer10.sh (application/octet-stream, text), 142.03 KiB.

[23 Sep 2014 0:01] Roel Van de Paar

1.sql

Attachment: 1.sql (application/octet-stream, text), 2 bytes.

[23 Sep 2014 0:04] Roel Van de Paar

[roel@localhost 598892]$ ./reducer10.sh sql.sql
2014-09-03 23:42:40 [Init] Workdir: /dev/shm/1411466021 <--- note workdir (!)
[...]
2014-09-03 23:42:56 [Init] Looking for this string: 'm_can_overwrite_status' in mysqld error log output
[...wait for issue to reproduce... if it fails, restart reducer after rm -Rf /dev/shm/* ...]  <------ (!)
2014-09-03 23:45:23 [] [Stage V] [MULTI] All verification subreducer threads have finished/terminated
2014-09-03 23:45:23 [*] [Stage V] [MULTI] Threads which reproduced the issue: #16
2014-09-03 23:45:23 [*] [Stage V] [MULTI] Only 1 out of 30 threads reproduced the issue: this issue is sporadic
Got it!

As soon as you see this "Got it!" you can see the occurence:

[roel@localhost 202440]$ cd /dev/shm/1411466021
[roel@localhost 1411466021]$ grep 'm_can_overwrite_status' */*/error.log.out
mysqld: /bzr/mysql-5.6/sql/sql_error.cc:521: void Diagnostics_area::set_error_status(uint, const char*, const char*, const Sql_condition*): Assertion `! is_set() || m_can_overwrite_status' failed.

[23 Sep 2014 0:05] Roel Van de Paar

(sql.sql in that last comment should have read 1.sql)

[23 Sep 2014 0:06] Roel Van de Paar

Btw, if you use grep -l 'm_can_overwrite_status' */*/error.log.out you can see which subreducer failed with the issue;

[roel@localhost 1411466021]$ grep -l 'm_can_overwrite_status' */*/error.log.out
subreducer/2/error.log.out
[roel@localhost 1411466021]$ ls subreducer/2/data/core.*
subreducer/2/data/core.26101.1000.1000.6.1411466084.mysqld

[23 Sep 2014 0:09] Roel Van de Paar

The testcase shows that other statements can trigger the same assert.

[15 Nov 2016 7:27] MySQL Verification Team

Hello Roel,

Thank you for the report.
Marking as duplicate of Bug #83797.

Thanks,
Umesh