Page MenuHomePhabricator

MySQL database on deployment-db03 does not start due to InnoDB issue
Closed, DeclinedPublic

Description

deployment-db03 instance crashed last week and got recoved (T216404). However mysql refuses to start due to an InnoDB error:

The instance is reacheable but the service is not happy:

The log sequence numbers 212565209189 and 212565209189 in ibdata files do not match the log sequence number 233682420105 in the ib_logfiles!
[ERROR] InnoDB: Tried to read 16384 bytes at offset 0. Was only able to read 0.
InnoDB: Operating system error number 5 in a file operation.
InnoDB: Error number 5 means 'Input/output error'.

-- Logs begin at Mon 2019-02-18 13:24:47 UTC, end at Mon 2019-02-18 17:29:08 UTC. --
Feb 18 13:24:48 mysql[652]: /opt/wmf-mariadb10
Feb 18 13:24:48 mysql[652]: Starting MySQL
Feb 18 13:24:48 mysql[652]: .
Feb 18 13:24:48 mysqld[837]: 190218 13:24:48 [Note] /opt/wmf-mariadb10/bin/mysqld (mysqld 10.0.34-MariaDB) starting as process 836 ... 
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Warning] No argument was provided to --log-bin and neither --log-basename or --log-bin-index where used;  This may cause repliction to break when this server acts as a master and has its hostname changed! Please use '--log-basename=deployment-db03' or '--log-bin=deployment-db03-bin' to avoid this problem.
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: Using mutexes to ref count buffer pool pages
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: The InnoDB memory heap is disabled
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: Compressed tables use zlib 1.2.3
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: Using Linux native AIO
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: Using CPU crc32 instructions
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: Initializing buffer pool, size = 12.0G
Feb 18 13:24:53 mysqld[837]: 190218 13:24:53 [Note] InnoDB: Completed initialization of buffer pool
Feb 18 13:24:54 mysqld[837]: 190218 13:24:54 [Note] InnoDB: Highest supported file format is Barracuda.
Feb 18 13:24:54 mysqld[837]: 190218 13:24:54 [Note] InnoDB: The log sequence numbers 212565209189 and 212565209189 in ibdata files do not match the log sequence number 233682420105 in the ib_logfiles!
Feb 18 13:24:54 mysqld[837]: 190218 13:24:54 [ERROR] InnoDB: Tried to read 16384 bytes at offset 0. Was only able to read 0. 
Feb 18 13:24:54 mysqld[837]: 2019-02-18 13:24:54 7ff6015b4780  InnoDB: Operating system error number 5 in a file operation. 
Feb 18 13:24:54 mysqld[837]: InnoDB: Error number 5 means 'Input/output error'.
Feb 18 13:24:54 mysqld[837]: InnoDB: Some operating system error numbers are described at
Feb 18 13:24:54 mysqld[837]: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
Feb 18 13:24:54 mysqld[837]: 190218 13:24:54 [ERROR] InnoDB: File (unknown): 'read' returned OS error 105. Cannot continue operation

Event Timeline

hashar created this task.Feb 20 2019, 5:23 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 20 2019, 5:23 PM

Broken storage?:

Feb 18 13:24:54 mysqld[837]: InnoDB: Error number 5 means 'Input/output error'.

For DBA , I will poke you on Thursday for some assistance. Not sure whether the Innodb database can be recovered.

deployment-db03 is the master database. For the slave (deployment-db04) we have the task T216067

