Go slog の JSON Handler で入れ子の出力をする

slog の基本

Go1.21 から公式の標準ライブラリに構造化ログを出力可能な slog が追加されました。

呼び出し方

デフォルトで時刻やログレベルが付与されます。 比較のため、fmt でも出力します

fmt.Println("Hello, World!")
slog.Info("Hello, World!")
slog.InfoContext(ctx, "Hello, World!")

出力

Hello, World!
2024/04/13 13:30:48 INFO Hello, World!
2024/04/13 13:30:48 INFO Hello, World!

コード全文

package main

import (
    "context"
    "fmt"
    "log/slog"
)

func main() {
    fmt.Println("Hello, World!")
    slog.Info("Hello, World!")
    ctx := context.TODO()
    slog.InfoContext(ctx, "Hello, World!")
}

追加の情報を付与

key: value pair をログに付与することができます

slog.Info("Hello, World!", slog.Int("line", 9), slog.String("file", "main.go"))
slog.InfoContext(ctx, "Hello, World!", slog.Int("line", 11), slog.String("file", "main.go"))

出力

2024/04/13 13:39:06 INFO Hello, World! line=9 file=main.go
2024/04/13 13:39:06 INFO Hello, World! line=11 file=main.go

コード全体

package main

import (
    "context"
    "log/slog"
)

func main() {
    slog.Info("Hello, World!", slog.Int("line", 9), slog.String("file", "main.go"))
    ctx := context.TODO()
    slog.InfoContext(ctx, "Hello, World!", slog.Int("line", 11), slog.String("file", "main.go"))
}

JSON 形式で出力

出力の形式は handller で調整可能で、デフォルトでは TextHandler が使われます。

実用上便利なことが多いので、実際の開発では JSON Handler はよく使われます

func main() {
    jsonHandler := slog.NewJSONHandler(os.Stdout, nil)
    logger := slog.New(jsonHandler)
    ctx := context.TODO()

    logger.Info("Hello, World!", slog.Int("line", 15), slog.String("file", "main.go"))
    logger.InfoContext(ctx, "Hello, World!", slog.Int("line", 16), slog.String("file", "main.go"))
}

出力

{"time":"2024-04-13T13:53:07.414249+09:00","level":"INFO","msg":"Hello, World!","line":15,"file":"main.go"}
{"time":"2024-04-13T13:53:07.414599+09:00","level":"INFO","msg":"Hello, World!","line":16,"file":"main.go"}

コード全体

package main

import (
    "context"
    "os"

    "log/slog"
)

func main() {
    jsonHandler := slog.NewJSONHandler(os.Stdout, nil)
    logger := slog.New(jsonHandler)
    ctx := context.TODO()

    logger.Info("Hello, World!", slog.Int("line", 15), slog.String("file", "main.go"))
    logger.InfoContext(ctx, "Hello, World!", slog.Int("line", 16), slog.String("file", "main.go"))
}

余談ではありますが、比較すると、人間的には(個人的には) Text の方が読みやすいと思いました

# TextHandler
2024/04/13 13:39:06 INFO Hello, World! line=11 file=main.go
# JSONHandler
{"time":"2024-04-13T13:50:21.753606+09:00","level":"INFO","msg":"Hello, World!","line":15,"file":"main.go"}

slog の AddSource Option を探索

slog.NewJSONHandler の第2引数には Option を渡せます。 AddSource Option は Stacktrace まではいきませんが、コードの場所は教えてくれます。

...
    jsonHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        AddSource: true,
    })
    logger := slog.New(jsonHandler)
...

出力

{"time":"2024-04-13T13:56:09.692728+09:00","level":"INFO","source":{"function":"main.main","file":"/Users/atsuhiro.uchida/dev/playground/go-slog-playground/main.go","line":15},"msg":"Hello, World!"}

コード全体

package main

import (
    "os"

    "log/slog"
)

func main() {
    jsonHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        AddSource: true,
    })
    logger := slog.New(jsonHandler)

    logger.Info("Hello, World!")
}

どのファイルのどの関数で、何行目か、出力されてます。 ちなみに、 build しても source map の情報は維持されているようです

