KuriKumaChan’s diary

Kuri ちゃんと Kuma ちゃんの飼い主の独り言

QNAP NAS の ボリュームタイプ変更 (4) - バックアップからのリストアがエラー!さらに悪夢のバックアップデータを削除😭

本当は前回の記事で構成変更を完了後に、static volume から外付け HDD に取ってあったバックアップからさっさと新しい thin volume にリストアして作業完了!としたかったのですが、自分の痛恨のミスもあり、作業を始めて 2週間経ってもリストア復旧できなかったという涙が枯れてしまいそうなお話です。

2週間も試行錯誤していたのですから色々な発見や気づきそして思いもありましたので、それらをまとめて書こうとしていたのですが、痛恨のミスの精神的なダメージがひどく、大まかな経緯だけは忘れないうちにまとめておこうと思います。個別ポイントに関しては今後整理しておくべき項目だけ列挙しておき、気持ちが乗ったら追記して行こうと思います。。。

また、今回発生したエラーの原因はまだ分かっていません。私が問題判別のためのバックアップデータを削除してしまった、という痛恨のミスによって、もしかしたら原因究明は出来ないかもしれません。この点はご了承ください。

※下記の記述の中で「(id=nn)」とされている表記は、HBS3 (Hybrid Backup Sync; QNAP のバックアップソリューションであり、NAS 上で稼働するアプリケーション) のジョブ id です。この ID は残念ながらパネル上には表示されていませんが、内部的に管理されているもので "Debug Report" と呼ばれるログで確認することができました。UI 上はジョブ名で識別されていますが、ジョブ名自体は後から変更して再利用可能ですが変更すると過去のジョブ名は残らないので、ジョブを一意に識別するためにジョブ id を用いることにしました。
※HBS3 のジョブ設定に関するチュートリアルや、"Debug Report" の取得方法など、私が頻繁に参照していたけれども忘れやすい項目は下記記事に列挙してあります。

QNAP 自分のためのヒントメモ - KuriKumaChan’s diary


ここまでの振り返り

前回までで下図のような段階まで完了しています。

f:id:KuriKumaChan:20210526143223p:plain
後はバックアップからデータをリストアするだけ!
続きのステップとしては残るは "5. Copy the data back." だけです。
この文章の "5" がなぜ Restore ではなく "Copy Back" と書いてあるのか?すごく疑問に思って、もしかしたら「static volume から取ったバックアップからでは Storage pool 上の thin/thic ドライブにはリストアできないからあえて "Copy back" しないとならない」と書いてあるのかとも思いました。しかし、リストアジョブはちゃんと設定も実行もできるのであまり深い意味はないのではないかと考えてリストアジョブで作業を進めています(今となっては少しだけ気にはなっていますが、この後ご紹介する QNAP Support の対応でもリストアする事に何も指摘はありません)。

To be able to use the flexible volumes features, one would need to:

  1. Backup data from the static volume

  2. Remove the static volume

  3. Create new Storage Pool ➡︎ 既存ストレージプールの拡張

  4. Create a thin or thick volume inside the new Storage Pool

  5. Copy the data back.

【経緯1-ローカルバックアップ】外付け HDD にとったバックアップからリストアできない

最初に結論です。

  • 前提のお話として、バックアップ取得もバックアップからのリストアも QNAP の HBS3 というアプリで実行しています(HBS3 は過去の記事でも紹介したように、リストアも私の手もとである程度の実績あり。)。

  • 移行前(Static volume) のバックアップジョブ (id=22)はエラーも無く終了していた(ので正しくバックアップが取得できていたと信じている)。

  • 上記のバックアップデータを新しいボリュームにリストアするジョブ (id=29 ) を実行するが、17時間後に異常終了。その後何回も試行錯誤を繰り返すが、バックアップデータの特定のディレクトリでエラーが発生してエラーで終了するもしくはリトライを繰り返してジョブの UI 上進捗 % が 何時間以上も進まずキャンセル(手動でストップ)せざるを得なくなる。

    * 「エラーの発生でリトライを繰り返す」ことは、後ほど HBS3 のログから確認して分かったことです。

  • リストア対象から特定のディレクトリを外すとエラーなくリストアできる。

