Cloudflare のダッシュボードでトラフィックの急増を調べに行ったら、その下にもっとひどいものが埋まっていました。1日のうちにアプリが処理したリクエストの22%が失敗していたのです。アラートは一つも鳴っていません。ヘルスチェックはすべて緑。ログも完全に健全に見えました。失敗したリクエストが、そもそもアプリケーションに届いていなかったからです。
原因は自分で書いたコンテナの起動スクリプトでした。まっとうな処理を、まったく間違ったタイミングで実行していました。
急増は囮だった#
もともと調べたかったのは、中央値が毎時121件のところに約4,900件が集中した1時間です。ユニークな訪問者は42人。1人あたり110リクエストで、人間のブラウジングではありません。
スキャナーでした。ボットが1体、存在しないサブドメインをでっち上げながら、それぞれにシークレットを要求して回っていました。
api-stage-asia.marucommunity.com/.env.local
api-us-east-1-demo.marucommunity.com/.env
api-eu-uat.marucommunity.com/wp-config.php~
app-test-us-east-1.marucommunity.com/actuator/configprops
prod-api-use2.marucommunity.com/.env.local
relay.marucommunity.com/.env.production30ほどのホスト名、思いつく限りの .env の変種、そして Django アプリに向けた Spring Boot の actuator エンドポイント。すべて正規ホストへの301になり、何も返していません。退屈で、実際に無害でした。
ただ、分析画面を開いたついでに同じ日をステータスコードで集計しました。本当の問題はそこにありました。
| ステータス | 24時間のリクエスト数 |
|---|---|
| 合計 | 11,350 |
| 504 Gateway Timeout | 2,474 |
22%です。しかもサイト全体に均等ではなく、いちばん痛いところに正確に集中していました。
| エンドポイント | 504 |
|---|---|
| 通知の未読数 | 621 |
| 通知一覧 | 614 |
| メッセージの未読数 | 469 |
| フィードカーソル | 210 |
どれもモバイルアプリが30秒ごとにポーリングしているエンドポイントです。つまりこれは抽象的なエラー率の数字ではありませんでした。ユーザーの端末が1日中、おそらく何週間も、未読バッジを静かに読み込めずにいたということです。
ログが健全に見えた理由#
最初はアプリが遅くなったのだろうと考えました。違いました。最悪の時間帯のアプリケーション側のリクエストログをアーカイブから取り出しました。
[2026-09-08 01:00:29] "GET /api/v1/notifications/unread_count/" 304 61.615
[2026-09-08 01:00:29] "GET /api/v1/notifications/" 304 63.568
[2026-09-08 01:00:59] "GET /api/v1/notifications/unread_count/" 304 58.742
[2026-09-08 01:00:59] "GET /api/v1/notifications/" 304 105.43844〜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 fly.app.instance AS inst, timestamp,
CASE WHEN message ILIKE '%Starting Granian%' THEN 'begin'
WHEN message ILIKE '%Migrations complete%' THEN 'migrated'
WHEN message LIKE '%"GET /api/health/%' THEN 'serving' END AS phase
FROM logs('koreapost', '2026-09-08')
)
SELECT inst,
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 instすべてのマシンで一貫して出た答えです。
| フェーズ | 所要時間 |
|---|---|
| 起動からマイグレーション完了まで | 10〜13秒 |
| マイグレーションから最初のリクエスト処理まで | 8〜19秒 |
| 合計 | 25〜33秒 |
そして、それが何回起きているかを数えました。
SELECT count(*) AS starts, count(DISTINCT fly.app.instance) AS machines
FROM logs('koreapost', '2026-09-08')
WHERE message ILIKE '%Starting Granian%'
-- starts: 92, machines: 101日にコールドスタートが92回。そのたびに、そのマシンへ振られたリクエストがタイムアウトする30秒の窓が開いていました。22%はもう謎ではありません。
原因は自分の entrypoint の中にあった#
すべてのマシンが、リクエストを1件処理する前に実行していたものです。
if [ "$1" = "granian-api" ]; then
echo "Running migrations..."
python manage.py migrate --noinput
echo "Running collectstatic in background..."
python manage.py collectstatic --noinput &
exec granian --interface wsgi koreapost_project.wsgi:application ...
fi「1日に92回」を思い浮かべながらもう一度読んでみてください。
migrate は完全な Django の起動です。全モデルをインポートし、Postgres に接続し、マイグレーションテーブルを問い合わせ、やることがないと判断する。共有CPUでは、何も達成しないために10秒かかります。collectstatic は2回目の完全な Django 起動で、そのうえ静的ファイルをオブジェクトストレージにアップロードし、Web サーバーが立ち上がろうとしているまさに同じ単一コアを奪い合います。Granian が3回目の起動です。
Python インタプリタが3つ、うち2つはすでに済んだ作業を繰り返しながら、マシンが目覚めるたびに毎回。
そう書いた理由はまっとうで、おそらくあなたのコードも似た形でしょう。マイグレーションはどこかで走らせる必要があり、Fly の release_command は以前ハングしたことがあり、entrypoint はデプロイ時に必ず実行される唯一の場所だからです。デプロイ作業を置く場所としては正しい。ただマシン起動ごとに置く場所としては正しくない。そしてマシンが自分で止まったり起きたりし始めた瞬間、その2つはもう同じ出来事ではありません。
バグの全体はこれで、よくある種類だと思います。
リリースに属する作業が、マシン起動ごとに実行されていました。ゼロスケールが1つの出来事を92個に変えたのです。
解法: リリースを一度だけ確保する#
あるイメージで起動する8台目のマシンでマイグレーションが走る必要はありません。そのイメージについて一度走ればよく、残りはそれが済んだと知ればよいだけです。
つまり、デプロイごとに名前が変わるロックです。Fly はその名前を FLY_IMAGE_REF として無料で渡してくれますし、Redis はすでにありました。全体が Django より前に走る小さなスクリプトなので、よくあるケースの答えはフレームワークの起動ではなくミリ秒で済みます。
def release_id() -> str:
"""デプロイされたイメージが変わったときにちょうど変わる値。"""
return os.getenv("FLY_IMAGE_REF") or os.getenv("FLY_MACHINE_VERSION") or ""
def claim() -> int:
release = release_id()
if not release:
return PREPARE
client = _client()
if client is None: # Redis がなければ、以前とまったく同じ挙動
return PREPARE
done_key, lock_key = _keys(release)
if client.get(done_key): # このイメージは誰かがすでに準備済み
return SKIP
owner = os.getenv("FLY_MACHINE_ID", "unknown")
if client.set(lock_key, owner, nx=True, ex=LOCK_TTL_SECONDS):
return PREPARE # 競争に勝ったので自分が処理する
# 他のマシンが準備中なら待つ。半分だけ適用されたスキーマに
# リクエストを受けるより、起動が遅いほうがましだから。
deadline = _monotonic() + WAIT_SECONDS
while _monotonic() < deadline:
_sleep(POLL_SECONDS)
if client.get(done_key):
return SKIP
if not client.get(lock_key) and client.set(lock_key, owner, nx=True, ex=LOCK_TTL_SECONDS):
return PREPARE # 持ち主がマイグレーション中に落ちたので引き継ぐ
return PREPARE # 十分待ったので自分でやるentrypoint は if 一つになります。
if python3 koreapost_project/release_gate.py claim; then
python manage.py migrate --noinput
python manage.py collectstatic --noinput &
python3 koreapost_project/release_gate.py done
fi
exec granian --interface wsgi koreapost_project.wsgi:application ...すべての失敗は「とにかく準備する」で終わらせる#
コードよりも、この部分こそ真似する価値があります。
このゲートはユーザーとスキーマのマイグレーションの間に立ちます。スキップする方向に間違えれば、マイグレーションされていないデータベースにリクエストを受けることになり、これは本物の障害です。準備する方向に間違えれば、冪等な no-op のマイグレーションを2回走らせて10秒を無駄にするだけです。
この2つの結果は対称ではないので、コードも対称に扱ってはいけません。不確かな経路はすべて PREPARE を返します。
- Redis がない、または到達不能。 準備します。これは以前の挙動そのものなので、キャッシュ障害は「壊れる」ではなく「遅くなる」に落ちます。
- 環境にイメージ参照がない。 準備します。どのリリースか分からない以上、準備済みかどうかも分かりません。
- ロックの持ち主がマイグレーション中に落ちた。 ロックが期限切れになり、次の待機者が引き継いで準備します。
- タイムアウトより長く待った。 それでも準備します。永遠にサービスできないマシンのほうが、重複マイグレーションより悪いからです。
逆方向の非対称を1つだけ意図的に入れてあります。他のマシンが実際にロックを保持していると分かったマシンは、サービスを始めずに待ちます。デプロイ中に起動が遅いのは構いません。半分だけ適用されたスキーマに問い合わせを受けるのは構います。
耐障害性のあるキャッシュラッパーでこれを組む場合、罠が1つあります。私のラッパーは Redis に到達できないとき add() が False を返し、それは「他の誰かがロックを持っている」とまったく同じに読めます。そのままなら全マシンがマイグレーションをスキップしていました。まさに危険な方向です。ロックを読み返して区別してください。誰も保持していないロックは、競争に負けたのではなく、キャッシュが壊れているという意味です。
Redis なしでテストする#
このロジックはユニットテストの価値があります。面白い経路ほど手作業では再現できないからです。メソッド2つのフェイクで足ります。
class FakeRedis:
"""ゲートに必要なだけの redis-py: get と、nx/ex を受ける set。"""
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 の別名を使っている点に注目してください。おかげで同じプロセスの他のスレッドに触れずにテストで差し替えられます。
def test_a_waiter_takes_over_when_the_owner_disappears(self):
self.assertEqual(release_gate.claim(), release_gate.PREPARE) # 持ち主がロックを取る
_done, lock_key = release_gate._keys(release_gate.release_id())
def owner_dies(_seconds):
self.redis.store.pop(lock_key, None) # ロックが期限切れになった
with patch.object(release_gate, "_sleep", owner_dies):
self.assertEqual(release_gate.claim(), release_gate.PREPARE)効果はあったか、半分は#
デプロイしたあと、マシンを止めてもう一度起動し、時計を見ました。起動処理は自分の判断を出力して、すぐに道を空けます。
15:23:34 Starting Granian (API server — HTTP/1.1 + HTTP/2)...
15:23:36 release gate: this release is already prepared, starting straight away
15:23:44 "GET /api/health/ HTTP/1.1" 20010秒、2台目は11秒でした。以前の25〜33秒に対して、窓の3分の2が消えたことになります。ゲート自体は Django を一切インポートしないので2秒で済みます。
しかし10秒はやはり10秒です。その最初の1秒に届いたリクエストは相変わらず失敗します。そこで残りを探しに行きました。
誰もキャッシュしていなかったバイトコード#
このイメージには、世の中のほぼすべての Python Dockerfile に書かれているあの一行があります。
ENV PYTHONDONTWRITEBYTECODE=1良い助言です。コンテナがランタイムにレイヤーへ .pyc を書き散らすべきではありません。私が考え抜いていなかったのは、この取引のもう半分です。ランタイムがバイトコードを決して書かず、ビルドも書かないなら、何一つキャッシュされず、プロセスが起動するたびに依存関係ツリー全体をソースからコンパイルすることになります。
数えてみました。
site-packages .py ファイル : 5,707
site-packages .pyc ファイル : 0Django も DRF もすべてのライブラリも、1日92回の起動のたびに再コンパイルされていました。本番マシンでの計測値です。
django.setup() | 時間 |
|---|---|
| 出荷時のまま | 5.15秒 |
compileall 後 | 3.17秒 |
修正は一行で、compileall は明示的に書き込むので上の環境変数があっても動きます。
RUN python -m compileall -q /app/.venv/lib /app/koreapost_project /app/marketplace /app/utils || trueビルド時間16秒、一度きり、キャッシュされるレイヤーで。
ついでにもっと静かな問題も見つけました。.dockerignore にはこう書いてありました。
__pycache__/
*.pycDocker はこれらをパスの各要素ではなく、相対パス全体に対して照合します。したがってアンカーされていないパターンはビルドコンテキストのルートでしか一致しません。ネストした __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' # 以前は 'stop'試そうとしたら Fly に拒否され、今回の作業でいちばん役に立つエラーメッセージを受け取りました。
failed to suspend VM: failed_precondition:
Machines with swap cannot be suspended私の設定の冒頭には、自分で書いて自分で信じていたコメントとともに、これがありました。
# メモリスパイクが OOM kill ではなくディスクへスワップされるためのクッション。
swap_size_mb = 2048もっともな予防策です。実際に働いていたのか。全マシンの答えはこうでした。
MemTotal: 985220 kB
SwapTotal: 2097148 kB
SwapFree: 2097148 kB1ページたりともスワップされたことがありません。その日のログにも OOM kill はなく、“oom” に一致した11行は、コンテンツハッシュにたまたまその3文字を含む JavaScript バンドルへのリクエストでした。そして本当のメモリガードはまったく別の場所、サーバーの起動コマンドにありました。--workers-max-rss 800 が、1GB の天井に届くはるか手前でワーカーを再生成していたのです。
つまりこのクッションは、一度も起きたことのない事象への保険であり、すでに別の仕組みが担保しており、その保険料がサスペンド機能でした。外しました。
| 復帰の経路 | 応答までの時間 |
|---|---|
| 今朝のコールドブート | 25〜33秒 |
| ゲートとバイトコード後のコールドブート | 9〜10秒 |
| サスペンドからの復帰 | 2.5〜3.1秒 |
3回試して、ばらつきは0.5秒以内。復帰直後にすべてのエンドポイントが250〜435ミリ秒で200を返しました。
マシンが眠っている間、ソケットはどうなるのか#
ろくなことになりませんし、直すためのフックもありません。Fly は VM を凍結します。プロセスにシグナルは届かず、降りていく途中で何も閉じられません。握っていた接続は目覚めたときもメモリに残り、数分前に相手が捨てたソケットを指しています。
これは降りるときに解く問題ではありません。上がってくるときに解く問題で、その大半は、すでに正しい判断をしてあったかどうかで決まります。
- データベース接続はリクエストごとに開く（
conn_max_age = 0）。古びるほど長生きする接続がありません。 - Redis キャッシュは例外を投げずに degrade する。 ラッパーが接続エラーを捕まえてミスとして返します。
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を大きく超えさせ、プロキシがサスペンド中のマシンへスケールアウトせざるを得ない状況にしました。
ステータスコード: 40 × 200
最も遅いもの: 2.1秒教訓は2つ、そして高くつくのは2つ目です。計測しやすい経路ではなく、ユーザーが通る経路を測ること。そして、ツールが何かを拒否したら、その拒否文を読むこと。「Machines with swap cannot be suspended」という一文が、この午後すべてを開いてくれました。
あなたのアプリで確認すべきこと#
アイドルのインスタンスを停止するプラットフォームを使っているなら、次の問いに私は半日を費やし、そして数週間分の静かな失敗を節約できたはずです。
- コールドスタートは何秒かかりますか。 コンテナが走る時間ではなく、実際のリクエストに応答するまでの時間です。秒数で即答できないなら、必要になる前に測ってください。
- entrypoint が起動ごとに行っている処理のうち、デプロイに属するものは何ですか。 マイグレーション、静的ファイル収集、キャッシュのウォームアップ、インデックス構築。1回ならどれも問題ありません。92回ならどれも高くつきます。
- バイトコードをキャッシュしているものはありますか。 ビルドに
compileallのないPYTHONDONTWRITEBYTECODEは、答えが「ノー」だという意味です。 - 停止ではなくサスペンドにできますか。 できないなら、何が邪魔していますか。私の場合は一度も使われなかったスワップでした。
- エッジには見えてオリジンには見えないエラーはありますか。 両者を比べてください。その差はレポートの癖ではなく、あいだで死んでいるリクエストであり、アプリケーションログは決してそれを見せてくれません。
ちなみにヘルスチェックはその間ずっと緑でした。いつもそうです。ヘルスチェックはすでに立ち上がっているマシンに対して走るので、そのマシンが存在する前の30秒については何も報告できません。