golangの高速な構造化ログライブラリ「zap」の使い方

はじめに

構造化メッセージが構築できる高速なロギングライブラリを謳っている『zap』を触ってみました。
ドキュメントがあまり充実していなくて、どんなことができるのかGodoc見ながら調査したので、その結果を自分用のメモがてら書いておこうと思います。

確認した環境とバージョン

• Mac OSX 10.11.6 (El Capitan)
• go v1.8
• zap v1.0.0

zapの特徴

高速

zapは以下のようなアプローチで高速化していると言っています。

• Reflectionを使わない
• アロケーションしないJSONエンコーダを使用
• 可能な限りシリアル化のオーバーヘッドとアロケーションを避ける

そして、独自のベンチマークによると、他の構造化ロギングライブラリだけでなく、標準ライブラリよりも高速に動作するそうです。
確かにReadMeのパフォーマンスを見ると圧倒的に高速で低アロケーションを実現しています。

構造化されたメッセージ

ロギング時にKeyとValueを持ったフィールドをセットすることで構造化されたログメッセージを出力することができます。
また、Namespaceを使うことで階層構造も比較的簡単に表現できます。
コードにおけるレイヤーや保持するデータの種類などでうまくフィールドを構造化させておけば、わかりやすいログメッセージを出力することもできます。

変更可能な豊富な設定や独自エンコーダ利用可能による柔軟さ

スタックトレースの表示/非表示、呼び出し元の表示/非表示、出力形式(Console形式/Json形式)の選択、TimeやDurationの表示形式の選択などデフォルトで用意された変更可能な設定も多数あります。
それでも要件を満たさないならば、独自にエンコーダを作成して利用することも可能になっています。

Quick Start

インストールから簡単な使い方まで見ていきます。

Install

グローバルに突っ込んでもいいならgo getでOKです。

$ go get -u go.uber.org/zap

パッケージマネージャを使っているならよしなに定義して下さい。
Glideだとこのように定義してglide upすればOKです。

e.g.glide

import:
  - package: go.uber.org/zap
    version: ^1

Hello zap

最も簡単な方法でロガーを作ってログを出力してみましょう。

main.go

package main

import "go.uber.org/zap"

func main() {
    logger, _ := zap.NewDevelopment()
    logger.Info("Hello zap", zap.String("key", "value"), zap.Time("now", time.Now()))
}

これで終わりです。これを実行すると、

2017-03-23T17:52:59.005+0900	INFO	zap-example/main.go:7	Hello zap	{"key": "value", "now": "2017-03-23T17:52:59.005+0900"}

ロギング時間、ログレベル、ロギングした場所、メッセージと構造化されたメッセージが出力されます。

ロギング編

ロギングに関する構造体やメソッドの解説です。

Logger

ロギングを行う為の構造体です。
SugaredLoggerよりも高速かつ低アロケーションで動作しますが、構造化スタイルのロギングしかできません（printやprintfスタイルのロギングはできません）。

メソッド

Method	Description
New	独自に作成したCoreから作成 最も柔軟で、最も冗長な方法
Config#Build	独自に定義したConfigから作成 最も基本的な方法（詳細はConfig編を参照）
NewDevelopment	あらかじめ定義された設定のLoggerを作成 dev用という位置づけらしくconsole形式で表示
NewProduction	あらかじめ定義された設定のLoggerを作成 prd用という位置づけらしくjson形式で表示
Logger#With	現在のLoggerをcloneし、引数に指定したフィールドを保持した新しいロガーを取得
Logger#WithOptions	現在のLoggerをcloneし、引数に指定したオプションを適用した新しいロガーを取得
Logger#Named	現在のLoggerをcloneし、引数に指定した名称のセグメントを追加した新しいロガーを取得 セグメントはName項目として表示
Logger#Sugar	SugaredLoggerを取得
Logger#{ログレベル}	指定したログメッセージとフィールドでロギングする
Logger#Sync	バッファリングされたログエントリをflushする

• ロギングサンプルコード

sample

logger.Debug("msg", zap.String("Key", "String"), zap.Ints("ints", []int{10, 20}))

output

