[MDEV-26373] Various crashes & asserts and UBSAN null pointer passed as argument 2 in trx_undo_report_row_operation Created: 2021-08-16  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Server, Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11, 11.0, 11.1
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: affects-tests

Issue Links:
Relates
relates to MDEV-24706 Assertion `thd->transaction->stmt.is_... Confirmed
relates to MDEV-24812 Assertion `!trx->read_only' failed in... Confirmed
relates to MDEV-31584 Assertion `thd->transaction->stmt.is_... Confirmed

 Description   

Strong suspicion that this issue is in InnoDB. Also see first comment in MDEV-26217 which has a similar stack but looks otherwise unrelated. Issue seems to be a combination of unforeseen circumstances converging. Whilst not proven, corruption seems a possibility. Note that enforce-storage-engine=InnoDB cannot be on startup (MDEV-26372). Testcase may be lightly sporadic.

# mysqld options required for replay: --enforce-storage-engine=InnoDB 
SET sql_mode='';
 
ALTER TABLE mysql.slow_log ENGINE=MyISAM;
 
SET tx_read_only=1;
 
SET SESSION long_query_time=0;
 
SET SESSION slow_query_log=1;
 
SET GLOBAL slow_query_log=1;
 
SET GLOBAL log_output='TABLE,FILE';
 
ALTER TABLE mysql.slow_log ENGINE=MyISAM;

Leads to:

10.6.5 9ac1ac006197c8979db1dc73f4e983f623e831e8 (Optimized)

 
Core was generated by `/test/MD160821-mariadb-10.6.5-linux-x86_64-opt/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGSEGV, Segmentation fault.
 
#0  0x00005604205cc1b9 in std::__atomic_base<unsigned int>::compare_exchange_strong (__m2=std::memory_order_relaxed, __m1=std::memory_order_acquire, 
    __i2=2147483648, __i1=<synthetic pointer>: 0, this=0x8)
 
    at /usr/include/c++/9/bits/atomic_base.h:493
 
493	      compare_exchange_strong(__int_type& __i1, __int_type __i2,
 
[Current thread is 1 (Thread 0x14c5c5560700 (LWP 2521451))]
 
(gdb) bt
 
#0  0x00005604205cc1b9 in std::__atomic_base<unsigned int>::compare_exchange_strong (__m2=std::memory_order_relaxed, __m1=std::memory_order_acquire, __i2=2147483648, __i1=<synthetic pointer>: 0, this=0x8) at /usr/include/c++/9/bits/atomic_base.h:493
 
#1  srw_mutex::wr_lock_try (this=0x8) at /test/10.6_opt/storage/innobase/include/srw_lock.h:65
 
#2  srw_mutex::wr_lock (this=0x8) at /test/10.6_opt/storage/innobase/include/srw_lock.h:70
 
#3  ssux_lock_low::wr_lock (this=0x8) at /test/10.6_opt/storage/innobase/include/srw_lock.h:212
 
#4  trx_undo_assign_low (trx=trx@entry=0x14c5c781a130, rseg=rseg@entry=0x0, undo=undo@entry=0x14c5c781b0e0, err=err@entry=0x14c5c555bc84, mtr=mtr@entry=0x14c5c555bcd0) at /test/10.6_opt/storage/innobase/trx/trx0undo.cc:1208
 
#5  0x00005604205ad76c in trx_undo_report_row_operation (thr=thr@entry=0x14c590033960, index=index@entry=0x14c59002e310, clust_entry=clust_entry@entry=0x14c59002ee50, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x0, offsets=0x0, roll_ptr=0x14c5c555ce80) at /test/10.6_opt/storage/innobase/trx/trx0rec.cc:2065
 
#6  0x00005604205f66db in btr_cur_ins_lock_and_undo (inherit=0x14c5c555ce67, mtr=0x14c5c555d870, thr=0x14c590033960, entry=0x14c59002ee50, cursor=0x14c5c555d120, flags=0) at /test/10.6_opt/storage/innobase/btr/btr0cur.cc:3300
 
#7  btr_cur_optimistic_insert (flags=0, cursor=0x14c5c555d120, offsets=offsets@entry=0x14c5c555d108, heap=heap@entry=0x14c5c555d100, entry=entry@entry=0x14c59002ee50, rec=rec@entry=0x14c5c555d118, big_rec=0x14c5c555d0f8, n_ext=<optimized out>, thr=0x14c590033960, mtr=0x14c5c555d870) at /test/10.6_opt/storage/innobase/btr/btr0cur.cc:3527
 
#8  0x000056042055e72d in row_ins_clust_index_entry_low (flags=<optimized out>, mode=<optimized out>, index=0x14c59002e310, n_uniq=<optimized out>, entry=0x14c59002ee50, n_ext=<optimized out>, thr=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:2752
 
#9  0x0000560420560039 in row_ins_clust_index_entry (index=0x14c59002e310, entry=0x14c59002ee50, thr=0x14c590033960, n_ext=0) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3225
 
#10 0x0000560420560729 in row_ins_index_entry (thr=0x14c590033960, entry=<optimized out>, index=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3351
 
#11 row_ins_index_entry_step (thr=0x14c590033960, node=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3519
 
#12 row_ins (thr=0x14c590033960, node=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3665
 
#13 row_ins_step (thr=thr@entry=0x14c590033960) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3811
 
#14 0x0000560420570865 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x14c590028190 "a\031\355\231\f\336\321\031", prebuilt=0x14c5900328d0, ins_mode=ROW_INS_NORMAL) at /test/10.6_opt/storage/innobase/row/row0mysql.cc:1342
 
#15 0x00005604204c0e6a in ha_innobase::write_row (this=0x14c590027420, record=0x14c590028190 "a\031\355\231\f\336\321\031") at /test/10.6_opt/storage/innobase/handler/ha_innodb.cc:7781
 
#16 0x00005604201b3360 in handler::ha_write_row (this=0x14c590027420, buf=0x14c590028190 "a\031\355\231\f\336\321\031") at /test/10.6_opt/sql/handler.cc:7514
 
#17 0x00005604202a0629 in Log_to_csv_event_handler::log_slow (this=<optimized out>, thd=0x14c590000c58, current_time=<optimized out>, user_host=0x14c5c555f0e0 "root[root] @ localhost []", user_host_len=25, query_utime=<optimized out>, lock_utime=0, is_command=false, sql_text=0x14c590010840 "SET GLOBAL log_output='TABLE,FILE'", sql_text_len=34) at /test/10.6_opt/sql/log.cc:1004
 
#18 0x000056042029a8ea in LOGGER::slow_log_print (this=0x5604210e1b80 <logger>, thd=0x14c590000c58, query=0x14c590010840 "SET GLOBAL log_output='TABLE,FILE'", query_length=34, current_utime=<optimized out>) at /test/10.6_opt/sql/log.cc:1371
 
#19 0x000056041ff6e0d7 in log_slow_statement (thd=thd@entry=0x14c590000c58) at /test/10.6_opt/sql/sql_class.h:1357
 
#20 0x000056041ff738f6 in dispatch_command (command=COM_QUERY, thd=0x14c590000c58, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /test/10.6_opt/sql/sql_parse.cc:2428
 
#21 0x000056041ff763e7 in do_command (thd=0x14c590000c58, blocking=blocking@entry=true) at /test/10.6_opt/sql/sql_parse.cc:1404
 
#22 0x0000560420084ef7 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /test/10.6_opt/sql/sql_connect.cc:1418
 
#23 0x000056042008523d in handle_one_connection (arg=arg@entry=0x560422bf6558) at /test/10.6_opt/sql/sql_connect.cc:1312
 
#24 0x000056042040f778 in pfs_spawn_thread (arg=0x560422b78888) at /test/10.6_opt/storage/perfschema/pfs.cc:2201
 
#25 0x000014c5dc8ea609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#26 0x000014c5dc4d8293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
mysqld: /test/10.7_dbg/storage/innobase/trx/trx0rec.cc:2058: dberr_t trx_undo_report_row_operation(que_thr_t*, dict_index_t*, const dtuple_t*, const upd_t*, ulint, const rec_t*, const rec_offs*, roll_ptr_t*): Assertion `!trx->read_only' failed.

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
Core was generated by `/test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x14ce60130700 (LWP 3553419))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x000014ce6a796859 in __GI_abort () at abort.c:79
 
