klog, zap, logrus などで stderr に吐かれるログのレベルを Datadog で良い感じにする
こんにちは、@key60228 です。
新しく立ち上げた GKE Cluster に Datadog Agent を入れてログを有効化してみたところ、とんでもない数のエラーログが吐かれていました。
まだ何も特別なことをしていないのに…？？？と不思議に思いログの詳細を見てみたところ、特に問題なさそうなログがほとんどでした。
結論としては、各コンポーネントが吐くログが Datadog が解釈できる形式で構造化されておらず、エラーレベルとして判定されてしまっていることが原因でした。
というわけでこの記事では各コンポーネント、ロガーがどんな構造で出力していて、どうすれば正しいログレベルで表示できるのかについてまとめていければと思います。
ソリューションを求めている方へ
Datadog のログパイプラインで加工してあげてください。
Terraform
pipelines.tf
resource "datadog_logs_custom_pipeline" "container_log_level" {
name = "container-log-level"
description = "stderr 由来で error になったコンテナログの status を、本文の klog / zap / logfmt のレベルから付け直す。"
is_enabled = true
filter {
query = "kube_cluster_name:*"
}
processor {
grok_parser {
name = "klog / zap / logfmt からレベルを取り出す"
is_enabled = true
source = "message"
samples = [
"I0911 07:22:25.408586 1 cni_writer.go:930] Successfully synced \"gke-xxxxx-xxxxx-nod-xxxxxxxx-xxxx\"", # klog (GKE cni-writer)
"E0911 07:10:07.225293 1 base_controller.go:161] \"controller failed to sync\" err=\"...\" key=\"image-sync\"", # klog (OCM work-agent)
"2026-09-11T07:19:45Z\tINFO\tcontrollers.Spoke\trequeueing\t{\"request\": {\"name\":\"xxx\",\"namespace\":\"fleetconfig-system\"}, \"after\": \"1m0s\"}", # zap console、タブ区切り (fleetconfig-controller)
"2026-09-11T04:39:22.159Z error logging/logging.go:16 NodeCollector: Failed to export metrics {\"kind\": \"receiver\"}", # zap console、スペース区切り (gke-metrics-agent)
"time=2026-09-11T06:13:28Z level=info msg=Reconciling subsys=sfc reasons=[...]", # logfmt / logrus (cilium)
]
grok {
support_rules = ""
match_rules = file("${path.module}/grok/container_log_level.grok")
}
}
}
processor {
lookup_processor {
name = "klog の severity 1 文字をレベル語に直す"
is_enabled = true
source = "klog.severity"
target = "level"
lookup_table = [
"I,info",
"W,warning",
"E,error",
"F,critical",
]
}
}
processor {
lookup_processor {
name = "zap のレベルを status remapper が解釈できる語に直す"
is_enabled = true
source = "zap.level"
target = "level"
lookup_table = [
"DEBUG,debug",
"INFO,info",
"WARN,warning",
"ERROR,error",
"DPANIC,critical",
"PANIC,critical",
"FATAL,critical",
]
}
}
processor {
lookup_processor {
name = "logrus のレベルを status remapper が解釈できる語に直す"
is_enabled = true
source = "logfmt.level"
target = "level"
lookup_table = [
"trace,debug",
"debug,debug",
"info,info",
"warning,warning",
"error,error",
"fatal,critical",
"panic,critical",
]
}
}
processor {
status_remapper {
name = "level を status にする"
is_enabled = true
sources = ["level"]
}
}
}
grok/container_log_level.grok
klog %{regex("[IWEF]"):klog.severity}%{regex("\d{4} \d{2}:\d{2}:\d{2}\.\d+")}\s+%{integer:klog.thread_id}\s+%{regex("[^\]]+"):klog.location}]\s?%{data:klog.message}
zap %{regex("\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d+)?(Z|[+-]\d{2}:\d{2})"):zap.timestamp}[\t ]+%{regex("(DEBUG|INFO|WARN|ERROR|DPANIC|PANIC|FATAL|debug|info|warn|error|dpanic|panic|fatal)"):zap.level:uppercase}[\t ]+%{data:zap.message}
logfmt_with_time time=%{notSpace:logfmt.time}\s+level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message}
logfmt level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message}
Datadog Log Management のログレベルの仕組み
Datadog のログでは status という予約済み属性が Log Explorer で表示されるログレベルに対応しています。1
Datadog Agent を使っている場合、この status は次の3つのタイミングで決まります。
Datadog Agent がログを送る時
Datadog が JSON ログをパースする時
ログパイプラインの Status Remapper を通る時
① Datadog Agent がログを送る時
Kubernetes の Datadog Agent (各ノードの DaemonSet) では stdout に出たものを info、stderr に出たものを error と判定して Datadog に送っているようです。
github.com/DataDog/datadog-agent/blob/f85c4980d2b…
② Datadog が JSON ログをパースする時
次に、ログが JSON 形式であれば、Datadog は取り込み時の前処理で status、severity、level などの属性を探し、見つかった値で status を上書きします。2
{"level":"info","msg":"..."} のようなログは、stderr に書かれていても info として扱われます。
③ ログパイプラインの Status Remapper を通る時
最後に、ログパイプライン に Status Remapper を置くと、任意の属性の値で status を上書きできます。
Status Remapper は指定された属性の値を先頭の文字列で以下の通り判定してくれます。3
値
status
0 から 7 の整数
Syslog の規格に従う
emerg または f で始まる文字列 (大文字小文字を区別しない)
emerg (0)
a で始まる文字列 (大文字小文字を区別しない)
alert (1)
c で始まる文字列 (大文字小文字を区別しない)
critical (2)
err で始まる文字列 (大文字小文字を区別しない)
error (3)
w で始まる文字列 (大文字小文字を区別しない)
warning (4)
n で始まる文字列 (大文字小文字を区別しない)
notice (5)
i で始まる文字列 (大文字小文字を区別しない)
info (6)
d、t、v、trace、verbose で始まる文字列 (大文字小文字を区別しない)
debug (7)
o または s で始まる文字列、または OK か Success に一致する文字列 (大文字小文字を区別しない)
OK
上記以外
info (6)
つまり、プレーンテキストの本文にレベルを埋め込んでいるログは、②の前処理では拾われず、③のパイプラインを用意しない限り①のストリームだけで status が決まります。
今回の自分の環境のエラーログは、まさにこのパターンでした。
対策と各コンポーネント/ロガーの仕組み
根本的には各コンポーネントが JSON でログを吐くか、レベルに応じて stdout/stderr を使い分けていればこういった問題は起きません。
しかし GKE が管理するシステムコンポーネントは出力形式をこちら側では変えられず、OSS のコンポーネントも全てが出力形式を選べるわけではありません。
また、Datadog Agent でストリームと status の mapping を変更する方法も現時点ではなさそうです。
となるとメッセージ本文からレベルを取り出し、Status Remapper で status 属性を更新するログパイプラインを用意するのが良さそうです。
今回の自分の環境で問題になったログは、出力元のロガーで分けると klog、zap、logrus の3種類でした。
これらのロガーで、どのようにレベルを抽出すれば良いか見ていきます。
klog
klog は glog の fork で、Kubernetes 本体も使用しているロガーです。
kubernetes/klog
今回の環境では、GKE のシステムコンポーネント (cni-writer、gke-metadata-server、proxy-agent etc.) や cert-manager などが klog かつ stderr でログを吐いていました。
klog の構造は以下のようになっており、先頭の L が severity を指しています。
Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg
github.com/kubernetes/klog/blob/ae3961e316a310e71…
severity は I が INFO、W が WARNING、E が ERROR、F が FATAL を指します。
github.com/kubernetes/klog/blob/ae3961e316a310e71…
例えば proxy-agent の次のログは INFO ですが、stderr に書かれているため Datadog 上では ERROR になっていました。
そこで、まずは Grok Parser で属性をパースしてあげます。
klog %{regex("[IWEF]"):klog.severity}%{regex("\d{4} \d{2}:\d{2}:\d{2}\.\d+")}\s+%{integer:klog.thread_id}\s+%{regex("[^\]]+"):klog.location}]\s?%{data:klog.message}
上記ルールで IWEF の値を klog.severity に書き出しましたが、klog の場合はこの severity をそのまま Status Remapper に渡すことはできません。
I と W は期待通り info と warning になり、F は emergency になりますが、E は何にも当てはまらず、info になってしまいます。
そこで、Lookup Processor で klog.severity を調整してから level 属性に入れます。 (ついでに F も critical に調整しています)
I,info
W,warning
E,error
F,critical
その後 Status Remapper を挟んであげることで、proxy-agent の INFO ログは info として表示されるようになりました。
zap
zap は Uber が開発しているロガーで、Kubernetes 周りでは controller-runtime を使ったコントローラーの多くが zap を使っています。
uber-go/zap
今回の環境では、gke-metrics-agent や 別記事 で導入していた Open Cluster Management の fleetconfig-controller が zap でログを吐いていました。
zap には JSON で出力する JSON encoder と、人が読みやすいテキストで出力する console encoder があります。
github.com/uber-go/zap/blob/4892335e05f14bce8a98a…
console encoder はデフォルトでは、タイムスタンプ、レベル、ロガー名、呼び出し元、メッセージ、追加フィールド (JSON) を区切り文字でつないで 1 行にします。
TIMESTAMP LEVEL LOGGER CALLER MESSAGE {FIELDS}
zap の console encoder の出力は、次のルールで分解します。
zap %{regex("\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d+)?(Z|[+-]\d{2}:\d{2})"):zap.timestamp}[\t ]+%{regex("(DEBUG|INFO|WARN|ERROR|DPANIC|PANIC|FATAL|debug|info|warn|error|dpanic|panic|fatal)"):zap.level:uppercase}[\t ]+%{data:zap.message}
同じ console encoder でも、出力の細かいところはコンポーネントによって異なっているため、区切り文字はタブと半角スペース、レベルは大文字と小文字の両方に対応しています。
zap のレベルは DEBUG、INFO、WARN、ERROR、DPANIC、PANIC、FATAL とあり、今のままだと DPANIC が debug に、PANIC が info になってしまいます。
ついでに FATAL は klog に合わせて critical として扱うよう、Lookup Processor で調整してあげます。
github.com/uber-go/zap/blob/4892335e05f14bce8a98a…
"DEBUG,debug",
"INFO,info",
"WARN,warning",
"ERROR,error",
"DPANIC,critical",
"PANIC,critical",
"FATAL,critical",
なお、controller-runtime の zap のオプションをコマンドライン引数に結び付けているコントローラーであれば、--zap-encoder=json を渡して JSON encoder に切り替えられます。
JSON encoder の出力には level 属性が含まれるので、前処理で status に反映され、パイプラインは要りません。
logrus
logrus もメジャーな構造化ロガーで、今回の環境では Zitadel が logrus でログを出していました。
sirupsen/logrus
出力形式は TextFormatter と JSONFormatter から選べ、TextFormatter は端末以外に出力するとき key=value を並べた logfmt 風の形式になります。
time="2026-10-13T05:58:18Z" level=INFO msg="structured logger configured" caller="..." error="..."
レベルは level= の後ろに info、warning、error のような語で書かれます。
スクリーンショットのログは level=INFO ですが、Datadog 上では ERROR になっていました。
logrus の TextFormatter の出力は、次の 2 つのルールで分解します。
logfmt_with_time time=%{notSpace:logfmt.time}\s+level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message}
logfmt level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message}
TextFormatter は設定によってタイムスタンプを出さないことがあるため、time= で始まる行と level= で始まる行の両方に対応しています。
今回のログのように時刻を time="..." と引用符で囲む場合も、引用符ごと notSpace で logfmt.time に取り込まれるので問題ありません。
logrus のレベルは以下の通りなので、zap 同様に Lookup Processor で調整してあげましょう。
github.com/sirupsen/logrus/blob/6ef0748d1177dadae…
"trace,debug",
"debug,debug",
"info,info",
"warning,warning",
"error,error",
"fatal,critical",
"panic,critical",
これでログレベルが正しく表現されるようになりました。
!
この記事の本筋とズレるので本文では言及しませんでしたが、ZITADEL はオプションでログフォーマットを JSON 化できます。4
まとめ
パイプラインを適用したあとは、status:error のログがほとんどなくなりました。
これで万事解決…とは思いつつ、klog、zap、logrus とは異なる出力形式を持つロガーを採用しているコンポーネントが出てきたらその都度対応しないといけない…？ 🤔
GKE とか各 KaaS のシステムコンポーネント以外は大概ログの format などをこっちで指定できるから特に問題にならないのかな〜〜とは思いつつ、こんな複雑なことをしないといけないのはちょっと不思議な気がするな〜〜 5
もっと良い方法あるよって方、もし居たら教えてください〜〜
最後に
AI Shiftではエンジニアの採用に力を入れています！少しでも興味を持っていただけましたら、カジュアル面談でお話しませんか？（オンライン・19時以降の面談も可能です！）
【面談フォームはこちら】
hrmos.co
脚注
属性とエイリアス設定 - Datadog Docs ↩︎
Pipelines (Preprocessing) - Datadog Docs ↩︎
Log Status Remapper - Datadog Docs ↩︎
ZITADEL Production Setup - ZITADEL Docs ↩︎
「こんな複雑なことをしないといけないのはおかしい」というソフトウェアエンジニアの勘 - valid,invalid ↩︎
Go 1.27 Finds Leaked Goroutines With the Garbage Collector. Here's What It Misses
- Book: The Complete Guide to Go Programming
- Also by me: Pocket Guides for Developers — the 8-book series
- My project: Hermes IDE | GitHub — an IDE for developers who ship with Claude Code and other AI coding tools
- Me: xgabriel.com | GitHub
---
When researchers pointed a prototype detector at one of Uber's production Go services, it found hundreds of previously hidden partial deadlocks: goroutines parked on a channel or a lock that nothing would ever release. Each one kept its stack and everything that stack pointed to. None of them raised an error.
That detector now lives in the Go runtime. Go 1.26 shipped it as an experimental profile behind GOEXPERIMENT=goroutineleakprofile. Go 1.27, released on 19 August 2026, made the goroutineleak profile generally available and deleted the experiment flag. You read it from runtime/pprof or from the /debug/pprof/goroutineleak endpoint.
The interesting part is how it decides that a goroutine is leaked. There are no timers and no "blocked for more than ten minutes" heuristics. The runtime asks the garbage collector a reachability question. Once you see the question, you can predict which leaks it will report and which ones it will never notice.
What "leaked" means to the runtime
The release notes define it precisely: a leaked goroutine is one "blocked on some concurrency primitive (channels, sync.Mutex, sync.Cond, etc) that cannot possibly become unblocked."
Think about what it takes to wake a goroutine stuck on ch <- v. Some other goroutine has to run <-ch. To do that, it needs a reference to ch. If no goroutine that could ever run again holds a pointer to that channel, the send can never complete. And "who holds a pointer to what" is exactly what the garbage collector computes on every cycle.
The Go blog post on leak profiles states the rule inductively. A goroutine is live if it is not blocked, or if at least one primitive blocking it is referenced by another live goroutine. Everything else is leaked.
The primitives covered are channel sends and receives (nil channels included), blocking select (empty select {} included), sync.Mutex, sync.RWMutex, sync.WaitGroup and sync.Cond, per the same post. A goroutine blocked on file or network IO, a raw system call, or a hand-rolled primitive that is not built on those is never reported.
How the mark phase answers "can anything wake this up?"
In a normal GC cycle, every goroutine's stack is a root. A leak-detection cycle changes that. The design document by Georgian-Vlad Saioc and Milind Chabbi lays out the loop:
1. Treat only runnable goroutines as goroutine roots.
2. Mark everything reachable from the roots.
3. Check each unmarked, blocked goroutine. If the primitive it waits on was marked, some live goroutine can reach it, so this goroutine is "eventually runnable." Add it as a root.
4. Resume marking from step 2. Stop when no new goroutine gets promoted.
5. Every blocked goroutine that never became a root is leaked. Mark from those too, so the heap ends up marked the same way a regular cycle would mark it, then sweep as usual.
That final step matters for what you expect in production. The profile reports leaks; it does not reclaim them. The blog says the last round lets the GC "mark all the memory it would have marked during a regular run."
There is one wiring problem the loop has to solve. A blocked goroutine is attached to its channel through a sudog, the runtime's record for "a g in a wait list." In runtime2.go, the sudog's channel field is a maybeTraceableChan and its data field is a maybeTraceablePtr. Sudogs are reachable from the global goroutine list and the semaphore table, according to the design doc. If the GC traced those fields normally, every channel with a waiter would be marked through the waiter itself, and nothing would ever look leaked.
So the pointer is stored twice: once as a uintptr (vu, the "source of truth") and once as an unsafe.Pointer (vp, "for liveness only"). When a leak-detection cycle starts, the runtime makes the vp half of every sudog untraceable, so the GC cannot follow the pointer while the address stays recorded. When the cycle ends, it makes them traceable again. The waiter still knows which channel it is parked on, and that knowledge no longer counts as a reason to keep the channel alive.
The blocked goroutine's own stack gets the same treatment by construction. It is not a root until it gets promoted, so the ch variable sitting in its closure does not mark the channel either. A goroutine that survives the whole loop ends up in a new status, _Gleaked, which runtime2.go documents as "a leaked goroutine caught by the GC."
A leak it catches
Here is the classic timeout leak. The worker sends on an unbuffered channel, the caller gives up first, and the send blocks forever.
package main
import (
"context"
"fmt"
"os"
"runtime/pprof"
"time"
)
func fetch(ctx context.Context) error {
ch := make(chan error) // unbuffered: the bug
go func() {
time.Sleep(50 * time.Millisecond)
ch <- nil // nobody receives after a timeout
}()
select {
case err := <-ch:
return err
case <-ctx.Done():
return ctx.Err()
}
}
func main() {
for range 3 {
ctx, cancel := context.WithTimeout(
context.Background(), 10*time.Millisecond)
_ = fetch(ctx)
cancel()
}
time.Sleep(200 * time.Millisecond) // senders block
p := pprof.Lookup("goroutineleak")
if p == nil {
fmt.Println("needs Go 1.27, or 1.26 with " +
"GOEXPERIMENT=goroutineleakprofile")
return
}
p.WriteTo(os.Stdout, 1)
}
On Go 1.27, go run . is enough. On Go 1.26, build with GOEXPERIMENT=goroutineleakprofile go run .. Writing the profile triggers a leak-detecting GC cycle and waits for it, as the design doc describes, and debug=1 gives you the text format with function names and line numbers.
Walk through it with the loop above. After each fetch returns, main's frame no longer holds ch. The only remaining references live in the sender's closure and in its sudog. The sender is blocked, so its stack is not a root. The sudog's channel pointer is hidden for the cycle. Nothing marks the channel, so none of the three senders gets promoted, and all three should land in the profile with stacks pointing at the ch <- nil line. I haven't run this exact snippet, so treat that as what the mechanism predicts, not pasted output.
The fix is the one the Go blog gives for its own timeout example: give the channel a buffer of size 1. Then make(chan error, 1) lets the late sender drop its value and exit.
A leak it cannot see
Now move the channel to package level.
var results = make(chan error) // package-level
func fetchGlobal(ctx context.Context) error {
go func() {
time.Sleep(50 * time.Millisecond)
results <- nil // same leak as before
}()
select {
case err := <-results:
return err
case <-ctx.Done():
return ctx.Err()
}
}
The leak is the same: every timed-out call can strand a sender. Sharing the channel also adds a second bug, because a later call can now receive an earlier call's stale result. The profile stays quiet.
Package-level variables are always roots. In step 2 the GC marks results straight from the global, the blocked senders look "eventually runnable" in step 3, and they never reach the leaked set. The Go 1.26 release notes spell this out: "the runtime may fail to identify leaks caused by blocking on concurrency primitives reachable through global variables or the local variables of runnable goroutines."
The second half of that sentence catches more real code than the first. A long-lived worker goroutine that keeps a map of per-request channels in a local variable, and never reads some of them, keeps every one of those channels marked. So does a struct of channels hanging off a server object that a running goroutine still references. The design doc puts it plainly: the detector's "effectiveness is reduced the more heap resources are over-exposed in memory."
That gives you a design rule the detector rewards. Create channels as close to their use as you can, scope them to one request or one call, and do not park them in registries that outlive the work. The narrower the reachability, the more the GC can prove.
Running it in production and in tests
If a service already imports net/http/pprof, Go 1.27 adds the endpoint with no code change. The blog's workflow, with the address left as a placeholder:
# ADDR: wherever net/http/pprof listens in your service
curl "$ADDR/debug/pprof/goroutineleak" > leak.prof
go tool pprof leak.prof
Inside pprof, list fetch (or whatever function spawned the goroutine) shows the blocked line in context.
On cost, the Go 1.26 notes say the feature is designed "to not incur any additional run-time overhead unless it is actively in-use." When you do request it, there is a worst case. The blog describes a leak-free "daisy chain" where runnable G0 references the primitive blocking G1, G1 references the one blocking G2, and so on. Each link only proves live after the previous one, which serializes marking and gives O(n²) steps for one GC cycle, with n the number of goroutines. The blog's answer is to profile periodically, every 4 hours in its example, since a leak that can be observed once stays observable.
The design doc calls the approach "theoretically sound, i.e., there are no false positives," and the blog describes it as "precise" with "little-to-no false positives," so treat a goroutine in the report as a strong signal that it is stuck. The detector also only sees leaks that have already happened. The blog recommends pairing it with goleak in test suites, which flags goroutines still running when a test ends, and with testing/synctest, whose fake clock lets a timeout path run deterministically.
When the profile comes back empty and memory still climbs, check your package-level channels first.
---
If this was useful
The leak profile makes sense once you know what the runtime does underneath your code: how goroutines park on channels and what the garbage collector treats as a root. The Complete Guide to Go Programming covers the runtime and its concurrency primitives with that picture in mind, including the channel and context patterns that keep a goroutine from getting stranded in the first place.
Mentions
klog, zap, logrus などで stderr に吐かれるログのレベルを Datadog で良い感じにする こんにちは、@key60228 です。 新しく立ち上げた GKE Cluster に Datadog Agent を入れてログを有効化してみたところ、とんでもない数のエラーログが吐かれていました。 まだ何も特別なことをしていないのに…？？？と不思議に思いログの詳細を見てみたところ、特に問題なさそうなログがほとんどでした。 結論としては、各コンポーネントが吐くログが Datadog が解釈できる形式で構造化されておらず、エラーレベルとして判定されてしまっていることが原因でした。 というわけでこの記事では各コンポーネント、ロガーがどんな構造で出力していて、どうすれば正しいログレベルで表示できるのかについてまとめていければと思います。 ソリューションを求めている方へ Datadog のログパイプラインで加工してあげてください。 Terraform pipelines.tf resource "datadog_logs_custom_pipeline" "container_log_level" { name = "container-log-level" description = "stderr 由来で error になったコンテナログの status を、本文の klog / zap / logfmt のレベルから付け直す。" is_enabled = true filter { query = "kube_cluster_name:*" } processor { grok_parser { name = "klog / zap / logfmt からレベルを取り出す" is_enabled = true source = "message" samples = [ "I0911 07:22:25.408586 1 cni_writer.go:930] Successfully synced \"gke-xxxxx-xxxxx-nod-xxxxxxxx-xxxx\"", # klog (GKE cni-writer) "E0911 07:10:07.225293 1 base_controller.go:161] \"controller failed to sync\" err=\"...\" key=\"image-sync\"", # klog (OCM work-agent) "2026-09-11T07:19:45Z\tINFO\tcontrollers.Spoke\trequeueing\t{\"request\": {\"name\":\"xxx\",\"namespace\":\"fleetconfig-system\"}, \"after\": \"1m0s\"}", # zap console、タブ区切り (fleetconfig-controller) "2026-09-11T04:39:22.159Z error logging/logging.go:16 NodeCollector: Failed to export metrics {\"kind\": \"receiver\"}", # zap console、スペース区切り (gke-metrics-agent) "time=2026-09-11T06:13:28Z level=info msg=Reconciling subsys=sfc reasons=[...]", # logfmt / logrus (cilium) ] grok { support_rules = "" match_rules = file("${path.module}/grok/container_log_level.grok") } } } processor { lookup_processor { name = "klog の severity 1 文字をレベル語に直す" is_enabled = true source = "klog.severity" target = "level" lookup_table = [ "I,info", "W,warning", "E,error", "F,critical", ] } } processor { lookup_processor { name = "zap のレベルを status remapper が解釈できる語に直す" is_enabled = true source = "zap.level" target = "level" lookup_table = [ "DEBUG,debug", "INFO,info", "WARN,warning", "ERROR,error", "DPANIC,critical", "PANIC,critical", "FATAL,critical", ] } } processor { lookup_processor { name = "logrus のレベルを status remapper が解釈できる語に直す" is_enabled = true source = "logfmt.level" target = "level" lookup_table = [ "trace,debug", "debug,debug", "info,info", "warning,warning", "error,error", "fatal,critical", "panic,critical", ] } } processor { status_remapper { name = "level を status にする" is_enabled = true sources = ["level"] } } } grok/container_log_level.grok klog %{regex("[IWEF]"):klog.severity}%{regex("\d{4} \d{2}:\d{2}:\d{2}\.\d+")}\s+%{integer:klog.thread_id}\s+%{regex("[^\]]+"):klog.location}]\s?%{data:klog.message} zap %{regex("\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d+)?(Z|[+-]\d{2}:\d{2})"):zap.timestamp}[\t ]+%{regex("(DEBUG|INFO|WARN|ERROR|DPANIC|PANIC|FATAL|debug|info|warn|error|dpanic|panic|fatal)"):zap.level:uppercase}[\t ]+%{data:zap.message} logfmt_with_time time=%{notSpace:logfmt.time}\s+level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message} logfmt level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message} Datadog Log Management のログレベルの仕組み Datadog のログでは status という予約済み属性が Log Explorer で表示されるログレベルに対応しています。1 Datadog Agent を使っている場合、この status は次の3つのタイミングで決まります。 Datadog Agent がログを送る時 Datadog が JSON ログをパースする時 ログパイプラインの Status Remapper を通る時 ① Datadog Agent がログを送る時 Kubernetes の Datadog Agent (各ノードの DaemonSet) では stdout に出たものを info、stderr に出たものを error と判定して Datadog に送っているようです。 github.com/DataDog/datadog-agent/blob/f85c4980d2b… ② Datadog が JSON ログをパースする時 次に、ログが JSON 形式であれば、Datadog は取り込み時の前処理で status、severity、level などの属性を探し、見つかった値で status を上書きします。2 {"level":"info","msg":"..."} のようなログは、stderr に書かれていても info として扱われます。 ③ ログパイプラインの Status Remapper を通る時 最後に、ログパイプライン に Status Remapper を置くと、任意の属性の値で status を上書きできます。 Status Remapper は指定された属性の値を先頭の文字列で以下の通り判定してくれます。3 値 status 0 から 7 の整数 Syslog の規格に従う emerg または f で始まる文字列 (大文字小文字を区別しない) emerg (0) a で始まる文字列 (大文字小文字を区別しない) alert (1) c で始まる文字列 (大文字小文字を区別しない) critical (2) err で始まる文字列 (大文字小文字を区別しない) error (3) w で始まる文字列 (大文字小文字を区別しない) warning (4) n で始まる文字列 (大文字小文字を区別しない) notice (5) i で始まる文字列 (大文字小文字を区別しない) info (6) d、t、v、trace、verbose で始まる文字列 (大文字小文字を区別しない) debug (7) o または s で始まる文字列、または OK か Success に一致する文字列 (大文字小文字を区別しない) OK 上記以外 info (6) つまり、プレーンテキストの本文にレベルを埋め込んでいるログは、②の前処理では拾われず、③のパイプラインを用意しない限り①のストリームだけで status が決まります。 今回の自分の環境のエラーログは、まさにこのパターンでした。 対策と各コンポーネント/ロガーの仕組み 根本的には各コンポーネントが JSON でログを吐くか、レベルに応じて stdout/stderr を使い分けていればこういった問題は起きません。 しかし GKE が管理するシステムコンポーネントは出力形式をこちら側では変えられず、OSS のコンポーネントも全てが出力形式を選べるわけではありません。 また、Datadog Agent でストリームと status の mapping を変更する方法も現時点ではなさそうです。 となるとメッセージ本文からレベルを取り出し、Status Remapper で status 属性を更新するログパイプラインを用意するのが良さそうです。 今回の自分の環境で問題になったログは、出力元のロガーで分けると klog、zap、logrus の3種類でした。 これらのロガーで、どのようにレベルを抽出すれば良いか見ていきます。 klog klog は glog の fork で、Kubernetes 本体も使用しているロガーです。 kubernetes/klog 今回の環境では、GKE のシステムコンポーネント (cni-writer、gke-metadata-server、proxy-agent etc.) や cert-manager などが klog かつ stderr でログを吐いていました。 klog の構造は以下のようになっており、先頭の L が severity を指しています。 Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg github.com/kubernetes/klog/blob/ae3961e316a310e71… severity は I が INFO、W が WARNING、E が ERROR、F が FATAL を指します。 github.com/kubernetes/klog/blob/ae3961e316a310e71… 例えば proxy-agent の次のログは INFO ですが、stderr に書かれているため Datadog 上では ERROR になっていました。 そこで、まずは Grok Parser で属性をパースしてあげます。 klog %{regex("[IWEF]"):klog.severity}%{regex("\d{4} \d{2}:\d{2}:\d{2}\.\d+")}\s+%{integer:klog.thread_id}\s+%{regex("[^\]]+"):klog.location}]\s?%{data:klog.message} 上記ルールで IWEF の値を klog.severity に書き出しましたが、klog の場合はこの severity をそのまま Status Remapper に渡すことはできません。 I と W は期待通り info と warning になり、F は emergency になりますが、E は何にも当てはまらず、info になってしまいます。 そこで、Lookup Processor で klog.severity を調整してから level 属性に入れます。 (ついでに F も critical に調整しています) I,info W,warning E,error F,critical その後 Status Remapper を挟んであげることで、proxy-agent の INFO ログは info として表示されるようになりました。 zap zap は Uber が開発しているロガーで、Kubernetes 周りでは controller-runtime を使ったコントローラーの多くが zap を使っています。 uber-go/zap 今回の環境では、gke-metrics-agent や 別記事 で導入していた Open Cluster Management の fleetconfig-controller が zap でログを吐いていました。 zap には JSON で出力する JSON encoder と、人が読みやすいテキストで出力する console encoder があります。 github.com/uber-go/zap/blob/4892335e05f14bce8a98a… console encoder はデフォルトでは、タイムスタンプ、レベル、ロガー名、呼び出し元、メッセージ、追加フィールド (JSON) を区切り文字でつないで 1 行にします。 TIMESTAMP LEVEL LOGGER CALLER MESSAGE {FIELDS} zap の console encoder の出力は、次のルールで分解します。 zap %{regex("\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d+)?(Z|[+-]\d{2}:\d{2})"):zap.timestamp}[\t ]+%{regex("(DEBUG|INFO|WARN|ERROR|DPANIC|PANIC|FATAL|debug|info|warn|error|dpanic|panic|fatal)"):zap.level:uppercase}[\t ]+%{data:zap.message} 同じ console encoder でも、出力の細かいところはコンポーネントによって異なっているため、区切り文字はタブと半角スペース、レベルは大文字と小文字の両方に対応しています。 zap のレベルは DEBUG、INFO、WARN、ERROR、DPANIC、PANIC、FATAL とあり、今のままだと DPANIC が debug に、PANIC が info になってしまいます。 ついでに FATAL は klog に合わせて critical として扱うよう、Lookup Processor で調整してあげます。 github.com/uber-go/zap/blob/4892335e05f14bce8a98a… "DEBUG,debug", "INFO,info", "WARN,warning", "ERROR,error", "DPANIC,critical", "PANIC,critical", "FATAL,critical", なお、controller-runtime の zap のオプションをコマンドライン引数に結び付けているコントローラーであれば、--zap-encoder=json を渡して JSON encoder に切り替えられます。 JSON encoder の出力には level 属性が含まれるので、前処理で status に反映され、パイプラインは要りません。 logrus logrus もメジャーな構造化ロガーで、今回の環境では Zitadel が logrus でログを出していました。 sirupsen/logrus 出力形式は TextFormatter と JSONFormatter から選べ、TextFormatter は端末以外に出力するとき key=value を並べた logfmt 風の形式になります。 time="2026-10-13T05:58:18Z" level=INFO msg="structured logger configured" caller="..." error="..." レベルは level= の後ろに info、warning、error のような語で書かれます。 スクリーンショットのログは level=INFO ですが、Datadog 上では ERROR になっていました。 logrus の TextFormatter の出力は、次の 2 つのルールで分解します。 logfmt_with_time time=%{notSpace:logfmt.time}\s+level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message} logfmt level=%{word:logfmt.level:lowercase}\s+%{data:logfmt.message} TextFormatter は設定によってタイムスタンプを出さないことがあるため、time= で始まる行と level= で始まる行の両方に対応しています。 今回のログのように時刻を time="..." と引用符で囲む場合も、引用符ごと notSpace で logfmt.time に取り込まれるので問題ありません。 logrus のレベルは以下の通りなので、zap 同様に Lookup Processor で調整してあげましょう。 github.com/sirupsen/logrus/blob/6ef0748d1177dadae… "trace,debug", "debug,debug", "info,info", "warning,warning", "error,error", "fatal,critical", "panic,critical", これでログレベルが正しく表現されるようになりました。 ! この記事の本筋とズレるので本文では言及しませんでしたが、ZITADEL はオプションでログフォーマットを JSON 化できます。4 まとめ パイプラインを適用したあとは、status:error のログがほとんどなくなりました。 これで万事解決…とは思いつつ、klog、zap、logrus とは異なる出力形式を持つロガーを採用しているコンポーネントが出てきたらその都度対応しないといけない…？ 🤔 GKE とか各 KaaS のシステムコンポーネント以外は大概ログの format などをこっちで指定できるから特に問題にならないのかな〜〜とは思いつつ、こんな複雑なことをしないといけないのはちょっと不思議な気がするな〜〜 5 もっと良い方法あるよって方、もし居たら教えてください〜〜 最後に AI Shiftではエンジニアの採用に力を入れています！少しでも興味を持っていただけましたら、カジュアル面談でお話しませんか？（オンライン・19時以降の面談も可能です！） 【面談フォームはこちら】 hrmos.co 脚注 属性とエイリアス設定 - Datadog Docs ↩︎ Pipelines (Preprocessing) - Datadog Docs ↩︎ Log Status Remapper - Datadog Docs ↩︎ ZITADEL Production Setup - ZITADEL Docs ↩︎ 「こんな複雑なことをしないといけないのはおかしい」というソフトウェアエンジニアの勘 - valid,invalid ↩︎
Go 1.27 Finds Leaked Goroutines With the Garbage Collector. Here's What It Misses - Book: The Complete Guide to Go Programming - Also by me: Pocket Guides for Developers — the 8-book series - My project: Hermes IDE | GitHub — an IDE for developers who ship with Claude Code and other AI coding tools - Me: xgabriel.com | GitHub --- When researchers pointed a prototype detector at one of Uber's production Go services, it found hundreds of previously hidden partial deadlocks: goroutines parked on a channel or a lock that nothing would ever release. Each one kept its stack and everything that stack pointed to. None of them raised an error. That detector now lives in the Go runtime. Go 1.26 shipped it as an experimental profile behind GOEXPERIMENT=goroutineleakprofile. Go 1.27, released on 19 August 2026, made the goroutineleak profile generally available and deleted the experiment flag. You read it from runtime/pprof or from the /debug/pprof/goroutineleak endpoint. The interesting part is how it decides that a goroutine is leaked. There are no timers and no "blocked for more than ten minutes" heuristics. The runtime asks the garbage collector a reachability question. Once you see the question, you can predict which leaks it will report and which ones it will never notice. What "leaked" means to the runtime The release notes define it precisely: a leaked goroutine is one "blocked on some concurrency primitive (channels, sync.Mutex, sync.Cond, etc) that cannot possibly become unblocked." Think about what it takes to wake a goroutine stuck on ch <- v. Some other goroutine has to run <-ch. To do that, it needs a reference to ch. If no goroutine that could ever run again holds a pointer to that channel, the send can never complete. And "who holds a pointer to what" is exactly what the garbage collector computes on every cycle. The Go blog post on leak profiles states the rule inductively. A goroutine is live if it is not blocked, or if at least one primitive blocking it is referenced by another live goroutine. Everything else is leaked. The primitives covered are channel sends and receives (nil channels included), blocking select (empty select {} included), sync.Mutex, sync.RWMutex, sync.WaitGroup and sync.Cond, per the same post. A goroutine blocked on file or network IO, a raw system call, or a hand-rolled primitive that is not built on those is never reported. How the mark phase answers "can anything wake this up?" In a normal GC cycle, every goroutine's stack is a root. A leak-detection cycle changes that. The design document by Georgian-Vlad Saioc and Milind Chabbi lays out the loop: 1. Treat only runnable goroutines as goroutine roots. 2. Mark everything reachable from the roots. 3. Check each unmarked, blocked goroutine. If the primitive it waits on was marked, some live goroutine can reach it, so this goroutine is "eventually runnable." Add it as a root. 4. Resume marking from step 2. Stop when no new goroutine gets promoted. 5. Every blocked goroutine that never became a root is leaked. Mark from those too, so the heap ends up marked the same way a regular cycle would mark it, then sweep as usual. That final step matters for what you expect in production. The profile reports leaks; it does not reclaim them. The blog says the last round lets the GC "mark all the memory it would have marked during a regular run." There is one wiring problem the loop has to solve. A blocked goroutine is attached to its channel through a sudog, the runtime's record for "a g in a wait list." In runtime2.go, the sudog's channel field is a maybeTraceableChan and its data field is a maybeTraceablePtr. Sudogs are reachable from the global goroutine list and the semaphore table, according to the design doc. If the GC traced those fields normally, every channel with a waiter would be marked through the waiter itself, and nothing would ever look leaked. So the pointer is stored twice: once as a uintptr (vu, the "source of truth") and once as an unsafe.Pointer (vp, "for liveness only"). When a leak-detection cycle starts, the runtime makes the vp half of every sudog untraceable, so the GC cannot follow the pointer while the address stays recorded. When the cycle ends, it makes them traceable again. The waiter still knows which channel it is parked on, and that knowledge no longer counts as a reason to keep the channel alive. The blocked goroutine's own stack gets the same treatment by construction. It is not a root until it gets promoted, so the ch variable sitting in its closure does not mark the channel either. A goroutine that survives the whole loop ends up in a new status, _Gleaked, which runtime2.go documents as "a leaked goroutine caught by the GC." A leak it catches Here is the classic timeout leak. The worker sends on an unbuffered channel, the caller gives up first, and the send blocks forever. package main import ( "context" "fmt" "os" "runtime/pprof" "time" ) func fetch(ctx context.Context) error { ch := make(chan error) // unbuffered: the bug go func() { time.Sleep(50 * time.Millisecond) ch <- nil // nobody receives after a timeout }() select { case err := <-ch: return err case <-ctx.Done(): return ctx.Err() } } func main() { for range 3 { ctx, cancel := context.WithTimeout( context.Background(), 10*time.Millisecond) _ = fetch(ctx) cancel() } time.Sleep(200 * time.Millisecond) // senders block p := pprof.Lookup("goroutineleak") if p == nil { fmt.Println("needs Go 1.27, or 1.26 with " + "GOEXPERIMENT=goroutineleakprofile") return } p.WriteTo(os.Stdout, 1) } On Go 1.27, go run . is enough. On Go 1.26, build with GOEXPERIMENT=goroutineleakprofile go run .. Writing the profile triggers a leak-detecting GC cycle and waits for it, as the design doc describes, and debug=1 gives you the text format with function names and line numbers. Walk through it with the loop above. After each fetch returns, main's frame no longer holds ch. The only remaining references live in the sender's closure and in its sudog. The sender is blocked, so its stack is not a root. The sudog's channel pointer is hidden for the cycle. Nothing marks the channel, so none of the three senders gets promoted, and all three should land in the profile with stacks pointing at the ch <- nil line. I haven't run this exact snippet, so treat that as what the mechanism predicts, not pasted output. The fix is the one the Go blog gives for its own timeout example: give the channel a buffer of size 1. Then make(chan error, 1) lets the late sender drop its value and exit. A leak it cannot see Now move the channel to package level. var results = make(chan error) // package-level func fetchGlobal(ctx context.Context) error { go func() { time.Sleep(50 * time.Millisecond) results <- nil // same leak as before }() select { case err := <-results: return err case <-ctx.Done(): return ctx.Err() } } The leak is the same: every timed-out call can strand a sender. Sharing the channel also adds a second bug, because a later call can now receive an earlier call's stale result. The profile stays quiet. Package-level variables are always roots. In step 2 the GC marks results straight from the global, the blocked senders look "eventually runnable" in step 3, and they never reach the leaked set. The Go 1.26 release notes spell this out: "the runtime may fail to identify leaks caused by blocking on concurrency primitives reachable through global variables or the local variables of runnable goroutines." The second half of that sentence catches more real code than the first. A long-lived worker goroutine that keeps a map of per-request channels in a local variable, and never reads some of them, keeps every one of those channels marked. So does a struct of channels hanging off a server object that a running goroutine still references. The design doc puts it plainly: the detector's "effectiveness is reduced the more heap resources are over-exposed in memory." That gives you a design rule the detector rewards. Create channels as close to their use as you can, scope them to one request or one call, and do not park them in registries that outlive the work. The narrower the reachability, the more the GC can prove. Running it in production and in tests If a service already imports net/http/pprof, Go 1.27 adds the endpoint with no code change. The blog's workflow, with the address left as a placeholder: # ADDR: wherever net/http/pprof listens in your service curl "$ADDR/debug/pprof/goroutineleak" > leak.prof go tool pprof leak.prof Inside pprof, list fetch (or whatever function spawned the goroutine) shows the blocked line in context. On cost, the Go 1.26 notes say the feature is designed "to not incur any additional run-time overhead unless it is actively in-use." When you do request it, there is a worst case. The blog describes a leak-free "daisy chain" where runnable G0 references the primitive blocking G1, G1 references the one blocking G2, and so on. Each link only proves live after the previous one, which serializes marking and gives O(n²) steps for one GC cycle, with n the number of goroutines. The blog's answer is to profile periodically, every 4 hours in its example, since a leak that can be observed once stays observable. The design doc calls the approach "theoretically sound, i.e., there are no false positives," and the blog describes it as "precise" with "little-to-no false positives," so treat a goroutine in the report as a strong signal that it is stuck. The detector also only sees leaks that have already happened. The blog recommends pairing it with goleak in test suites, which flags goroutines still running when a test ends, and with testing/synctest, whose fake clock lets a timeout path run deterministically. When the profile comes back empty and memory still climbs, check your package-level channels first. --- If this was useful The leak profile makes sense once you know what the runtime does underneath your code: how goroutines park on channels and what the garbage collector treats as a root. The Complete Guide to Go Programming covers the runtime and its concurrency primitives with that picture in mind, including the channel and context patterns that keep a goroutine from getting stranded in the first place. 