[MDEV-25031] Not applying INSERT_REUSE_REDUNDANT due to corruption on page Created: 2021-03-02  Updated: 2023-10-31  Resolved: 2021-03-11

Status: Closed
Project: MariaDB Server
Component/s: Backup, Storage Engine - InnoDB
Affects Version/s: 10.5.4, 10.5.2, 10.5.3, 10.5.5, 10.5.6, 10.5.7, 10.5.8, 10.5.9
Fix Version/s: 10.5.10

Type: Bug Priority: Blocker
Reporter: Ben Utzer Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: corruption, recovery, regression-10.5
Environment:

Arch Linux, current updates installed: Linux 5.10.19-1-lts #1 SMP Fri, 26 Feb 2021

Issue Links:
Blocks
blocks MDEV-24197 Prepare step of backup failing on lar... Closed
Duplicate
is duplicated by MDEV-25569 Restore crashed due to Data structure... Closed
Problem/Incident
is caused by MDEV-21724 Optimize page_cur_insert_rec_low() re... Closed
Relates
relates to MDEV-24197 Prepare step of backup failing on lar... Closed
relates to MDEV-24705 add check that LSN of the last skippe... Closed
relates to MDEV-25745 InnoDB recovery fails with [ERROR] In... Closed

 Description   

I get this fault below, from the journal. I am not in a position to conclude if this is a bug, but it happens repeatedly and if there is a small chance it is a bug I would like to submit the fault here to have someone exclude it is a bug. Sorry to bother your with this. I am thankful for any effort taken and also for any tip what to look into specifically.

I did check the filesystem, but there was no fault there, as far as I can see. 

Mär 02 12:26:40 social systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL
 
Mär 02 12:26:40 social systemd[1]: mariadb.service: Failed with result 'signal'.
 
Mär 02 12:26:45 social systemd[1]: mariadb.service: Scheduled restart job, restart counter is at 1.
 
Mär 02 12:26:45 social systemd[1]: Stopped MariaDB 10.5.9 database server.
 
Mär 02 12:26:45 social systemd[1]: Starting MariaDB 10.5.9 database server...
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] /usr/bin/mariadbd (mysqld 10.5.9-MariaDB) starting as process 319571 ...
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Warning] Could not increase number of max_open_files to more than 16384 (request: 32425)
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] InnoDB: Uses event mutexes
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] InnoDB: Number of pools: 1
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] InnoDB: Using generic crc32 instructions
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] InnoDB: Using Linux native AIO
 
Mär 02 12:26:46 social mariadbd[319571]: 2021-03-02 12:26:46 0 [Note] InnoDB: Initializing buffer pool, total size = 17179869184, chunk size = 134217728
 
Mär 02 12:26:47 social mariadbd[319571]: 2021-03-02 12:26:47 0 [Note] InnoDB: Completed initialization of buffer pool
 
Mär 02 12:26:47 social mariadbd[319571]: 2021-03-02 12:26:47 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
Mär 02 12:26:47 social mariadbd[319571]: 2021-03-02 12:26:47 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1950138044187,1950909387225
 
Mär 02 12:27:02 social mariadbd[319571]: 2021-03-02 12:27:02 0 [Note] InnoDB: Read redo log up to LSN=1951723032064
 
Mär 02 12:27:02 social mariadbd[319571]: 2021-03-02 12:27:02 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77357.
 
Mär 02 12:27:02 social mariadbd[319571]: 2021-03-02 12:27:02 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77356.
 
Mär 02 12:27:06 social mariadbd[319571]: 2021-03-02 12:27:06 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77362.
 
Mär 02 12:27:06 social mariadbd[319571]: 2021-03-02 12:27:06 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77363.
 
Mär 02 12:27:07 social mariadbd[319571]: 2021-03-02 12:27:07 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77362.
 
Mär 02 12:27:07 social mariadbd[319571]: 2021-03-02 12:27:07 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77364.
 
Mär 02 12:27:07 social mariadbd[319571]: 2021-03-02 12:27:07 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77363.
 
