Bug #77809 #08S01 Bad handshake with MySQL 5.7.7-rc-debug-valgrind
Submitted: 23 Jul 2015 6:14 Modified: 25 Jun 2018 21:18
Reporter: Shahriyar Rzayev (OCA) Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: DML Severity:S1 (Critical)
Version:5.7.7-rc OS:CentOS (7)
Assigned to: CPU Architecture:Any

[23 Jul 2015 6:14] Shahriyar Rzayev
Description:
Started MySQL as:

[root@centos7_vm ~]# gdb /opt/mysql/bin/mysqld
(gdb) run --defaults-file=/opt/mysql/my.cnf --basedir=/opt/mysql --datadir=/opt/mysql/datadir --plugin-dir=/opt/mysql/lib/plugin --user=mysql --log-error=/opt/mysql/datadir/centos7_vm.err --pid-file=/opt/mysql/datadir/mysqld-new.pid --socket=/opt/mysql/datadir/mysqld-new.sock --port=3306

Sample Table structure:

create table t2(c1 int primary key);

inserting some data via bash script:

[root@centos7_vm ~]# cat insert.sh
for var in $(seq 1000000)
do
echo "INSERT INTO t2 (c1) VALUES ($var);" | /opt/mysql/bin/mysql -uroot tst --socket=/opt/mysql/datadir/mysqld-new.sock;
done

After some time if you try to cancel using ctrl+c:

[root@centos7_vm ~]# ./insert.sh
^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C

On GDB side:

Program received signal SIGPIPE, Broken pipe.
[Switching to Thread 0x7fffde146700 (LWP 2493)]
0x00007ffff7bcd75b in __libc_send (fd=50, buf=0x7fffc0005e80, n=26, flags=-1) at ../sysdeps/unix/sysv/linux/x86_64/send.c:31
31	  ssize_t result = INLINE_SYSCALL (sendto, 6, fd, buf, n, flags, NULL,

(gdb) bt
#0  0x00007ffff7bcd75b in __libc_send (fd=50, buf=0x7fffc0005e80, n=26, flags=-1) at ../sysdeps/unix/sysv/linux/x86_64/send.c:31
#1  0x0000000001d7f859 in inline_mysql_socket_send (src_file=0x2228550 "/root/mysql-5.7.7-rc/vio/viosocket.c", src_line=201, mysql_socket=..., 
    buf=0x7fffc0005e80, n=26, flags=64) at /root/mysql-5.7.7-rc/include/mysql/psi/mysql_socket.h:781
#2  0x0000000001d80160 in vio_write (vio=0x7fffc0020250, buf=0x7fffc0005e80 "\026", size=26) at /root/mysql-5.7.7-rc/vio/viosocket.c:201
#3  0x00000000014a66cb in net_write_raw_loop (net=0x7fffc0000c80, buf=0x7fffc0005e80 "\026", count=26) at /root/mysql-5.7.7-rc/sql/net_serv.cc:489
#4  0x00000000014a69b0 in net_write_packet (net=0x7fffc0000c80, packet=0x7fffc0005e80 "\026", length=26) at /root/mysql-5.7.7-rc/sql/net_serv.cc:628
#5  0x00000000014a6004 in net_flush (net=0x7fffc0000c80) at /root/mysql-5.7.7-rc/sql/net_serv.cc:218
#6  0x00000000014a6485 in net_write_command (net=0x7fffc0000c80, command=255 '\377', header=0x1ee0a74 "", head_len=0, 
    packet=0x7fffde1458d0 "\023\004#08S01Bad handshake", len=21) at /root/mysql-5.7.7-rc/sql/net_serv.cc:388
#7  0x00000000014bcfc3 in net_send_error_packet (net=0x7fffc0000c80, sql_errno=1043, err=0x7fffc0003550 "Bad handshake", sqlstate=0x7fffc0003750 "08S01", 
    bootstrap=false, client_capabilities=29338125, character_set_results=0x2ba3ea0 <my_charset_utf8_general_ci>) at /root/mysql-5.7.7-rc/sql/protocol.cc:546
#8  0x00000000014bcdea in net_send_error_packet (thd=0x7fffc00009e0, sql_errno=1043, err=0x7fffc0003550 "Bad handshake", sqlstate=0x7fffc0003750 "08S01")
    at /root/mysql-5.7.7-rc/sql/protocol.cc:488
#9  0x00000000014bd49b in Protocol::send_error (this=0x7fffc0000f48, sql_errno=1043, err_msg=0x7fffc0003550 "Bad handshake", sql_state=0x7fffc0003750 "08S01")
    at /root/mysql-5.7.7-rc/sql/protocol.cc:731
#10 0x00000000014bd187 in Protocol::end_statement (this=0x7fffc0000f48) at /root/mysql-5.7.7-rc/sql/protocol.cc:646
#11 0x00000000015340ec in login_connection (thd=0x7fffc00009e0) at /root/mysql-5.7.7-rc/sql/sql_connect.cc:721
#12 0x0000000001534770 in thd_prepare_connection (thd=0x7fffc00009e0) at /root/mysql-5.7.7-rc/sql/sql_connect.cc:857
#13 0x00000000016adcd3 in handle_connection (arg=0x3c96cd0) at /root/mysql-5.7.7-rc/sql/conn_handler/connection_handler_per_thread.cc:291
#14 0x0000000001cd9905 in pfs_spawn_thread (arg=0x3b3b050) at /root/mysql-5.7.7-rc/storage/perfschema/pfs.cc:2147
#15 0x00007ffff7bc6df5 in start_thread (arg=0x7fffde146700) at pthread_create.c:308
#16 0x00007ffff62281ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

