MySQL Bugs: #68244: lock_rec_validate_page() may dereference a pointer to a freed lock

Bug #68244	lock_rec_validate_page() may dereference a pointer to a freed lock
Submitted:	1 Feb 2013 13:24	Modified:	6 Jun 2013 15:13
Reporter:	Laurynas Biveinis (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.5	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	innodb, valgrind

Description:
Credit goes to Roel at https://bugs.launchpad.net/percona-server/+bug/1111119

We have encountered this Valgrind error on Percona Server, which seems to apply to MySQL as well:

==12667== Invalid read of size 8
==12667== at 0x93D473: lock_rec_block_validate (lock0lock.c:4969)
==12667== by 0x93D8D0: lock_print_info_all_transactions (lock0lock.c:5113)
==12667== by 0x862BAC: srv_printf_innodb_monitor (srv0srv.c:2263)
==12667== by 0x862DA5: srv_monitor_thread (srv0srv.c:2580)
==12667== by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
==12667== by 0x19FCA6FF: ???
==12667== Address 0x16220c48 is 664 bytes inside a block of size 872 free'd
==12667== at 0x4C2695D: free (vg_replace_malloc.c:366)
==12667== by 0x952579: mem_area_free (mem0pool.c:519)
==12667== by 0x951465: mem_heap_block_free (mem0mem.c:511)
==12667== by 0x9405B6: lock_release_off_kernel (mem0mem.ic:287)
==12667== by 0x88A392: trx_commit_off_kernel (trx0trx.c:1044)
...

lock0lock.c:4969 is 

			lock_rec_queue_validate(block, rec, lock->index,
						offsets);

in lock_rec_block_validate(). It is surrounded by lock_mutex_exit_kernel()/lock_mutex_enter_kernel(). Thus, the lock might become invalid between lock_mutex_exit_kernel() and lock_rec_queue_validate(), resulting in bad lock->index read and the Valgrind error above. In the case the freed memory is already overwritten, then this could even result in a crash in lock_req_queue_validate (ut_a(lock->index == index)).

5.1 seems to be OK because it saves the lock->index pointer before releasing the mutex and lock_rec_queue_validate() seems to be able to handle the disappeared lock just fine. 5.6 seems to be OK because there is no mutex release. 5.5 stopped being OK at revno 3394.1.3, where it seems to be an unrelated minor change to remove some local vars.

revno: 3394.1.3
committer: Marko Mäkelä <marko.makela@oracle.com>
branch nick: mysql-5.5
timestamp: Tue 2011-05-24 14:11:21 +0300
message:
  Bug#12584374 LOCK_VALIDATE TRIPS ASSERTION !BLOCK->PAGE.FILE_PAGE_WAS_FREED

How to repeat:
If code analysis is not enough, then Roel can upload the run that hit this on Percona Server.

Suggested fix:
Copy index from lock->index while the lock is held and pass it instead.

I can confirm seeing this valgrind error on 5.5.31 today. I generic DML testcase with innodb_lock_monitor enabled.

Thread 61:
Invalid read of size 8
at: lock_rec_validate_page (lock0lock.c:5048)
by: lock_rec_block_validate (lock0lock.c:5139)
by: lock_validate (lock0lock.c:5192)
by: lock_print_info_all_transactions (lock0lock.c:4663)
by: srv_printf_innodb_monitor (srv0srv.c:1900)
by: innodb_show_status (ha_innodb.cc:9458)
by: innobase_show_status (ha_innodb.cc:9704)
by: ha_show_status (handler.cc:4916)
by: mysql_execute_command (sql_parse.cc:2330)
by: mysql_parse (sql_parse.cc:5627)
by: dispatch_command (sql_parse.cc:1037)
by: do_command (sql_parse.cc:773)
by: do_handle_one_connection (sql_connect.cc:853)
by: handle_one_connection (sql_connect.cc:772)
by: start_thread (pthread_create.c:309)
by: clone (clone.S:115)
 Address 0x149769a0 is 320 bytes inside a block of size 376 free'd
at: free (vg_replace_malloc.c:446)
by: mem_area_free (mem0pool.c:519)
by: mem_heap_block_free (mem0mem.c:511)
by: mem_heap_free_func (mem0mem.ic:500)
by: trx_free (trx0trx.c:323)
by: trx_free_for_mysql (trx0trx.c:409)
by: innobase_close_connection(handlerton*, THD*) (ha_innodb.cc:3049)
by: closecon_handlerton (handler.cc:725)
by: plugin_foreach_with_mask (sql_plugin.cc:2024)
by: ha_close_connection(handler.cc:739)
by: THD::~THD (sql_class.cc:1380)
by: THD::~THD (sql_class.cc:1407)
by: delete_thd (mysqld.cc:2160)
by: unlink_thd (mysqld.cc:2189)
by: one_thread_per_connection_end(THD*, bool) (mysqld.cc:2293)
by: do_handle_one_connection(THD*) (sql_connect.cc:860)
by: handle_one_connection (sql_connect.cc:772)
by: start_thread (pthread_create.c:309)
by: clone (clone.S:115)

Same testcase hits another valgrind error:

Conditional jump or move depends on uninitialised value(s)
at 0x926995: rec_offs_validate (rem0rec.ic:971)
by 0x9FA2B3: lock_rec_queue_validate (lock0lock.c:4839)
by 0x9FAAD2: lock_rec_validate_page (lock0lock.c:5048)
by 0x9FAD60: lock_rec_block_validate (lock0lock.c:5139)
by 0x9FAE97: lock_validate (lock0lock.c:5192)
by 0x9F9C8A: lock_print_info_all_transactions (lock0lock.c:4663)
by 0x94D2C7: srv_printf_innodb_monitor (srv0srv.c:1900)
by 0x917D44: innodb_show_status (ha_innodb.cc:9458)
by 0x91877F: innobase_show_status (ha_innodb.cc:9704)
by 0x76D801: ha_show_status (handler.cc:4916)
by 0x5FA839: mysql_execute_command (sql_parse.cc:2330)
by 0x6031A5: mysql_parse (sql_parse.cc:5627)
by 0x5F7802: dispatch_command (sql_parse.cc:1037)
by 0x5F6AB4: do_command (sql_parse.cc:773)
by 0x6DC3F7: do_handle_one_connection(THD*) (sql_connect.cc:853)
by 0x6DBED6: handle_one_connection (sql_connect.cc:772)
by 0x3679C07D13: start_thread (pthread_create.c:309)
by 0x36798F168C: clone (clone.S:115)
==31577==
971     if (index) {
(gdb) p index
$1 = (const dict_index_t *) 0x152fbfc8

And a few other possibly related ones (seen directly after the first one)

Conditional jump or move depends on uninitialised value(s)
   at 0x95CC5F: dict_index_get_n_unique_in_tree (dict0dict.ic:588)
   by 0x9609DA: rec_offs_validate (rem0rec.ic:974)
   by 0x966A2D: lock_rec_queue_validate (lock0lock.c:4760)
   by 0x9674C8: lock_rec_block_validate (lock0lock.c:4969)
   by 0x968FAB: lock_print_info_all_transactions (lock0lock.c:5113)
   by 0x880D10: srv_printf_innodb_monitor (srv0srv.c:2267)
   by 0x880F09: srv_monitor_thread (srv0srv.c:2584)
   by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x199CA6FF: ???

Conditional jump or move depends on uninitialised value(s)
   at 0x9609B4: rec_offs_validate (rem0rec.ic:973)
   by 0x966A2D: lock_rec_queue_validate (lock0lock.c:4760)
   by 0x9674C8: lock_rec_block_validate (lock0lock.c:4969)
   by 0x968FAB: lock_print_info_all_transactions (lock0lock.c:5113)
   by 0x880D10: srv_printf_innodb_monitor (srv0srv.c:2267)
   by 0x880F09: srv_monitor_thread (srv0srv.c:2584)
   by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x199CA6FF: ???

Conditional jump or move depends on uninitialised value(s)
   at 0x95C9B8: dict_index_is_clust (dict0dict.ic:250)
   by 0x95CCCF: dict_index_get_n_unique_in_tree (dict0dict.ic:592)
   by 0x9609DA: rec_offs_validate (rem0rec.ic:974)
   by 0x966A2D: lock_rec_queue_validate (lock0lock.c:4760)
   by 0x9674C8: lock_rec_block_validate (lock0lock.c:4969)
   by 0x968FAB: lock_print_info_all_transactions (lock0lock.c:5113)
   by 0x880D10: srv_printf_innodb_monitor (srv0srv.c:2267)
   by 0x880F09: srv_monitor_thread (srv0srv.c:2584)
   by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x199CA6FF: ???

Use of uninitialised value of size 8
   at 0x95C9D7: dict_index_is_clust (dict0dict.ic:251)
   by 0x95CCCF: dict_index_get_n_unique_in_tree (dict0dict.ic:592)
   by 0x9609DA: rec_offs_validate (rem0rec.ic:974)
   by 0x966A2D: lock_rec_queue_validate (lock0lock.c:4760)
   by 0x9674C8: lock_rec_block_validate (lock0lock.c:4969)
   by 0x968FAB: lock_print_info_all_transactions (lock0lock.c:5113)
   by 0x880D10: srv_printf_innodb_monitor (srv0srv.c:2267)
   by 0x880F09: srv_monitor_thread (srv0srv.c:2584)
   by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x199CA6FF: ???

Use of uninitialised value of size 8
   at 0x95CCD5: dict_index_get_n_unique_in_tree (dict0dict.ic:573)
   by 0x9609DA: rec_offs_validate (rem0rec.ic:974)
   by 0x966A2D: lock_rec_queue_validate (lock0lock.c:4760)
   by 0x9674C8: lock_rec_block_validate (lock0lock.c:4969)
   by 0x968FAB: lock_print_info_all_transactions (lock0lock.c:5113)
   by 0x880D10: srv_printf_innodb_monitor (srv0srv.c:2267)
   by 0x880F09: srv_monitor_thread (srv0srv.c:2584)
   by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x199CA6FF: ???

Use of uninitialised value of size 8
   at 0x9609DB: rec_offs_validate (dict0dict.ic:551)
   by 0x966A2D: lock_rec_queue_validate (lock0lock.c:4760)
   by 0x9674C8: lock_rec_block_validate (lock0lock.c:4969)
   by 0x968FAB: lock_print_info_all_transactions (lock0lock.c:5113)
   by 0x880D10: srv_printf_innodb_monitor (srv0srv.c:2267)
   by 0x880F09: srv_monitor_thread (srv0srv.c:2584)
   by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x199CA6FF: ???

Conditional jump or move depends on uninitialised value(s)
   at 0x966C31: lock_rec_queue_validate (lock0lock.c:4799)
   by 0x9674C8: lock_rec_block_validate (lock0lock.c:4969)
   by 0x968FAB: lock_print_info_all_transactions (lock0lock.c:5113)
   by 0x880D10: srv_printf_innodb_monitor (srv0srv.c:2267)
   by 0x880F09: srv_monitor_thread (srv0srv.c:2584)
   by 0x4E34850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x199CA6FF: ???

etc.

Full error log with all Valgrind warnings

Attachment: 13213_master.err (application/octet-stream, text), 788.36 KiB.

run mysqld in valgrind, then execute this testcase against it.

Attachment: bug68244.c (text/plain), 10.48 KiB.

Shane: great, as always. Thanks!

It took nearly an hour for this last testcase to hit a problem on my machine. So when it did, I just uploaded it. It does need improvement..

Added changelog entry for 5.5.32, 5.6.12, 5.7.2:

"When calling the "lock_rec_block_validate()" function after releasing the
kernel mutex, there is a chance the lock might be invalid and result in a
Valgrind error due to an invalid read on "lock->index". This fix copies
the "lock->index" when the kernel mutex is being held and passes the
"lock->index" to "lock_rec_block_validate()".

5.6$ bzr log -r 2875.437.8
------------------------------------------------------------
revno: 2875.437.8
committer: Aditya A <aditya.a@oracle.com>
branch nick: mysql-5.5
timestamp: Wed 2013-03-13 11:43:21 +0530
message:
  Bug#16268289 LOCK_REC_VALIDATE_PAGE() MAY DEREFERENCE A POINTER TO A
               FREED LOCK
  
  ANALYIS
  -------
  
  In 5.5 code the lock_rec_block_validate() is called after releasing
  the kernel mutex. There is a chance that the lock might be invalid so,
  we are getting the valgrind error on invalid read on lock->index.
  
  FIX
  ---
  
  Fix would be to copy the lock->index when we are holding the kernel mutex 
  and then pass it to the lock_rec_block_validate(). This implementation
  is present in 5.1 code.  
  
  [ Approved by sunny rb.no.oracle.com/rb/r/2152/ ]