Mär 02 12:27:07 social mariadbd[319571]: 2021-03-02 12:27:07 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77365.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77364.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77366.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77365.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77367.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77366.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77368.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77367.
 
Mär 02 12:27:08 social mariadbd[319571]: 2021-03-02 12:27:08 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77369.
 
Mär 02 12:27:09 social mariadbd[319571]: 2021-03-02 12:27:09 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77368.
 
Mär 02 12:27:09 social mariadbd[319571]: 2021-03-02 12:27:09 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77370.
 
Mär 02 12:27:09 social mariadbd[319571]: 2021-03-02 12:27:09 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77369.
 
Mär 02 12:27:09 social mariadbd[319571]: 2021-03-02 12:27:09 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77371.
 
Mär 02 12:27:10 social mariadbd[319571]: 2021-03-02 12:27:10 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77370.
 
Mär 02 12:27:10 social mariadbd[319571]: 2021-03-02 12:27:10 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77372.
 
Mär 02 12:27:10 social mariadbd[319571]: 2021-03-02 12:27:10 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77371.
 
Mär 02 12:27:10 social mariadbd[319571]: 2021-03-02 12:27:10 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77373.
 
Mär 02 12:27:11 social mariadbd[319571]: 2021-03-02 12:27:11 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77374, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77372.
 
Mär 02 12:27:11 social mariadbd[319571]: 2021-03-02 12:27:11 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77375, since the redo log references ./ylms_friendica/process.ibd with space ID 77373.
 
Mär 02 12:27:12 social mariadbd[319571]: 2021-03-02 12:27:12 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=4]
 
Mär 02 12:27:12 social mariadbd[319571]: 2021-03-02 12:27:12 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
Mär 02 12:27:12 social mariadbd[319571]: 2021-03-02 12:27:12 0 [ERROR] [FATAL] InnoDB: Trying to read 16384 bytes at 13844040843264 outside the bounds of the file: ./ibdata1
 
Mär 02 12:27:12 social mariadbd[319571]: 210302 12:27:12 [ERROR] mysqld got signal 6 ;
 
Mär 02 12:27:12 social mariadbd[319571]: This could be because you hit a bug. It is also possible that this binary
 
Mär 02 12:27:12 social mariadbd[319571]: or one of the libraries it was linked against is corrupt, improperly built,
 
Mär 02 12:27:12 social mariadbd[319571]: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Mär 02 12:27:12 social mariadbd[319571]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
Mär 02 12:27:12 social mariadbd[319571]: We will try our best to scrape up some info that will hopefully help
 
Mär 02 12:27:12 social mariadbd[319571]: diagnose the problem, but since we have already crashed,
 
Mär 02 12:27:12 social mariadbd[319571]: something is definitely wrong and this may fail.
 
Mär 02 12:27:12 social mariadbd[319571]: Server version: 10.5.9-MariaDB
 
Mär 02 12:27:12 social mariadbd[319571]: key_buffer_size=134217728
 
Mär 02 12:27:12 social mariadbd[319571]: read_buffer_size=131072
 
Mär 02 12:27:12 social mariadbd[319571]: max_used_connections=0
 
Mär 02 12:27:12 social mariadbd[319571]: max_threads=388
 
Mär 02 12:27:12 social mariadbd[319571]: thread_count=0
 
Mär 02 12:27:12 social mariadbd[319571]: It is possible that mysqld could use up to
 
Mär 02 12:27:12 social mariadbd[319571]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 985198 K  bytes of memory
 
Mär 02 12:27:12 social mariadbd[319571]: Hope that's ok; if not, decrease some variables in the equation.
 
Mär 02 12:27:12 social mariadbd[319571]: Thread pointer: 0x0
 
Mär 02 12:27:12 social mariadbd[319571]: Attempting backtrace. You can use the following information to find out
 
Mär 02 12:27:12 social mariadbd[319571]: where mysqld died. If you see no messages after this, something went
 
Mär 02 12:27:12 social mariadbd[319571]: terribly wrong...
 
