1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@gerrard15
in

AWS Lambda Web Adapter の `app is not ready after` を調査し、TypeScript の実行時起動を事前ビルド方式へ変更した話

1
Posted at

AWS Lambda Web Adapter を利用するコンテナイメージ形式の Lambda で、次のようなログが継続的に出ていました。

INFO lambda_web_adapter: app is not ready after 2000ms url=http://127.0.0.1:8080/version
error: script "start" was terminated by signal SIGTERM (Polite quit request)

調査したところ、Lambda の実行環境が起動してから、アプリケーションが readiness check に応答できるようになるまで、長いケースでは数十秒かかっていました。

また、一部の実行環境では、ready になる前にプロセスが終了していました。

最終的には、Lambda 起動時に tsx で TypeScript を実行する構成をやめ、Docker build 時に生成した JavaScript を Bun で実行する構成へ変更しました。

検証環境では、readiness の最大待ち時間が約40秒から約8秒まで短縮され、「ready にならないまま終了する」という今回問題視していたパターンも確認されなくなりました。

なお、本記事は特定のアプリケーションにおける事例です。tsx が常に遅い、あるいは Lambda で利用すべきではないという趣旨ではありません。

この記事の要点

  • app is not ready after は、AWS Lambda Web Adapter の readiness check がまだ成功していないことを示す
  • ログの総件数だけでなく、@logStream 単位で最大待ち時間と前後のログを追うと調査しやすい
  • SIGTERM 単体では起動失敗と断定せず、起動完了ログや readiness 応答と組み合わせて判断する
  • 少なくとも計測対象の Secrets Manager 取得だけでは、数十秒規模の待ち時間を説明できなかった
  • 今回は tsx を含むアプリケーションの起動経路が主要な遅延要因の一つと判断した
  • TypeScript の実行時起動をやめ、事前ビルドした JavaScript を Bun で実行することで改善した

構成

今回の構成を整理すると、次のようになります。

  • AWS Lambda
  • コンテナイメージ
  • AWS Lambda Web Adapter
  • TypeScript
  • Bun
  • Provisioned Concurrency を利用
  • readiness check path: /version

AWS Lambda Web Adapter は、コンテナ内で起動する Web アプリケーションに対して readiness check を行い、HTTP リクエストを受け付けられる状態になったか確認します。

readiness check のポート、パス、プロトコル、正常とみなす HTTP ステータスコードの範囲は、環境変数で設定できます。

参考:

app is not ready after が意味すること

次のログから分かるのは、指定された readiness check がまだ成功していないという点までです。

INFO lambda_web_adapter: app is not ready after 2000ms url=http://127.0.0.1:8080/version

原因としては、例えば次のようなものが考えられます。

  • Web サーバーがまだ listen を開始していない
  • アプリケーションの初期化処理が完了していない
  • readiness check のポートやパスが誤っている
  • readiness endpoint が正常とみなされないステータスコードを返している
  • readiness endpoint 内部の処理に時間がかかっている
  • アプリケーションが起動途中で終了している

そのため、app is not ready after が出たという事実だけでは、原因までは特定できません。

発生していたログ

CloudWatch Logs では、次のように待ち時間が増えていくログが記録されていました。

INFO lambda_web_adapter: app is not ready after 2000ms url=http://127.0.0.1:8080/version
INFO lambda_web_adapter: app is not ready after 4000ms url=http://127.0.0.1:8080/version
INFO lambda_web_adapter: app is not ready after 6000ms url=http://127.0.0.1:8080/version
...
error: script "start" was terminated by signal SIGTERM (Polite quit request)

このパターンが一時的ではなく繰り返し発生していたため、アプリケーションの起動処理を詳しく調べることにしました。

ここで注意したのが、SIGTERM の扱いです。

Lambda の実行環境には、初期化、呼び出し、シャットダウンというライフサイクルがあります。

そのため、終了シグナルが記録されたことだけで、アプリケーションの起動処理に異常があったと断定することはできません。

今回は SIGTERM の有無だけでなく、同じ log stream 内で次のログまで到達しているかを確認しました。

  • Web サーバーの起動完了ログ
  • readiness endpoint へのアクセスログ
  • readiness endpoint の応答後に出力されるログ

参考:

