Go言語

slogのドキュメントを読み込む(和訳)

goの新しい構造化ログ slog パッケージ のドキュメントを読み込み内容を和訳したものです。

概要

slogパッケージは構造化されたロギングを提供し、ログレコードにはメッセージ、重大度、key-valueのペアで表現される様々な属性を含む。

Logger 型を定義していて、これはイベントレポートのための様々なメソッドを提供する。(Logger.InfoLogger.Error など)

Logger は Handler に関連付いている。Logger 出力メソッドは メソッドの引数からRecord を作成し、Handlerにわたす。HandlerはどのようにRecordを扱うかを決定する。トップレベル関数(InfoError など)からアクセス可能なデフォルトLoggerが用意されていて、このトップレベル関数は対応する Logger メソッドを呼び出す。

// logger.go
// A Logger records structured information about each call to its
// Log, Debug, Info, Warn, and Error methods.
// For each call, it creates a Record and passes it to a Handler.
//
// To create a new Logger, call [New] or a Logger method
// that begins "With".
type Logger struct {
	handler Handler // for structured logging
}

// handler.go
type Handler interface {
	Enabled(context.Context, Level) bool
	Handle(context.Context, Record) error
	WithAttrs(attrs []Attr) Handler
	WithGroup(name string) Handler
}

ログレコードは時間とレベル、メッセージ、key-valueのペアから成り、キーは文字列、値は any 型。

例: slog.Info("hello", "count", 3)

これは、「呼び出した時間」、「Infoレベル」、「"hello"というメッセージ」、「キー:"count"、値: 3」のレコードを作る。トップレベル関数Info はデフォルトLoggerの Logger.Info メソッドを呼び出す。加えて、Debug, Warn , Error レベルのメソッドやログレベルを引数として受け取るLogger.Log メソッドもある。これらのメソッドには、デフォルトLoggerを使う対応するトップレベル関数がある。

デフォルトのhandlerはログレコードのメッセージ、時刻、レベル、その他属性の書式を整えて、logパッケージにわたす。(logパッケージはslogとは別の標準パッケージ)

2022/11/08 15:28:26 INFO hello count=3

出力形式を制御するには、Handlerを変える必要がある。下記のコードは slog.New 関数を使って構造化されたレコードをテキスト形式で標準エラーに書き出す TextHandler を持つ loggerを生成している。

TextHandlerの出力は key=value の列。

logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
logger.Info("hello", "count", 3) // => time=2022-11-08T15:28:26.000-05:00 level=INFO msg=hello count=3

JSONHandlerを使うとJSON形式の出力になる。

logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
logger.Info("hello", "count", 3) // => {"time":"2022-11-08T15:28:26.000000000-05:00","level":"INFO","msg":"hello","count":3}

サンプルコード: Go Playground

TextHandlerもJSONHandlerも HandlerOption で細かな設定が可能(ログ出力の最低レベルの指定やファイルの行数出力などなど)。コンストラクタ(NewTextHandler, NewJSONHandler ) の第二引数にHandlerOptionを渡せばOK。

slog.Info , slog.Error などを呼び出したときのログ出力形式をカスタマイズしたければ、SetDefault でデフォルトのLoggerを変更すればよい。デフォルトの Logger は トップレベル関数(Info, Error , Debug など)で使われるLogger。

// Default returns the default Logger.
func Default() *Logger { return defaultLogger.Load().(*Logger) }

// SetDefault makes l the default Logger.
// After this call, output from the log package's default Logger
// (as with [log.Print], etc.) will be logged at LevelInfo using l's Handler.
func SetDefault(l *Logger) {
	defaultLogger.Store(l)

	if _, ok := l.Handler().(*defaultHandler); !ok {
		capturePC := log.Flags()&(log.Lshortfile|log.Llongfile) != 0
		log.SetOutput(&handlerWriter{l.Handler(), LevelInfo, capturePC})
		log.SetFlags(0) // we want just the log message, no time or location
	}
}

// Error calls Logger.Error on the default logger.
func Error(msg string, args ...any) {
	Default().log(nil, LevelError, msg, args...)
}

// ErrorContext calls Logger.ErrorContext on the default logger.
func ErrorContext(ctx context.Context, msg string, args ...any) {
	Default().log(ctx, LevelError, msg, args...)
}

