NETGEAR ReadyNASでRAID再構築中にシステムが無応答になるのをなんとか凌いだ件

TL;DR

• ReadyNASはRAID再構築中に何らかの条件でI/Oがスタックしてしまう事象が起こる模様
• 経験則としては再構築中のRAID領域へのアクセスが引き金になっていそう
• 念の為Samba、netatalk、Apacheを止めておくことで事象防止になる

前提の環境

私はヤフオクで中古で買ったReadyNAS 312 + EDA500を自宅で運用しているのですが、ディスク交換に伴うRAID再構築の際にシステムが無応答になる事象が頻発して困りました。
参ったことにWebのインタフェースも応答しなくなってしまうため、何が起こっているのかまったく分かりませんでした。

そこで、手始めにSSHでログインできるように設定します。

この設定を仕込んであげると、SSHでログインできるようになります (ID: root / パスワード: Webのadminのパスワードと同じ)。

Welcome to ReadyNASOS 6.10.3

Last login: Tue Apr 20 23:03:33 2021 from 192.168.40.13
root@readynas:~# uname -a
Linux readynas 4.4.190.x86_64.1 #1 SMP Mon Oct 28 01:55:46 UTC 2019 x86_64 GNU/Linux

「ReadyNASOS」を名乗っていますが、uname -aを叩くと普通にLinuxであることがわかります。しかもx86_64アーキテクチャ。PCじゃん。lscpuするとこんな感じ。

root@readynas:~# lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                4
On-line CPU(s) list:   0-3
Thread(s) per core:    2
Core(s) per socket:    2
Socket(s):             1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 54
Model name:            Intel(R) Atom(TM) CPU D2701   @ 2.13GHz
Stepping:              1
CPU MHz:               2128.003
BogoMIPS:              4256.00
L1d cache:             24K
L1i cache:             32K
L2 cache:              512K

さすがに旧製品ですのでCPU性能はなかなか厳しいです。

さて、NASですので「RAIDをどうやって実現しているか」が問題です。lsblkで見てみます。

root@readynas:~# lsblk
NAME      MAJ:MIN RM  SIZE RO TYPE  MOUNTPOINT
sda         8:0    0  2.7T  0 disk
├sda1      8:1    0    4G  0 part
│└md0     9:0    0    4G  0 raid1 /
├sda2      8:2    0  512M  0 part
│└md1     9:1    0  511M  0 raid1 [SWAP]
└sda3      8:3    0  2.7T  0 part
  └md127   9:127  0 13.6T  0 raid6 /tank
sdb         8:16   0  5.5T  0 disk
├sdb1      8:17   0    4G  0 part
│└md0     9:0    0    4G  0 raid1 /
├sdb2      8:18   0  512M  0 part
│└md1     9:1    0  511M  0 raid1 [SWAP]
└sdb3      8:19   0  2.7T  0 part
  └md127   9:127  0 13.6T  0 raid6 /tank
sdc         8:32   0  2.7T  0 disk
├sdc1      8:33   0    4G  0 part
│└md0     9:0    0    4G  0 raid1 /
└sdc3      8:35   0  2.7T  0 part
  └md127   9:127  0 13.6T  0 raid6 /tank
sdd         8:48   0  2.7T  0 disk
├sdd1      8:49   0    4G  0 part
│└md0     9:0    0    4G  0 raid1 /
└sdd3      8:51   0  2.7T  0 part
  └md127   9:127  0 13.6T  0 raid6 /tank
sde         8:64   0  3.7T  0 disk
├sde1      8:65   0    4G  0 part
│└md0     9:0    0    4G  0 raid1 /
└sde3      8:67   0  2.7T  0 part
  └md127   9:127  0 13.6T  0 raid6 /tank
sdf         8:80   0  3.7T  0 disk
├sdf1      8:81   0    4G  0 part
│└md0     9:0    0    4G  0 raid1 /
└sdf3      8:83   0  2.7T  0 part
  └md127   9:127  0 13.6T  0 raid6 /tank
sdg         8:96   0  3.7T  0 disk
├sdg1      8:97   0    4G  0 part
│└md0     9:0    0    4G  0 raid1 /
└sdg3      8:99   0  2.7T  0 part
  └md127   9:127  0 13.6T  0 raid6 /tank