まとめて書いてしまうとこれだけなのですが、リストアジョブの実行から結果が分かるまでに長時間かかる傾向があり、最初は何が起こっているのか頭の中での整理がなかなか進みませんでした。

試行錯誤の繰り返しの 10日間

最初にジョブの設定項目の意味の確認を兼ねたリストアのテストを 数回行った後、「これでいける!」と思ったジョブ (id=29 )のリストアが、一晩たって (19時間後) QTS の Event notification にエラーメッセージが表示されていてビックリ!声

Warning 2021-05-23 13:51:14 admin 127.0.0.1 Hybrid Backup Sync Job Status [Hybrid Backup Sync] Failed to complete Restore job: "Restore-otachidai". Bad job parameters. Check job settings. Attempting to retry. Error code: -22.

エラーコードも表示されていることなので早速 QNAP のサポートでチケットをオープンして追加資料(NAS が自動的に作成する HBS3 の "Debug Report")取得のアドバイスを受けて自分でも少し覗いてみたり、ジョブの設定を変更するなど試行錯誤をまるまる 10日間ほど苦闘し続けました。
本当はここの整理が大切だとわかっていたので色々メモしたり記録を撮っていたのですが、QNAP サポートへの報告は行ったものの現時点で再度見直そうという気力が湧かず、この間の詳細は割愛させていただきます。

f:id:KuriKumaChan:20210605173754p:plain
試行錯誤の山

HBS3 で内部的にエラーを検知してリトライすることはバッチジョブとしては当然だと思います(リトライすれば先に進むエラーもあるので、「エラー発生即ジョブの終了」よりはリトライしてくれた方がバッチジョブとしては好ましいことが多い)ですが、その間ジョブの状況を UI 上では進捗%と処理済みファイル数くらいしか確認できません。そうなるとユーザーとしてはとても不安に陥ってしまいます。特にデジカメファイルがたくさん入ったディレクトリでこうなると 24時間以上進捗の無い状態が続いたりして、私のような小心者にはとても耐えがたい気持ちに陥りました。

部分リストア + ファイルコピーで対応しよう!

この間、iTunes のライブラリなどが入っている NAS 上のもう一つのボリュームは利用できていたのでなんとか日常作業をこなせていましたが、さすがに 10日も経つと撮影データの保存やら「ちょっと Lightroom で確認を!」ということが出来ないのがだんだん辛くなってきて、方針転換をすることにしました。
具体的にはエラーの発生している α77 と OM-D EM-1 の一部(と言っても今までの主力機のデータなので大量!)のディレクトリを除けばリストアはできそうなのでまずはそれらを通常のリストアジョブで復旧し、残りはバックアップファイルのある外付け HDD を QNAP の FileStation (ブラウザ上で稼働する Finder や Exploler に相当するもの)でファイルにアクセスできたような気がしていたので、エラー発生ディレクトリのファイルだけは手動でコピーしてみよう、という作戦です。
手動の個別ファイルコピーだと作業の管理をしなくてはならないのと、ファイルコピーだとファイルのタイムスタンプが今日のものに変更されることもあるのであまりやりたくなかったのですが、もう背に腹は変えられません。

悪夢のバックアップデータ削除!

ということで、幾つかテストジョブを実行して確認をしたのちに、テストジョブの残骸を FileStation で削除した上でリストア先のボリュームを綺麗にしてからさぁリストア開始!
ところがリストアジョブが実行できません。そうです、誤って残骸データと間違えてバックアップデータのディレクトリを削除してしまったのです。
・・・
・・・・・
・・・・・・・
やっている作業がリストアなので、Finder/Explorer 似の FileStation で削除した残骸だっと思ってクリックした "Pro5300" というディレクトリはリストア先のテスト残骸ではなく、バックアップを格納していた外付け HDD のものだったのです😭
この時の自分の様子は思い出したくありません。その後しばらく何もできませんでした。 自分の今までの全てのデジカメデータが。
手元にあった FileStation でアクセスすればちゃんとアクセスできたであろうデータが。