2017-03-27T10:17:19.930+0900	DEBUG	zap-example/main.go:5	msg	{"Key": "String", "int": [10, 20]}

SugaredLogger

Loggerから取得できる簡易なLoggerです。
構造化ロギングとprintfスタイルのロギングどちらも利用可能ですが、Loggerよりも低速で高アロケーションです（それでも他のロギングライブラリよりも高速らしい）。

メソッド

Method	Description
SugaredLogger#With	現在のSugaredLogger（正確には内部に保持している元のLogger）をcloneし、引数に指定したフィールドを保持した新しいロガーを取得
SugaredLogger#Named	現在のSugaredLogger（正確には内部に保持している元のLogger）をcloneし、引数に指定した名称のセグメントを追加した新しいロガーを取得 セグメントはName項目として表示
SugaredLogger#Desugar	元のLoggerを取得
SugaredLogger#{ログレベル}	fmt.Printスタイルでロギング
SugaredLogger#{ログレベル}f	fmt.Printfスタイルでロギング
SugaredLogger#{ログレベル}w	構造化スタイルでロギング
SugaredLogger#Sync	バッファリングされたログエントリをflushする

• ロギングサンプルコード

suger.Info("one", "two", "three")
suger.Infof("one: %s, %d", "two", 10)
suger.Infow("msg", "key", "value", "intArray", []int{10, 100}, "duration", time.Second*200)

output

2017-03-27T10:17:19.930+0900	INFO	zap-example/main.go:5	onetwothree
2017-03-27T10:17:19.930+0900	INFO	zap-example/main.go:6	one: two, 10
2017-03-27T10:17:19.930+0900	INFO	zap-example/main.go:7	msg	{"key": "value", "intArray": [10, 100], "duration": "3m20s"}

ログレベル

ログレベルは以下の種類が用意されています。

Level	Description
Debug	Debugレベルのメッセージを出力
Info	Infoレベルのメッセージを出力
Warn	Warnレベルのメッセージを出力 デフォルトではスタックトレースも出力
Error	Errorレベルのメッセージを出力 デフォルトではスタックトレースも出力
DPanic	DPanicレベルのメッセージを出力 デフォルトではスタックトレースも出力 Devモードの場合、その後Panic
Panic	Panicレベルのメッセージを出力 デフォルトではスタックトレースも出力 その後Panic
Fatal	Fatalレベルのメッセージを出力 デフォルトではスタックトレースも出力 その後ステータスコード1でプロセスを終了

Field

Loggerによるロギング時に指定できる、構造化のための構造体です。
基本的な型からそれらの配列、エラー、オブジェクトなどたくさんあるので、一覧にしておきます。

Method	Description
Skip	non-operation。何も表示しない。使い道がよく分からない。
Binary	バイト配列。BASE64でエンコードされた形式で表示。
ByteString	UTF-8でエンコードされたバイト配列。
ByteStrings	UTF-8でエンコードされたバイト配列の配列。
String	string型の値。
Strings	string型の値の配列。
Stringer	fmt.Stringerを実装した型のインスタンス。Stringメソッドの結果を表示。
Bool	Bool型の値。
Bools	Bool型の値の配列。
Complex64/128	complex64/complex128型の値。
Complex64/128s	complex64/complex128型の値の配列。
Float32/64	float32/float64型の値。
Float32/64s	float32/float64型の値の配列。
Int/8/16/32/64	int/int8/int16/int32/int64型の値。
Int/8/16/32/64s	int/int8/int16/int32/int64型の値の配列。
Uint/8/16/32/64	uint/uint8/uint16/uint32/uint64型の値。
Uint/8/16/32/64s	uint/uint8/uint16/uint32/uint64型の値の配列。
Uintptr	uintptr型の値。
Uintptrs	uintptr型の値の配列。
Time	Time型の値。表示形式はTimeEncoderに依存する。
Times	Time型の値の配列。表示形式はTimeEncoderに依存する。
Duration	Duration型の値。表示形式はDurationEncoderに依存する。
Durations	Duration型の値の配列。表示形式はDurationEncoderに依存する。
Any	任意の型の値。エンコーダが自動的に型を判別する。型によってはReflectionを利用するので型を明示するメソッドを使うより遅くなる可能性がある。
Reflect	任意の型の値。エンコーダが自動的に型を判別する。ReflectionベースなのでAnyより重い。
Error	error型の値。メッセージのみの"error"とエラー詳細の"errorVerbose"が表示される。
Errors	error型の値の配列。メッセージのみの"error"とエラー詳細の"errorVerbose"が表示される。
NamedError	error型の値。Key名も指定可能。
Stack	スタックトレースを格納する。
Object	ObjectMarshalerを実装した型のインスタンスやObjectMarshalerFuncを設定。MarshalLogObjectメソッドを実行した結果を表示。詳しくはObjectメソッドの詳細を参照。
Array	ArrayMarshalerを実装した型のインスタンスやArrayMarshalerFuncを設定。MarshalLogArrayメソッドを実行した結果を表示。詳しくはArrayメソッドの詳細を参照。
Namespace	指定した名称でフィールドのスコープを設定。これ以降に指定したフィールドは全てこのスコープ内に設定される。詳しくはNamespaceメソッドの詳細を参照。

