[MDEV-23563] InnoDB: Failing assertion: !cursor->index->is_committed() in row0ins.cc Created: 2020-08-24  Updated: 2022-04-28  Resolved: 2022-04-28

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4.14, 10.5.15
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Todd Coker (Inactive) Assignee: Todd Coker (Inactive)
Resolution: Incomplete Votes: 0
Labels: corruption
Environment:

Ubuntu 18.04.4

Attachments: File MDEV-23563.yy    
Issue Links:
Blocks
is blocked by MDEV-22924 Warning InnoDB: Index 'Marvão_idx3' c... Closed
Relates
relates to MDEV-27751 InnoDB: Failing assertion: !cursor->i... Closed
relates to MDEV-27744 LPAD in vcol created in ORACLE mode m... Closed

 Description   

Server got stuck in a crash loop with the below crash. There were some log messages suggesting table corruption that could possibly be related, though most are for a table not involved in the crash.

2020-08-24 15:13:18 26 [ERROR] InnoDB: Record in index `tasks_ta_assignee_id_2c3ca866_fk_chronometer_userprofile_user_id` of table `db_name`.`table_name` was not found on update: TUPLE (info_bits=0, 2 fields): {[4]    (0x8004F4AF),[4] z| (0x807A7CF9)} at: COMPACT RECORD(info_bits=0, 2 fields): {[4]    (0x8004F4AF),[4] v  (0x8076E8A3)}


2020-08-24 16:10:10 0x7f4ec43dc700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.4.14/storage/innobase/row/row0ins.cc line 218
 
InnoDB: Failing assertion: !cursor->index->is_committed()
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
 
InnoDB: about forcing recovery.
 
200824 16:10:10 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.4.14-MariaDB-1:10.4.14+maria~bionic-log
 
key_buffer_size=33554432
 
read_buffer_size=16777216
 
max_used_connections=121
 
max_threads=2002
 
thread_count=146
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 164086070 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f4dd8000c08
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x7f4ec43dbd98 thread_stack 0x30000
 
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55938409855e]
 
/usr/sbin/mysqld(handle_fatal_signal+0x515)[0x559383b13ea5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x128a0)[0x7f658bb5d8a0]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7f658a491f47]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7f658a4938b1]
 
/usr/sbin/mysqld(+0x587885)[0x55938381d885]
 
/usr/sbin/mysqld(+0xada5b7)[0x559383d705b7]
 
/usr/sbin/mysqld(+0xadf84c)[0x559383d7584c]
 
/usr/sbin/mysqld(+0xb1ae67)[0x559383db0e67]
 
/usr/sbin/mysqld(+0xb1b847)[0x559383db1847]
 
/usr/sbin/mysqld(+0xaf2684)[0x559383d88684]
 
/usr/sbin/mysqld(+0xa2ca68)[0x559383cc2a68]
 
/usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x127)[0x559383b1f467]
 
/usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x237)[0x559383c15d97]
 
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x23c)[0x559383c08d3c]
 
/usr/sbin/mysqld(+0x5c3d52)[0x559383859d52]
 
/usr/sbin/mysqld(+0x7a2279)[0x559383a38279]
 
/usr/sbin/mysqld(handle_rpl_parallel_thread+0xcf6)[0x559383a3da26]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7f658bb526db]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f658a574a3f]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f4d9955485b): UPDATE `table_name` SET `archived` = 0, `title` = 'XXXXXXXXXXXXXXXXXX', `created_by_id` = 359245, `assignee_id` = 347523, `assignee_group_id` = NULL, `assigned_by_id` = 347523, `status_id` = 2, `category_id` = NULL, `priority` = 30, `due_date_id` = 1251132, `chain_link_id` = NULL, `created_at` = '2020-08-12 12:39:18', `updated_at` = '2020-08-24 12:08:42.970881' WHERE `tasks_task`.`id` = 7671933
 
Connection ID (thread ID): 26
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on
 
 
 
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
 
information that should help you find out what is causing the crash.
 
Writing a core file...
 
Working directory at /var/lib/mysql
 
Resource Limits:
 
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        0                    unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             515014               515014               processes 
Max open files            16384                16384                files     
Max locked memory         16777216             16777216             bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       515014               515014               signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us        
Core pattern: |/usr/share/apport/apport %p %s %c %d %P %E



 Comments   
Comment by Marko Mäkelä [ 2020-08-25 ]

In MDEV-22924 we should be able to reproduce this form of corruption.

Comment by Rick Pizzi [ 2020-08-25 ]