「あー…本体側に入れたディスクにいつの間にかSWAP領域作られている…」などの感想もあるにはありますが、着目したいのがmdのデバイス名。これはLinuxのmdraidサブシステムにより作成されるブロックデバイスのようです。
つまりReadyNASのRAID-Xは内部的にはmdraidだということです。
(中身PCなんだったらOSをFreeBSDにしてストレージをZFSにしてよ…)

事象の観察

mdraidが動いているとわかったので、コマンドラインからシステムのモニタリングをしてみるものとします。いろいろ試して、私は次のワンライナーに落ち着きました。

while true; do uptime ; grep finish= /proc/mdstat ; sleep 5 ; done

これで5秒ごとに/proc/mdstatを確認し、「finish=」の含まれる行を抽出します (resyncやrecoveryが走っていると終了見込み時間を「finish=1234.5min」のように出力するので)。合わせて時刻を確認できるようuptimeも合わせて表示します。

で、resyncが走ってからこいつをしかけて一晩待っていたところ…

 08:37:02 up 19:32,  1 user,  load average: 10.90, 9.96, 7.97
      [========>............]  resync = 40.0% (1172320968/2925416832) finish=38923.2min speed=750K/sec

なんかやたらとload averageが高くなってる! しかも5秒おきに更新されても「1172320968/2925416832」が全然変わらない! (= 同期が何らかの理由で進んでいない)
確かにこれだけload averageが高ければSMBも応答しないしWebのインタフェースも返ってこないわけだ…。
いろいろ試してわかったのが、次の通り。というかこれは「わかった」のではなく「事象を並べているだけ」ですな。

• この状態になるとmdraidにsync止めるようにコマンドを打っても帰ってこなくなる
• shutdownコマンドも効かない
• というかsyncすら返ってこない。
• sync最中にSMB経由でファイルコピーとかをかけていると簡単にこの状態に陥る
• 刺激しないようにしていても、なにかのはずみでこの状態に陥ることもある
  • おそらくWindowsエクスプローラが接続先のボリュームの容量を計算したりファイル一覧を更新したりするためにSMBアクセスを発生させ、ReadyNAS側のディスクアクセスに繋がりI/Oを刺激している?

syncが返ってこないってことはディスクI/Oのどこかが詰まっているのか…。
こうなるとReadyNASの同期中は余計なディスクアクセスを起こさないようにそ～っとしておくしかなさそう。

余計なディスクアクセスをいかに防ぐか

前項の推測ではWindowsエクスプローラがたびたびアクセスを発生させていると睨みました。となると、アクセスしてきても反応しなければいいわけです。つまりSambaを止める。
ついでに他にも負荷を上げる要因になりそうなものも併せて止めちゃいます。私の場合はnetatalk (AFP) とApacheを一緒に止めました。

ということでまずはサービス確認。

root@readynas:~# systemctl status smb
● smb.service - Samba SMB Daemon
   Loaded: loaded (/lib/systemd/system/smb.service; enabled; vendor preset: enab
led)
   Active: active (running) since Tue 2021-04-20 22:52:33 JST; 1min 5
6s ago
 Main PID: 3001 (smbd)
   Status: "smbd: ready to serve connections..."
   CGroup: /system.slice/smb.service
           ├─3001 /usr/sbin/smbd --foreground --no-process-group
           ├─3140 /usr/sbin/smbd --foreground --no-process-group
           ├─3141 /usr/sbin/smbd --foreground --no-process-group
           └─3175 /usr/sbin/smbd --foreground --no-process-group

Apr 20 22:52:31 readynas systemd[1]: Starting Samba SMB Daemon...
Apr 20 22:52:33 readynas systemd[1]: Started Samba SMB Daemon.
Apr 20 22:52:33 readynas smbd[3001]: [2021/04/20 22:52:33.962152,  0] ..
/lib/util/become_daemon.c:136(daemon_ready)
Apr 20 22:52:33 readynas smbd[3001]:   daemon_ready: daemon 'smbd' finis
hed starting up and ready to serve connections
root@readynas:~# systemctl status netatalk
● netatalk.service - Netatalk AFP fileserver for Macintosh clients
   Loaded: loaded (/lib/systemd/system/netatalk.service; enabled; vendor preset:
 disabled)
   Active: active (running) since Tue 2021-04-20 22:52:31 JST; 2min 1
