はじめに

App Service on Linux の組み込みイメージがどのようにアプリケーションを起動しているかについては下記の Microsoft Azure Tech Advent Calendar 2022 7 日目の記事を参照してください。
本稿はその続編となります。折角の機会なのでこちらの投稿も Advent Calendar に紐づけておきます。

PaaS の特性上、App Service ではアプリケーションの再起動は発生することを前提に考える必要があります。App Service の構成の観点で備えるべき事項もいくつかありますが¹、アプリケーションレイヤにおいても、そのプロセスの停止を検知し、何らかの処理を行い Disposability を高めたいと思います。
本稿では App Service on Linux Node ランタイムにおける、アプリケーションの Graceful shutdown の実現方法を探ります。

TL;DR

カスタムスクリプトでコンテナ終了時のシグナルを trap する
カスタムスクリプトは exec でPID 1 に置き換える
コンテナ終了間際のログは別ファイルに書き込む
サンプルコードはこちら

解決したいこと

App Service on Linux Node ランタイムにおいて

シャットダウンを検知し、
終了処理を含むコードが処理をおこなう

下記のコードを含むアプリケーションをそのままデプロイしても、App Service の停止や、再起動時(古いコンテナの停止+新しいコンテナの開始)において、期待したログ出力(SIGTERM received や SIGINT received)を得ることはできません。つまりアプリケーションの終了を検知できず、Graceful shutdown を行うことができません。

process.on('SIGTERM', () => {
  console.log("SIGTERM received");

  // do something before exit
  // server.close, release connection etc...

  // exit
  process.exit(0);
});

// PM2 を使っている場合は SIGINT
// https://pm2.keymetrics.io/docs/usage/signals-clean-restart/
process.on('SIGINT', () => {
  console.log("SIGINT received");

  // do something before exit
  // server.close, release connection etc...

  // exit
  process.exit(0);
});

期待したログ出力が行われない理由として2点ありました。

そもそもシグナルを受信していない
ログの出力先がない

以降で上記 2 つの原因と対策について記載します。

App Service Linux で SIGTERM を受け取るには

App Service Linux では、Docker が利用されています。Docker では PID 1 問題であったり、そもそも Node.js was not designed to run as PID 1 となっています。

また、Blessed Image においてどのようにアプリケーションが実行されるかに書いたように、Node Blessed Image では、EntryPoint に /opt/startup/init_container.sh が指定されており、これを変更する方法はありません。そのため dumb-init や、docker run --init オプションによってTini を挟む余地がありません。
また、/opt/startup/init_container.sh から exec コマンドで /opt/startup/startup.sh が実行され、その後アプリケーションの起動が行われます。exec を介したことで、PID 1 は /bin/sh /opt/startup/startup.sh に置き換えられています。

/opt/startup/startup.sh　は、シグナルをハンドリングしていないので、アプリケーションに対してシグナルが伝播されません。まずはこの PID 1 を管理下に手に入れ、シグナルをハンドリングする必要があります。

`exec` でカスタムスクリプトを実行して PID 1 をとる

以下のような起動スクリプトを作成・配置し、スタートアップコマンドに、exec /home/site/wwwroot/init.sh と指定します。

暫定版

#!/usr/bin/env bash

# https://gist.github.com/georgeOsdDev/706886b4818071d8980ef7141aa2ec8a
CONTAINER_ID=$(cat /proc/self/cgroup | grep docker | grep $WEBSITE_SITE_NAME | head -1| rev | cut -d "/" -f 1 | rev)

logevent() {
  echo `date "+%Y-%m-%dT%H:%M:%S.%3N%z"` "[StartScript] Message: $1, Event: $2, COMPUTERNAME: ${COMPUTERNAME}, CONTAINER_ID: ${CONTAINER_ID}"
}

handler15() {
  logevent "'Handling SIGTERM, stopping process PID: ${pid}'" "SIGTERM"
  kill -s TERM $pid
}
trap handler15 15 # SIGTERM

node index.js &
pid=$!
START_MSG="Process started with node, PID: ${pid}"
logevent "${START_MSG}" "startup"

wait $pid

以下のようにPID 1 を暫定版の init-minimum.sh に置き換えることができました。

ローカル環境の Docker ではコンテナ停止時にコンソールへの出力が確認できたため、スクリプトの動作としては問題なさそうです。
しかし App Service 上でコンテナの標準出力が保存される AppServiceConsoleLogs や default_docker.log に、init.sh からの出力および、アプリケーション側での SIGTERM received を確認することはできませんでした。
明確な根拠は確認できていませんが、コンテナ停止に伴い標準出力のファイルへの書き込みが行われなくなるようです。おそらく新しく起動するコンテナの標準出力をファイルへ書き込む処理が始まるため、古いコンテナの標準出力は拾われなくなるのでわないかと考えられます。
ということで、独自のファイルへの書き込み、外部への情報送信を行ってみます。

処理内容を独自ログに出力する

以下のように、init.sh 内の標準出力は ${COMPUTERNAME}-lifecycle.log という独自のファイルにリダイレクトし、また同時に外部サーバーに対して WEBHOOK のようなイメージで POST リクエストで情報を送ってみます。