Mentioned in SAL (#wikimedia-releng) [2019-02-20T17:26:29Z] <hashar> For beta cluster the MySQL master database has some innodb issue T216635 , the MySQL slave has an issue as well T216067

umount /srv
fsck /srv
<fixed bunch of things>
mount /srv

I restarted mysql. Same I/O error. Maybe the disk is corrupted :(((

Anything on dmesg?
Can you do a touch /srv/test?

Ah dmesg!

[Mon Feb 18 13:24:48 2019] EXT4-fs (dm-0): warning: mounting fs with errors, running e2fsck is recommended
[Mon Feb 18 13:24:48 2019] EXT4-fs (dm-0): Errors on filesystem, clearing orphan list.
[Mon Feb 18 13:24:48 2019] EXT4-fs (dm-0): recovery complete
[Mon Feb 18 13:24:48 2019] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)

[Mon Feb 18 13:24:54 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:54 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:54 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:54 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:54 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:54 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:54 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:55 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:24:55 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Mon Feb 18 13:29:58 2019] EXT4-fs (dm-0): error count since last fsck: 18
[Mon Feb 18 13:29:58 2019] EXT4-fs (dm-0): initial error at time 1550067501: ext4_find_extent:921: inode 1310890
[Mon Feb 18 13:29:58 2019] EXT4-fs (dm-0): last error at time 1550496294: ext4_find_extent:921: inode 1310890
[Mon Feb 18 17:35:41 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)
[Tue Feb 19 06:24:59 2019] Process accounting resumed
[Tue Feb 19 15:07:16 2019] EXT4-fs (dm-0): error count since last fsck: 19
[Tue Feb 19 15:07:16 2019] EXT4-fs (dm-0): initial error at time 1550067501: ext4_find_extent:921: inode 1310890
[Tue Feb 19 15:07:16 2019] EXT4-fs (dm-0): last error at time 1550511342: ext4_find_extent:921: inode 1310890
[Wed Feb 20 06:24:56 2019] Process accounting resumed
[Wed Feb 20 16:45:07 2019] EXT4-fs (dm-0): error count since last fsck: 19
[Wed Feb 20 16:45:07 2019] EXT4-fs (dm-0): initial error at time 1550067501: ext4_find_extent:921: inode 1310890
[Wed Feb 20 16:45:07 2019] EXT4-fs (dm-0): last error at time 1550511342: ext4_find_extent:921: inode 1310890
[Wed Feb 20 17:33:16 2019] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)

[Mon Feb 18 17:35:41 2019] EXT4-fs error (device dm-0): ext4_find_extent:921: inode #1310890: comm mysqld: pblk 5275729 bad header/extent: invalid magic - magic 1fe, entries 3082, max 18(0), depth 86(0)

So yeah in troubles :/

I did a fsck again, but I am afraid the partitions are corrupted beyond control :/

head /usr/share/prometheus-node-exporter/apt.sh
k����ۅ�T��L�~�$�=���

:/

Mentioned in SAL (#wikimedia-releng) [2019-02-20T19:45:56Z] <hashar> deployment-db03: restored some old /var/lib/dpkg/status file : sudo zcat /var/backups/dpkg.status.2.gz | sudo tee /var/lib/dpkg/status # T216635

After I have done the fsck the I/O error is gone. It was:

Feb 18 13:24:54 mysqld[837]: 190218 13:24:54 [ERROR] InnoDB: Tried to read 16384 bytes at offset 0. Was only able to read 0.
Feb 18 13:24:54 mysqld[837]: 2019-02-18 13:24:54 7ff6015b4780 InnoDB: Operating system error number 5 in a file operation.
Feb 18 13:24:54 mysqld[837]: InnoDB: Error number 5 means 'Input/output error'.
Feb 18 13:24:54 mysqld[837]: 190218 13:24:54 [ERROR] InnoDB: File (unknown): 'read' returned OS error 105. Cannot continue operation

After sudo systemctl start mariadb I got:

190220 20:02:00 [Note] InnoDB: The log sequence numbers 212565209189 and 212565209189 in ibdata files do not match the log sequence number 233682420105 in the ib_logfiles!
190220 20:02:01 [ERROR] InnoDB: space header page consists of zero bytes in tablespace ./enwiki/archive.ibd (table enwiki/archive)
190220 20:02:01 [Note] InnoDB: Page size:1024 Pages to analyze:64
190220 20:02:01 [Note] InnoDB: Page size: 1024, Possible space_id count:0
190220 20:02:01 [Note] InnoDB: Page size:2048 Pages to analyze:64
190220 20:02:01 [Note] InnoDB: Page size: 2048, Possible space_id count:0
190220 20:02:01 [Note] InnoDB: Page size:4096 Pages to analyze:64
190220 20:02:01 [Note] InnoDB: Page size: 4096, Possible space_id count:0
190220 20:02:01 [Note] InnoDB: Page size:8192 Pages to analyze:64
190220 20:02:01 [Note] InnoDB: Page size: 8192, Possible space_id count:0
190220 20:02:01 [Note] InnoDB: Page size:16384 Pages to analyze:64
190220 20:02:01 [Note] InnoDB: Page size: 16384, Possible space_id count:0
2019-02-20 20:02:01 7f1e403d4780  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
InnoDB: Error: could not open single-table tablespace file ./enwiki/archive.ibd
InnoDB: We do not continue the crash recovery, because the table may become
InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it. 
InnoDB: To fix the problem and start mysqld:
InnoDB: 1) If there is a permission problem in the file and mysqld cannot
InnoDB: open the file, you should modify the permissions.
InnoDB: 2) If the table is not needed, or you can restore it from a backup,
InnoDB: then you can remove the .ibd file, and InnoDB will do a normal
InnoDB: crash recovery and ignore that table.
InnoDB: 3) If the file system or the disk is broken, and you cannot remove
InnoDB: the .ibd file, you can set innodb_force_recovery > 0 in my.cnf
InnoDB: and force InnoDB to continue crash recovery here.

