Skip to content

Logging v2 - #25

Merged
yukicoder0509 merged 12 commits into
mainfrom
logging-v2
Aug 29, 2026
Merged

Logging v2#25
yukicoder0509 merged 12 commits into
mainfrom
logging-v2

Conversation

@yorukot

@yorukot yorukot commented May 14, 2026

Copy link
Copy Markdown
Member

Type of changes

  • Feature
  • Refactor

這個 PR 想解決什麼

現在的 log 有兩個問題。

第一個是同一件事會被寫很多次,而且每一次都只看得到一半。以「建立使用者時 email 重複」為例,WrapDBError 在 repository 層先寫一筆 Error 再寫一筆 Warn,往上傳到 problem.WriteError 又寫第三筆。三筆講的是同一個失敗,可是最底層那兩筆只知道 SQL 出了什麼錯,不知道是哪個 user 發的哪個 request;最上層那筆知道 request,但 driver 的細節在中途被 %v 壓成字串,已經撈不回來了。查問題的時候要把三筆湊起來看,而且湊不完整。

第二個是 log 的內容是寫給人讀的句子,不是可以查詢的資料。"Failed to create user" 這種 message 沒辦法拿來做聚合,想知道「這週有多少次因為 email 重複而建立失敗」只能 grep,欄位名稱也是各寫各的。

會變成這樣的原因是 WrapDBError 這類 helper 一次做了三件事:寫 log、分類 error、回傳 error。既然它在最底層就把 log 寫掉了,那個時間點能拿到的 context 自然就只有那麼多。

所以這個 PR 做的事是把這三件事拆開,讓 error 負責把資訊揹到邊界,context 負責帶 request scope 的欄位,log 只在邊界寫一次。

使用前後的差異

以前在 repository 層這樣寫,log 就順便產生了:

user, err := q.CreateUser(ctx, params)
if err != nil {
    return databaseutil.WrapDBError(err, logger, "create user")
}

同一個請求會產生三筆 log(以下為示意):

ERROR  Failed to create user          {"error": "ERROR: duplicate key value violates unique constraint \"users_email_key\" (SQLSTATE 23505)"}
WARN   Wrapped database error         {"error": "...", "operation": "create user", "unknown_error": false}
WARN   Handling Conflict              {"problem": "Conflict", "status": 409, "type": "...", "detail": "..."}

改完之後,handler 進來的地方先把這個 flow 的身分交代清楚:

ctx, logger := logutil.SetupFlow(ctx, logger, "user.create",
    zap.String("service.name", "account-api"))
ctx = logutil.WithUserID(ctx, userID)
ctx = logutil.WithRequestID(ctx, requestID)

repository 層只回傳分類過的 error,不寫 log:

user, err := q.CreateUser(ctx, params)
if err != nil {
    return errutil.NewTypedInfoError(errutil.ALREADY_EXISTS, err, map[errutil.ErrorInfoKey]any{
        errutil.ErrorInfoOperation: "create_user",
        errutil.ErrorInfoField:     "email",
        errutil.ErrorInfoRetryable: false,
    })
}

到邊界時 problem.WriteError 寫出一筆,該有的資訊都在同一筆裡面:

WARN   request failed  {
  "event.name": "user.create", "event.outcome": "failure",
  "error.type": "ALREADY_EXISTS", "event.reason": "duplicate_email",
  "error.info.operation": "create_user", "error.info.field": "email", "error.info.retryable": false,
  "enduser.id": "user-42", "request.id": "req-7", "service.name": "account-api",
  "trace_id": "...", "span_id": "...",
  "http.status_code": 409, "problem.title": "Conflict", "problem.instance": "/users",
  "code.file.path": "internal/user/handler.go", "code.line.number": 88,
  "error.message": "ERROR: duplicate key value violates unique constraint ..."
}

三筆變一筆,而且底層的 driver 錯誤訊息跟上層的 request 身分同時保留下來。

