ゼロスケールと、再起動のたびに起きる30秒の障害

追記（2026年10月22日）：この記事の一番大事な数字は間違っています。公開したその日に、ゾーンの504をユーザーエージェントごとに集計したところ、9月5日から9日までの7,344件はすべてCloudflare自身のEarly Hintsのプローブ（bastion early hintsとnginx-ssl early hints）によるものでした。これらはFlyのオリジンから応答を得られずに504として記録され、実際のリクエストと同じパスをなぞるので、ユーザー側の障害とまったく同じに見えます。同じ期間に、実際のクライアント（アプリ、ブラウザ、curl、検索エンジンのクローラー）が受け取った504はひとつもありませんでした。オリジンはpreloadヘッダーを送っておらず、Early Hintsは何の役にも立っていなかったので、その日のうちに無効にしました。以下のコールドスタートは本物で、対策も有効ですが、22%はユーザーが体験した数字ではありませんでした。Cloudflareの5xx率を障害と判断する前に、どのユーザーエージェントがそのエラーを受けているかを確認してください。

Cloudflare のダッシュボードでトラフィックの急増を調べに行ったら、その下にもっとひどいものが埋まっていました。1日のうちにアプリが処理したリクエストの22%が失敗していたのです。アラートは一つも鳴っていません。ヘルスチェックはすべて緑。ログも完全に健全に見えました。失敗したリクエストが、そもそもアプリケーションに届いていなかったからです。

原因は自分で書いたコンテナの起動スクリプトでした。まっとうな処理を、まったく間違ったタイミングで実行していました。

急増は囮だった

#

もともと調べたかったのは、中央値が毎時121件のところに約4,900件が集中した1時間です。ユニークな訪問者は42人。1人あたり110リクエストで、人間のブラウジングではありません。

スキャナーでした。ボットが1体、存在しないサブドメインをでっち上げながら、それぞれにシークレットを要求して回っていました。

api-stage-asia.example.com/.env.local
api-us-east-1-demo.example.com/.env
api-eu-uat.example.com/wp-config.php~
app-test-us-east-1.example.com/actuator/configprops
prod-api-use2.example.com/.env.local
relay.example.com/.env.production

30ほどのホスト名、思いつく限りの .env の変種、そして Django アプリに向けた、ある Java フレームワークの actuator エンドポイント。すべて正規ホストへの301になり、何も返していません。退屈で、実際に無害でした。

ただ、分析画面を開いたついでに同じ日をステータスコードで集計しました。本当の問題はそこにありました。

22%です。しかもサイト全体に均等ではなく、いちばん痛いところに正確に集中していました。

どれもモバイルアプリが30秒ごとにポーリングしているエンドポイントです。つまりこれは抽象的なエラー率の数字ではありませんでした。ユーザーの端末が1日中、おそらく何週間も、未読バッジを静かに読み込めずにいたということです。

ログが健全に見えた理由

#

最初はアプリが遅くなったのだろうと考えました。違いました。最悪の時間帯のアプリケーション側のリクエストログをアーカイブから取り出しました。

[2026-09-08 01:00:29] "GET /api/notifications/unread/" 304 61.615
[2026-09-08 01:00:29] "GET /api/notifications/"        304 63.568
[2026-09-08 01:00:59] "GET /api/notifications/unread/" 304 58.742
[2026-09-08 01:00:59] "GET /api/notifications/"        304 105.438

44〜105ミリ秒、すべて304。オリジンは速かったのです。

これが重要な手がかりで、ルールとして書いておく価値があります。エッジがオリジンの知らないエラーを報告しているなら、リクエストは到達する前に死んでいます。 アプリケーションログを読むのをやめて、その手前にあるものを見てください。

私の場合は Fly.io のプロキシで、答えはマシンのスケジューリング方法にありました。

ゼロスケールはコストの約束であって、レイテンシの約束ではない

#

私の設定はこうです。一見すると妥当でしょう。

[http_service]
  auto_stop_machines = 'stop'
  auto_start_machines = true
  min_machines_running = 1

アイドルのマシンは停止し、トラフィックが来れば再び起動する。使った分だけ払う。トラフィックにムラのある小さなアプリならまさに望む挙動で、だからこそマシンを10台定義していても普段は1台しか動いていませんでした。

