npmの脆弱性APIが遅いとpnpm/action-setup v6が5分止まる

概要

pnpm/action-setup v6のSet up pnpmは、npmの脆弱性APIの応答が遅れると、遅れた末に503が返る場合も含めて、エラーを出さずに最大5分止まる。
action内部のnpm ciが実行するaudit（依存の脆弱性の照会）が、APIの応答を待つためである。
待ちかどうかはnpm ciの最後の行とverboseのログで判別でき、npm_config_audit=falseを渡すか、事前に導入したpnpmを使用してaction-setupを削除すれば解消する。

背景

自社のself-hosted runnerで、PRのチェックの1つが約1分半から約6分に伸びた。
遅かったのはSet up pnpmで、普段は数秒から十数秒のステップが最大で約5分かかっていた。
ログにエラーはなく、npm ciの最後の行はadded 1 package in 5mだった。

action-setup v6はnpm ciでbootstrapのpnpmを導入する

この待機がv6で発生するのは、v6がpnpmの導入の途中でnpm ciを実行するためである。
v4とv5はnpm ciを使用しないので、bulk APIの応答の影響を受けない。

action-setup v6は、pnpmを次の順で導入する。

1. 作業用のディレクトリに、pnpmだけを依存とするpackage.jsonとpackage-lock.jsonを作成する。pnpm 11以下を導入する場合、Node.jsが22.13未満かstandalone: trueなら、pnpmの代わりに@pnpm/exeを依存にする
2. そのディレクトリでnpm ciを実行し、一時的に使用するpnpm（以下bootstrapのpnpm）を導入する
3. v6.0.7以降はbootstrapのpnpmのpnpm self-update <version>で、packageManagerなどで指定したバージョンに置換する

v5まではaction自体に同梱したpnpmでinstall --no-lockfileを実行しており、npmを使用しなかった。
v6以降はnpmの設定と挙動がこのステップの所要時間を左右する。

v6.0.7以降では手順3があるため、bootstrapのpnpmはpackageManagerのバージョンと異なれば直後に置換される。
自社の例では300秒かけて導入したbootstrapのpnpmは使用されず、packageManagerで固定した別のバージョンに置換されていた。

npm ciはauditの応答を待機してから終了する

bulk APIの応答が遅いとき、ステップの所要時間を左右するのはpnpmのダウンロードではなく、auditのリクエストへの応答である。
応答の内容に関係なくnpm ciは成功扱いになる。
auditは依存の一覧（パッケージ名とバージョン）をnpmの脆弱性APIに送信し、既知の脆弱性を照会する処理だ。
送信先のエンドポイントは/-/npm/v1/security/advisories/bulk（以下bulk API）である。

npmの設定項目auditのデフォルト値はtrueで、auditが有効なら、npm ciとnpm installはインストールのたびに依存の一覧をregistryのbulk APIへPOSTする。
このリクエストはインストールと並行して送信され、npmが応答を待機するのはインストールの最後。
応答のヘッダを受信できない場合の上限はfetch-timeoutのデフォルト値の300000msで、ログのin 5mはこの値と一致する。

auditのリクエストが失敗しても、npmはエラーをverboseのログに記録するだけで、インストールの結果を変更しない。
依存が1個のインストールでも、APIの応答が遅ければその分だけ終了が遅延する。
auditのリクエストの失敗が503の応答と時間切れのどちらであっても、npm ciの終了コードは0になる。

bulk APIの応答が上の3つのどの分岐でも終了コードは0で、変化するのはステップの所要時間と、最後の行のand auditedの有無である。

bulk APIの状態ごとのnpm ciの所要時間とログは次のとおり。

いずれも終了コードは0である。
auditが成功したときだけ、最後の行にand audited N packagesが付加される。

最後の行とverboseのログでauditの待機を判別する

遅延の原因がauditの待機かどうかは、npm ciの最後の行で見当がつき、verboseのログで確定する。
原因がnpm側か社内のproxyかは、runnerとproxyを経由しない場所からの計測で区別できる。

action-setupのログでauditの待機を判別する

ログで判別する手順はnpm ciの末尾のand auditedの確認である。
ない場合はverboseのログのaudit errorの行、ある場合はhttpの行のbulk APIの所要時間を確認する。

