Fly.io移行後の運用と、あとから踏んだ地雷

移行そのものは無事に終わりました。 この記事では、その後に作り直した運用と、1 か月後に踏んだ障害を書きます。

ログの永続化

Fly.io の標準のログ UI は live tail が主体で、3 か月前のある日のエラーを探す用途には向きません。 移行前はログ SaaS で長期保管と検索をしていたので、その代わりが必要でした。

選んだのは fly-log-shipper（中身は Vector）で S3 に流し込む構成です。

リポジトリに持つファイル

3 つだけです。

fly-log-shipper/
├── fly.toml
├── Dockerfile          # FROM flyio/log-shipper:latest + sinks/aws_s3.toml を COPY
└── sinks/aws_s3.toml   # upstream の同名 sink を上書き

FROM flyio/log-shipper:latest
COPY sinks/aws_s3.toml /etc/vector/sinks/aws_s3.toml

upstream イメージの起動スクリプトは、必要な環境変数が揃っている sink だけを有効化します。 AWS_BUCKET などを secret に入れておけば S3 の sink だけが自動で立ち上がるので、自前の vector.toml を持たずに済みます。 upstream が更新されても、そのまま追随できます。

保存期間

ライフサイクル設定は入れず、無期限で置いています。

移行前の実績が月 835MB 程度なので、3 年で 30GB ほどです。 S3 Standard なら月 $1 に届きません。 この規模では、階層化を設計して保守するコストのほうが高くつきます。 コストが跳ねてきたら、後から Glacier Deep Archive への階層化を足せば済みます。

healthcheck に必要な権限

s3:PutObject だけを与えると、起動時にこう出ます。

ERROR vector::topology::builder: msg="Healthcheck failed." error=Invalid credentials
  component_kind="sink" component_type="aws_s3"

「Invalid credentials」と言われるので、まずアクセスキーを疑います。 ところがキーは正しく、原因は権限のほうにあります。 Vector のドキュメントは、S3 の sink が healthcheck に s3:ListBucket、書き込みに s3:PutObject を要求すると明示しています。

厄介なのは、healthcheck だけが落ちて PutObject は成功することです。 ログは S3 に届いているのに、エラーだけが出続けます。 切り分けは 2 つのコマンドで付きます。

# キー自体が有効か
AWS_ACCESS_KEY_ID=... AWS_SECRET_ACCESS_KEY=... AWS_REGION=ap-northeast-1 \
  aws sts get-caller-identity

# 実際に書き込めているか
aws s3 ls s3://myapp-fly-logs/ --recursive

前者が通り、後者に何か入っていれば、healthcheck だけの失敗です。

IAM ポリシーは 2 つのステートメントに分けます。

{
  "Version": "2012-10-17",
  "Statement": [
    {"Effect": "Allow", "Action": ["s3:PutObject"],  "Resource": "arn:aws:s3:::myapp-fly-logs/*"},
    {"Effect": "Allow", "Action": ["s3:ListBucket"], "Resource": "arn:aws:s3:::myapp-fly-logs"}
  ]
}

