[MDEV-26577] InnoDB: Failing assertion: dict_tf2_is_valid(flags, flags2) during ADD COLUMN Created: 2021-09-09  Updated: 2022-06-28  Resolved: 2022-06-27

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.3.36, 10.4.26, 10.5.17, 10.6.9, 10.7.5, 10.8.4, 10.9.2, 10.10.1

Type: Bug Priority: Critical
Reporter: Benjamin Schnarr Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: regression-10.3
Environment:

10.4.20-MariaDB-1:10.4.20+maria~focal on Ubuntu

Issue Links:
Duplicate
is duplicated by MDEV-27852 InnoDB: Failing assertion: dict_tf2_i... Closed
Problem/Incident
is caused by MDEV-11369 Instant add column for InnoDB Closed
Relates
relates to MDEV-23295 Assertion `fields[i].same(instant.fie... Closed
relates to MDEV-23345 Assertion `not_redundant() == old.not... Closed
relates to MDEV-24758 ASAN use-after-poison in ut_memcpy / ... Closed
relates to MDEV-18827 Create utility to parse frm files and... Open
relates to MDEV-28512 InnoDB: Assertion failure in file ./s... Closed

 Description   

The following Query (Nextcloud) causes a Maria DB Failing assertion: dict_tf2_is_valid(flags, flags2):

ALTER TABLE oc_talk_rooms ADD sip_enabled SMALLINT UNSIGNED DEFAULT 0 NOT NULL, ADD description LONGTEXT DEFAULT NULL, ADD listable SMALLINT UNSIGNED DEFAULT 0, ADD call_flag INT DEFAULT 0 NOT NULL

The following stack trace is printed within the error logs:

Error Log

2021-09-09 12:22:54 0x7fc56cbea700 InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.4.20/storage/innobase/dict/dict0mem.cc line 152
InnoDB: Failing assertion: dict_tf2_is_valid(flags, flags2)
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.
210909 12:22:54 [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.20-MariaDB-1:10.4.20+maria~focal
key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=13
max_threads=153
thread_count=10
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 353082 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fc4d801e438
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 = 0x7fc56cbe9dd8 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x32)[0x555d47e5ae82]
/usr/sbin/mysqld(handle_fatal_signal+0x55d)[0x555d4790e82d]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x153c0)[0x7fc57122b3c0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb)[0x7fc570d3118b]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x12b)[0x7fc570d10859]
/usr/sbin/mysqld(+0x5b7b85)[0x555d475d8b85]
/usr/sbin/mysqld(+0x5c9f01)[0x555d475eaf01]
/usr/sbin/mysqld(+0xad2c16)[0x555d47af3c16]
/usr/sbin/mysqld(+0xada493)[0x555d47afb493]
/usr/sbin/mysqld(+0x763814)[0x555d47784814]
/usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPK25st_mysql_const_lex_stringS3_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x3611)[0x555d47790bc1]
/usr/sbin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x34f)[0x555d477e9e7f]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1168)[0x555d476e62b8]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x223)[0x555d476ed273]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x134d)[0x555d476ef78d]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x140)[0x555d476f19c0]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x22e)[0x555d477e591e]
/usr/sbin/mysqld(handle_one_connection+0x3f)[0x555d477e5a3f]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x9609)[0x7fc57121f609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43)[0x7fc570e0d293]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fc4d80563b0): ALTER TABLE oc_talk_rooms ADD sip_enabled SMALLINT UNSIGNED DEFAULT 0 NOT NULL, ADD description LONGTEXT DEFAULT NULL, ADD listable SMALLINT UNSIGNED DEFAULT 0, ADD call_flag INT DEFAULT 0 NOT NULL

Connection ID (thread ID): 171879
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 31493 31493 processes
Max open files 32768 32768 files
Max locked memory 65536 65536 bytes
Max address space unlimited unlimited bytes
Max file locks unlimited unlimited locks
Max pending signals 31493 31493 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

