slog：Go 官方版結構化日誌包

Go 自誕生以來就在其標準庫 [1] 內置了 log 包作爲 Go 源碼輸出日誌 [2] 的標準組件，該包被廣泛應用於 Go 標準庫自身以及 Go 社區項目中。

不過，針對 Go 標準庫 log 包，Go 社區要求改進的聲音始終不斷，主流聲音聚焦在以下幾點：

log 包是爲了方便人類可讀而設計的，不支持便於機器解析的結構化日誌 (比如像 zap 那樣輸出 json 格式的日誌 [3])；
不支持日誌級別 (log level)；
log 包採用專有日誌輸出格式，又沒有提供可供 Go 社區共同遵循的 Logger 接口類型，導致 Go 社區項目使用的 log 輸出格式五花八門，相互之間又難以兼容。

Go 社區曾經嘗試過合力改進標準庫 log 包 [4]，並撰寫了 Proposal 設計初稿 [5]，但最終因各種原因都沒有被 Go 核心團隊接受。

2022 年 8 月末，Go 團隊的 Jonathan Amsterdam[6] 發起 discussion[7]，意在和社區討論爲 Go 標準庫添加結構化的、支持日誌級別的日誌包相關事宜 [8]，並形成一個一致的 Proposal。

Jonathan Amsterdam 將該結構化日誌包命名爲 slog，計劃放在 log/slog 下。他還在 golang.org/x/exp 下面給出了 slog 的初始實現 [9]，這幾天該 Proposal 正式進入 review 階段 [10]。至於何時能正式落地到 Go 正式版本中還不可知。

在這篇文章中，我們就來簡單看一下 slog 的 proposal 以及它的初始實現。

1. slog 的設計簡介

slog 的設計之初對社區目前的一些應用廣泛的 log 包進行了詳細調研，比如 uber zap[11]、zerolog[12] 等，因此 slog 的設計也算是 “站在前人的肩膀上”，尤其是 uber zap。

Jonathan Amsterdam 爲此次 slog 的設計設定了如下目標 (摘自 slog 的 proposal)：

易用性

通過對現有日誌包的調查發現，程序員們希望有一套簡潔且易於理解的 logging API。在此 proposal 中，我們將採用目前最流行的方式來表達鍵值對，即交替傳入鍵和值。

高性能高

該 log API 的設計將盡量減少內存分配和加鎖。它提供了一個交替輸入鍵和值的方法，雖略繁瑣，但速度更快；

可以與運行時跟蹤 (tracing) 集成

Go 團隊正在開發一個改進的運行時跟蹤 (runtime tracing) 系統。本軟件包的日誌將可以被無縫集成到這個跟蹤系統中，使開發者能夠將他們的程序行爲與運行時的行爲聯繫起來。

這裏基於 slog proposal 和 golang.org/x/exp/slog 的源碼，畫了一幅 slog 的結構示意圖：

簡單解釋一下這個圖：

slog 從邏輯上分爲前端 (front) 和後端(backend)。

slog 前端就是 slog 提供給使用者的 API，不過，很遺憾 slog 依舊像 log 那樣沒有抽取出 Logger 接口，而是定義了一個 Logger 結構體，並提供瞭如圖中的那些方法，這也意味着我們依舊無法在整個 Go 社區統一前端 API；

通過前端方法，slog 將日誌內容以及相關屬性信息封裝成一個 slog.Record 類型實例，然後傳遞給 slog 的後端。

如果你使用的是 Go 社區的第三方 log 包的前端方法，比如 zap，如果要使用 slog 後端，你同樣需要對 zap 等進行封裝，讓其輸出 slog.Record 並傳遞給 slog 的後端 (目前尚沒有這方面示例)。

slog 將後端抽象爲 slog.Handler 接口，接口如下：

