Amazon ECSのローリングアップデート開始からSidekiq停止までの流れを追う

はじめに

こんにちは。

SREグループの佐々木と申します。

Amazon ECS（以下、ECS）を使っていて、ローリングアップデート時に、コンテナ上のSidekiqで実行中のジョブに影響が無いのか、気になったことはありませんか？

この記事では、ローリングアップデート時のECSとSidekiqの挙動、ローリングアップデート時に気をつけるポイントを紹介します。

⁠背景

最近、「Sidekiq::Shutdown」のエラーメッセージと共に落ちたジョブがいました。

リリースの際に発生していたので、ECSのローリングアップデート起因で、Sidekiqのジョブが強制終了してしまい、ジョブが落ちたのだろう。と想定していました。

とはいえ、あくまで想定です。また、ジョブが落ちたことによる影響の有無が分かりませんでした。

そこで、エラーメッセージの原因を調査するために、ECSとSidekiqの挙動を追いました。

⁠前提

登場人物は以下の通りです。

Rails側でジョブをRedisにEnqueueし、SidekiqがRedisからジョブをDequeueして実行する。という流れです。

Sidekiqのバージョンは6.5.7です。

⁠調査

以下の順で説明します。

ローリングアップデート時のECS側の挙動
Sidekiq側の挙動

ローリングアップデート時のECS側の挙動

公式ドキュメントから引用。

更新中にサービススケジューラがタスクを置き換えるとき、
サービスはまずロードバランサーからタスクを削除し (使用されている場合)、接続のドレインが完了するのを待ちます。
その後、タスクで実行されているコンテナに docker stop と同等のコマンドが発行されます。
この結果、SIGTERM 信号と 30 秒のタイムアウトが発生し、その後に SIGKILL が送信され、コンテナが強制的に停止されます。
コンテナが SIGTERM 信号を正常に処理し、その受信時から 30 秒以内に終了する場合、SIGKILL 信号は送信されません。

以下の流れのようです。

ロードバランサからタスクを切り離す（ALBを使用している場合）。
タスクで実行されているコンテナにSIGTERMが送られる。
SIGTERM送信の30秒後にSIGKILLが送信される。 ※ SIGTERM送信から30秒以内にコンテナが終了した場合は、SIGKILLは送信されない

SIGTERMの送信後、30秒の猶予時間を与えられます。

コンテナ側は30秒の猶予時間の間に、正常に処理を終わらせられるように動きます。

30秒の猶予時間を過ぎると、SIGKILLが送信され、コンテナのプロセスが終了させられます。

Sidekiq側の挙動

今度はSidekiq側の挙動を追っていきます。

Sidekiq::Shutdownが発生した際のコールスタックを一部抜粋しています。

 "/sidekiq-6.5.7/lib/sidekiq/processor.rb:57:in `kill'",
 "/sidekiq-6.5.7/lib/sidekiq/manager.rb:113:in `block in hard_shutdown'",
 "/sidekiq-6.5.7/lib/sidekiq/manager.rb:112:in `hard_shutdown'",
 "/sidekiq-6.5.7/lib/sidekiq/manager.rb:68:in `stop'",
 "/sidekiq-6.5.7/lib/sidekiq/launcher.rb:55:in `stop'",
 "/sidekiq-cron-1.8.0/lib/sidekiq/cron/launcher.rb:39:in `stop'",
 "/sidekiq-6.5.7/lib/sidekiq/cli.rb:129:in `rescue in launch'",
 "/sidekiq-6.5.7/lib/sidekiq/cli.rb:120:in `launch'",
 "/sidekiq-6.5.7/lib/sidekiq/cli.rb:110:in `run'",
 "/sidekiq-6.5.7/bin/sidekiq:31:in `<top (required)>'",

以下の流れのようです。

SIGTERM受信後、launcherの停止処理がされる（cli.rb）
Sidekiqのタイムアウト時間を引数に渡して、managerからジョブの停止処理が実行される。（manager.rb）
タイムアウト時間の間、実行中のジョブの終了を待つ。タイムアウト時間が過ぎると、実行中のジョブが空になったかどうかを確認する。（manager.rb）
ジョブが空にならなかった場合は、実行中のジョブを強制終了する。（manager.rb）
Sidekiq::Shutdownがraiseされる。（processor.rb）

