Valgrind: Use-after-free in one_thread_per_connection_end

[Raghavendra D Prabhu]

http://jenkins.percona.com/job/PXC-5.5-mrandgen/189/BTYPE=release,Host=pxc-rqg/artifact/results-189/trial3.log/*view*/

========================
# 2014-04-21T09:55:48 [7004] Valgrind: Issues detected (error count: 0). Relevant messages from log file '/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/189/tmp.a2GQnNiF5W/current1_3/node0/data/../mysql.err':
# 2014-04-21T09:55:48 [7004] ==00:00:00:00.000 14609== Memcheck, a memory error detector
# 2014-04-21T09:55:48 [7004] ==00:00:00:00.000 14609== Copyright (C) 2002-2012, and GNU GPL'd, by Julian Seward et al.
# 2014-04-21T09:55:48 [7004] ==00:00:00:00.000 14609== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info
# 2014-04-21T09:55:48 [7004] ==00:00:00:00.000 14609== Command: /rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/Percona-XtraDB-Cluster-5.5.36-25.10.724.Linux.x86_64/bin/mysqld --no-defaults --basedir=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/Percona-XtraDB-Cluster-5.5.36-25.10.724.Linux.x86_64 --datadir=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/189/tmp.a2GQnNiF5W/current1_3/node0/data --lc-messages-dir=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/Percona-XtraDB-Cluster-5.5.36-25.10.724.Linux.x86_64/share --character-sets-dir=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/Percona-XtraDB-Cluster-5.5.36-25.10.724.Linux.x86_64/share/charsets --tmpdir=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/189/tmp.a2GQnNiF5W/current1_3/node0/tmp --core-file --max-allowed-packet=128Mb --port=12120 --socket=/tmp/RQGmysql.12120.sock --pid-file=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/189/tmp.a2GQnNiF5W/current1_3/node0/mysql.pid --general-log --general-log-file=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/189/tmp.a2GQnNiF5W/current1_3/node0/mysql.log --wsrep_sst_method=rsync --innodb_autoinc_lock_mode=2 --default-storage-engine=InnoDB --binlog-format=row --wsrep_node_incoming_address=127.0.0.1 --wsrep_node_address=127.0.0.1 --wsrep_cluster_address=gcomm://?gmcast.listen_addr=tcp://127.0.0.1:5197&pc.ignore_sb=true --wsrep_sst_receive_address=127.0.0.1:5200 --skip-performance-schema --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --innodb-buffer-pool-populate --innodb_flush_method=O_DIRECT --innodb_change_buffering=all --innodb_lock_wait_timeout=5 --lock_wait_timeout=1500 --innodb_adaptive_hash_index_partitions=4 --wsrep_retry_autocommit=1 --wsrep_slave_threads=8 --wsrep_causal_reads=OFF --innodb_flush_log_at_trx_commit=2 --transaction-isolation=REPEATABLE-READ --log_slave_updates --sync_binlog=1 --log-bin=mysql-bin --binlog_format=ROW --wsrep-provider=/rqg/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/pxc-rqg/Percona-XtraDB-Cluster-5.5.36-25.10.724.Linux.x86_64/lib/libgalera_smm.so
# 2014-04-21T09:55:48 [7004] ==00:00:00:00.001 14609==
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== Thread 32:
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== Invalid read of size 1
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== at 0x522F5F: one_thread_per_connection_end(THD*, bool) (mysqld.cc:2437)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x642BEB: do_handle_one_connection(THD*) (sql_connect.cc:1448)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x642E20: handle_one_connection (sql_connect.cc:1338)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x5037850: start_thread (in /lib64/libpthread-2.12.so)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x691094C: clone (in /lib64/libc-2.12.so)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== Address 0x2cca9ee8 is 7,064 bytes inside a block of size 13,136 free'd
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== at 0x4C273F0: free (vg_replace_malloc.c:446)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x522EF3: unlink_thd(THD*) (mysqld.cc:2331)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x522F59: one_thread_per_connection_end(THD*, bool) (mysqld.cc:2435)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x642BEB: do_handle_one_connection(THD*) (sql_connect.cc:1448)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x642E20: handle_one_connection (sql_connect.cc:1338)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x5037850: start_thread (in /lib64/libpthread-2.12.so)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609== by 0x691094C: clone (in /lib64/libc-2.12.so)
# 2014-04-21T09:55:48 [7004] ==00:00:00:30.140 14609==
# 2014-04-21T09:55:48 [7004] Shutting down server on port 12121 via DBI...
# 2014-04-21T09:55:48 [7004] Shutting down server with pid 17529 with SIGTERM...
# 2014-04-21T09:55:48 [7004] Waiting for mysqld with pid 17529 to terminate...
+++++++++
# 2014-04-21T09:55:57 [7004] ... waiting complete. Just in case, killing server with pid 17529 with SIGKILL ...
# 2014-04-21T09:55:57 [7004] Shutting down server on port 12120 via DBI...
# 2014-04-21T09:55:57 [7004] Shutting down server with pid 14609 with SIGTERM...
# 2014-04-21T09:55:57 [7004] Waiting for mysqld with pid 14609 to terminate...
================================================

This is happening because:

  DBUG_ENTER("one_thread_per_connection_end");
  unlink_thd(thd);
#ifdef WITH_WSREP
  if (put_in_cache && !thd->wsrep_applier)
  ----------------------------------> thd is already free-d here
  in unlink_thd.
#else
  if (put_in_cache)
#endif /* WITH_WSREP */
    put_in_cache= cache_thread();
  mysql_mutex_unlock(&LOCK_thread_count);

[Raghavendra D Prabhu (raghavendra-prabhu)]

Also seen in

http://jenkins.percona.com/job/PXC-5.5-mrandgen/189/BTYPE=release,Host=pxc-rqg/artifact/results-189/trial21.log/*view*/
http://jenkins.percona.com/job/PXC-5.5-mrandgen/189/BTYPE=release,Host=pxc-rqg/artifact/results-189/trial22.log/*view*/

[Raghavendra D Prabhu (raghavendra-prabhu)]

Introduced in fix of https://bugs.launchpad.net/codership-mysql/+bug/1208493

------------------------------------------------------------
revno: 3936
committer: Seppo Jaakola <email address hidden>
branch nick: wsrep-5.5
timestamp: Tue 2014-01-07 23:49:58 +0200
message:
  References lp:1208493 -
  - Releasing LOCK_global_system_variables for wsrep_stop_replication after cluster address update
  - counting applier threads by wsrep_running_threads variable, which is accessed under LOCK_thread_count mutex
  - avoiding caching of applier threads
modified:
  sql/mysqld.cc
  sql/wsrep_var.cc

[Alex Yurchenko (ayurchen)]

pushed fix in http://bazaar.launchpad.net/~codership/codership-mysql/wsrep-5.5/revision/3988

[Raghavendra D Prabhu (raghavendra-prabhu)]

Doesn't affect 5.6.

[Nirbhay Choubey (nirbhay)]

Correct like for the fix : http://bazaar.launchpad.net/~codership/codership-mysql/wsrep-5.5/revision/3987

[Shahriyar Rzayev (rzayev-sehriyar)]

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