MySQL Bugs: #79905: Assertion `strlen(m_ptr) == m

Bug #79905	Assertion `strlen(m_ptr) == m_length' failed.
Submitted:	10 Jan 2016 21:44	Modified:	14 Mar 2016 14:07
Reporter:	Roel Van de Paar	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S6 (Debug Builds)
Version:	5.7.10, 5.7.11	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
2016-01-10T21:31:02.073389Z 0 [Note] /sdc/MS-mysql-5.7.10-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.7.10-debug'  socket: '/sdc/MS-mysql-5.7.10-linux-x86_64-debug/socket.sock'  port: 18119  MySQL Community Server (GPL)
mysqld: /git/mysql-server_dbg/include/sql_string.h:320: void String::chop(): Assertion `strlen(m_ptr) == m_length' failed.
21:31:04 UTC - mysqld got signal 6 ;

+bt
#0  0x00007fba0978c741 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1  0x00000000017ef4b0 in my_write_core (sig=6) at /git/mysql-server_dbg/mysys/stacktrace.c:247
#2  0x0000000000e58274 in handle_fatal_signal (sig=6) at /git/mysql-server_dbg/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007fba07b255f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5  0x00007fba07b26ce8 in __GI_abort () at abort.c:90
#6  0x00007fba07b1e566 in __assert_fail_base (fmt=0x7fba07c6e228 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x1e7964b "strlen(m_ptr) == m_length", file=file@entry=0x1e79620 "/git/mysql-server_dbg/include/sql_string.h", line=line@entry=320, function=function@entry=0x1e79ad0 <String::chop()::__PRETTY_FUNCTION__> "void String::chop()") at assert.c:92
#7  0x00007fba07b1e612 in __GI___assert_fail (assertion=0x1e7964b "strlen(m_ptr) == m_length", file=0x1e79620 "/git/mysql-server_dbg/include/sql_string.h", line=320, function=0x1e79ad0 <String::chop()::__PRETTY_FUNCTION__> "void String::chop()") at assert.c:101
#8  0x000000000142d35e in String::chop (this=0x7fba09d7ee90) at /git/mysql-server_dbg/include/sql_string.h:320
#9  0x000000000142c37d in Transaction_state_tracker::store (this=0x7fb93c031080, thd=0x7fb93c019000, buf=...) at /git/mysql-server_dbg/sql/session_tracker.cc:1185
#10 0x000000000142cdf5 in Session_tracker::store (this=0x7fb93c01c650, thd=0x7fb93c019000, buf=...) at /git/mysql-server_dbg/sql/session_tracker.cc:1667
#11 0x0000000001419bd2 in net_send_ok (thd=0x7fb93c019000, server_status=16387, statement_warn_count=0, affected_rows=0, id=0, message=0x7fb93c01bdd8 "", eof_identifier=false) at /git/mysql-server_dbg/sql/protocol_classic.cc:348
#12 0x000000000141a4bc in Protocol_classic::send_ok (this=0x7fb93c01a188, server_status=3, statement_warn_count=0, affected_rows=0, last_insert_id=0, message=0x7fb93c01bdd8 "") at /git/mysql-server_dbg/sql/protocol_classic.cc:645
#13 0x000000000148a08b in THD::send_statement_status (this=0x7fb93c019000) at /git/mysql-server_dbg/sql/sql_class.cc:4762
#14 0x00000000014e2025 in dispatch_command (thd=0x7fb93c019000, com_data=0x7fba09d7fcb0, command=COM_QUERY) at /git/mysql-server_dbg/sql/sql_parse.cc:1835
#15 0x00000000014dfb71 in do_command (thd=0x7fb93c019000) at /git/mysql-server_dbg/sql/sql_parse.cc:993
#16 0x000000000160ad5b in handle_connection (arg=0x7fb955b91820) at /git/mysql-server_dbg/sql/conn_handler/connection_handler_per_thread.cc:301
#17 0x000000000181b8fc in pfs_spawn_thread (arg=0x7fb955fe8120) at /git/mysql-server_dbg/storage/perfschema/pfs.cc:2192
#18 0x00007fba09787dc5 in start_thread (arg=0x7fba09d80700) at pthread_create.c:308
#19 0x00007fba07be621d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

How to repeat:
DROP DATABASE test;
SET session_track_transaction_info='CHARACTERISTICS';
SET character_set_connection=ucs2;
XA START 'a';

See fixed bug 75870

Hello Roel,

Thank you for the report and test case.
Observed that 5.7.10/5.7.11 debug builds are affected.

Thanks,
Umesh

// 5.7.10  only debug build affected

bin/mysql_install_db --insecure --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.10 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.10/79905 -v
bin/mysqld-debug --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.10 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.10/79905 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-advanced-5.7.10/79905/log.err 2>&1 &

(gdb) bt
#0  0x00007f173fa61771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000188bda1 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/mysys/stacktrace.c:247
#2  0x0000000000eadfe4 in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007f173e6675d7 in raise () from /lib64/libc.so.6
#5  0x00007f173e668cc8 in abort () from /lib64/libc.so.6
#6  0x00007f173e660546 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f173e6605f2 in __assert_fail () from /lib64/libc.so.6
#8  0x00000000014b40f1 in String::chop (this=0x7f1712467b40) at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/include/sql_string.h:320
#9  0x00000000014b3053 in Transaction_state_tracker::store (this=0x7f16cc0079a0, thd=0x7f16cc000b70, buf=...)
    at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/session_tracker.cc:1185
#10 0x00000000014b3b5c in Session_tracker::store (this=0x7f16cc004038, thd=0x7f16cc000b70, buf=...)
    at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/session_tracker.cc:1667
#11 0x00000000014a063b in net_send_ok (thd=0x7f16cc000b70, server_status=16387, statement_warn_count=0, affected_rows=0, id=0, message=0x7f16cc0037c0 "", eof_identifier=false)
    at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/protocol_classic.cc:348
#12 0x00000000014a0f1f in Protocol_classic::send_ok (this=0x7f16cc001bb0, server_status=3, statement_warn_count=0, affected_rows=0, last_insert_id=0, message=0x7f16cc0037c0 "")
    at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/protocol_classic.cc:645
#13 0x0000000001512635 in THD::send_statement_status (this=0x7f16cc000b70) at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/sql_class.cc:4762
#14 0x000000000156c66d in dispatch_command (thd=0x7f16cc000b70, com_data=0x7f1712468e00, command=COM_QUERY)
    at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/sql_parse.cc:1835
#15 0x000000000156a116 in do_command (thd=0x7f16cc000b70) at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/sql_parse.cc:993
#16 0x000000000169b713 in handle_connection (arg=0x3ae6600) at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/sql/conn_handler/connection_handler_per_thread.cc:301
#17 0x0000000001917660 in pfs_spawn_thread (arg=0x3bf5d10) at /export/home/pb2/build/sb_0-17208442-1448825515.37/mysqlcom-pro-5.7.10/storage/perfschema/pfs.cc:2192
#18 0x00007f173fa5cdf5 in start_thread () from /lib64/libpthread.so.0
#19 0x00007f173e72860d in clone () from /lib64/libc.so.6
(gdb)

// 5.7.11 only debug build affected

bin/mysql_install_db --insecure --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.11 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.11/79905 -v
bin/mysqld-debug --no-defaults --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.11 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.11/79905 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-advanced-5.7.11/79905/log.err 2>&1 &

commit: 7b6adbc3112e994c35f89dd97f3cfb8dd6afda30
date: 2016-01-11 09:25:36 +0530
build-date: 2016-01-11 05:02:02 +0100
short: 7b6adbc
branch: mysql-5.7

MySQL source 5.7.11

(gdb) bt
#0  0x00007f164ba39771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000018abfc9 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/mysys/stacktrace.c:247
#2  0x0000000000ec057c in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007f164a63f5d7 in raise () from /lib64/libc.so.6
#5  0x00007f164a640cc8 in abort () from /lib64/libc.so.6
#6  0x00007f164a638546 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f164a6385f2 in __assert_fail () from /lib64/libc.so.6
#8  0x00000000014a71d5 in String::chop (this=0x7f1608505b30) at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/include/sql_string.h:320
#9  0x00000000014a6137 in Transaction_state_tracker::store (this=0x7f15b40079c0, thd=0x7f15b4000b70, buf=...)
    at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/session_tracker.cc:1185
#10 0x00000000014a6c40 in Session_tracker::store (this=0x7f15b4004050, thd=0x7f15b4000b70, buf=...)
    at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/session_tracker.cc:1667
#11 0x000000000149370f in net_send_ok (thd=0x7f15b4000b70, server_status=16387, statement_warn_count=0, affected_rows=0, id=0, message=0x7f15b40037d8 "", eof_identifier=false)
    at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/protocol_classic.cc:346
#12 0x0000000001493ff3 in Protocol_classic::send_ok (this=0x7f15b4001bb8, server_status=3, statement_warn_count=0, affected_rows=0, last_insert_id=0, message=0x7f15b40037d8 "")
    at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/protocol_classic.cc:643
#13 0x00000000015148fb in THD::send_statement_status (this=0x7f15b4000b70) at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/sql_class.cc:4745
#14 0x000000000156e62a in dispatch_command (thd=0x7f15b4000b70, com_data=0x7f1608506e00, command=COM_QUERY)
    at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/sql_parse.cc:1844
#15 0x000000000156c05f in do_command (thd=0x7f15b4000b70) at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/sql_parse.cc:996
#16 0x000000000169e93f in handle_connection (arg=0x3e72c00) at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/sql/conn_handler/connection_handler_per_thread.cc:301
#17 0x0000000001937908 in pfs_spawn_thread (arg=0x41b4f70) at /export/home/pb2/build/sb_0-17571407-1452485714.11/mysqlcom-pro-5.7.11/storage/perfschema/pfs.cc:2192
#18 0x00007f164ba34df5 in start_thread () from /lib64/libpthread.so.0
#19 0x00007f164a70060d in clone () from /lib64/libc.so.6
(gdb)

May have some connection (not established) with http://bugs.mysql.com/bug.php?id=80332

Posted by developer:
 
Noted in 5.8.0 changelog.

Transaction state tracking now avoids a function that is not 8-bit
safe, for enhanced compatibility with nonstandard character sets.