最初に疑ったこと

最初に疑ったのは、起動時に行っている外部リソースへのアクセスです。

例えば、次のような処理です。

  • Secrets Manager などからの設定取得
  • DB 接続の初期化
  • 外部 API クライアントの初期化
  • 各種設定ファイルの読み込み

特に VPC 内の Lambda から AWS の各種 API や外部サービスへアクセスしている場合は、VPC Endpoint、NAT Gateway、DNS、ネットワーク経路などの影響も候補になります。

ただし、既存ログから分かったのは「アプリケーション全体の起動が遅い」ということだけでした。

どの処理で何秒待っているかまでは判断できませんでした。

調査1: log stream ごとの最大待ち時間を見る

まず、CloudWatch Logs Insights を使って、log stream ごとの最大待ち時間を確認しました。

fields @timestamp, @logStream, @message
| filter @message like /app is not ready after/
| parse @message /after (?<notReadyMs>\d+)ms/
| stats
    max(toNumber(notReadyMs)) as maxNotReadyMs,
    count(*) as logCount
  by @logStream
| sort maxNotReadyMs desc
| limit 50

parse でログ中の待ち時間を取り出し、数値へ変換してから最大値を集計しています。

ログの総件数だけを見ると、「同じ実行環境で長時間待ち続けていたのか」「多数の実行環境で短時間ずつ発生したのか」が分かりません。

@logStream ごとに集約することで、起動単位に近い粒度で状況を追いやすくなりました。

参考:

調査2: 起動完了と終了ログを関連付ける

次に、readiness 待ち、起動完了、終了に関係するログをまとめて確認しました。

fields @timestamp, @logStream, @message
| filter @message like /app is not ready after|SIGTERM|exited with code 143|Server is running|GET \/version/
| parse @message /after (?<notReadyMs>\d+)ms/
| stats
    max(toNumber(notReadyMs)) as maxNotReadyMs,
    sum(if(@message like /app is not ready after/, 1, 0)) as notReadyLogs,
    sum(if(@message like /SIGTERM|exited with code 143/, 1, 0)) as sigtermLogs,
    sum(if(@message like /Server is running/, 1, 0)) as serverRunningLogs,
    sum(if(@message like /GET \/version/, 1, 0)) as versionLogs
  by @logStream
| sort maxNotReadyMs desc
| limit 50

Server is running は例なので、実際のアプリケーションが出力する起動完了ログに合わせて置き換えます。

ここで確認したかったのは、単純な SIGTERM の件数ではありません。

  • readiness check は最終的に成功したか
  • Web サーバーは起動完了ログを出しているか
  • /version へのアクセスまで到達しているか
  • それらより前にプロセスが終了していないか

というログの流れを確認しました。

調査3: Secrets Manager の取得処理を計測する

外部リソースへのアクセスが遅いかを確認するため、まず Secrets Manager の取得箇所に経過時間を出すログを追加しました。

概念的には、次のような計測です。

async function measure<T>(
  step: string,
  task: () => Promise<T>,
): Promise<T> {
  const startedAt = performance.now();

  try {
    const result = await task();

    console.info(
      JSON.stringify({
        event: "startup_step",
        step,
        status: "ok",
        elapsedMs: Math.round(performance.now() - startedAt),
      }),
    );

    return result;
  } catch (error) {
    console.error(
      JSON.stringify({
        event: "startup_step",
        step,
        status: "error",
        elapsedMs: Math.round(performance.now() - startedAt),
        errorName: error instanceof Error ? error.name : "UnknownError",
      }),
    );

    throw error;
  }
}

利用側は次のようになります。

const config = await measure(
  "load_secret_config",
  loadSecretConfig,
);

ログには、次の情報だけを出しました。

  • 処理名
  • 成功または失敗
  • 経過時間
  • エラーの種類

Secret の値、Secret 名、接続先、認証情報などは出力しません。

計測した範囲では、Secrets Manager の取得処理に数十秒規模の遅延は確認できませんでした。

ただし、キャッシュの状態などによって実際のアクセス経路が変わる可能性があります。また、DB 接続やすべての外部 API を網羅的に計測したわけでもありません。

したがって、外部リソースへのアクセス全般が原因ではないと断定したのではなく、「少なくとも今回計測した Secrets Manager の取得だけでは、観測した待ち時間を説明できなかった」と判断しました。