//
// Any of the Handler's methods may be called concurrently with itself
// or with other methods. It is the responsibility of the Handler to
// manage this concurrency.
type Handler interface {
 // Enabled reports whether the handler handles records at the given level.
 // The handler ignores records whose level is lower.
 // Enabled is called early, before any arguments are processed,
 // to save effort if the log event should be discarded.
 Enabled(Level) bool

 // Handle handles the Record.
 // It will only be called if Enabled returns true.
 // Handle methods that produce output should observe the following rules:
 //   - If r.Time is the zero time, ignore the time.
 //   - If an Attr's key is the empty string, ignore the Attr.
 Handle(r Record) error

 // WithAttrs returns a new Handler whose attributes consist of
 // both the receiver's attributes and the arguments.
 // The Handler owns the slice: it may retain, modify or discard it.
 WithAttrs(attrs []Attr) Handler

 // WithGroup returns a new Handler with the given group appended to
 // the receiver's existing groups.
 // The keys of all subsequent attributes, whether added by With or in a
 // Record, should be qualified by the sequence of group names.
 //
 // How this qualification happens is up to the Handler, so long as
 // this Handler's attribute keys differ from those of another Handler
 // with a different sequence of group names.
 //
 // A Handler should treat WithGroup as starting a Group of Attrs that ends
 // at the end of the log event. That is,
 //
 //     logger.WithGroup("s").LogAttrs(slog.Int("a", 1), slog.Int("b", 2))
 //
 // should behave like
 //
 //     logger.LogAttrs(slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))
 WithGroup(name string) Handler
}

接口類型的存在，讓 slog 的後端擴展性更強，我們除了可以使用 slog 提供的兩個內置 Handler 實現：TextHandler 和 JSONHandler 之外，還可以基於第三方 log 包定義或完全自定義後端 Handler 的實現。

slog 內置兩個最常用的 Handler：TextHandler 和 JSONHandler。TextHandler 顧名思義，像標準庫 log 包那樣將日誌以一行文本那樣輸出；而 JSONHandler 則是以 JSON 格式輸出 log 內容與各個屬性，我們看一下作者給的例子：

// github.com/bigwhite/experiments/tree/master/slog-examples/demo1/main.go
package main

import (
    "net"

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

func main() {
    slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr))) 
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))
}

這是一個使用內置 TextHandler 的示例，我們運行一下看看結果：

time=2022-10-23T18:41:35.074+08:00 level=INFO msg=hello name=Al
time=2022-10-23T18:41:35.074+08:00 level=ERROR msg=oops status=500 err="use of closed network connection"
time=2022-10-23T18:41:35.074+08:00 level=ERROR msg=oops status=500 err="use of closed network connection"

我們看到，輸出的日誌以 “key1=value1 key2=value2 ... keyN=valueN” 形式呈現，time 和 level 兩個 key 是必選，調用 Error 方法時，err 這個 key 也是必選的。

接下來，我們將 TextHandler 換成 JSONHandler：

slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr)))

改爲：

slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr)))

運行修改後的程序，我們得到：

{"time":"2022-10-23T18:45:26.2131+08:00","level":"INFO","msg":"hello","name":"Al"}
{"time":"2022-10-23T18:45:26.213287+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T18:45:26.21331+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}

我們看到，每條日誌以一條 json 記錄的形式呈現，這樣的結構化日誌非常適合機器解析。

如果我們去掉上面 SetDefault 那一行代碼，再來運行一下程序：

2022/10/23 18:47:51 INFO hello name=Al
2022/10/23 18:47:51 ERROR oops status=500 err="use of closed network connection"
2022/10/23 18:47:51 ERROR oops status=500 err="use of closed network connection"

我們得到了不同於 TextHandler 和 JSONHandler 的日誌樣式，不過這個日誌樣式非常眼熟！這不和 log 包的輸出樣式相同麼！沒錯，如果沒有顯式將新創建的 Logger 設置爲默認 Logger，slog 會使用 defaultHandler，而 defaultHandler 的 output 函數就是 log.Output：

// slog項目

// logger.go
var defaultLogger atomic.Value
    
func init() {
    defaultLogger.Store(Logger{
        handler: newDefaultHandler(log.Output), // 這裏直接使用了log.Output
    })
} 

// handler.go

type defaultHandler struct {
    ch *commonHandler
    // log.Output, except for testing
    output func(calldepth int, message string) error
}
    
func newDefaultHandler(output func(int, string) error) *defaultHandler {
    return &defaultHandler{
        ch:     &commonHandler{json: false},
        output: output,
    }
}

slog 的前端是 “固定格式” 的，因此沒什麼可定製的。但後端這塊倒是有不少玩法，接下來我們重點看一下後端。

2. Handler 選項 (HandlerOptions)

slog 提供了 HandlerOptions 結構：

// handler.go

// HandlerOptions are options for a TextHandler or JSONHandler.
// A zero HandlerOptions consists entirely of default values.
type HandlerOptions struct {
    // Add a "source" attribute to the output whose value is of the form
    // "file:line".
    // This is false by default, because there is a cost to extracting this
    // information.
    AddSource bool

    // Ignore records with levels below Level.Level().
    // The default is InfoLevel.
    Level Leveler

    // If set, ReplaceAttr is called on each attribute of the message,
    // and the returned value is used instead of the original. If the returned
    // key is empty, the attribute is omitted from the output.
    //
    // The built-in attributes with keys "time", "level", "source", and "msg"
    // are passed to this function first, except that time and level are omitted
    // if zero, and source is omitted if AddSourceLine is false.
    //
    // ReplaceAttr can be used to change the default keys of the built-in
    // attributes, convert types (for example, to replace a `time.Time` with the
    // integer seconds since the Unix epoch), sanitize personal information, or
    // remove attributes from the output.
    ReplaceAttr func(a Attr) Attr
}

通過該結構，我們可以爲輸出的日誌添加 source 信息，即輸出日誌的文件名與行號，下面就是一個例子：

// github.com/bigwhite/experiments/tree/master/slog-examples/demo2/main.go
package main
  
import (
    "net"
    "os"

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

func main() {
    opts := slog.HandlerOptions{
        AddSource: true,
    }

    slog.SetDefault(slog.New(opts.NewJSONHandler(os.Stderr)))
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))
}