A bit of history. This customer suffered from data corruption since they moved to 10.4. They get corrupted tables on multiple tables and multiple replicas. I have rebuilt ALL the replicas from a logical dump of the master few months ago, but corruption returned, on the same tables.... this means 10.4 is silently corrupting indexes.
Any known bug around this? marko

Comment by Matthias Leich [ 2021-03-22 ] 

I hit the following during RQG testing "enriched" by test simplification on
 
origin/HEAD, origin/10.6 b3c470a3c7e8bb497bca5bc9fca4cf52cfc9e88e 2021-03-19T18:12:26+03:00
 
 
 
# 2021-03-22T12:06:59 [4117603] | [rr 4118016 409640]2021-03-22 12:03:14 0x640000a76700[rr 4118016 409643]  InnoDB: Assertion failure in file /Server/10.6N/storage/innobase/row/row0ins.cc line 221
 
# 2021-03-22T12:06:59 [4117603] | [rr 4118016 409645]InnoDB: Failing assertion: !cursor->index->is_committed()
 
...
 
Query (0x62b0000c4238): UPDATE t1 SET col2 = 6 LIMIT 2
 
[rr 4118016 440954]Status: KILL_TIMEOUT     <== The protocol of the actual run shows that. But many other replays showed Status: NOT_KILLED
 
 
 
# 2021-03-22T12:06:59 [4117603] | Thread 3 (Thread 4118016.4118528):
 
# 2021-03-22T12:06:59 [4117603] | #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
# 2021-03-22T12:06:59 [4117603] | #1  0x00007ffde0418859 in __GI_abort () at abort.c:79
 
# 2021-03-22T12:06:59 [4117603] | #2  0x000055b3e0052ecd in ut_dbg_assertion_failed (expr=0x55b3e15bcb40 "!cursor->index->is_committed()", file=0x55b3e15bc800 "/Server/10.6N/storage/innobase/row/row0ins.cc", line=221) at /Server/10.6N/storage/innobase/ut/ut0dbg.cc:60
 
# 2021-03-22T12:06:59 [4117603] | #3  0x000055b3dfe68368 in row_ins_sec_index_entry_by_modify (flags=0, mode=2, cursor=0x640000a70fc0, offsets=0x640000a70f00, offsets_heap=0x61a000cdda98, heap=0x61a000cde098, entry=0x61a000cdd520, thr=0x62200021a390, mtr=0x640000a71380) at /Server/10.6N/storage/innobase/row/row0ins.cc:221
 
# 2021-03-22T12:06:59 [4117603] | #4  0x000055b3dfe77dd8 in row_ins_sec_index_entry_low (flags=0, mode=2, index=0x61600525e820, offsets_heap=0x61a000cdda98, heap=0x61a000cde098, entry=0x61a000cdd520, trx_id=0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0ins.cc:3123
 
# 2021-03-22T12:06:59 [4117603] | #5  0x000055b3dfe7916e in row_ins_sec_index_entry (index=0x61600525e820, entry=0x61a000cdd520, thr=0x62200021a390, check_foreign=true) at /Server/10.6N/storage/innobase/row/row0ins.cc:3337
 
# 2021-03-22T12:06:59 [4117603] | #6  0x000055b3dff7b0d4 in row_upd_sec_index_entry (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:2240
 
# 2021-03-22T12:06:59 [4117603] | #7  0x000055b3dff7b6f7 in row_upd_sec_step (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:2267
 
# 2021-03-22T12:06:59 [4117603] | #8  0x000055b3dff8100d in row_upd (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:3050
 
# 2021-03-22T12:06:59 [4117603] | #9  0x000055b3dff81b12 in row_upd_step (thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:3165
 
# 2021-03-22T12:06:59 [4117603] | #10 0x000055b3dfec982a in row_update_for_mysql (prebuilt=0x6220002191a0) at /Server/10.6N/storage/innobase/row/row0mysql.cc:1814
 
# 2021-03-22T12:06:59 [4117603] | #11 0x000055b3dfb2da60 in ha_innobase::update_row (this=0x61d000f26cb8, old_row=0x61a000c9c950 "0", new_row=0x61a000c9c6b8 "0") at /Server/10.6N/storage/innobase/handler/ha_innodb.cc:8224
 
# 2021-03-22T12:06:59 [4117603] | #12 0x000055b3df033683 in handler::ha_update_row (this=0x61d000f26cb8, old_data=0x61a000c9c950 "0", new_data=0x61a000c9c6b8 "0") at /Server/10.6N/sql/handler.cc:7208
 
