[MDEV-17092] ERROR: AddressSanitizer: use-after-poison around lock_trx_handle_wait_low Created: 2018-08-29  Updated: 2022-08-24  Resolved: 2020-05-25

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.18
Fix Version/s: 10.5.4, 10.2.33, 10.3.24, 10.4.14

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None
Environment:

Ubuntu 17.04 but most probably unimportant.


Issue Links:
Duplicate
duplicates MDEV-8088 [Draft] Server crashed on KILL QUERY Closed
is duplicated by MDEV-22670 AddressSanitizer: use-after-poison 10... Closed
Relates
relates to MDEV-23328 Server hang due to Galera lock confli... Closed
relates to MDEV-23536 Race condition between KILL and trans... Closed
relates to MDEV-26014 Race condition between KILL and clien... Closed
relates to MDEV-29368 Assertion `trx->mysql_thd == thd' fai... Closed

 Description   

RQG testing with the test conf/mariadb/tables_stress* on 
bb-10.2-marko commit 0aa9db1b4877ed411eae4175c059546fa07faa4f
compiled with ASAN
 
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
#5  0x00007f8f6062737a in __GI_abort () at abort.c:89
#6  0x00007f8f61db9169 in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.3
#7  0x00007f8f61dae06b in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.3
#8  0x00007f8f61da7457 in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.3
#9  0x00007f8f61da7b47 in __asan_report_load1 () from /usr/lib/x86_64-linux-gnu/libasan.so.3
#10 0x000055ad8d70277d in lock_trx_handle_wait_low (trx=0x7f8f55009778)
  at storage/innobase/lock/lock0lock.cc:6926
#11 0x000055ad8d702948 in lock_trx_handle_wait (trx=0x7f8f55009778)
  at storage/innobase/lock/lock0lock.cc:6950
#12 0x000055ad8d5daa5b in innobase_kill_query (thd=0x62a0001e0208)
  at storage/innobase/handler/ha_innodb.cc:5249
#13 0x000055ad8d0f4dc5 in kill_handlerton (thd=0x62a0001e0208, plugin=0x60200002e618, level=0x7f8f2d52d8c4)
   at sql/handler.cc:808
#14 0x000055ad8cb695fc in plugin_foreach_with_mask (thd=0x62a0001e0208, func=0x55ad8d0f4c96 <kill_handlerton(THD*, plugin_ref, void*)>, type=1, state_mask=8, arg=0x7f8f2d52d8c4)
   at sql/sql_plugin.cc:2398
#15 0x000055ad8d0f4e99 in ha_kill_query (thd=0x62a0001e0208, level=THD_ABORT_ASAP)
   at sql/handler.cc:815
#16 0x000055ad8ca7cdbc in THD::awake (this=0x62a0001e0208, state_to_set=KILL_CONNECTION_HARD)
   at sql/sql_class.cc:1710
#17 0x000055ad8cb4dce7 in kill_one_thread (thd=0x62a0001bc208, id=135, kill_signal=KILL_QUERY_HARD, type=KILL_TYPE_ID)
   at sql/sql_parse.cc:8897
#18 0x000055ad8cb4e669 in sql_kill (thd=0x62a0001bc208, id=135, state=KILL_QUERY_HARD, type=KILL_TYPE_ID)
   at sql/sql_parse.cc:9003
#19 0x000055ad8cb38361 in mysql_execute_command (thd=0x62a0001bc208)
   at sql/sql_parse.cc:5472
#20 0x000055ad8cb47f28 in mysql_parse (thd=0x62a0001bc208, rawbuf=0x62b0000c4220 "KILL QUERY @kill_id  /* E_R Thread31 QNO 771 CON_ID 288 */", length=58, parser_state=0x7f8f2d52f560, is_com_multi=false, is_next_command=false)
   at sql/sql_parse.cc:8009
#21 0x000055ad8cb22c46 in dispatch_command (command=COM_QUERY, thd=0x62a0001bc208, packet=0x629003886209 " KILL QUERY @kill_id  /* E_R Thread31 QNO 771 CON_ID 288 */ ", packet_length=60, is_com_multi=false, is_next_command=false)
   at sql/sql_parse.cc:1824
#22 0x000055ad8cb1fce7 in do_command (thd=0x62a0001bc208)
   at sql/sql_parse.cc:1377
#23 0x000055ad8ce50fc2 in do_handle_one_connection (connect=0x60800000b2a8)
   at sql/sql_connect.cc:1335
#24 0x000055ad8ce509a7 in handle_one_connection (arg=0x60800000b2a8)
   at sql/sql_connect.cc:1241
#25 0x00007f8f612666da in start_thread (arg=0x7f8f2d531700) at pthread_create.c:456
 
SUMMARY: AddressSanitizer: use-after-poison /work_m/bb-10.2-marko/storage/innobase/lock/lock0lock.cc:6926 in lock_trx_handle_wait_low
Shadow bytes around the buggy address:
  0x0ff26a9f92b0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
  0x0ff26a9f92c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
  0x0ff26a9f92d0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
  0x0ff26a9f92e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
  0x0ff26a9f92f0: 00 00 00 00 00 00 00 00 00 00 00 00 00 f7 f7 f7 
=>0x0ff26a9f9300: f7 f7 f7 f7 f7 f7 f7 f7 f7[f7]f7 f7 f7 f7 f7 f7 
  0x0ff26a9f9310: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 
  0x0ff26a9f9320: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 
  0x0ff26a9f9330: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 
  0x0ff26a9f9340: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 
  0x0ff26a9f9350: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7



 Comments   
Comment by Marko Mäkelä [ 2018-08-29 ]

I believe that this is a race condition between innobase_kill_query() and trx_free(). The thread associated with the thd->real_id is idle outside InnoDB, so it must have been freed the transaction object already:

#3  0x000055ad8c93443a in cache_thread (thd=0x62a0001e0208)
    at /work_m/bb-10.2-marko/sql/mysqld.cc:2972
#4  0x000055ad8c9349e0 in one_thread_per_connection_end (thd=0x62a0001e0208, 
    put_in_cache=true) at /work_m/bb-10.2-marko/sql/mysqld.cc:3061

Also, thd_to_trx() would now return NULL to innobase_kill_query() in the core dump:

(gdb) p thd->ha_data[innodb_hton_ptr->slot].ha_ptr
$7 = (void *) 0x0

It seems to me that in 10.2, we should probably acquire trx->mutex and trx_sys->mutex after invoking thd_to_trx(), then recheck thd_to_trx(), and finally acquire lock_sys->mutex.

In 10.3, trx_sys->mutex does not exist any more, so we must skip acquiring it. Perhaps we should do something smart about trx->id or other fields instead? trx_free() is not acquiring any mutex in 10.3.

Acquiring trx->mutex could trigger use-after-poison, so perhaps we should rewrite the poisoning so that it would always leave the mutex alone?

	trx_pools->mem_free(trx);
	/* Unpoison the memory for innodb_monitor_set_option;
	it is operating also on the freed transaction objects. */
	MEM_UNDEFINED(&trx->mutex, sizeof trx->mutex);

Comment by Matthias Leich [ 2018-08-30 ]

Shrinked YY grammar for showing what the test does.
query:
    CREATE TABLE IF NOT EXISTS t1 (col1 INT) ENGINE = InnoDB |
    DROP TABLE IF EXISTS t1 |
    SELECT MIN(processlist_id) INTO @kill_id FROM test . rqg_sessions WHERE rqg_id <> _thread_id ; KILL CONNECTION @kill_id ;
 
thread_connect:
    REPLACE INTO test . rqg_sessions SET rqg_id = _thread_id , processlist_id = CONNECTION_ID(); COMMIT ;
 
sql_script run before YY grammar processing:
CREATE TABLE IF NOT EXISTS test . rqg_sessions (rqg_id BIGINT, processlist_id BIGINT, pid BIGINT, connect_time INT, PRIMARY KEY(rqg_id)) ENGINE = MyISAM ;

Comment by Marko Mäkelä [ 2020-05-25 ]

I debugged this a bit further in a short rr replay trace. Based on a disassembly of the code that called __asan_report_load1(), I found out the address of the ASAN poison bits and set an access watchpoint:

p &((char*)0x7fff8000)[((ulint)&trx.lock.was_chosen_as_deadlock_victim) / 8]

Armed with awatch, I narrowed the problem to the following area:

10.2

Thread 1 hit Breakpoint 6, innobase_kill_query (thd=0x62a0001fe208)
    at /home/mleich/10.2/storage/innobase/handler/ha_innodb.cc:5190
5190	{
(rr) 
Continuing.
[Switching to Thread 98211.100335]Thread 35 hit Breakpoint 5, innobase_close_connection (hton=0x614000001248, 
    thd=0x62a0001fe208)
    at /home/mleich/10.2/storage/innobase/handler/ha_innodb.cc:5177
5177				innobase_rollback_trx(trx);

Here, KILL is invoked slightly before the client disconnects. The innobase_close_connection() would invoke trx_free(), and this would happen before lock_trx_handle_wait_low() dereferences the trx->lock.was_chosen_as_deadlock_victim.

I believe that the correct fix is to check somewhere in innobase_kill_query() that the trx actually is registered in the system. This bug is somewhat similar to MDEV-15326.

Comment by Marko Mäkelä [ 2020-05-25 ]

I believe that in MariaDB 10.1 and MySQL 5.6 and earlier, this race condition between KILL and client disconnect may cause memory corruption, because free() would be invoked on the trx_t object.

A side effect of this fix is that transactions in the XA PREPARE state will be immune to the KILL statement.

Comment by Sergey Vojtovich [ 2020-06-19 ]

Sad to see 5530a93f4. My comments are based on 10.5.

First of all it doesn't really fix the broader problem, but rather silences symptoms.

+  if (trx_t* trx= thd_to_trx(thd))
+  {
 ---- THE GAP ---
+    lock_mutex_enter();
+    trx_sys_mutex_enter();

While going through THE GAP concurrent thread may release (or even free?) trx back to trx_pool and another thread may reuse it. In effect it may break innocent transaction, even worse it may break innocent transaction of another user which it is not permitted to kill.

Secondly, trx is found via server_threads/thd->ha_data and not via trx_sys.trx_list. The latter is officially protected by trx_sys.mutex, the former is not. The fact that trx_sys.mutex helps here is pure coincidence and can in no way be considered as meaningful design.

Thirdly, the bug is in the server and not in InnoDB. Consider the following...

KILL thread:

rdlock(server_threads.rwlock);
thd= server_threads.find();
lock(thd->LOCK_thd_kill);
unlock(server_thread.rwlock);
thd->awake()/.../innobase_kill_query();
unlock(thd->LOCK_thd_kill);

InnoDB thd->ha_data is reset only upon disconnect, in ha_close_connection(). Relevant pseudo code:

wrlock(server_thread.rwlock);
server_threads.erase(thd);
unlock(server_thread.rwlock);
thd->free_connection()/ha_close_connection()/innobase_close_connection()/trx_free()

If you look carefully into the above, you can conclude that thd->free_connection() can be called concurrently with KILL/thd->awake(). Which is the bug. And it is partially fixed in THD::~THD(), that is destructor waits for KILL completion:

  /*
    Other threads may have a lock on LOCK_thd_kill to ensure that this
    THD is not deleted while they access it. The following mutex_lock
    ensures that no one else is using this THD and it's now safe to delete
  */
  if (WSREP_NNULL(this)) mysql_mutex_lock(&LOCK_thd_data);
  mysql_mutex_lock(&LOCK_thd_kill);
  mysql_mutex_unlock(&LOCK_thd_kill);
  if (WSREP_NNULL(this)) mysql_mutex_unlock(&LOCK_thd_data);

However this only works when THD is actually destroyed, whereas it must've been called when THD is released to the thread cache.

If the above empty critical section would've been moved to thd->free_connection(), the whole 5530a93f4 would not be needed.

Comment by Sergey Vojtovich [ 2020-06-21 ]

I must revoke my first claim because:

  • trx objects seem to be freed only on shutdown
  • even though another trx->mysql_thd == thd binding is not impossible, it can't be established while we're holding thd->LOCK_thd_kill.

So there seem to be no practical issues with the fix, despite absence of meaningful design: the fact that KILL may not be completed up through victim THD being released to thread cache/stay cached/re-initialised for another connection sounds fragile.

Comment by Marko Mäkelä [ 2020-07-28 ]

svoj, sorry, I only now noticed your comments. I agree that the homebrew memory pool is a somewhat unfortunate design (which MariaDB inherited from MySQL). We might want to revise it at some point. Maybe trx_t should be a part of the InnoDB data of THD. Maybe removing unnecessary bloat from it would fix any memory allocator overhead.

I am not proud of my solution, but I did not want to touch any code outside InnoDB. Do you have a better solution in mind? (Note: MDEV-21910 may have changed this flow again, without fixing the reported issue yet.)

Comment by Sergey Vojtovich [ 2020-07-28 ]

@marko, yes, there's better solution that I've explained in my previous comment. InnoDB code should stay intact (as if fix for this bug was not pushed) and the real problem should be fixed in the server.

I'm concerned (as far as I can be in the current situation) that trx_sys.mutex (or whatever it is called now) is abused for unrelated matters.

A healthy code that we've designed back in May (with Eugene IIRC) was supposed to encapsulate trx_sys.trx_list and trx_sys.mutex so that the latter exclusively protects the former. Now this code looks less healthy because it got infected by another sick code.

Comment by Marko Mäkelä [ 2020-08-22 ]

I filed MDEV-23536 for the better suggestion.

Generated at Thu Feb 08 08:33:51 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.