多くのログ呼び出しで共通な属性もある。例えば、サーバーへのリクエストのURLやトレースできる識別子をすべてのログイベントに含めたいことがある。そのようなとき、すべてのログ呼び出しに繰り返し属性を追加するのではなくLogger.With を使って属性を含むロガーを生成できる。

applogger := logger.With("url", req.URL)

With への引数はLogger.Info などと同じように key-value のペア。With で作られたロガーは元のロガーと同じ Handler を使い、追加した属性(例では"url")がすべてのログ呼び出し時に出力される。

ヨノ

おそらく、リクエストURL、UserID、セッションID、HTTP メソッドなど共通項目の出力させたいときに使うのでしょう

Levels

Level はログイベントの重要度を表す integer。levelパッケージには一般的なログレベルの定数が定義されている。

アプリケーションでは、特定のレベル以上のときのみログメッセージをを出力したいだろう。よくある設定の1つは、Info以上のメッセージを出力してデバッグログは必要になるまで抑制するもの。組み込みのハンドラーではログ出力する最低レベルを HandlerOptions.Level で設定できる。通常、プログラムの main 関数でこの設定を行う。デフォルトの最低レベルはInfo。

HandlerOptions.Level フィールドで設定したレベルは、ハンドラーのライフタイムを通じて固定される。LevelVar で設定すると動的にログレベルを変更できる。LevelVar はログレベルを保持していて複数のゴルーチンから安全に読み書き可能になっている。
ログレベルをプログラム全体から動的に変更するためには、まずグローバルな LevelVar を初期化する。

var programLevel = new(slog.LevelVar) // Info by default

そして、このLevelVar をハンドラーのコンストラクタに渡す。

h := slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: programLevel})
slog.SetDefault(slog.New(h))

これで1行でログレベルを動的に変更できる。

programLevel.Set(slog.LevelDebug)

サンプルコード (Go Playground)

Groups

属性はグループにまとめることができる。グループには、まとめた属性を修飾するための名前がある。この修飾がどのように表示されるかはハンドラーに依存する。TextHandlerはグループ名と属性名を「.(ドット)」で区切る。JSONHandlerはグループ名をキーとして、各グループを個別のJSONオブジェクトとして扱う。

グループ属性を作るには Group を使う。

slog.Group("request", "method", r.Method, "url", r.URL)

出力は次のようになる
・TextHandler
=> request.method=GET request.url=http://example.com
・JSONHandler
=> "request":{"method":"GET","url":"http://example.com"}

Loggerのすべての出力をグループ名で修飾するには Logger.WithGroup を使う。WithGroup をLoggerに対して呼び出すと元と同じHandlerを持つ新しいLoggerを生成するが、その属性はすべてグループ名で修飾される。

これは巨大なシステムで、サブシステムでも同じ属性名を使いたいといった、属性名(キー)の重複を防ぐのに役立つ。各サブシステムに独自のグループ名をもつ異なるLoggerを渡すことで、重複の可能性を限定的にできる。

logger := slog.Default().With("id", systemID)
parserLogger := logger.WithGroup("parser")

Contexts

ハンドラーで、呼び出し元の context.Context の情報を含みたい場合もあるだろう。

Logger.LogLogger.LogAttrs メソッドは第一引数に context をとる、対応するトップレベル関数も同様

Loggerの便利なメソッド(Infoなど)とそれに対応するトップレベル関数は context を引数に取らないけれど、代わりに関数名が "Context" で終わるものがある。例えば slog.InfoContext(ctx, "message")

コンテキストがあれば、出力メソッドに渡すことを推奨する。

Attrs and Values

Attr はkey-valueのペア。

type Attr struct {
	Key   string
	Value Value
}

Loggerの出力メソッドは key と value を交互に書くのと同様にAttrを受け取ることができる。

// 下記2つはどちらも同じ
// Attr を渡す例
slog.Info("hello", slog.Int("count", 3))
// key, value を渡す例
slog.Info("hello", "count", 3)

Attr の値部分は Value 型になっている。any のように、Goの任意の値を保持することが可能だが、数値や文字列と言った典型的な値をメモリ割り当てなしで表現できる。

