JetsonNanoに接続したHDDがI/O Error多発する問題をなんとかした

この記事の内容

JetsonNanoを使い、とあるデータの配信サービスをやっているのですが、突然データが受信できなくなる問題が発生したのでそれを修正するまでのメモ

実行環境

• Jetson Nano
• 4.9.140-tegra (buildbrain@mobile-u64-4428)
• Docker Swarm + Portainer
• 20.10.7, build 20.10.7-0ubuntu5~18.04.3
• 以前の記事で構築したやつです
• 外部HDD接続
• ケース: Logitec LGB-EKU3
• HDD: WD Blue 6TB WD60EZAZ-RT
• フォーマット: EXT4

先に結論

USB3.0 + デフォルトのUAS(USB Attached Storage)ドライバ + Debian は I/O storageエラーをよく吐く組み合わせなので、UASドライバを使わないようにさせて、旧型のusb_storageドライバを使うのがおすすめ

トラブルシュート記録 その1

2日前の記録

エラー報告された内容

配信されてるいくつかのデータだけ読み込めない、他は読み取れる

Dockerコンテナ内のエラーログ

エラーが出たらまずはサービス提供してるコンテナ内を見るのが妥当だろうってことで Portainerから確認

GET /repository/files/bgm.mp3 500 2962546 - 3.155 ms
GET /repository/files/bgm.mp3 500 383346 - 5.196 ms
Error: EIO: i/o error, read
Error: EIO: i/o error, read
Error: EIO: i/o error, read

なんかめちゃくちゃ Error: EIO: i/o error, read を吐いている。一部だけ読み取れないと言っていたが、たぶん挟んでるCDN(Cloudflare)にキャッシュされてる分に関してはそのまま配信できてるからってだけだと判断。

HDDのマウント先を普通にlsしてみる