換過去之後可以做到什麼

查詢從 grep 變成用欄位篩。想看某個使用者這週所有失敗的操作,條件是 enduser.idevent.outcome=failure;想看特定失敗類型的趨勢,直接對 error.type 做聚合。這些欄位名稱照 OpenTelemetry semantic conventions 走,collector 或 log aggregation 那邊不用另外寫 mapping。

一個請求的所有 log 可以串起來。request.id 跟 trace 欄位由 context 自動帶上去,不需要每個 call site 手動掛。

錯誤分類有固定的字彙表。ErrorTypeEventOutcome 都是常數,不會這裡寫 failed 那裡寫 failure,也不會同一種失敗在不同 package 有不同講法。

錯誤細節可以從發生的地方帶到寫 log 的地方。InfoError 讓底層把 operation、欄位名稱、能不能 retry 這些資訊掛在 error 上,邊界寫 log 時自動展開成 error.info.*,中間層不用為了保留這些資訊而多包一層自己的 struct。

檔案行號會指到真正的呼叫點。以前靠 zap.AddCallerSkip(1) 手動數層數,多包一層就要改數字,很容易對不準;現在在 level helper 裡用 runtime.Callers 直接抓。

技術細節

新增 pkg/log 的 context-first API

SetupFlow(ctx, logger, eventName, fields...) 開場,把 request scope 的欄位放進 context,同時幫 logger 掛上 event.name,回傳這兩個值。ctxlogger 傳 nil 會分別退回 context.Background()zap.NewNop()

level helper Debug / Info / Warn / Error / DPanic / Panic / Fatal 的簽章是 (ctx, logger, msg, ...)。它們會呼叫 Constructs 把 context 上的欄位合併進來,並且補上 code.file.pathcode.file.namecode.line.numbercode.function.namecode.namespace。收 error 的那幾個還會把 error 展開成結構化欄位。

Constructs(ctx, logger) 取代舊的 WithContext,合併 WithFields 存的欄位、OTel 的 trace_id / span_id / trace_flags / trace_sampled / trace_state,以及 user 和 request 的欄位。

with.go 提供 context 端的 helper:WithFieldsWithUserIDWithUsernameWithDisplayNameWithRequestIDWithReasonWithErrorType。欄位存在以 key 為索引的 map 裡,同一個 key 重設會覆蓋,所以一筆 log 不會出現重複的 key,空 key 跟空值會直接略過。

logger 端的 helper 有 WithEventNameWithEventOutcomeWithOutcomeWithTraceContextWithUserContext,適合 logger 本身已經代表某個特定 event 的情況。

constant.go 定義 EventOutcome 常數:successfailurecancelledtimeoutunknown。需要自訂字串時用 WithOutcome

doc.go 說明 context-first 跟 logger-first 兩條路徑各自的適用時機。

新增 pkg/errorerrutil

ErrorType 常數涵蓋常見的分類(INVALID_ARGUMENTNOT_FOUNDALREADY_EXISTSPERMISSION_DENIEDINTERNAL 等),讓不相干的 Go error type 可以按照維運上的意義歸成同一類。

InfoError[K, V] 包住原本的 error,額外帶一個 ErrorType 跟一份 metadata map。它實作了 Unwrap,所以 errors.Iserrors.As 照樣穿得過去。

建構子是 NewInfoErrorNewTypedInfoError,另外有 WrapInfoErrorWrapTypedInfoError 兩個同義的名字。

InfoCarrierErrorTypeCarrier 這兩個 interface 用 errors.As 尋找,所以掛在 error chain 深處的 metadata 到邊界一樣撈得到。

ErrorFields(err) 產生 zap.Errorerror.messageerror.type(有的話)跟 error.info.*ErrorFieldsWithStacktrace(err) 再多加 exception.stacktraceErrorInfoKey 提供常用的 key:operationreasonfieldretryableuser.idrequest.id

調整 pkg/problem