#2  0x000014ce6a796729 in __assert_fail_base (fmt=0x14ce6a92c588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x56173ed669b1 "!trx->read_only", file=0x56173ed66c30 "/test/10.7_dbg/storage/innobase/trx/trx0rec.cc", line=2058, function=<optimized out>) at assert.c:92
 
#3  0x000014ce6a7a7f36 in __GI___assert_fail (assertion=assertion@entry=0x56173ed669b1 "!trx->read_only", file=file@entry=0x56173ed66c30 "/test/10.7_dbg/storage/innobase/trx/trx0rec.cc", line=line@entry=2058, function=function@entry=0x56173ed677d8 "dberr_t trx_undo_report_row_operation(que_thr_t*, dict_index_t*, const dtuple_t*, const upd_t*, ulint, const rec_t*, const rec_offs*, roll_ptr_t*)") at assert.c:101
 
#4  0x000056173e6fa607 in trx_undo_report_row_operation (thr=thr@entry=0x14ce08026688, index=index@entry=0x14ce08038858, clust_entry=clust_entry@entry=0x14ce08039658, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x0, offsets=0x0, roll_ptr=0x14ce6012cbf0) at /test/10.7_dbg/storage/innobase/trx/trx0rec.cc:2058
 
#5  0x000056173e754fad in btr_cur_ins_lock_and_undo (flags=flags@entry=0, cursor=cursor@entry=0x14ce6012d100, entry=entry@entry=0x14ce08039658, thr=thr@entry=0x14ce08026688, mtr=mtr@entry=0x14ce6012d6b0, inherit=inherit@entry=0x14ce6012ccd7) at /test/10.7_dbg/storage/innobase/btr/btr0cur.cc:3300
 
#6  0x000056173e75ba06 in btr_cur_optimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x14ce6012d100, offsets=offsets@entry=0x14ce6012d0c8, heap=heap@entry=0x14ce6012d0c0, entry=entry@entry=0x14ce08039658, rec=rec@entry=0x14ce6012d0d8, big_rec=0x14ce6012d0b8, n_ext=<optimized out>, thr=0x14ce08026688, mtr=0x14ce6012d6b0) at /test/10.7_dbg/storage/innobase/btr/btr0cur.cc:3527
 
#7  0x000056173e63d3ee in row_ins_clust_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=2, index=index@entry=0x14ce08038858, n_uniq=n_uniq@entry=0, entry=entry@entry=0x14ce08039658, n_ext=n_ext@entry=0, thr=<optimized out>) at /test/10.7_dbg/storage/innobase/row/row0ins.cc:2752
 
#8  0x000056173e63efe1 in row_ins_clust_index_entry (index=index@entry=0x14ce08038858, entry=entry@entry=0x14ce08039658, thr=thr@entry=0x14ce08026688, n_ext=n_ext@entry=0) at /test/10.7_dbg/storage/innobase/row/row0ins.cc:3225
 
#9  0x000056173e643ef7 in row_ins_index_entry (thr=0x14ce08026688, entry=0x14ce08039658, index=0x14ce08038858) at /test/10.7_dbg/storage/innobase/row/row0ins.cc:3351
 
#10 row_ins_index_entry_step (thr=0x14ce08026688, node=0x14ce08025d08) at /test/10.7_dbg/storage/innobase/row/row0ins.cc:3519
 