> ls /mnt/hdd1
ls: `ファイル名' の読み込みエラー: 入力/出力エラーです
ls: `ファイル名' の読み込みエラー: 入力/出力エラーです
ls: `ファイル名' の読み込みエラー: 入力/出力エラーです
ls: `ファイル名' の読み込みエラー: 入力/出力エラーです
ls: `ファイル名' の読み込みエラー: 入力/出力エラーです

ファイル名だけはどっかのキャッシュに乗っかって出てきているようだが、まさかの全ファイル読み書き不可。うーん困った...

とりあえずサービスとマウントを一旦停止

Portainerから停止 + 停止アナウンスをコミュニティに流して サービスを止める。
そして マウント停止

> sudo umount /mnt/hdd1
> sudo umount /mnt/hdd2

接続されているhddの状態を確認する

まずは、HDDの物理的故障を確認するためにS.M.A.R.Tを見るべきだろうと思いたつ。

> sudo apt install smartmontools
> smartctl -i /dev/sda
smartctl 6.6 2016-05-31 r4324 [aarch64-linux-4.9.140-tegra] (local build)
Copyright (C) 2002-16, Bruce Allen, Christian Franke, www.smartmontools.org

/dev/sdb: Unknown USB bridge [0x0789:0x0282 (0x7205)]
Please specify device type with the -d option.

# こういうときは中身がSATAであれば -d satを指定すればだいたいなんとかなる
> smartctl -i -d sat /dev/sda

実際のログは長いので折りたたみ

smartctl 6.6 2016-05-31 r4324 [aarch64-linux-4.9.140-tegra] (local build)
Copyright (C) 2002-16, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Device Model:     WDC WD60EZAZ-00ZGHB0
Serial Number:    WD-WX32D80DALC5
LU WWN Device Id: 5 0014ee 26877741e
Firmware Version: 80.00A80
User Capacity:    6,001,175,126,016 bytes [6.00 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    5400 rpm
Form Factor:      3.5 inches
Device is:        Not in smartctl database [for details use: -P showall]
ATA Version is:   ACS-3 T13/2161-D revision 5
SATA Version is:  SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Tue Jan 25 03:47:35 2022 JST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   200   200   051    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0027   233   223   021    Pre-fail  Always       -       3333
  4 Start_Stop_Count        0x0032   085   085   000    Old_age   Always       -       15193
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   091   091   000    Old_age   Always       -       6702
 10 Spin_Retry_Count        0x0032   100   100   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   253   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       22
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       9
193 Load_Cycle_Count        0x0032   152   152   000    Old_age   Always       -       144696
194 Temperature_Celsius     0x0022   133   108   000    Old_age   Always       -       17
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0030   100   253   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       28
200 Multi_Zone_Error_Rate   0x0008   100   253   000    Old_age   Offline      -       0

SMART Error Log Version: 1
No Errors Logged

特にエラーがあるような雰囲気のログに見えないが Selftest(自己診断)もやらせてみる。

> smartctl -t shot /dev/sda
# 診断が裏で開始されるので3分ぐらい待つ
> smartctl -d sat -l error /dev/sda
smartctl 6.6 2016-05-31 r4324 [aarch64-linux-4.9.140-tegra] (local build)
Copyright (C) 2002-16, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF READ SMART DATA SECTION ===
SMART Error Log Version: 1
No Errors Logged

やっぱりエラーは無かった

念の為、取り外して WindowsのPCにつなぎ、CrystalDiskInfoで見るも特に問題なかった。起動時間6702時間 電源ON/OFF 62回という 稼働時間的にもまだエラー吐きそうなタイミングではないだろう(個人的意見)

システムのエラーログを確認する

じゃあシステムのログ見ようかと思い、Qiita記事に書かれてた方法でログを見る

> dmesg
[ 2044.462877] sd 1:1:1:0: rejecting I/O to offline device
[ 2044.467606] sd 1:1:1:0: rejecting I/O to offline device
[ 2044.472357] sd 1:1:1:0: rejecting I/O to offline device
[ 2044.477110] sd 1:1:1:0: rejecting I/O to offline device
[ 2044.481844] sd 1:1:1:0: rejecting I/O to offline device

無限に同様のエラーが連なっていて、どうやら、繋がっていないデバイスにI/Oしようとするなとお怒りのご様子。
一番上まで見たりgrepしてみるも、どこからオフラインになったのか全くわからず。エラー発生時刻から時間が立ちすぎてるのが原因かと思いつつ、とりあえず rejecting I/O to offline device でググる

出てきた解決策: ケーブル繋ぎ直し

軽く調べた結果、物理的にHDDの接続が切れてるのが問題では? という話が出てきた。そういえば、ケースのレビューを見る限りでも、接続がちょくちょく切れますと書いてあったので、単に繋ぎなおして再起動してみることに。

これだけで動いてしまう

再起動すると何もなかったかのように全て読み込みできてしまった...
なんか釈然としないがとりあえず様子見することに。

トラブルシュート記録 その2

やっぱりダメだったので、今日の記録

エラー報告された内容

配信されてるデータのほとんど、というか全部読み込めない
なぜか悪化しているような気がするが、キャッシュの期限切れがちょっとタイミング悪かっただけと解釈。

Dockerコンテナ内のエラーログ

同様のエラーだった、まぁファイルが読めないってことなので当然か。

GET /repository/files/bgm.mp3 500 2962546 - 3.155 ms
GET /repository/files/bgm.mp3 500 383346 - 5.196 ms
Error: EIO: i/o error, read
Error: EIO: i/o error, read
Error: EIO: i/o error, read

HDDのマウント先を普通にlsしてみる

こっちも同様、やはり同様。

> ls /mnt/hdd1
ls: `ファイル名' の読み込みエラー: 入力/出力エラーです

ファイルシステムの問題を疑う

接続はし直したし、SMARTも問題ないってことは物理的故障じゃないだろうと思いファイルシステムがどっかで壊れた説を思い立つ。今回使っているHDDはEXT4でフォーマットしているので、EXT4の修復コマンドを試す。

> sudo e2fsck /dev/sda1
(パーティション名): clean. (0000/0000的数字) files (0000/0000的数字) blocks
> sudo e2fsck /dev/sda2
(パーティション名): clean. (0000/0000的数字) files (0000/0000的数字) blocks

cleanと言われてしまったので、ファイルシステム的な問題でもなかった。

ちゃんとエラーログを探す

どこにエラーログが保管されているかよくわからないのでそれっぽいのを総当りした

> dmesg
(1時間分ぐらいしか見れない...ので offlineというログしか出ない)
> cat /var/log/messages
(ファイル無し)
> cat /var/log/dmesg
(ファイル無し)
> cat /var/log/syslog
なんかそれらしきログがいっぱい入ってたので絞り込んでみる
> cat /var/log/syslog | grep "sd 1:0:0:0" | head -10
Jan 26 16:36:40 jet kernel: [147068.973199] sd 1:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD IN
Jan 26 16:36:40 jet kernel: [147068.973209] sd 1:0:0:0: [sdb] tag#3 CDB: opcode=0x88 88 00 00 00 00 00 19 80 b7 e0 00 00 00 08 00 00

出てきた解決策: UASドライバが悪いかも