writeProblemResponse 改成收 ctx,並且讓 logger 先經過 logutil.Constructs,所以 problem response 會繼承整個 flow 的 context 欄位。

錯誤回應會帶上 http.status_codeproblem.typeproblem.titleproblem.detailproblem.instanceerror.kind。5xx 用 Error level 並附 stacktrace,4xx 用 Warn level 不附。

新增 problemErrorKind(status) 把 HTTP status 對應到分類字串。

調整 pkg/database

WrapDBErrorWrapDBErrorWithKeyValueWrapMSSQLErrorWrapMSSQLErrorWithKeyValue 標記為 Deprecated,並且拿掉裡面的 log,只留分類。

包裝方式從 %v 改成 %wInternalServerError 補上 Unwrap(),底層的 driver error 因此可以透過 errors.Iserrors.As 取得。

logger 參數保留但不再使用,維持簽章相容。

相容性

WithContext 搬到 deprecated.go,行為跟舊欄位名(trace_idspan_iduser_idusernamedisplay-name)完全沒動,既有的呼叫端(包含 pkg/trace/middleware.go)不受影響,只是標記為 Deprecated,建議改用 ConstructsWithTraceContextWithUserContext

pkg/database 那幾個 helper 的簽章沒變,但它們不再寫 log。這一點編譯器不會提醒,測試也不會失敗,原本靠這些 helper 產生 log 的服務升上來之後會悄悄少掉那些 log entry,需要改在邊界寫。這是升級時最容易忽略的地方。

測試與範例

pkg/log/flow_test.gozaptest/observer 驗證 SetupFlow 搭配 WithReasonWithErrorTypeWithEventOutcome 之後產生的欄位是否符合預期,另外驗證 ctxlogger 傳 nil 以及 event name 為空字串的情況。

examples/simple-log/log.go 示範完整流程:SetupFlow 到 context 補欄位到 WrapInfoErrorlogutil.Error

example/ 改名為 examples/

Merge 前要處理的事

這條 branch 落後 main 26 個 commit 且目前有衝突(main 上的 #34 也動過 pkg/log/logger.go),需要 rebase。

README 的 pkg/log 段落目前只寫 WithContext,還沒涵蓋 SetupFlow、level helper 跟 pkg/error,review 提到的文件需求尚未處理。

pkg/problem 送出的是 error.kindpkg/error 定義的是 error.type,兩者用同一組字彙卻是不同的 key,建議收斂成一個再 merge。

@yorukot
yorukot marked this pull request as ready for review May 27, 2026 13:38
@yorukot
yorukot requested a review from YukinaMochizuki June 3, 2026 09:21
@dytsou
dytsou requested a review from linoil June 4, 2026 12:35

@yukicoder0509 yukicoder0509 left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we need some descriptions of this PR. Also, please document the new APIs and the deprecated APIs in the README.

Comment thread pkg/database/errors.go
Comment thread pkg/error/error_warp.go
Replace the `Deprecated:` doc markers on the database wrap helpers and
logutil.WithContext with plain comments, so linters and IDEs stop flagging
existing call sites while the docs still point new code elsewhere.

Restore the structured logging the wrappers lost: an Error on entry and a
Warn with operation/unknown_error (plus table/key/value) after classification.
yukicoder0509
yukicoder0509 previously approved these changes Aug 29, 2026
@YukinaMochizuki
YukinaMochizuki dismissed stale reviews from yukicoder0509 and themself via 245bb7d August 29, 2026 08:02
The nil-context cases are intentional: they cover SetupFlow's fallback when a
caller has no context. Passing a nil context.Context variable keeps that
coverage while staticcheck's SA1012 only flags a literal nil.
@yukicoder0509
yukicoder0509 merged commit 352ac21 into main Aug 29, 2026
4 checks passed
@yukicoder0509
yukicoder0509 deleted the logging-v2 branch August 29, 2026 08:10
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants