Goメモ-493 (slogメモ-14)(カスタムログハンドラの作成 (1))

関連記事

Goメモ-477 (slogメモ-01)(基本的な使い方) - いろいろ備忘録日記

Goメモ-478 (slogメモ-02)(構造化ログの出力) - いろいろ備忘録日記

Goメモ-479 (slogメモ-03)(デフォルトロガー) - いろいろ備忘録日記

Goメモ-480 (slogメモ-04)(従来のlogパッケージとの連携) - いろいろ備忘録日記

Goメモ-482 (slogメモ-05)(テキスト形式のログ) - いろいろ備忘録日記

Goメモ-483 (slogメモ-06)(JSON形式のログ) - いろいろ備忘録日記

Goメモ-484 (slogメモ-07)(動的にログレベルを変更) - いろいろ備忘録日記

Goメモ-485 (slogメモ-08)(グループ (1)) - いろいろ備忘録日記

Goメモ-486 (slogメモ-09)(グループ (2)) - いろいろ備忘録日記

Goメモ-487 (slogメモ-10)(機密情報などのマスキング) - いろいろ備忘録日記

Goメモ-488 (slogメモ-11)(カスタムログレベル) - いろいろ備忘録日記

Goメモ-490 (slogメモ-12)(context.Contextとの連携) - いろいろ備忘録日記

Goメモ-491 (slogメモ-13)(io.Writerとの連携) - いろいろ備忘録日記

GitHub - devlights/blog-summary: ブログ「いろいろ備忘録日記」のまとめ

概要

以下、自分用のメモです。

今更ながら、Go 1.21で導入された log/slog を使ってみたりしています。

少しづつメモしていきます。今回はカスタムログハンドラの作成について。

slogで、カスタムログハンドラを作成する場合、フルスクラッチから作成するよりも既存のハンドラを元にして何らかの追加機能を付与するという形が一番多いと思います。今回はそのサンプルです。

尚、カスタムログハンドラを作成する際は以下の情報がとても参考になります。ただ、とても文章量が多い・・・。まだ全部見れていないです。

github.com

サンプル

main.go

package main

import (
    "context"
    "log/slog"
    "os"
    "runtime"
    "strconv"
    "sync"
    "time"
)

type (
    // counterHandler は、内部でログ出力回数をカウントし、その内容を出力するカスタムハンドラです。
    // ログ出力自体は、作成時に指定した元ハンドラに任せます。
    //
    // slogでカスタムハンドラを作成する場合, `slog.Handler` インターフェースを満たす必要があります。
    // `slog.Handler` インターフェースには以下のメソッドが定義されています。(https://pkg.go.dev/log/slog@go1.23.2#Handler)
    //
    //     - Enabled(context.Context, Level) bool
    //     - Handle(context.Context, Record) error
    //     - WithAttrs(attrs []Attr) Handler
    //     - WithGroup(name string) Handler
    //
    // コアとなる処理は `slog.Handler.Handle` メソッドです。
    // `go doc` にある通り、独自実装する場合は以下のルールに従うべきであると記載されています。
    //
    //     - If r.Time is the zero time, ignore the time.(r.Timeがゼロ時刻の場合は、時刻を無視する)
    //     - If r.PC is zero, ignore it.(r.PCがゼロの場合、無視する)
    //     - Attr's values should be resolved.(Attrの値は解決されるべき)
    //     - If an Attr's key and value are both the zero value, ignore the Attr. This can be tested with attr.Equal(Attr{}).(Attrのkeyとvalueの両方がゼロの場合、そのAttrは無視される。これは attr.Equal(Attr{}) でテスト可能)
    //     - If a group's key is empty, inline the group's Attrs.(グループのキーが空の場合、グループのAttrsをインライン化する)
    //     - If a group has no Attrs (even if it has a non-empty key), ignore it.(グループにAttrがない場合は (空でないキーがある場合でも)、無視する)
    //
    // 詳細な解説については [A Guide to Writing slog Handlers](https://github.com/golang/example/blob/master/slog-handler-guide/README.md) を参照。
    // (日本語訳を添えてあるものを [slog-handler-guide-ja.md](./slog-handler-guide-ja.md) として置いています。)
    //
    // 現実的に、フルカスタムのハンドラをゼロから自前で作成することはほぼ無いと思います。
    // 基本は、元から存在している何かのハンドラ(slog.JSONHandlerなど)を元にして、その上に独自の処理を付け加えることになります。
    //
    // その場合、ログ出力の部分は元ハンドラに移譲する形で完了するが、実装時に以下の点には注意する必要がある。
    //
    //     1. `WithAttrs`と`WithGroup`メソッドを上書きでメソッド定義しておかないと、カスタムハンドラをハンドラとして生成したロガーにて `Logger.With()` または `Logger.WithGroup()` を使ってロガーを複製した場合に属性が引き継がれない状態が発生する。
    //     2. 内部で何らかの状態を保持する必要がある場合は、複数のゴルーチンにて同時に呼び出されることを考慮してロックする。
    //     3. 2の件に加えて、`slog.Logger.With()` または `slog.Logger.WithGroup()` が利用されることが想定される場合は値やミューテックスをポインタで持っておく。（これらのメソッドではハンドラをコピーするため）
    //
    counterHandler struct {
        slog.Handler             // 内部で利用する元ハンドラ
        count        *int        // カウンタ
        mu           *sync.Mutex // ロック用
    }
)

