前提

zapで出力したログは Entry, []Field 形式で出力される。

// https://github.com/uber-go/zap/blob/master/zapcore/entry.go
type Entry struct {
	Level      Level
	Time       time.Time
	LoggerName string
	Message    string
	Caller     EntryCaller
	Stack      string
}

// https://github.com/uber-go/zap/blob/master/zapcore/field.go
type Field struct {
	Key       string
	Type      FieldType
	Integer   int64
	String    string
	Interface interface{}
}

例えば、

logger.Error("failed to xxx", zap.String("key1", "value1"), zap.String("key2", "value2"))

と出力すると、構造化ログは以下のようになる。

{
  "level": "error",
  "ts": "2024-11-20T10:28:53+09:00",
  "caller": "main.go:10",
  "msg": "failed to xxx",
  "stacktrace": "xxx"
  "key1": "value1",
  "key2": "value2",
}

内部的には level〜stacktrace 部を Entry、key1〜key2 部を []Field で保持している。👈これをテストする。

はる / Haru

方法

zaptest/observer を利用する。

テスト内でobserverを用いてログ観測すると、以下のように Entry, []Field が observer.LoggedEntry として取得できるのでこれをチェックすれば良い。

// https://github.com/uber-go/zap/blob/master/zaptest/observer/logged_entry.go
type LoggedEntry struct {
	zapcore.Entry
	Context []zapcore.Field
}

zap.Logger に observer を仕込む方法は2通りある。

はる / Haru

いずれにしても observer.New した「zapcore.Core を差し込む」ことが必要。

[Case1] zap.New

基本的にはこちらを使う。

core, observedLogs := observer.New(zap.InfoLevel) // Info 以上
logger := zap.New(core)                           // zap.Loggerを生成
got := observedLogs.TakeAll()                     // []observer.LoggedEntryを取得

[Case2] WithOptions

共通処理を func NewLogger() (*zap.Logger, error) と定義してる場合には、こちらを使う。
ただし、呼ぶだけでログテストとして機能していない点が多い（詳細は後述）ため、検証範囲は方法①と変わらないのであえて使う必要はない。

core2, observedLogs := observer.New(zap.InfoLevel)                               // Info 以上を取得
logger, _ := NewLogger()                                                         // 共通処理でzap.Loggerを生成
logger = logger.WithOptions(zap.WrapCore(func(core1 zapcore.Core) zapcore.Core { // observerのcore追加
	return zapcore.NewTee(core1, core2)
}))
// 以下、方法①と同様のため割愛

はる / Haru

注意点

Logger 生成関数を作成して共通処理のような作り込みをしている場合、その共通処理に対しては observer でテストすることができない可能性がある。

例えば、アプリケーション全体でトランザクションを一位に示す transaction_id をログ出力時に必ず付与したい場合、以下のような Logger 生成関数で共通化することが考えられる。

func NewLogger() (*zap.Logger, error) {
	c := zap.NewProductionConfig()

	logger, err := c.Build()
	if err != nil {
		return nil, err
	}

	// loggerインスタンスに共通の Field を追加
	return logger.With(
		zap.String("transaction_id", uuid.NewString()),
	), nil
}

こうすることで、NewLogger で生成された Logger を引き回す限りは、必ずログ出力時に []Field{{Key: "transaction_id, String: "d57f596a-5574-3dc5-0667-0ab09307d7c4"}} が設定されるようになる。

しかしながら、この transaction_id が付与されていること を observer でテストすることはできない。
これは、共通で付与する Field の情報を Logger 内部の Core（interface）で保持しており、observer の仕組みはこの Core Interface をモックにしているような作りだからである。

type Logger struct {
	core zapcore.Core // 👈 logger.With() でここにセット
	// (中略)
	clock zapcore.Clock
}

observer.New で生成した Core も同じ箇所にセットする必要があり、zap.Logger は immutable（不変）な設計となっているので、結果として「どこでログ出力しても必ず付与される Field」のような処理をテストすることはできない。

要望として Issue, PR も挙がっているが、重大な変更になるので対応は難しい気もしている。

はる / Haru

Appendix

2通りの方法でログテストしてみたソースコード。
実際には transaction_id がログ出力されるが、テストできていないことが確認できる。

main.go

package main

import (
	"github.com/google/uuid"
	"go.uber.org/zap"
)

func main() {
	logger, err := NewLogger()
	if err != nil {
		panic(err)
	}

	app := &App{logger: logger}
	app.Run()
}

func NewLogger() (*zap.Logger, error) {
	c := zap.NewProductionConfig()

	logger, err := c.Build()
	if err != nil {
		return nil, err
	}

	return logger.With(
		zap.String("transaction_id", uuid.NewString()),
	), nil
}

type App struct {
	logger *zap.Logger
}

func (a *App) Run() {
	a.logger.Debug("debug test", zap.String("key", "value"))
	a.logger.Info("info test", zap.String("key1", "value1"), zap.String("key2", "value2"))
	a.logger.Error("error test", zap.String("key1", "value1"), zap.String("key2", "value2"))
}

main_test.go

package main

import (
	"testing"

	"github.com/stretchr/testify/require"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	"go.uber.org/zap/zaptest/observer"
)

func TestLogger(t *testing.T) {
	t.Parallel()

	tests := []struct {
		name string
		want []observer.LoggedEntry
	}{
		{
			name: "ok",
			want: []observer.LoggedEntry{
				{Entry: zapcore.Entry{Level: zap.InfoLevel, Message: "info test"}, Context: []zapcore.Field{
					{Key: "key1", Type: zapcore.StringType, String: "value1"},
					{Key: "key2", Type: zapcore.StringType, String: "value2"},
				}},
				{Entry: zapcore.Entry{Level: zap.ErrorLevel, Message: "error test"}, Context: []zapcore.Field{
					{Key: "key1", Type: zapcore.StringType, String: "value1"},
					{Key: "key2", Type: zapcore.StringType, String: "value2"},
				}},
			},
		},
	}

	for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
			t.Parallel()

			// arrange
			// [Case1] zap.New
			core, observedLogs := observer.New(zap.InfoLevel)
			logger := zap.New(core)

			// [Case2] WithOptions
			// core2, observedLogs := observer.New(zap.InfoLevel)
			// logger, _ := NewLogger()
			// logger = logger.WithOptions(zap.WrapCore(func(core1 zapcore.Core) zapcore.Core {
			// 	return zapcore.NewTee(core1, core2)
			// }))

			// act
			app := &App{logger: logger}
			app.Run()

			// assert
			got := observedLogs.TakeAll()
			require.Equal(t, len(tt.want), len(got))
			for i := range got {
				// extry
				require.Equal(t, tt.want[i].Entry.Level, got[i].Entry.Level)
				require.Equal(t, tt.want[i].Entry.Message, got[i].Entry.Message)
				// context
				require.Equal(t, len(tt.want[i].Context), len(got[i].Context))
				require.Equal(t, tt.want[i].Context, got[i].Context)
			}
		})
	}
}

このスクラップは1日前にクローズされました