# 初嚐 OpenTelemetry Go Log  Beta

在當初[寫書](https://www.tenlong.com.tw/products/9786263338739)跟在公司應用時，OpenTelemetry Go 其實對於 Log 這類型遙測信號還沒實踐，去年都還在草案討論，今年終於在 [OTel Go v1.24.0](https://github.com/open-telemetry/opentelemetry-go/compare/v1.23.1...v1.24.0) 提出設計。從它們迭代過程中我們也能看到都是從 API 和 Bridge API 開始著手，接著是 Record 結構（v1.25.0），最後才是 SDK （v1.26.0）的實踐。

當初小弟在[書上第五章](https://www.tenlong.com.tw/products/9786263338739)就層介紹到 OTel log record 的結構︰

![](https://cdn.hashnode.com/res/hashnode/image/upload/v1731856403958/887ab411-64fe-427d-ac2b-66bfc7ddc7b3.png align="center")

今天就能來嘗試看看。在此之前 Go 有出 slog 套件，但我之前都覺得用起來沒 OTel + 自己客製化一點點 zap 來的順手。但直到今日我覺得 OTel log bridge 搭配 slog ，用起來幾乎零門檻！

絕大部分內容都參考自官方網站 [`Doc/Language APIs & SDKs/Go/Getting Started`](https://opentelemetry.io/docs/languages/go/getting-started/) 的內容。今天的內容我有上傳至 [OpenTelemetry 入門指南的 Ch5/rolldice](https://github.com/tedmax100/OpenTelemetryEntryBeook/tree/main/ch5/rolldice) 中。

[在 Log instrument 的頁面](https://opentelemetry.io/docs/languages/go/instrumentation/#logs)還有提到 log 直接傳送給 collector 與寫到 stdout和file的比較。這部份有機會再寫一篇介紹。

## Logger Provider

Logger Provider 主要是給 OTel Log API 的的一個入口點，提供對 Logger 的建立存取與管理。因此 API 應該會提供方法來設定或註冊以及訪問全域的 LoggerProvider。

Logger 才是真的去發送 Log Record 的實例。

這些都在書上第5章有更全面的說明。

![](https://cdn.hashnode.com/res/hashnode/image/upload/v1731856971662/7ac28ba2-fd0d-49d5-9dbb-79adf4a46c5e.png align="center")

```go
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章有提。

```go
// setupOTelSDK bootstraps the OpenTelemetry pipeline.
// If it does not return an error, make sure to call shutdown for proper cleanup.
func setupOTelSDK(ctx context.Context) (shutdown func(context.Context) error, err error) {
	var shutdownFuncs []func(context.Context) error

	// shutdown calls cleanup functions registered via shutdownFuncs.
	// The errors from the calls are joined.
	// Each registered cleanup will be invoked once.
	shutdown = func(ctx context.Context) error {
		var err error
		for _, fn := range shutdownFuncs {
			err = errors.Join(err, fn(ctx))
		}
		shutdownFuncs = nil
		return err
	}

	// handleErr calls shutdown for cleanup and makes sure that all errors are returned.
	handleErr := func(inErr error) {
		err = errors.Join(inErr, shutdown(ctx))
	}

	// Set up propagator.
	prop := newPropagator()
	otel.SetTextMapPropagator(prop)

	// Set up trace provider.

	// Set up meter provider.
	
	// Set up logger provider.
	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。

```go
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) {
	// 從 parent span 產生 current span
    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 紀錄 Info 事件
	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 紀錄 Error 事件
	logger.ErrorContext(ctx, errors.New("errrrr").Error(),
		"argName", "1212",
		"argName2", 4444)
}
```

## 首次執行

```go
make run

curl -X GET http://localhost:8080/rolldice/Alice
```

### Info Log

從下方 Json資料能看見上面表5-2的欄位幾乎都存在於這資料中。連 Trace 與 Span 還有重要的 Recouce 資訊都自動代入了。這裡的Severity Number 是`9`。

```json
{
	"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`。

```json
{
	"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 填入也行。

![](https://cdn.hashnode.com/res/hashnode/image/upload/v1731857723423/a8c2599e-81e0-475e-a20e-ce3dd27124b3.png align="center")

看起來都很完美！只是！

我習慣看 Caller 資訊，是哪隻模組的哪個檔案的那一行產生 Log event 的。

## 自定義 Logger

```go
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 也改一下

```go
logger = NewCustLoggerLogger(otelslog.NewLogger(name))
```

## 再次執行

```go
make run

curl -X GET http://localhost:8080/rolldice/Alice
```

漂亮！我有 Caller 資訊了。

```json
{
	"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
}
```

```json
{
	"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了。這細節能自己在追蹤就好。

```go
// NewLogger returns a new [slog.Logger] backed by a new [Handler]. See
// [NewHandler] for details on how the backing Handler is created.
func NewLogger(name string, options ...Option) *slog.Logger {
	return slog.New(NewHandler(name, options...))
}
```

```go
func (l *Logger) log(ctx context.Context, level Level, msg string, args ...any) {
	... ignore
	_ = l.Handler().Handle(ctx, r)
}
```

有興趣能購買[`OpenTelemetry 入門指南：建立全面可觀測性架構（iThome鐵人賽系列書）`](https://www.books.com.tw/products/E050230487?srsltid=AfmBOoqGbaY9XPyzh201UxqG6Msl8M_EzcwRVRTKnK72YqR1EnFlC_RJ) 電子書來閱讀。

程式內容︰[OpenTelemetry 入門指南的 Ch5/rolldice](https://github.com/tedmax100/OpenTelemetryEntryBeook/tree/main/ch5/rolldice)