Восстановление резервной копии не удалось: 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 занял около часа для примерно 100 000 постов, а rebake_uncooked ничего не сделал, так как, видимо, полное переформатирование уже всё обработало).

Если предположить, что именно эта нагрузка мешает успешному созданию резервной копии, не должно ли восстановление резервной копии сначала очищать очереди задач?

Также почему Sidekiq генерирует миниатюры, когда, судя по всему, делать нечего? Или команды rebake просто помещают работу в очередь?

# rake posts:rebake_uncooked_posts
Переформатирование неготовых постов в дефолтном режиме

0 постов обработано!

Верно. Пересборка ставит в очередь множество задач, а не выполняет их все сразу.

Скорее всего. Но обычно считается, что если вы достаточно опытны, чтобы восстановить резервную копию, то вы также знаете, как сначала очистить очередь Sidekiq; обычно восстановление выполняется на пустом сайте.

Я полагаю, что именно так и происходит.

Спасибо, теперь это начинает иметь гораздо больший смысл.

Значит, правильная последовательность действий будет следующей: сначала уничтожить, затем (пере)создать контейнер, после чего войти в него и восстановить резервную копию?

Если это так, то отлично, хотя, возможно, Discourse мог бы выдавать такое указание или предупреждение при попытке начать восстановление в непустой контейнер.

Это ядерный вариант (и, я полагаю, вам нужно будет просто удалить данные Redis, а затем пересобрать). Обычно у вас не запущены тысячи задач, и это просто не проблема. Но поскольку вы, судя по всему, выполняете два восстановления подряд, и первое еще не полностью завершено, когда вы начинаете второе, вы — особый случай.

Другой вариант — перейти в /sidekiq и удалить все задачи из очереди. Это займет всего несколько кликов.

Тогда это хороший тест на восстановление после катастрофы :smiley:

Вы правы, что это, вероятно, немного особый случай. Я пытаюсь сократить время пересоздания (rebake), поэтому восстанавливаю резервные копии и замеряю время в разных условиях (восстановление без миниатюр по умолчанию занимает от 2 до 3 дней для завершения пересоздания!). Всё это подготовка к миграции сайта.

Теперь я понимаю гораздо больше, спасибо. Но для чего-то столь критичного, как резервное копирование, считаю разумным, чтобы Discourse обеспечивал максимально возможную надёжность (например, очищал очереди Sidekiq перед запуском) или выдавал чёткие предупреждения о необходимости дополнительных шагов, если обнаруживаются потенциальные проблемы при восстановлении.

Только тот, кто знает, что это нужно сделать.

Я рекомендую создать резервную копию с миниатюрами (настройка сайта include_thumbnails_in_backups), если вы планируете миграцию на другой сервер.

Спасибо! Это вариант, который я тоже пробовал, но резервная копия, хотя и занимает всего около дополнительных 6 ГБ, создаётся примерно на час дольше. Похоже, что время уходит на этап tar — возможно, на моём старом оборудовании много мелких файлов медленно читаются. Уровень сжатия gzip установлен на 1, поэтому я думаю, что ограничение связано с вводом-выводом, а не с процессором. На новом хосте та же резервная копия создаётся за 30–40 минут.

Возможно, я просто немного нетерпелив в этом вопросе, и мне стоит смириться с тем, что резервное копирование занимает больше времени, но поскольку основной сайт находится в режиме только для чтения во время этого процесса, я стремлюсь минимизировать это время.