◆ console.log しないと動かない

久々に使った

前に書いたように Node.js のサービス化を systemd にしました
そのときに一応 PM2 も見てみるとバージョンは 4.5 で以前使ったときからメジャーアップデートもあってそこそこ変化がありそうです

目に見えるところで何か変わったのか 軽く見てみました

restart 回数が増えない

久々に使ってみるといきなり思ったとおりに動きませんでした
JavaScript の処理が終了したときに再起動していないようです

試しに 2 種類のファイルを用意しました

[foo.js]
setTimeout(() => {
console.log(new Date().toLocaleTimeString())
}, 3000)

[bar.js]
setTimeout(() => {
1 + 1
}, 3000)

どちらも 3 秒後に処理を実行して正常に終了します
foo では console.log で時刻を表示して bar は 1 + 1 を計算するだけの特に意味のない処理です

両方を pm2 コマンドから起動します

pm2 start foo.js
pm2 start bar.js

しばらく待ってから status を表示すると

┌────┬────────────────────┬──────────┬──────┬───────────┬──────────┬──────────┐
│ id │ name │ mode │ ↺ │ status │ cpu │ memory │
├────┼────────────────────┼──────────┼──────┼───────────┼──────────┼──────────┤
│ 1 │ bar │ fork │ 0 │ online │ 0% │ 39.1mb │
│ 0 │ foo │ fork │ 5 │ online │ 0% │ 39.1mb │
└────┴────────────────────┴──────────┴──────┴───────────┴──────────┴──────────┘

↺ 記号が restart 回数ですが bar のほうは 0 のままです
なぜかカウントされてないだけでしょうか?

再起動してるか確かめるために 1 + 1 のところをファイル追記処理に変えてみます

[bar.js]
setTimeout(() => {
require("fs").appendFileSync("/tmp/bar", ".")
}, 3000)

これで再度実行してしばらく待ってから 「/tmp/bar」 見ます
結果は 「.」 は 1 つだけでした
起動はしているものの終了後に再起動していません

以前からこんな挙動でしたっけ?
こんなバグみたいな動きしていれば気づきそうですけど console.log を一つもしないコードを書いてなかっただけなのかもしれません

調べてみる

restart 関係をドキュメントでみてみると autorestart という設定があります
デフォルトは ON で OFF にすると正常終了や異常終了時にアプリケーションを再起動しなくなるというもののようです

if false, PM2 will not restart your app if it crashes or ends peacefully

ON のときについては詳しく書いていないのですが 終了は常に再起動ではなく異常終了だけ再起動で正常終了は再起動しないのでしょうか?
それだと console.log で出力直後に終了しているのは異常終了とみなして 何も出力しないのは正常終了とみなしてるからとも考えられます
特に Node.js の場合は Promise をキャッチしてないと警告が出るだけでそのまま終了したら終了コード的には 0 です
最新の Node.js 15 からはエラーで異常終了ですが LTS の 14 などでは正常扱いになるので見分けるためにこうしてる可能性はあります

それだと

process.exit(1)

で終了コードを 1 にすると出力無しでも再起動してくれるのでしょうか?

試してみると 再起動してくれました……が process.exit(0) でも再起動してくれました
なんかもう意味がわかりません
1+1 でも process.exit(0) でも親プロセスが受け取る結果としてはどっちも同じのはずなのですけど

child_process を使って実行してみましたが返り値の違いはありません

> child_process.spawnSync("node" , ["1.js"])
{
status: 0,
signal: null,
output: [ null, <Buffer >, <Buffer > ],
pid: 24581,
stdout: <Buffer >,
stderr: <Buffer >
}
> child_process.spawnSync("node" , ["exit.js"])
{
status: 0,
signal: null,
output: [ null, <Buffer >, <Buffer > ],
pid: 24608,
stdout: <Buffer >,
stderr: <Buffer >
}

1.js が 1+1 をする方で exit.js が process.exit(0) する方です

終了していない?

いまさらながら status 結果の違和感に気づきました

┌────┬────────────────────┬──────────┬──────┬───────────┬──────────┬──────────┐
│ id │ name │ mode │ ↺ │ status │ cpu │ memory │
├────┼────────────────────┼──────────┼──────┼───────────┼──────────┼──────────┤
│ 1 │ bar │ fork │ 0 │ online │ 0% │ 39.1mb │
│ 0 │ foo │ fork │ 5 │ online │ 0% │ 39.1mb │
└────┴────────────────────┴──────────┴──────┴───────────┴──────────┴──────────┘

restart が 0 の方の status は 「online」 なんですよね
終了していたら 「stopped」 のはずです

つまり PM2 的には bar.js は終了していないということです

Node.js の処理としては console.log でも 1 + 1 でも ref を確保してない限りは処理が終われば終了します
実際に

node bar.js

をすると 3 秒後に終了しています

ということは PM2 の終了判断のバグのように思います
しかし一応 ps コマンドで実行中コマンドを表示すると node コマンドが実行中になっていました
なぜか終了できていないようです

普通に node コマンドで実行した場合にはそんなことはないので PM2 がそうしているのだと思います
標準出力のログやモニタリングのための IPC 通信など色々やってそうですし そのせいで bar.js が終了できていないようです
これなら process.exit(0) の場合は強制終了になっているので再起動されるというのも理解できます

この PM2 との通信は console.log すれば終了するようで console.log をするとプロセスが終了できて再起動します
PM2 側で標準出力への何かの書き込みを検知したら正常に初期化・起動できたと判断してるのかもしれません
process.exit なしで終了させるためには console.log しないといけないのは変な話ですが 標準出力に空文字を書き込んでもいいようです

process.stdout.write("")

setTimeout(() => {
1 + 1
}, 3000)

これでも 3 秒後にプログラムが終了して 再起動するようになりました

とは言えこれも気持ち悪いには違いないです
PM2 を使うなら標準出力はなにかのプログラムへパイプで送られず PM2 が受け取ってログファイルへ出力するだけになるはずなので 起動したときに 「process started」 みたいなメッセージをログに書き込むようにするのがいいのかもしれません