MySQL / MariaDB error with InnoDB on startup

[GoWilkes]

I've been dealing with a problem with InnoDB for several days now. So far it looks like the short term fix is to eliminate InnoDB entirely, but of course I think I'll just have problems again when/if someone creates a new table.

It's notable that I have "innodb_force_recovery=4" set in my.cnf, a new thing trying to help resolve this problem.

Upon restarting MySQL via WHM at 3:27am, though, I see the following error in mysqld.log. I don't see any reference to database or table names, though, so where is the problem that I need to fix?

2021-05-21  3:27:03 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
2021-05-21  3:27:03 0 [Note] Event Scheduler: Purging the queue. 0 events
2021-05-21  3:27:03 0 [Note] InnoDB: Starting shutdown...
2021-05-21  3:27:03 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2021-05-21  3:27:03 0 [Note] InnoDB: Buffer pool(s) dump completed at 210521  3:27:03
2021-05-21 03:27:04 0x7f7901785700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.29/storage/innobase/trx/trx0rseg.cc line 361
InnoDB: Failing assertion: UT_LIST_GET_LEN(rseg->undo_list) == 0
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.
210521  3:27:04 [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.3.29-MariaDB-log
key_buffer_size=1073741824
read_buffer_size=131072
max_used_connections=17
max_threads=153
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1384933 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0x0 thread_stack 0x49000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x564566065a7e]
/usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x564565af8f1f]
sigaction.c:0(__restore_rt)[0x7f795c223630]
:0(__GI_raise)[0x7f795be7c387]
:0(__GI_abort)[0x7f795be7da78]
/usr/sbin/mysqld(+0x4f4e62)[0x564565834e62]
/usr/sbin/mysqld(+0xa93c3b)[0x564565dd3c3b]
/usr/sbin/mysqld(+0xa97fca)[0x564565dd7fca]
/usr/sbin/mysqld(+0xa67202)[0x564565da7202]
/usr/sbin/mysqld(+0x95162f)[0x564565c9162f]
/usr/sbin/mysqld(_Z22ha_finalize_handlertonP13st_plugin_int+0x34)[0x564565afb5d4]
/usr/sbin/mysqld(+0x5e34d4)[0x5645659234d4]
/usr/sbin/mysqld(+0x5e636e)[0x56456592636e]
/usr/sbin/mysqld(_Z15plugin_shutdownv+0x73)[0x564565926db3]
/usr/sbin/mysqld(+0x51864a)[0x56456585864a]
/usr/sbin/mysqld(_Z10unireg_endv+0x3b)[0x56456585892b]
/usr/sbin/mysqld(+0x51c50f)[0x56456585c50f]
/usr/sbin/mysqld(kill_server_thread+0xe)[0x56456585c72e]
pthread_create.c:0(start_thread)[0x7f795c21bea5]
/lib64/libc.so.6(clone+0x6d)[0x7f795bf449fd]
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             62987                62987                processes
Max open files            40000                40000                files    
Max locked memory         65536                65536                bytes    
Max address space         unlimited            unlimited            bytes    
Max file locks            unlimited            unlimited            locks    
Max pending signals       289154               289154               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: core

2021-05-21  3:27:05 0 [Note] InnoDB: Using Linux native AIO
2021-05-21  3:27:05 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2021-05-21  3:27:05 0 [Note] InnoDB: Uses event mutexes
2021-05-21  3:27:05 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
2021-05-21  3:27:05 0 [Note] InnoDB: Number of pools: 1
2021-05-21  3:27:05 0 [Note] InnoDB: Using SSE2 crc32 instructions
2021-05-21  3:27:05 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2021-05-21  3:27:05 0 [Note] InnoDB: Completed initialization of buffer pool
2021-05-21  3:27:05 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

** these next 2 lines repeat thousands of times **
2021-05-21  3:27:05 0 [ERROR] InnoDB: Page [page id: space=0, page number=313] log sequence number 690626571434 is in the future! Current system log sequence number 690626204880.
2021-05-21  3:27:05 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
**