Mär 02 12:27:12 social mariadbd[319571]: stack_bottom = 0x0 thread_stack 0x49000
 
Mär 02 12:27:12 social mariadbd[319571]: ??:0(my_print_stacktrace)[0x55ba2dc07ebf]
 
Mär 02 12:27:12 social mariadbd[319571]: ??:0(handle_fatal_signal)[0x55ba2d6eb650]
 
Mär 02 12:27:12 social mariadbd[319571]: sigaction.c:0(__restore_rt)[0x7f9a2aae4960]
 
Mär 02 12:27:13 social mariadbd[319571]: :0(__GI_raise)[0x7f9a2a5fbef5]
 
Mär 02 12:27:13 social mariadbd[319571]: :0(__GI_abort)[0x7f9a2a5e5862]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x55ba2d3ca9da]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x55ba2d3de0c5]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x55ba2d3de10c]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(std::unique_lock<std::mutex>::unlock())[0x55ba2db27131]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(std::unique_lock<std::mutex>::unlock())[0x55ba2db28385]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(std::unique_lock<std::mutex>::unlock())[0x55ba2db17401]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(std::unique_lock<std::mutex>::unlock())[0x55ba2dadedd1]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(std::unique_lock<std::mutex>::unlock())[0x55ba2dad51cc]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(std::unique_lock<std::mutex>::unlock())[0x55ba2dadb6d0]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x55ba2d3c3e1d]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x55ba2d9f192a]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(ha_initialize_handlerton(st_plugin_int*))[0x55ba2d6ee193]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(sys_var_pluginvar::sys_var_pluginvar(sys_var_chain*, char const*, st_plugin_int*, st_mysql_sys_var*))[0x55ba2d5018dd]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(plugin_init(int*, char**, int))[0x55ba2d502a04]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(unireg_abort)[0x55ba2d42c89a]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(mysqld_main(int, char**))[0x55ba2d432725]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(__libc_start_main)[0x7f9a2a5e6b25]
 
Mär 02 12:27:13 social mariadbd[319571]: ??:0(_start)[0x55ba2d4266fe]
 
Mär 02 12:27:13 social mariadbd[319571]: The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
 
Mär 02 12:27:13 social mariadbd[319571]: information that should help you find out what is causing the crash.
 
Mär 02 12:27:13 social mariadbd[319571]: Writing a core file...
 
Mär 02 12:27:13 social mariadbd[319571]: Working directory at /var/lib/mysql
 
Mär 02 12:27:13 social mariadbd[319571]: Resource Limits:
 
Mär 02 12:27:13 social mariadbd[319571]: Limit                     Soft Limit           Hard Limit           Units
 
Mär 02 12:27:13 social mariadbd[319571]: Max cpu time              unlimited            unlimited            seconds
 
Mär 02 12:27:13 social mariadbd[319571]: Max file size             unlimited            unlimited            bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max data size             unlimited            unlimited            bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max stack size            8388608              unlimited            bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max core file size        unlimited            unlimited            bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max resident set          unlimited            unlimited            bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max processes             79997                79997                processes
 
Mär 02 12:27:13 social mariadbd[319571]: Max open files            16384                16384                files
 
Mär 02 12:27:13 social mariadbd[319571]: Max locked memory         65536                65536                bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max address space         unlimited            unlimited            bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max file locks            unlimited            unlimited            locks
 
Mär 02 12:27:13 social mariadbd[319571]: Max pending signals       79997                79997                signals
 
Mär 02 12:27:13 social mariadbd[319571]: Max msgqueue size         819200               819200               bytes
 
Mär 02 12:27:13 social mariadbd[319571]: Max nice priority         0                    0
 
Mär 02 12:27:13 social mariadbd[319571]: Max realtime priority     0                    0
 
Mär 02 12:27:13 social mariadbd[319571]: Max realtime timeout      unlimited            unlimited            us
 
Mär 02 12:27:13 social mariadbd[319571]: Core pattern: |/usr/lib/systemd/systemd-coredump %P %u %g %s %t %c %h
 
