はじめに(What’s New の内容含む)
ここでは、Kubernetes 1.19 の CHANGELOG から Metrics の変更と SIG Instrumentation の取り組みについてまとめています。
Kubernetes v1.19 では SIG Instrumentation の大きなテーマとして、構造化ロギング(Structured logging)が導入されました。
構造化ロギングは KEP の1602-structured-logging kubernetes/enhancements で提案されています。
原文の What's New では次のように紹介されています。
ログメッセージの構造と Kubernetes オブジェクトへの参照を標準化しました。
構造化されたログにより、ログのパース、処理、保存、検索、そして分析が簡単になりました。klog ライブラリの新しいメソッドを利用することでログメッセージの構造化を強制できます。
この KEP により klog には 構造化されたログを出力するInfoS や ErrorS、Kubernetes オブジェクトを展開する KObj、KRef などのメソッドが追加され、ライブラリは v2 に更新されました。
そしてこちらの移行計画をもとに、ログ出力の割合が多い重要なログに焦点を絞りメソッドの置き換えが進められています。Tracking Issue はこちらです。
これらのメソッドを使った出力イメージは次の通りとなり、これだけでは ndjson のような json 形式で出力されません。
> klog.V(2).InfoS("Pod status updated", "pod", klog.KObj(p), "status", status.Phase)
# key=value の形式で出力される
I0903 23:43:18.302818    3894 kubelet_getters.go:176] "Pod status updated" pod="kube-system/etcd-minikube" status=Running
ndjson の形式で出力するには component-base に実装された --logging-format のオプションを使用し、json を指定します。
実際にどのようなログが出力されるか minikube を使って確認してみます。
2020-09-03 時点でリリースされている minikube v1.12.3 では extra-config の内容が反映されなかったため、master ブランチの minikube をビルドし利用します。
kube-controller-manager と kube-scheduler の引数に --logging-format オプションを追加するため、次のような extra-config を付けて minikube を起動します。
# macOS で実行しています
$ minikube start \
  --kubernetes-version 1.19.0 \
  --vm-driver hyperkit \
  --extra-config 'controller-manager.logging-format=json' \
  --extra-config 'scheduler.logging-format=json'
  --extra-config 'kubelet.logging-format=json'
  --extra-config 'controller-manager.v=6' \
  --extra-config 'scheduler.v=6'
  --extra-config 'kubelet.v=6'
😄  minikube v1.12.3 on Darwin 10.15.6
✨  Using the hyperkit driver based on user configuration
👍  Starting control plane node minikube in cluster minikube
🔥  Creating hyperkit VM (CPUs=2, Memory=4000MB, Disk=20000MB) ...
🎉  minikube 1.13.0 is available! Download it: https://github.com/kubernetes/minikube/releases/tag/v1.13.0
💡  To disable this notice, run: 'minikube config set WantUpdateNotification false'
🐳  Preparing Kubernetes v1.19.0 on Docker 19.03.12 ...
    ▪ controller-manager.logging-format=json
    ▪ scheduler.logging-format=json
    ▪ kubelet.logging-format=json
    ▪ controller-manager.v=6
    ▪ scheduler.v=6
    ▪ kubelet.v=6
🔎  Verifying Kubernetes components...
🌟  Enabled addons: default-storageclass, storage-provisioner
🏄  Done! kubectl is now configured to use "minikube"
このオプションで minikube の起動に成功すると次のようなフォーマットでログが出力されます。
kubelet のログ(一部抜粋)
$ minikube ssh 'sudo journalctl -xu kubelet'
...
I0904 00:17:45.010069    2773 flags.go:59] FLAG: --add-dir-header="false"
I0904 00:17:45.010111    2773 flags.go:59] FLAG: --address="0.0.0.0"
I0904 00:17:45.010117    2773 flags.go:59] FLAG: --allowed-unsafe-sysctls="[]"
I0904 00:17:45.010124    2773 flags.go:59] FLAG: --alsologtostderr="false"
I0904 00:17:45.010127    2773 flags.go:59] FLAG: --anonymous-auth="true"
I0904 00:17:45.010132    2773 flags.go:59] FLAG: --application-metrics-count-limit="100"
...
{"ts":1599178665518.6204,"msg":"Version: v1.19.0\n","v":0}
{"ts":1599178665518.9753,"msg":"feature gates: &{map[]}\n","v":1}
{"ts":1599178665521.7664,"msg":"feature gates: &{map[]}\n","v":1}
{"ts":1599178665521.9856,"msg":"Client rotation is on, will bootstrap in background\n","v":0}
{"ts":1599178665523.6094,"msg":"Config loaded from file:  /etc/kubernetes/kubelet.conf\n","v":6}
{"ts":1599178665525.3655,"msg":"Config loaded from file:  /etc/kubernetes/kubelet.conf\n","v":6}
{"ts":1599178665525.5464,"msg":"Current kubeconfig file contents are still valid, no bootstrap necessary\n","v":2}
# このログだと pod や status のキーが指定されているがまだ含まれてない?
# > klog.V(2).InfoS("Pod status updated", "pod", klog.KObj(p), "status", status.Phase)
{"ts":1599178743113.197,"msg":"Pod status updated","v":2}
{"ts":1599178743113.3542,"msg":"Pod status updated","v":2}
...
kube-controller-manager のログ(一部抜粋)
$ kubectl logs kube-scheduler-minikube
I0902 07:48:26.091216       1 registry.go:173] Registering SelectorSpread plugin
I0902 07:48:26.091310       1 registry.go:173] Registering SelectorSpread plugin
I0902 07:48:26.689893       1 serving.go:331] Generated self-signed cert in-memory
{"ts":1599032912174.6284,"msg":"Registering SelectorSpread plugin\n","v":0}
{"ts":1599032912174.6775,"msg":"Registering SelectorSpread plugin\n","v":0}
{"ts":1599032912177.0889,"msg":"Authorization is disabled\n","v":0}
{"ts":1599032912177.1306,"msg":"Authentication is disabled\n","v":0}
{"ts":1599032912177.163,"msg":"Serving healthz insecurely on [::]:10251\n","v":0}
{"ts":1599032912180.8513,"msg":"Starting client-ca::kube-system::extension-apiserver-authentication::client-ca-file\n","v":0}
{"ts":1599032912181.0864,"msg":"Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::client-ca-file\n","v":0}
{"ts":1599032912181.209,"msg":"Serving securely on [::]:10259\n","v":0}
kube-scheduler のログ(一部抜粋)
$ kubectl logs kube-controller-manager-minikube
I0902 07:48:26.685344       1 serving.go:331] Generated self-signed cert in-memory
{"ts":1599032906964.9773,"msg":"Version: v1.19.0\n","v":0}
{"ts":1599032906966.5215,"msg":"Serving securely on [::]:10257\n","v":0}
{"ts":1599032906967.1287,"msg":"Serving insecurely on [::]:10252\n","v":0}
{"ts":1599032906967.9482,"msg":"Starting request-header::/var/lib/minikube/certs/front-proxy-ca.crt\n","v":0}
{"ts":1599032906968.5168,"msg":"Starting DynamicServingCertificateController\n","v":0}
{"ts":1599032906968.684,"msg":"Starting client-ca-bundle::/var/lib/minikube/certs/ca.crt\n","v":0}
{"ts":1599032914511.9033,"msg":"Waiting for caches to sync for tokens\n","v":0}
出力されたログは KEP にて定義された次のキーが含まれた構造体になっており、キーの追加もできるようになっています。
- ts: タイムスタンプ as UNIX time (required, float)
- v: verbosity (required, int, default 0)
- err: error string (optional, string)
- msg: message (required, string)
{
   "ts": 1580306777.04728,
   "v": 4,
   "msg": "Pod status updated",
   "pod":{
      "name": "nginx-1",
      "namespace": "default"
   },
   "status": "ready"
}
現状では全てのコンポーネントやログが構造化されているわけではありませんが、フィードバックを反映しながら性能やスキームの改善がされていく見込みです。
この取り組みにより、今まで Fluentd などの正規表現でパースしていた処理がシンプルになり、分析したかったことに注力できそうです。
それでは恒例の Metrics Changes について説明していきます。
ただし今回の ChangeLog から Metrics Changes の項目は削除されたため、私の方で Changes by Kind からメトリクスの変更に関連するものを抜粋した内容を Metrics Changes としてまとめました。
メトリクスの変更(Metrics Changes)
変更
kube-scheduler
- 
profileラベルが追加されました(#92268, @alculquicondor)- scheduler_framework_extension_point_duration_seconds
 
- 
profileラベルが追加され、scheduler ごとにメトリクスが記録されるようになりました(#92202, @alculquicondor)- scheduler_schedule_attempts_total
 
- 
resultとprofileラベルが追加され、スケジュールできなかった試行回数とエラー試行の時間が記録されるようになりました(#92202, @alculquicondor)。- scheduler_e2e_scheduling_duration_seconds
 
- 次のメトリクスがリネームされました(#91448, @RainbowMango)
- 
scheduler_total_preemption_attempts->scheduler_preemption_attempts_total
 
- 
kubelet
- 次のメトリクスがリネームされました(#92407, @RainbowMango)
- 
kubelet_running_container_count->kubelet_running_containers
- 
kubelet_running_pod_count->kubelet_running_pods
 
- 
- 
/metrics/resourceエンドポイントから取得できる次のメトリクスがリネームされました(#89540, @dashpole)- 
node_cpu_usage_seconds->node_cpu_usage_seconds_total
- 
container_cpu_usage_seconds->container_cpu_usage_seconds_total
 
- 
kube-aggregator
- 次のメトリクスがリネームされました(#88156, @p0lyn0mial)
- 
aggregator_unavailable_apiservice_count->aggregator_unavailable_apiservice_total
 
- 
- レート制限のメトリス Prometheus のベストプラクティスに従いリネームしました(#77979, @s-urbaniak)
- 
APIServiceOpenAPIAggregationControllerQueue1->open_api_aggregation_controller
 
- 
その他
- 
CoreDNS v1.17 へのアップグレードに伴い、メトリクス名を Prometheus のベストプラクティスに合わせるため、次のメトリクスがリネームされました。この変更は下位互換がないためアップグレードする前に利用箇所の修正が必要です(#92651, @rajansandeep)。
- 
coredns_request_block_count_total->coredns_dns_blocked_requests_total
- 
coredns_request_allow_count_total->coredns_dns_allowed_requests_total
- 
coredns_dns_acl_request_block_count_total->coredns_acl_blocked_requests_total
- 
coredns_dns_acl_request_allow_count_total->coredns_acl_allowed_requests_total
- 
coredns_autopath_success_count_total->coredns_autopath_success_total
- 
coredns_forward_request_count_total->coredns_forward_requests_total
- 
coredns_forward_response_rcode_count_total->coredns_forward_responses_total
- 
coredns_forward_healthcheck_failure_count_total->coredns_forward_healthcheck_failures_total
- 
coredns_forward_healthcheck_broken_count_total->coredns_forward_healthcheck_broken_total
- 
coredns_forward_max_concurrent_reject_count_total->coredns_forward_max_concurrent_rejects_total
- 
coredns_grpc_request_count_total->coredns_grpc_requests_total
- 
coredns_grpc_response_rcode_count_total->coredns_grpc_responses_total
- 
coredns_panic_count_total->coredns_panics_total
- 
coredns_dns_request_count_total->coredns_dns_requests_total
- 
coredns_dns_request_do_count_total->coredns_dns_do_requests_total
- 
coredns_dns_response_rcode_count_total->coredns_dns_responses_total
- 
coredns_reload_failed_count_total->coredns_reload_failed_total
- 
coredns_cache_size->coredns_cache_entries
- 
coredns_dns_request_type_count_total- このメトリクスは削除され、既存のメトリクスである coredns_dns_requests_totalに統合されました
 
- このメトリクスは削除され、既存のメトリクスである 
 
- 
- 
kubernetes_build_infoメトリクスのラベル名がcamelCaseからsnake_caseになりました。この変更は kube-apiserver、kube-scheduler、kube-proxy、kube-controller-manager のコンポーネントに適用されています(#91805, @RainbowMango)。- 
gitVersion->git_version
- 
gitCommit->git_commit
- 
gitTreeState->git_tree_state
- 
buildDate->build_date
- 
goVersion->go_version
 
- 
追加
kube-apiserver
- 
非推奨バージョンの API にリクエストすると、API レスポンスに警告ヘッダーが含まれ、非推奨 API の利用がわかるメトリクスへ記録されるようになりました。このメトリクスは Gauge となっており、非推奨 API が利用されると値として 1 が記録されます(#73032, @liggitt) - apiserver_requested_deprecated_apis
- クラスタ運用者としては便利な機能ですね!
 # HELP apiserver_requested_deprecated_apis [ALPHA] Gauge of deprecated APIs that have been requested, broken out by API group, version, resource, subresource, and removed_release. # TYPE apiserver_requested_deprecated_apis gauge apiserver_requested_deprecated_apis{group="extensions",removed_release="1.22",resource="ingresses",subresource="",version="v1beta1"} 1
- api-server でキューに入ってるリクエスト数を記録するメトリクスが追加されました(#91177, @MikeSpreitzer)
- apiserver_current_inqueue_requests
 
- FeatureGate=APIPriorityAndFairness とした際に役立つメトリクスが追加されました。詳細はこちらのドキュメントを参照してください(#91177, @MikeSpreitzer)。
- apiserver_flowcontrol_priority_level_request_count_samples
- apiserver_flowcontrol_priority_level_request_count_watermarks
- apiserver_flowcontrol_read_vs_write_request_count_samples
- apiserver_flowcontrol_read_vs_write_request_count_watermarks
 
kubelet
- クライアント証明書をローテーションするように設定された kubelet が、証明書の有効期限までの残りの秒数を記録するメトリクスが追加されました(#91148, @liggitt)。
- kubelet_certificate_manager_client_ttl_seconds
 
kube-proxy
- kube-proxy の変更を適用するため、キューに入れられた最後の時間を記録するメトリクスが追加されました(#90175, @squeed)
- kubeproxy_sync_proxy_rules_last_queued_timestamp_seconds
 
kube-controller-manager
- ローカル nodeipam のレンジアロケーターをリファクタリングし、割り当てられた CIDR を格納するために使用する cidrset を次のメトリクスで記録するようになりました(#90288, @aojea)
- node_ipam_controller_cidrset_cidrs_allocations_total
- node_ipam_controller_cidrset_cidrs_releases_total
- node_ipam_controller_cidrset_usage_cidrs
- node_ipam_controller_cidrset_allocation_tries_per_request
 
削除
kubelet
- 
#91148 の対応により、kubelet_certificate_manager_client_ttl_secondsが追加されたので次のメトリクスは削除されました- kubelet_certificate_manager_client_expiration_seconds
 
種類別の変更点(Changes by Kind)
機能追加(Feature)
component-base
- 
--logging-formatオプションが追加されました。デフォルト値はtextとなり以前と同じフォーマットになります。jsonを指定すると ndjson のようなフォーマットでログが出力されます(#89683, @yuzhiquan)。
kubelet
- 構造化ロギングをサポートするために --logging-formatオプションが追加されました(#91532, @afrouzMashaykhi)
kube-controller-manager
kube-scheduler
api-server
- 非推奨の API バージョンへリクエストされると監査イベント に "k8s.io/deprecated": "true"の監査アノテーションが含まれるようになりました。削除対象となるリリースが特定された場合、監査イベントには"k8s.io/removal-release": "<majorVersion>.<minorVersion>"の監査アノテーションも追加されます(#92842, @liggitt)。
- 
api-server のログのトレース出力がより整理され、包括的になりました。トレースはネストされ長時間実行されていない全てのリクエストエンドポイントについて、フィルターチェイン全体が計測されます。 例では認証チェックが含まれています(#88936, @jpbetz)。 Trace[1374095871]: "HTTP Request" method:GET,url:/api/v1/namespaces/kube-system/resourcequotas,user-agent:kube-apiserver/v1.19.0 (linux/amd64) kubernetes/482c37a,client:::1 (02-Jun-2020 10:38:00.615) (total time: 3201ms): Trace[1374095871]: ---"Authenticate check done" 1000ms (10:38:00.615) Trace[1374095871]: ---"Authorize check done" 1000ms (10:38:00.616) Trace[1374095871]: ["List" url:/api/v1/namespaces/kube-system/resourcequotas,user-agent:kube-apiserver/v1.19.0 (linux/amd64) kubernetes/482c37a,client:::1 1200ms (10:38:00.616) Trace[1374095871]: ["List etcd3" key:/resourcequotas/kube-system,resourceVersion:,limit:0,continue: 1200ms (10:38:00.616)]] Trace[1374095871]: [3.201532894s] [3.201532894s] END 将来的にはこのようなログも構造化される予定です。 将来的にはこのようなログも構造化される予定です。
不具合の修正(Bug or Regression)
- cadvisor を v0.37.0 にアップグレードし、次の内容を修正しました(#92919, @dashpole)
- コンテナイメージのファイルシステムの検出を修正
- devicemapper デバイスのディスクメトリクスを修正
- Linux カーネル 5.0 以上 で発生する OOM Kill の検出を修正
 
所感
今回も Stability Level が ALPHA なメトリクスですが、ガンガンリネームされてます!
特に CoreDNS を監視されている Application Developer はご注意ください。
構造化ロギングは Fluentd の設定がシンプルになり、負荷の軽減にも繋がるので導入の検討をしていきたいです。
ただ今までログに出力されていたソースコードのファイル名と行数は調査時に助かっていたので、復活してもらえると嬉しいです。ログの容量のことを考えるとオプションの扱いが妥当でしょうか。