LOGFILE_PATH="/home/LogFiles"
LOGFILE="${LOGFILE_PATH}/${COMPUTERNAME}-lifecycle.log"

logevent() {
  echo `date "+%Y-%m-%dT%H:%M:%S.%3N%z"` "[StartScript] Message: $1, Event: $2, COMPUTERNAME: ${COMPUTERNAME}, CONTAINER_ID: ${CONTAINER_ID}" >> ${LOGFILE}
}
hookevent() {
  timestamp=`date "+%Y-%m-%dT%H:%M:%S.%3N%z"`
  postdata="message=$1&event=$2&computername=${COMPUTERNAME}&container_id=${CONTAINER_ID}&timestamp=${timestamp}"
  # echo $postdata
  if [ -n "$SHUTDOWN_HOOK_URL" ]; then
    curl -s -X POST "${SHUTDOWN_HOOK_URL}" -d "$postdata" -H "Content-Type: application/x-www-form-urlencoded"
  fi
}

再起動してみると独自に作成した ${COMPUTERNAME}-lifecycle.log に以下のような出力が得られました。
SIGTERM を受け取って、PID 62 の Node プロセスの停止を（init.sh が実行しようと）しているログ、次の実行ではコンテナID²が変わっていることが確認できます。

lifecycle.log

2022-12-12T15:06:35.615+0000 [StartScript] Message: Process started with node, PID: 62, Event: startup, COMPUTERNAME: lw0sdlwk0000JM, CONTAINER_ID: 14b165d60b067cb7f12c0697b20cbaf23297ad8d53fab3d858cc103a2b133e50
2022-12-12T15:10:17.625+0000 [StartScript] Message: 'Handling SIGTERM, stopping process PID: 62', Event: SIGTERM, COMPUTERNAME: lw0sdlwk0000JM, CONTAINER_ID: 14b165d60b067cb7f12c0697b20cbaf23297ad8d53fab3d858cc103a2b133e50
2022-12-12T15:10:33.209+0000 [StartScript] Message: Process started with node, PID: 63, Event: startup, COMPUTERNAME: lw0sdlwk0000JM, CONTAINER_ID: 31aba1cc32610b7a234c6c812e078d4a8cee16203d2aee2fc119891617b3b740

外部への通知も以下のようにうまくいきました。

アプリケーション側コードの改善

アプリケーションコード側でも終了間際の標準出力が AppServiceConsoleLogs や default_docker.log にリダイレクトされない可能性を考慮して、独自のファイルに書き出すようにします。念のため init.sh 側からの書き込みとの衝突を避けるため別のファイル( lifecycle.app.log )にしておきます。

const fs = require("fs");
const LOGFILE = `/home/LogFiles/${process.env.COMPUTERNAME}-lifecycle.app.log`
const getlogTimeStampAndPrefix = () => `${new Date().toISOString().replace('Z','+0000')} [Application.${process.pid}]`;
const writeLog = (msg) => {
  const text = `${getlogTimeStampAndPrefix()} ${msg}`
  // console.log will not forwarded to AppServiceConsoleLogs or docker_default.log any more, so we need to write log to a file
  console.log(text)
  // write log to a file
  try {
    fs.appendFileSync(LOGFILE, `${text}\n`);
  } catch (err) {}
}

// start log
const START_MSG = `Node process started.`
writeLog(START_MSG);

process.on('SIGTERM', () => {
  const SIGTERM_MSG = `SIGTERM received, shutting down.`
  writeLog(SIGTERM_MSG);

  // do something before exit
  // server.close, release connection etc...

  server.close((e) => {
    const SERVER_CLOSED_MSG = `Server closed ${e ? `with error: ${e}` : 'successfully'}`
    writeLog(SERVER_CLOSED_MSG, e);
    // exit
    process.exit(0);
  });
});

以下のような出力を得ることができました。

lifecycle.app.log

2022-12-12T15:59:09.563+0000 [Application.62] Node process started.
2022-12-12T15:59:11.531+0000 [Application.62] SIGTERM received, shutting down.
2022-12-12T15:59:11.551+0000 [Application.62] Server closed successfully

とりあえず fs を使いましたが、本来は何かしらのロガーライブラリを使ったほうが良さそうです。

PM2 を使う場合

init.sh では、kill -s TERM $pid の代わりに pm2 stop all を呼び出します。
また、pm2 stop を実行した場合、アプリケーション側には SIGINT が送信されることになります。そのためアプリ側では SIGINT をハンドルするコードを追加する必要があります。

注意点、免責事項

本記事の内容はオフィシャルにアナウンスされている内容ではなく、あくまでも個人的に試してみた結果です。
コンテナライフサイクルについて明示的な公開情報はなく、タイムアウト値等は不明です。そのためシャットダウン処理がどのくらいの猶予をもって行えるかは不確定です。³
独自形式で出力したファイルのローテートは考慮していません。

The Ultimate Guide to Running Healthy Apps in the Cloud ↩
コンテナ ID については Gist を参照してください。AppServicePlatformLogs に出力される値をコンテナ内部から取得できます。 ↩
Need explanation about container lifecycle for graceful shutdown ↩

App Service on Linux で Graceful shutdown