運行上述程序，我們將得到：

{"time":"2022-10-23T21:46:25.718112+08:00","level":"INFO","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:16","msg":"hello","name":"Al"}
{"time":"2022-10-23T21:46:25.718324+08:00","level":"ERROR","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:17","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:46:25.718352+08:00","level":"ERROR","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:18","msg":"oops","status":500,"err":"use of closed network connection"}

我們也可以通過 HandlerOptions 實現日誌級別的動態設置，比如下面例子：

// github.com/bigwhite/experiments/tree/master/slog-examples/demo3/main.go
func main() {
    var lvl = &slog.AtomicLevel{}
    lvl.Set(slog.DebugLevel)
    opts := slog.HandlerOptions{
        Level: lvl,
    }
    slog.SetDefault(slog.New(opts.NewJSONHandler(os.Stderr)))

    slog.Info("before resetting log level:")

    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

    slog.Info("after resetting log level to error level:")
    lvl.Set(slog.ErrorLevel)
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

}

slog.HandlerOptions 的字段 Level 是一個接口類型變量，其類型爲 slog.Leveler：

type Leveler interface {
    Level() Level
}

實現了 Level 方法的類型都可以賦值給 HandlerOptions 的 Level 字段，slog 提供了支持併發訪問的 AtomicLevel 供我們直接使用，上面的 demo3 使用的就是 AtomicLevel，初始時設置的是 DebugLevel，於是第一次調用 Info、Error 等 API 輸出的日誌都會得到輸出，之後重置日誌級別爲 ErrorLevel，這樣 Info API 輸出的日誌將不會被呈現出來，下面是 demo3 程序的運行結果：

{"time":"2022-10-23T21:58:48.467666+08:00","level":"INFO","msg":"before resetting log level:"}
{"time":"2022-10-23T21:58:48.467818+08:00","level":"INFO","msg":"hello","name":"Al"}
{"time":"2022-10-23T21:58:48.467825+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467842+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467846+08:00","level":"INFO","msg":"after resetting log level to error level:"}
{"time":"2022-10-23T21:58:48.46785+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467854+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}

HandlerOptions 的第三個字段 ReplaceAttr 有什麼功用，就留給大家自己探索一下。

除了利用 HandleOptions 做一些定製之外，我們也可以完全自定義 Handler 接口的實現，下面我們就用一個示例來說明一下。

3. 自定義 Handler 接口的實現

我們來定義一個新 Handler：ChanHandler，該 Handler 實現將日誌寫入 channel 的行爲（用來模擬日誌寫入 kafka)，我們來建立該 ChanHandler：

// github.com/bigwhite/experiments/tree/master/slog-examples/demo4/main.go
type ChanHandler struct {
    slog.Handler
    ch  chan []byte
    buf *bytes.Buffer
}

func (h *ChanHandler) Enabled(level slog.Level) bool {
    return h.Handler.Enabled(level)
}