Resource の /* の有無が違います。 PutObject はオブジェクト単位の権限なので /* が付き、ListBucket はバケット単位の権限なので付きません。

machine が 2 台立つ

Fly は active と standby の 2 台を作ります。 ログシッパーに冗長性は要らず、むしろ二重転送になるので 1 台に固定します。

fly scale count 1 -a myapp-log-shipper
fly machine list -a myapp-log-shipper   # started が 1 台であることを確認

fly.toml に台数を宣言する仕組みはありません。 CLI で一度実行すればアプリの設定として残りますが、設定ファイルに書いていないのに 1 台になっている状態ができます。 リポジトリの手順書に、この操作を書き残しておく必要があります。

使わない public IP

[http_service] を書かなければ新規デプロイで public IP は付きませんが、確認はしておきます。

fly ips list -a myapp-log-shipper
fly ips release <IP> -a myapp-log-shipper

dedicated な IPv6 は無料なので、これは費用の話ではありません。 外部から到達する必要のないコンポーネントに IP が生えていること自体を避けます。

S3 のキーに UUID を入れる

キーの形はこうしました。

logs/<app-name>/dt=YYYY-MM-DD/YYYY-MM-DD-HH-<uuid>.json.gz

平時は毎時 1 ファイルなので、素直に作れば YYYY-MM-DD-HH.json.gz で足ります。 ところがデプロイや緊急再起動があると、同じ時間帯に追加の flush が走ります。 UUID がないと、そのとき前のファイルを上書きしてログを失います。

障害調査で最も見たいのは、そのデプロイや再起動があった時間帯です。 最も必要なログが最も失われやすい形になるので、UUID は省けません。

トークンのスコープ

個人のアクセストークンを使うと、作成者が退職した時点でログ収集が止まります。 止まったことに気づくのは、たいてい障害調査でログを見に行ったときです。

org スコープの readonly トークンを使い、有効期限も短く切ります。 長く取るほど、漏れたときに悪用できる期間もそのまま延びます。 短くするほど更新の回数は増えるので、どこに置くかは運用の手間との釣り合いです。

問題は、更新を忘れたときの止まり方です。 期限切れは退職のときと同じで、エラーも出ないまま途切れます。 カレンダーの予定だけに頼らず、S3 に新しいオブジェクトが届き続けているかを監視しておきます。 一定時間 PutObject がなければ通知する形にしておけば、原因が期限切れでも転送の障害でも、同じように気づけます。

たとえば 90 日ならこう書きます。

fly tokens create readonly -o <org> -x 2160h

プラットフォーム外へのバックアップ

Fly Managed Postgres には自動バックアップがあります。 ただし Fly が丸ごと落ちたときには、Fly の中のバックアップも取り出せません。

Heroku 時代も同じ構造の問題を抱えていたので、移行を機に手を入れました。 日次で S3 へダンプを吐くジョブを Recurring Tasks に追加しています。

db_backup_to_s3:
  class: DbBackupToS3Job
  schedule: every day at 2am
  timezone: Asia/Tokyo

class DbBackupToS3Job < ApplicationJob
  queue_as :file_generation

  # バックアップ用バケットは東京。アプリ本体の AWS_REGION とは別なので明示する
  BACKUP_REGION = 'ap-northeast-1'.freeze
  JOB_TIMEOUT = 15.minutes

  def perform
    Timeout.timeout(JOB_TIMEOUT) do
      bucket_name = ENV.fetch('BACKUP_S3_BUCKET', nil)
      return if bucket_name.blank?   # 未設定の環境では何もしない

      # pg_dump --no-acl --no-owner -Fc して BACKUP_REGION のバケットに upload
    end
  end
end

工夫は 2 点です。

環境変数がなければ何もせずに抜けます。 if Rails.env.production? のような分岐を書かずに済むので、同じコードがステージングでも安全に動きます。 本番でしか動かないコードは、本番でしか壊れ方が分かりません。 バックアップ先を増やしたくなったら、環境変数を設定するだけで足ります。

Timeout は必ず付けます。 ダンプが終わらないとき、worker のスロットを永久に占有するのを防ぐためです。 定期実行のジョブは、失敗するより終わらないほうが厄介です。

PDF 生成が止まった

移行から 1 か月ほど経ったころ、本番の PDF 生成がこのエラーで落ち始めました。

Ferrum::ProcessTimeoutError: Browser did not produce websocket url within 60 seconds

60 秒待っても WebSocket の URL が出てこない、と読めます。 PDF は headless Chrome で生成していて、Ferrum はそれを Ruby から操作するライブラリです。 素直に受け取れば Chrome の起動が遅いということなので、Docker で headless Chrome を動かすときの定番の原因である /dev/shm の 64MB を疑い、--disable-dev-shm-usage を追加して本番に入れました。 直りませんでした。

真因

Dockerfile が apt-get install chromium とバージョンを固定していなかったため、イメージの再ビルドで Chromium が 149 から 150 に上がっていました。 そして Chromium 150 は、Fly の実機では起動の途中に SIGTRAP で即座に死にます。 なぜ死ぬのかまでは特定していません。

Chrome が瞬時に死ぬので、Ferrum は WebSocket の URL を 60 秒待ってタイムアウトしていました。 60 秒待つという症状は、遅かったのではなく、最初から何も出てこなかったということです。

外れた仮説

デバッグの記録としては、外れた仮説のほうに価値があります。

• VM のメモリ枯渇：OOM の形跡がなく、実機のメモリにも余裕があった
• /dev/shm の枯渇：--disable-dev-shm-usage が実機で効かなかった。そもそも単発の起動でも落ちるので、共有メモリの枯渇なら説明が付かない
• 依存ライブラリの欠落：ldd で確認したところ欠けはなかった

単発で落ちるなら枯渇ではない、という切り分けは後から見れば当たり前です。 症状に飛びついて定番の対処を試す前に、仮説が症状の出方と噛み合っているかを確かめるべきでした。

対処

即時の対応は、Chromium 149 を含む障害前のイメージへのロールバックです。

fly deploy --image registry.fly.io/<app>:deployment-<BEFORE>

恒久の対応として、apt の chromium をやめ、Chrome for Testing の chrome-headless-shell をバージョン固定で入れました。 この headless-shell は 149 から 152 のいずれも Fly の実機で正常に起動しました。 ただしこの入れ替えでは、full Chromium から headless shell へという違いと、Debian のパッケージから Google 配布のビルドへという違いが同時に動いています。 どちらが原因だったのかは切り分けていないので、言い切れるのは「apt の chromium 150 は Fly で起動しない」ところまでです。

ARG CHROME_HEADLESS_SHELL_VERSION=150.0.7871.49
ENV CHROME_HEADLESS_SHELL_PATH=/usr/local/bin/chrome-headless-shell

RUN curl -fsSL "https://storage.googleapis.com/chrome-for-testing-public/${CHROME_HEADLESS_SHELL_VERSION}/linux64/chrome-headless-shell-linux64.zip" -o /tmp/chs.zip && \
    unzip -q /tmp/chs.zip -d /opt && \
    mv /opt/chrome-headless-shell-linux64 /opt/chrome-headless-shell && \
    chmod +x /opt/chrome-headless-shell/chrome-headless-shell && \
    ln -sf /opt/chrome-headless-shell/chrome-headless-shell /usr/local/bin/chrome-headless-shell

zip は chrome-headless-shell-linux64/ に展開されるので、名前を変えてから symlink を張ります。 ここを飛ばすとリンク切れになり、この記事が扱っているのと同じ「Chrome が起動しない」状態になります。

アプリ側は環境変数があればそれを使い、なければ自動検出に落とします。

browser_path: ENV['CHROME_HEADLESS_SHELL_PATH'].presence

この障害から持ち帰ったこと

本番で Chrome が起動しなくなったら、メモリより先にバージョンの変化を疑います。 apt-get install chromium のようにバージョンを固定しない記述は、コードを何も変えていないのにイメージを再ビルドしたら壊れる、という形で表面化します。 固定しないままにすれば、次のデプロイでまた同じことが起きます。

コンテナ内の Chrome を arm64 Mac の QEMU で検証するわけにはいきません。 SSE3 がないため、原因の違う SIGTRAP が出ます。 手元で再現したと思って別の原因を追いかけることになるので、実機で確認します。

fly ssh console -a myapp-production
grep sse3 /proc/cpuinfo

切り分けには、Chrome が user-data-dir 直下に作る DevToolsActivePort ファイルの有無が使えます。 あれば Chrome は起動していて Ferrum が拾えていない、なければ Chrome が起動していません。 今回は後者でした。 この確認ひとつで、調べる範囲が半分になります。

Excel 生成が SIGKILL された

こちらは移行とは独立した問題ですが、Heroku 時代の R14（メモリクォータ超過）の根本原因でもあったので併せて対処しました。

使っていた Excel 生成ライブラリが全セルをメモリ上に保持する設計で、行数の多いエクスポートでプロセスごと殺されていました。 紛らわしいのは、signal 9 をタイムアウトと読み違えやすいことです。 生成中にメモリが単調に増えるため、ジョブはいつも同じくらいの時間で死にます。 時間で切られているように見えるので、タイムアウトの設定を疑いたくなります。 実際には OOM Killer なので、タイムアウトをいくら伸ばしても直りません。

真のストリーミング生成ができるライブラリに載せ替えて解決しました。

この件で分かったのは、移行で直る問題と移行では直らない問題を分けて考える必要がある、ということです。 worker のメモリが 1GB から 2GB になったのは移行で得られた余裕で、症状の頻度は下がります。 ただし根本の原因はライブラリの設計なので、メモリを増やしても行数が増えればまた落ちます。

移行の直後は、あらゆる不具合が移行のせいに見えます。 移行したのに直っていないと焦れば、別の軸で対処すべき問題まで移行の失敗として扱ってしまいます。 ここは意識して切り分ける必要があります。

シリーズ 4 本を通して行った判断

いちばん大きかったのは、ジョブ基盤の入れ替えとプラットフォームの移行を、同じデプロイに載せなかったことです。 2 つを分けてあるので、問題が起きたときに、どちらの変更が原因かを切り分けられます。

ステージングで手順を確立してから本番に臨んだので、当日は同じ手順を踏むだけで済みました。 DB の移行コマンド、環境変数の移送、スモークテストの項目まで、当日に判断することは残していません。

旧環境は 1〜2 週間残しました。 切り戻し先があると分かっていれば、迷ったときに、無理に進めず止める選択を取れます。 結局使わなくても、無駄ではありません。

サイジングは実測で決めました。 1 CPU 専有の 2.5GB で load average 0.01 という Heroku Metrics の数値があったからこそ、shared-cpu-8x へ思い切って落とせました。 移行を検討し始めたら、まず現行環境が実際にどれだけ使っているかを確かめておきます。

この記事で書いたログの永続化とプラットフォーム外へのバックアップは、どちらも移行が終わってから作り直した部分です。 当日までで力尽きると、この 2 つは手つかずのまま残ります。

そして移行の成否を評価できたのは、直る問題と直らない問題を最後まで混ぜなかったからです。 混ぜて数えると、Excel の件のように移行と関係のない障害まで、移行の失敗に見えます。

参考リンク

• superfly/fly-log-shipper
• Vector AWS S3 sink
• Fly.io Tokens
• Fly.io Exporting Logs
• Chrome for Testing