Objectメソッドの詳細

Objectメソッドは他のフィールドを設定するメソッド群とは少し扱い方が異なるので解説します。
ObjectメソッドはValueにzapcore.ObjectMarshalerインタフェースを取り、このインタフェースはfunc MarshalLogObject(ObjectEncoder) errorの実装を要求しています。
また、zapcore.ObjectMarshalerFuncを利用してクロージャを使うこともできます。

以下、ObjectMarshalerを満たす構造体のインスタンスを渡すパターンのサンプルコードです。

ObjectMarshaler

type user struct {
	Name      string
	Email     string
	CreatedAt time.Time
}

func (u user) MarshalLogObject(enc zapcore.ObjectEncoder) error {
	enc.AddString("name", u.Name)
	enc.AddString("email", u.Email)
	enc.AddInt64("created_at", u.CreatedAt.UnixNano())
	return nil
}

func main() {
	logger, _ := zap.NewDevelopment()
	user := &user{
		Name: "Zap",
		Email: "[e-mail]",
		CreatedAt: time.Now(),
	}
	logger.Info("object sample", zap.Object("userObj", user))
}

ログのメッセージ部分はこのように表示されます。

object sample	{"userObj": {"name": "Zap", "email": "[e-mail]", "created_at": 1490365748443608592}}

続いてObjectMarshalerFuncを使ったクロージャパターンのサンプルです。

ObjectMarshalerFunc

type user struct {
	Name      string
	Email     string
	CreatedAt time.Time
}

func main() {
	logger, _ := zap.NewDevelopment()
	user := &user{
		Name: "Zap",
		Email: "[e-mail]",
		CreatedAt: time.Now(),
	}
	logger.Info("object sample", zap.Object("object", zapcore.ObjectMarshalerFunc(func(inner zapcore.ObjectEncoder) error {
		inner.AddString("name", user.Name)
		inner.AddString("email", user.Email)
		inner.AddInt64("created_at", user.CreatedAt.UnixNano())
		return nil
	})))
}

これでも同じような結果が得られます。

object sample	{"object": {"name": "Zap", "email": "[e-mail]", "created_at": 1490366381679343297}}

Arrayメソッドの詳細

ArrayメソッドもObjectメソッドと同様の方法で利用できます。
ArrayメソッドはValueにzapcore.ArrayMarshalerインタフェースを取り、このインタフェースはfunc MarshalLogArray(ArrayEncoder) errorの実装を要求しています。
また、zapcore.ArrayMarshalerFuncを利用してクロージャを使うこともできます。

以下、ArrayMarshalerを満たす構造体のインスタンスを渡すパターンのサンプルコードです。

ArrayMarshaler

type user struct {
	Name string
}

type users []*user

func (us users) MarshalLogArray(enc zapcore.ArrayEncoder) error {
	for _, u := range us {
		enc.AppendString(u.Name)
	}
	return nil
}

func main() {
	logger, _ := zap.NewDevelopment()
	var users users = []*user{
		&user{Name: "Zap1"},
		&user{Name: "Zap2"},
		&user{Name: "Zap3"},
	}
	logger.Info("array sample", zap.Array("userArray", users))
}

