背景

超今さらExpress触ってみた - その1 Expressって生々しすぎない？ - で express の middleware として morgan という logger を導入したけど、これは HTTP request に応じて自動で吐くやつ。

expressjs/morgan: HTTP request logger middleware for node.js

今回は手動の方の話。

winstonにしてみる

今回の Express アプリの目的はあくまで Cloud Functions なので、log は Stackdriver Logging に送られることになる。

Stackdriver - ハイブリッドモニタリング | Stackdriver | Google Cloud

Stackdriver Logging に Node.js からログを送るライブラリとしてオフィシャルに紹介されているのは

Bunyan または Winston プラグインを使用するか、Node.js 用 Stackdriver Logging クラウドクライアントライブラリを直接使用して、Node.js アプリケーションから Stackdriver Logging にログを書き込むことができます。

https://cloud.google.com/logging/docs/setup/nodejs

にあるように、

の二つ。

シンプルなのは bunyan の方だと思うのだが、winston は transport レイヤーをカスタムすることができ、logger から例えば Webhook や Mail で送信するといったことを手軽に実現できる機能がある。

今回はこれを期待して winston を採用してみようと思う。

組み合わせて試したのは以下のバージョン。

winston 3.1
logging-winston 0.9

実は、上の組み合わせは

undefined is a legacy winston transport. ...

と ERROR が起きてしまう。ただし、実際には動作する。という状態なので、安心したい場合は winston@2 系列と組み合わせるのがよいと思う。

最近のアップデートで 0.10.x 系で winston 3 対応している様子は分かるんだけど、中の依存で Node 6 がたぶん意図せず弾かれたり、ややこしい感じなので慌てない方がよさそう。

winstonを入れてみる

というわけで改めて必要なのはこれ。

winstonjs/winston: A logger for just about everything.

winston で logger を作る際の超基本的な構造はこんな感じになります。

logger.js

const winston = require('winston')
const logger  = winston.createLogger({
  level,
  format,
  transports
})

module.exports = logger

もうちょっと具体的に書くと、以下のようにしておけばとりあえず動く。

const winston = require('winston')
const logger  = winston.createLogger({
  level: 'info',
  format: new winston.format.simple(),
  transports: [new winston.transports.Console()]
})

module.exports = logger

で、index.js（function 側）では

const logger = require('./logger')

module.exports.test = (req, res) => {
  logger.info('ok')
  res.send('200 ok')
}

のように logger を呼び出して叩く。これで少なくとも functions-emulator では問題なく console に出力される。

この logger は morgan のような express middleware ではないので、function のコードで require していきなり使えます。

Cloud Functions用にlogging-winstonを追加

googleapis/nodejs-logging-winston: Node.js client integration between Stackdriver Logging and Winston.

Google Cloud Functions からは console が STDOUT だから自動的にログが Stackdriver Logging に流れてくれる、ようなことはない¹。そこで winston に Stackdriver Logging 用の transport を追加する。

const winton           = require('winston')
const {LoggingWinston} = require('@google-cloud/logging-winston')
..
snip)
..
const transports = [
  new winston.transports.Console(),
  new LoggingWinston()
]
..
snip)
..
const logger = winston.createLogger({
  level: 'info',
  format: winston.format.simple(),
  transports
})

module.exports = logger

てな感じ。

IAM Roleを足す

念のため、メモ。実際に Stackdriver Logging へログを送るには以下の permission ( Role )

logging.logEntries.create ( Logs Writer )

が要ります。ただ、Function に限って言えば Function の実行権限を持っていれば Logging への write 権限も普通はあると思います。

何が嬉しいのか

これで何が嬉しいかというと、とりあえず log level の記述が Stackdriver Logging の期待するものとだいたい一致するところ。

なんでここが気になるかというと、

ログを書き込む
Cloud Function からログラインを得るには、console.log か console.error を使います。

snip)

console.log() コマンドには INFO ログレベルがあります。
console.error() コマンドには ERROR ログレベルがあります。
内部システムメッセージには DEBUG ログレベルがあります。

https://cloud.google.com/functions/docs/monitoring/logging

あれー、Warning とかどうすんだー？というのが気になったから。

もう一つ大事なのは format. 例えば timestamp を自動で入れることもできるし、すべての backtrace を入れた JSON ログ²を作ることもできる。そのうえで Stackdriver Monitoring と組み合わせると、ログ → 監視 → 通知 → 対応（修正）をスムーズに行うことができるようになる。はず。

そのうち

Cloud Functions の外からでもこの組み合わせだけであれこれ ( Project ID とか ) 設定すればイケるんじゃないかと思っているので、今度試す。

GAE とかはそうなってるはず ↩
Stackdriver Logging 用語では protoPayload ↩

2018-09-15

超今さらExpress触ってみた - その5 Loggerを改善する -

背景