Mär 02 12:27:15 social systemd[1]: mariadb.service: Main process exited, code=dumped, status=6/ABRT
 
Mär 02 12:27:15 social systemd[1]: mariadb.service: Failed with result 'core-dump'.
 
Mär 02 12:27:15 social systemd[1]: Failed to start MariaDB 10.5.9 database server.



 Comments   
Comment by Marko Mäkelä [ 2021-03-02 ]

utzer, thank you. Yes, this looks like a bug: crash recovery would fail. We introduced a consistency check in MDEV-24705 to catch exactly this type of failure, but curiously no such message is present in the log.

The failure is related to ROW_FORMAT=REDUNDANT tables, which ceased to be the default in MySQL 5.0.3. What had happened to the server before the first such failed crash recovery? Was the database restored from a backup? Which MariaDB version had last been successfully used on the data directory?

Comment by Ben Utzer [ 2021-03-02 ]

The failure is related to ROW_FORMAT=REDUNDANT tables, which ceased to be the default in MySQL 5.0.3. What had happened to the server before the first such failed crash recovery?
I had a crash before, I thought it was the same reason, it was yesterday, I will check more closely. After that crash I started MariaDB with 

innodb_force_recovery = 1

, but let me check what happened before.
I updated from 10.5.8 to 10.5.9 on 24 Feb. 2021 12:39 pm.
I increased the max_open_files at some point because I saw the notes in the log in the last days, don't remember when exactly. I also increased the max_allowed_packet the last days, when I moved some files around and saw the warning in the log.

I got some warnings like this before the first crash:

Feb 28 09:23:04 social mariadbd[864708]: 2021-02-28  9:23:04 502983 [Warning] Aborted connection 502983 to db: 'ylms_friendica' user: 'root' host: 'localhost' (Got an error writing communication packets)
 
Feb 28 10:23:19 social mariadbd[864708]: 2021-02-28 10:23:19 450847 [Warning] Aborted connection 450847 to db: 'ylms_friendica' user: 'ylms' host: 'localhost' (Got an error reading communication packets)
 
Feb 28 15:59:47 social mariadbd[864708]: 2021-02-28 15:59:46 533631 [Warning] Aborted connection 533631 to db: 'ylms_friendica' user: 'root' host: 'localhost' (Got an error writing communication packets)
 
Feb 28 20:45:01 social systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL
 
Feb 28 20:45:01 social systemd[1]: mariadb.service: Failed with result 'signal'.
 
Feb 28 20:45:06 social systemd[1]: mariadb.service: Scheduled restart job, restart counter is at 1.
 
Feb 28 20:45:06 social systemd[1]: Stopped MariaDB 10.5.9 database server.
 
Feb 28 20:45:06 social systemd[1]: Starting MariaDB 10.5.9 database server...
 
Feb 28 21:00:07 social systemd[1]: mariadb.service: start operation timed out. Terminating.
 
Feb 28 21:15:07 social systemd[1]: mariadb.service: State 'stop-sigterm' timed out. Skipping SIGKILL.

Was lazy then and rebooted the machine.

From that reboot to the next crash:

Feb 28 21:24:51 social systemd[1]: Starting MariaDB 10.5.9 database server...
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Note] /usr/bin/mariadbd (mysqld 10.5.9-MariaDB) starting as process 409 ...
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Warning] Could not increase number of max_open_files to more than 16384 (request: 32425)
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Warning] The parameter innodb_buffer_pool_instances is deprecated and has no effect.
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Note] InnoDB: Uses event mutexes
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Note] InnoDB: Number of pools: 1
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Note] InnoDB: Using generic crc32 instructions
 
Feb 28 21:24:51 social mariadbd[409]: 2021-02-28 21:24:51 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Using Linux native AIO
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Initializing buffer pool, total size = 17179869184, chunk size = 134217728
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Completed initialization of buffer pool
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1915242122093,1915247067683
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/cache.ibd' with space ID 77141, since the redo log references ./ylms_friendica/cache.ibd with space ID 77084.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/oembed.ibd' with space ID 77144, since the redo log references ./ylms_friendica/oembed.ibd with space ID 77087.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/parsed_url.ibd' with space ID 77145, since the redo log references ./ylms_friendica/parsed_url.ibd with space ID 77088.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/session.ibd' with space ID 77147, since the redo log references ./ylms_friendica/session.ibd with space ID 77090.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77136.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77137.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/auth_codes.ibd' with space ID 77140, since the redo log references ./ylms_friendica/auth_codes.ibd with space ID 77083.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/challenge.ibd' with space ID 77142, since the redo log references ./ylms_friendica/challenge.ibd with space ID 77085.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/locks.ibd' with space ID 77143, since the redo log references ./ylms_friendica/locks.ibd with space ID 77086.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/profile_check.ibd' with space ID 77146, since the redo log references ./ylms_friendica/profile_check.ibd with space ID 77089.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/tokens.ibd' with space ID 77148, since the redo log references ./ylms_friendica/tokens.ibd with space ID 77091.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77138.
 
Feb 28 21:24:52 social mariadbd[409]: 2021-02-28 21:24:52 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77139.
 
Feb 28 21:24:54 social mariadbd[409]: 2021-02-28 21:24:54 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77138.
 
Feb 28 21:24:54 social mariadbd[409]: 2021-02-28 21:24:54 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77149.
 
Feb 28 21:24:54 social mariadbd[409]: 2021-02-28 21:24:54 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77139.
 
Feb 28 21:24:54 social mariadbd[409]: 2021-02-28 21:24:54 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77150.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77149.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77151.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77150.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77152.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77151.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77153.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77152.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77154.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77153.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77155.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77154.
 
Feb 28 21:24:55 social mariadbd[409]: 2021-02-28 21:24:55 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77156.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77155.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77157.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77156.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77158.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77157.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77159.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77158.
 
Feb 28 21:24:56 social mariadbd[409]: 2021-02-28 21:24:56 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77160.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77159.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77161.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77160.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77162.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77161.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77163.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77162.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77164.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77163.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77165.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77164.
 
Feb 28 21:24:57 social mariadbd[409]: 2021-02-28 21:24:57 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77166.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77165.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77167.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77166.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77168.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77167.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77169.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77168.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77170.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77169.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77171.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77170.
 
Feb 28 21:24:58 social mariadbd[409]: 2021-02-28 21:24:58 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77172.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77171.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77173.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77172.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77174.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77173.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77175.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77174.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77176.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77175.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77177.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77176.
 
Feb 28 21:24:59 social mariadbd[409]: 2021-02-28 21:24:59 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77178.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77177.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77179.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77178.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77180.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77179.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77181.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77180.
 
Feb 28 21:25:00 social mariadbd[409]: 2021-02-28 21:25:00 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77182.
 
Feb 28 21:25:01 social mariadbd[409]: 2021-02-28 21:25:01 0 [Note] InnoDB: Ignoring data file './ylms_friendica/workerqueue.ibd' with space ID 77183, since the redo log references ./ylms_friendica/workerqueue.ibd with space ID 77181.
 
Feb 28 21:25:01 social mariadbd[409]: 2021-02-28 21:25:01 0 [Note] InnoDB: Ignoring data file './ylms_friendica/process.ibd' with space ID 77184, since the redo log references ./ylms_friendica/process.ibd with space ID 77182.
 
Feb 28 21:25:01 social mariadbd[409]: 2021-02-28 21:25:01 0 [Note] InnoDB: Starting final batch to recover 154483 pages from redo log.
 
Feb 28 21:25:07 social mariadbd[409]: 2021-02-28 21:25:07 0 [Note] InnoDB: To recover: 71269 pages from log
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: Last binlog file './mysql-bin.000028', position 599081215
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: 128 rollback segments are active.
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: 10.5.9 started; log sequence number 1916230170963; transaction id 4910077199
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] Server socket created on IP: '127.0.0.1'.
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] Reading of all Master_info entries succeeded
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] Added new Master_info '' to hash table
 
