Bug #84191 redo log corrupted after btrfs filesystem no space left on device
Submitted: 13 Dec 2016 18:26 Modified: 24 Feb 2017 11:06
Reporter: Philipp Gassmann Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S4 (Feature request)
Version:5.7.16 OS:Ubuntu (14.04)
Assigned to: MySQL Verification Team CPU Architecture:Any
Tags: corruption, filesystem full, no space

[13 Dec 2016 18:26] Philipp Gassmann 
Description:
No space left on device resulted in corrupt redo log. btrfs had full disk-usage. 
Details for btrfs problem: http://askubuntu.com/questions/464074/ubuntu-thinks-btrfs-disk-is-full-but-its-not/860222#...

After filesystem was fixed, mysql could only be started again with innodb_force_recovery = 6, 
Mode 6 - Doesn't roll-forward from the redo logs (ib_logfiles) during start-up as described here: https://forums.cpanel.net/threads/innodb-corruption-repair-guide.418722/

Logs, including automatic backtrace: 
# service log, journalctl -xe -u mysql:

Dec 13 07:15:04 mysql2 systemd[1]: mysql.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Dec 13 07:15:04 mysql2 systemd[1]: mysql.service: Unit entered failed state.
Dec 13 07:15:04 mysql2 systemd[1]: mysql.service: Failed with result 'exit-code'.
Dec 13 07:15:05 mysql2 systemd[1]: mysql.service: Service hold-off time over, scheduling restart.
Dec 13 07:15:05 mysql2 systemd[1]: Stopped MySQL Community Server.
-- Subject: Unit mysql.service has finished shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mysql.service has finished shutting down.
Dec 13 07:15:05 mysql2 systemd[1]: Starting MySQL Community Server...
-- Subject: Unit mysql.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mysql.service has begun starting up.
Dec 13 07:15:06 mysql2 systemd[1]: mysql.service: Main process exited, code=exited, status=1/FAILURE
Dec 13 07:15:35 mysql2 systemd[1]: Failed to start MySQL Community Server.
-- Subject: Unit mysql.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mysql.service has failed.
--
-- The result is failed.

# mysql-error.log
2016-12-13T07:15:04.175758Z 0 [Warning] InnoDB: Retry attempts for writing partial data failed.
2016-12-13T07:15:04.269830Z 0 [ERROR] InnoDB: Write to file ./ib_logfile0failed at offset 156809216, 512 bytes should have been written, only 0 were written. Operating system error number 28. Check that your OS and file system suppo
rt files of this size. Check also that the disk is not full or a disk quota exceeded.
2016-12-13T07:15:04.301760Z 0 [ERROR] InnoDB: Error number 28 means 'No space left on device'
2016-12-13T07:15:04.322196Z 0 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2016-12-13 07:15:04 0x7f8de7fff700  InnoDB: Assertion failure in thread 140247459428096 in file fil0fil.cc line 5779
InnoDB: Failing assertion: req_type.is_dblwr_recover() || err == DB_SUCCESS
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
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: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
07:15:04 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=16
max_threads=500
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 231439 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 = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xe7f7db]
/usr/sbin/mysqld(handle_fatal_signal+0x489)[0x784739]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x113e0)[0x7f911b73e3e0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f911aaf8428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f911aafa02a]
/usr/sbin/mysqld[0x75a5be]
/usr/sbin/mysqld(_Z6fil_ioRK9IORequestbRK9page_id_tRK11page_size_tmmPvS8_+0xaa6)[0x1169696]
/usr/sbin/mysqld(_Z15log_write_up_tomb+0xc81)[0xf641d1]
/usr/sbin/mysqld(_Z14log_checkpointbb+0x1c5)[0xf669e5]
/usr/sbin/mysqld(srv_master_thread+0xfd4)[0x104ad34]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x770a)[0x7f911b73470a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f911abc982d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2016-12-13T07:15:05.220591Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-12-13T07:15:05.235800Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.16-0ubuntu0.16.04.1-log) starting as process 9636 ...
2016-12-13T07:15:05.287853Z 0 [Note] InnoDB: PUNCH HOLE support available
2016-12-13T07:15:05.288046Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-12-13T07:15:05.288092Z 0 [Note] InnoDB: Uses event mutexes
2016-12-13T07:15:05.288113Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-12-13T07:15:05.291671Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-12-13T07:15:05.291713Z 0 [Note] InnoDB: Using Linux native AIO
2016-12-13T07:15:05.292955Z 0 [Note] InnoDB: Number of pools: 1
2016-12-13T07:15:05.300077Z 0 [Note] InnoDB: Using CPU crc32 instructions
2016-12-13T07:15:05.390086Z 0 [Note] InnoDB: Initializing buffer pool, total size = 12G, instances = 8, chunk size = 128M
2016-12-13T07:15:05.788505Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-12-13T07:15:05.848250Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-12-13T07:15:05.885339Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-12-13T07:15:05.887854Z 0 [ERROR] InnoDB: Invalid redo log header checksum.
2016-12-13T07:15:05.911689Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2016-12-13T07:15:06.524196Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2016-12-13T07:15:06.527608Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2016-12-13T07:15:06.527636Z 0 [ERROR] Failed to initialize plugins.
2016-12-13T07:15:06.527646Z 0 [ERROR] Aborting