func (h *ChanHandler) Handle(r slog.Record) error {
    err := h.Handler.Handle(r)
    if err != nil {
        return err
    }
    var nb = make([]byte, h.buf.Len())
    copy(nb, h.buf.Bytes())
    h.ch <- nb
    h.buf.Reset()
    return nil
}

func (h *ChanHandler) WithAttrs(as []slog.Attr) slog.Handler {
    return &ChanHandler{
        buf:     h.buf,
        ch:      h.ch,
        Handler: h.Handler.WithAttrs(as),
    }
}

func (h *ChanHandler) WithGroup(name string) slog.Handler {
    return &ChanHandler{
        buf:     h.buf,
        ch:      h.ch,
        Handler: h.Handler.WithGroup(name),
    }
}

func NewChanHandler(ch chan []byte) *ChanHandler {
    var b = make([]byte, 256)
    h := &ChanHandler{
        buf: bytes.NewBuffer(b),
        ch:  ch,
    }

    h.Handler = slog.NewJSONHandler(h.buf)

    return h
}

我們看到 ChanHandler 內嵌了 slog.JSONHandler，對 slog.Handler 接口的實現多半由內嵌的 JSONHandler 去完成，唯一不同的是 Handle 方法，這裏要把 JSONHandler 處理完的日誌 copy 出來併發送到 channel 中。下面是該 demo 的 main 函數：

// github.com/bigwhite/experiments/tree/master/slog-examples/demo4/main.go

func main() {
    var ch = make(chan []byte, 100)
    attrs := []slog.Attr{
        {Key: "field1", Value: slog.StringValue("value1")},
        {Key: "field2", Value: slog.StringValue("value2")},
    }
    slog.SetDefault(slog.New(NewChanHandler(ch).WithAttrs(attrs)))
    go func() { // 模擬channel的消費者，用來消費日誌
        for {
            b := <-ch
            fmt.Println(string(b))
        }
    }()

    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

    time.Sleep(3 * time.Second)
}

運行上述程序，我們將得到下面輸出結果：

{"time":"2022-10-23T23:09:01.358702+08:00","level":"INFO","msg":"hello","field1":"value1","field2":"value2","name":"Al"}

{"time":"2022-10-23T23:09:01.358836+08:00","level":"ERROR","msg":"oops","field1":"value1","field2":"value2","status":500,"err":"use of closed network connection"}

{"time":"2022-10-23T23:09:01.358856+08:00","level":"ERROR","msg":"oops","field1":"value1","field2":"value2","status":500,"err":"use of closed network connection"}

4. slog 的性能

我們再來看看 slog 的性能，我們直接使用了 slog 源碼中自帶的與 zap 的性能對比數據，使用 benchstat 工具查看對比結果如下：

$ benchstat zapbenchmarks/zap.bench slog.bench  
name                              old time/op    new time/op    delta
Attrs/async_discard/5_args-8         348ns ± 2%      88ns ± 2%   -74.77%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8        570ns ± 2%     280ns ± 2%   -50.94%  (p=0.008 n=5+5)
Attrs/async_discard/40_args-8       1.84µs ± 2%    0.91µs ± 3%   -50.37%  (p=0.008 n=5+5)
Attrs/fastText_discard/5_args-8      476ns ± 2%     200ns ±45%   -57.92%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8     822ns ± 7%     524ns ± 2%   -36.27%  (p=0.008 n=5+5)
Attrs/fastText_discard/40_args-8    2.70µs ± 3%    2.01µs ± 3%   -25.76%  (p=0.008 n=5+5)

name                              old alloc/op   new alloc/op   delta
Attrs/async_discard/5_args-8          320B ± 0%        0B       -100.00%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8         640B ± 0%      208B ± 0%   -67.50%  (p=0.008 n=5+5)
Attrs/async_discard/40_args-8       2.69kB ± 0%    1.41kB ± 0%   -47.64%  (p=0.008 n=5+5)
Attrs/fastText_discard/5_args-8       320B ± 0%        0B       -100.00%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8      641B ± 0%      208B ± 0%   -67.55%  (p=0.008 n=5+5)
Attrs/fastText_discard/40_args-8    2.70kB ± 0%    1.41kB ± 0%   -47.63%  (p=0.029 n=4+4)

name                              old allocs/op  new allocs/op  delta
Attrs/async_discard/5_args-8          1.00 ± 0%      0.00       -100.00%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8         1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/async_discard/40_args-8         1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/fastText_discard/5_args-8       1.00 ± 0%      0.00       -100.00%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8      1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/fastText_discard/40_args-8      1.00 ± 0%      1.00 ± 0%      ~     (all equal)