ログのメッセージ部分はこのように表示されます。

array sample	{"userArray": ["Zap1", "Zap2", "Zap3"]}

続いてArrayMarshalerFuncを使ったクロージャパターンのサンプルです。

ArrayMarshalerFunc

type user struct {
	Name string
}

func main() {
	logger, _ := zap.NewDevelopment()
	users := []*user{
		&user{Name: "Zap1"},
		&user{Name: "Zap2"},
		&user{Name: "Zap3"},
	}
	logger.Info("array sample", zap.Array("userArray", zapcore.ArrayMarshalerFunc(func(inner zapcore.ArrayEncoder) error {
		for _, u := range users {
			inner.AppendString(u.Name)
		}
		return nil
	})))
}

これでも同じような結果が得られます。

array sample	{"userArray": ["Zap1", "Zap2", "Zap3"]}

Namespaceメソッドの詳細

Namespaceメソッドを使うと引数に指定したKey名でスコープを設定し、これ以降にセットしたフィールドは全てこのスコープ内に収まるようになります。
文面だとわかりにくいと思うのでサンプルコードを示します。

Namespace

func main() {
	logger, _ := zap.NewDevelopment()
	logger.Info("namespace sample", zap.String("scope", "top"))
	logger = logger.With(zap.Namespace("second scope"))
	logger.Info("namespace sample", zap.String("scope", "second"))
	logger = logger.With(zap.Namespace("third scope"))
	logger.Info("namespace sample", zap.String("scope", "third"))
}

ここで使用しているWithメソッドは、現在のLoggerをクローンし、引数に指定したフィールドを追加した子ロガーを作成するメソッドです。

namespace sample	{"scope": "top"}
namespace sample	{"second scope": {"scope": "second"}}
namespace sample	{"second scope": {"third scope": {"scope": "third"}}}

メッセージはこのようになります。

Config編

zapのConfigに関する構造体やメソッドの解説です。

Config

zapの設定を定義した構造体です。
Configはコーディングベースで設定する方法と、JsonまたはYamlファイルから設定する方法があります。
いずれかの作成したConfigのBuildメソッドでLoggerを生成できます。

以下、サンプルコードです。いずれのサンプルも同じ内容のConfigを作成しています。

• コーディングベースで作成するサンプル

コーディングベース

level := zap.NewAtomicLevel()
level.SetLevel(zapcore.DebugLevel)

myConfig := zap.Config{
	Level: level,
	Encoding: "json",
	EncoderConfig: zapcore.EncoderConfig{
		TimeKey:        "Time",
		LevelKey:       "Level",
		NameKey:        "Name",
		CallerKey:      "Caller",
		MessageKey:     "Msg",
		StacktraceKey:  "St",
		EncodeLevel:    zapcore.CapitalLevelEncoder,
		EncodeTime:     zapcore.ISO8601TimeEncoder,
		EncodeDuration: zapcore.StringDurationEncoder,
		EncodeCaller:   zapcore.ShortCallerEncoder,
	},
	OutputPaths:      []string{"stdout"},
	ErrorOutputPaths: []string{"stderr"},
}
logger, _ := myConfig.Build()

• Jsonファイルから作成するサンプル

config.json

{
  "level": "debug",
  "encoding": "json",
  "encoderConfig": {
    "messageKey": "Msg",
    "levelKey": "Level",
    "timeKey": "Time",
    "nameKey": "Name",
    "callerKey": "Caller",
    "stacktraceKey": "St",
    "levelEncoder": "capital",
    "timeEncoder": "iso8601",
    "durationEncoder": "string",
    "callerEncoder": "short"
  },
  "outputPaths": [
    "stdout"
  ],
  "errorOutputPaths": [
    "stderr"
  ]
}

from_json

configJson, err := ioutil.ReadFile("./config.json")
if err != nil {
	panic(err)
}
var myConfig zap.Config
if err := json.Unmarshal(configJson, &myConfig); err != nil {
	panic(err)
}
logger, _ := myConfig.Build()

• Yamlファイルから作成するサンプル

config.yaml