最も効率的なログ出力は Logger.LogAttrs を使う方法。Logger.Log に似ているが、Attrのみを受け取り、keyとvalueを交互に渡すことはできない。これによってメモリ割り当てを避けることが可能。

slog.Info("hello", "count", 3)
// ↓こっちの方が効率的
logger.LogAttrs(nil, slog.LevelInfo, "hello", slog.Int("count", 3))

Customizing a type's logging behavior

type LogValuer interface {
	LogValue() Value
}

LogValuer インターフェースを実装する型なら、LogValueメソッドの返り値の Value がログ出力に使われる。これを使えばログ出力される値をコントロールできる。例えば、パスワードのような秘密情報を編集してログ出力したり、Groupにまとめて出力したりできる。

秘密情報を編集して出力する例

import (
	"os"

	"golang.org/x/exp/slog"
	"golang.org/x/exp/slog/internal/testutil"
)

// A token is a secret value that grants permissions.
type Token string

// LogValue implements slog.LogValuer.
// It avoids revealing the token.
func (Token) LogValue() slog.Value {
	return slog.StringValue("REDACTED_TOKEN")
}

// This example demonstrates a Value that replaces itself
// with an alternative representation to avoid revealing secrets.
func main() {
	t := Token("shhhh!")
	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: testutil.RemoveTime}))
	logger.Info("permission granted", "user", "Perry", "token", t)

}

Groupにまとめて出力する例

package main

import "golang.org/x/exp/slog"

type Name struct {
	First, Last string
}

// LogValue implements slog.LogValuer.
// It returns a group containing the fields of
// the Name, so that they appear together in the log output.
func (n Name) LogValue() slog.Value {
	return slog.GroupValue(
		slog.String("first", n.First),
		slog.String("last", n.Last))
}

func main() {
	n := Name{"Perry", "Platypus"}
	slog.Info("mission accomplished", "agent", n)

	// JSON Output would look in part like:
	// {
	//     ...
	//     "msg": "mission accomplished",
	//     "agent": {
	//         "first": "Perry",
	//         "last": "Platypus"
	//     }
	// }
}

LogValueメソッドがLogValuer インターフェースを実装しているValue を返すこともありえる。ValueResolve メソッドはこのようなケースを注意深く処理し、無限ループや無制限の再帰を回避する。ハンドラーの実装者などは LogValue メソッドを直接呼ぶよりも ValueResolve メソッドを使いたい場合もあるだろう。

ちなみに、標準で用意されているハンドラーでは ValueResolve メソッドを呼ぶようになっているので、ハンドラーを自作しない場合は意識しなくても大丈夫。

Wrapping output methods

ロガー関数はアプリケーション内のロギング呼び出しのファイル名と行番号を見つけるためにコールスタック上でリフレクションを使用している。このため、slogをラップした関数に関するソース情報が不正確になる場合がある。

例えば、次のslogをラップした関数をmylog.goファイルに定義したとする。

// mylog.go
func Infof(format string, args ...any) {
    slog.Default().Info(fmt.Sprintf(format, args...))
}

main.goでこの関数を呼び出す。

// main.go
Infof(slog.Default(), "hello, %s", "world") // 引数の型が間違っているのでエラーになる。

slogはmain.goではなくmylog.goをソースファイルとして出力する。

Infof の正しい実装はソースロケーション(pc)を獲得して、それをNewRecordにわたす方法。具体的にどうするのかは Examplesの"wrapping"で紹介されている。

package main

import (
	"context"
	"fmt"
	"os"
	"path/filepath"
	"runtime"
	"time"

	"golang.org/x/exp/slog"
)

// Infof is an example of a user-defined logging function that wraps slog.
// The log record contains the source position of the caller of Infof.
func Infof(logger *slog.Logger, format string, args ...any) {
	if !logger.Enabled(context.Background(), slog.LevelInfo) {
		return
	}
	var pcs [1]uintptr
	runtime.Callers(2, pcs[:]) // skip [Callers, Infof]
	r := slog.NewRecord(time.Now(), slog.LevelInfo, fmt.Sprintf(format, args...), pcs[0])
	_ = logger.Handler().Handle(context.Background(), r)
}