Feb 28 21:25:24 social mariadbd[409]: 2021-02-28 21:25:24 0 [Note] /usr/bin/mariadbd: ready for connections.
 
Feb 28 21:25:24 social mariadbd[409]: Version: '10.5.9-MariaDB'  socket: '/run/mysqld/mysqld.sock'  port: 3306  Arch Linux
 
Feb 28 21:25:24 social systemd[1]: Started MariaDB 10.5.9 database server.
 
Feb 28 21:26:47 social mariadbd[409]: 2021-02-28 21:26:47 0 [Note] InnoDB: Buffer pool(s) load completed at 210228 21:26:47
 
Feb 28 21:39:41 social mariadbd[409]: 2021-02-28 21:39:41 2440 [Warning] Aborted connection 2440 to db: 'ylms_friendica' user: 'root' host: 'localhost' (Got an error writing communication packets)
 
Mär 01 04:47:11 social mariadbd[409]: 2021-03-01  4:47:11 43351 [Warning] Aborted connection 43351 to db: 'ylms_friendica' user: 'root' host: 'localhost' (Got an error writing communication packets)
 
Mär 01 09:26:03 social mariadbd[409]: 2021-03-01  9:26:03 9 [Warning] Aborted connection 9 to db: 'ylms_friendica' user: 'ylms' host: 'localhost' (Got an error reading communication packets)
 
Mär 01 11:26:09 social mariadbd[409]: 2021-03-01 11:26:09 73467 [Warning] Aborted connection 73467 to db: 'ylms_friendica' user: 'root' host: 'localhost' (Got an error writing communication packets)
 
Mär 01 12:45:19 social systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL
 
Mär 01 12:45:19 social systemd[1]: mariadb.service: Failed with result 'signal'.
 
Mär 01 12:45:24 social systemd[1]: mariadb.service: Scheduled restart job, restart counter is at 1.
 
Mär 01 12:45:24 social systemd[1]: Stopped MariaDB 10.5.9 database server.

Was the database restored from a backup?
No.

Which MariaDB version had last been successfully used on the data directory?
I would say 10.5.8.

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

utzer, thank you. I wonder what caused the following, and which server version was running at that point:

Feb 28 20:45:01 social systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL

Based on what you wrote, I would assume that it was already running 10.5.9 at that point. Still, what would have killed the process forcibly? Can you get more logs from the server somehow? Or enable core dumps, so that we could get stack traces for the next crash. Those stack traces might give some hint on what is going on.

I am afraid that it will now be hard to say what is the consequence of the corrupted page (which is the result of skipping some redo log records) and what is the original cause of the corruption. We cover crash recovery and backup in our internal tests, and there is no known problem in this area.

Finally, one thing that might explain this is faulty hardware. Have you checked sudo smartctl -a on your storage devices, and run sudo memtester to rule out problems in those areas?

Comment by Ben Utzer [ 2021-03-02 ]

As for the killed message I now found that this seems to be a system config problem, as it was out of memory on that VM. 

Feb 28 20:44:56 social kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/mariadb.service,task=mariadbd,pid=864708,uid=974
 
Feb 28 20:44:56 social kernel: Out of memory: Killed process 864708 (mariadbd) total-vm:20868696kB, anon-rss:3813012kB, file-rss:0kB, shmem-rss:0kB, UID:974 pgtables:39276kB oom_score_adj:0
 
Feb 28 20:45:01 social kernel: oom_reaper: reaped process 864708 (mariadbd), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
 
Feb 28 20:45:01 social systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL

For the host I ran smartctl lately, for the vm I ran btrfs scrub yesterday and a check now (it is running and mounted, but there is no errors found in both).

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

Thank you, utzer (nice pseudonym, by the way). The reason for the crash has been explained, and this ticket will be covering the incorrect crash recovery, which will likely lead to corruption.

It is possible that the incorrect recovery was introduced by MDEV-21724 in MariaDB Server 10.5. I have asked for a more extensive test of ROW_FORMAT=REDUNDANT to be run, hoping that we will be able to repeat a similar failure. I would think that most of the time, our internal tests would be covering the recovery of the other page format (COMPACT or DYNAMIC).

