バックアップの復元に失敗し、sidekiqが停止せず暴走する

今朝、リビルドを実行し、その後コンテナ内にバックアップのリストアを試みました。使用しているバージョンは 2.6.0.beta5 (75a893fd61) で、すべてコンテナ内で動作しています。

通常、バックアップのリストアは正常に動作します(以前も成功しています)が、今日は以下のように失敗しました。

Starting restore: app-2020-11-06-033740-v20201009190955.tar.gz
[STARTED]
'system' has started the restore!
Marking restore as running...
Making sure /var/www/discourse/tmp/restores/default/2020-11-06-084354 exists...
Copying archive to tmp directory...
Unzipping archive, this may take a while...
Extracting dump file...
Validating metadata...
  Current version: 20201103103401
  Restored version: 20201009190955
Enabling readonly mode...
Pausing sidekiq...
Waiting up to 60 seconds for Sidekiq to finish running jobs...
Waiting for sidekiq to finish running jobs... #2
Waiting for sidekiq to finish running jobs... #3
Waiting for sidekiq to finish running jobs... #4
Waiting for sidekiq to finish running jobs... #5
Waiting for sidekiq to finish running jobs... #6
Waiting for sidekiq to finish running jobs... #7
Waiting for sidekiq to finish running jobs... #8
Waiting for sidekiq to finish running jobs... #9
Waiting for sidekiq to finish running jobs... #10
EXCEPTION: Sidekiq did not finish running all the jobs in the allowed time!
/var/www/discourse/lib/backup_restore/system_interface.rb:89:in `block in wait_for_sidekiq'
/var/www/discourse/lib/backup_restore/system_interface.rb:84:in `loop'
/var/www/discourse/lib/backup_restore/system_interface.rb:84:in `wait_for_sidekiq'
/var/www/discourse/lib/backup_restore/restorer.rb:47:in `run'
script/discourse:143:in `restore'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/thor-1.0.1/lib/thor/command.rb:27:in `run'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/thor-1.0.1/lib/thor/invocation.rb:127:in `invoke_command'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/thor-1.0.1/lib/thor.rb:392:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/thor-1.0.1/lib/thor/base.rb:485:in `start'
script/discourse:284:in `<top (required)>'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/cli/exec.rb:63:in `load'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/cli/exec.rb:63:in `kernel_load'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/cli/exec.rb:28:in `run'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/cli.rb:476:in `exec'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/cli.rb:30:in `dispatch'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/cli.rb:24:in `start'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/exe/bundle:46:in `block in <top (required)>'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/lib/bundler/friendly_errors.rb:123:in `with_friendly_errors'
/usr/local/lib/ruby/gems/2.6.0/gems/bundler-2.1.4/exe/bundle:34:in `<top (required)>'
/usr/local/bin/bundle:23:in `load'
/usr/local/bin/bundle:23:in `<main>'
Trying to rollback...
There was no need to rollback
Cleaning stuff up...
Removing tmp '/var/www/discourse/tmp/restores/default/2020-11-06-084354' directory...
Unpausing sidekiq...
Disabling readonly mode...
Marking restore as finished...
Notifying 'system' of the end of the restore...
Finished!
[FAILED]
Restore done.

その後、Ruby プロセスが数時間 100% の CPU を使用し続けています。このプロセスは以下のように表示されます。

# ps aux | grep sidekiq
discour+    141  100  5.0 9302596 401484 ?      SNl  06:34 127:46 sidekiq 6.1.2 discourse [5 of 5 busy]

コンテナを停止して再起動しても、この Sidekiq は再び 100% の CPU 使用率に戻ってしまいます。sidekiq.log は空であり、production.log にもほとんど情報が表示されません。

この Sidekiq が何をしているのかを特定する方法はありますか?また、このバージョンでバックアップのリストアに同様の問題に遭遇した方はいますか?

親切な方が Sidekiq コンソールを教えてくださいました。Sidekiq がサムネイル生成で忙しいようです:

私が使用しているバックアップにはサムネイルが含まれていないため、これは想定される動作かもしれませんが、以前のテスト用バックアップ復元後に rake posts:rebake を実行し、その後 rake posts:rebake_uncooked_posts も実行しました。そのため、すべてのサムネイル生成は完了しているはずだと思っていました(rebake は約 10 万件の投稿に対して約 1 時間かかり、rebake_uncooked は何も行いませんでした。おそらく完全な rebake ですべて処理が完了していたためでしょう)。

この処理負荷がバックアップの成功を妨げていると仮定すると、バックアップを復元する際にタスクキューはクリアされないのでしょうか?

また、なぜ Sidekiq は特にやるべきことがないのにサムネイルを生成しているのでしょうか?それとも rebake コマンドは単に作業をキューに追加するだけなのでしょうか?

# rake posts:rebake_uncooked_posts
デフォルトで未調理の投稿を再構築中

0 件の投稿完了!

その通りです。リベイクは実際にすべてを実行するのではなく、多くの作業をキューに追加するだけです。

おそらくそうです。ただし、バックアップを復元できるほど知識があるなら、Sidekiq キューを先にクリアする方法も知っているだろうという前提が一般的です。通常は、空のサイトに対して復元を行います。

おそらくその通りだと思います。

ありがとうございます、だいぶ理解が進みました。

では、正しい手順は、まずコンテナを破棄し、次に(再)構築し、その後コンテナにログインしてバックアップを復元するという流れでしょうか?

もしそうであれば素晴らしいですが、空でないコンテナへのリストアを開始する際に、Discourse側からそのヒントや警告を表示してくれるとより親切かもしれません。

それは究極の手段です(おそらく、Redis のデータを削除して再構築する必要があるだけでしょう)。通常、数百万ものジョブが実行されていることはなく、問題にはなりません。しかし、あなたの場合はどうやら連続して 2 回リストアを行っており、最初のリストアが完全に終了する前に 2 回目を開始しているため、特殊なケースと言えます。

もう一つの方法は、/sidekiq にアクセスしてキューに並んでいるすべてのジョブを削除することです。数回のクリックで完了します。

では、災害復旧の優れたテストになりますね :smiley:

確かにそれは少し特殊なケースだということはご指摘の通りです。私は再焼成(re-bake)の時間を短縮しようと努めており、バックアップをリストアしてさまざまな状況で時間を計測しています(サムネイルなしでリストアする場合、デフォルトでは再焼成が完了するのに 2〜3 日かかります!)。これはすべてサイト移行に向けた基礎作業です。

今でははるかに多くを理解できたと思います。ありがとうございます。しかし、バックアップほど重要な機能であれば、Discourse 側が可能な限り信頼性を確保する(例えば、開始前に Sidekiq キューを purge するなど)か、復元に潜在的な問題を検知した場合は追加のステップが必要であることを明確に警告するべきだと考えます。

それを知っているのはあなただけでしょう。

異なるサーバーへ移行する際は、サムネイルを含むバックアップ(サイト設定 include_thumbnails_in_backups)を作成することをお勧めします。

ありがとうございます!このオプションも試しましたが、バックアップは約6GB増えるだけなのに、作成に約1時間余計にかかります。どうやらtarのステップに時間がかかっているようです。古いハードウェアでは、多数の小さなファイルへのアクセスが遅いのかもしれません。Gzipレベルは1に設定されているので、CPUではなくI/Oがボトルネックになっていると思われます。新しいホストなら、同じバックアップを30〜40分で完了できます。

もしかすると、私が少し焦っているだけなのかもしれません。バックアップに時間がかかることを受け入れるべきでしょう。ただし、この処理中はメインサイトが読み取り専用モードになるため、その時間を最小限に抑えたいと考えています。