[MDEV-28887] Unexpected WARN_VERS_PART_FULL or ASAN errors in maria_status Created: 2022-06-19  Updated: 2024-02-02

Status: Stalled
Project: MariaDB Server
Component/s: Storage Engine - Aria, Triggers, Versioned Tables
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Unresolved Votes: 0
Labels: regression


 Description    

--source include/have_partition.inc
 
 
 
CREATE TABLE t1 (a INT) ENGINE=Aria WITH SYSTEM VERSIONING PARTITION BY system_time LIMIT 100 (PARTITION p0 HISTORY, PARTITION pn CURRENT);
 
CREATE TABLE t2 (b INT);
 
INSERT INTO t2 VALUES (1);
 
CREATE TRIGGER tr BEFORE UPDATE ON t2 FOR EACH ROW INSERT INTO t1 VALUES (1);
 
 
 
UPDATE t2 SET b = 4;
 
 
 
# Cleanup
 
DROP TABLE t2, t1;

10.3 be99d0dd

 
UPDATE t2 SET b = 4;
 
Warnings:
 
Warning	4114	Versioned table `test`.`t1`: partition `p0` is full, add more HISTORY partitions

10.3 be99d0dd ASAN

 
==1852723==ERROR: AddressSanitizer: heap-use-after-free on address 0x60d00000ac98 at pc 0x5650ef04045b bp 0x7f38b6bd9bf0 sp 0x7f38b6bd9be8
 
READ of size 8 at 0x60d00000ac98 thread T5
 
    #0 0x5650ef04045a in maria_status /data/src/10.3/storage/maria/ma_info.c:63
 
    #1 0x5650ef064f0d in ha_maria::info(unsigned int) /data/src/10.3/storage/maria/ha_maria.cc:2454
 
    #2 0x5650ee0aef13 in ha_partition::part_records(partition_element*) /data/src/10.3/sql/ha_partition.h:1612
 
    #3 0x5650ee0aef13 in partition_info::vers_check_limit(THD*) /data/src/10.3/sql/partition_info.cc:911
 
    #4 0x5650edc659c4 in close_thread_tables(THD*) /data/src/10.3/sql/sql_base.cc:757
 
    #5 0x5650eddb11d7 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:6160
 
    #6 0x5650eddc3637 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7870
 
    #7 0x5650eddc8179 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1852
 
    #8 0x5650eddcdf1d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1398
 
    #9 0x5650ee0ebc96 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #10 0x5650ee0ec4fa in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #11 0x5650ef331e14 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
 
    #12 0x7f38c15feea6 in start_thread nptl/pthread_create.c:477
 
    #13 0x7f38c152edee in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xfddee)
 
 
 
0x60d00000ac98 is located 24 bytes inside of 144-byte region [0x60d00000ac80,0x60d00000ad10)
 
freed by thread T5 here:
 
    #0 0x7f38c1ea0b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123
 
    #1 0x5650ef046209 in _ma_trnman_end_trans_hook /data/src/10.3/storage/maria/ma_state.c:551
 
    #2 0x5650ef077ac0 in trnman_end_trn /data/src/10.3/storage/maria/trnman.c:474
 
    #3 0x5650ef0ca451 in ma_commit /data/src/10.3/storage/maria/ma_commit.c:73
 
    #4 0x5650ef07670e in ha_maria::implicit_commit(THD*, bool) /data/src/10.3/storage/maria/ha_maria.cc:2865
 
    #5 0x5650eddb11cd in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:6155
 
    #6 0x5650eddc3637 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7870
 
    #7 0x5650eddc8179 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1852
 
    #8 0x5650eddcdf1d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1398
 
    #9 0x5650ee0ebc96 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #10 0x5650ee0ec4fa in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #11 0x5650ef331e14 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
 
    #12 0x7f38c15feea6 in start_thread nptl/pthread_create.c:477
 
 
 