#11 row_ins (thr=0x14ce08026688, node=0x14ce08025d08) at /test/10.7_dbg/storage/innobase/row/row0ins.cc:3665
 
#12 row_ins_step (thr=thr@entry=0x14ce08026688) at /test/10.7_dbg/storage/innobase/row/row0ins.cc:3811
 
#13 0x000056173e667c26 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x14ce080205c0 "a\031\362\257\n\255\317\031", prebuilt=0x14ce080255d8, ins_mode=ROW_INS_NORMAL) at /test/10.7_dbg/storage/innobase/row/row0mysql.cc:1342
 
#14 0x000056173e4f0b87 in ha_innobase::write_row (this=0x14ce0802d170, record=0x14ce080205c0 "a\031\362\257\n\255\317\031") at /test/10.7_dbg/storage/innobase/handler/ha_innodb.cc:7776
 
#15 0x000056173e1549c5 in handler::ha_write_row (this=0x14ce0802d170, buf=0x14ce080205c0 "a\031\362\257\n\255\317\031") at /test/10.7_dbg/sql/handler.cc:7514
 
#16 0x000056173e291b15 in Log_to_csv_event_handler::log_slow (this=<optimized out>, thd=0x14ce08000db8, current_time=<optimized out>, user_host=0x14ce6012f060 "root[root] @ localhost []", user_host_len=25, query_utime=<optimized out>, lock_utime=0, is_command=false, sql_text=0x14ce08013d20 "SET GLOBAL log_output='TABLE,FILE'", sql_text_len=34) at /test/10.7_dbg/sql/log.cc:1004
 
#17 0x000056173e28a1f7 in LOGGER::slow_log_print (this=this@entry=0x56173f4436c0 <logger>, thd=thd@entry=0x14ce08000db8, query=0x14ce08013d20 "SET GLOBAL log_output='TABLE,FILE'", query_length=34, current_utime=<optimized out>) at /test/10.7_dbg/sql/log.cc:1371
 
#18 0x000056173e293614 in slow_log_print (thd=thd@entry=0x14ce08000db8, query=<optimized out>, query_length=<optimized out>, current_utime=<optimized out>) at /test/10.7_dbg/sql/log.cc:6831
 
#19 0x000056173de3d2eb in log_slow_statement (thd=thd@entry=0x14ce08000db8) at /test/10.7_dbg/sql/sql_class.h:1357
 
#20 0x000056173de46982 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14ce08000db8, packet=<optimized out>, packet@entry=0x14ce0800b7d9 "", packet_length=packet_length@entry=34, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:2428
 
#21 0x000056173de47ae9 in do_command (thd=0x14ce08000db8, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:1404
 
#22 0x000056173dfbddd6 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x561740fb6358, put_in_cache=put_in_cache@entry=true) at /test/10.7_dbg/sql/sql_connect.cc:1418
 
#23 0x000056173dfbe3db in handle_one_connection (arg=arg@entry=0x561740fb6358) at /test/10.7_dbg/sql/sql_connect.cc:1312
 
#24 0x000056173e426ce4 in pfs_spawn_thread (arg=0x561740edf038) at /test/10.7_dbg/storage/perfschema/pfs.cc:2201
 
#25 0x000014ce6aca5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#26 0x000014ce6a893293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.41 (dbg), 10.2.41 (opt), 10.3.32 (dbg), 10.3.32 (opt), 10.4.22 (dbg), 10.4.22 (opt), 10.5.13 (dbg), 10.5.13 (opt), 10.6.5 (dbg), 10.6.5 (opt), 10.7.0 (dbg), 10.7.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.35 (dbg), 5.7.35 (opt), 8.0.26 (dbg), 8.0.26 (opt)

 Comments   
Comment by Roel Van de Paar [ 2021-08-16 ]

The original testcase can also produce the stack seen in MDEV-24812.