2021-05-21  3:27:05 0 [Note] InnoDB: 3 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2021-05-21  3:27:05 0 [Note] InnoDB: Trx id counter is 7780274540492096086
2021-05-21  3:27:05 0 [ERROR] InnoDB: Page [page id: space=0, page number=0] log sequence number 690626642182 is in the future! Current system log sequence number 690626204880.
2021-05-21  3:27:05 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
2021-05-21  3:27:05 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2021-05-21  3:27:05 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2021-05-21  3:27:05 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-05-21  3:27:05 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-05-21  3:27:05 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-05-21  3:27:05 0 [Note] InnoDB: 10.3.29 started; log sequence number 690626204871; transaction id 7780274540492096086
2021-05-21  3:27:05 0 [Note] InnoDB: !!! innodb_force_recovery is set to 4 !!!
2021-05-21  3:27:05 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2021-05-21  3:27:05 0 [Note] Plugin 'FEEDBACK' is disabled.
2021-05-21  3:27:05 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`plugin` in the cache. Attempting to load the tablespace with space id 28
2021-05-21  3:27:05 0 [Warning] InnoDB: Allocated tablespace ID 28 for mysql/plugin, old maximum was 0

** these next 2 lines repeat thousands of times **
2021-05-21  3:27:05 0 [ERROR] InnoDB: Page [page id: space=0, page number=348] log sequence number 690626230010 is in the future! Current system log sequence number 690626204880.
2021-05-21  3:27:05 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
**