調査で分かったこと

調査の結果、次の傾向が確認できました。

  • readiness endpoint が応答可能になるまで、最大で約40秒かかるケースがあった
  • readiness 成功を示すログがないまま終了する log stream があった
  • 少なくとも計測対象の Secrets Manager 取得だけでは、数十秒規模の待ち時間を説明できなかった
  • アプリケーション自身の起動経路に時間がかかっている可能性が高かった

SIGTERM 単体では起動失敗と判断できません。

しかし、長時間の readiness 待ちに加えて、起動完了ログや readiness 応答がないまま終了する流れが繰り返し確認できたため、アプリケーションの起動方法を見直すことにしました。

ボトルネック候補: tsx による実行時起動

変更前の起動コマンドは、次のような構成でした。

{
  "scripts": {
    "start": "tsx src/server.ts"
  }
}

tsx は TypeScript ファイルを直接実行できるツールです。

参考:

開発環境では、事前ビルドなしで TypeScript を実行できるため便利です。

一方、この構成では Lambda の実行環境が起動するたびに、アプリケーション本体の初期化に加えて、tsx の起動と TypeScript の実行時変換が起動経路に含まれます。

事前ビルドした JavaScript に変更しても、依存モジュールの読み込みや通常のモジュール解決がなくなるわけではありません。

今回、起動経路から外せるのは、主に tsx を介した起動と TypeScript の実行時変換です。

また、今回の比較は tsx のオーバーヘッドだけを分離したベンチマークではありません。

ビルド方法や import の整理なども含む変更です。

そのため、「tsx だけが唯一の原因だった」とは断定していません。

変更前後のログと各処理の計測結果から、tsx を含む実行時 TypeScript 起動が、主要な遅延要因の一つだったと判断しています。

対応: Docker build 時に JavaScript を生成する

Docker build 時に TypeScript を JavaScript へ変換し、Lambda 実行時は生成済みの JavaScript を Bun で起動するように変更しました。

変更前は次のとおりです。

{
  "scripts": {
    "start": "tsx src/server.ts"
  }
}

変更後は次のようにしました。

{
  "scripts": {
    "build": "tsc",
    "start": "bun dist/src/server.js"
  }
}

Dockerfile では、build stage でビルドを実行し、生成物を runner stage へコピーします。

単一パッケージ構成に簡略化すると、次のようなイメージです。

FROM oven/bun:1 AS builder

WORKDIR /app

COPY package.json bun.lock ./
RUN bun install --frozen-lockfile

COPY . .
RUN bun run build

FROM oven/bun:1-slim AS runner

WORKDIR /app

ENV NODE_ENV=production

COPY package.json bun.lock ./
RUN bun install --frozen-lockfile --production

COPY --from=builder /app/dist ./dist

CMD ["bun", "dist/src/server.js"]

Lambda Web Adapter の組み込み、環境変数、設定ファイルなどは省略しています。

実際の構成では複数のパッケージがあったため、依存される側から順にビルドするようにしました。

runner stage には、少なくとも次のものが必要です。

  • ビルド済み JavaScript
  • 実行時に必要な依存パッケージ
  • package.json
  • 必要な設定ファイルや静的ファイル

Bun の Docker 利用例については、公式ガイドも参考になります。

事前ビルドで注意した点

import alias は tsc が書き換えてくれるとは限らない

TypeScript 実行時には動いていた import alias が、ビルド後の JavaScript では解決できないことがあります。

例えば、次のような import です。

import { foo } from "src/lib/foo";

tsconfig.json の paths は、TypeScript にモジュールの探索方法を伝える設定です。

一方で、tsc が出力する import path 自体を書き換えるものではありません。

参考:

ビルド後にも次のコードが残る可能性があります。

import { foo } from "src/lib/foo";

実行時のランタイムがこのパスを解決できなければ、アプリケーションは起動に失敗します。

今回は、ビルド後の実行環境でも解決できるように、import を整理しました。

対応方法としては、例えば次のような選択肢があります。

  • 相対 import に変更する
  • workspace package 名を使用する
  • package.json の exports を利用する
  • bundler 側で alias を解決する
  • runtime 側の alias 解決機能を明示的に利用する