# 2021-03-22T12:06:59 [4117603] | #13 0x000055b3deb03196 in mysql_update (thd=0x62b0000bd218, table_list=0x62b0000c4398, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=2, ignore=false, found_return=0x640000a74210, updated_return=0x640000a74230) at /Server/10.6N/sql/sql_update.cc:1077
 
# 2021-03-22T12:06:59 [4117603] | #14 0x000055b3de800759 in mysql_execute_command (thd=0x62b0000bd218) at /Server/10.6N/sql/sql_parse.cc:4389
 
# 2021-03-22T12:06:59 [4117603] | #15 0x000055b3de819963 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "UPDATE t1 SET col2 = 6 LIMIT 2 /* E_R Thread2 QNO 121 CON_ID 16 */", length=66, parser_state=0x640000a74bc0) at /Server/10.6N/sql/sql_parse.cc:8004
 
# 2021-03-22T12:06:59 [4117603] | #16 0x000055b3de7f0420 in dispatch_command (command=COM_QUERY, thd=0x62b0000bd218, packet=0x629000bc2219 "UPDATE t1 SET col2 = 6 LIMIT 2 /* E_R Thread2 QNO 121 CON_ID 16 */ ", packet_length=67, blocking=true) at /Server/10.6N/sql/sql_parse.cc:1888
 
# 2021-03-22T12:06:59 [4117603] | #17 0x000055b3de7ed14f in do_command (thd=0x62b0000bd218, blocking=true) at /Server/10.6N/sql/sql_parse.cc:1399
 
# 2021-03-22T12:06:59 [4117603] | #18 0x000055b3dec2efdd in do_handle_one_connection (connect=0x6080000033b8, put_in_cache=true) at /Server/10.6N/sql/sql_connect.cc:1410
 
# 2021-03-22T12:06:59 [4117603] | #19 0x000055b3dec2e93f in handle_one_connection (arg=0x6080000030b8) at /Server/10.6N/sql/sql_connect.cc:1312
 
# 2021-03-22T12:06:59 [4117603] | #20 0x000055b3df92c5dd in pfs_spawn_thread (arg=0x61500000af98) at /Server/10.6N/storage/perfschema/pfs.cc:2201
 
# 2021-03-22T12:06:59 [4117603] | #21 0x00002e7963a77609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
# 2021-03-22T12:06:59 [4117603] | #22 0x00007ffde0515293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
pluto:/data/Results/TBR-1-ExMDEV-14643/left_over/dev/shm/vardir/1616414463/83/1/rr
 
_RR_TRACE_DIR="." rr replay --mark-stdio
 
 
 
RQG
 
-------
 
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
 
 
perl rqg.pl \              
--duration=200 \
 
--queries=10000000 \
 
--no_mask \
 
--seed=random \
 
--engine=InnoDB \
 
--gendata_sql=conf/mariadb/table_stress.sql \
 
--gendata=conf/mariadb/table_stress.zz \
 
--rpl_mode=none \
 
--mysqld=--lock-wait-timeout=86400 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--innodb_stats_persistent=off \
 
--mysqld=--loose_innodb_use_native_aio=0 \
 
--mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
 
--mysqld=--log-output=none \
 
--mysqld=--log-bin \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--innodb-buffer-pool-size=24M \
 
--mysqld=--plugin-load-add=file_key_management.so \
 
--mysqld=--innodb_page_size=64K \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--loose-max-statement-time=30 \
 
--reporters=Backtrace,Deadlock1,ErrorLog \
 
--validators=None \
 
--threads=2 \
 
--grammar=MDEV-23563.yy \
 
--duration=200 \
 
--workdir=<local settings> \
 
--vardir=<local settings> \
 
--mtr-build-thread=<local settings> \
 
--basedir1=<local settings> \
 
--script_debug=_nix_ \
 
--rr=Extended \
 
--rr_options=--chaos
 
 
 
Search pattern
 
[ 'TBR-1-ExMDEV-14643' , 'InnoDB: Failing assertion: \!cursor->index->is_committed\(\)' ],

Comment by Marko Mäkelä [ 2021-03-22 ]

I conducted some analysis of the trace that mleich posted, and unfortunately it looks like MDEV-371 and existing bugs in indexed virtual columns are to blame.

The unexpected record (with no delete-mark) was inserted a little earlier by the same thread:

10.6 b3c470a3c7e8bb497bca5bc9fca4cf52cfc9e88e

 
#6  0x000055b3dfe7916e in row_ins_sec_index_entry (index=0x61600525e820, entry=0x61a000ca7520, thr=0x62200021a390, check_foreign=true) at /Server/10.6N/storage/innobase/row/row0ins.cc:3337
 