% go build -o main
% ./main 
{"time":"2024-04-13T14:04:38.670391+09:00","level":"INFO","source":{"function":"main.main","file":"/Users/atsuhiro.uchida/dev/playground/go-slog-playground/main.go","line":15},"msg":"Hello, World!"}

入れ子で出力する

struct の場合

構造体を出力したい場合は、json タグをつければ出力されます

package main

import (
    "os"

    "log/slog"
)

type Address struct {
    City  string `json:"city"`
    State string `json:"state"`
}

type User struct {
    Name    string   `json:"name"`
    Age     int      `json:"age"`
    Address *Address `json:"address,omitempty"`
}

func main() {
    jsonHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        AddSource: true,
    })
    logger := slog.New(jsonHandler)
    u := &User{
        Name: "Alice",
        Age:  25,
        Address: &Address{
            City:  "San Francisco",
            State: "CA",
        },
    }

    logger.Info("Hello, World!", "user", u)
}

出力

{"time":"2024-04-13T14:17:13.399365+09:00","level":"INFO","source":{"function":"main.main","file":"/Users/atsuhiro.uchida/dev/playground/go-slog-playground/main.go","line":34},"msg":"Hello, World!","user":{"name":"Alice","age":25,"address":{"city":"San Francisco","state":"CA"}}}

見づらいので整えると、以下のように出力が得られていることがわかります

{
  "time": "2024-04-13T14:17:13.399365+09:00",
  "level": "INFO",
  "source": {
    "function": "main.main",
    "file": "/Users/atsuhiro.uchida/dev/playground/go-slog-playground/main.go",
    "line": 34
  },
  "msg": "Hello, World!",
  "user": {
    "name": "Alice",
    "age": 25,
    "address": { "city": "San Francisco", "state": "CA" }
  }
}

ちなみに json タグがない場合、struct のフィールド名が key として使われます

// タグをなくす
type Address struct {
    City  string
    State string
}


func main() {
...
    logger.Info("Hello, World!", "user", u)
}

出力

{"time":"2024-04-13T14:36:16.765509+09:00","level":"INFO","source":{"function":"main.main","file":"/Users/atsuhiro.uchida/dev/playground/go-slog-playground/main.go","line":34},"msg":"Hello, World!","user":{"name":"Alice","age":25,"address":{"City":"San Francisco","State":"CA"}}}

コード全体

package main

import (
    "os"

    "log/slog"
)

type Address struct {
    City  string
    State string
}

type User struct {
    Name    string   `json:"name"`
    Age     int      `json:"age"`
    Address *Address `json:"address,omitempty"`
}

func main() {
    jsonHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        AddSource: true,
    })
    logger := slog.New(jsonHandler)
    u := &User{
        Name: "Alice",
        Age:  25,
        Address: &Address{
            City:  "San Francisco",
            State: "CA",
        },
    }

    logger.Info("Hello, World!", "user", u)
}

*"City", "State" と、先頭が大文字になっている(フィールド名が使われている)

group で出力する

同じ出力を slog.Group を使って再現できます。実際は struct なら group は使わず直接渡した方が楽です。

package main

import (
    "os"

    "log/slog"
)

func main() {
    jsonHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        AddSource: true,
    })
    logger := slog.New(jsonHandler)

    logger.Info(
        "Hello, World!",
        slog.Group(
            "user",
            slog.String("name", "Alice"),
            slog.Int("age", 25),
            slog.Group(
                "address",
                slog.String("city", "San Francisco"),
                slog.String("state", "CA"),
            ),
        ),
    )
}
{"time":"2024-04-13T14:26:48.645613+09:00","level":"INFO","source":{"function":"main.main","file":"/Users/atsuhiro.uchida/dev/playground/go-slog-playground/main.go","line":15},"msg":"Hello, World!","user":{"name":"Alice","age":25,"address":{"city":"San Francisco","state":"CA"}}}

余談

公式 GoDoc 曰く、

logger.LogAttrs(ctx, slog.LevelInfo, "hello", slog.Int("count", 3))

と呼ぶことが最も効率がいいようです。 LogLevel の指定は面倒なので、プロジェクトの中でこれで統一するなら、snippet を用意したいなと思いました。