GoのロギングライブラリZapを試す

はじめに

GoのLogライブラリは標準のものを使うことが多かったのですが、構造化したりするのがちょっと大変だったので、より高機能で使い勝手がよいものを試してみたくなってZapというのをどこかで見かけたのを思い出して、ちょっと試してみようと思います。
ここでは、コアな設定などは行わず先ずはプリセットの設定などを利用して、Quick Startを参考にしたコードを動かし足がかりにしながら、少しだけ深堀りして学んで行きたいと思います。

Zapとは

タイトルの通り、Goのロギングライブラリです。GitHubを見ているかぎり速さを売りにしているみたいです。1.x系では破壊的変更が行われないことが明記されています(おそらく普通にセマンティクスバージョニングだと思います)。また、サポートに関しては過去2つ分のマイナーバージョンまでサポートがされているみたいです。
ログのスタイルとしては構造化されているスタイルと単にprintfスタイルのAPIが提供されているみたいです。

動かしてみる

環境

今回の動作環境はこちら

$ uname -srvmpio
Linux 5.4.0-100-generic #113-Ubuntu SMP Thu Feb 3 18:43:29 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

$ lsb_release -a
LSB Version:    core-11.1.0ubuntu2-noarch:security-11.1.0ubuntu2-noarch
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.3 LTS
Release:    20.04
Codename:   focal

$ go version
go version go1.17.7 linux/amd64

プロジェクトの初期化&Zapのインストール

先ずはプロジェクトの初期化からします。

$ mkdir zap-example && cd zap-example
$ go mod init zap-exampe

次にプロジェクトにZapのインストールを行います。

$ go get -u go.uber.org/zap
go get: added go.uber.org/atomic v1.9.0
go get: added go.uber.org/multierr v1.7.0
go get: added go.uber.org/zap v1.21.0

これで下準備は完了です。

何はともあれログを出力してみる

ひとまずGitHubのQuick Startを参考にログを出力してみます。
以下のコードを記述します。

package main

import (
    "go.uber.org/zap"
    "time"
)

func main() {
    logger, _ := zap.NewProduction()
    defer logger.Sync()

    sugar := logger.Sugar()
    sugar.Infow("This is my first Log with Zap",
        "int num", 3,
        "Time", time.Now(),
        "String", "Hello, Zap",
    )
}

もろもろ気になることはありますが、実行してみます。

$ go run main.go
{"level":"info","ts":1645328356.9622054,"caller":"zap-example/main.go:14","msg":"This is my first Log with Zap","int num":3,"Time":1645328356.9622047,"String":"Hello, Zap"}

いい感じに出力されました。

ちょっとコードを詳細に見ていきます。

ZapのLoggerプリセット

まず、Zapを使うためプリセットの設定がいくつ用意されています。上記のコードではzap.NewProduction()などで設定済みのロガーを取得することができます。
このプリセットはfunc NewDevelopmentfunc NewProductionfunc NewExamplefunc NewNopが用意されておりそれぞれログの出力レベルと出力の形式が異なっています。

すでに出力していますがNewProductionを利用した場合は、ログがJson形式で出力されよりツールで利用されることを想定したログが出力されます。また、ここでのログレベルはInfoレベルになり標準エラーに出力されるようです。
これは、NewProductionConfig().Build(...Option)のショートカットとなっているようです。

次にNewDevelopmentを利用した場合以下のような出力になります。

$ go run main.go
2022-02-20T12:49:50.559+0900    INFO    zap-example/main.go:14  This is my first Log with Zap   {"int num": 3, "Time": "2022-02-20T12:49:50.559+0900", "String": "Hello, Zap"}

ログ出力はよりヒューマンリーダブルな形で出力され、更にDebugレベルでのログ出力になります。 こちらも標準エラーにログが出力されます。

NewExampleを利用した場合は以下のような出力になります。

$ go run main.go
{"level":"info","msg":"This is my first Log with Zap","int num":3,"Time":"2022-02-20T13:05:35.718+0900","String":"Hello, Zap"}

こちらはZapをちょっと試したい時ときに利用されるもののようです。諸々が事前にわかりきっている(ドキュメントには決定論的?と書かれていました)環境で利用されるもので、時間などが省略されたより短いログ出力になります。こちらも出力レベルはDebugになるようです。

最後に、NewNopを利用した場合の出力です。

$ go run main.go

こちらはログ出力を全く行わないロガーで、ユーザが定義したHooksなども実行されません。
こちらは、WithOptions関数などで、Coreやエラーアウトプットを置き換えることでログ出力を行うことが可能になるようです。
(おそらく、性能などの関心で全くログ出力を行わない場合やマニュアルでログを設定したい場合に利用されるものだと個人的に理解しています)

defer logger.Sync()

ロガーを取得した後のdefer logger.Sync()ですが、これはアプリケーション終了時にすべてのログを出力してくれるようです。

Sugar

そして、個人的に最も気になったsugar := logger.Sugar()このSugarはZapのLoggerラッパーでLoggerを生で使うよりはほんの少し遅いもののより人間が使いやすい形に設計されているようです。後述しますが、suger.Infow()などの関数はSugarの方で提供されているみたいです。
このブログでは先ずはSugarを使って、ログ出力するところにフォーカスして進めます。

ログ出力

ログ出力の部分です。

sugar.Infow("This is my first Log with Zap",
    "int num", 3,
    "Time", time.Now(),
    "String", "Hello, Zap",
)

前述の通りZapは構造化されたログの形式とprintfスタイルのログ出力両方をサポートしています。
上記の用に〇〇w()関数(func (*SugaredLogger) Infow func (*SugaredLogger) Debugwfunc (*SugaredLogger) Errorwfunc (*SugaredLogger) Fatalw等)というようなwが着く関数は第一引数にメッセージを受け取り第二引数以降はkey-valueの形で構造化されるログを受け取ります。

printfスタイルのログを出力する場合は関数の後にfが着く以下のような関数を利用することで行えます。

sugar.Infof("Hello, %s", "World")

出力結果

{"level":"info","ts":1645332593.3569844,"caller":"zap-example/main.go:20","msg":"Hello, World"}

構造化されたスタイルのログ出力を行う場合でマイクロ秒レベルのパフォーマンスが求められる場合は以下のように事前に型を指定してkey-valueでわたしてやることでより低コストでログ出力を行えるようです。

sugar.Infow("This is my first Log with Zap",
    zap.Int("int num", 3),
    zap.Time("Time", time.Now()),
    zap.String("String", "Hello, Zap"),
)