level: "debug"
encoding: "json"
encoderConfig:
  messageKey: "Msg"
  levelKey: "Level"
  timeKey: "Time"
  nameKey: "Name"
  callerKey: "Caller"
  stacktraceKey: "St"
  levelEncoder: "capital"
  timeEncoder: "iso8601"
  durationEncoder: "string"
  callerEncoder: "short"
outputPaths:
  - "stdout"
errorOutputPaths:
  - "stderr"

from_yaml

configYaml, err := ioutil.ReadFile("./config.yaml")
if err != nil {
	panic(err)
}
var myConfig zap.Config
if err := yaml.Unmarshal(configYaml, &myConfig); err != nil {
	panic(err)
}
logger, _ := myConfig.Build()

項目一覧

Item	Type	Description	Key(for json/yaml)	Value(for json/yaml)
Level	AtomicLevel	有効なログレベル 必須 動的に変更可能で、変更するとこのConfigから生成されたすべてのLoggerに反映される	level	debug info warn error dpanic panic fatal
Development	bool	Devモード/Prdモード true:Devモード、false:Prdモード	development	true false
DisableCaller	bool	呼び出し元（ロギングしたファイル名と行番号）出力の有無 true:出力しない、false:出力する	disableCaller	true false
DisableStacktrace	bool	スタックトレース出力の有無 true:出力しない、false:出力する	disableStacktrace	true false
Sampling	*SamplingConfig	サンプリングの設定 詳細はSamplingConfigを参照	sampling	SamplingConfigを参照
Encoding	string	出力エンコーダ 必須 Console形式またはJson形式を選択可能	encoding	console json
EncoderConfig	EncoderConfig	表示に関わるエンコーダの設定 詳細はEncoderConfigを参照	encoderConfig	EncoderConfigを参照
OutputPaths	[]string	ログの出力先	outputPaths	任意のファイルパス stdout stderr
ErrorOutputPaths	[]string	zapの内部エラーの出力先	errorOutputPaths	任意のファイルパス stdout stderr
InitialFields	map[string]interface{}	初期フィールド 全てのLoggerにセットしたいフィールドがある場合などに利用できる	initialFields	任意のKey(string)とValue

SamplingConfig

サンプリングの設定を定義する構造体です。
これを定義すると、同じログレベルかつ同じメッセージのログを1秒間に出力できる数を制限でき、それによってCPU負荷やI/O負荷を抑制できます。

項目一覧

Item	Type	Description	Key(for json/yaml)	Value(for json/yaml)
Initial	int	最初のサンプリング上限数	initial	1以上の整数
Thereafter	int	以降のサンプリング上限数	thereafter	1以上の整数

例えば、first=3、thereafter=5でSamplingConfigを定義した状態でlogger.Info("sample")を1秒間に10回呼び出した場合、以下のような出力になります。

[1回目]	INFO sample <- すぐに出力
[2回目]	INFO sample <- すぐに出力
[3回目]	INFO sample <- すぐに出力
[4回目]	INFO sample <- 8回目と同じタイミングで出力
[5回目]	INFO sample <- 8回目と同じタイミングで出力
[6回目]	INFO sample <- 8回目と同じタイミングで出力
[7回目]	INFO sample <- 8回目と同じタイミングで出力
[8回目]	INFO sample <- すぐに出力
[9回目]	INFO sample <- 出力されない（次の出力タイミング(13番目)が来ない為）
[10回目]	INFO sample <- 出力されない（次の出力タイミング(13番目)が来ない為）

EncoderConfig

Json形式で出力する場合の各Key名と、ログレベル、Time、Duration、Caller（呼び出し元）の表示形式を決定するエンコーダの設定を定義する構造体。
各エンコーダは関数のエイリアスなので、これを満たす独自エンコーダを作成してConfigにセット→Buildすることで任意の表示形式にすることも可能です。

項目一覧