我們看到，slog 的性能相對於本就以高性能著稱的 zap 還要好上不少，內存分配也減少很多。

5. 小結

通過對 slog 的初步探索，感覺 slog 整體上借鑑了 zap 等第三方 log 包的設計，都採用前後端分離的策略，但似乎又比 zap 好理解一些。

前面示例中提到了使用起來很方便的前端 API，談到了 slog 的高性能，slog 設計目標中與 runtime tracing 集成在 proposal 中提及不多，更多談到的是其與 context.Context 的集成 (通過 slog.WithContext 和 slog.FromContext 等)，也許這就是與 runtime tracing 集成的基礎吧。

Jonathan Amsterdam 在 proposal 也提到過，每個第三方 log 包都有其特點，不指望 slog 能替換掉所有第三方 log 包，只是希望 slog 能與第三方 log 包充分交互，實現每個程序有一個共同的 "後端"。一個有許多依賴關係的應用程序可能會發現，它已經連接了許多日誌包。如果所有的包都支持 slog 提出的 Handler 接口，那麼應用程序就可以創建一個單一的 Handler 併爲每個日誌庫安裝一次，以便在其所有的依賴中獲得一致的日誌。

個人觀點：等 slog 加入標準庫後，新項目推薦使用 slog。

本文涉及的示例代碼可以在這裏 [13] 下載。

6. 參考資料

Proposal: Structured Logging review - https://go-review.googlesource.com/c/proposal/+/444415/3/design/56345-structured-logging.md
discussion: structured, leveled logging - https://github.com/golang/go/discussions/54763
proposal: log/slog: structured, leveled logging - https://github.com/golang/go/issues/56345
slog 實驗性實現 - https://github.com/golang/exp/tree/master/slog
logr - https://github.com/go-logr/logr
Go Logging Design Proposal - Ross Light - https://docs.google.com/document/d/1nFRxQ5SJVPpIBWTFHV-q5lBYiwGrfCMkESFGNzsrvBU/edit
Standardization around logging and related concerns - https://groups.google.com/g/golang-dev/c/F3l9Iz1JX4g/m/t0J0loRaDQAJ

Gopher Daily(Gopher 每日新聞) 歸檔倉庫 - https://github.com/bigwhite/gopherdaily

我的聯繫方式：

微博：https://weibo.com/bigwhite20xx
博客：tonybai.com
github: https://github.com/bigwhite

商務合作方式：撰稿、出書、培訓、在線課程、合夥創業、諮詢、廣告合作。

參考資料

[1] 標準庫: https://tonybai.com/2022/10/25/the-modules-that-go-standard-library-depend-on

[2] 輸出日誌: https://tonybai.com/2022/03/05/go-logging-practice

[3] 像 zap 那樣輸出 json 格式的日誌: https://tonybai.com/2021/07/14/uber-zap-advanced-usage

[4] 嘗試過合力改進標準庫 log 包: https://groups.google.com/g/golang-dev/c/F3l9Iz1JX4g/m/t0J0loRaDQAJ

[5] 撰寫了 Proposal 設計初稿: https://docs.google.com/document/d/1nFRxQ5SJVPpIBWTFHV-q5lBYiwGrfCMkESFGNzsrvBU/edit

[6] Jonathan Amsterdam: https://github.com/jba

[7] 發起 discussion: https://github.com/golang/go/discussions/54763

[8] 爲 Go 標準庫添加結構化的、支持日誌級別的日誌包相關事宜: https://github.com/golang/go/discussions/54763

[9] slog 的初始實現: https://github.com/golang/exp/slog

[10] 該 Proposal 正式進入 review 階段: https://go-review.googlesource.com/c/proposal/+/444415/3/design/56345-structured-logging.md

[11] uber zap: https://tonybai.com/2021/07/14/uber-zap-advanced-usage

[12] zerolog: https://github.com/rs/zerolog

[13] 這裏: https://github.com/bigwhite/experiments/tree/master/slog-examples

[14] “Gopher 部落” 知識星球: https://wx.zsxq.com/dweb2/index/group/51284458844544

[15] 我愛發短信: https://51smspush.com/

[16] 鏈接地址: https://m.do.co/c/bff6eed92687

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/5kHATSVx4W5lDJdnPujgkQ