Highlight:

[ERROR] InnoDB: space header page consists of zero bytes in tablespace ./enwiki/archive.ibd (table enwiki/archive)

The files are still there, I guess it got corrupted:

-rw-rw---- 1 mysql mysql     4561 Feb  7 07:21 enwiki/archive.frm
-rw-rw---- 1 mysql mysql 16777216 Feb 13 10:13 enwiki/archive.ibd

But we got a:

InnoDB: Operating system error number 2 in a file operation.

And again:

Error: could not open single-table tablespace file ./enwiki/archive.ibd
Addshore triaged this task as High priority.Feb 20 2019, 8:19 PM
Addshore added a subscriber: Addshore.

Marking as High (as I did with the other ticket) as beta is broken until this is fixed afaik.

Then I am trying:

/etc/my.cnf
[mysqld]
innodb-force-recovery = 1

Then sudo systemctl start mariadb which spurts a long output P8111

So a couple pages are corrupted. They hint about dumping, dropping, reimporting the table. Seems that is still the enwiki/archive table.

Data looks very corrupted. At this point the best option is to rebuild that host from the slave.

Without innodb-force-recovery = 1, I get the same P8111 by simply moving enwiki/archive files. So that table definitely has some kind of issue, I think we can afford to loose it entirely. However the page fault is more concerning:

[Note] InnoDB: The log sequence numbers 212565209189 and 212565209189 in ibdata files do not match the log sequence number 233682420105 in the ib_logfiles!
[Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
InnoDB: Database page corruption on disk or a failed
InnoDB: file read of page 971.

InnoDB: uncompressed page, stored checksum in field1 3415262682, calculated checksums for field1: crc32 807103456, innodb 3455493490, none 3735928559, stored checksum in field2 2941335486, calculated checksums for field2: crc32 807103456, innodb 2672159324, none 3735928559, page LSN 54 1754110149, low 4 bytes of LSN at page end 1567740479, page number (if stored to page already) 971, space id (if created with >= MySQL-4.1.1 and stored already) 0


I have tried with innodb-force-recovery >= 4 since the doc states it can further corrupt the files ;-)

The page is 16384 bytes long and the dump shows a lot of zeros.

hashar changed the task status from Open to Stalled.Feb 20 2019, 8:54 PM

Not much to do here. The slave deployment-db04 eventually managed to start mysql and new instances are rebuild with a dump/import to them.

Stalling this in favor of actions being done on the slave T216067

mmodell closed this task as Declined.Feb 26 2019, 2:08 AM
mmodell added a subscriber: mmodell.

I think we should just delete db03 now that we've got db04 and db05 going. Can we snapshot these instances somehow so that it'll be easy to recover next time? This has happened several times that I can remember and it's a big pain every time.

deployment-db03 is still around. And yes I guess you can delete it.

For a better recovery, I guess we could at least get a database backup/dump? An alternative for the future would be to use real databases and have them maintained by DBA (if they agree). Much like the labs replica of the wikis databases.

Mentioned in SAL (#wikimedia-releng) [2019-04-09T16:38:00Z] <Krenair> deleting deployment-db03, unused since T216635 and shut down since 24th March. T219087