[MDEV-30832] InnoDB: Assertion failure in file /build/mariadb-10.5-mnI6vJ/mariadb-10.5-10.5.8/storage/innobase/os/os0file.cc line 3880 Created: 2023-03-10  Updated: 2023-05-02  Resolved: 2023-05-02

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

Type: Bug Priority: Major
Reporter: sugar Assignee: Marko Mäkelä
Resolution: Incomplete Votes: 0
Labels: innodb
Environment:

OS: Linux
Distro: Debian 5.10.158-2
CPU: Intel(R) Xeon(R) CPU E3-1246 v3 @ 3.50GHz
MariaDB: 10.5.8



 Description   

Lines from MariaDB log using the command "journalctl -u mariadb.service":

Feb 28 01:41:10 mariadbd[980796]: 2023-02-28 01:41:10 0x7f9b0ef67700  InnoDB: Assertion failure in file /build/mariadb-10.5-mnI6vJ/mariadb-10.5-10.5.8/storage/innobase/os/os0file.cc line 3880
Feb 28 01:41:10 mariadbd[980796]: InnoDB: Failing assertion: cb->m_err == DB_SUCCESS
Feb 28 01:41:10 mariadbd[980796]: InnoDB: We intentionally generate a memory trap.
Feb 28 01:41:10 mariadbd[980796]: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
Feb 28 01:41:10 mariadbd[980796]: InnoDB: If you get repeated assertion failures or crashes, even
Feb 28 01:41:10 mariadbd[980796]: InnoDB: immediately after the mysqld startup, there may be
Feb 28 01:41:10 mariadbd[980796]: InnoDB: corruption in the InnoDB tablespace. Please refer to
Feb 28 01:41:10 mariadbd[980796]: InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
Feb 28 01:41:10 mariadbd[980796]: InnoDB: about forcing recovery.
Feb 28 01:41:10 mariadbd[980796]: 230228  1:41:10 [ERROR] mysqld got signal 6 ;
Feb 28 01:41:10 mariadbd[980796]: This could be because you hit a bug. It is also possible that this binary
Feb 28 01:41:10 mariadbd[980796]: or one of the libraries it was linked against is corrupt, improperly built,
Feb 28 01:41:10 mariadbd[980796]: or misconfigured. This error can also be caused by malfunctioning hardware.
Feb 28 01:41:10 mariadbd[980796]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Feb 28 01:41:10 mariadbd[980796]: We will try our best to scrape up some info that will hopefully help
Feb 28 01:41:10 mariadbd[980796]: diagnose the problem, but since we have already crashed,
Feb 28 01:41:10 mariadbd[980796]: something is definitely wrong and this may fail.
Feb 28 01:41:10 mariadbd[980796]: Server version: 10.5.8-MariaDB-3
Feb 28 01:41:10 mariadbd[980796]: key_buffer_size=134217728
Feb 28 01:41:10 mariadbd[980796]: read_buffer_size=131072
Feb 28 01:41:10 mariadbd[980796]: max_used_connections=49

This continues (see how "the restart counter is at 31"):