previously allocated by thread T5 here:
 
    #0 0x7f38c1ea0e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
 
    #1 0x5650ef402e62 in my_malloc /data/src/10.3/mysys/my_malloc.c:101
 
    #2 0x5650ef043523 in _ma_setup_live_state /data/src/10.3/storage/maria/ma_state.c:81
 
    #3 0x5650ef413e99 in thr_multi_lock /data/src/10.3/mysys/thr_lock.c:1323
 
    #4 0x5650ee7a0c17 in mysql_lock_tables(THD*, st_mysql_lock*, unsigned int) /data/src/10.3/sql/lock.cc:347
 
    #5 0x5650ee7a2d75 in mysql_lock_tables(THD*, TABLE**, unsigned int, unsigned int) /data/src/10.3/sql/lock.cc:299
 
    #6 0x5650edc7263c in lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) /data/src/10.3/sql/sql_base.cc:5370
 
    #7 0x5650ee014051 in mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, bool, unsigned long long*, unsigned long long*) /data/src/10.3/sql/sql_update.cc:372
 
    #8 0x5650eddb73b1 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:4343
 
    #9 0x5650eddc3637 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7870
 
    #10 0x5650eddc8179 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1852
 
    #11 0x5650eddcdf1d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1398
 
    #12 0x5650ee0ebc96 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #13 0x5650ee0ec4fa in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #14 0x5650ef331e14 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
 
    #15 0x7f38c15feea6 in start_thread nptl/pthread_create.c:477
 
 
 
Thread T5 created by T0 here:
 
    #0 0x7f38c1e4c2a2 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:214
 
    #1 0x5650ef33646a in spawn_thread_v1 /data/src/10.3/storage/perfschema/pfs.cc:1919
 
    #2 0x5650edb5af9b in inline_mysql_thread_create /data/src/10.3/include/mysql/psi/mysql_thread.h:1275
 
    #3 0x5650edb5af9b in create_thread_to_handle_connection(CONNECT*) /data/src/10.3/sql/mysqld.cc:6668
 
    #4 0x5650edb6b2ad in create_new_thread /data/src/10.3/sql/mysqld.cc:6738
 
    #5 0x5650edb6b2ad in handle_connections_sockets() /data/src/10.3/sql/mysqld.cc:6996
 
    #6 0x5650edb6d255 in mysqld_main(int, char**) /data/src/10.3/sql/mysqld.cc:6290
 
    #7 0x7f38c1457d09 in __libc_start_main ../csu/libc-start.c:308
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.3/storage/maria/ma_info.c:63 in maria_status
 
Shadow bytes around the buggy address:
 
  0x0c1a7fff9540: fa fa 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c1a7fff9550: 00 00 00 fa fa fa fa fa fa fa fa fa 00 00 00 00
 
  0x0c1a7fff9560: 00 00 00 00 00 00 00 00 00 00 00 00 00 fa fa fa
 
  0x0c1a7fff9570: fa fa fa fa fa fa 00 00 00 00 00 00 00 00 00 00
 
  0x0c1a7fff9580: 00 00 00 00 00 00 00 fa fa fa fa fa fa fa fa fa
 
=>0x0c1a7fff9590: fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c1a7fff95a0: fd fd fa fa fa fa fa fa fa fa fd fd fd fd fd fd
 
  0x0c1a7fff95b0: fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa fa
 
  0x0c1a7fff95c0: fa fa fa fa fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c1a7fff95d0: fd fd fd fd fd fa fa fa fa fa fa fa fa fa fd fd
 
  0x0c1a7fff95e0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fa
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Container overflow:      fc
 
  Array cookie:            ac
 
  Intra object redzone:    bb
 
  ASan internal:           fe
 
  Left alloca redzone:     ca
 
  Right alloca redzone:    cb
 
  Shadow gap:              cc
 
==1852723==ABORTING

The failure started happening on 10.3 after this commit:

commit ddc416c60698e1f8939faff0cb09c5b5af8e03a7
 
Author: Aleksey Midenkov
 
Date:   Mon Apr 25 13:58:41 2022 +0300
 
 
 
    MDEV-20077 Warning on full history partition is delayed until next DML statement



 Comments   
Comment by Aleksey Midenkov [ 2023-07-19 ]

Failure happens from legit usage of handler in close_thread_tables() because ha_maria_implicit_commit() prematurely freed some data used by the handler (info->state).

2 problems:

1. ha_maria_implicit_commit() frees tables in _ma_trnman_end_trans_hook() before close_thread_tables();
2. info->state is allocated from tables (assigned in _ma_setup_live_state()): info aka handler lives longer than its state.

Generated at Thu Feb 08 10:04:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.