1s ago
     Docs: man:afp.conf(5)
           man:netatalk(8)
           man:afpd(8)
           man:cnid_metad(8)
           man:cnid_dbd(8)
           http://netatalk.sourceforge.net/
 Main PID: 3040 (netatalk)
   CGroup: /system.slice/netatalk.service
           ├─3040 /usr/sbin/netatalk
           ├─3053 /usr/sbin/afpd -d -F /etc/netatalk/afp.conf
           └─3054 /usr/sbin/cnid_metad -d -F /etc/netatalk/afp.conf

Apr 20 22:52:31 readynas systemd[1]: Starting Netatalk AFP fileserver for Macint
osh clients...
Apr 20 22:52:31 readynas systemd[1]: netatalk.service: Failed to read PID from f
ile /var/lock/netatalk: Invalid argument
Apr 20 22:52:31 readynas systemd[1]: Started Netatalk AFP fileserver for Macinto
sh clients.
Apr 20 22:52:31 readynas netatalk[3040]: iniparser: cannot open "/etc/ne
tatalk/timemachine.conf"
root@readynas:~# systemctl status apache2
● apache2.service - The Apache HTTP Server
   Loaded: loaded (/lib/systemd/system/apache2.service; enabled; vendor preset:
enabled)
   Active: active (running) since Tue 2021-04-20 22:52:33 JST; 2min 1
7s ago
  Process: 3641 ExecReload=/usr/sbin/apachectl graceful (code=exited, status=0/S
UCCESS)
 Main PID: 3170 (apache2)
   CGroup: /system.slice/apache2.service
           ├─3170 /usr/sbin/apache2 -k start
           ├─3695 apache_log
           ├─3696 apache_log
           ├─3702 /usr/sbin/apache2 -k start
           ├─3703 /usr/sbin/apache2 -k start
           ├─3705 /usr/sbin/apache2 -k start
           ├─3706 /usr/sbin/apache2 -k start
           ├─3707 /usr/sbin/apache2 -k start
           └─3708 /usr/sbin/apache2 -k start