その日は何もできないまま終わったと思います。QNAP サポートに拙い英語で「自分の不注意で大切なバックアップデータを消去してしまった」とだけ伝えて。

取り外してあった旧 Static volume の HDD からの復旧を試みるが中身が見れない

翌日気を取り直して、NAS から取り外して残っていた旧 Static volume の HDD をotachidai経由で PC に接続して中を除いてみました。以前 Windows PC の内蔵 RAID 1 HDD を交換した際に、RAID 1 の片割れの HDD であれば普通に Windows のエクスプローラーでアクセスできた経験があったからのチャレンジです。
しかし、エクスプローラーに表示されるドライブの様子は全く理解できないもの。ファイルにアクセスすることはできませんでした。

【経緯2-クラウドバックアップ】最後の手段 - クラウドバックアップからのリストア

最後の手段を使わなくてはならなくなりました。リストアにコストが発生しますがそんなことは言っていられません。クラウドには Static volume を外す直前の日曜日に自動バックアップで更新されたデータが残ってい流はずです。つい先日 HBS3 でリストアのテストも行っていたことがが心の支えです。

順調にリストア進むも途中でリストアジョブが異常終了

S3 Glacier からのリストアジョブ (id=49) を流し始めてすぐに、S3 Glacier の取り出しオプションを変更するのを忘れていたことに気づきました(本来はコストの安い「一括」に設定すべきだったのに、デフォルトのコストの高い「標準」のまま実行してしまった)。
ローカルにあるバックアップファイルからのリストアジョブなら気軽にキャンセルできますが、クラウドの場合はジョブ実行が内部的に何段階かに分かれているはずで、最初にクラウド側にデータ取り出しのリクエストを出しているはずです。それを開始してしまったであろう今、ジョブをキャンセルして設定変更をしたジョブを再実行するとどうなるのだろうか?なんて考えると恐ろしくてキャンセルもできません。仕方がないのでそのまま見守ることにしました。少々のコスト高(高くても 1,000円かそこら?)は大切な写真データには代えられません。
翌朝ジョブの様子をチェックするとエラーで終了していました。夜寝る時には快調にダウンロードが進んでいたのに...

[Restore 3] Files that Were Filtered or Skipped.,,,, Name,Size,Status,Reason,Date&Time /Pro5300/Photo/OM-D_E-M1/101OLYMP/P7161227.MOV,1.30 GB,Skipped,,2021/06/01 05:21:15

"Total files:10,Filtered files:0,Skipped files:10",,,,

また落ち込んではいましたが、これはスキップされたファイルサイズがいずれも 1GB 超だったこと、ジョブの設定に "skipped file limit" という項目がありデフォルト 10 だったことから、ファイルサイズの大きなファイルはリストアがスキップされる(その訳はわかりませんが)、そのスキップしたファイルの数が上限に達するとジョブがエラーで終了する、という仕組みだと想像できました。

skip file の上限設定変更して再度リストア実行 ➡︎ダウンロード待ちのループで停止

本来ファイルサイズが大きかろうがなんだろうが、バックアップしたファイルをリストアしないということ自体例外だと思うので、そのような機能を作るのであればそれはオプションにすれば良いと思うのですが、現実こうなっているので、こちらの想定外の理由でジョブが終了しないように limit を 1000 にして再実行 (多分 id=54)。 Glaier からのリストアは、最初にクラウド内でファイルの準備をするのに数時間かかるため、このジョブでは 9時間ほど何もダウンロードされない状態が続きましたが、ある時から快調にダウンロードが始まります。HBS3 で実行中のジョブの状況を確認できる "Job Run Status" をみると、"Skipped files: 12" の表示があり、Glacier に実際にあったスキップ対象のファイル(おそらく 1GB 超のもの)は 12個存在しており、前のジョブでは上限が 10 であったので異常終了したけれど今回は 1000 の設定なのでジョブは続行していることが確認できました。 f:id:KuriKumaChan:20210606112309p:plain しかし翌日ジョブは実行中なのにファイルのダウンロードが停止してしまいました。上図にある "Status: Restoreing....nn%" の表示が進間ないのです。8時間ほど経った時にやむなくジョブをキャンセル。ログから結果特定のディレクトリでファイルのダウンロード待ちのままループしていたことが分かりました。
この日はこれでまた心が折れかかってしまいました。