2021-09-09 12:23:02 0 [Note] InnoDB: Using Linux native AIO
2021-09-09 12:23:02 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2021-09-09 12:23:02 0 [Note] InnoDB: Uses event mutexes
2021-09-09 12:23:02 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-09-09 12:23:02 0 [Note] InnoDB: Number of pools: 1
2021-09-09 12:23:02 0 [Note] InnoDB: Using generic crc32 instructions
2021-09-09 12:23:02 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2021-09-09 12:23:02 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2021-09-09 12:23:02 0 [Note] InnoDB: Completed initialization of buffer pool
2021-09-09 12:23:02 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2021-09-09 12:23:02 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=130872279427
2021-09-09 12:23:02 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2021-09-09 12:23:02 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2021-09-09 12:23:02 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-09-09 12:23:02 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-09-09 12:23:02 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-09-09 12:23:02 0 [Note] InnoDB: Waiting for purge to start
2021-09-09 12:23:02 0 [Note] InnoDB: 10.4.20 started; log sequence number 130872279436; transaction id 48766583
2021-09-09 12:23:02 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2021-09-09 12:23:02 0 [Note] Plugin 'FEEDBACK' is disabled.
2021-09-09 12:23:02 0 [Note] Server socket created on IP: '127.0.0.1'.
2021-09-09 12:23:02 0 [Note] Reading of all Master_info entries succeeded
2021-09-09 12:23:02 0 [Note] Added new Master_info '' to hash table
2021-09-09 12:23:02 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.4.20-MariaDB-1:10.4.20+maria~focal' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
2021-09-09 12:23:03 0 [Note] InnoDB: Buffer pool(s) load completed at 210909 12:23:03

 Comments   
Comment by Marko Mäkelä [ 2021-09-09 ]

Can you please provide a complete test case for reproducing this bug on an newly initialized server instance?

Edit: This cannot be related to MDEV-26537 or MDEV-24393, because the reported version is 10.4.20, not 10.4.21.

Comment by Benjamin Schnarr [ 2021-09-10 ]

Thanks for your reply. Unfortunately, I was not able to reproduce the error after dumping, deleting and importing the affected table, the query could be processed without any errors. No idea why.

Best regards
Ben

Comment by Elena Stepanova [ 2021-10-10 ]

marko,
There is also MDEV-22627, can it be related to it?

Comment by Marko Mäkelä [ 2022-05-09 ]

In MDEV-27852 there is some analysis that seems to match this scenario.

Comment by Marko Mäkelä [ 2022-06-27 ]

I did not get a plain table-rebuilding ALTER TABLE…FORCE to crash, with or without explicit ROW_FORMAT. An instant ADD COLUMN crashes instantly when the ROW_FORMAT in the .frm file does not match the data file:

--source include/have_innodb.inc
 
--source include/innodb_row_format.inc
 
 
 
CREATE TABLE t(a INT PRIMARY KEY) ENGINE=InnoDB ROW_FORMAT=COMPRESSED;
 
CREATE TABLE u(a INT PRIMARY KEY) ENGINE=InnoDB;
 
FLUSH TABLES;
 
--let $datadir=`select @@datadir`
 
--remove_file $datadir/test/u.frm
 
--copy_file $datadir/test/t.frm $datadir/test/u.frm
 
ALTER TABLE u ADD COLUMN b INT;
 
DROP TABLE t,u;

10.3 a75ad73545cbf3f02355af4193fb4e199290c48f

 
mysqltest: At line 12: query 'ALTER TABLE u ADD COLUMN b INT' failed: 2013: Lost connection to MySQL server during query
 
…
 
Version: '10.3.36-MariaDB-debug-log'  socket: '/dev/shm/10.3/mysql-test/var/tmp/mysqld.1.sock'  port: 16020  Source distribution
 
2022-06-27 15:31:06 0x7f81444c0640  InnoDB: Assertion failure in file /mariadb/10.3/storage/innobase/dict/dict0mem.cc line 143
 
InnoDB: Failing assertion: dict_tf2_is_valid(flags, flags2)

The test crashes for innodb_default_row_format=COMPACT and innodb_default_row_format=REDUNDANT but not with innodb_default_row_format=DYNAMIC. The test would also crash if ROW_FORMAT=COMPACT were specified explicitly for the second table.

Comment by Marko Mäkelä [ 2022-06-27 ]

This problem had been partially fixed in MDEV-23295, MDEV-23345, MDEV-24758, but not for the case that the .frm file wrongly claims ROW_FORMAT=COMPRESSED. The fix is simple:

diff --git a/storage/innobase/handler/handler0alter.cc b/storage/innobase/handler/handler0alter.cc
 
index 22af1f91f61..0cba7d953d1 100644
 
--- a/storage/innobase/handler/handler0alter.cc
 
+++ b/storage/innobase/handler/handler0alter.cc
 
@@ -5012,8 +5012,10 @@ prepare_inplace_alter_table_dict(
 
 		/* If we promised ALGORITHM=NOCOPY or ALGORITHM=INSTANT,
 
 		we must retain the original ROW_FORMAT of the table. */
 
 		flags = (user_table->flags & (DICT_TF_MASK_COMPACT
 
+					      | DICT_TF_MASK_ZIP_SSIZE
 
 					      | DICT_TF_MASK_ATOMIC_BLOBS))
 
 			| (flags & ~(DICT_TF_MASK_COMPACT
 
+				     | DICT_TF_MASK_ZIP_SSIZE
 
 				     | DICT_TF_MASK_ATOMIC_BLOBS));
 
 	}

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