なお、強制終了したジョブはRedisに戻され、Sidekiqの起動時に再度実行されます。 https://github.com/mperham/sidekiq/wiki/Signals#term

Sidekiq::Shutdownのエラーを再現させ、詳細を追ってみましょう。

エラーの再現方法とコードの流れの詳細

再現方法

※ SidekiqとRedisはローカルで起動している前提です

適当なジョブを作成します。タイムアウトするようにsleepを仕込みます。

class TestJob < ApplicationJob
 
  def perform()
    p "start perform"
    sleep(60)
    p "end perform"
  end
end

ジョブをRedisに積みます。

TestJob.perform_later

Sidekiqではジョブが実行されます。

{"ts":"2022-11-28T07:54:04.179Z","pid":95576,"tid":"pa4","lvl":"INFO", "msg":"start","ctx":{"class":"TestJob","jid":"073af9c41e5e7b1861b9af64","arguments":[]}}
{"ts":"2022-11-28T07:54:04.204Z","pid":95576,"tid":"pa4","lvl":"INFO", "msg":"Performing TestJob (Job ID: 3ac33ff8-c71e-4c05-becd-9fceb1589880) from Sidekiq(default) enqueued at 2022-11-28T07:54:04Z","ctx":{"class":"TestJob","jid":"073af9c41e5e7b1861b9af64","arguments":[]}}
"start perform"

※ ログのフォーマットは設定によって差異があると思うので参考程度にご覧ください

別のターミナルを開いて、psコマンドでSidekiqのプロセスIDを調べておきます。 SidekiqにSIGTERMを送ります。これで、約25秒後に「Sidekiq::Shutdown」のエラーがraiseされます。

> ps -ef | grep "sidekiq 6.5.7" 
> kill -TERM [sidekiqのPID]

SidekiqではSIGTERMを受け取り、Sidekiq停止の準備をします。

{"ts":"2022-11-28T07:54:24.352Z","pid":95576,"tid":"1vbw","lvl":"INFO","msg":"Shutting down"}
{"ts":"2022-11-28T07:54:24.353Z","pid":95576,"tid":"oy8","lvl":"INFO","msg":"Scheduler exiting..."}
{"ts":"2022-11-28T07:54:24.353Z","pid":95576,"tid":"1vbw","lvl":"INFO","msg":"Terminating quiet threads"}
{"ts":"2022-11-28T07:54:24.353Z","pid":95576,"tid":"oxw","lvl":"INFO","msg":"Scheduler exiting..."}
{"ts":"2022-11-28T07:54:24.453Z","pid":95576,"tid":"1vbw","lvl":"INFO","msg":"Pausing to allow jobs to finish..."}

25秒が経過すると、ジョブがRedisに戻され、「Sidekiq::Shutdown」エラーが発生します。