Mar 10 11:32:14 mariadbd[538800]: 2023-03-10 11:32:14 0x7f92f0ff9700230310 11:32:14   InnoDB: Assertion failure in file /build/mariadb-10.5-mnI6vJ/mariadb-10.5-10.5.8/storage/innobase/os/os0file.cc line 3880
Mar 10 11:32:14 mariadbd[538800]: [ERROR] mysqld got signal 6 ;
Mar 10 11:32:14 mariadbd[538800]: InnoDB: Failing assertion: cb->m_err == DB_SUCCESS
Mar 10 11:32:14 mariadbd[538800]: This could be because you hit a bug. It is also possible that this binary
Mar 10 11:32:14 mariadbd[538800]: or one of the libraries it was linked against is corrupt, improperly built,
Mar 10 11:32:14 mariadbd[538800]: or misconfigured. This error can also be caused by malfunctioning hardware.
Mar 10 11:32:14 mariadbd[538800]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Mar 10 11:32:14 mariadbd[538800]: InnoDB: We intentionally generate a memory trap.
Mar 10 11:32:14 mariadbd[538800]: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
Mar 10 11:32:14 mariadbd[538800]: InnoDB: If you get repeated assertion failures or crashes, even
Mar 10 11:32:14 mariadbd[538800]: InnoDB: immediately after the mysqld startup, there may be
Mar 10 11:32:14 mariadbd[538800]: InnoDB: corruption in the InnoDB tablespace. Please refer to
Mar 10 11:32:14 mariadbd[538800]: InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
Mar 10 11:32:14 mariadbd[538800]: InnoDB: about forcing recovery.
Mar 10 11:32:14 mariadbd[538800]: We will try our best to scrape up some info that will hopefully help
Mar 10 11:32:14 mariadbd[538800]: diagnose the problem, but since we have already crashed,
Mar 10 11:32:14 mariadbd[538800]: something is definitely wrong and this may fail.
Mar 10 11:32:14 mariadbd[538800]: Server version: 10.5.8-MariaDB-3
Mar 10 11:32:14 mariadbd[538800]: key_buffer_size=134217728
Mar 10 11:32:14 mariadbd[538800]: read_buffer_size=131072
Mar 10 11:32:14 mariadbd[538800]: max_used_connections=0
Mar 10 11:32:14 mariadbd[538800]: max_threads=153
Mar 10 11:32:14 mariadbd[538800]: thread_count=0
Mar 10 11:32:14 mariadbd[538800]: It is possible that mysqld could use up to
Mar 10 11:32:14 mariadbd[538800]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467860 K  bytes of memory
Mar 10 11:32:14 mariadbd[538800]: Hope that's ok; if not, decrease some variables in the equation.
Mar 10 11:32:14 mariadbd[538800]: Thread pointer: 0x0
Mar 10 11:32:14 mariadbd[538800]: Attempting backtrace. You can use the following information to find out
Mar 10 11:32:14 mariadbd[538800]: where mysqld died. If you see no messages after this, something went
Mar 10 11:32:14 mariadbd[538800]: terribly wrong...
Mar 10 11:32:14 systemd[1]: mariadb.service: Main process exited, code=killed, status=6/ABRT
Mar 10 11:32:14 systemd[1]: mariadb.service: Failed with result 'signal'.
Mar 10 11:32:14 systemd[1]: Failed to start MariaDB 10.5.8 database server.
Mar 10 11:32:19 systemd[1]: mariadb.service: Scheduled restart job, restart counter is at 31.
Mar 10 11:32:19 systemd[1]: Stopped MariaDB 10.5.8 database server.
Mar 10 11:32:19 systemd[1]: Starting MariaDB 10.5.8 database server...
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] /usr/sbin/mariadbd (mysqld 10.5.8-MariaDB-3) starting as process 538890 ...
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Warning] Could not increase number of max_open_files to more than 16384 (request: 32190)
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Using Linux native AIO
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Uses event mutexes
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Number of pools: 1
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Completed initialization of buffer pool
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1132174484164,1132174484164
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Starting final batch to recover 1242 pages from redo log.
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [ERROR] InnoDB: Failed to read page 8282733 from file './myweirddb/extra.ibd': Table is encrypted but decrypt failed.
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Set innodb_force_recovery=1 to ignore corrupted pages.
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption
Mar 10 11:32:19 mariadbd[538890]: 2023-03-10 11:32:19 0 [Note] InnoDB: Starting shutdown...
Mar 10 11:32:20 mariadbd[538890]: 2023-03-10 11:32:20 0x7f622e7fc700  InnoDB: Assertion failure in file /build/mariadb-10.5-mnI6vJ/mariadb-10.5-10.5.8/storage/innobase/os/os0file.cc line 3880
Mar 10 11:32:20 mariadbd[538890]: InnoDB: Failing assertion: cb->m_err == DB_SUCCESS
Mar 10 11:32:20 mariadbd[538890]: InnoDB: We intentionally generate a memory trap.
Mar 10 11:32:20 mariadbd[538890]: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
Mar 10 11:32:20 mariadbd[538890]: InnoDB: If you get repeated assertion failures or crashes, even
Mar 10 11:32:20 mariadbd[538890]: InnoDB: immediately after the mysqld startup, there may be
Mar 10 11:32:20 mariadbd[538890]: InnoDB: corruption in the InnoDB tablespace. Please refer to

...Also notice that in the logs above, it also throws this error: [ERROR] InnoDB: Failed to read page 8282733 from file './myweirddb/extra.ibd': Table is encrypted but decrypt failed.

...mariadb was restarted with innodb_force_recovery = 1... and then this was done:

MariaDB [myweirddb]> select count(*) from extra;
ERROR 1034 (HY000): Index for table `extra` is corrupted: try to repair it

That DB was dropped.

