在當初寫書跟在公司應用時，OpenTelemetry Go 其實對於 Log 這類型遙測信號還沒實踐，去年都還在草案討論，今年終於在 OTel Go v1.24.0 提出設計。從它們迭代過程中我們也能看到都是從 API 和 Bridge API 開始著手，接著是 Record 結構（v1.25.0），最後才是 SDK （v1.26.0）的實踐。
當初小弟在書上第五章就層介紹到 OTel log record 的結構︰
今天就能來嘗試看看。在此之前 Go 有出 slog 套件，但我之前都覺得用起來沒 OTel + 自己客製化一點點 zap 來的順手。但直到今日我覺得 OTel log bridge 搭配 slog ，用起來幾乎零門檻！
絕大部分內容都參考自官方網站 Doc/Language APIs & SDKs/Go/Getting Started 的內容。今天的內容我有上傳至 OpenTelemetry 入門指南的 Ch5/rolldice 中。
在 Log instrument 的頁面還有提到 log 直接傳送給 collector 與寫到 stdout和file的比較。這部份有機會再寫一篇介紹。
Logger Provider
Logger Provider 主要是給 OTel Log API 的的一個入口點，提供對 Logger 的建立存取與管理。因此 API 應該會提供方法來設定或註冊以及訪問全域的 LoggerProvider。
Logger 才是真的去發送 Log Record 的實例。
這些都在書上第5章有更全面的說明。
func newLoggerProvider() (*log.LoggerProvider, error) {
logExporter, err := stdoutlog.New(stdoutlog.WithPrettyPrint())
if err != nil {
return nil, err
}
loggerProvider := log.NewLoggerProvider(
log.WithProcessor(log.NewSimpleProcessor(logExporter)),
)
return loggerProvider, nil
}
接著就能開始設定 SDK ，shutdownFuncs很重要，如果我們要做 Graceful shutdown，把還queue在logger中的records 都送出去，就要依賴它去調用loggerProvider.Shutdown。
Shutdown 的作用在書上第6章有提。
func setupOTelSDK(ctx context.Context) (shutdown func(context.Context) error, err error) {
var shutdownFuncs []func(context.Context) error
shutdown = func(ctx context.Context) error {
var err error
for _, fn := range shutdownFuncs {
err = errors.Join(err, fn(ctx))
}
shutdownFuncs = nil
return err
}
handleErr := func(inErr error) {
err = errors.Join(inErr, shutdown(ctx))
}
prop := newPropagator()
otel.SetTextMapPropagator(prop)
loggerProvider, err := newLoggerProvider()
if err != nil {
handleErr(err)
return
}
shutdownFuncs = append(shutdownFuncs, loggerProvider.Shutdown)
global.SetLoggerProvider(loggerProvider)
return
}
業務模組的 Logger
通常每個業務模組都會有一個具名的 Logger。這裡只用 Slog 來示範。OTel Go contrib 有提供了 Slog 的 bridge。
import (
"go.opentelemetry.io/contrib/bridges/otelslog"
)
const name = "go.opentelemetry.io/otel/example/dice"
var (
logger = otelslog.NewLogger(name)
)
func rolldice(w http.ResponseWriter, r *http.Request) {
ctx, span := tracer.Start(r.Context(), "roll")
defer span.End()
roll := 1 + rand.Intn(6)
var msg string
if player := r.PathValue("player"); player != "" {
msg = fmt.Sprintf("%s is rolling the dice", player)
} else {
msg = "Anonymous player is rolling the dice"
}
logger.InfoContext(ctx, msg,
"result", roll)
rollValueAttr := attribute.Int("roll.value", roll)
span.SetAttributes(rollValueAttr)
rollCnt.Add(ctx, 1, metric.WithAttributes(rollValueAttr))
resp := strconv.Itoa(roll) + "\n"
if _, err := io.WriteString(w, resp); err != nil {
log.Printf("Write failed: %v\n", err)
}
logger.ErrorContext(ctx, errors.New("errrrr").Error(),
"argName", "1212",
"argName2", 4444)
}
首次執行
make run
curl -X GET http:
Info Log
從下方 Json資料能看見上面表5-2的欄位幾乎都存在於這資料中。連 Trace 與 Span 還有重要的 Recouce 資訊都自動代入了。這裡的Severity Number 是9。
{
"Timestamp": "2024-11-17T23:30:14.457791572+08:00",
"ObservedTimestamp": "2024-11-17T23:30:14.457828932+08:00",
"Severity": 9,
"SeverityText": "",
"Body": {
"Type": "String",
"Value": "Alice is rolling the dice"
},
"Attributes": [
{
"Key": "result",
"Value": {
"Type": "Int64",
"Value": 3
}
}
],
"TraceID": "6c554d8e71da75aec261bbd8dcfa9171",
"SpanID": "e0a4005b7be246ef",
"TraceFlags": "01",
"Resource": [
{
"Key": "service.name",
"Value": {
"Type": "STRING",
"Value": "unknown_service:rolldice_log_demo"
}
},
{
"Key": "telemetry.sdk.language",
"Value": {
"Type": "STRING",
"Value": "go"
}
},
{
"Key": "telemetry.sdk.name",
"Value": {
"Type": "STRING",
"Value": "opentelemetry"
}
},
{
"Key": "telemetry.sdk.version",
"Value": {
"Type": "STRING",
"Value": "1.32.0"
}
}
],
"Scope": {
"Name": "go.opentelemetry.io/otel/example/dice",
"Version": "",
"SchemaURL": "",
"Attributes": {}
},
"DroppedAttributes": 0
}
Error Log
我們自定義的參數也都被自動帶入於Attributes 欄位中且判斷出型別。
這裡的Severity Number 是17。
{
"Timestamp": "2024-11-17T23:30:14.458313377+08:00",
"ObservedTimestamp": "2024-11-17T23:30:14.45831527+08:00",
"Severity": 17,
"SeverityText": "",
"Body": {
"Type": "String",
"Value": "errrrr"
},
"Attributes": [
{
"Key": "argName",
"Value": {
"Type": "String",
"Value": "1212"
}
},
{
"Key": "argName2",
"Value": {
"Type": "Int64",
"Value": 4444
}
}
],
"TraceID": "6c554d8e71da75aec261bbd8dcfa9171",
"SpanID": "e0a4005b7be246ef",
"TraceFlags": "01",
"Resource": [
{
"Key": "service.name",
"Value": {
"Type": "STRING",
"Value": "unknown_service:rolldice_log_demo"
}
},
{
"Key": "telemetry.sdk.language",
"Value": {
"Type": "STRING",
"Value": "go"
}
},
{
"Key": "telemetry.sdk.name",
"Value": {
"Type": "STRING",
"Value": "opentelemetry"
}
},
{
"Key": "telemetry.sdk.version",
"Value": {
"Type": "STRING",
"Value": "1.32.0"
}
}
],
"Scope": {
"Name": "go.opentelemetry.io/otel/example/dice",
"Version": "",
"SchemaURL": "",
"Attributes": {}
},
"DroppedAttributes": 0
}
SeverityNumber 與 Log級別 的對應
但其實 OTel 還有個 SeverityText ，這部份可以自己團隊定義，或者就按照 Log level 填入也行。
看起來都很完美！只是！
我習慣看 Caller 資訊，是哪隻模組的哪個檔案的那一行產生 Log event 的。
自定義 Logger
package main
import (
"context"
"log/slog"
"runtime"
)
type CustLogger struct {
base *slog.Logger
}
func NewCustLoggerLogger(base *slog.Logger) *CustLogger {
return &CustLogger{base: base}
}
func getCallerInfo() (file string, line int, funcName string) {
pc, file, line, ok := runtime.Caller(2)
if !ok {
return "unknown", 0, "unknown"
}
funcName = runtime.FuncForPC(pc).Name()
return file, line, funcName
}
func (l *CustLogger) InfoContext(ctx context.Context, msg string, keysAndValues ...any) {
file, line, funcName := getCallerInfo()
extendedKeysAndValues := append(keysAndValues,
"caller.file", file,
"caller.line", line,
"caller.func", funcName,
)
l.base.InfoContext(ctx, msg, extendedKeysAndValues...)
}
func (l *CustLogger) ErrorContext(ctx context.Context, err error, keysAndValues ...any) {
file, line, funcName := getCallerInfo()
extendedKeysAndValues := append(keysAndValues,
"caller.file", file,
"caller.line", line,
"caller.func", funcName,
)
l.base.ErrorContext(ctx, err.Error(), extendedKeysAndValues...)
}
Logger 也改一下
logger = NewCustLoggerLogger(otelslog.NewLogger(name))
再次執行
make run
curl -X GET http:
漂亮！我有 Caller 資訊了。
{
"Timestamp": "2024-11-17T23:39:49.11538527+08:00",
"ObservedTimestamp": "2024-11-17T23:39:49.11542815+08:00",
"Severity": 9,
"SeverityText": "",
"Body": {
"Type": "String",
"Value": "Alice is rolling the dice"
},
"Attributes": [
{
"Key": "result",
"Value": {
"Type": "Int64",
"Value": 5
}
},
{
"Key": "caller.file",
"Value": {
"Type": "String",
"Value": "/home/nathan/Project/OpenTelemetryEntryBeook/ch5/rolldice/rolldice.go"
}
},
{
"Key": "caller.line",
"Value": {
"Type": "Int64",
"Value": 51
}
},
{
"Key": "caller.func",
"Value": {
"Type": "String",
"Value": "main.rolldice"
}
}
],
"TraceID": "aa3f83b7b738ce028cfb9f00e1c566dd",
"SpanID": "b3fa02d56626b129",
"TraceFlags": "01",
"Resource": [
{
"Key": "service.name",
"Value": {
"Type": "STRING",
"Value": "unknown_service:rolldice_log_demo"
}
},
{
"Key": "telemetry.sdk.language",
"Value": {
"Type": "STRING",
"Value": "go"
}
},
{
"Key": "telemetry.sdk.name",
"Value": {
"Type": "STRING",
"Value": "opentelemetry"
}
},
{
"Key": "telemetry.sdk.version",
"Value": {
"Type": "STRING",
"Value": "1.32.0"
}
}
],
"Scope": {
"Name": "go.opentelemetry.io/otel/example/dice",
"Version": "",
"SchemaURL": "",
"Attributes": {}
},
"DroppedAttributes": 0
}
{
"Timestamp": "2024-11-17T23:39:49.115839158+08:00",
"ObservedTimestamp": "2024-11-17T23:39:49.115841733+08:00",
"Severity": 17,
"SeverityText": "",
"Body": {
"Type": "String",
"Value": "errrrr"
},
"Attributes": [
{
"Key": "argName",
"Value": {
"Type": "String",
"Value": "1212"
}
},
{
"Key": "argName2",
"Value": {
"Type": "Int64",
"Value": 4444
}
},
{
"Key": "caller.file",
"Value": {
"Type": "String",
"Value": "/home/nathan/Project/OpenTelemetryEntryBeook/ch5/rolldice/rolldice.go"
}
},
{
"Key": "caller.line",
"Value": {
"Type": "Int64",
"Value": 64
}
},
{
"Key": "caller.func",
"Value": {
"Type": "String",
"Value": "main.rolldice"
}
}
],
"TraceID": "aa3f83b7b738ce028cfb9f00e1c566dd",
"SpanID": "b3fa02d56626b129",
"TraceFlags": "01",
"Resource": [
{
"Key": "service.name",
"Value": {
"Type": "STRING",
"Value": "unknown_service:rolldice_log_demo"
}
},
{
"Key": "telemetry.sdk.language",
"Value": {
"Type": "STRING",
"Value": "go"
}
},
{
"Key": "telemetry.sdk.name",
"Value": {
"Type": "STRING",
"Value": "opentelemetry"
}
},
{
"Key": "telemetry.sdk.version",
"Value": {
"Type": "STRING",
"Value": "1.32.0"
}
}
],
"Scope": {
"Name": "go.opentelemetry.io/otel/example/dice",
"Version": "",
"SchemaURL": "",
"Attributes": {}
},
"DroppedAttributes": 0
}
結論
這次 OTel GO 於 log 的開發結果讓應用開發者的我很滿意，幾乎能無腦轉移。只是覺得SeverityText 能幫忙自動設定log level 進去阿 XD。不過這其實自己客製化也不難。
重點是保證是 structured log 以及自動整合了resource context 與 trace context。蠻多框架輸出的其實並不太是 structured log。但目前還是處於 Beta 階段，很可能使用的方式上還會改動。
至於 slog 怎麼能寫入 log 時被多塞這麼多 OTel 資訊呢？那是因為OTel slog bridge , 就新增一個handler 給slog了。這細節能自己在追蹤就好。
func NewLogger(name string, options ...Option) *slog.Logger {
return slog.New(NewHandler(name, options...))
}
func (l *Logger) log(ctx context.Context, level Level, msg string, args ...any) {
... ignore
_ = l.Handler().Handle(ctx, r)
}
有興趣能購買OpenTelemetry 入門指南：建立全面可觀測性架構（iThome鐵人賽系列書） 電子書來閱讀。
程式內容︰OpenTelemetry 入門指南的 Ch5/rolldice
