clue / log パッケージ

概要

いつのまにか clue という Goa のお友達が出来ていたので何が出来るのか調べてみたメモです。よくわかってない＆主観が入っているので、正確なところはレポジトリを参照下さい（そしてツッコミを下さい）。

clue とは何か？

マイクロサービスにあったらいいなという機能をまとめたライブラリです。
複数のパッケージから構成されています。Goa に限らずマイクロサービスでの利用を想定して書かれています（が、Goa ではこれを積極的に利用したいという風に見えます）。

clue が提供する機能：

• Logging: コンテキストベースのロガーを提供
• Metrics: Prometheus 互換の /metrics HTTPエンドポイントを公開可能
• Health checks: サービスのヘルスチェックエンドポイントを公開
• Dependency mocks: テストのためのモックを提供
• Tracing: OpenTelemetry仕様に準拠してリクエストをトレース

今回は log パッケージについてです。

log パッケージ

ロガーを context.Context に仕込んでおこうというのがアイディアのようです。

package main

import (
        "context"
        "github.com/goadesign/clue/log"
)

func main() {
        ctx := log.Context(context.Background()) // ← ここでロガーが ctx にセットされている
        log.Printf(ctx, "hello %s", "world") // ← ctx からロガーを取り出してメッセージを表示する
        log.Print(ctx, log.KV{"hello", "world"})

        log.Print(ctx,
                log.KV{"example", "log.KV"},
                log.KV{"order", "deterministic"},
                log.KV{"backed_by", "slice"},
        )

        log.Print(ctx, log.Fields{
                "example": "log.Fields",
                "order": "random",
                "backed_by": "map",
        })
}

OUTPUT:

time=2022-02-22T02:22:02Z level=info msg="hello world"
time=2022-02-22T02:22:02Z level=info hello=world
time=2022-02-22T02:22:02Z level=info example=log.KV order=deterministic backed_by=slice
time=2022-02-22T02:22:02Z level=info order=random backed_by=map example=log.Fields

ログを context.Context に仕込む以外は普通のログとそう変わらない。
ただ、log.Context(ctx) でロガーがセットされるのはわかりにくい感じがする。

// Context initializes a context for logging.
func Context(ctx context.Context, opts ...LogOption) context.Context {
	l, ok := ctx.Value(ctxLogger).(*logger)
	if !ok {
		l = &logger{options: defaultOptions()}
	}
	l.lock.Lock()
	defer l.lock.Unlock()
	for _, opt := range opts {
		opt(l.options)
	}
	if l.options.disableBuffering != nil && l.options.disableBuffering(ctx) {
		l.flush()
	}
	return context.WithValue(ctx, ctxLogger, l)
}

何がうれしいのかというと、ctx で引き回しているロガーに値をセットしておくと、引き回された箇所のログでその値がセットされているのでログが分かりやすくなる、という点。たとえば、次のように key/value をセットしておくと、

ctx := log.With(log.Context(context.Background()), log.KV{"user-id", 123})

この ctx から生成されるログには、user-id=123 という key/value が必ず与えられるので、ログが迷子になりにくくなります。

その他にもいくつか機能があります。

バッファリング

ログは、エラーの時だけ欲しいけど、エラーが起こったときには周辺のログも欲しい、という要望があると思います。clue では、log.Info(...) で出力したログをバッファリングして log.Errorf(...) で出力したときだけ出力する機能があります。

log.Infof(ctx, "request started")  // ← このログはまだ出力されない。バッファされるだけ
// ... ここで log.Infof(...) が何回か呼ばれるかも知れない
log.Errorf(ctx, err, "request failed") // ← ここで今までバッファリングしたログが出力されます

バッファをフラッシュするタイミングは、Fatal, Error, もしくは Flush が呼び出されたときです。また、Print は常にバッファリングされないので、バッファリングされたメッセージをフラッシュせずに、任意のログを出力することが出来ます。

また、バッファリングを停止して、強制的にログ出力することも可能です。

ctx := log.Context(req.Context(), log.WithDisableBuffering(log.IsTracing))

構造化ログ

key/value のペアでロギングできます。

ctx := log.Context(context.Background())
ctx := log.With(ctx, log.KV{"key2", "val2"})
log.Print(ctx, log.KV{"hello",  "world 1"})

ctx = log.With(ctx, log.KV{"key3", "val3"})
log.Print(ctx, log.KV{"hello", "world 2"}, log.KV{"key4", "val4"})

ログレベル

ログのレベルが debug, info, erro の3段階用意されています。

ctx := log.Context(context.Background())
log.Debugf(ctx, "debug message 1")

ctx := log.Context(ctx, log.WithDebug())
log.Debugf(ctx, "debug message 2")
log.Infof(ctx, "info message")

OUTPUT:

DEBG[0000] msg="debug message 2"
INFO[0000] msg="info message"

0000 はアプリケーションが開始してからの秒数とのこと。

ログの出力先

ctx := log.Context(context.Background(), log.WithOutput(os.Stderr))
log.Printf(ctx, "hello world")

ログの形式

ログの形式は、カスタムフォーマッターで変更可能ですが、組み込みのフォーマットも3つ用意されています。

• FormatText： logfmtを使用したプレーンテキスト形式
  • time=2022-01-09T20:29:45Z level=info msg="hello world"
• FormatTerminal：コンソールに色付きでログを表示するのに適した形式
  • INFO[0000] msg="hello world"
• FormatJSON：JSON形式
  • {"time":"2022-01-09T20:29:45Z","level":"info","msg":"hello world"}

カスタムフォーマッター

func formatFunc(entry *log.Entry) []byte {
        return []byte(fmt.Sprintf("%s: %s", entry.Severity, entry.Keyvals[0].V))
}

ctx := log.Context(context.Background(), log.WithFormat(formatFunc))
log.Printf(ctx, "hello world")

OUTPUT:

INFO: hello world

HTTP ミドルウエア

ログコンテキスト（ロガーが仕込まれた context.Context）を伝播させるミドルウエアを生成します。ログが不要なパスを正規表現で指定可能なので、特定のパスだけログしないようにすることができます（ヘルスチェックのパスなどを除外することを想定しているようです）。

gRPC インターセプター

上記の gRPC 版です。

標準ログとの互換

標準ログのインターフェースとの互換があります。標準ログは Print を利用するので、バッファリングはおこなわれません。

標準ログはインターフェースで定義されてないので、インターフェースを満たしていてもな・・・。みたいなところはある感じしますが、どうなんでしょうか？ 🤔

Goa のミドルウエアとして利用する

ctx := log.Context(context.Background())
logger := log.AsGoaMiddlewareLogger(ctx) // logger は middleware.Logger を満たします

Happy hacking!