Comment by Matthias Leich [ 2021-03-05 ] 

I was able to achieve during RQG testing
 
 
 
...  many times [Note] InnoDB: Ignoring data file ...
 
2021-03-05  7:09:13 0 [Note] InnoDB: Ignoring data file 'test/t5.ibd' with space ID 27, since the redo log references test/t5.ibd with space ID 23.
 
 2021-03-05  7:09:16 0 [Note] InnoDB: Starting final batch to recover 763 pages from redo log.
 
 2021-03-05  7:09:19 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=26, page number=49]
 
 2021-03-05  7:09:19 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
 2021-03-05  7:09:19 0 [ERROR] InnoDB: Not applying DELETE_ROW_FORMAT_REDUNDANT due to corruption on [page id: space=26, page number=49]
 
 2021-03-05  7:09:19 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
 2021-03-05  7:09:20 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1473] with error Data structure corruption
 
 [00] FATAL ERROR: 2021-03-05 07:09:20 mariabackup: innodb_init() returned 39 (Data structure corruption).
 
 
 
sdp:/home/mleich/RQG_O/storage/1614954603/MDEV-25031/dev/shm/vardir/1614954603/76/1_clone/rr
 
_RR_TRACE_DIR="." rr replay --mark-stdio                                  (the first prepare)
 
_RR_TRACE_DIR="." rr replay --mark-stdio mariabackup-0   (the backup before it)
 
 
 
Archive:
 
sdp:/home/mleich/RQG_O/storage/1614954603/000934.tgz
 
 
 
Work flow:
 
1. Start the server and load some initial data
 
2. Two sessions run a DDL/DML mix
 
3. During 2. is ongoing
 
     mariabackup --backup
 
    Example: bin/mariabackup --host=127.0.0.1 --user=root --password=''  --innodb-use-native-aio=0  --port=26100 --backup --datadir=/dev/shm/vardir/1614954603/76/1/data --target-dir=/dev/shm/vardir/1614954603/76/1_clone/data
 
     Make a backup/copy of the data written by mariabackup --backup
 
     in /home/mleich/RQG_O/storage/1614954603/MDEV-25031/dev/shm/vardir/1614954603/76/1/data_backup
 
     mariabackup --prepare ...    <----  I got the messages above at this step.
 
     Example: mariabackup --host=127.0.0.1 --user=root --password=''  --innodb-use-native-aio=0  --port=26104 --prepare --target-dir=/dev/shm/vardir/1614954603/76/1_clone/data
 
     mariabackup --prepare ... again in that directory   (users do not need to run a second prepare)
 
     Start a server on the data there + check consistency
 
In most of the RQG tests all goes well.
 
 
 
origin/10.6 33cf577ad86f3a7dd6ff86fee4ecd9c535161f02 2021-03-05T14:26:14+02:00
 
The server claims to be 10.6.0.
 
 
 
RQG
 
====
 
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
 
 
perl rqg.pl \              
--grammar=conf/mariadb/table_stress_innodb_nocopy1.yy \
 
--gendata=conf_redundant/mariadb/table_stress.zz \
 
--gendata_sql=conf/mariadb/table_stress.sql \
 
--reporters=Mariabackup_linux \
 
--mysqld=--innodb_use_native_aio=1 \
 
--mysqld=--innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--lock-wait-timeout=86400 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--no-mask \
 
--queries=10000000 \
 
--seed=random \
 
--reporters=Backtrace \
 
--reporters=ErrorLog \
 
--reporters=Deadlock1 \
 
--validators=None \
 
--mysqld=--log_output=none \
 
--mysqld=--log-bin \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--engine=InnoDB \
 
--restart_timeout=240 \
 
--mysqld=--plugin-load-add=file_key_management.so \
 
--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf_redundant/mariadb/encryption_keys.txt \
 
--duration=300 \
 
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
--mysqld=--loose-innodb-sync-debug \
 
--mysqld=--innodb_stats_persistent=on \
 