この方式が隠している請求書はレイテンシです。停止中のマシンにリクエストが来れば、誰かがそのマシンの起動を待つことになります。起動がプロキシの我慢より長ければ、その誰かは504を受け取ります。

では私のマシンの起動には何秒かかっていたのか。一度も測っていませんでした。ログアーカイブは知っています。起動スクリプトが各フェーズを出力し、すべての行にマシンIDが付いているからです。

WITH s AS (
  SELECT instance, timestamp,
         CASE WHEN message ILIKE '%Starting app server%' THEN 'begin'
              WHEN message ILIKE '%Migrations complete%' THEN 'migrated'
              WHEN message LIKE  '%"GET /healthz%'       THEN 'serving' END AS phase
  FROM logs
  WHERE app = 'myapp' AND timestamp::date = '2026-09-08'
)
SELECT instance,
       min(timestamp) FILTER (WHERE phase = 'begin')    AS started,
       min(timestamp) FILTER (WHERE phase = 'migrated') AS migrated,
       min(timestamp) FILTER (WHERE phase = 'serving')  AS first_serve
FROM s GROUP BY instance

すべてのマシンで一貫して出た答えです。

そして、それが何回起きているかを数えました。

SELECT count(*) AS starts, count(DISTINCT instance) AS machines
FROM logs
WHERE app = 'myapp' AND timestamp::date = '2026-09-08'
  AND message ILIKE '%Starting app server%'
-- starts: 92, machines: 10

1日にコールドスタートが92回。そのたびに、そのマシンへ振られたリクエストがタイムアウトする30秒の窓が開いていました。22%はもう謎ではありません。

原因は自分の entrypoint の中にあった

#

すべてのマシンが、リクエストを1件処理する前に実行していたものです。

# entrypoint.sh, run on every machine start
echo "Running migrations..."
python manage.py migrate --noinput

echo "Running collectstatic in background..."
python manage.py collectstatic --noinput &

exec "$@"    # then start the app server

「1日に92回」を思い浮かべながらもう一度読んでみてください。

migrate は完全な Django の起動です。全モデルをインポートし、Postgres に接続し、マイグレーションテーブルを問い合わせ、やることがないと判断する。共有CPUでは、何も達成しないために10秒かかります。collectstatic は2回目の完全な Django 起動で、そのうえ静的ファイルをオブジェクトストレージにアップロードし、Web サーバーが立ち上がろうとしているまさに同じ単一コアを奪い合います。アプリサーバーが3回目の起動です。

Python インタプリタが3つ、うち2つはすでに済んだ作業を繰り返しながら、マシンが目覚めるたびに毎回。

そう書いた理由はまっとうで、同じような形になっているコードは多いはずです。マイグレーションはどこかで走らせる必要があり、Fly の release_command は以前ハングしたことがあり、entrypoint はデプロイ時に必ず実行される唯一の場所だからです。デプロイ作業を置く場所としては正しい。ただマシン起動ごとに置く場所としては正しくない。そしてマシンが自分で止まったり起きたりし始めた瞬間、その2つはもう同じ出来事ではありません。

バグの全体はこれで、よくある種類だと思います。

リリースに属する作業が、マシン起動ごとに実行されていました。ゼロスケールが1つの出来事を92個に変えたのです。

解法: リリースを一度だけ確保する

#

あるイメージで起動する8台目のマシンでマイグレーションが走る必要はありません。そのイメージについて一度走ればよく、残りはそれが済んだと知ればよいだけです。

つまり、デプロイごとに名前が変わるロックです。Fly はその名前を FLY_IMAGE_REF として無料で渡してくれますし、Redis はすでにありました。全体が Django より前に走る小さなスクリプトなので、よくあるケースの答えはフレームワークの起動ではなくミリ秒で済みます。

# release_gate.py: runs before Django exists. Exit code 0 means "prepare this release".
import os, time

PREPARE, SKIP = 0, 1
LOCK_TTL, WAIT, POLL = 300, 240, 2
_sleep, _monotonic = time.sleep, time.monotonic    # aliases, so tests can replace them