Apr 20 22:52:33 readynas systemd[1]: Started The Apache HTTP Server.
Apr 20 22:52:34 readynas apache2[3170]: [ssl:warn] [pid 3170] AH01909: 1
27.0.0.1:443:0 server certificate does NOT include an ID which matches the serve
r name
Apr 20 22:53:29 readynas systemd[1]: Reloading The Apache HTTP Server.
Apr 20 22:53:30 readynas apachectl[3641]: [Tue Apr 20 22:53:30.472406 2021] [so:

清々しいほど普通にsystemdを使っているLinuxですね。では止めます。

root@readynas:~# systemctl stop smb
root@readynas:~# systemctl stop netatalk
root@readynas:~# systemctl stop apache2
root@readynas:~# systemctl status smb
● smb.service - Samba SMB Daemon
   Loaded: loaded (/lib/systemd/system/smb.service; enabled; vendor preset: enab
led)
   Active: inactive (dead) since Tue 2021-04-20 22:55:18 JST; 19s ago
 Main PID: 3001 (code=killed, signal=TERM)
   Status: "smbd: ready to serve connections..."

Apr 20 22:52:31 readynas systemd[1]: Starting Samba SMB Daemon...
Apr 20 22:52:33 readynas systemd[1]: Started Samba SMB Daemon.
Apr 20 22:52:33 readynas smbd[3001]: [2021/04/20 22:52:33.962152,  0] ..
/lib/util/become_daemon.c:136(daemon_ready)
Apr 20 22:52:33 readynas smbd[3001]:   daemon_ready: daemon 'smbd' finis
hed starting up and ready to serve connections
Apr 20 22:55:18 readynas systemd[1]: Stopping Samba SMB Daemon...
Apr 20 22:55:18 readynas systemd[1]: Stopped Samba SMB Daemon.
root@readynas:~# systemctl status netatalk
● netatalk.service - Netatalk AFP fileserver for Macintosh clients
   Loaded: loaded (/lib/systemd/system/netatalk.service; enabled; vendor preset:
 disabled)
   Active: inactive (dead) since Tue 2021-04-20 22:55:24 JST; 18s ago
     Docs: man:afp.conf(5)
           man:netatalk(8)
           man:afpd(8)
           man:cnid_metad(8)
           man:cnid_dbd(8)
           http://netatalk.sourceforge.net/
 Main PID: 3040 (code=exited, status=0/SUCCESS)

Apr 20 22:52:31 readynas systemd[1]: Started Netatalk AFP fileserver for Macinto
sh clients.
Apr 20 22:52:31 readynas netatalk[3040]: iniparser: cannot open "/etc/ne
tatalk/timemachine.conf"
Apr 20 22:52:31 readynas netatalk[3040]: Netatalk AFP server starting
Apr 20 22:52:31 readynas netatalk[3040]: Registered with Zeroconf
Apr 20 22:52:31 readynas cnid_metad[3054]: CNID Server listening on loca
lhost:4700
Apr 20 22:52:33 readynas afpd[3053]: dsi_tcp: couldn't find network inte
rface with IP address to advertice, check to make sure "readynas" is in /etc/hos
ts or can be resolved with DNS, or add a netinterface that is not a loopback or
point-2-point type
Apr 20 22:52:33 readynas afpd[3053]: Netatalk AFP/TCP listening on :::54
root@readynas:~# systemctl status apache2
● apache2.service - The Apache HTTP Server
   Loaded: loaded (/lib/systemd/system/apache2.service; enabled; vendor preset:
enabled)
   Active: inactive (dead) since Tue 2021-04-20 22:55:32 JST; 17s ago
  Process: 4257 ExecStop=/usr/sbin/apachectl stop (code=exited, status=0/SUCCESS
)
  Process: 4157 ExecStop=/frontview/bin/fvapps (code=exited, status=0/SUCCESS)
 Main PID: 3170 (code=exited, status=0/SUCCESS)

Apr 20 22:53:30 readynas apachectl[3641]: AH00558: apache2: Could not reliably d
etermine the server's fully qualified domain name, using 127.0.0.1. Set the 'Ser
verName' directive globally to suppress this message
Apr 20 22:53:30 readynas systemd[1]: Reloaded The Apache HTTP Server.
Apr 20 22:53:30 readynas apache2[3170]: [ssl:warn] [pid 3170] AH01909: 1
27.0.0.1:443:0 server certificate does NOT include an ID which matches the serve
r name
Apr 20 22:53:30 readynas apache2[3170]: [mpm_prefork:warn] [pid 3170] AH
00167: long lost child came home! (pid 3171)
Apr 20 22:53:30 readynas apache2[3170]: [mpm_prefork:warn] [pid 3170] AH
00167: long lost child came home! (pid 3172)
Apr 20 22:53:30 readynas apache2[3170]: [mpm_prefork:warn] [pid 3170] AH
00167: long lost child came home! (pid 3179)
Apr 20 22:55:31 readynas systemd[1]: Stopping The Apache HTTP Server...
Apr 20 22:55:31 readynas apachectl[4257]: [Tue Apr 20 22:55:31.978100 2021] [so:
warn] [pid 4260] AH01574: module cgi_module is already loaded, skipping

ここまでお膳立てしてあげたところ、2日かけてresync処理をしていてもI/Oが刺さることはありませんでした。

なおこの後のサービス立ち上げは念の為OS再起動 (shutdown -r now) で実施しました。立ち上げる順番とかでハマりたくなかったのと、同期が終わった後のきれいな状態でOSを上げ直してあげたかったので。

今後もハマりそうだ。
(ちなみに、以前ディスク交換でトチってしまいmdraidをふっ飛ばしかけています。その時はmdraidを強制同期してなんとか復旧できました。こういうことはWebの管理画面からだとできないので、SSHを有効にしておくと転ばぬ先の杖になるかと思います。まぁセキュリティに気をつける必要がありますが)