10.2.41 (Debug)

 
mysqld: /test/10.2_dbg/storage/innobase/trx/trx0rec.cc:2048: dberr_t trx_undo_report_row_operation(que_thr_t*, dict_index_t*, const dtuple_t*, const upd_t*, ulint, const rec_t*, const rec_offs*, roll_ptr_t*): Assertion `!trx->read_only' failed.

10.2.41 (Debug)

 
Core was generated by `/test/MD160821-mariadb-10.2.41-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
[Current thread is 1 (Thread 0x1510f1b57700 (LWP 3414585))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x000056079c02bd15 in my_write_core (sig=sig@entry=6) at /test/10.2_dbg/mysys/stacktrace.c:382
 
#2  0x000056079b921e2d in handle_fatal_signal (sig=6) at /test/10.2_dbg/sql/signal_handler.cc:355
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x000015110cc61859 in __GI_abort () at abort.c:79
 
#6  0x000015110cc61729 in __assert_fail_base (fmt=0x15110cdf7588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x56079c1e6b4e "!trx->read_only", file=0x56079c22ba58 "/test/10.2_dbg/storage/innobase/trx/trx0rec.cc", line=2048, function=<optimized out>) at assert.c:92
 
#7  0x000015110cc72f36 in __GI___assert_fail (assertion=assertion@entry=0x56079c1e6b4e "!trx->read_only", file=file@entry=0x56079c22ba58 "/test/10.2_dbg/storage/innobase/trx/trx0rec.cc", line=line@entry=2048, function=function@entry=0x56079c22c588 "dberr_t trx_undo_report_row_operation(que_thr_t*, dict_index_t*, const dtuple_t*, const upd_t*, ulint, const rec_t*, const rec_offs*, roll_ptr_t*)") at assert.c:101
 
#8  0x000056079bceb557 in trx_undo_report_row_operation (thr=thr@entry=0x1510a0022da8, index=index@entry=0x1510a00375f0, clust_entry=clust_entry@entry=0x1510a00352a0, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x0, offsets=0x0, roll_ptr=0x1510f1b53db0) at /test/10.2_dbg/storage/innobase/include/trx0trx.h:1051
 
#9  0x000056079bd39ae1 in btr_cur_ins_lock_and_undo (flags=flags@entry=0, cursor=cursor@entry=0x1510f1b54290, entry=entry@entry=0x1510a00352a0, thr=thr@entry=0x1510a0022da8, mtr=mtr@entry=0x1510f1b54850, inherit=inherit@entry=0x1510f1b53e88) at /test/10.2_dbg/storage/innobase/btr/btr0cur.cc:3001
 
#10 0x000056079bd4719f in btr_cur_optimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x1510f1b54290, offsets=offsets@entry=0x1510f1b54260, heap=heap@entry=0x1510f1b54258, entry=entry@entry=0x1510a00352a0, rec=rec@entry=0x1510f1b54268, big_rec=0x1510f1b54250, n_ext=<optimized out>, thr=0x1510a0022da8, mtr=0x1510f1b54850) at /test/10.2_dbg/storage/innobase/btr/btr0cur.cc:3221
 
#11 0x000056079bc20e53 in row_ins_clust_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=2, index=index@entry=0x1510a00375f0, n_uniq=n_uniq@entry=0, entry=entry@entry=0x1510a00352a0, n_ext=n_ext@entry=0, thr=0x1510a0022da8) at /test/10.2_dbg/storage/innobase/row/row0ins.cc:2689
 
#12 0x000056079bc28e4a in row_ins_clust_index_entry (index=index@entry=0x1510a00375f0, entry=entry@entry=0x1510a00352a0, thr=thr@entry=0x1510a0022da8, n_ext=n_ext@entry=0) at /test/10.2_dbg/storage/innobase/row/row0ins.cc:3141
 
#13 0x000056079bc2a2df in row_ins_index_entry (thr=0x1510a0022da8, entry=0x1510a00352a0, index=0x1510a00375f0) at /test/10.2_dbg/storage/innobase/row/row0ins.cc:3260
 
#14 row_ins_index_entry_step (thr=0x1510a0022da8, node=0x1510a0022408) at /test/10.2_dbg/storage/innobase/row/row0ins.cc:3411
 
#15 row_ins (thr=0x1510a0022da8, node=0x1510a0022408) at /test/10.2_dbg/storage/innobase/row/row0ins.cc:3548
 
#16 row_ins_step (thr=thr@entry=0x1510a0022da8) at /test/10.2_dbg/storage/innobase/row/row0ins.cc:3672
 
#17 0x000056079bc43bcd in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x1510a0039d38 "a\031\376\036\006\226:\031", prebuilt=0x1510a0021cd0) at /test/10.2_dbg/storage/innobase/row/row0mysql.cc:1408
 
#18 0x000056079bb211dd in ha_innobase::write_row (this=0x1510a00395a8, record=0x1510a0039d38 "a\031\376\036\006\226:\031") at /test/10.2_dbg/storage/innobase/handler/ha_innodb.cc:8246
 
#19 0x000056079b93016e in handler::ha_write_row (this=0x1510a00395a8, buf=0x1510a0039d38 "a\031\376\036\006\226:\031") at /test/10.2_dbg/sql/handler.cc:6118
 
#20 0x000056079ba31fca in Log_to_csv_event_handler::log_slow (this=<optimized out>, thd=0x1510a0000d90, current_time=<optimized out>, user_host=0x1510f1b56180 "root[root] @ localhost []", user_host_len=25, query_utime=50, lock_utime=0, is_command=false, sql_text=0x1510a0011238 "SET GLOBAL log_output='TABLE,FILE'", sql_text_len=34) at /test/10.2_dbg/sql/log.cc:956
 
#21 0x000056079ba2b8cf in LOGGER::slow_log_print (this=this@entry=0x56079c852360 <logger>, thd=thd@entry=0x1510a0000d90, query=0x1510a0011238 "SET GLOBAL log_output='TABLE,FILE'", query_length=34, current_utime=<optimized out>) at /test/10.2_dbg/sql/log.cc:1322
 
#22 0x000056079ba34086 in slow_log_print (thd=thd@entry=0x1510a0000d90, query=<optimized out>, query_length=<optimized out>, current_utime=<optimized out>) at /test/10.2_dbg/sql/log.cc:6490
 
#23 0x000056079b70f27f in log_slow_statement (thd=thd@entry=0x1510a0000d90) at /test/10.2_dbg/sql/sql_class.h:1109
 
#24 0x000056079b7266dc in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1510a0000d90, packet=<optimized out>, packet@entry=0x1510a0019671 "", packet_length=<optimized out>, packet_length@entry=34, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.2_dbg/sql/sql_parse.cc:2402
 
#25 0x000056079b727789 in do_command (thd=0x1510a0000d90) at /test/10.2_dbg/sql/sql_parse.cc:1381
 
#26 0x000056079b82c630 in do_handle_one_connection (connect=connect@entry=0x56079e3c15a0) at /test/10.2_dbg/sql/sql_connect.cc:1336
 
#27 0x000056079b82c85b in handle_one_connection (arg=0x56079e3c15a0) at /test/10.2_dbg/sql/sql_connect.cc:1241
 
#28 0x000015110d168609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#29 0x000015110cd5e293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Roel Van de Paar [ 2021-08-16 ]

Another testcase able to reproduce this issue generated a stack alike to MDEV-24706 when partially replayed. Ref first comment in that bug for testcase/stack.

Comment by Roel Van de Paar [ 2021-08-16 ]

I have another, partially reduced (no longer able to reproduce the issue for unknown reason) testcase. Just adding it here for info/reference. Not all options required.

--log_bin --sql_mode=ONLY_FULL_GROUP_BY --max_allowed_packet=33554432 --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --log-slow-rate-limit=2047 --tmp-memory-table-size=24


CREATE OR REPLACE TABLE mysql.general_log (a INT) ENGINE=InnoDB;
 
CREATE TABLE IF NOT EXISTS t1 (a INT) SELECT 3 AS a;
 
SET GLOBAL general_log=ON;
 
SET GLOBAL log_output='TABLE,TABLE';
 
SET SESSION tx_read_only=1;
 
SET SESSION AUTOCOMMIT=0;
 
SELECT 't1 ROWs AFTER SMALL DELETE', COUNT(*) FROM t1;
 
SET SESSION tx_read_only=0;
 
INSERT INTO t1 VALUES (1);
 
SELECT SLEEP (3);
 
SET SESSION tx_read_only=1;  # added for looping

Comment by Roel Van de Paar [ 2021-12-12 ]

Sporadic.

# mysqld options required for replay: --sql_mode= --enforce-storage-engine=InnoDB
 
ALTER TABLE mysql.general_log ENGINE=MyISAM;
 
SET SESSION TRANSACTION READ ONLY,ISOLATION LEVEL REPEATABLE READ;
 
SET GLOBAL general_log=ON;
 
SET GLOBAL log_output='TABLE,FILE';   # Repeat twice if necessary

Leads to:

10.6.6 50ed0bd891f11a2dae3a67d1ecbf8223fcbedbc6 (Optimized)

 
Core was generated by `/test/MD121221-mariadb-10.6.6-linux-x86_64-opt/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGSEGV, Segmentation fault.
 
#0  0x000055ab6b6a1631 in std::__atomic_base<unsigned int>::compare_exchange_strong (__m2=std::memory_order_relaxed, __m1=std::memory_order_acquire, 
    __i2=2147483649, __i1=<synthetic pointer>: 0, this=0x8)
 
    at /usr/include/c++/9/bits/atomic_base.h:493
 
493	      compare_exchange_strong(__int_type& __i1, __int_type __i2,
 
[Current thread is 1 (Thread 0x145df0f71700 (LWP 808173))]
 
(gdb) bt
 
#0  0x000055ab6b6a1631 in std::__atomic_base<unsigned int>::compare_exchange_strong (__m2=std::memory_order_relaxed, __m1=std::memory_order_acquire, __i2=2147483649, __i1=<synthetic pointer>: 0, this=0x8) at /usr/include/c++/9/bits/atomic_base.h:493
 
#1  srw_mutex_impl<true>::wr_lock_try (this=0x8) at /test/10.6_opt/storage/innobase/include/srw_lock.h:75
 
#2  srw_mutex_impl<true>::wr_lock (this=0x8) at /test/10.6_opt/storage/innobase/include/srw_lock.h:80
 
#3  ssux_lock_impl<true>::wr_lock (this=0x8) at /test/10.6_opt/storage/innobase/include/srw_lock.h:226
 
#4  trx_undo_assign_low (trx=trx@entry=0x145df0f73130, rseg=rseg@entry=0x0, undo=undo@entry=0x145df0f740e0, err=err@entry=0x145df0f6c724, mtr=mtr@entry=0x145df0f6c770) at /test/10.6_opt/storage/innobase/trx/trx0undo.cc:1219
 
#5  0x000055ab6b68189c in trx_undo_report_row_operation (thr=thr@entry=0x145d9802e528, index=index@entry=0x145d98029c50, clust_entry=clust_entry@entry=0x145d98029140, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x0, offsets=0x0, roll_ptr=0x145df0f6d920) at /test/10.6_opt/storage/innobase/trx/trx0rec.cc:2082
 
#6  0x000055ab6b6cbddb in btr_cur_ins_lock_and_undo (inherit=0x145df0f6d907, mtr=0x145df0f6e310, thr=0x145d9802e528, entry=0x145d98029140, cursor=0x145df0f6dbc0, flags=0) at /test/10.6_opt/storage/innobase/btr/btr0cur.cc:3288
 
#7  btr_cur_optimistic_insert (flags=0, cursor=0x145df0f6dbc0, offsets=offsets@entry=0x145df0f6dba8, heap=heap@entry=0x145df0f6dba0, entry=entry@entry=0x145d98029140, rec=rec@entry=0x145df0f6dbb8, big_rec=0x145df0f6db98, n_ext=<optimized out>, thr=0x145d9802e528, mtr=0x145df0f6e310) at /test/10.6_opt/storage/innobase/btr/btr0cur.cc:3515
 
#8  0x000055ab6b632d5d in row_ins_clust_index_entry_low (flags=<optimized out>, mode=<optimized out>, index=0x145d98029c50, n_uniq=<optimized out>, entry=0x145d98029140, n_ext=<optimized out>, thr=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:2759
 
#9  0x000055ab6b634649 in row_ins_clust_index_entry (index=0x145d98029c50, entry=0x145d98029140, thr=0x145d9802e528, n_ext=0) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3230
 
#10 0x000055ab6b634d39 in row_ins_index_entry (thr=0x145d9802e528, entry=<optimized out>, index=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3356
 
#11 row_ins_index_entry_step (thr=0x145d9802e528, node=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3524
 
#12 row_ins (thr=0x145d9802e528, node=<optimized out>) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3670
 
#13 row_ins_step (thr=thr@entry=0x145d9802e528) at /test/10.6_opt/storage/innobase/row/row0ins.cc:3816
 
#14 0x000055ab6b644b45 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x145d98024530 "a\265\216Q\r\267\361\031", prebuilt=0x145d9802dbf0, ins_mode=ROW_INS_NORMAL) at /test/10.6_opt/storage/innobase/row/row0mysql.cc:1318
 
#15 0x000055ab6b58f44a in ha_innobase::write_row (this=0x145d9802c2e0, record=0x145d98024530 "a\265\216Q\r\267\361\031") at /test/10.6_opt/storage/innobase/handler/ha_innodb.cc:7836
 
#16 0x000055ab6b2843b0 in handler::ha_write_row (this=0x145d9802c2e0, buf=0x145d98024530 "a\265\216Q\r\267\361\031") at /test/10.6_opt/sql/handler.cc:7519
 
#17 0x000055ab6b3711de in Log_to_csv_event_handler::log_general (this=<optimized out>, thd=0x145d98000c58, event_time=<optimized out>, user_host=0x145df0f6fbc0 "root[root] @ localhost []", user_host_len=25, thread_id_arg=4, command_type=0x55ab6b9790ae "Quit", command_type_len=4, sql_text=0x145df0f6fe10 "", sql_text_len=0, client_cs=0x55ab6c190280 <my_charset_utf8mb3_general_ci>) at /test/10.6_opt/sql/log.cc:799
 
#18 0x000055ab6b373325 in LOGGER::general_log_write (this=0x55ab6c1d3ba0 <logger>, thd=0x145d98000c58, command=<optimized out>, query=0x145df0f6fe10 "", query_length=0) at /test/10.6_opt/sql/log.cc:1389
 
#19 0x000055ab6b3733e2 in LOGGER::general_log_print (this=this@entry=0x55ab6c1d3ba0 <logger>, thd=thd@entry=0x145d98000c58, command=command@entry=COM_QUIT, format=format@entry=0x0, args=args@entry=0x145df0f70258) at /test/10.6_opt/sql/log.cc:1415
 
#20 0x000055ab6b3734e5 in general_log_print (thd=thd@entry=0x145d98000c58, command=command@entry=COM_QUIT, format=format@entry=0x0) at /test/10.6_opt/sql/log.cc:6856
 
#21 0x000055ab6b042940 in dispatch_command (command=COM_QUIT, thd=0x145d98000c58, packet=<optimized out>, packet_length=0, blocking=<optimized out>) at /test/10.6_opt/sql/sql_parse.cc:2117
 
#22 0x000055ab6b044d37 in do_command (thd=0x145d98000c58, blocking=blocking@entry=true) at /test/10.6_opt/sql/sql_parse.cc:1404
 
#23 0x000055ab6b154a67 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /test/10.6_opt/sql/sql_connect.cc:1418
 
#24 0x000055ab6b154dad in handle_one_connection (arg=arg@entry=0x55ab6d61e1c8) at /test/10.6_opt/sql/sql_connect.cc:1312
 
#25 0x000055ab6b4e0938 in pfs_spawn_thread (arg=0x55ab6d591188) at /test/10.6_opt/storage/perfschema/pfs.cc:2201
 
#26 0x0000145e0612c609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#27 0x0000145e05d1a293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.42 (opt), 10.2.42 (dbg), 10.3.33 (dbg), 10.3.33 (opt), 10.4.23 (dbg), 10.4.23 (opt), 10.5.14 (dbg), 10.5.14 (opt), 10.6.6 (dbg), 10.6.6 (opt), 10.7.2 (dbg), 10.7.2 (opt), 10.8.0 (dbg), 10.8.0 (opt)

Comment by Roel Van de Paar [ 2021-12-12 ]

This bug seems definitely connected with MDEV-24812. Idem like the earlier testcase in this report, the last testcase above also produces stacks from MDEV-24812.

Comment by Marko Mäkelä [ 2021-12-13 ]

Is mysql.slow_log even supposed to be written to InnoDB? Maybe the SQL layer should return an error if the transaction is in read-only mode and the slow query log is enabled? If I omit the .opt file with --enforce-storage-engine=InnoDB then the test will fail like this, for the ALTER TABLE (not the slow query log):

mysqltest: At line 9: query 'ALTER TABLE mysql.slow_log ENGINE=MyISAM' failed: 1792: Cannot execute statement in a READ ONLY transaction

Comment by Roel Van de Paar [ 2023-03-03 ]

A new testcase (very lightly sporadic) produces an UBSAN null pointer passed as argument 2, which is declared to never be null error in storage/innobase/trx/trx0rec.cc:

SET sql_mode='';
 
SET SESSION enforce_storage_engine=InnoDB;
 
CREATE TABLE t (ind SET('') DEFAULT'',string1 CHAR,KEY(ind)) ENGINE=Spider DEFAULT CHARSET=utf8;
 
ALTER TABLE mysql.general_log ENGINE=MyISAM;
 
SET SESSION tx_read_only=ON;
 
XA START 'a';
 
SET GLOBAL log_output='TABLE';
 
SELECT * FROM t;
 
SET GLOBAL general_log=ON;

Leads to a variety of stacks/asserts across versions:

SIGSEGV|TTASEventMutex<GenericPolicy>::try_lock|TTASEventMutex<GenericPolicy>::enter|PolicyMutex<TTASEventMutex<GenericPolicy> >::enter|trx_undo_assign_low
 
SIGSEGV|std::__atomic_base<unsigned int>::compare_exchange_strong|TTASEventMutex<GenericPolicy>::try_lock|TTASEventMutex<GenericPolicy>::enter|PolicyMutex<TTASEventMutex<GenericPolicy> >::enter
 
SIGSEGV|std::__atomic_base<unsigned int>::compare_exchange_strong|srw_mutex_impl<true>::wr_lock_try|srw_mutex_impl<true>::wr_lock|ssux_lock_impl<true>::wr_lock
 
thr_get_trx(thr)->id || index->table->no_rollback() || index->table->is_temporary()|SIGABRT|row_ins_index_entry|row_ins_index_entry_step|row_ins|row_ins_step
 
trx->id || index->table->no_rollback() || index->table->is_temporary()|SIGABRT|row_ins_index_entry|row_ins_index_entry_step|row_ins|row_ins_step

As well as:

11.0.1 4d09050ca77a7efac4565d46e4bcd85a5f210c53 (Optimized, UBASAN)

 
/test/11.0_opt_san/storage/innobase/trx/trx0rec.cc:1896:47: runtime error: null pointer passed as argument 2, which is declared to never be null
 
    #0 0x558fe9e91602 in trx_undo_report_row_operation(que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned short const*, unsigned long*) /test/11.0_opt_san/storage/innobase/trx/trx0rec.cc:1896
 
    #1 0x558fedde021a in btr_cur_ins_lock_and_undo /test/11.0_opt_san/storage/innobase/btr/btr0cur.cc:2030
 
    #2 0x558fedde021a in btr_cur_optimistic_insert(unsigned long, btr_cur_t*, unsigned short**, mem_block_info_t**, dtuple_t*, unsigned char**, big_rec_t**, unsigned long, que_thr_t*, mtr_t*) /test/11.0_opt_san/storage/innobase/btr/btr0cur.cc:2255
 
    #3 0x558fed9e8466 in row_ins_clust_index_entry_low(unsigned long, btr_latch_mode, dict_index_t*, unsigned long, dtuple_t*, unsigned long, que_thr_t*) /test/11.0_opt_san/storage/innobase/row/row0ins.cc:2902
 
    #4 0x558feda02f92 in row_ins_clust_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, unsigned long) /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3275
 
    #5 0x558feda056b9 in row_ins_index_entry /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3407
 
    #6 0x558feda056b9 in row_ins_index_entry_step /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3575
 
    #7 0x558feda056b9 in row_ins /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3692
 
    #8 0x558feda056b9 in row_ins_step(que_thr_t*) /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3821
 
    #9 0x558feda703b4 in row_insert_for_mysql(unsigned char const*, row_prebuilt_t*, ins_mode_t) /test/11.0_opt_san/storage/innobase/row/row0mysql.cc:1307
 
    #10 0x558fed595154 in ha_innobase::write_row(unsigned char const*) /test/11.0_opt_san/storage/innobase/handler/ha_innodb.cc:7779
 
    #11 0x558febf4038d in handler::ha_write_row(unsigned char const*) /test/11.0_opt_san/sql/handler.cc:7584
 
    #12 0x558fecafcb2f in Log_to_csv_event_handler::log_general(THD*, my_hrtime_t, char const*, unsigned long, unsigned long long, char const*, unsigned long, char const*, unsigned long, charset_info_st const*) /test/11.0_opt_san/sql/log.cc:924
 
    #13 0x558fecb0ba18 in LOGGER::general_log_write(THD*, enum_server_command, char const*, unsigned long) /test/11.0_opt_san/sql/log.cc:1510
 
    #14 0x558fecb0c2f6 in LOGGER::general_log_print(THD*, enum_server_command, char const*, __va_list_tag*) /test/11.0_opt_san/sql/log.cc:1535
 
    #15 0x558fecb0c550 in general_log_print(THD*, enum_server_command, char const*, ...) /test/11.0_opt_san/sql/log.cc:7075
 
    #16 0x558feaa7f016 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/11.0_opt_san/sql/sql_parse.cc:2115
 
    #17 0x558feaa87700 in do_command(THD*, bool) /test/11.0_opt_san/sql/sql_parse.cc:1407
 
    #18 0x558feb36803c in do_handle_one_connection(CONNECT*, bool) /test/11.0_opt_san/sql/sql_connect.cc:1416
 
    #19 0x558feb36a63c in handle_one_connection /test/11.0_opt_san/sql/sql_connect.cc:1318
 
    #20 0x14f79b1b2b42 in start_thread nptl/pthread_create.c:442
 
    #21 0x14f79b2449ff  (/lib/x86_64-linux-gnu/libc.so.6+0x1269ff)
 
 
 
/test/11.0_opt_san/storage/innobase/trx/trx0undo.cc:1419:8: runtime error: member access within null pointer of type 'struct trx_rseg_t'
 
    #0 0x558fedd18567 in trx_undo_assign_low(trx_t*, trx_rseg_t*, trx_undo_t**, dberr_t*, mtr_t*) /test/11.0_opt_san/storage/innobase/trx/trx0undo.cc:1419
 
    #1 0x558fedc27b23 in trx_undo_report_row_operation(que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned short const*, unsigned long*) /test/11.0_opt_san/storage/innobase/trx/trx0rec.cc:1896
 
    #2 0x558fedde021a in btr_cur_ins_lock_and_undo /test/11.0_opt_san/storage/innobase/btr/btr0cur.cc:2030
 
    #3 0x558fedde021a in btr_cur_optimistic_insert(unsigned long, btr_cur_t*, unsigned short**, mem_block_info_t**, dtuple_t*, unsigned char**, big_rec_t**, unsigned long, que_thr_t*, mtr_t*) /test/11.0_opt_san/storage/innobase/btr/btr0cur.cc:2255
 
    #4 0x558fed9e8466 in row_ins_clust_index_entry_low(unsigned long, btr_latch_mode, dict_index_t*, unsigned long, dtuple_t*, unsigned long, que_thr_t*) /test/11.0_opt_san/storage/innobase/row/row0ins.cc:2902
 
    #5 0x558feda02f92 in row_ins_clust_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, unsigned long) /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3275
 
    #6 0x558feda056b9 in row_ins_index_entry /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3407
 
    #7 0x558feda056b9 in row_ins_index_entry_step /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3575
 
    #8 0x558feda056b9 in row_ins /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3692
 
    #9 0x558feda056b9 in row_ins_step(que_thr_t*) /test/11.0_opt_san/storage/innobase/row/row0ins.cc:3821
 
    #10 0x558feda703b4 in row_insert_for_mysql(unsigned char const*, row_prebuilt_t*, ins_mode_t) /test/11.0_opt_san/storage/innobase/row/row0mysql.cc:1307
 
    #11 0x558fed595154 in ha_innobase::write_row(unsigned char const*) /test/11.0_opt_san/storage/innobase/handler/ha_innodb.cc:7779
 
    #12 0x558febf4038d in handler::ha_write_row(unsigned char const*) /test/11.0_opt_san/sql/handler.cc:7584
 
    #13 0x558fecafcb2f in Log_to_csv_event_handler::log_general(THD*, my_hrtime_t, char const*, unsigned long, unsigned long long, char const*, unsigned long, char const*, unsigned long, charset_info_st const*) /test/11.0_opt_san/sql/log.cc:924
 
    #14 0x558fecb0ba18 in LOGGER::general_log_write(THD*, enum_server_command, char const*, unsigned long) /test/11.0_opt_san/sql/log.cc:1510
 
    #15 0x558fecb0c2f6 in LOGGER::general_log_print(THD*, enum_server_command, char const*, __va_list_tag*) /test/11.0_opt_san/sql/log.cc:1535
 
    #16 0x558fecb0c550 in general_log_print(THD*, enum_server_command, char const*, ...) /test/11.0_opt_san/sql/log.cc:7075
 
    #17 0x558feaa7f016 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/11.0_opt_san/sql/sql_parse.cc:2115
 
    #18 0x558feaa87700 in do_command(THD*, bool) /test/11.0_opt_san/sql/sql_parse.cc:1407
 
    #19 0x558feb36803c in do_handle_one_connection(CONNECT*, bool) /test/11.0_opt_san/sql/sql_connect.cc:1416
 
    #20 0x558feb36a63c in handle_one_connection /test/11.0_opt_san/sql/sql_connect.cc:1318
 
    #21 0x14f79b1b2b42 in start_thread nptl/pthread_create.c:442
 
    #22 0x14f79b2449ff  (/lib/x86_64-linux-gnu/libc.so.6+0x1269ff)

Bug confirmed present in:
MariaDB: 10.3.38 (dbg), 10.3.38 (opt), 10.4.29 (dbg), 10.4.29 (opt), 10.5.20 (dbg), 10.5.20 (opt), 10.6.13 (dbg), 10.6.13 (opt), 10.7.8 (dbg), 10.7.8 (opt), 10.8.8 (dbg), 10.8.8 (opt), 10.9.6 (dbg), 10.9.6 (opt), 10.10.4 (dbg), 10.10.4 (opt), 11.0.1 (dbg), 10.11.2 (dbg), 10.11.2 (opt), 11.0.1 (opt)

Bug (or feature/syntax) confirmed not present in:
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.40 (dbg), 5.7.40 (opt), 8.0.31 (dbg), 8.0.31 (opt)

Comment by Roel Van de Paar [ 2023-03-04 ]

marko Hi! Please have a look at the UBSAN error in innobase/trx/trx0rec.cc then feel free to reassign as you see fit. Thank you

Comment by Roel Van de Paar [ 2023-03-04 ]

An additional code path is triggered with this testcase

SET sql_mode='',enforce_storage_engine=InnoDB;
 
ALTER TABLE mysql.general_log ENGINE=MyISAM;
 
SET unique_checks=0,tx_read_only=ON,foreign_key_checks=0;
 
SET GLOBAL general_log=ON;
 
SET GLOBAL log_output='TABLE,FILE';
 
SELECT 1;

Leads to across versions (first one is new):

!trx->read_only|SIGABRT|trx_undo_report_row_operation|row_ins_clust_index_entry_low|row_ins_clust_index_entry|row_ins_index_entry
 
!trx->read_only|SIGABRT|trx_undo_report_row_operation|btr_cur_ins_lock_and_undo|btr_cur_optimistic_insert|row_ins_clust_index_entry_low
 
SIGSEGV|TTASEventMutex<GenericPolicy>::try_lock|TTASEventMutex<GenericPolicy>::enter|PolicyMutex<TTASEventMutex<GenericPolicy> >::enter|trx_undo_assign_low
 
SIGSEGV|std::__atomic_base<unsigned int>::compare_exchange_strong|TTASEventMutex<GenericPolicy>::try_lock|TTASEventMutex<GenericPolicy>::enter|PolicyMutex<TTASEventMutex<GenericPolicy> >::enter
 
SIGSEGV|std::__atomic_base<unsigned int>::compare_exchange_strong|srw_mutex_impl<true>::wr_lock_try|srw_mutex_impl<true>::wr_lock|ssux_lock_impl<true>::wr_lock

And

UBSAN|null pointer passed as argument 2, which is declared to never be null|storage/innobase/trx/trx0rec.cc|trx_undo_report_row_operation|row_ins_clust_index_entry_low|row_ins_clust_index_entry|row_ins_index_entry

Comment by Marko Mäkelä [ 2023-03-06 ]

For me, the assertion trx->read_only fails in trx_undo_report_row_operation(). The bug seems to be in Log_to_csv_event_handler::log_general(), which disregards the fact that the transaction is supposed to be read-only. Or in ALTER TABLE, which wrongly allows the system table mysql.slow_log to be created in InnoDB. I used the following test case:

--source include/have_innodb.inc
 
SET sql_mode='',enforce_storage_engine=InnoDB;
 
ALTER TABLE mysql.general_log ENGINE=MyISAM;
 
SET unique_checks=0,tx_read_only=ON,foreign_key_checks=0;
 
SET GLOBAL general_log=ON;
 
SET GLOBAL log_output='TABLE,FILE';
 
SELECT 1;

Comment by Marko Mäkelä [ 2023-06-30 ]

MDEV-31584 was filed for something similar, related to making mysql.general_log a malformed system table. This bug is about mysql.slow_log, but the underlying component could be the same.

Generated at Thu Feb 08 09:44:49 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.