def release_id() -> str:
    """Something that changes exactly when the deployed image does."""
    return os.getenv("FLY_IMAGE_REF") or os.getenv("FLY_MACHINE_VERSION") or ""


def claim(client, release: str) -> int:
    if client is None or not release:   # no Redis, or no idea which release: behave as before
        return PREPARE
    done_key, lock_key = f"release:{release}:done", f"release:{release}:lock"
    if client.get(done_key):            # somebody already did it for this image
        return SKIP

    owner = os.getenv("FLY_MACHINE_ID", "unknown")
    if client.set(lock_key, owner, nx=True, ex=LOCK_TTL):
        return PREPARE                  # we won the race; we do the work

    # Someone else is preparing. Wait for them, because serving requests
    # against a half-migrated schema is worse than starting slowly.
    deadline = _monotonic() + WAIT
    while _monotonic() < deadline:
        _sleep(POLL)
        if client.get(done_key):
            return SKIP
        if client.set(lock_key, owner, nx=True, ex=LOCK_TTL):
            return PREPARE              # the owner died and its lock expired; take over
    return PREPARE                      # waited long enough; do it ourselves

# ... plus `done` (sets done_key) and a main() that treats any Redis error as PREPARE

entrypoint は if 一つになります。

if python3 release_gate.py claim; then
    python manage.py migrate --noinput
    python manage.py collectstatic --noinput &
    python3 release_gate.py done
fi

exec "$@"

すべての失敗は「とにかく準備する」で終わらせる

#

コードよりも、この部分こそ真似する価値があります。

このゲートはユーザーとスキーマのマイグレーションの間に立ちます。スキップする方向に間違えれば、マイグレーションされていないデータベースにリクエストを受けることになり、これは本物の障害です。準備する方向に間違えれば、冪等な no-op のマイグレーションを2回走らせて10秒を無駄にするだけです。

この2つの結果は対称ではないので、コードも対称に扱ってはいけません。不確かな経路はすべて PREPARE を返します。

• Redis がない、または到達不能。 準備します。これは以前の挙動そのものなので、キャッシュ障害は「壊れる」ではなく「遅くなる」に落ちます。
• 環境にイメージ参照がない。 準備します。どのリリースか分からない以上、準備済みかどうかも分かりません。
• ロックの持ち主がマイグレーション中に落ちた。 ロックが期限切れになり、次の待機者が引き継いで準備します。
• タイムアウトより長く待った。 それでも準備します。永遠にサービスできないマシンのほうが、重複マイグレーションより悪いからです。

逆方向の非対称を1つだけ意図的に入れてあります。他のマシンが実際にロックを保持していると分かったマシンは、サービスを始めずに待ちます。デプロイ中に起動が遅いのは構いません。半分だけ適用されたスキーマに問い合わせを受けるのは困ります。

接続エラーを握りつぶすキャッシュラッパーの上にこれを組む場合、罠が1つあります（私も最初はそうしていました）。そういうラッパーは Redis に到達できないとき add() が False を返し、それは「他の誰かがロックを持っている」とまったく同じに読めます。そのままなら全マシンがマイグレーションをスキップしていました。まさに危険な方向です。ロックを読み返して区別してください。誰も保持していないロックは、競争に負けたのではなく、キャッシュが壊れているという意味です。

Redis なしでテストする

#

このロジックはユニットテストの価値があります。面白い経路ほど手作業では再現できないからです。メソッド2つのフェイクで足ります。

class FakeRedis:
    """Enough of a Redis client for the gate: get, and set with nx/ex."""

    def __init__(self) -> None:
        self.store: dict[str, str] = {}

    def get(self, key): return self.store.get(key)

    def set(self, key, value, nx=False, ex=None):
        if nx and key in self.store:
            return None
        self.store[key] = value
        return True

あとは時間を自分の都合で進めて厄介なケースを動かします。ゲートが time.sleep を直接呼ばず、モジュールレベルの _sleep と _monotonic の別名を使っているのはこのためです。こうしておけば、同じプロセスの他のスレッドに影響する time モジュールごとのパッチを当てずに、テストで差し替えられます。