{"ts":"2022-11-28T07:54:49.298Z","pid":95576,"tid":"1vbw","lvl":"WARN","msg":"Terminating 1 busy threads"}
{"ts":"2022-11-28T07:54:49.302Z","pid":95576,"tid":"1vbw","lvl":"INFO","msg":"Pushed 1 jobs back to Redis"}
{"ts":"2022-11-28T07:54:49.304Z","pid":95576,"tid":"pa4","lvl":"ERROR","msg":"Error performing TestJob (Job ID: 3ac33ff8-c71e-4c05-becd-9fceb1589880) from Sidekiq(default) in 45099.29ms: Sidekiq::Shutdown (Sidekiq::Shutdown): 
（省略）

もう一度Sidekiqを起動してみると、先程のジョブが再度実行されます。

> bundle exec sidekiq -C config/sidekiq.yml

{"ts":"2022-11-28T07:55:30.219Z","pid":96115,"tid":"1vqv","lvl":"INFO","msg":"Starting processing, hit Ctrl-C to stop"}
{"ts":"2022-11-28T07:55:30.243Z","pid":96115,"tid":"opb","lvl":"INFO","msg":"start","ctx":{"class":"TestJob","jid":"073af9c41e5e7b1861b9af64","arguments":[]}}
{"ts":"2022-11-28T07:55:30.275Z","pid":96115,"tid":"opb","lvl":"INFO","msg":"Performing TestJob (Job ID: 3ac33ff8-c71e-4c05-becd-9fceb1589880) from Sidekiq(default) enqueued at 2022-11-28T07:54:04Z","ctx":{"class":"TestJob","jid":"073af9c41e5e7b1861b9af64","arguments":[]}}
"start perform"
（省略）

ソースコードのトレース

Sidekiq::shutdownエラー発生までのコードを追っていきます。

以下のメソッドでSidekiqがシグナルの受信を待ってます。

    def launch(self_read)
      if environment == "development" && $stdout.tty?
        logger.info "Starting processing, hit Ctrl-C to stop"
      end

      @launcher = Sidekiq::Launcher.new(@config)

      begin
        launcher.run

        while self_read.wait_readable
          signal = self_read.gets.strip
          handle_signal(signal)
        end
      rescue Interrupt
        logger.info "Shutting down"
        launcher.stop
        logger.info "Bye!"

        # Explicitly exit so busy Processor threads won't block process shutdown.
        #
        # NB: slow at_exit handlers will prevent a timely exit if they take
        # a while to run. If Sidekiq is getting here but the process isn't exiting,
        # use the TTIN signal to determine where things are stuck.
        exit(0)
      end
    end

SIGTERMが送信されると、handle_signal(signal)が実行されます。

        while self_read.wait_readable
          signal = self_read.gets.strip
>         handle_signal(signal)
        end

SIGNAL_HANDLERSの中で以下が呼び出され、

    def handle_signal(sig)
      logger.debug "Got #{sig} signal"
>     SIGNAL_HANDLERS[sig].call(self)
    end

Interruptがraiseされます。

      "TERM" => ->(cli) { raise Interrupt },

launchメソッドのrescueに入り、launcher.stopが実行されます。

      rescue Interrupt
        logger.info "Shutting down"
>       launcher.stop
        logger.info "Bye!"

親のstopを呼び出します。

      def stop
        cron_poller.terminate if @cron_poller
>       super
      end

ここで、Sidekiqのタイムアウト時間をdeadlineとして渡しています。

# Shuts down this Sidekiq instance. Waits up to the deadline for all jobs to complete.
def stop
  deadline = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + @config[:timeout]

  @done = true
  @manager.quiet
  @poller.terminate

> @manager.stop(deadline)

  # Requeue everything in case there was a thread which fetched a job while the process was stopped.
  # This call is a no-op in Sidekiq but necessary for Sidekiq Pro.
  strategy = @config[:fetch]
  strategy.bulk_requeue([], @config)

  clear_heartbeat
end

タイムアウト時間を待って、実行中のジョブが空になったかどうかを確認します。空になっていなければ、hard_shutdownが実行されます。

    def stop(deadline)
      quiet
      fire_event(:shutdown, reverse: true)

      # some of the shutdown events can be async,
      # we don't have any way to know when they're done but
      # give them a little time to take effect
      sleep PAUSE_TIME
      return if @workers.empty?

      logger.info { "Pausing to allow jobs to finish..." }
      wait_for(deadline) { @workers.empty? }
      return if @workers.empty?

>     hard_shutdown
    end

実行中のジョブはkillされて、

    def hard_shutdown
      # We've reached the timeout and we still have busy threads.
      # They must die but their jobs shall live on.
      cleanup = nil
      @plock.synchronize do
        cleanup = @workers.dup
      end

      if cleanup.size > 0
        jobs = cleanup.map { |p| p.job }.compact

        logger.warn { "Terminating #{cleanup.size} busy threads" }
        logger.debug { "Jobs still in progress #{jobs.inspect}" }

        # Re-enqueue unfinished jobs
        # NOTE: You may notice that we may push a job back to redis before
        # the thread is terminated. This is ok because Sidekiq's
        # contract says that jobs are run AT LEAST once. Process termination
        # is delayed until we're certain the jobs are back in Redis because
        # it is worse to lose a job than to run it twice.
        capsule.fetcher.bulk_requeue(jobs)
      end

      cleanup.each do |processor|
>       processor.kill
      end

Sidekiq::Shutdownが出力されます。

    def kill(wait = false)
      @done = true
      return unless @thread
      # unlike the other actors, terminate does not wait
      # for the thread to finish because we don't know how
      # long the job will take to finish.  Instead we
      # provide a `kill` method to call after the shutdown
      # timeout passes.
>     @thread.raise ::Sidekiq::Shutdown
      @thread.value if wait
    end

ここまでの調査結果まとめ

これで、ECSとSidekiqの挙動、エラーメッセージの原因が分かりました。

ECSのローリングアップデート時のECSとSidekiqの挙動

タスクで実行されているコンテナにSIGTERMが送られる
SIGTERMを受け取って、Sidekiqの停止処理を開始する
Sidekiqがジョブの停止処理を開始する実行中のジョブがある場合は25秒間終了を待つ
25秒以内に終わらないジョブは全て強制終了し、Redisに戻される（この際に「Sidekiq::shutdown」のログが出力される）
Sidekiqが終了する

※ 30秒以内に2 ~ 5が完了しない場合は、ECSからSidekiqコンテナにSIGKILLが送信され、無慈悲にプロセスが終了します。この場合、Sidekiqで実行中のジョブは揮発します。

Sidekiq::shutdownのエラーメッセージの原因

ECSのローリングアップデート時に、Sidekiqのタイムアウト時間（デフォルトだと25秒）以内に終了しなかった実行中のジョブが、Sidekiqの処理の中で強制終了した。その際に、Sidekiq::shutdownのエラーが出力された。というのが原因です。

ローリングアップデート時に気をつけるポイント

ECSからSIGKILLが送信されてSidekiqコンテナのプロセスが終了してしまう前に、Sidekiqの停止処理が正常に終了するように、気をつける必要があります。

実行中のジョブを揮発させてしまうのは避けたいです。

それぞれの時間は、デフォルト値から変更することも可能です。

ECSのSIGKILL送信までの時間：30秒
- 調整も可能（参考：ECS のアプリケーションを正常にシャットダウンする方法）
  - ECS タスクのパラメータの stopTimeout
  - ECS エージェントの環境変数 ECS_CONTAINER_STOP_TIMEOUT
Sidekiqのタイムアウト：25秒 ※ Sidekiq実行時に-tオプションで指定可能

この場合、Sidekiqのタイムアウト時間だけを伸ばしていたことで、SIGKILLでSidekiqコンテナのプロセスが切られ、ジョブが揮発してしまった。なんて事件が起きないようにします。

おわりに

ローリングアップデート時のECSとSidekiqの挙動を追い、「Sidekiq::Shutdown」のエラーメッセージの原因を調査しました。

Sidekiqのタイムアウト時間以内に終了しなかったジョブは、Redisに戻されてから再実行されます。なので、ローリングアップデート時に、コンテナ上のSidekiqで実行中のジョブへの影響は無いと判断しました。 ※ プロダクトのユースケースによって影響有無の判断は変わると思います。　考慮が必要な観点が増えれば、この限りではないことはご承知ください。

以上です。

マネーフォワードでは、エンジニアを募集しています。ご応募お待ちしています。

【会社情報】 ■Wantedly ■株式会社マネーフォワード ■福岡開発拠点 ■関西開発拠点（大阪/京都）

【SNS】 ■マネーフォワード公式note ■Twitter - 【公式】マネーフォワード ■Twitter - Money Forward Developers ■connpass - マネーフォワード ■YouTube - Money Forward Developers

Money Forward Developers Blog

株式会社マネーフォワード公式開発者向けブログです。技術や開発手法、イベント登壇などを発信します。サービスに関するご質問は、各サービス窓口までご連絡ください。