この記事の内容
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 は ちゃんとやってます
# 安全な取り外し
> 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を一旦無効化した(なお関係なかった)