def test_a_waiter_takes_over_when_the_owner_disappears(self):
    redis = FakeRedis()
    self.assertEqual(release_gate.claim(redis, "img-1"), release_gate.PREPARE)   # the owner takes the lock

    def owner_dies(_seconds):
        redis.store.pop("release:img-1:lock", None)                              # its lock expired

    with patch.object(release_gate, "_sleep", owner_dies):
        self.assertEqual(release_gate.claim(redis, "img-1"), release_gate.PREPARE)

効果はあったか、半分は

#

デプロイしたあと、マシンを止めてもう一度起動し、時計を見ました。起動処理は自分の判断を出力して、すぐに道を空けます。

15:23:34  Starting app server...
15:23:36  release gate: this release is already prepared, starting straight away
15:23:44  "GET /healthz HTTP/1.1" 200

10秒、2台目は11秒でした。以前の25〜33秒に対して、窓の3分の2が消えたことになります。ゲート自体は Django を一切インポートしないので2秒で済みます。

しかし10秒はやはり10秒です。その最初の1秒に届いたリクエストは相変わらず失敗します。そこで残りを探しに行きました。

誰もキャッシュしていなかったバイトコード

#

このイメージには、世の中のほぼすべての Python Dockerfile に書かれているあの一行があります。

ENV PYTHONDONTWRITEBYTECODE=1

良い助言です。コンテナがランタイムにレイヤーへ .pyc を書き散らすべきではありません。私が考え抜いていなかったのは、この取引のもう半分です。ランタイムがバイトコードを決して書かず、ビルドも書かないなら、何一つキャッシュされず、プロセスが起動するたびに依存関係ツリー全体をソースからコンパイルすることになります。

数えてみました。

site-packages .py  files : 5,707
site-packages .pyc files : 0

Django も REST フレームワークもすべてのライブラリも、1日92回の起動のたびに再コンパイルされていました。本番マシンでの計測値です。

修正は一行で、compileall は明示的に書き込むので上の環境変数があっても動きます。

RUN python -m compileall -q /app/.venv/lib /app/myapp || true

ビルド時間16秒、一度きり、キャッシュされるレイヤーで。

ついでにもっと静かな問題も見つけました。.dockerignore にはこう書いてありました。

__pycache__/
*.pyc