[2021-06-02 16:28:50,081][ Thread-8][I][FileRetriever][retriever.py:retrieve_next_batch:235] : Retrieve next batch: rate=3932160.0, ready pool size=293446798800, retrieve pool size=0
[2021-06-02 16:28:50,083][ Thread-8][I][FileRetriever][retriever.py:
retrieve_next_batch:243] : No more items need to retrieve
[2021-06-02 16:28:51,870][ RstWorker][I][FileRetriever][retriever.py:iter:163] : Waiting available download
[2021-06-02 16:29:50,183][ Thread-8][I][FileRetriever][retriever.py:retrieve_next_batch:235] : Retrieve next batch: rate=3932160.0, ready pool size=293446798800, retrieve pool size=0
[2021-06-02 16:29:50,184][ Thread-8][I][FileRetriever][retriever.py:
retrieve_next_batch:243] : No more items need to retrieve
[2021-06-02 16:29:53,082][ RstWorker][I][FileRetriever][retriever.py:iter:163] : Waiting available download

やむなく対象ディレクトリのリストア状況を個別確認して再実行

今やっている作業が最後の手段なので、ここで諦めるわけにはいきません。Glacier 側では AWS コンソールでバックアップ対象のディレクトリ構造やファイル(数、容量)の確認もできるので、NAS 側のリストア済み状況を FileStation でディレクトリ単位で一つ一つ確認していきました。

f:id:KuriKumaChan:20210605221849p:plain
Glacier 側のディレクトリ構造を確認して Glacier 側と NAS 側のファイル数とバイト数をチェック(画像はチェック対象ディレクトリの一部)

結果、リストアが途中で終わっているディレクトリや、そもそも一つのファイルもダウンロードされていないディレクトリがあることが確認できたので、その対象ディレクトリだけ再度リストアジョブ (id=56) を流しました。その結果部分完了していたディレクトリに関しては、HBS3 がチェックしてダウンロード済みのものを除外して残りをリストアしてくれたようです(HBS3 賢い!... 初めて HBS3 を褒めた)。

f:id:KuriKumaChan:20210606113224p:plain
すでにリストア済みのファイルが "Unchanged files" にカウントされているようだ

クラウドからリストアできないファイルに福の神到来 "R-Linux" !

ようやく久しぶりに Mac から接続して新しいデジカメファイルを NAS に保存したり、Lightroom で以前の写真をチェックしたりする日常が取り戻せてきました(そういえばフィルムのデジタル化が進んでいない..)。 しかし、ここで終わりにしてはいけないのです。10個の 1GB超の動画ファイルがスキップされていてリストアできていないのです。実際にはやらなかったですが、やろうと思えば S3 Glacier から S3 に転送してAWS コンソールでダウンロードできるような気がします。

QNAP サポートから「旧 Static volume の HDD をアクセスするフリーソフトあるよ!」と連絡

S3 経由のファイルダウンロードを行う腹は括っていたのですが、少しめんどくさくなって躊躇していると、QNAP から、

Because the disks are configured inside the NAS hence it can't be easily read by simply attaching it via USB connection. You can try this procedure and see if the files will be retrieved on the disk that was not formatted. - Download on a Windows PC (or Linux) the R-Linux program (https://www.r-studio.com/free-linux-recovery/) - Use the old disk, (use only either 1 disk if from RAID1) - Attach the NAS disk to your PC - Use R-Linux SW to access the disk data partition - Copy the data to your PC or to an external storage device" https://www.r-studio.com/free-linux-recovery/

とアドバイスがありました。ポイントは NAS の内蔵 HDD として使っていた HDD は取り出して USB 接続しても簡単に中身を読めないので、Windows か Linux 環境で R-Linux というツールを使ってみる価値あるよ、とのこと。
調べてみると結構以前から存在するフリーのツールのようです。最近の新しい記事はあまり見つかりませんでしたが、手元にあるこの前まで使っていた static volume のデータに直接アクセスできるならとても嬉しい事です。何より skip された 1GB を超える 12個のファイルをネット経由でダウンロードする手間が省けます。

