今月初めは平成30(2018)年9月1日に発生したサーバ障害は、その週明けにはなんとか復旧できたのだけれど、残念ながら未だ「致命的な問題」が残っていたようで再びダウンしてしまった。正確にはHDD故障で重要なパーティションをマウントできなくなり、ウェブサービスは勿論、システムサービスの類が軒並み停止してしまったという次第 。
最初の障害でサーバが強制Shutdownした際、HDD内のLVMである /var パーティションで何か処理していたのだろうか。リモートからサーバにログインできないことに気づいた時はなんとなく嫌な予感がしたが 。
で帰宅して調べてみると、案の定、朝まで動いていたサーバは最後にアクセスしてから数時間後に突然、次のようなHDD読み取りエラーが発生していた:
[711805.660457] sd 25:0:0:0: [sdh] FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
[711805.660465] sd 25:0:0:0: [sdh] Sense Key : Hardware Error [current]
[711805.660468] sd 25:0:0:0: [sdh] Add. Sense: No additional sense information
[711805.660471] sd 25:0:0:0: [sdh] CDB:
[711805.660473] Read(10): 28 00 0f a9 6b 10 00 00 10 00
[711805.660484] blk_update_request: I/O error, dev sdh, sector 262761232
[711822.460908] sd 25:0:0:0: [sdh] FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
[711822.460916] sd 25:0:0:0: [sdh] Sense Key : Hardware Error [current]
[711822.460919] sd 25:0:0:0: [sdh] Add. Sense: No additional sense information
[711822.460922] sd 25:0:0:0: [sdh] CDB:
[711822.460924] Read(10): 28 00 0f a9 6b 10 00 00 10 00
[711822.460936] blk_update_request: I/O error, dev sdh, sector 262761232
[711822.460982] XFS (dm-0): metadata I/O error: block 0xfa1bb10 ("xlog_recover_do..(read#2)") error 5 numblks 16
[711822.478620] XFS (dm-0): log mount/recovery failed: error -5
[711822.478680] XFS (dm-0): log mount failed
[711827.723684] XFS (dm-0): Mounting V4 Filesystem
[711827.866409] XFS (dm-0): Starting recovery (logdev: internal)
[711830.994951] sd 25:0:0:0: [sdh] FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
[711830.994959] sd 25:0:0:0: [sdh] Sense Key : Hardware Error [current]
[711830.994962] sd 25:0:0:0: [sdh] Add. Sense: No additional sense information
[711830.994965] sd 25:0:0:0: [sdh] CDB:
[711830.994967] Read(10): 28 00 0f a9 6b 10 00 00 10 00
[711830.994979] blk_update_request: I/O error, dev sdh, sector 262761232
[711847.817378] sd 25:0:0:0: [sdh] FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
[711847.817386] sd 25:0:0:0: [sdh] Sense Key : Hardware Error [current]
[711847.817390] sd 25:0:0:0: [sdh] Add. Sense: No additional sense information
[711847.817393] sd 25:0:0:0: [sdh] CDB:
[711847.817395] Read(10): 28 00 0f a9 6b 10 00 00 10 00
[711847.817406] blk_update_request: I/O error, dev sdh, sector 262761232
[711847.817480] XFS (dm-0): metadata I/O error: block 0xfa1bb10 ("xlog_recover_do..(read#2)") error 5 numblks 16
[711847.839055] XFS (dm-0): log mount/recovery failed: error -5
[711847.839111] XFS (dm-0): log mount
このI/OエラーによってLVMの /var パーティションが読み込めなくなった。このパーティションが読み込めなくなるのはシステムとして致命的である 。例えばゲートウェイ+ルータ機能、ブログなどのDBシステム、SSHなどランタイムサービスの他、apt パッケージシステムが動かない等、かなり厳しい状況だった。
特にHDD内にあるブログやウェブのデータが逝ってしまったことで、最初は心が折れそうになってしまった 。
1日ほど塞ぎこんでしまったが、ゲートウェイ機能を復旧させないと、いつまでたってもインターネットに接続できないので、ひとまずHDDを新調してシステムの全復旧を行うことにした。それに、かなり古いけどブログのDBのバックアップが残っていた ので、時間はかかるけどブログの方は再び書いていけば、いつか元に戻るであろうと前向きに考えることにした 。
ということで、まずは新規のSSD(120GB)とHDD(3TB)を注文、到着するまでの間は既存のHDDからデータの吸い上げ。この時、I/OエラーがでていたHDDについては重要なデータがストアされており、色々試すことで結局は負荷をかけてハードウェアの寿命が縮んでしまいそうなので、GNU Ddrescue なるツールでddイメージを安全かつ堅実に抜き出すことにした。これは本当に素晴らしいツール:
- 不良セクタをスキップして、良好データをまず先に復旧する
- これによりHDDに不必要な負荷をかけることがないため、最終的に復旧できるデータ量が大きい
- 不良セクタはログに記録できる
- 別ツールであるddrescureviewを使うとGTK+ベースの GUI 上にセクタのマップを表示することができる
I/OエラーがでたパーティションはLVMボリュームで容量は 500GB であったが、Ddrescue は特に問題なかった。このサイズのrawイメージを保存できる空きHDDを用意して、玄人志向のHDDスタンド経由でDdrescureを実行した:
$ sudo ddrescue -n -v /dev/mikeforce-vg/vgroup-var_lv ./back-vgroup-var_lv.img back-vgroup-var_lv.log
GNU ddrescue 1.19
About to copy 536870 MBytes from /dev/mikeforce-vg/vgroup-var_lv to ./back-vgroup-var_lv.img.
Starting positions: infile = 0 B, outfile = 0 B
Copy block size: 128 sectors Initial skip size: 128 sectors
Sector size: 512 Bytes
Press Ctrl-C to interrupt
rescued: 536870 MB, errsize: 12288 B, current rate: 1686 B/s
ipos: 268691 MB, errors: 3, average rate: 16525 kB/s
opos: 268691 MB, run time: 9.02 h, successful read: 0 s ago
Finished
500GBのrawイメージを9時間ほどかけて取得、不良セクタは12KBと予想外に少なかった 。この後、XFSのfschkであるxfs_repairでファイルシステムを補修してからloopbackでマウントしてみたら、見事にパーティションを読み込むことができた:
$ sudo xfs_repair -L -f /opt/back-vgroup-var_lv.img
Phase 1 - find and verify superblock...
Cannot get host filesystem geometry.
Repair may fail if there is a sector size mismatch between
the image and the host filesystem.
Phase 2 - using internal log
- zero log...
ALERT: The filesystem has valuable metadata changes in a log which is being
destroyed because the -L option was used.
- scan filesystem freespace and inode maps...
out-of-order bno btree record 46 (98638 1) block 1/4
block (1,98638-98638) multiply claimed by bno space tree, state - 1
out-of-order bno btree record 47 (225432 1) block 1/4
block (1,225432-225432) multiply claimed by bno space tree, state - 1
out-of-order bno btree record 48 (292435 2) block 1/4
block (1,292435-292435) multiply claimed by bno space tree, state - 1
out-of-order bno btree record 174 (324055 3) block 1/4
block (1,324055-324055) multiply claimed by bno space tree, state - 1
out-of-order bno btree record 175 (324059 2) block 1/4
block (1,324059-324059) multiply claimed by bno space tree, state - 1
out-of-order bno btree record 176 (324096 5) block 1/4
block (1,324096-324096) multiply claimed by bno space tree, state - 1
agf_freeblks 27730912, counted 27730884 in ag 1
agf_freeblks 28437926, counted 28437911 in ag 3
block (2,5220537-5220537) multiply claimed by cnt space tree, state - 2
agf_freeblks 26476336, counted 26476369 in ag 2
agi_freecount 51, counted 52 in ag 3
agi_freecount 64, counted 65 in ag 2
agi_freecount 139, counted 142 in ag 0
sb_ifree 368, counted 335
sb_fdblocks 106740156, counted 106773627
- found root inode chunk
Phase 3 - for each AG...
- scan and clear agi unlinked lists...
- process known inodes and perform inode discovery...
- agno = 0
data fork in ino 137948 claims free block 4822
data fork in ino 137948 claims free block 4823
correcting nblocks for inode 10686304, was 1 - counted 0
- agno = 1
Metadata corruption detected at block 0xfa1bb10/0x2000
(...)
Metadata corruption detected at block 0xfa1bb10/0x2000
Metadata corruption detected at block 0xfa1bb10/0x2000
data fork in ino 536882165 claims free block 33555077
Metadata corruption detected at block 0xfa03108/0x1000
corrupt block 0 in directory inode 536896076
will junk block
no . entry for directory 536896076
no .. entry for directory 536896076
problem with directory contents in inode 536896076
cleared inode 536896076
bad magic number 0x0 on inode 537097760
bad version number 0x0 on inode 537097760
(...)
Phase 4 - check for duplicate blocks...
- setting up duplicate extent list...
- check for inodes claiming duplicate blocks...
- agno = 0
- agno = 1
- agno = 2
- agno = 3
(...)
Phase 5 - rebuild AG headers and trees...
- reset superblock...
Phase 6 - check inode connectivity...
- resetting contents of realtime bitmap and summary inodes
- traversing filesystem ...
(...)
Phase 7 - verify and correct link counts...
resetting inode 61515 nlinks from 20 to 19
resetting inode 512221 nlinks from 16 to 15
Metadata corruption detected at block 0x8058/0x1000
libxfs_writebufr: write verifer failed on bno 0x8058/0x1000
Metadata corruption detected at block 0x3fe90/0x1000
libxfs_writebufr: write verifer failed on bno 0x3fe90/0x1000
Metadata corruption detected at block 0x3fe90/0x1000
libxfs_writebufr: write verifer failed on bno 0x3fe90/0x1000
Metadata corruption detected at block 0x8058/0x1000
libxfs_writebufr: write verifer failed on bno 0x8058/0x1000
done
$ sudo mount -o loop /opt/back-vgroup-var_lv.img ./mnt
$
こちらがddrescueviewで表示させたもの。赤色が不良セクタ:
ddrescueviewの結果
不良セクタのサイズが少なかったことが不幸中の幸いだった。これらのセクタはMySQLのデータであったけどブログには影響が無くて安心した 。
思えば、今夏の酷暑がHDDに与えていた影響は少なくないとして、HDD間の配置を変更し、RootfsはSSDにして発熱を抑えることにした。そして、今さらながらHDDの寿命と故障率について身にしみたのでバックアップを励行することにした。
ということで、全復旧までお金と一週間ほどの時間を要したけど、素晴らしいツールと教訓を得ることができて良しとする。
この後は、自動バックアップシステムを構築し、S.M.A.R.Tで温度を監視しつつサーバを運用することにする。