백업 복원 실패, 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.

그 후 몇 시간 동안 CPU 사용량이 100%인 ruby 프로세스가 있습니다. 이 프로세스는 다음과 같이 설명됩니다:

# 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개 게시글에 대해 약 1시간 정도 소요되었고, rebake_uncooked은 아무것도 하지 않은 것으로 보아 전체 rebake가 모든 작업을 처리한 것 같습니다).

이 워크로드가 백업 성공을 막는 원인이라면, 백업을 복원하기 전에 먼저 작업 큐를 비워야 하지 않을까요?

또한 할 일이 아무것도 없는 것처럼 보이는데 왜 sidekiq가 썸네일을 생성하는 걸까요, 아니면 rebake 명령어가 단순히 작업을 큐에 넣는 것일까요?

# rake posts:rebake_uncooked_posts
Rebaking uncooked posts on default

0 posts done!

맞습니다. Rebake는 실제로 모든 작업을 수행하기보다는 여러 작업을 큐에 추가합니다.

그렇습니다. 하지만 백업을 복원할 만큼 충분히 알고 있다면, 먼저 sidekiq 큐를 비우는 방법도 알고 있을 것이라고 가정합니다. 보통 빈 사이트로 복원하는 경우가 많습니다.

그렇습니다.

고맙습니다. 이제 훨씬 더 이해가 됩니다.

그러면 올바른 순서는 먼저 컨테이너를 삭제한 다음, 컨테이너를 (다시) 구축하고, 컨테이너에 진입하여 백업을 복원하는 것인가요?

만약 그렇다면 좋겠지만, 비어 있지 않은 컨테이너로 복원을 시작할 때 Discourse가 해당 힌트/경고를 제공하면 좋겠습니다.

이것은 핵옵션(nuclear option)입니다 (사실 redis 데이터를 삭제한 뒤 다시 빌드만 하면 될 것 같네요). 보통은 수백 개의 잡이 동시에 실행되는 경우가 아니라서 문제가 되지 않습니다. 하지만 연속으로 두 번의 복구를 수행하고 있고, 첫 번째가 완전히 끝나기도 전에 다시 시작하고 있으므로 특수한 경우에 해당합니다.

다른 방법으로는 /sidekiq로 가서 대기 중인 모든 잡을 삭제하는 것입니다. 클릭 몇 번이면 끝납니다.

그럼 재해 복구 테스트를 해볼 기회네요 :smiley:

확실히 특수한 경우일 수 있다는 말씀에 동의합니다. 저는 rebake 시간을 줄이려고 노력하고 있으며, 이를 위해 백업 복구를 수행하고 다양한 상황(썸네일 없이 복구하는 경우 기본값으로 rebaking 완료에 2~3일이 소요됨!)에서 시간을 측정하고 있습니다. 이는 모두 사이트 마이그레이션을 위한 기초 작업입니다.

이제 훨씬 더 많이 이해하게 된 것 같습니다. 감사합니다. 하지만 백업만큼 중요한 것은 없으므로, Discourse가 이를 최대한 신뢰할 수 있도록 보장하는 것(예: 시작 전에 sidekiq 큐를 정리하는 것) 또는 복구에 잠재적인 문제가 감지되면 추가 단계가 필요하다는 명확한 경고를 내보내는 것이 합리적이라고 생각합니다.

그렇게 해야 한다는 것을 아는 사람은 당신뿐이죠.

서버를 다른 곳으로 이전하려는 경우, 썸네일(include_thumbnails_in_backups 사이트 설정)을 포함한 백업을 생성하는 것을 권장합니다.

감사합니다! 저도 이 옵션을 시도해 봤는데, 백업 용량이 약 6GB 정도 더 늘어나는 것 같지만, 생성에 약 1시간 정도 더 걸리는 것 같습니다. 시간이 오래 걸리는 부분은 tar 단계인 것 같고, 아마도 제 오래된 하드웨어에서 작은 파일이 많을 때 접근 속도가 느려지는 문제가 있는 것 같습니다. Gzip 압축 수준은 1로 설정되어 있으므로 CPU보다는 I/O에 한계가 있는 것 같습니다. 새로운 호스트에서는 동일한 백업을 30~40분 만에 수행할 수 있습니다.

아마도 제가 조금 조급한 것일 수도 있고, 백업에 시간이 더 걸리는 것을 받아들여야 할 수도 있습니다. 다만 이 과정 동안 주 사이트가 읽기 전용 모드로 전환되므로, 해당 시간을 최소화하고 싶습니다.