すると、NVidiaのフォーラムがヒットした。

どうやら カーネルのソース内の例外定義ファイルに定義を追加して、改めてビルドしろとの指示。そこまではやってられないので、もっと簡単な方法はないかもっと調べる。

同様のエラーを見ると UASドライバというのが なにか相性悪いとこうなるらしい

UASドライバのブラックリストに追加すれば usb_storageという旧ドライバにフォールバックしてマウントしてくれるらしいので、UASドライバのブラックリストに追加を試みる

UASドライバをどうにかこうにか使わせないようにしたい

を見てやってみた。

# ベンダーIDとデバイスIDを取得
> lsusb
Bus 002 Device 006: ID 0789:0282 Logitec Corp.
...
# 確かにuasドライバを使われてしまっている
> lsusb -t
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=tegra-xusb/4p, 5000M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=""uas"", 5000M
        |__ Port 2: Dev 6, If 0, Class=Mass Storage, Driver=usb-storage, 5000M
# 書いてあった方法を試す
> sudo su
> echo "options usb_storage quirks=0789:0282:u" > /etc/modprobe.d/blacklist-uas.conf
> update-initramfs -u
> reboot

これでは反映されず。他の方法を探る。

この回答の方法もやってみることに。

> echo "options usb_storage quirks=0789:0282:u" > /etc/modprobe.d/disable_uas.conf
> update-initramfs -u
> reboot

これも反映されず。

ここではじめのNvidiaのフォーラムを見直すと 最後の人が
echo 152d:0583:u > /sys/module/usb_storage/parameters/quirks
してからHDDをつないだら、ビルドし直さなくともなんとかなるよと言っていた(神か?)

とは言っても手動でHDD繋ぎ直すのは面倒なのでmodprobeで有効/無効を切り替えたらいいんじゃないかと思い立つ。

> sudo modprobe -r usb-storage
modprobe: FATAL: Module usb_storage is builtin.

初めからビルトインされているモジュールなので無効にすることはできないらしい。
めんどくさいと思いつつ、普通に物理的に繋ぎ直してみた。

勝利

> lsusb -t
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=tegra-xusb/4p, 5000M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 5000M
        |__ Port 2: Dev 6, If 0, Class=Mass Storage, Driver=usb-storage, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=tegra-xusb/5p, 480M
    |__ Port 2: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M

すると Driverがusb-storageになって、ちゃんとUASと別れを告げることができた。
ただし、再起動したら毎回 /sys/module/usb_storage/parameters/quirks が消えるので
コマンドの打ち直し + 都度手動でケーブルを差し直す必要があるらしい。

とか参考にしたら、なんとかすることもできるようだが、めんどくさそうだったので放置することにした。
自宅鯖なので、まぁいいか...

乾燥した感想

なんで今まで問題なく動いてたのか不思議、Debianと外部HDDの組み合わせなんもわからん...

細かいコマンドのメモ

最近Linux直接触ってなかったから、色々コマンド忘れてたためここにコマンド載せ直しておく

実行環境の確認方法

> cat /proc/version
Linux version 4.9.140-tegra (buildbrain@mobile-u64-4428) (gcc version 7.3.1 20180425 [linaro-7.3-2018.05 revision d29120a424ecfbc167ef90065c0eeb7f91977701] (Linaro GCC 7.3-2018.05) ) #1 SMP PREEMPT Tue Oct 27 21:02:37 PDT 2020
> docker -v
Docker version 20.10.7, build 20.10.7-0ubuntu5~18.04.3
> cat /etc/nv_tegra_release
R32 (release), REVISION: 4.4, GCID: 23942405, BOARD: t210ref, EABI: aarch64, DATE: Fri Oct 16 19:44:43 UTC 2020
# 長いことdist-updateしてないのでそろそろ古いかもしれない、apt upgrade は ちゃんとやってます

HDDのアンマウント

# 安全な取り外し
> sudo umount /mnt/hdd1
> sudo umount /mnt/hdd2
# なんらかのプロセスが読み書きしていたらこう言われる
Device is busy
# 安全じゃない取り外し
> sudo umount -f /dev/sdb
# あんまり重要なプロセスは動いていないので 何回か安全じゃない取り外ししました...

サービス関連

# サービスの停止
> sudo systemctl stop smbd
# サービスの無効化
> sudo systemctl disable smbd
# 数日前にSambaでのファイル転送中にネットワークから切断してしまったのでその関連性もあると見て、Sambaを一旦無効化した(なお関係なかった)

参考ページ色々