Set up pnpmのログでnpm ciの最後の行にand auditedがなく、所要時間が数分なら、auditの待機の可能性が高い。
確定にはaction-setupのstepに環境変数npm_config_loglevel: verboseを設定する。
actionはprocess.envを引き継いだ環境でnpm ciを実行するため、stepのenvに指定したnpmの設定が反映される。
リポジトリの.npmrcはv6では作業用のディレクトリにコピーされないので、効果がない。

- uses: pnpm/action-setup@<sha> # v6
  env:
    npm_config_loglevel: verbose

bulk APIが時間切れになると、verboseのログに次の行が出力される。

npm verbose audit error FetchError: network timeout at: https://registry.npmjs.org/-/npm/v1/security/advisories/bulk

bulk APIから応答があった場合は、ステータスと所要時間の行が出力される。
たとえば503の場合は次の行が出力される（所要時間は例）。
時間切れの場合はこの行が出力されないため、audit errorの行で判別する。

npm http fetch POST 503 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 3012ms

runnerからbulk APIの所要時間を直接計測する

runnerからpackument、tarball、bulk APIの3つの所要時間を計測すると、bulk APIだけが遅いかを確認できる。
proxyを経由しない場所の計測と比較すれば、npm側か社内のproxyかも区別できる。

runnerから直接計測する場合は、npmが実際に使用するregistryを宛先として、3種類のリクエストの所要時間を比較する。
社内のミラーやproxyを経由する環境では、npmはそのregistry経由でbulk APIにPOSTする。
registry.npmjs.orgに直接送信しても、npmと同じ条件にはならない。

REG="$(npm config get registry)"
REG="${REG%/}/"   # 末尾の / をそろえる
# packument（パッケージのメタデータ）
curl -o /dev/null -s -w '%{http_code} %{time_total}\n' "${REG}pnpm"
# tarball
curl -o /dev/null -s -w '%{http_code} %{time_total}\n' "$(npm view pnpm dist.tarball)"
# bulk API
curl -o /dev/null -s -w '%{http_code} %{time_total}\n' -X POST \
  -H 'content-type: application/json' -d "{\"pnpm\":[\"$(npm view pnpm version)\"]}" \
  "${REG}-/npm/v1/security/advisories/bulk"

自社のrunnerからの計測では、packument（パッケージのバージョン一覧などのメタデータ）とtarball（パッケージ本体のアーカイブ）は0.2秒前後で応答した。
bulk APIは約4分後に200で応答するか、503で応答した。
bulk APIだけが遅い状態は、npm側の障害でも、POSTだけを遅延させる社内のproxyでも起こりうる。
proxyを経由する環境では、proxyを経由しない場所からも同じリクエストを計測する。

npmのステータスページにも、bulk APIの障害（「npm audits endpoint is having issues」）が掲載された。
掲載は自社での遅延の観測開始から半日ほど後で、遅延の開始時点では、ステータスページは判断材料にならなかった。

ジョブがtimeout-minutesでcancelledになった場合

timeout-minutesでジョブが先に停止すると、上の手がかりはログに出力されない。
この場合の手がかりは停止したstepの位置である。

timeout-minutesが短いジョブは、Set up pnpmの途中でcancelledになる。
fetch-timeoutより前のcancelledでは、npmの最後の行もverboseのaudit errorの行も出力されない。
手がかりはcancelledになったstepがSet up pnpmであることだ。
前述のverboseのログを有効にしていれば、ログの最後の行がtarballの取得になる。

auditの停止かaction-setupの削除で待機を解消する

対処の方法は4つあり、主にイメージの管理の有無で選択し、pnpmのバージョンとauditを維持するかも考慮する。
自社はイメージを管理しているため、同梱したpnpmを使用してaction-setupを削除した。

auditの待機を避ける4つの方法

4つの方法の内容はauditの停止、待機時間の上限の設定、Workflowでのnpm経由の導入の回避のいずれかである。

自社のWorkflowに適用したのは1番目だけである。
2番目と4番目は前節の表のとおり、bulk APIへのPOSTを停止するか、時間で中断する。
2番目で停止するのはbootstrapのpnpmの導入時のauditだけで、プロジェクトの依存の脆弱性の確認には影響しない。
action-setupのREADMEは、pnpm 11以降の選択肢として3番目のpnpm/setupを案内している。