On MySQL side you will not be able to select and open new connection:

mysql> select count(*) from t2;
^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C^C

It will hang:

[root@centos7_vm ~]# /opt/mysql/bin/mysql -u root --socket=/opt/mysql/datadir/mysqld-new.sock

How to repeat:
1. Start MySQL 5.7.7-rc-debug-valgrind build
2. Create sample table
3. Try to insert sample data using script
4. Try to cancel script using ctrl+c

Suggested fix:
As i tested only debug build affected.
[23 Jul 2015 6:23] Shahriyar Rzayev
Added  bt full output

Attachment: bt_full_#77809.txt (text/plain), 6.82 KiB.

[16 Apr 2018 4:11] Zhijiang TAO
I am using mysql-connector-cpp, this problem also affected me.
When reuse a long time idle connect, the SIGPIPE caught:

Program received signal SIGPIPE, Broken pipe.
[Switching to Thread 0x7fffecdfa700 (LWP 8582)]
0x00000036c3a0edac in send () from /lib64/libpthread.so.0
(gdb) bt
#0  0x00000036c3a0edac in send () from /lib64/libpthread.so.0
#1  0x00007ffff6ca936b in inline_mysql_socket_send (vio=0x7ffff0007a10, buf=0x7ffff000d610 "\001", size=5)
    at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/include/mysql/psi/mysql_socket.h:781
#2  vio_write (vio=0x7ffff0007a10, buf=0x7ffff000d610 "\001", size=5) at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/vio/viosocket.c:201
#3  0x00007ffff6cee24e in net_write_raw_loop (net=0x7ffff0004c50, packet=0x7ffff000d610 "\001", length=5)
    at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/sql/net_serv.cc:500
#4  net_write_packet (net=0x7ffff0004c50, packet=0x7ffff000d610 "\001", length=5) at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/sql/net_serv.cc:639
#5  0x00007ffff6cee3d3 in net_flush (net=0x7ffff0004c50) at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/sql/net_serv.cc:222
#6  0x00007ffff6cee6f6 in net_write_command (net=<value optimized out>, command=<value optimized out>, header=0x0, head_len=0, packet=0x0, len=0)
    at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/sql/net_serv.cc:401
#7  0x00007ffff6c9e927 in cli_advanced_command (mysql=0x7ffff0004c50, command=COM_PING, header=0x0, header_length=0, arg=0x0, arg_length=0, skip_check=0 '\000', stmt=0x0)
    at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/sql-common/client.c:1253
#8  0x00007ffff6c90526 in mysql_ping (mysql=<value optimized out>) at /export/home/pb2/build/sb_0-22759043-1489824767.95/rpm/BUILD/mysql-5.7.18/mysql-5.7.18/libmysql/libmysql.c:935
#9  0x00007ffff6c8d646 in sql::mysql::NativeAPI::LibmysqlStaticProxy::ping (this=<value optimized out>, mysql=<value optimized out>)
    at /export/home/pb2/build/sb_0-23369517-1494438204.13/mysql-connector-c++-1.1.9/driver/nativeapi/libmysql_static_proxy.cpp:348
#10 0x00007ffff6c8e6c0 in sql::mysql::NativeAPI::MySQL_NativeConnectionWrapper::ping (this=<value optimized out>)
    at /export/home/pb2/build/sb_0-23369517-1494438204.13/mysql-connector-c++-1.1.9/driver/nativeapi/mysql_native_connection_wrapper.cpp:317
#11 0x00007ffff6c4076f in sql::mysql::MySQL_Connection::isValid (this=0x7ffff00052f0)
    at /export/home/pb2/build/sb_0-23369517-1494438204.13/mysql-connector-c++-1.1.9/driver/mysql_connection.cpp:1564
#12 0x00000000005f57ff in SqlConn::sqlconn_execute_query (this=0x7ffff00012b0, sql=
    " SELECT stats.F_partner_id, F_partner_name, F_channel_id, F_channel, F_amount, F_count, F_date  FROM bankpay.t_partner_submit_stats stats, bankpay.t_partner partner, bankpay.t_channel channel  WHERE F"...) at /home/nicol/tiserials/tistat/source/SqlConn.cpp:92
[25 Jun 2018 21:18] Miguel Solorzano
Thank you for the bug report. I couldn't repeat with most recent source server if you have a clue please let me know.

miguel@tikal:~/test/5.7 $ bin/mysql -uroot
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.7.24-debug-valgrind Source distribution 2018-JUN-13

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create database tst;
Query OK, 1 row affected (0,00 sec)

mysql> use tst
Database changed
mysql> create table t2(c1 int primary key);
Query OK, 0 rows affected (0,29 sec)

mysql> exit
Bye
miguel@tikal:~/test/5.7 $ cat insert.sh
for var in $(seq 1000000)
do
echo "INSERT INTO t2 (c1) VALUES ($var);" | /home/miguel/test/5.7/bin/mysql -uroot tst --socket=/tmp/mysql.sock;
done
miguel@tikal:~/test/5.7 $ ./insert.sh
^C^C -- query aborted

miguel@tikal:~/test/5.7 $ bin/mysql -uroot tst
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2352
Server version: 5.7.24-debug-valgrind Source distribution 2018-JUN-13

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select count(*) from t2;
+----------+
| count(*) |
+----------+
|     2711 |
+----------+
1 row in set (0,00 sec)