Is "[ERROR] InnoDB: Failed to read page 8282733 from file './myweirddb/extra.ibd': Table is encrypted but decrypt failed" related to "InnoDB: Assertion failure in file /build/mariadb-10.5-mnI6vJ/mariadb-10.5-10.5.8/storage/innobase/os/os0file.cc line 3880"? In case it is I thought I should also include it.

Content of .cnf:

#
# These groups are read by MariaDB server.
# Use it for options that only the server (but not clients) should see
 
# this is read by the standalone daemon and embedded servers
[server]
 
# this is only for the mysqld standalone daemon
[mysqld]
 
#innodb_force_recovery = 1
 
#
# * Basic Settings
#
 
user                    = mysql
pid-file                = /run/mysqld/mysqld.pid
basedir                 = /usr
datadir                 = /var/lib/mysql
tmpdir                  = /tmp
lc-messages-dir         = /usr/share/mysql
lc-messages             = en_US
skip-external-locking
 
# Broken reverse DNS slows down connections considerably and name resolve is
# safe to skip if there are no "host by domain name" access grants
#skip-name-resolve
 
# Instead of skip-networking the default is now to listen only on
# localhost which is more compatible and is not less secure.
bind-address            = 127.0.0.1
 
#
# * Fine Tuning
#
 
#key_buffer_size        = 128M
#max_allowed_packet     = 1G
#thread_stack           = 192K
#thread_cache_size      = 8
# This replaces the startup script and checks MyISAM tables if needed
# the first time they are touched
#myisam_recover_options = BACKUP
#max_connections        = 100
#table_cache            = 64
 
#
# * Logging and Replication
#
 
# Both location gets rotated by the cronjob.
# Be aware that this log type is a performance killer.
# Recommend only changing this at runtime for short testing periods if needed!
#general_log_file       = /var/log/mysql/mysql.log
#general_log            = 1
 
# When running under systemd, error logging goes via stdout/stderr to journald
# and when running legacy init error logging goes to syslog due to
# /etc/mysql/conf.d/mariadb.conf.d/50-mysqld_safe.cnf
# Enable this if you want to have error logging into a separate file
#log_error = /var/log/mysql/error.log
# Enable the slow query log to see queries with especially long duration
#slow_query_log_file    = /var/log/mysql/mariadb-slow.log
#long_query_time        = 10
#log_slow_verbosity     = query_plan,explain
#log-queries-not-using-indexes
#min_examined_row_limit = 1000
 
# The following can be used as easy to replay backup logs or for replication.
# note: if you are setting up a replication slave, see README.Debian about
#       other settings you may need to change.
#server-id              = 1
#log_bin                = /var/log/mysql/mysql-bin.log
expire_logs_days        = 10
#max_binlog_size        = 100M
 
#
# * SSL/TLS
#
 
# For documentation, please read
# https://mariadb.com/kb/en/securing-connections-for-client-and-server/
#ssl-ca = /etc/mysql/cacert.pem
#ssl-cert = /etc/mysql/server-cert.pem
#ssl-key = /etc/mysql/server-key.pem
#require-secure-transport = on
 
#
# * Character sets
#
 
# MySQL/MariaDB default is Latin1, but in Debian we rather default to the full
# utf8 4-byte character set. See also client.cnf
character-set-server  = utf8mb4
collation-server      = utf8mb4_general_ci
 
#
# * InnoDB
#
 
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
# Read the manual for more InnoDB related options. There are many!
# Most important is to give InnoDB 80 % of the system RAM for buffer use:
# https://mariadb.com/kb/en/innodb-system-variables/#innodb_buffer_pool_size
#innodb_buffer_pool_size = 8G
 
# this is only for embedded server
[embedded]
 
# This group is only read by MariaDB servers, not by MySQL.
# If you use the same .cnf file for MySQL and MariaDB,
# you can put MariaDB-only options here
[mariadb]
 
# This group is only read by MariaDB-10.5 servers.
# If you use the same .cnf file for MariaDB of different versions,
# use this group for options that older servers don't understand
[mariadb-10.5]



 Comments   
Comment by Marko Mäkelä [ 2023-03-31 ]

Thank you for the bug report. The assertion fails at the start of an asynchronous I/O callback function:

static void io_callback(tpool::aiocb* cb)
{
  ut_a(cb->m_err == DB_SUCCESS);

Can you please try to produce full stacktraces of all threads at the time of the crash? Additionally, please show what the parameter cb points to:

print *cb

after you have used the commands up, down, frame in the thread of the crash.

Which file system and what type of storage are you using? Are there any I/O related error messages reported by sudo dmesg, sudo smartctl -a or any system logs?

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