Docker はこれらをパスの各要素ではなく、相対パス全体に対して照合します。したがってアンカーされていないパターンはビルドコンテキストのルートでしか一致しません。ネストした __pycache__ はすべてイメージに載っていました。ノートパソコンの Python 3.15 がコンパイルした .pyc が218個、インタプリタが3.14のイメージの中に紛れ込み、すべて静かに無視されていたのです。パターンは **/__pycache__/ と **/*.pyc であるべきでした。

正直な結果: 全体では2秒ではなく1秒ほどの改善でした。10秒が9秒になりました。隔離されたベンチマークは、いつもどおり過大に見せていたわけです。

サスペンドと、それを塞いでいた一行

#

9秒まで来て、取り除ける作業が尽きました。残っていたのは避けられない起動1回分です。Python が立ち上がり、Django がインポートされ、WSGI アプリが共有コアの上で起き上がる時間。

ならば起動しなければいい。Fly はマシンをシャットダウンする代わりにメモリをスナップショットできます。

[http_service]
  auto_stop_machines = 'suspend'   # was 'stop'

試そうとしたら Fly に拒否され、今回の作業でいちばん役に立つエラーメッセージを受け取りました。

failed to suspend VM: failed_precondition:
Machines with swap cannot be suspended

私の設定の冒頭には、自分で書いて自分で信じていたコメントとともに、これがありました。

# Swap cushion so a memory spike swaps to disk instead of getting OOM-killed.
swap_size_mb = 2048

もっともな予防策です。実際に働いていたのか。全マシンの答えはこうでした。

MemTotal:   985220 kB
SwapTotal: 2097148 kB
SwapFree:  2097148 kB

1ページたりともスワップされたことがありません。その日のログにも OOM kill はなく、“oom” に一致した11行は、コンテンツハッシュにたまたまその3文字を含む JavaScript バンドルへのリクエストでした。そして本当のメモリガードはまったく別の場所、アプリサーバー自身の設定にありました。800MB を超えたワーカーを、1GB の天井に届くはるか手前で再生成していたのです。

つまりこのクッションは、一度も起きたことのない事象への保険であり、すでに別の仕組みが担保しており、その保険料がサスペンド機能でした。外しました。

3回試して、ばらつきは0.5秒以内。復帰直後にすべてのエンドポイントが250〜435ミリ秒で200を返しました。

マシンが眠っている間、ソケットはどうなるのか

#

ろくなことになりませんし、直すためのフックもありません。Fly は VM を凍結します。プロセスにシグナルは届かず、降りていく途中で何も閉じられません。握っていた接続は目覚めたときもメモリに残り、数分前に相手が捨てたソケットを指しています。

これは降りるときに解く問題ではありません。上がってくるときに解く問題で、その大半は、すでに正しい判断をしてあったかどうかで決まります。

• データベース接続はリクエストごとに開く（conn_max_age = 0）。古びるほど長生きする接続がありません。
• Redis キャッシュは例外を投げずに縮退する。 ラッパーが接続エラーを捕まえてミスとして返します。

2つ目が働く瞬間を実際に見られました。ある復帰で、予想どおりの失敗がログに出ました。

redis.exceptions.ConnectionError: Error while reading from fly-...

そしてそれが起きたリクエストは3.6秒で200を返しました。死んだキャッシュは遅いページであって、エラーページではないからです。以降の復帰では何も出ませんでした。

使っているキャッシュクライアントが死んだ接続で例外を投げるなら、サスペンドは復帰のたびに500の花火を打ち上げます。設定を切り替える前に確認してください。

私に嘘をついたテスト

#

最初のサスペンド計測は、この機能が大失敗だと告げました。502、30秒後、しかも2回続けて。

私は fly-force-instance-id でリクエストを特定のマシンに固定していました。インスタンス1台を負荷試験するには素晴らしいヘッダーですが、この用途には最悪です。インスタンスを強制すると、そのマシンを起こしてくれるはずのプロキシのロジックを迂回してしまうからです。Fly はちゃんと教えてくれていました。それをエラーではなく答えとして読んでいれば。

machine was recently stopped and is unavailable to service request

意味のある数字は、実トラフィックが通る経路から出てきます。エッジ経由で同時40リクエスト、ソフトリミット12を大きく超えさせ、プロキシがサスペンド中のマシンへスケールアウトせざるを得ない状況にしました。

status codes:  40 × 200
slowest:       2.1s

教訓は2つ、そして高くつくのは2つ目です。計測しやすい経路ではなく、ユーザーが通る経路を測ること。そして、ツールが何かを拒否したら、その拒否文を読むこと。「Machines with swap cannot be suspended」という一文が、この午後の作業すべての突破口になりました。

あなたのアプリで確認すべきこと

#

アイドルのインスタンスを停止するプラットフォームを使っているなら、次の問いに答えるのに私は半日かかりましたが、もっと早く確かめていれば、何週間も続いた静かな失敗を防げたはずです。

1. コールドスタートは何秒かかりますか。 コンテナが走る時間ではなく、実際のリクエストに応答するまでの時間です。秒数で即答できないなら、必要になる前に測ってください。
2. entrypoint が起動ごとに行っている処理のうち、デプロイに属するものは何ですか。 マイグレーション、静的ファイル収集、キャッシュのウォームアップ、インデックス構築。1回ならどれも問題ありません。92回ならどれも高くつきます。
3. バイトコードをキャッシュしているものはありますか。 ビルドに compileall のない PYTHONDONTWRITEBYTECODE は、答えが「ノー」だという意味です。
4. 停止ではなくサスペンドにできますか。 できないなら、何が邪魔していますか。私の場合は一度も使われなかったスワップでした。
5. エッジには見えてオリジンには見えないエラーはありますか。 両者を比べてください。その差はレポートの癖ではなく、あいだで死んでいるリクエストであり、アプリケーションログは決してそれを見せてくれません。

ちなみにヘルスチェックはその間ずっと緑でした。いつもそうです。ヘルスチェックはすでに立ち上がっているマシンに対して走るので、そのマシンが存在する前の30秒については何も報告できません。