Closed6
ipfs/go-log を試してみる
ピン留めされたアイテム
Spiegelブログ記事にした。
SpiegelBluesky の API にアクセスするための公式 Go パッケージがあるのだが
この中で使われている logger がこれ。
これって IPFS の Go 実装の中で使われている logger で zap のラッパーになっているようだ。
個人的にはシンプルで高速な zerolog 推しなのだが，今どきの gRPC や分散システムでは大抵 zap なので，重い腰を上げて zap および ipfs/go-log について調べてみる。
このスクラップは，あとでブログ記事にまとめる予定。
Spiegelzap を使ってみる
早速，ログを出力する簡単なコード書いてみる。
sample1.go
package main
import (
"os"
"github.com/goark/errs"
"go.uber.org/zap"
)
func checkFileOpen(path string) error {
file, err := os.Open(path)
if err != nil {
return errs.New(
"file open error",
errs.WithCause(err),
errs.WithContext("path", path),
)
}
defer file.Close()
return nil
}
func main() {
logger := zap.NewExample()
defer logger.Sync()
path := "not-exist.txt"
if err := checkFileOpen("not-exist.txt"); err != nil {
logger.Error("error in checkFileOpen function", zap.Error(err), zap.String("file", path))
}
}
checkFileOpen() 関数でファイルオープンを試みる。失敗した場合は error を返すが，拙作の goark/errs パッケージで構造化している。 main 関数では checkFileOpen() 関数の引数に意図的に存在しないファイルを指定し，エラーを発生させてログに出力している。
これを実行すると以下のログ出力が得られる。
{"level":"error","msg":"error in checkFileOpen function","error":"file open error: open not-exist.txt: no such file or directory","errorVerbose":"{\"Type\":\"*errs.Error\",\"Err\":{\"Type\":\"*errors.errorString\",\"Msg\":\"file open error\"},\"Context\":{\"function\":\"main.checkFileOpen\",\"path\":\"not-exist.txt\"},\"Cause\":{\"Type\":\"*fs.PathError\",\"Msg\":\"open not-exist.txt: no such file or directory\",\"Cause\":{\"Type\":\"syscall.Errno\",\"Msg\":\"no such file or directory\"}}}","file":"not-exist.txt"}
うん。ワケワカメ（笑） 出力を jq コマンドで整形してみよう。
$ go run sample1.go | jq .
{
"level": "error",
"msg": "error in checkFileOpen function",
"error": "file open error: open not-exist.txt: The system cannot find the file specified.",
"errorVerbose": "{\"Type\":\"*errs.Error\",\"Err\":{\"Type\":\"*errors.errorString\",\"Msg\":\"file open error\"},\"Context\":{\"function\":\"main.checkFileOpen\",\"path\":\"not-exist.txt\"},\"Cause\":{\"Type\":\"*fs.PathError\",\"Msg\":\"open not-exist.txt: The system cannot find the file specified.\",\"Cause\":{\"Type\":\"syscall.Errno\",\"Msg\":\"The system cannot find the file specified.\"}}}",
"file": "not-exist.txt"
}
errorVerbose の項目には error を %+v 書式で出力した結果が入っていると思われる。拙作の goark/errs は %+v を指定すると JSON 形式の文字列を返すようにしている。のだが，これだとただの文字列として出力されているので「構造化」ログになっていない。困った。
Spiegelzapobject モジュールを作ってみた。
前節の問題に対処するために goark/errs のサブパッケージとして zapobject パッケージを作ってみた。こんな感じにインポートできる。
import "github.com/goark/errs/zapobject"
zapobject パッケージは errs パッケージとは別のモジュールとして定義している（ので，元の errs パッケージの依存関係等を汚さない）。今のところ，中身はこんな感じに簡単に書いている。
github.com/goark/errs/zapobject/zapobject.go
package zapobject
import (
"fmt"
"sort"
"github.com/goark/errs"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
type ErrObject struct {
Err error
}
// New wrapped error instance in ErrObject.
func New(err error) ErrObject {
return ErrObject{Err: err}
}
// MarshalLogObject method is object marshaler for go.uber.org/zap.
func (e ErrObject) MarshalLogObject(enc zapcore.ObjectEncoder) error {
if e.Err == nil {
return nil
}
var ee *errs.Error
if errs.As(e.Err, &ee) {
enc.AddString("type", fmt.Sprintf("%T", ee.Err))
enc.AddString("msg", ee.Err.Error())
if ee.Cause != nil {
if err := enc.AddObject("cause", New(ee.Cause)); err != nil {
return err
}
}
if len(ee.Context) > 0 {
keys := make([]string, 0, len(ee.Context))
for k := range ee.Context {
keys = append(keys, k)
}
sort.Strings(keys)
enc.OpenNamespace("context")
for _, k := range keys {
_ = enc.AddReflected(k, ee.Context[k])
}
}
} else {
enc.AddString("type", fmt.Sprintf("%T", e.Err))
enc.AddString("msg", e.Err.Error())
if errList := errs.Unwraps(e.Err); len(errList) > 0 {
if len(errList) == 1 {
return enc.AddObject("cause", New(errList[0]))
}
elist := make([]ErrObject, 0, len(errList))
for i, e := range errList {
elist[i] = New(e)
}
zap.Objects("causes", elist).AddTo(enc)
}
}
return nil
}
これを使って error インスタンスをラップすることにより， goark/errs パッケージで作ったインスタンスに限らず，任意の error インスタンスで Unwrap メソッドの挙動に従って内容を構造化できる。
では，これを使って前節のコードを書き替えてみよう。 main() 関数のみ挙げておく。
sample2.go
func main() {
logger := zap.NewExample()
defer logger.Sync()
path := "not-exist.txt"
if err := checkFileOpen("not-exist.txt"); err != nil {
logger.Error("error in checkFileOpen function", zap.Object("error", zapobject.New(err)), zap.String("file", path))
}
}
zap.Error() ではなく zap.Object() を使っている点に注意。これを実行して jq で整形するとこうなった。
$ go run sample2.go | jq .
{
"level": "error",
"msg": "error in checkFileOpen function",
"error": {
"type": "*errors.errorString",
"msg": "file open error",
"cause": {
"type": "*fs.PathError",
"msg": "open not-exist.txt: The system cannot find the file specified.",
"cause": {
"type": "syscall.Errno",
"msg": "The system cannot find the file specified."
}
},
"context": {
"function": "main.checkFileOpen",
"path": "not-exist.txt"
}
},
"file": "not-exist.txt"
}
今度はちゃんと error の内部構造が示されている。うんうん。
Spiegelgo-log を試す
それじゃあ，いよいよ ipfs/go-log を使ってみよう。さきほどの main() 関数を以下のように書き換える。checkFileOpen() 関数は中身同じなので省略するね。
sample3.go
package main
import (
"os"
"github.com/goark/errs"
"github.com/goark/errs/zapobject"
"github.com/ipfs/go-log/v2"
)
func checkFileOpen(path string) error {
...
}
func main() {
logger := log.Logger("sample")
path := "not-exist.txt"
if err := checkFileOpen("not-exist.txt"); err != nil {
logger.Errorw("error in checkFileOpen function", "error", zapobject.New(err), "file", path)
}
}
では，実行。
$ go run sample3.go
2023-05-17T14:38:20.815+0900 ERROR sample sample3/sample3.go:30 error in checkFileOpen function {"error": {"type": "*errors.errorString", "msg": "file open error", "cause": {"type": "*fs.PathError", "msg": "open not-exist.txt: The system cannot find the file specified.", "cause": {"type": "syscall.Errno", "msg": "The system cannot find the file specified."}}, "context": {"function": "main.checkFileOpen", "path": "not-exist.txt"}}, "file": "not-exist.txt"}
うっ。なんか変な出方してる。ドキュメントを見ると環境変数で出力レベルや出力先や出力フォーマットを指定するらしい。
それを踏まえて改めて実行。
$ export GOLOG_OUTPUT="stdout"
$ export GOLOG_LOG_FMT="json"
$ go run sample3.go
{"level":"error","ts":"2023-05-17T14:38:20.815+0900","logger":"sample","caller":"sample3/sample3.go:30","msg":"error in checkFileOpen function","error":{"type":"*errors.errorString","msg":"file open error","cause":{"type":"*fs.PathError","msg":"open not-exist.txt: The system cannot find the file specified.","cause":{"type":"syscall.Errno","msg":"The system cannot find the file specified."}},"context":{"function":"main.checkFileOpen","path":"not-exist.txt"}},"file":"not-exist.txt"}
{
"level": "error",
"ts": "2023-05-17T14:38:20.815+0900",
"logger": "sample",
"caller": "sample3/sample3.go:30",
"msg": "error in checkFileOpen function",
"error": {
"type": "*errors.errorString",
"msg": "file open error",
"cause": {
"type": "*fs.PathError",
"msg": "open not-exist.txt: The system cannot find the file specified.",
"cause": {
"type": "syscall.Errno",
"msg": "The system cannot find the file specified."
}
},
"context": {
"function": "main.checkFileOpen",
"path": "not-exist.txt"
}
},
"file": "not-exist.txt"
}
標準出力だけ指定したのに標準エラー出力にも出てるなぁ。あと caller とか変な項目が付いている。あとは概ね問題なしかな。
log.Logger() 関数で取得する logger の中身はこんな内容になっている。
github.com/ipfs/go-log/log.go
// ZapEventLogger implements the EventLogger and wraps a go-logging Logger
type ZapEventLogger struct {
zap.SugaredLogger
// used to fix the caller location when calling Warning and Warningf.
skipLogger zap.SugaredLogger
system string
}
そう， SugaredLogger なのよ。まぁ Desugar して使えるのでお好みでどうぞ。
logger.Desugar().Error("error in checkFileOpen function", zap.Object("error", zapobject.New(err)), zap.String("file", path))
アプリケーションによっては環境変数じゃなくてコードで出力を制御したいかもしれない。その場合は以下のように設定を変更できる。
sample3b.go
func main() {
cfg := log.GetConfig()
cfg.Format = log.JSONOutput
cfg.Stderr = false
cfg.Stdout = true
cfg.Level = log.LevelDebug
log.SetupLogging(cfg)
logger := log.Logger("sample")
path := "not-exist.txt"
if err := checkFileOpen("not-exist.txt"); err != nil {
logger.Desugar().Error("error in checkFileOpen function", zap.Object("error", zapobject.New(err)), zap.String("file", path))
}
}
これを実行すると。
$ go run sample3b.go | jq .
{
"level": "error",
"ts": "2023-05-17T14:54:17.270+0900",
"logger": "sample",
"caller": "sample3b/sample3b.go:37",
"msg": "error in checkFileOpen function",
"error": {
"type": "*errors.errorString",
"msg": "file open error",
"cause": {
"type": "*fs.PathError",
"msg": "open not-exist.txt: The system cannot find the file specified.",
"cause": {
"type": "syscall.Errno",
"msg": "The system cannot find the file specified."
}
},
"context": {
"function": "main.checkFileOpen",
"path": "not-exist.txt"
}
},
"file": "not-exist.txt"
}
となった。今度は標準エラー出力には出てないな。
Spiegelcaller を外したい場合は
logger := log.Logger("sample").Desugar().WithOptions(zap.WithCaller(false)).Sugar()
とかすればいいらしい。ただし，この場合の logger は log.ZapEventLogger ではなく zap.SugaredLogger になる。まぁ，実用上の問題はないけど。
このスクラップは2023/05/21にクローズされました