【golang】zap.Loggerをobserverでテストする方法

gRPCのInterceptorでサーバー共通設定をloggerに設定してほしいという依頼を先日受けました。実装自体は簡単だったのですが、zap.loggerのインスタンスのみだとちゃんと共通のログを出力できているのか確認ができません。

仕方ないので目視での確認だけしてちゃんとしたユニットテストは作っていなかったのですが、上司からobserverというライブラリがあることを教えてもらい、無事にテストすることが可能になりました。

このobserver、日本語の情報も少ないみたいなので記事としてまとめることにしてみます。

この記事を読むとわかること

zap.Loggerの概要
observerを使ったzap.Loggerの使い方

zap.Loggerの概要
zap.Loggerをテストする

zap.Loggerの概要

この記事を必要とする人は大体わかっている内容でしょうが、一応簡単にzap.Loggerの説明もしておきます。

zap.Loggerはzapが提供しているログ出力機能です。メソッドとしていくつかレベル別の出力を行うことができ、設定に応じて必要なログだけを出力することができるようになります。

特徴としては他のLoggerより高速であることのようです。

WebサーバーやgRPCサーバーなんかで使うときは、context.Contextに格納して同一セッションでは同じLoggerインスタンスを使いまわすことが多いようです。少なくともgRPCサーバーようにはContextに格納、取得する関数が準備されていました。

package main

import (
	"context"

	"github.com/grpc-ecosystem/go-grpc-middleware/logging/zap/ctxzap"
	"go.uber.org/zap"
)

func main() {
	logger, _ := zap.NewDevelopment()
	ctx := context.Background()
	// logger をContextに格納
	ctx = ctxzap.ToContext(ctx, logger)
	useLoggerInContext(ctx)
}

func useLoggerInContext(ctx context.Context) {
	// loggerをContextから取得
	logger := ctxzap.Extract(ctx)
	logger.Debug("debug", zap.String("message", "test log"))
	logger.Error("error", zap.String("message", "test log"))
}

zap.Loggerをテストする

単純にログを出力するだけであればLoggerに関連するテストはあまり必要ないことが多いと思います。ただ、Contextに入れて使い回すLoggerにサーバー共通で出力したいフィールドを追加する場合などは、そのフィールドがちゃんと出力されるか知りたいケースもあるでしょう。

zap.Logger自体にはすでに設定されているフィールドを確認する方法がありません。そこで利用するのがobserverです。実はgo.uber.org/zapのサブパッケージで、zapが準備してくれています。私は注意不足で存在に気が付かず、テストできないと思いこんでいました・・・。

observerを使うと、zap.Loggerにどのようなログが出力されるのかを確認することができます。通常のzap.Loggerのかわりにobserverが作ったインスタンスを渡すことで確認可能になるので、LoggerはDI（Dependency injection：依存性の注入）していることが前提です。ContextにLoggerを格納する運用をしていれば、これは満たせるでしょう。

使い方はこんな感じです。

テスト対象のコード：

package main

import (
	"context"

	"github.com/grpc-ecosystem/go-grpc-middleware/logging/zap/ctxzap"
	"go.uber.org/zap"
)

func main() {
	logger, _ := zap.NewDevelopment()
	logger = initLogger(logger)
	ctx := context.Background()
	// logger をContextに格納
	ctx = ctxzap.ToContext(ctx, logger)
	useLoggerInContext(ctx)
}

// テスト対象その1
func initLogger(logger *zap.Logger) *zap.Logger {
	return logger.With(zap.String("common", "hoge"))
}

// テスト対象その2
func useLoggerInContext(ctx context.Context) {
	// loggerをContextから取得
	logger := ctxzap.Extract(ctx)
	logger.Debug("debug", zap.String("message", "fuga"))
	logger.Error("error", zap.String("message", "piyo"))
}

テストコード：

package main

import (
	"context"
	"testing"

	"github.com/grpc-ecosystem/go-grpc-middleware/logging/zap/ctxzap"
	"github.com/stretchr/testify/assert"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	"go.uber.org/zap/zaptest/observer"
)

func Test_initLogger(t *testing.T) {

	tests := []struct {
		name          string
		wantZapFields []zap.Field
	}{
		{
			name:          "loggerに想定通りのフィールドが存在する",
			wantZapFields: []zap.Field{zap.String("common", "hoge")},
		},
	}
	for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
			// observer関連インスタンスの作成、この辺はおまじないに近い
			observedZapCore, observedLogs := observer.New(zap.DebugLevel)
			observedLogger := zap.New(observedZapCore)

			got := initLogger(observedLogger)
			// observerは出力したログしか確認できないため、ここで確認用のログを出力
			got.Debug("test")
			// observerに出力されたすべてのログを取得、
			allLogs := observedLogs.All()
			// ログ出力はすぐ上のDebugを1回行っただけのはずなので長さは1のはず
			if assert.Equal(t, 1, len(allLogs)) {
				// テスト内でのログ出力であまり意味はないけど想定通りのメッセージか確認
				assert.Equal(t, "test", allLogs[0].Message)
				// initLoggerで設定したフィールドが出力されているか確認
				assert.ElementsMatch(t, tt.wantZapFields, allLogs[0].Context)
			}
		})
	}
}

func Test_useLoggerInContext(t *testing.T) {
	type logOut struct {
		message string
		fields  []zap.Field
	}
	tests := []struct {
		name     string
		logLevel zapcore.Level
		wantLogs []logOut
	}{
		{
			name:     "DebugとErrorログが出力される",
			logLevel: zap.DebugLevel,
			wantLogs: []logOut{
				{
					message: "debug",
					fields:  []zap.Field{zap.String("message", "fuga")},
				},
				{
					message: "error",
					fields:  []zap.Field{zap.String("message", "piyo")},
				},
			},
		},
		{
			name:     "Errorログだけが出力される",
			logLevel: zap.WarnLevel,
			wantLogs: []logOut{
				{
					message: "error",
					fields:  []zap.Field{zap.String("message", "piyo")},
				},
			},
		},
	}
	for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
			observedZapCore, observedLogs := observer.New(&tt.logLevel)
			observedLogger := zap.New(observedZapCore)
			ctx := context.Background()
			ctx = ctxzap.ToContext(ctx, observedLogger)
			useLoggerInContext(ctx)
			allLogs := observedLogs.All()
			if !assert.Equal(t, len(allLogs), len(tt.wantLogs), "not equal log count") {
				return
			}
			// observedLogs.Allはログの出力順に格納されている
			for i, log := range allLogs {
				assert.Equal(t, tt.wantLogs[i].message, log.Message)
				assert.ElementsMatch(t, tt.wantLogs[i].fields, log.Context)
			}
		})
	}
}

テストコードで注目するべきはこの2行。

			observedZapCore, observedLogs := observer.New(&tt.logLevel)
			observedLogger := zap.New(observedZapCore)

observedLoggerが通常のLoggerのモックで、テストをしたい場合はLoggerのかわりにDIすることになります。

そして、実際に出力されたログの情報はobservedLogsに格納されます。observedLogsにはログ出力順に情報が格納されていくので、テスト対象の関数が実行されたあとはその関数内でのログを取得できる仕組みです。

observedLogs.All()で取得できる情報は、LoggedEntryです。サンプルコードではMessage（Logger.Debugメソッドなどの第1引数の文）とContext（Debugメソッドの第2引数以下のzap.Field）だけを使っていますが、必要であれば他のもの（ログレベルとか出力された時間とか）も取得可能になっています。

この記事に質問やご意見がありましたら、Twitterやお問い合わせフォームから連絡をください。このページにあるコメント欄でも大丈夫です。