Item	Type	Description	Key(for json/yaml)	Value(for json/yaml)
MessageKey	string	Json形式時のメッセージに対するKey名 指定しない場合、メッセージ自体表示しない	messageKey	任意
LevelKey	string	Json形式時のログレベルに対するKey名 指定しない場合、ログレベル自体表示しない	levelKey	任意
TimeKey	string	Json形式時のロギング日時に対するKey名 指定しない場合、ロギング日時自体表示しない	timeKey	任意
NameKey	string	Json形式時のセグメントに対するKey名 指定しない場合、セグメント自体表示しない	nameKey	任意
CallerKey	string	Json形式時の呼び出し元に対するKey名 指定しない場合、呼び出し元自体表示しない	callerKey	任意
StacktraceKey	string	Json形式時のスタックトレースに対するKey名 指定しない場合、スタックトレース自体表示しない	stacktraceKey	任意
EncodeLevel	LevelEncoder	ログレベルの表示形式を決定するエンコーダ 詳細はLevelEncoderを参照	levelEncoder	LevelEncoderを参照
EncodeTime	TimeEncoder	Time型の表示形式を決定するエンコーダ 詳細はTimeEncoderを参照	timeEncoder	TimeEncoderを参照
EncodeDuration	DurationEncoder	Duration型の表示形式を決定するエンコーダ 詳細はDurationEncoderを参照	durationEncoder	DurationEncoderを参照
EncodeCaller	CallerEncoder	呼び出し元の表示形式を決定するエンコーダ 詳細はCallerEncoderを参照	callerEncoder	CallerEncoderを参照

LevelEncoder

ログレベルの表示形式を決定するエンコーダです。
実体はfunc(Level, PrimitiveArrayEncoder)のエイリアス。

エンコーダ一覧

Encoder	Description	Value(for json/yaml)
CapitalLevelEncoder	大文字で表示(INFOなど)	"capital"
CapitalColorLevelEncoder	色付きの大文字で表示	"capitalColor"
LowercaseColorLevelEncoder	色付きの小文字で表示(infoなど)	"color"
LowercaseLevelEncoder	小文字で表示	任意の文字列

TimeEncoder

Time型の表示形式を決定するエンコーダです。
実体はfunc(time.Time, PrimitiveArrayEncoder)のエイリアス。

エンコーダ一覧

Encoder	Description	Value(for json/yaml)
ISO8601TimeEncoder	ISO8601形式で表示	"iso8601" or "ISO8601"
EpochMillisTimeEncoder	ミリ秒単位のエポックタイムで表示	"millis"
EpochNanosTimeEncoder	ナノ秒単位のエポックタイムで表示	"nanos"
EpochTimeEncoder	秒単位のエポックタイムで表示	任意の文字列

DurationEncoder

Duration型の表示形式を決定するエンコーダです。
実体はfunc(time.Duration, PrimitiveArrayEncoder)のエイリアス。

エンコーダ一覧

Encoder	Description	Value(for json/yaml)
StringDurationEncoder	1h15m30sのような形式で表示	"string"
NanosDurationEncoder	ナノ秒で表示	"nanos"
SecondsDurationEncoder	秒単位で表示	任意の文字列

CallerEncoder

呼び出し元の表示形式を決定するエンコーダです。
実体はfunc(EntryCaller, PrimitiveArrayEncoder)のエイリアス。

エンコーダ一覧

Encoder	Description	Value(for json/yaml)
FullCallerEncoder	フルパスと行番号で表示	"full"
ShortCallerEncoder	パッケージ以降のパスと行番号で表示	任意の文字列

Option編

Optionに関する解説です。

Option

apply(*Logger)を持つインターフェースです。
Config#Buildで初期設定として定義したり、Logger#WithOptionsで設定を変更したLoggerを生成したりできます。

メソッド一覧

Optionとして設定できる（Optionを返す）主なメソッドの一覧です。

Method	Description
AddCaller	呼び出し元(パスと行番号)を出力する
AddCallerSkip	呼び出し元スタックのスキップ数を追加する
AddStacktrace	スタックトレースを出力する 引数には出力する最低ログレベルを指定
Development	Devモードにする
ErrorOutput	zapの内部エラーを出力する場所を指定する
Fields	フィールドを設定する

まとめ

とりあえずここでは一般的に使いそうなメソッドなどを中心にまとめました。
他にも独自のCoreやエンコーダを作ったり、ロギング時にHookして別処理を追加したり、ログをもっと細かいレベルでコントロールすることができそうなので、これらについてはまた別途アウトプットしたいと思います。