TypeScript の型チェックが通ることと、生成された JavaScript が実行できることは、分けて確認する必要があります。

ビルド成果物を直接起動して確認する

Docker image を作る前に、生成された JavaScript を直接起動して確認しました。

bun run build
bun dist/src/server.js

「ビルドが成功した」だけでなく、「生成物を実際に起動できる」ことまで確認するのが重要です。

特に、次の問題はビルド成功後の起動時に初めて判明することがあります。

  • import alias を解決できない
  • 実行時の依存パッケージが不足している
  • ESM と CommonJS の設定が一致していない
  • ビルド成果物のパスが想定と異なる
  • 設定ファイルや静的ファイルがコピーされていない

.dockerignore でローカル生成物を除外する

Docker build context にローカルの node_modules や古い dist が含まれると、ビルドの再現性が下がります。

そこで、次のような除外を追加しました。

**/node_modules
**/dist

主な目的は次のとおりです。

  • build context の肥大化を防ぐ
  • 過去のビルド成果物が混ざるのを防ぐ
  • ローカル環境で生成した依存関係の混入を防ぐ
  • multi-stage build の成果物だけを runner stage に持ち込む

readiness endpoint が重くないかも確認する

今回の主対応は、readiness endpoint の変更ではありませんでした。

ただし、readiness endpoint が DB や外部 API に依存している場合は、それ自体が遅延要因になります。

readiness endpoint は、可能であれば外部サービスへアクセスせず、軽量かつ副作用のない処理にしておくのが望ましいです。

今回のような問題を調査する際は、アプリケーション全体の起動処理だけでなく、readiness endpoint 内部の処理も確認対象に含める必要があります。

結果

検証環境で、変更前後の CloudWatch Logs を同程度の期間で比較しました。

正確なログ件数ではなく、傾向と最大待ち時間を示しています。

観点 変更前 変更後
app is not ready after 継続的に発生 少数まで減少
readiness の最大待ち時間 約40秒 約8秒
readiness への到達 到達しないケースあり 確認したケースでは到達
ready 前に終了するパターン 一部で確認 検証期間中は未確認

変更後にも app is not ready after は少数記録されました。

ただし、該当する log stream では、その後に次のログまで到達していました。

  • Web サーバーの起動完了ログ
  • /version へのアクセスログ
  • readiness check の成功後に出力されるログ

また、確認対象の log stream では、ready になる前の SIGTERM は記録されていませんでした。

そのため、今回問題視していた「アプリケーションが ready にならないまま終了する」というパターンは、検証期間中には再現しなくなったと判断しました。

ログ件数は、その時間帯に作成された実行環境数、負荷、デプロイ操作などによって変わります。

単純な件数だけではなく、次の点を主な判断材料にしました。

  • 最大待ち時間
  • log stream 内のログの順序
  • readiness 応答へ到達したか
  • readiness 前にプロセスが終了したか

Provisioned Concurrency があっても起動処理は重要

この Lambda では、コールドスタートの影響を抑えるため、Provisioned Concurrency も利用していました。

Provisioned Concurrency を設定すると、Lambda は指定された数の実行環境を事前に初期化し、リクエストを処理できる状態で用意します。

この割り当て時には、ライブラリの読み込みやクライアントの生成など、アプリケーションの初期化コードも実行されます。

参考:

ただし、初期化処理そのものがなくなるわけではありません。

Provisioned Concurrency の設定や更新、割り当て数の変更などに伴って、実行環境の初期化は発生します。

つまり、Provisioned Concurrency は初期化をリクエストより前に行う仕組みであり、重い初期化処理そのものを軽くする機能ではありません。

今回のようにアプリケーションの起動自体に時間がかかる場合は、Provisioned Concurrency を利用していても、次の点を見直す必要があります。

  • 実行時変換やコンパイルを起動経路から外す
  • 外部サービスへのアクセス時間を計測する
  • 不要なモジュールの読み込みを減らす
  • readiness endpoint の処理内容を確認する
  • 起動時に同期的に行う処理を見直す

CI/CD 側で見つかった副次的な課題

今回の調査中に、デプロイパイプライン側でも改善点が見つかりました。

ECR immutable tag と workflow の再実行

