slog正式版来了：Go日志记录新选择！
本文永久链接 – https://tonybai.com/2023/09/01/slog-a-new-choice-for-logging-in-go
在大约一年前，我就写下了《slog：Go官方版结构化日志包》一文，文中介绍了Go团队正在设计并计划在下一个Go版本中落地的Go官方结构化日志包：slog。但slog并未如预期在Go 1.20版本中落地，而是在golang.org/x/exp/slog下面给出了slog的初始实现供社区体验。
时光飞逝，slog在golang.org/x/exp/slog下经历了1年多时间的改善和演进，终于在最近发布的Go 1.21版本中以log/slog的包导入路径正式加入Go标准库。
正式版的slog在结构上并未作较大变化，依旧是分为前端和后端，因此讲exp/slog时的那幅图依然适用：
不过，正式版的slog与当初那篇文章中的exp/slog在一些类型与API上已有不同。在这篇文章中，我就来简要说明一下。我这里讲述的思路大致是将《slog：Go官方版结构化日志包》一文中的例子用log/slog改造一遍，这个过程可以让我们看到正式版log/slog与exp/slog的差异。
1. slog快速入门
1.1 slog的”hello, world”
如果仅是想以最快速的方式开始使用slog，那么下面可以算是slog的”hello, world”版本：
//slog-examples-go121/demo0/main.go
package main
import (
"log/slog"
)
func main() {
slog.Info("my first slog msg", "greeting", "hello, slog")
}
运行这段程序，会得到下面输出：
$go run main.go
2023/08/29 05:01:36 INFO my first slog msg greeting="hello, slog"
1.2 TextHandler和JSONHandler
默认情况下，slog输出的格式仅是普通text格式，而并非JSON格式，也不是以key=value形式呈现的文本。
slog提供了以JSON格式输出的JSONHandler和以key=value形式呈现的文本形式的TextHandler。不过要使用这两种Handler进行日志输出，我们需要显式创建它们：
//slog-examples-go121/demo1/main.go
h := slog.NewTextHandler(os.Stderr, nil)
l := slog.New(h)
l.Info("greeting", "name", "tony")
l.Error("oops", "err", net.ErrClosed, "status", 500)
h1 := slog.NewJSONHandler(os.Stderr, nil)
l1 := slog.New(h1)
l1.Info("greeting", "name", "tony")
l1.Error("oops", "err", net.ErrClosed, "status", 500)
注：相对于exp/slog，正式版的log/slog的NewTextHandler和NewJSONHandler增加了一个新的opts *HandlerOptions参数。
上述代码分别创建了一个使用TextHandler的slog.Logger实例以及一个使用JSONHandler的slog.Logger实例，执行这段代码后将输出如下日志：
$go run main.go
time=2023-08-29T05:34:27.370+08:00 level=INFO msg=greeting name=tony
time=2023-08-29T05:34:27.370+08:00 level=ERROR msg=oops err="use of closed network connection" status=500
{"time":"2023-08-29T05:34:27.370306+08:00","level":"INFO","msg":"greeting","name":"tony"}
{"time":"2023-08-29T05:34:27.370315+08:00","level":"ERROR","msg":"oops","err":"use of closed network connection","status":500}
如果觉得每次还得使用l或l1来调用Info、Error等输出日志的函数不便利，可以将l或l1设置为Default Logger，这样无论在任何包内都可以直接通过slog包级函数，如Info、Error等直接输出日志：
//slog-examples-go121/demo1/main.go
time=2023-08-29T05:40:08.503+08:00 level=INFO msg="textHandler after setDefault" name=tony age=30
{"time":"2023-08-29T05:40:08.503672+08:00","level":"INFO","msg":"jsonHandler after setDefault","name":"tony","age":30}
注：相对于exp/slog，正式版的log/slog提供了带有Context的Info、Error日志输出函数：DebugContext、InfoContext、ErrorContext等。
1.3 HandlerOption
通过在创建Handler时传入自定义的HandlerOption，我们可以设置Logger的日志级别和是否输出Source，比如下面示例：
//slog-examples-go121/demo2/main.go
opts := slog.HandlerOptions{
AddSource: true,
Level: slog.LevelError,
}
slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, &opts)))
slog.Info("open file for reading", "name", "foo.txt", "path", "/home/tonybai/demo/foo.txt")
slog.Error("open file error", "err", os.ErrNotExist, "status", 2)
上述代码通过HandlerOption设置了Handler仅输出Error级别日志，并在输出的日志中带上Source信息，运行这段程序，会得到下面输出：
$go run main.go
{"time":"2023-08-29T05:18:18.068213+08:00","level":"ERROR","source":{"function":"main.main","file":"/Users/tonybai/Go/src/github.com/bigwhite/experiments/slog-examples-go121/demo2/main.go","line":17},"msg":"open file error","err":"file does not exist","status":2}
我们看到通过Info函数输出的日志并没有被仅处理Error级别的Handler输出到console上。另外在输出的日志中，我们看到了source这个key，以及它的值，即输出日志的那行代码在源代码文件中位置。
1.4 属性字段
我们日常输出的日志都有一些共同的字段，比如上面的level、time，这些字段被称为属性。slog支持带有属性(attribute)的日志输出，slog内置了若干属性，如下面代码所示：
// log/slog/handler.go
// Keys for "built-in" attributes.
const (
// TimeKey is the key used by the built-in handlers for the time
// when the log method is called. The associated Value is a [time.Time].
TimeKey = "time"
// LevelKey is the key used by the built-in handlers for the level
// of the log call. The associated value is a [Level].
LevelKey = "level"
// MessageKey is the key used by the built-in handlers for the
// message of the log call. The associated value is a string.
MessageKey = "msg"
// SourceKey is the key used by the built-in handlers for the source file
// and line of the log call. The associated value is a string.
SourceKey = "source"
)
当然slog也支持自定义属性：
//slog-examples-go121/demo2/main.go
l := slog.Default().With("attr1", "attr1_value", "attr2", "attr2_value")
l.Error("connect server error", "err", net.ErrClosed, "status", 500)
l.Error("close conn error", "err", net.ErrClosed, "status", 501)
在上面的代码中，我们定义了两个属性：attr1和attr2，以及它们的值，这样当我们用带有这两个属性的Logger输出日志时，每行日志都会包含这两个属性：
{"time":"2023-08-29T05:28:39.322014+08:00","level":"ERROR","source":{"function":"main.main","file":"/Users/tonybai/Go/src/github.com/bigwhite/experiments/slog-examples-go121/demo2/main.go","line":23},"msg":"connect server error","attr1":"attr1_value","attr2":"attr2_value","err":"use of closed network connection","status":500}
{"time":"2023-08-29T05:28:39.322028+08:00","level":"ERROR","source":{"function":"main.main","file":"/Users/tonybai/Go/src/github.com/bigwhite/experiments/slog-examples-go121/demo2/main.go","line":24},"msg":"close conn error","attr1":"attr1_value","attr2":"attr2_value","err":"use of closed network connection","status":501}
当然你也可以通过slog.LogAttrs做“一次性”的属性输出：
//slog-examples-go121/demo2/main.go
l.LogAttrs(context.Background(), slog.LevelError, "log with attribute once", slog.String("attr3", "attr3_value"))
l.Error("reconnect error", "err", net.ErrClosed, "status", 502)
这两行输出如下日志：
{"time":"2023-08-29T05:32:00.419772+08:00","level":"ERROR","source":{"function":"main.main","file":"/Users/tonybai/Go/src/github.com/bigwhite/experiments/slog-examples-go121/demo2/main.go","line":26},"msg":"log with attribute once","attr1":"attr1_value","attr2":"attr2_value","attr3":"attr3_value"}
{"time":"2023-08-29T05:32:00.419778+08:00","level":"ERROR","source":{"function":"main.main","file":"/Users/tonybai/Go/src/github.com/bigwhite/experiments/slog-examples-go121/demo2/main.go","line":27},"msg":"reconnect error","attr1":"attr1_value","attr2":"attr2_value","err":"use of closed network connection","status":502}
我们看到通过LogAttrs输出的attr3属性仅出现一次。
注：相对于exp/slog，正式版的log/slog提供的LogAttrs方法多了一个context.Context参数。
1.5 Group形式的日志输出
slog支持group形式的日志输出，这点保持了与exp/slog的一致。下面是一个输出group log的例子：
//slog-examples-go121/demo2/main.go
gl := l.WithGroup("response")
gl.Error("http post response", "code", 403, "status", "server not response", "server", "10.10.121.88")
我们先创建一个名为“response”的group logger，然后调用Error输出日志。Error会将所有attribute之外的字段放入response这个group中呈现，我们看一下运行结果：
{"time":"2023-08-29T12:54:07.623002+08:00","level":"ERROR","source":{"function":"main.main","file":"/Users/tonybai/Go/src/github.com/bigwhite/experiments/slog-examples-go121/demo2/main.go","line":30},"msg":"http post response","attr1":"attr1_value","attr2":"attr2_value","response":{"code":403,"status":"server not response","server":"10.10.121.88"}}
2. 动态调整日志级别
exp/slog使用slog.AtomicLevel实现Logger级别的动态调整。在正式版slog中，我们则使用slog.LevelVar来实现Logger日志级别的动态调整，使用方法差不多，看下面这个例子：
// slog-examples-go121-demo3/main.go
func main() {
var lvl slog.LevelVar
lvl.Set(slog.LevelDebug)
opts := slog.HandlerOptions{
Level: &lvl,
}
slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, &opts)))
slog.Info("before resetting log level:")
slog.Info("greeting", "name", "tony")
slog.Error("oops", "err", net.ErrClosed, "status", 500)
slog.LogAttrs(context.Background(), slog.LevelError, "oops",
slog.Int("status", 500), slog.Any("err", net.ErrClosed))
slog.Info("after resetting log level to error level:")
lvl.Set(slog.LevelError)
slog.Info("greeting", "name", "tony")
slog.Error("oops", "err", net.ErrClosed, "status", 500)
slog.LogAttrs(context.Background(), slog.LevelError, "oops",
slog.Int("status", 500), slog.Any("err", net.ErrClosed))
}
结合LevelVar和HandlerOption，我们实现了Logger日志级别的动态调整，这里是由LevelDebug调整为LevelError。上面示例的输出结果如下：
{"time":"2023-08-29T06:15:26.103022+08:00","level":"INFO","msg":"before resetting log level:"}
{"time":"2023-08-29T06:15:26.103197+08:00","level":"INFO","msg":"greeting","name":"tony"}
{"time":"2023-08-29T06:15:26.103203+08:00","level":"ERROR","msg":"oops","err":"use of closed network connection","status":500}
{"time":"2023-08-29T06:15:26.103222+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2023-08-29T06:15:26.103226+08:00","level":"INFO","msg":"after resetting log level to error level:"}
{"time":"2023-08-29T06:15:26.103232+08:00","level":"ERROR","msg":"oops","err":"use of closed network connection","status":500}
{"time":"2023-08-29T06:15:26.103236+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
我们看到，动态调整到LevelError后，Info函数打印的日志将不再输出到console了。
3. 自定义后端Handler
在《slog：Go官方版结构化日志包》一文中，我们就举例说明了如何自定义一个后端Handler，正式版slog在自定义Handler这方面变化不大，都是通过实现slog.Handler接口的方式达成的。大家可自行查看slog-examples-go121/demo4中的代码，这里就不赘述了。
此外，log/slog的作者Jonathan Amsterdam还提供了一篇“slog自定义handler指南”供大家参考。
4. 验证handler
Go 1.21正式版提供了一个testing/slogtest包可以用来辅助测试自定义后端Handler，我们就以slog-examples-go121/demo4中自定义的ChanHandler为例，用slogtest包对其进行一下测试：
// slog-examples-go121/demo4/handler_test.go
func TestChanHandlerParsing(t *testing.T) {
var ch = make(chan []byte, 100)
h := NewChanHandler(ch)
results := func() []map[string]any {
var ms []map[string]any
ticker := time.NewTicker(time.Second)
loop:
for {
select {
case line := <-ch:
if len(line) == 0 {
break
}
var m map[string]any
if err := json.Unmarshal(line, &m); err != nil {
t.Fatal(err)
}
ms = append(ms, m)
case <-ticker.C:
break loop
}
}
return ms
}
err := slogtest.TestHandler(h, results)
if err != nil {
log.Fatal(err)
}
}
slogtest仅提供一个导出函数TestHandler，它会自动基于你提供的Handler创建Logger并向Logger写入一些日志，然后通过传入的results函数对写入的日志进行格式验证，主要是json反序列化，如果成功，会记录在map[string]any类型的切片中。最后TestHandler会比对写入日志条数与反序列化成功的条数，如果一致，说明测试ok，反之则测试失败。
注：基于这个TestHandler，还真测试出原ChanHandler的一个问题，已经fix。
5. 性能tips
按官方benchmark结果，log/slog的性能要高于Go社区常用的结构化日志包，比如zap等。
即便如此，log在go应用中带来的延迟依旧不可忽视。slog的proposal design中给出了一些关于性能的考量和tip，大家可以在日后使用slog时借鉴：
- 使用Logger.With避免重复格式化公共属性字段，这使得处理程序可以缓存格式化结果。
- 将昂贵的计算推迟到日志输出时再进行，例如传递指针而不是格式化后的字符串。这可以避免在禁用的日志行上进行不必要的工作。
- 对于昂贵的值，可以实现LogValuer接口，这样在输出时可以进行lazy加载计算。
// log/slog/value.go
// A LogValuer is any Go value that can convert itself into a Value for logging.
//
// This mechanism may be used to defer expensive operations until they are
// needed, or to expand a single value into a sequence of components.
type LogValuer interface {
LogValue() Value
}
最后，内置的Handler已经处理了原子写入的加锁。自定义Handler应该实现自己的加锁。
6. 小结
总体来说，slog正式版与之前实现相比，接口变化不大，功能也基本保持不变，但代码质量、性能、文档等有较大改进，符合预期。
slog填补了Go标准库在结构化日志支持上的短板，提供了简洁、易用、易扩展的API。相信随着slog的推广，可以逐步统一Go社区中的日志实践，也让更多人受益。
个人建议：新项目如果没有使用第三方日志包，可以直接采用slog，无需再考虑zap、zerolog等第三方选择。对于没有升级到Go 1.21版本的新项目，也可以使用exp/slog，目前exp/slog也已经与log/slog保持了同步。
本文涉及的示例代码可以在这里下载。
7. 参考资料
- Proposal: Structured Logging – https://go.googlesource.com/proposal/+/master/design/56345-structured-logging.md
- slog包手册 – https://pkg.go.dev/log/slog
- Structured Logging with slog – https://go.dev/blog/slog
- A Guide to Writing slog Handlers – https://github.com/golang/example/blob/master/slog-handler-guide/README.md
“Gopher部落”知识星球旨在打造一个精品Go学习和进阶社群！高品质首发Go技术文章，“三天”首发阅读权，每年两期Go语言发展现状分析，每天提前1小时阅读到新鲜的Gopher日报，网课、技术专栏、图书内容前瞻，六小时内必答保证等满足你关于Go语言生态的所有需求！2023年，Gopher部落将进一步聚焦于如何编写雅、地道、可读、可测试的Go代码，关注代码质量并深入理解Go核心技术，并继续加强与星友的互动。欢迎大家加入！
著名云主机服务厂商DigitalOcean发布最新的主机计划，入门级Droplet配置升级为：1 core CPU、1G内存、25G高速SSD，价格5$/月。有使用DigitalOcean需求的朋友，可以打开这个链接地址：https://m.do.co/c/bff6eed92687 开启你的DO主机之路。
Gopher Daily(Gopher每日新闻) – https://gopherdaily.tonybai.com
我的联系方式：
- 微博(暂不可用)：https://weibo.com/bigwhite20xx
- 微博2：https://weibo.com/u/6484441286
- 博客：tonybai.com
- github: https://github.com/bigwhite
- Gopher Daily归档 – https://github.com/bigwhite/gopherdaily
商务合作方式：撰稿、出书、培训、在线课程、合伙创业、咨询、广告合作。
评论