goでcontextual logging + structural loggingする小さなパッケージを作った

golang ctxlog

github.com

なんで作ったの？

ちょっとした作業をするのに欲しくなったから。特にcontextual loggingの部分が欲しい。 ぶっちゃけた話structural loggingはzapを使えばおしまいで良さそうだった。ただできそうなことが多すぎそうだったので絞った。

contextual loggingとstructural loggingの話は昔書いた（ただしpythonでの話で余分な情報がたくさん含まれている）。

さすがに丸投げだと悪いのでもう少しだけ説明する。

contextual logging ?

雑に言うとトップレベルの情報（あるいは上流の情報）を末端部分（あるいは下流）でも利用したいと言う時に使われる。

例えば以下のようなトップレベルの関数Fの呼び出しがあったとして、それが末端部分ではh0,h1のような関数呼び出しにつながるとする。ここで引数としては渡って来ない情報をh0,h1などのログに付加したいよねみたいな話。

例えば、APIサーバーなどを提供している時のrequestのIDやtracing IDなどはその最たるもの。

F() // tracingIDはここまでしか渡ってきていない
  g0()
    h0() // ここのログにもtracingIDを載せたくない？
    h1()
  g1()
    h2()
...

// でもこちらから呼ばれた場合には不要
Another()
  h0() // tracingIDは関係ないのだから付加させたくない

はい。

使いかた

以下のような形の関数の呼び出し関係のときに

f() // x-id
  g() // y-id (x-idは直接は渡されない)

以下のような出力を作ることができる。

{"level":"info","ts":1565388319.7551425,"caller":"main.go:29","msg":"start f","x-id":10,"y-id":20}
{"level":"info","ts":1565388319.7551734,"caller":"main.go:36","msg":"start g","x-id":10,"y-id":20,"y-id":20}
{"level":"info","ts":1565388319.7551854,"caller":"main.go:38","msg":"end g","x-id":10,"y-id":20,"y-id":20}
{"level":"info","ts":1565388319.755195,"caller":"main.go:31","msg":"end f","x-id":10,"y-id":20}
package main

import (
    "context"
    "log"

    "github.com/podhmo/ctxlog"
    "github.com/podhmo/ctxlog/zapctxlog"
)

func main() {
    if err := run(); err != nil {
        log.Fatal(err)
    }
}

func run() error {
    l := zapctxlog.MustNew()
    ctx, _ := ctxlog.Set(context.Background(), l).With("x-id", 10)
    return f(ctx)
}

func f(ctx context.Context) error {
    ctx, log := ctxlog.Get(ctx).With("y-id", 20)
    log.Info("start f")
    defer log.Info("end f")
    return g(ctx)
}

func g(ctx context.Context) error {
    ctx, log := ctxlog.Get(ctx).With("y-id", 20)
    log.Info("start g")
    defer log.Info("end g")
    return nil
}

contextにロガーを突っ込むのはなし？

個人的にはありだと想う。先程言った通りでcontextual loggingをやるにはなにかしらの情報を保持する存在が必要。それをcontextオブジェクト以外に渡すという形になると常にloggerも込みでバケツリレーが必要になる。またtracing IDなどはrequest scopeのもの。当然それを状態として保持するものもrequest scope（でしかないように使う）。

scopeが同じものなので渡しちゃうのが自然で手軽(厳密な意味でobject自体のlife cycleは違うかもしれない)。

注意点としてはcontextにロガーが含まれていない場合にnilパニックを起こすようなコードは書いてはダメということくらい。これはデフォルトではNoopLoggerが返ってくるので大丈夫。以下のような警告メッセージを出すことにした。

**CTXLOG WARNING*************************
ctxlog.Get is not found. please set logger, via ctxlog.Set()
****************************************

警告メッセージが微妙という話はある。

ctx, log := ctxlog.Get(ctx).With(...) は不格好じゃない？

With() の戻り値がちょっとだけ不格好なように観える。ctx,logは実はどちらも同じ値で *ctxlog.GetContext の型の値。なんでこのようにしたかという話。

まず context.Context だけを返した場合のことを考えてみる。これはLoggerのメソッドが使えない。不便。

次は *ctxlog.LotggerContext だけを返した場合。これは一見大丈夫なのだけれど。下方の関数を呼び出す際に渡し忘れが発生する可能性が出てきそうで良くない。例えばfからgの時に以下の様なコードになる。

func f(ctx context.Context) {
    // ctxと型が異なるので ctx = ctxlog.Get(ctx).With(...) とは書けない

    lctx := ctxlog.Get(ctx).With("z-id", 10)
    g(ctx) // 本来は g(lctx) が正しい
}

こういう微妙な事は考えたくない。 goの x, y := <val1>, <val2> という構文は特に単なる束縛を意味しておらずふつうに存在している変数に対しては代入として働くので引数として渡ってくるctxを上書きしてあげればOK。

func f(ctx context.Context) {
    ctx, log := ctxlog.Get(ctx).With("z-id", 10)
    g(ctx) // g(log) と渡してあげても動きはする
}

WithError

ただし↑のようなWith()の使いかたにした結果不具合が出る部分もある。戻り値が多値なので情報を付加しつつ出力みたいなことが１行でできなくなった。

// 以下のように書きたいがダメ
ctxlog.Get(ctx).With("z-id", 10).Info("hello")

これは安全のために諦めることにしたのだけれど、エラーだけは１行で書きたいことが多い。そんなわけで WithError() を用意した。

if err := doSomething(); err != nil {
    log.WithError(err).Info("oops")
}

追記:

  • ctxlog.Logger() から ctxlog.Get() に関数名を変更した。
  • ctxlog.WithLogger() から ctxlog.Set() に関数名を変更した。