--mysqld=--innodb_adaptive_hash_index=off \
 
--mysqld=--loose-max-statement-time=30 \
 
--threads=2 \
 
--rr=Extended \
 
--mysqld=--innodb_page_size=4K \
 
--mysqld=--innodb-buffer-pool-size=5M \
 
--duration=300 \
 
--workdir=<local settings> \
 
--vardir=<local settings> \
 
--mtr-build-thread=<local settings> \
 
--basedir1=<local settings> \
 
--script_debug=_nix_
 
 
 
conf_redundant/mariadb/table_stress.zz
 
$tables = {
 
    pk      => [ 'int' ],
 
    engines => [ 'InnoDB' ],
 
    rows => [ 0, 1, 1000 ],
 
    row_formats => [ 'REDUNDANT' ]
 
};
 
 
 
$fields = {
 
    types   => [ 'int' ],
 
    indexes => [ undef ]
 
};
 
 
 
$data = {
 
    numbers => [ 'digit' ]
 
};
 
I will try to simplify the test/increase the likelihood to replay the problem.

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

I realized that page 4 in the system tablespace is the root page of the change buffer B-tree (FSP_IBUF_TREE_ROOT_PAGE_NO). That is in the original InnoDB format. So, even if no tables are in ROW_FORMAT=REDUNDANT, this error is possible, when it affects the change buffer pages in the system tablespace.

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

The rr replay trace that mleich posted shows an off-by-1 problem in page_cur_insert_rec_low():

(rr) p/x cur->rec[-extra_size]@extra_size
 
$14 = {0x80, 0x0, 0x0, 0x40, 0x43, 0x40, 0x80, 0x2c, 0x0, 0x2c, 0x0, 0x19, 
  0x0, 0x15, 0x0, 0x11, 0x0, 0xa, 0x0, 0x4, 0x0, 0x0, 0x18, 0x10, 0x7, 0x55}
 
(rr) p/x *insert_buf@extra_size
 
$15 = {0x3, 0x44, 0x83, 0x40, 0x43, 0x40, 0x80, 0x2c, 0x0, 0x2c, 0x0, 0x19, 
  0x0, 0x15, 0x0, 0x11, 0x0, 0xa, 0x0, 0x4, 0x0, 0x0, 0x20, 0x14, 0x0, 0x74}

The extra_size is actually referring to the record that we are about to insert, and not to the predecessor record cur->rec from which we are letting recovery copy a number of identical bytes. It turns out that the correct extra_size of cur->rec is 4 bytes shorter, and the first 4 bytes above actually belong to the preceding record. It happens so that the last of the 4 bytes matches insert_buf, and we will write an INSERT_HEAP_REDUNDANT record where the condition on pextra_size will be violated in page_apply_insert_redundant():

  if (UNIV_UNLIKELY(hdr_c > extra_size || hdr_c > pextra_size))
 
    goto corrupted;

I think that we must simply make the recovery more tolerant and allow us to reuse data that resides before the preceding record. We are already doing the same in page_apply_insert_dynamic(). We must relax the above condition, but ensure that hdr_c is not referring to anything that is before the start of the payload area (which is something that we checked in page_cur_insert_rec_low() before writing the record):

    const byte * const c_start= cur->rec - extra_size;
 
    if (c_start >=
 
        &block->frame[PAGE_OLD_SUPREMUM_END + REC_N_OLD_EXTRA_BYTES])

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

While testing this, we found another crash recovery regression MDEV-25110, introduced in 10.5.7. That one could mostly affect Mariabackup and not normal crash recovery.

Comment by Haidong Ji [ 2022-10-27 ]

I have come across a crash with the same error message:

2022-05-23 10:12:14 0 [ERROR] InnoDB: Not applying INSERT_REUSE_DYNAMIC due to corruption on [page id: space=745895, page number=647870]

But unlike this bug that is trigger from the "page_apply_insert_redundant" function, the bug I observed follows the path of "page_apply_insert_dynamic" before the crash. For that reason, I will file a new JIRA for it.

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