2016-12-13T07:15:06.527658Z 0 [Note] Binlog end
2016-12-13T07:15:06.527722Z 0 [Note] Shutting down plugin 'CSV'
2016-12-13T07:15:06.527735Z 0 [Note] Shutting down plugin 'MyISAM'
2016-12-13T07:15:06.528482Z 0 [Note] /usr/sbin/mysqld: Shutdown complete

How to repeat:
See description. I did not try to reproduce it.
[9 Feb 2017 16:08] MySQL Verification Team 
Hi!

Since  its inception in MySQL 4.0, InnoDB and other storage engines do not and did not check for the free space on the disk, for any of its components. Simply, hard storage is very cheap these days and cases like this are extremely rare.

Still, I consider this a valid feature request. Also, I will write to the Documentation team that this behavior gets documented.

Verified as a feature request.
[24 Feb 2017 11:06] MySQL Verification Team 
Hi Philipp,

I'm sorry but I can't reproduce this on 2 different machines, with btrfs (mounted with "default options" - rw, realatime, seclabel, space_cache, subvolid=5, subvol=/) using kernel 4.7.7 and 3.10.0 ... the only thing I was able to corrupt is myisam table! Pushing data into innodb did not corrupt anything. I tried inserting data in one, 2 and 4 threads in parallel. The mysql crashes (as expected) when disk is full but you remove enough free space and mysql starts right up without any issues. Nothing corrupted. Made over 20 crashes today with different scenario and never had a corruption.

Dunno if this had to do with btrfs bug or what else, but I was not able to reproduce it on two different machines with all scenarios I could think of.

The redo space is preallocated and it's a "real file" not a sparse one so the only bug here can be the btrfs bug, there's nothing we can do about it.

take care
Bogdan Kecman
[15 Mar 2019 19:45] Leho Kraav 
This is certainly a real thing, as I just encountered exact same scenario, all the way to details, but on MariaDB 10.2, kernel 4.14.14.

Only `innodb_force_recovery = 6` helped.

```
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins                                                                
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Uses event mutexes                                                                                          
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Compressed tables use zlib 1.2.11                                                                           
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Using Linux native AIO                                                                                      
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Number of pools: 1
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Using SSE2 crc32 instructions                                                                               
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M                               
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Completed initialization of buffer pool                                                                     
2019-03-15 21:41:42 140309522929408 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of
setpriority().                                                                                                                                                 
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Highest supported file format is Barracuda.                                                                 
2019-03-15 21:41:42 140313413187648 [ERROR] InnoDB: Invalid redo log header checksum.                                                                          
2019-03-15 21:41:42 140313413187648 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption                                         
2019-03-15 21:41:42 140313413187648 [Note] InnoDB: Starting shutdown...                                                                                        
2019-03-15 21:41:42 140313413187648 [ERROR] Plugin 'InnoDB' init function returned error.                                                                      
2019-03-15 21:41:42 140313413187648 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.                                                           
2019-03-15 21:41:42 140313413187648 [Note] Plugin 'FEEDBACK' is disabled.
2019-03-15 21:41:42 140313413187648 [ERROR] Unknown/unsupported storage engine: InnoDB                                                                         
2019-03-15 21:41:42 140313413187648 [ERROR] Aborting
                                                                                                                                                               
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Started in read only mode
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins                                                                
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Uses event mutexes
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Compressed tables use zlib 1.2.11                                                                           
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Using Linux native AIO
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Number of pools: 1                                                                                          
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Using SSE2 crc32 instructions
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Disabling background log and ibuf IO write threads.                                                         
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M                               
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Completed initialization of buffer pool                                                                     
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: Highest supported file format is Barracuda.                                                                 
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: innodb_force_recovery=6 skips redo log apply                                                                
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: 5.7.25 started; log sequence number 0                                                                       
2019-03-15 21:41:52 139657289590848 [Note] InnoDB: !!! innodb_force_recovery is set to 6 !!!                                                                   
2019-03-15 21:41:52 139657289590848 [Note] Plugin 'FEEDBACK' is disabled.
2019-03-15 21:41:52 139657289590848 [Note] Recovering after a crash using gusto-bin                                                                            
2019-03-15 21:41:52 139657289590848 [Note] Starting crash recovery...
2019-03-15 21:41:52 139657289590848 [Note] Crash recovery finished.
```
[16 Mar 2019 0:20] MySQL Verification Team 
Hi Leho Kraav,

While I can reproduce this on maria I was not able to reproduce this on mysql 5.7.24/5.7.25 and this is mysql bugs database so being able to reproduce with maria is 100% irrelevant info.

Also, as Sinisa already pointed out - MySQL since day 1 never cared about free disk space, it's system admin's / dba's work, you need to setup monitoring, use MySQL Enterprise Monitor or whatever else.. but you should not allow your system to get to position your datadir partition is full.

all best
Bogdan
[16 Mar 2019 14:19] Leho Kraav 
Thanks for the confirmation, Bogdan.

"Irrelevant" from one aspect, perhaps, but probably still useful from a global know-how perspective. Large majority of people probably are not aware of how far codebases have diverged by now, and sometimes there's only a very limited no of highly similar cases available on search engines.

Y, I will be attending to disk space issues for sure, btrfs snapshotting implementation clearly had weak spots.
[16 Mar 2019 19:06] MySQL Verification Team 
One should really monitor one's RDBMS for free space. That is one of the first, most basic, monitors one sysadmin and one dba need to set up. For me, personally, a "something failed 'cause partition was full" is a huge fail of whoever is in charge of that system, irrelevant if it ended up failing your RDBMS or any other service on affected system.

all best
Bogdan