func newHandler(handler slog.Handler) *counterHandler {
    var (
        count = 0
        mu    sync.Mutex
    )
    return &counterHandler{Handler: handler, count: &count, mu: &mu}
}

func (me *counterHandler) Handle(ctx context.Context, r slog.Record) error {
    me.mu.Lock()
    defer me.mu.Unlock()

    //
    // ミリ秒と呼び出し回数を出力
    //
    r.AddAttrs(slog.String("millis", time.Now().Format(".000")))
    *me.count++
    r.AddAttrs(slog.Int("count", *me.count))

    return me.Handler.Handle(ctx, r)
}

func (me *counterHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
    return &counterHandler{Handler: me.Handler.WithAttrs(attrs), count: me.count, mu: me.mu}
}

func (me *counterHandler) WithGroup(name string) slog.Handler {
    return &counterHandler{Handler: me.Handler.WithGroup(name), count: me.count, mu: me.mu}
}

func main() {
    var (
        level = &slog.LevelVar{}
        opt   = &slog.HandlerOptions{
            Level:       level,
            ReplaceAttr: replaceAttr,
        }
        writer  = os.Stderr
        handler = newHandler(slog.NewTextHandler(writer, opt))
        logger  = slog.New(handler)

        wg             sync.WaitGroup
        goroutineCount = runtime.NumCPU() * 2
        loopCount      = 2
    )
    logger.Info("Start", "NumCPU", runtime.NumCPU(), "goroutineCount", goroutineCount)

    //
    // 複数のゴルーチンから並行してログ出力
    //
    wg.Add(goroutineCount)
    for i := range goroutineCount {
        go func(logger *slog.Logger) {
            defer wg.Done()
            for i := range loopCount {
                logger.Info(strconv.Itoa(i))
            }
        }(logger.With("goroutine", i))
    }

    wg.Wait()
}

func replaceAttr(g []string, a slog.Attr) slog.Attr {
    if a.Key == slog.TimeKey {
        return slog.Attr{}
    }

    return a
}

実行すると以下のように出力されます。

Taskfile.yml

# https://taskfile.dev

version: '3'

tasks:
  default:
    cmds:
      - task: run
  run:
    cmds:
      - go run main.go

shell