イメージに同梱したpnpmへの切り替え

イメージがすでにpnpmを同梱していたため、変更は切り替えの条件とsetupのstepの削除だけで、ジョブの所要時間は元の水準に回復した。

1番目を採用したのはrunnerのイメージがNode.js 24と、packageManagerと同じバージョンのpnpmをすでに同梱していたためである。
イメージでは次のDockerfileでpnpmを導入している。

ARG PNPM_VERSION=<version>
RUN npm install --global "pnpm@${PNPM_VERSION}"

同梱のpnpmへの切り替えはRepositoryの変数を条件にしていたが、その変数が未設定で、すべてのrunでaction-setupとsetup-nodeが実行されていた。
この条件と両方のstepを削除し、次の検証のstepを無条件に実行するよう変更した。

- name: Verify preinstalled Node.js and pnpm
  run: |
    test "$(node --version | cut -d. -f1)" = v24
    test "$(cd "$RUNNER_TEMP" && pnpm --version)" = <version>

変更後、遅くなっていたジョブの所要時間の中央値は約1分半に回復した。
Set up pnpmのステップが存在しないため、bulk APIの状態とは無関係になった。

pnpm auditのstepの削除

pnpm auditも同じAPIに依存するため、PRのチェックからは削除し、脆弱性の確認は別の仕組みで継続する。

同じWorkflowにあったpnpm audit --prod --audit-level=highのstepも削除した。
pnpm 11のpnpm auditは同じbulk APIを使用するため、APIの応答が遅いとこのstepも応答を待機する（上限はpnpmのfetchTimeout）。
対象のproduction依存は少ない。
同じlockfileはDependabot security updatesが継続して監視しており、出荷するイメージはビルド時にTrivyでスキャンしている。
このため、PRの待ち時間を左右するジョブからは削除した。
確認を継続するならPRの待ち時間と無関係な別のジョブか定期実行への移行も選択肢になる。

検証のstepはpackageManagerのないディレクトリで実行する

action-setupの削除後は、イメージのpnpmのバージョンの不一致を検出できるよう、検証のstepをpackageManagerのないディレクトリで実行する。

action-setupを削除すると、pnpmのバージョンはrunnerのイメージで確定する。
ただしpackageManagerのあるディレクトリでpnpmを実行すると、pnpmはpmOnFailのデフォルトのdownloadに従い、宣言されたバージョンをダウンロードして実行する。
このため、そのディレクトリでpnpm --versionを実行すると、イメージのバージョンではなく宣言されたバージョンが出力され、不一致を検出できない。
不一致があれば宣言されたバージョンのpnpmはregistryから取得される。

図のとおり、packageManagerのあるディレクトリでは、イメージのバージョンがずれていても宣言どおりの値が出力される。

上の検証のstepも当初はプロジェクトのディレクトリで実行しており、不一致を検出できるよう後から$RUNNER_TEMPでの実行に変更した。
packageManagerのない場所で出力されるのはイメージに導入したバージョンで、stepの比較対象はこの値だ。
プロジェクトのディレクトリで実行するコマンド自体を不一致で失敗させたい場合は、pnpm_config_pm_on_fail: errorを設定する。

バージョンの更新の順序

検証のstepは1つのバージョンと完全一致で比較するので、更新の途中では新旧どちらのバージョンも通す形に一時的に変える。

バージョンはrunnerのイメージのDockerfile、プロジェクトのpackage.jsonのpackageManager、Workflowの検証のstepの3か所に記述する。
イメージだけを先に配布すると、Workflowが旧バージョンを期待したまま新しいpnpmと比較するため、検証のstepが失敗する。
自社では、イメージの変更と同時に検証のstepを新旧両方のバージョンを受け付ける形に変え、新しいイメージの反映を確認した後で、検証のstepを新しいバージョンだけに戻した。
packageManagerは、新しいイメージの反映後に新しいバージョンへ更新する。

- name: Verify preinstalled Node.js and pnpm
  run: |
    test "$(node --version | cut -d. -f1)" = v24
    case "$(cd "$RUNNER_TEMP" && pnpm --version)" in
      11.5.3|11.28.5) ;;  # 旧バージョン|新バージョン
      *) echo "Unexpected pnpm version" >&2; exit 1 ;;
    esac