Node.js＆log4jsのログ管理についてあれこれ

Node.jsでlog4jsを使ってログ出力する場合の、ログ管理に関する検証記録。
思いついたことを追記していく予定。

log4jsでログを出力するサンプルアプリを作る

検証用に、log4jsでログを出力するサンプルアプリを作る。

１．Docker環境で以下を実行し、node.jsコンテナを起動する。

# docker run -it --rm --name app node bash

２．コンテナのbashプロンプトで以下を実行し、環境を準備する。

# mkdir app
# cd app
# npm install express log4js
# apt-get update
# apt-get install -y vim curl

３．viでapp.jsというファイルを以下内容で作る。

app.js

var express = require("express");
var app = express();

var log4js = require("log4js");
log4js.configure({
          appenders: { app: { type: "file", filename: "app.log" } },
          categories: { default: { appenders: ["app"], level: "info" } }
});
var logger = log4js.getLogger();

app.get("/", (req, res) => {
        res.send("got request\n");
        console.log("got request");
        logger.info("got request");
})

app.listen(80, () => {
        console.log("started");
        logger.info("started");
})

４．サンプルアプリを起動する。

# node app.js

５．別のコマンドプロンプトを開き、コンテナにdocker execで接続する。

# docker exec -it app bash

６．ログファイル（app.log）が出力されていることを確認する。

# cd app
# ls -l app.log
# cat app.log

（実行結果）
root@dffd1ffd90f0:/app# cat app.log
[2020-12-22T00:29:01.888] [INFO] default - started

７．クライアントアクセスのログを記録させる。

# curl localhost
# cat app.log

（実行結果）
root@dffd1ffd90f0:/app# curl localhost
got request
root@dffd1ffd90f0:/app# cat app.log
[2020-12-22T00:29:01.888] [INFO] default - started
[2020-12-22T00:32:32.046] [INFO] default - got request
root@dffd1ffd90f0:/app#

ログをmv/renameするとどうなるか

log4jsはmvした先のファイルに出力を続ける。

# mv app.log mv.log
# curl localhost
# cat mv.log

（実行結果）
root@dffd1ffd90f0:/app# mv app.log mv.log
root@dffd1ffd90f0:/app# curl localhost
got request
root@dffd1ffd90f0:/app# cat mv.log
[2020-12-22T00:29:01.888] [INFO] default - started
[2020-12-22T00:32:32.046] [INFO] default - got request
[2020-12-22T00:34:19.797] [INFO] default - got request
root@dffd1ffd90f0:/app#

node app.jsを実行している側のプロンプトでCtrl+cでプログラムを止め、プログラムを起動しなおすと、再度app.logにログを出力し始める。

ログを0バイトに切り詰める

cat /dev/null >を使う。

# cat /dev/null > app.log
# ls -l app.log

（実行結果）
root@dffd1ffd90f0:/app# cat /dev/null > app.log
root@dffd1ffd90f0:/app# ls -l app.log
-rw-r--r-- 1 root root 0 Dec 22 01:10 app.log

log4jsの機能で、毎日（毎時）ログファイルをローテートする

appendersのtypeをdateFileにする。
オプションでpatternに.yyyy-MM-dd-hhと、hhまで指定すると毎時ローテーションする様になる。
実際にローテーションが行われるのは、期限がきた後の初回アクセス時になる。つまり、毎時ログを他所に転送してバックアップを取るような運用では、app.logファイルをローテーションさせるためにわざとログを出力するためのハンドラをアプリが持っていることが望ましい。
https://github.com/log4js-node/log4js-node/blob/master/docs/dateFile.md

app.js(修正分)

          appenders: { app: { type: "dateFile", pattern: '.yyyy-MM-dd-hh', filename: "app.log" } },

以下を、？時00分になったタイミングで実行する。

# curl localhost
# ls -la app.log*
# curl localhost
# cat app.log

（実行結果）
root@dffd1ffd90f0:/app# curl localhost
got request
root@dffd1ffd90f0:/app# ls -la app.log*
-rw-r--r-- 1 root root  55 Dec 22 01:00 app.log
-rw-r--r-- 1 root root 216 Dec 22 00:48 app.log.2020-12-22-00
root@dffd1ffd90f0:/app# curl localhost
got request
root@dffd1ffd90f0:/app# cat app.log
[2020-12-22T01:00:21.551] [INFO] default - got request
[2020-12-22T01:00:31.230] [INFO] default - got request

毎時ローテートされたログファイルをコンテナの外にコピーする

毎時ローテートして、ログファイルをコンテナの外に出す。
以下を毎時00分か、NTPの時刻同期とかに不安がある場合は01分に実行する。
dockerで実行しているがkubectlでも似たような事は出来るだろう。
ワイルドカードの扱いが面倒くさい。

# docker exec app curl localhost
# docker exec app mkdir /app/logtmp
# docker exec app bash -c 'mv /app/app.log.* /app/logtmp/'
# docker cp app:/app/logtmp .
# mv logtmp/* .
# rmdir logtmp
# docker exec app rm -Rf /app/logtmp
# ls -la ./app.log.*
# docker exec app ls -l /app

（実行結果）
root@ubuntu-20:~# docker exec app curl localhost
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0got request
100    12  100    12    0     0   2242      0 --:--:-- --:--:-- --:--:--  2400
root@ubuntu-20:~# docker exec app mkdir /app/logtmp
root@ubuntu-20:~# docker exec app bash -c 'mv /app/app.log.* /app/logtmp/'
root@ubuntu-20:~# docker cp app:/app/logtmp .
root@ubuntu-20:~# mv logtmp/* .
root@ubuntu-20:~# rmdir logtmp
root@ubuntu-20:~# docker exec app rm -Rf /app/logtmp
root@ubuntu-20:~# ls -la ./app.log.*
-rw-r--r-- 1 root root 110 Dec 22 01:43 ./app.log.2020-12-22-01
root@ubuntu-20:~# docker exec app ls -l /app
total 60
-rw-r--r--  1 root root   545 Dec 22 00:45 app.js
-rw-r--r--  1 root root    55 Dec 22 02:00 app.log
-rw-r--r--  1 root root   161 Dec 22 00:34 mv.log
drwxr-xr-x 61 root root  4096 Dec 22 00:28 node_modules
-rw-r--r--  1 root root 40299 Dec 22 00:28 package-lock.json
-rw-r--r--  1 root root    77 Dec 22 00:28 package.json

log4jsのログを標準出力に出力する

そもそも、コンテナのログは標準出力に出力するものである。
その場合はapp.jsのappernderのtypeをconsoleにすればいい。
様々な理由によりそれが適わない事はあるものだが。

app.js(修正分)

          appenders: { app: { type: "console" } },

（「node app」を実行したコンソールの出力例）
root@dffd1ffd90f0:/app# root@dffd1ffd90f0:/app# node app.js
started
[2020-12-22T02:03:35.466] [INFO] default - started
got request
[2020-12-22T02:03:46.001] [INFO] default - got request
got request
[2020-12-22T02:03:47.419] [INFO] default - got request