2021-05-21  3:27:05 0 [Note] Recovering after a crash using tc.log
2021-05-21  3:27:05 0 [Note] Starting crash recovery...
2021-05-21  3:27:05 0 [Note] Crash recovery finished.
2021-05-21  3:27:05 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`servers` in the cache. Attempting to load the tablespace with space id 31
2021-05-21  3:27:05 0 [Note] Server socket created on IP: '::'.
2021-05-21  3:27:05 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_leap_second` in the cache. Attempting to load the tablespace with space id 12
2021-05-21  3:27:05 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_name` in the cache. Attempting to load the tablespace with space id 8
2021-05-21  3:27:05 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone` in the cache. Attempting to load the tablespace with space id 9
2021-05-21  3:27:05 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_transition_type` in the cache. Attempting to load the tablespace with space id 11
2021-05-21  3:27:05 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_transition` in the cache. Attempting to load the tablespace with space id 10
2021-05-21  3:27:05 2 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`gtid_slave_pos` in the cache. Attempting to load the tablespace with space id 27
2021-05-21  3:27:05 0 [Note] Reading of all Master_info entries succeeded
2021-05-21  3:27:05 0 [Note] Added new Master_info '' to hash table
2021-05-21  3:27:05 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.29-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
2021-05-21  3:27:06 0 [Note] InnoDB: Buffer pool(s) load completed at 210521  3:27:06

It looks like this repeated at 3:27:10, then again at 3:42:12. So I guess MySQL is restarting on a loop or something?

 

[GoWilkes]

Also, just discovered that if I remove innodb_force_recovery then MySQL won't restart:

Job for mariadb.service failed because a fatal signal was delivered to the control process. See "systemctl status mariadb.service" and "journalctl -xe" for details.

 

[cPRex]

Hey hey! There's really not much we can do either through the forums here or through our support team for these issues. We have a great guide on this work here:

InnoDB Corruption Repair Guide

Please note that cPanel, LLC only supports the cPanel-provided software and does not provide general system-administration services. While this guide is designed to help, it is always suggested th...

support.cpanel.net

but it's usually best to get outside help from a database specialist to ensure you avoid data loss.

 

[GoWilkes]

Thanks for the link, @cPRex! I read through it, and I've narrowed the problem down to this:

B/1.2 InnoDB Time-Traveling & Log Sequence Number Errors

The take away from it:

Somewhere down the line, whether it was an unexpected restart, memory issues, file system corruption, replication issues, manual changes to the InnoDB files, or otherwise, these LSNs became out of "sync". Whether its crashing your server or not, this should be treated as legitimate corruption, and is generally something you'll want to address

That's all good, but what it doesn't say is how to narrow down which table(s) are causing the problem, and/or how to permanently fix them?

The log file hasn't had any updates since 4:30am (no clue why, I went to bed at 4), but that last series of errors points to the "sys" and "mysql" databases:

# These first lines were at 3:55am
2021-05-21  3:55:26 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`servers` in the cache. Attempting to load the tablespace with space id 31
2021-05-21  3:55:26 0 [Note] Server socket created on IP: '::'.
2021-05-21  3:55:26 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_leap_second` in the cache. Attempting to load the tablespace with space id 12
2021-05-21  3:55:26 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_name` in the cache. Attempting to load the tablespace with space id 8
2021-05-21  3:55:26 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone` in the cache. Attempting to load the tablespace with space id 9
2021-05-21  3:55:26 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_transition_type` in the cache. Attempting to load the tablespace with space id 11
2021-05-21  3:55:26 0 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`time_zone_transition` in the cache. Attempting to load the tablespace with space id 10
2021-05-21  3:55:26 0 [Note] InnoDB: Buffer pool(s) load completed at 210521  3:55:26
2021-05-21  3:55:26 2 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`gtid_slave_pos` in the cache. Attempting to load the tablespace with space id 27
2021-05-21  3:55:26 0 [Note] Reading of all Master_info entries succeeded
2021-05-21  3:55:26 0 [Note] Added new Master_info '' to hash table
2021-05-21  3:55:26 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.29-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

# this error was by itself at 4:14
2021-05-21  4:14:31 5996 [ERROR] InnoDB: Failed to find tablespace for table `sys`.`sys_config` in the cache. Attempting to load the tablespace with space id 21

# then these errors were at 4:30
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`server_cost` in the cache. Attempting to load the tablespace with space id 19
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`innodb_table_stats` in the cache. Attempting to load the tablespace with space id 30
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`transaction_registry` in the cache. Attempting to load the tablespace with space id 32
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`slave_master_info` in the cache. Attempting to load the tablespace with space id 16
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`innodb_index_stats` in the cache. Attempting to load the tablespace with space id 29
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`help_keyword` in the cache. Attempting to load the tablespace with space id 7
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`slave_relay_log_info` in the cache. Attempting to load the tablespace with space id 15
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`gtid_executed` in the cache. Attempting to load the tablespace with space id 18
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`help_relation` in the cache. Attempting to load the tablespace with space id 6
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`help_topic` in the cache. Attempting to load the tablespace with space id 4
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`slave_worker_info` in the cache. Attempting to load the tablespace with space id 17
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`engine_cost` in the cache. Attempting to load the tablespace with space id 20
2021-05-21  4:30:08 9215 [ERROR] InnoDB: Failed to find tablespace for table `mysql`.`help_category` in the cache. Attempting to load the tablespace with space id 5

Based on that, I'm guessing that the corruption is in the main MySQL tables instead of account databases?

How do I restore (reinstall?) these?

I was finally able to get a hosting client's account fixed last night by exporting the database to .SQL, editing the file to replace ENGINE=InnoDB to Engine=MyISAM, creating a new database in the account using cPanel and assigning the same user to it, importing the backed up .SQL to it, deleting the old one manually via FTP (I got an error when trying to drop it via cPanel or PMA), and then modifying Wordpress (/wp/wp-config.php) to point to the new database. I couldn't just rename it to the old database name, because MySQL kept recognizing the tables as InnoDB (presumably from cache).

That's obviously not an option with system files. I can back it up and import it to a new database, but that doesn't do me a whole lot of good

it's usually best to get outside help from a database specialist to ensure you avoid data loss.

Great in theory, but I've seen a YoY drop in ad revenue for the last 4 years, and then it dropped to virtually nil during COVID. So unless you know some kind hearted specialists that can do it pro bono, I'm kinda stuck figuring it out for myself

 

[cPRex]

I don't have much else to provide on my end. We're strictly hands-off when it comes to InnoDB issues. Another user may chime in with their experience.

 

[GoWilkes]

I don't blame you, I wouldn't touch it with a 10-foot pole, either, if I had a choice! LOL

I had originally changed several of my tables with high-inserts low-reads (more or less logs) to InnoDB because it was supposed to be preferable, but I never noticed any performance issues with it. And more recently, I've learned that the type of problem I'm having is VERY common:

InnoDB is in read only mode.

johnny.heliohost.org I'm trying to connect mysql from node. It shows InnoDB is in read only modewhen I write/update/drop tables.Please help. It was working properly before. Suddenly it started showing this error.

www.helionet.org

There appears to be no reason for me to have it, and I'm at a loss on why Wordpress uses it by default. I WISH that there was a way for me to change everything in the database to MyISAM and then lose InnoDB entirely, but alas, it looks like I have no choice in the matter