ECR リポジトリで image tag immutability を有効にしている場合、すでに存在するタグへ再度 push すると ImageTagAlreadyExistsException が返ります。

参考:

CI/CD で Git commit SHA などの一意な値を image tag に使っている場合でも、同じ commit に対して workflow を再実行すると、同じ tag を再度 push しようとして失敗することがあります。

そこで、push 前に対象 tag の存在を確認するようにしました。

if aws ecr describe-images \
  --repository-name "$ECR_REPOSITORY" \
  --image-ids imageTag="$IMAGE_TAG" \
  >/dev/null 2>&1; then
  echo "Image already exists. Reuse it."
else
  echo "Build and push image."
fi

describe-images では、image tag を指定して既存イメージを検索できます。

参考:

同一 tag のイメージが存在する場合は、build と push をスキップし、既存イメージを再利用します。

ただし、commit SHA 以外にもビルド結果を変える入力がある場合は注意が必要です。

  • ベースイメージ
  • build argument
  • 外部から取得するファイル
  • lockfile に固定されていない依存関係

既存イメージを安全に再利用するには、ビルドが十分に再現可能であることが前提になります。

Lambda alias と Provisioned Concurrency

Lambda alias に Provisioned Concurrency を設定している場合は、alias 更新時の状態管理にも注意が必要でした。

今回のパイプラインでは、次の流れにしました。

  1. alias に Provisioned Concurrency が設定されているか確認する
  2. 現在の設定値を一時的に保持する
  3. alias 更新前に既存の Provisioned Concurrency 設定を削除する
  4. alias を新しい version へ更新する
  5. 保持していた設定値で Provisioned Concurrency を再設定する
  6. ステータスが READY になるまで確認する
  7. FAILED の場合はデプロイ失敗として扱う

利用する主なコマンドは次のとおりです。

aws lambda get-provisioned-concurrency-config
aws lambda delete-provisioned-concurrency-config
aws lambda put-provisioned-concurrency-config

参考:

この手順は、今回採用したデプロイ方式であり、唯一の正解ではありません。

既存の Provisioned Concurrency を削除してから再設定する方式では、事前初期化された環境がない時間が発生する可能性があります。

可用性やレイテンシ要件が厳しい場合は、別 alias で事前に初期化してから切り替える方式なども検討する必要があります。

学び

今回の調査で得た知見は次のとおりです。

  • app is not ready after は、readiness check がまだ成功していないことを示す
  • ログ件数だけでなく、log stream ごとの最大待ち時間を見る
  • SIGTERM 単体では起動失敗と断定しない
  • 起動完了ログや readiness 応答と組み合わせて判断する
  • 計測していない外部依存まで、まとめて原因から除外しない
  • 外部アクセスとアプリケーション内部の初期化処理を分けて計測する
  • TypeScript の実行時変換を起動経路に含める場合は、コールドスタートへの影響を確認する
  • 本番相当の環境では、事前ビルドした JavaScript を実行する構成も検討する
  • tsconfig.json の import alias が、ビルド後にも解決できるとは限らない
  • readiness endpoint 自体が外部依存を持つ場合は、別の遅延要因になり得る
  • Provisioned Concurrency を利用していても、初期化処理自体は軽量化した方がよい

まとめ

AWS Lambda Web Adapter で app is not ready after が継続的に記録されている場合は、まず readiness check 先のアプリケーションが最終的に起動できているかを、log stream ごとに確認するのが有効でした。

今回のケースでは、少なくとも計測対象の Secrets Manager 取得だけでは長い待ち時間を説明できず、tsx を含むアプリケーションの起動経路が主要な遅延要因の一つと判断しました。

Docker build 時に TypeScript を JavaScript へ変換し、Lambda 実行時はビルド済み JavaScript を Bun で起動することで、readiness の最大待ち時間を約40秒から約8秒まで短縮できました。

また、「アプリケーションが ready にならないまま終了する」というパターンも、検証期間中には確認されなくなりました。

app is not ready after は原因そのものではなく、「アプリケーションがまだ ready ではない」という観測結果です。

外部リソースへのアクセス、アプリケーション初期化、TypeScript の実行時変換、readiness endpoint の処理をそれぞれ分けて確認することが、原因の切り分けにつながりました。

1
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?