#7  0x000055b3dff7b0d4 in row_upd_sec_index_entry (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:2240
 
#8  0x000055b3dff7b6f7 in row_upd_sec_step (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:2267
 
#9  0x000055b3dff8100d in row_upd (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:3050
 
#10 0x000055b3dff81b12 in row_upd_step (thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:3165
 
#11 0x000055b3dfec982a in row_update_for_mysql (prebuilt=0x6220002191a0) at /Server/10.6N/storage/innobase/row/row0mysql.cc:1814
 
#12 0x000055b3dfb2da60 in ha_innobase::update_row (this=0x61d000f26cb8, old_row=0x61a000c9c950 "0", new_row=0x61a000c9c6b8 "0") at /Server/10.6N/storage/innobase/handler/ha_innodb.cc:8224
 
#13 0x000055b3df033683 in handler::ha_update_row (this=0x61d000f26cb8, old_data=0x61a000c9c950 "0", new_data=0x61a000c9c6b8 "0") at /Server/10.6N/sql/handler.cc:7208
 
#14 0x000055b3deb03196 in mysql_update (thd=0x62b0000bd218, table_list=0x62b0000c4398, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=2, ignore=false, found_return=0x640000a74210, 
    updated_return=0x640000a74230) at /Server/10.6N/sql/sql_update.cc:1077
 
#15 0x000055b3de800759 in mysql_execute_command (thd=0x62b0000bd218) at /Server/10.6N/sql/sql_parse.cc:4389
 
#16 0x000055b3de819963 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "UPDATE t1 SET col2 = 6 LIMIT 2 /* E_R Thread2 QNO 113 CON_ID 16 */", length=66, parser_state=0x640000a74bc0)
 
    at /Server/10.6N/sql/sql_parse.cc:8004

The index is for an internally created virtual column. Unfortunately, there is no easy way to disable MDEV-371. Maybe sachin.setiya.007 could provide at least a code patch for that?

(rr) p *index.fields@index.n_fields
 
$8 = {{col = 0x61c00006f448, name = {m_name = 0x61c00006f6e0 "DB_ROW_HASH_9"}, prefix_len = 0, fixed_len = 8}, {col = 0x61c00006f1e0, name = {m_name = 0x6200001d82ba "DB_ROW_ID"}, prefix_len = 0, 
    fixed_len = 6}}

A little later, the same thread crashes, executing a similar query (different QNO in the comment):

#2  0x000055b3e0052ecd in ut_dbg_assertion_failed (expr=0x55b3e15bcb40 "!cursor->index->is_committed()", file=0x55b3e15bc800 "/Server/10.6N/storage/innobase/row/row0ins.cc", line=221)
 
    at /Server/10.6N/storage/innobase/ut/ut0dbg.cc:60
 
#3  0x000055b3dfe68368 in row_ins_sec_index_entry_by_modify (flags=0, mode=2, cursor=0x640000a70fc0, offsets=0x640000a70f00, offsets_heap=0x61a000cdda98, heap=0x61a000cde098, entry=0x61a000cdd520, 
    thr=0x62200021a390, mtr=0x640000a71380) at /Server/10.6N/storage/innobase/row/row0ins.cc:221
 
#4  0x000055b3dfe77dd8 in row_ins_sec_index_entry_low (flags=0, mode=2, index=0x61600525e820, offsets_heap=0x61a000cdda98, heap=0x61a000cde098, entry=0x61a000cdd520, trx_id=0, thr=0x62200021a390)
 
    at /Server/10.6N/storage/innobase/row/row0ins.cc:3123
 
#5  0x000055b3dfe7916e in row_ins_sec_index_entry (index=0x61600525e820, entry=0x61a000cdd520, thr=0x62200021a390, check_foreign=true) at /Server/10.6N/storage/innobase/row/row0ins.cc:3337
 
#6  0x000055b3dff7b0d4 in row_upd_sec_index_entry (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:2240
 
#7  0x000055b3dff7b6f7 in row_upd_sec_step (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:2267
 
#8  0x000055b3dff8100d in row_upd (node=0x622000219cf0, thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:3050
 
#9  0x000055b3dff81b12 in row_upd_step (thr=0x62200021a390) at /Server/10.6N/storage/innobase/row/row0upd.cc:3165
 
#10 0x000055b3dfec982a in row_update_for_mysql (prebuilt=0x6220002191a0) at /Server/10.6N/storage/innobase/row/row0mysql.cc:1814
 
#11 0x000055b3dfb2da60 in ha_innobase::update_row (this=0x61d000f26cb8, old_row=0x61a000c9c950 "0", new_row=0x61a000c9c6b8 "0") at /Server/10.6N/storage/innobase/handler/ha_innodb.cc:8224
 