$ task
task: [run] go run main.go
level=INFO msg=Start NumCPU=16 goroutineCount=32 millis=.552 count=1
level=INFO msg=0 goroutine=2 millis=.552 count=2
level=INFO msg=1 goroutine=2 millis=.552 count=3
level=INFO msg=0 goroutine=31 millis=.552 count=4
level=INFO msg=1 goroutine=31 millis=.552 count=5
level=INFO msg=0 goroutine=0 millis=.552 count=6
level=INFO msg=0 goroutine=12 millis=.552 count=7
level=INFO msg=0 goroutine=9 millis=.552 count=8
level=INFO msg=1 goroutine=9 millis=.553 count=9
level=INFO msg=0 goroutine=21 millis=.553 count=10
level=INFO msg=1 goroutine=21 millis=.553 count=11
level=INFO msg=0 goroutine=7 millis=.553 count=12
level=INFO msg=1 goroutine=7 millis=.553 count=13
level=INFO msg=0 goroutine=13 millis=.553 count=14
level=INFO msg=1 goroutine=13 millis=.553 count=15
level=INFO msg=0 goroutine=3 millis=.553 count=16
level=INFO msg=1 goroutine=3 millis=.553 count=17
level=INFO msg=0 goroutine=14 millis=.553 count=18
level=INFO msg=1 goroutine=14 millis=.553 count=19
level=INFO msg=0 goroutine=4 millis=.553 count=20
level=INFO msg=1 goroutine=4 millis=.553 count=21
level=INFO msg=1 goroutine=0 millis=.553 count=22
level=INFO msg=0 goroutine=1 millis=.553 count=23
level=INFO msg=1 goroutine=1 millis=.553 count=24
level=INFO msg=0 goroutine=15 millis=.553 count=25
level=INFO msg=1 goroutine=15 millis=.553 count=26
level=INFO msg=0 goroutine=16 millis=.553 count=27
level=INFO msg=1 goroutine=16 millis=.553 count=28
level=INFO msg=0 goroutine=22 millis=.553 count=29
level=INFO msg=1 goroutine=22 millis=.553 count=30
level=INFO msg=0 goroutine=17 millis=.553 count=31
level=INFO msg=1 goroutine=17 millis=.553 count=32
level=INFO msg=0 goroutine=23 millis=.553 count=33
level=INFO msg=1 goroutine=23 millis=.553 count=34
level=INFO msg=0 goroutine=18 millis=.553 count=35
level=INFO msg=1 goroutine=18 millis=.553 count=36
level=INFO msg=0 goroutine=24 millis=.553 count=37
level=INFO msg=1 goroutine=24 millis=.553 count=38
level=INFO msg=0 goroutine=19 millis=.553 count=39
level=INFO msg=1 goroutine=19 millis=.553 count=40
level=INFO msg=0 goroutine=25 millis=.553 count=41
level=INFO msg=1 goroutine=25 millis=.553 count=42
level=INFO msg=0 goroutine=26 millis=.553 count=43
level=INFO msg=1 goroutine=26 millis=.553 count=44
level=INFO msg=0 goroutine=20 millis=.553 count=45
level=INFO msg=1 goroutine=20 millis=.553 count=46
level=INFO msg=0 goroutine=6 millis=.553 count=47
level=INFO msg=1 goroutine=6 millis=.553 count=48
level=INFO msg=0 goroutine=29 millis=.553 count=49
level=INFO msg=1 goroutine=29 millis=.553 count=50
level=INFO msg=0 goroutine=27 millis=.553 count=51
level=INFO msg=1 goroutine=27 millis=.553 count=52
level=INFO msg=0 goroutine=30 millis=.553 count=53
level=INFO msg=1 goroutine=30 millis=.553 count=54
level=INFO msg=0 goroutine=8 millis=.553 count=55
level=INFO msg=0 goroutine=10 millis=.553 count=56
level=INFO msg=0 goroutine=11 millis=.554 count=57
level=INFO msg=0 goroutine=28 millis=.554 count=58
level=INFO msg=1 goroutine=12 millis=.554 count=59
level=INFO msg=0 goroutine=5 millis=.554 count=60
level=INFO msg=1 goroutine=5 millis=.554 count=61
level=INFO msg=1 goroutine=8 millis=.554 count=62
level=INFO msg=1 goroutine=10 millis=.554 count=63
level=INFO msg=1 goroutine=11 millis=.554 count=64
level=INFO msg=1 goroutine=28 millis=.554 count=65

try-golang/examples/slog at main · devlights/try-golang · GitHub

参考情報

• Structured Logging with slog
• log/slog
• A Guide to Writing slog Handlers
• awesome-slog
• Goのslog使い方まとめ
• Go1.21で登場したlog/slogパッケージのパフォーマンスを徹底解説！！
• Go1.21 log/slogパッケージ超入門
• Go公式の構造化ロガー（として提案されている）slogを触ってみたメモ
• slog を触る(Group, Context)
• 構造化ログと実装 -Goのslogによる実践-
• try-golang slog examples

Goのおすすめ書籍

初めてのGo言語 ―他言語プログラマーのためのイディオマティックGo実践ガイド

実用 Go言語 ―システム開発の現場で知っておきたいアドバイス

Go言語による並行処理

Go言語 100Tips ありがちなミスを把握し、実装を最適化する impress top gearシリーズ

Goならわかるシステムプログラミング 第2版

効率的なGo ―データ指向によるGoアプリケーションの性能最適化

---

過去の記事については、以下のページからご参照下さい。

• ブログ 「いろいろ備忘録日記」の記事まとめ | ブログ「いろいろ備忘録日記」のまとめ

サンプルコードは、以下の場所で公開しています。

• GitHub - devlights/try-golang: This is my TUTORIAL project for golang.
• GitHub - devlights/try-python: This is my TUTORIAL project for Python.
• GitHub - devlights/try-csharp: This is my TUTORIAL project for C#.