func main() {
	replace := func(groups []string, a slog.Attr) slog.Attr {
		// Remove time.
		if a.Key == slog.TimeKey && len(groups) == 0 {
			return slog.Attr{}
		}
		// Remove the directory from the source's filename.
		if a.Key == slog.SourceKey {
			source := a.Value.Any().(*slog.Source)
			source.File = filepath.Base(source.File)
		}
		return a
	}
	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{AddSource: true, ReplaceAttr: replace}))
	Infof(logger, "message, %s", "formatted")

}

Working with Records

ハンドラは他のハンドラまたはバックエンドに渡す前にレコードを修正する必要があることがある。Recordには、単純なパブリックフィールド(Time、Level、Messageなど)とステートを間接的に参照するプライベートなフィールドが混在している。これは、Recordの単純なコピーを変更する(例えば、属性を追加するためにRecord.AddまたはRecord.AddAttrsを呼び出す)と、オリジナルに予期しない影響を与える可能性があることを意味する。レコードを変更する前に、[Clone]を使用してオリジナルと状態を共有しないコピーを作成するか、NewRecordで新しいレコードを作成し、Record.Attrsで古いレコードをトラバースしてそのAttrsを構築すること。

Performance considerations

もしアプリケーションのプロファイリングでロギングに多くの時間を費やしていたら、次の方法を試すと良い。

もしログに共通の属性があるなら、Logger.With を使って、共通属性と一緒にLoggerを生成すると良い。組み込みのハンドラーは Logger.With を呼び出したときのみその属性を書式化する(共通属性をもったハンドラーを生成してくれる)。Handler インターフェースは最適化可能な設計で、この設計をうまく利用すればよいHandlerを作れる。

たとえログイベント(Debug, Infoなど)が捨てられる場合でも、ログ呼び出しへの引数は常に評価される。可能なら実際に値がログ出力されるまで計算を遅延すべき。

slog.Info("starting request", "url", r.URL.String()) // bad String()呼び出しが無駄になる可能性がある
slog.Info("starting request", "url", &r.URL) // ログ出力するときのみ URL.String() が呼ばれる

特にデバッグログを仕込むときに気をつけた方が良さそう。

組み込みのTextHandlerはStringメソッドを呼ぶが、ログイベントが有効なときのみ。Stringメソッドの呼び出しを避けることで、基礎(元の)値の構造も保持できる。例えば、JSONHandler はJSONオブジェクトにするときにパースされてURLのコンポーネントを出力する。ハンドラーが値の構造を検査させることなくString呼び出しのコストを回避したい場合は、Marshalメソッドを使わないようにしたfmt.Stringer実装で値をラップする。

LogValuer インターフェースでも無効なログ呼び出し時の無駄な処理を回避できる。
下記のコードだと、たとえDebugレベルのログ出力が無効でも、computeExpensiveValueは実行される

// computeExpensiveValue はコストがかかる処理
slog.Debug("frobbing", "value", computeExpensiveValue(arg))

これを回避するために、LogValuerを実装する。

type expensive struct { arg int }

func (e expensive) LogValue() slog.Value {
    return slog.AnyValue(computeExpensiveValue(e.arg))
}

// ログ呼び出し部分では expensive型の値を渡す
slog.Debug("frobbing", "value", expensive{arg})

LogValue() はログレベル判定のあとに呼ばれるので、無駄にcomputeExpensiveValueが実行されることはなくなる。

イチオシ記事

1

自己紹介 フリーランスエンジニアをしているヨノと申します。 独学でプログラミングを学び、ソシャゲ・SaaS開発などを経て、2018年からフリーランスエンジニアとして活動しています。 主にバックエンド中 ...

2

はじめまして、フリーランスエンジニアのヨノと申します。 自己紹介 独学でプログラミングを学び、ソシャゲ・SaaS開発などを経て、2018年からフリーランスエンジニアとして活動しています。 主にバックエ ...

3

ネット上で色々言われているフリーランスエンジニア....。「本当はどうなの?」と思っている人は多いでしょう。 そこで本記事ではフリーランスエンジニア5年生の私が、ネット上の意見も引用しながら実態を解説 ...

-Go言語