#12 0x000055b3df033683 in handler::ha_update_row (this=0x61d000f26cb8, old_data=0x61a000c9c950 "0", new_data=0x61a000c9c6b8 "0") at /Server/10.6N/sql/handler.cc:7208
 
#13 0x000055b3deb03196 in mysql_update (thd=0x62b0000bd218, table_list=0x62b0000c4398, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=2, ignore=false, found_return=0x640000a74210, 
    updated_return=0x640000a74230) at /Server/10.6N/sql/sql_update.cc:1077
 
#14 0x000055b3de800759 in mysql_execute_command (thd=0x62b0000bd218) at /Server/10.6N/sql/sql_parse.cc:4389
 
#15 0x000055b3de819963 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "UPDATE t1 SET col2 = 6 LIMIT 2 /* E_R Thread2 QNO 121 CON_ID 16 */", length=66, parser_state=0x640000a74bc0)
 
    at /Server/10.6N/sql/sql_parse.cc:8004

There was a commit between those two operations, in the same thread:

#4  0x000055b3dfb14de3 in innobase_commit (hton=0x615000002b18, thd=0x62b0000bd218, commit_trx=true) at /Server/10.6N/storage/innobase/handler/ha_innodb.cc:4095
 
#5  0x000055b3df00264f in commit_one_phase_2 (thd=0x62b0000bd218, all=true, trans=0x62b0000c09c0, is_real_trans=true) at /Server/10.6N/sql/handler.cc:1942
 
#6  0x000055b3df00235a in ha_commit_one_phase (thd=0x62b0000bd218, all=true) at /Server/10.6N/sql/handler.cc:1921
 
#7  0x000055b3df0006aa in ha_commit_trans (thd=0x62b0000bd218, all=true) at /Server/10.6N/sql/handler.cc:1715
 
#8  0x000055b3dec709fa in trans_commit_implicit (thd=0x62b0000bd218) at /Server/10.6N/sql/transaction.cc:329
 
#9  0x000055b3de7fc6cf in mysql_execute_command (thd=0x62b0000bd218) at /Server/10.6N/sql/sql_parse.cc:3731
 
#10 0x000055b3de819963 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "ALTER IGNORE TABLE t1 ADD UNIQUE ( col2, col2 ) /* E_R Thread2 QNO 118 CON_ID 16 */", length=83, parser_state=0x640000a74bc0)
 
    at /Server/10.6N/sql/sql_parse.cc:8004

Coker, rpizzi, could MDEV-371 play a role here? Was the schema identical before and after upgrading to 10.4? Is some SHOW CREATE TABLE available for the affected table?

If MDEV-371 cannot be blamed for the original failure (for example, if no DDL statements were executed and it has been verified that no hidden columns exist), then it could be the effect of some dormant corruption. While MDEV-24449 is fixed now, old data files will not uncorrupt themselves.

Comment by Marko Mäkelä [ 2022-03-22 ]

Is this bug repeatable after setting innodb_change_buffering=none (MDEV-27734 did that by default starting with 10.5.15) and rebuilding the table? In MDEV-22986 we have a similar corruption report where the change buffer was identified as the culprit.

Comment by Nikita Malyavin [ 2022-03-24 ]

allen.lee@mariadb.com I also recommend to all the customers to add STORED to all virtual columns that have indexes. It will slightly consume additional storage space (to store the field in the clustered index), but prevent all known crashes related to virtual column indexes.

I don't know how to recover the table gracefully now. We should drop the corrupted index somehow, maybe Marko can help with recovering, if that is in question.

Comment by Roel Van de Paar [ 2022-04-22 ]

Are MDEV-27751 or MDEV-27744 connected?

Comment by Marko Mäkelä [ 2022-04-28 ]

Roel, there can be multiple causes for inconsistency between indexes. This ticket starts to become much like MDEV-9663, convoluting several bugs, without contributing any reproducible test case. I think that we can close this one.

MDEV-27744 is a bug related to indexed virtual columns, which I think we have plenty of. The impact is amplified by MDEV-371, which can cause hidden virtual columns to be created. Such bugs by default belong to nikitamalyavin.

MDEV-27751 looks like something caused by MDEV-24621 in 10.7.

Apart from those bugs, there exists a bug in the InnoDB change buffer that we will be unable to fix until we are able to reproduce it. Let us handle that in MDEV-22986 (and eventually by disabling (MDEV-22986), deprecating (MDEV-27735) and removing the change buffer).

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