R-Linux を実際使って Static volume のオリジナルデータをコピーできた

f:id:KuriKumaChan:20210606182115p:plain
Windows 環境で R-Linux を起動すると USB 接続した HDD の中に "Datavol2" のパーテシション名があった!
このツールを使ったところ、旧 static volume に存在していた "Datavol2" というドライブ名が確認でき、その中にある "Pro5300" というディレクトリを丸ごと別の HDD にコピーすることができました。
(このあたりの詳細は(気力が出てきたら)また書いておこうと思いますが、今の段階では「役立つツールだった」というだけで終わります。)

skip されたファイルは実はダウンロードされていた!

R-Linux による 旧 Static Volume からの読み出しは結構時間がかかり、私の場合 6時間ほどかかりました。その間、skipped file とされていた以外はちゃんとダウンロードされているのか NAS を FileStation でチェックしていると、なんと skip file とされていたファイルもちゃんとダウンロードされていたことがわかりました。

f:id:KuriKumaChan:20210606183426p:plain
skip した、とされたファイルは、実際にはダウンロードされておりファイル名の一部が変更されていた。

これらのファイル名についていた余分な ".download.xxx" をファイル名から外してやれば(rename するだけ)、ちゃんと動画ファイルとして再生できることも確認できました。
skip されたという割には実際にはダンロード完了されており、わざわざ AWS S3 からダウンロードしたり、R-Linux の処理完了を待たなくてもファイル名の rename だけで良いこともわかりました。結局 skipped files も無事復旧でき、普通に利用するには問題のないレベルに NAS を回復させることができました。


ということで、以下、最低限の試行錯誤の項目だけメモしておいて、心の傷が癒えたら整理を始めようと思います。本日はここまでで終わりです。


【今後整理予定】具体的なエラーの内容(書きかけ)

幾つかのエラーメッセージを QTS の Notification なり HBS3 のログから確認しています。落ち着いたら QNAP へのレポートやログを見直してまとめようと思います。

# ERROR: Unable to create file "xxx/.../yyyy.zzz". (-22)

# WARNING: Unable to update the "xxx/.../yyyy.zzz" file (Permission denied), it will be skipped. (-5)

Failed to complete Restore job: "jobname". Bad job parameters. Check job settings. Error code: -22

Failed to complete Restore job: "Restore 3". Error count exceeds the allowed maximum number of skipped files.

【今後記載予定】どのような試行錯誤をしたのか?(書きかけ)

心が落ち着いたら整理しようと思いますのでしばらくお待ちください。

  • HBS3 リストアジョブの設定変更
    • "Source:" の設定変更:
    • リストア「元」の変更:これには "Backup file" と "destination" があり、私が期待したのは "Backup File" を選択した上で、Backup file の中にある "Pro5300" を言うディレクトリを指定して丸ごとリストアすることですが、後で分かるようにこの中の特定のディレクトリでエラーが発生しており、
    • リストア「先」の変更:余り意味ないと分かっていながら
  • リストア先のボリュームの変更:最初に Thin volume で試していましたが一旦 volume を削除して新規に Thick volume を作成してそこにリストア

なんで 10日間もしつこく試行錯誤を繰り返していたかというと、「最後は AWS S3 Glacier からのリストアという最後の手段もあるぞ」という安牌を持ったまま、その最後の手段はリストアにお金がかかるわけですし、私の過去の経験 (NAS 以外のメインフレームから PC までの) から、バックアップツールからのリストアには信頼を持っていたので、「エラーコードもわかっているわけだから QNAP から何かしらのアドバイスをもらえれば一部バイパスするなどしてもなんとかなるだろう。」という期待があったのだと思います。

慌てていた自分のチョンボの数々

※長文になってしまったので別の記事に分けて書きました。

blog0.kurikumachan.com

【今後記載予定】HBS Debuf Report について

【今後記載予定】R-Linux について

【今後記載予定】QNAP サポートについて