App Service on Linux で Graceful shutdown

# はじめに

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

https://qiita.com/georgeOsdDev@github/items/abdadd35248b98c4ef88

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

[^1]:[The Ultimate Guide to Running Healthy Apps in the Cloud](https://azure.github.io/AppService/2020/05/15/Robust-Apps-for-the-cloud.html)


# TL;DR
- カスタムスクリプトでコンテナ終了時のシグナルを `trap` する
- カスタムスクリプトは `exec` でPID 1 に置き換える
- コンテナ終了間際のログは別ファイルに書き込む
- サンプルコードは[こちら](https://github.com/georgeOsdDev/app-service-linux-node-graceful-shutdown-example)


# 解決したいこと

App Service on Linux Node ランタイムにおいて
 - シャットダウンを検知し、
 - 終了処理を含むコードが処理をおこなう

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

```javascript
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 問題](https://text.superbrothers.dev/200328-how-to-avoid-pid-1-problem-in-kubernetes/) であったり、そもそも [Node.js was not designed to run as PID 1](https://github.com/nodejs/docker-node/blob/main/docs/BestPractices.md#handling-kernel-signals) となっています。

また、[Blessed Image においてどのようにアプリケーションが実行されるか](https://qiita.com/georgeOsdDev@github/items/abdadd35248b98c4ef88#blessed-image-%E3%81%AB%E3%81%8A%E3%81%84%E3%81%A6%E3%81%A9%E3%81%AE%E3%82%88%E3%81%86%E3%81%AB%E3%82%A2%E3%83%97%E3%83%AA%E3%82%B1%E3%83%BC%E3%82%B7%E3%83%A7%E3%83%B3%E3%81%8C%E5%AE%9F%E8%A1%8C%E3%81%95%E3%82%8C%E3%82%8B%E3%81%8B) に書いたように、Node Blessed Image では、EntryPoint に `/opt/startup/init_container.sh` が指定されており、これを変更する方法はありません。そのため [dumb-init](https://github.com/Yelp/dumb-init) や、`docker run --init` オプションによって[Tini](https://github.com/krallin/tini) を挟む余地がありません。
また、`/opt/startup/init_container.sh` から `exec` コマンドで `/opt/startup/startup.sh` が実行され、その後アプリケーションの起動が行われます。`exec` を介したことで、PID 1 は `/bin/sh /opt/startup/startup.sh` に置き換えられています。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/4914/c4b76bcf-477e-d578-5cb4-0b50aabe1128.png)

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

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

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


```bash:暫定版
#!/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 に置き換えることができました。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/4914/0f727da7-8f42-00e9-31c4-7ee99fd8593d.png)

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

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

以下のように、init.sh 内の標準出力は `${COMPUTERNAME}-lifecycle.log` という独自のファイルにリダイレクトし、また同時に外部サーバーに対して WEBHOOK のようなイメージで POST リクエストで情報を送ってみます。
```bash
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[^2]が変わっていることが確認できます。

```log: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
```

外部への通知も以下のようにうまくいきました。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/4914/a188f062-e770-e0eb-5a01-ba0f2255ef9a.png)

[^2]: コンテナ ID については [Gist](https://gist.github.com/georgeOsdDev/706886b4818071d8980ef7141aa2ec8a) を参照してください。`AppServicePlatformLogs` に出力される値をコンテナ内部から取得できます。

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

```javascript
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` をハンドルするコードを追加する必要があります。

https://pm2.keymetrics.io/docs/usage/signals-clean-restart/


# 注意点、免責事項

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

[^3]:[Need explanation about container lifecycle for graceful shutdown](https://github.com/MicrosoftDocs/azure-docs/issues/72606)