controller-runtimeのロギング機能
controller-runtimeが提供するロギング機能について調べてみたら、意外と知らないことがあったので解説してみます。
対象のバージョン
- controller-runtime: 0.9.6
- kubebuilder: 3.1.0
パッケージ構成
controller-runtimeのロギング機能は、以下のパッケージから構成されています。
go-logr/logr
Go言語用のロギングAPIです。APIの定義のみで実装は提供していません。
以下のような非常にシンプルなinterfaceを提供しています。(v0.4.0時点)
type Logger interface {
Enabled() bool
Info(msg string, keysAndValues ...interface{})
Error(err error, msg string, keysAndValues ...interface{})
V(level int) Logger
WithValues(keysAndValues ...interface{}) Logger
WithName(name string) Logger
}
ライブラリやアプリケーションは、このインタフェースを利用してログ出力をおこなっておけば、簡単にロギングフレームワークを差し替えることが可能になります。
uber-go/zap
controller-runtimeが利用しているロギングフレームワークの実装です。
go-logr/zapr
zapを利用して、logrインタフェースを実装したものです。
controller-runtime/pkg/log
controller-runtimeではzap/zaprをより便利に使えるようにするために、いくつかのヘルパー関数を用意しています。
使い方
ロガーの初期化
まずは、Kubebuilderが生成した、ロガーの初期化処理を見てみましょう。
package main
import (
"flag"
ctrl "sigs.k8s.io/controller-runtime"
"sigs.k8s.io/controller-runtime/pkg/log/zap"
)
func main() {
opts := zap.Options{
Development: true,
}
opts.BindFlags(flag.CommandLine)
flag.Parse()
ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts)))
}
最初にzap.Optionsでログのオプションを用意しています。
Development: trueを指定すること、ログが人間が読みやすいプレインテキストの形式になります。
falseを指定すると構造化された形式（デフォルトではJSON）でログが出力されます。
次にopts.BindFlags()を利用することで、コマンドラインオプションに以下の4つのオプションを追加しています。
-zap-devel
Development Mode defaults(encoder=consoleEncoder,logLevel=Debug,stackTraceLevel=Warn). Production Mode defaults(encoder=jsonEncoder,logLevel=Info,stackTraceLevel=Error) (default true)
-zap-encoder value
Zap log encoding (one of 'json' or 'console')
-zap-log-level value
Zap Level to configure the verbosity of logging. Can be one of 'debug', 'info', 'error', or any integer value > 0 which corresponds to custom debug levels of increasing verbosity
-zap-stacktrace-level value
Zap Level at and above which stacktraces are captured (one of 'info', 'error', 'panic').
最後にzapのロガーを作成し、ctrl.SetLogger()で利用するロガーをセットしています。
なお、プログラム開始から30秒以内にctrl.SetLogger()を呼び出さないと、NullLoggerがセットされて正しくログが出力されない可能性があるので注意しましょう。
ログ出力
続いて、ロガーを利用してログを書き出してみましょう。
ctrl.SetLogger()でセットしたロガーは、以下のようにlog.FromContext()で取り出すことができます。
package controllers
import (
"context"
ctrl "sigs.k8s.io/controller-runtime"
"sigs.k8s.io/controller-runtime/pkg/log"
)
func (r *MyReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
logger := log.FromContext(ctx)
return ctrl.Result{}, err
}
ログ出力は以下のようにおこないます。
logger.Info("message")
keyとvalueを指定して、以下のように変数を出力することができます。
logger.Info("message", "key1", value1, "key2", value2)
keyとvalueは必ずペアで渡す必要があります。
keyとvalueの数が一致しない場合は正しくログが出力されないので注意してください。
keyは必ず文字列にしなければなりません。また、key名が重複しても問題ありません。
valueには、様々な型の変数を渡すことができます。
controller-runtimeでは、valueにKubernetesのオブジェクト（PodやDeploymentなど）を渡すと、下記のようにapiVersion, kind, namespace, nameを利用して適切なログ出力がおこなわれます。
{"level":"info","ts":1629369375.781519,"logger":"controller-runtime.manager.controller.test","msg":"message","deployment":{"apiVersion":"apps/v1","kind":"Deployment","namespace":"default","name":"sample"}}
エラー情報をロギングしたい場合はError()を利用します。
Info()とは異なり、第一引数にエラーを渡します。keyとvalueはInfo()と同じように渡すことができます。
if err != nil {
logger.Error(err, "failed to something", "key", "value")
return err
}
さらに、V()を指定してレベルの異なるログ出力をおこなうことができます。
logger.V(0).Info("message") // Info level
logger.V(1).Info("message") // Debug level
ただし、Error()はV()でレベルを変更することはできません。
MarshalLogObject
ログを出力する際のvalueには様々な型の変数を渡すことができると説明しました。
ユーザー定義型に関しても、zapcore.ObjectMarshalerインタフェースを実装することで、任意のフォーマットでログ出力ができるようになります。
例えば以下のようなデータ型を用意します。
type MySecretToken struct {
Name string
Token string
}
この型は秘密の情報を含んでいるので、ログを出力する際にはマスクして出力することにしましょう。
func (t MySecretToken) MarshalLogObject(enc zapcore.ObjectEncoder) error {
enc.AddString("name", t.Name)
if len(t.Token) == 0 {
enc.AddString("token", "<empty>")
} else {
enc.AddString("token", "****")
}
return nil
}
以下のように秘密の情報をログに出力してみます。
token := MySecretToken{
Name: "mytoken",
Token: "秘密のデータ",
}
logger.Info("Secret", "token", token)
すると、秘密の情報は以下のようにマスクして出力されました。
{"token":{"name":"mytoken","token":"****"}, ...
WithName
WithName()を利用してログを出力すると、loggerフィールドに指定した名前が付与されるようになります。
logger.WithName("a").Info("message")
なお、WithName()で指定した名前は.で連結されます。
以下のようにWithName()を複数回呼び出すと
newLogger := logger.WithName("a").WithName("b").WithName("c")
loggerフィールドは以下のようになります。
{"logger":"controller-runtime.manager.controller.test.a.b.c",...}
WithValues
Info()やError()ではkeyとvalueを指定して変数をロギングすることができます。
しかし、同じ変数を何度も指定するのは面倒です。
そこで、WithValues()を利用して新しいロガーを生成することができます。
newLogger := logger.WithValues("key1", "value1")
newLogger.Info("message")
この新しいロガーを利用してログ出力をおこなうと、指定したkeyとvalueが必ずログに含まれるようになります。
controller-runtimeが設定しているKeyValues
controller-runtimeではWithValues()を利用して、下記の変数が自動的にログ出力されるようになっています。
| キー | 説明 |
|---|---|
reconciler group |
Reconcileの対象となるリソースのAPI Group |
reconciler kind |
Reconcileの対象となるリソースのKind |
namespace |
Reconcileの対象となるリソースのNamespace |
name |
Reconcileの対象となるリソースのリソース名 |
webhook |
呼び出されたWebhookのパス |
例えば、Reconcile()の中でlogger.Info()を呼び出すと、以下のようなログが出力されます。
{"level":"info","ts":1629369608.0679593,"logger":"controller-runtime.manager.controller.markdownview.a.b.c","msg":"message","reconciler group":"view.zoetrope.github.io","reconciler kind":"MarkdownView","name":"markdownview-sample","namespace":"default"}
IntoContext/FromContext
WithName()やWithValues()で作成したロガーを別の関数でも利用したい場合、引数で受け渡すのは少々面倒です。
そこでcontroller-runtimeでは、Contextを介してロガーを受け渡す方法が用意されています。
新しいロガーを作成したら、IntoContext()でContextにロガーを設定し、新しいContextを作成します。
newLogger := logger.WithName("new")
ctx = log.IntoContext(ctx, newLogger)
myFunc(ctx)
利用側では、受け取ったContextからロガーを取り出します。
func myFunc(ctx context.Context) {
logger := log.FromContext(ctx)
}
ログレベルの話
zapでは以下のようなログレベルが用意されています。
値の大きい方が重要なログです。
- debug: -1
- info: 0
- warn: 1
- error: 2
- dpanic: 3
- panic: 4
- fatal: 5
これに対してlogrのV()で指定するログレベルは、値の小さいほうが重要なログになっています。
そのため、zaprではログレベルの正負を反転しています。
この結果、ロガーの初期化をする際には、利用したいログレベルを正負反転した形で指定する必要があります。
opts := zap.Options{
Level: zapcore.Level(-3),
}
ログを出力する際には、以下のようにログレベルを指定します。
logger.V(3).Info("message")
出力されるログには、以下のように出力されます。（ちょっと微妙ですね）
{"level":"Level(-3)",...
kube-apiserverからのwarning
kube-apiserverには、クライアントに対して警告を送信する仕組みが用意されています。
この仕組みにより、廃止予定のAPIを呼び出した場合や、非推奨のCRDを利用した場合、AdmissionWebhookでの警告などをクライアントに通知することができます。
controller-runtimeでは、この受け取った警告がログに出力するように設定されています。
client-goのログ
controller-runtimeが内部で利用しているclient-goは、ロガーとしてklogを利用しています。
そのため、以下のようにcontroller-runtimeが出力したログ(1行目)とclient-goが出力したログ(2行目)が、異なるフォーマットで出力されてしまいます。
{"level":"info","ts":1629293664.3974473,"logger":"controller-runtime.manager.controller.markdownview","msg":"Starting Controller","reconciler group":"view.zoetrope.github.io","reconciler kind":"MarkdownView"}
I0818 22:34:25.544370 72085 request.go:668] Waited for 1.0486281s due to client-side throttling, not priority and fairness, request: GET:https://127.0.0.1:45631/apis/admissionregistration.k8s.io/v1?timeout=32s
そこでklog.SetLogger()を利用して、client-goのログもzapで出力させると、同じ設定でログを出力することができるようになります。
package main
import (
"flag"
"k8s.io/klog/v2"
ctrl "sigs.k8s.io/controller-runtime"
"sigs.k8s.io/controller-runtime/pkg/log/zap"
)
func main() {
opts := zap.Options{
Development: true,
}
opts.BindFlags(flag.CommandLine)
flag.Parse()
zaplogger := zap.New(zap.UseFlagOptions(&opts))
ctrl.SetLogger(zaplogger)
klog.SetLogger(zaplogger.WithName("client-go"))
}
Discussion