本文永久链接 – 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核心技术,并继续加强与星友的互动。欢迎大家加入!

img{512x368}
img{512x368}

img{512x368}
img{512x368}

著名云主机服务厂商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

商务合作方式:撰稿、出书、培训、在线课程、合伙创业、咨询、广告合作。

© 2023, bigwhite. 版权所有.

Related posts:

  1. slog:Go官方版结构化日志包
  2. 聊聊Go应用输出日志的工程实践
  3. 一文告诉你如何用好uber开源的zap日志库
  4. Go 1.21中值得关注的几个变化
  5. 编译Go应用的黑盒挑战:无源码只有.a文件,你能搞定吗?