👾

client-goにおけるKubernetes EventのAggregationとSpam Filtering

2023/04/17に公開

Kubernetes

tech

TL;DR

clint-goには似たEventを1つにまとめるAggregationとEventへRate Limitを適応するためのSpam Filteringの機能が備わっている
AggregationはEventAggregatorByReasonFuncで生成されるAggregationKeyをキーとして10分間に10回以上同じEventが発行された場合、etcdの容量を節約するためにEventの新規作成を行わず、代わりに既存のEventを更新する
Spam FilteringはgetSpamKeyファンクションによって生成される値をキーとしてスパム判定を行う。スパムフィルターの中身はトークンバケットアルゴリズムを用いたRate Limiterで、初期25トークン、Refill Rateが5分に1トークン。これを超えてEventが発行された場合、Eventは破棄される

背景

CronJobの子Jobの完了を検知して、あるアクションを行うCustomControllerを作りたいと思ったとき、CronJobController (v2) が子Jobが完了した際にSawCompletedJobというEventを吐いていることを発見しました。

｢お、このEventを使えば簡単に子Jobの完了を検知出来るな、よしよし｣と思いましたが、ローカルクラスター (kind) で1分間に1回走るCronJobを実行してみたところ、途中 (10回目ぐらい) からSawCompletedJobが取得できなくなることに気がつきました。具体的には、以下のようになりました。

$ kubectl alpha events --for cronjob/hello
...
8m29s (x2 over 8m29s)   Normal   SawCompletedJob    CronJob/hello   Saw completed job: hello-28023907, status: Complete
8m29s                   Normal   SuccessfulDelete   CronJob/hello   Deleted job hello-28023904
7m35s                   Normal   SuccessfulCreate   CronJob/hello   Created job hello-28023908
7m28s (x2 over 7m28s)   Normal   SawCompletedJob    CronJob/hello   Saw completed job: hello-28023908, status: Complete
7m28s                   Normal   SuccessfulDelete   CronJob/hello   Deleted job hello-28023905
6m35s                   Normal   SuccessfulCreate   CronJob/hello   Created job hello-28023909
6m28s                   Normal   SawCompletedJob    CronJob/hello   Saw completed job: hello-28023909, status: Complete
2m35s (x3 over 4m35s)   Normal   SuccessfulCreate   CronJob/hello   (combined from similar events): Created job hello-28023913

6m28sまでは SawCompletedJob が通知されていますが、それ以降取得できなくなっています。SuccessfulCreateはAggregateされた形で、全てではないが通知されています。ちなみに、以下のように子Job及び子PodのEventはすべて通知されています。

$ kubectl alpha events

4m18s                 Normal    Scheduled                 Pod/hello-28023914-frb94   Successfully assigned default/hello-28023914-frb94 to kind-control-plane
4m11s                 Normal    Completed                 Job/hello-28023914         Job completed
3m18s                 Normal    Started                   Pod/hello-28023915-5fsh5   Started container hello
3m18s                 Normal    SuccessfulCreate          Job/hello-28023915         Created pod: hello-28023915-5fsh5
3m18s                 Normal    Created                   Pod/hello-28023915-5fsh5   Created container hello
3m18s                 Normal    Pulled                    Pod/hello-28023915-5fsh5   Container image "busybox:1.28" already present on machine
3m18s                 Normal    Scheduled                 Pod/hello-28023915-5fsh5   Successfully assigned default/hello-28023915-5fsh5 to kind-control-plane
3m11s                 Normal    Completed                 Job/hello-28023915         Job completed
2m18s                 Normal    Started                   Pod/hello-28023916-qbqqk   Started container hello
2m18s                 Normal    Pulled                    Pod/hello-28023916-qbqqk   Container image "busybox:1.28" already present on machine
2m18s                 Normal    Created                   Pod/hello-28023916-qbqqk   Created container hello
2m18s                 Normal    SuccessfulCreate          Job/hello-28023916         Created pod: hello-28023916-qbqqk
2m18s                 Normal    Scheduled                 Pod/hello-28023916-qbqqk   Successfully assigned default/hello-28023916-qbqqk to kind-control-plane
2m11s                 Normal    Completed                 Job/hello-28023916         Job completed
78s                   Normal    SuccessfulCreate          Job/hello-28023917         Created pod: hello-28023917-kpxvn
78s                   Normal    Created                   Pod/hello-28023917-kpxvn   Created container hello
78s                   Normal    Pulled                    Pod/hello-28023917-kpxvn   Container image "busybox:1.28" already present on machine
78s                   Normal    Started                   Pod/hello-28023917-kpxvn   Started container hello
78s                   Normal    Scheduled                 Pod/hello-28023917-kpxvn   Successfully assigned default/hello-28023917-kpxvn to kind-control-plane
71s                   Normal    Completed                 Job/hello-28023917         Job completed
18s (x8 over 7m18s)   Normal    SuccessfulCreate          CronJob/hello              (combined from similar events): Created job hello-28023918
18s                   Normal    Started                   Pod/hello-28023918-grvbz   Started container hello
18s                   Normal    Created                   Pod/hello-28023918-grvbz   Created container hello
18s                   Normal    Pulled                    Pod/hello-28023918-grvbz   Container image "busybox:1.28" already present on machine
18s                   Normal    SuccessfulCreate          Job/hello-28023918         Created pod: hello-28023918-grvbz
18s                   Normal    Scheduled                 Pod/hello-28023918-grvbz   Successfully assigned default/hello-28023918-grvbz to kind-control-plane
11s                   Normal    Completed                 Job/hello-28023918         Job completed

この挙動は公式ドキュメントにも特に記載が見つけられなかったため、何が起こっているのかソースコードを頼りに読み解きたいと思って調査しました。なお生の調査ログはこちらにあるので気になる場合はご確認ください。

Kubernetes Eventの送信フロー

KubernetsのEventはclient-goを通じてkube-apiserverへ送信され、etcdに保存されます。EventのAggregationやSpam Filteringはこのclient-goで行われますが、client-goがkube-apiserverへEventを送信するフローがそこそこ複雑なので初めにそれを説明します。なお、以下CronJobControllerのSawCompleteJob Eventを例に説明します。細かい挙動はControllerごとに異なる可能性がある点に注意してください。
client-go Event publication flow

CronJobControllerはRecorderのEventfメソッドを通じてEventを発行する。Eventfは内部でBroadcasterのActionOrDropメソッドを呼び出し、incommingチャネルへEventを送信する
incomingチャネルへ送信されたEventはloop goroutineにより取り出され、各Watcherのresultチャネルに転送される。
Event Watcherはゴルーチンの中でresultチャネルから送信されてきたEventに対してeventHandlerを呼ぶ。evenHandlerは中でeventBroadcasterImplのrecordToSinkを呼び、recordToSinkはEventCorrelatorを使ってEventのAggregationとSpam Filteringを行ったあと、recordEventを呼び出し、kube-apiservierに対してEventの作成 (Aggregationされた場合にはEventの更新) を行う

補足: loop goroutineの起動

loop goroutineを起動するNewLongQueueBroadcasterファンクションはNewBroadcasterファンクションを通じて呼ばれ、NewBroadcasterファンクションはNewControllerV2ファンクションで呼ばれます。

補足: Event Watcherの起動

CronJobControllerはeventBroadcasterImplのStartRecordingToSinkメソッドを呼び出し、StartEventWatcherメソッドからEvent Watcherを起動します。StartEventWatcherメソッドはBroadcasterのWatchメソッドを通じてWatcherの初期化と登録を行います。結構面白いなーと思ったのは、Wathcerの登録処理をincommingチャネルに送信し、loop goroutineが実行することで、Wacherの起動前に送信されたEventをWatcherから見えないようにしている点 (コメントにはterrible hackと書かれているけどw)

EventCorrelator

Kubernetes EventのAggreagationとSpam FilteringのコアロジックはEventCorrelatorが実装しています。EventCorrelatorはeventBroadcasterImplのStartRecordingToSinkメソッドでNewEventCorrelatorWithOptionsファンクションを通じて初期化されます。なお、 e.optionsは空なので全てデフォルトの設定が適応されます。eventBroadcasterImplのrecordToSinkメソッドでEventCorrelateメソッドが呼ばれ、EventのAggregationとSpam Filteringを実行します。

Aggregation

EventCorrelatorはEventAggregateメソッドとeventLoggerのeventObserveメソッドを通じてEventのAggregationを行います。ソースコードに非常に細かくコメントが残されているため、そちらを直接確認いただく方がいいと思いますが、ざっくりと処理を説明します。

EventAggregatorByReasonFuncを用いてaggregationKeyとlocalKeyを計算する。aggregationKeyはevent.Source、event.InvolvedObject、 event.Type、event.Reason、event.ReportingController、event.ReportingInstanceでlocalKeyは event.Messageになる
計算したaggregateKeyを用いてEventAggregatorのcacheを検索する。cacheのバリューはaggregateRecord。もしaggregateRecordのlastTimestampがEventAggregatorのmaxIntervalInSeconds (デフォルトは600秒) 以内でlocalKeysの数が、EventAggregatorのmaxEvents (デフォルトは10) 以上であればaggregationKeyを、そうでなければEvent固有のeventKey をキーとして返す
EventCorrelatorのEventCorrelateメソッドから返ってきたキーを元にeventLoggerのeventObserveメソッドを呼び出し、eventLoggerのcacheを探索する。cacheのバリューはeventLog。cacheにヒットした場合 (≒ キーがaggregateKeyだった場合) はEventを更新するためのパッチを計算する

Spam Filtering

EventCorrelatorのfilterFuncを呼び出し、Spam filetrを適応します。filterFuncの実体はEventSourceObjectSpamFilterのFilterメソッドです。こちらもソースコードに細かくコメントされているためそちらを確認いただくことをおすすめしますが、以下で処理を簡単に説明します。

EventからgetSpamKeyファンクションを使ってeventKeyを計算する
eventKeyを使ってEventSourceObjectSpamFilterのcacheを検索する。cacheのバリューはspamRecordでspamRecordにはrate limitterが保存されている。spamFiletrのqpsとburstはデフォルト値なのでqpsが1/300でburstが25。コメントによれば、rate limitterはトークンバケットアルゴリズムを用いて初めにburst分のトークンが与えられ、その後qpsのペースでトークンが補充されるということ。つまり初めに25トークンあり、その後は5分に1度トークンが補充される
tokenBucketPassiveRateLimiterのTryAcceptメソッドを呼び出し、Rate Limitを確認する。もしRate Limitに引っかかった場合Eventは送信されない

なぜSawCompletedJob Eventは発行されなくなったのか

以上を踏まえてなぜSawCompleteJob Eventが発行されなくなったのかを考えます。結論から言うと恐らくSpam filterに引っかかったことが原因です。

CronJobControllerは子JobごとにSuccessfulCreate、SawCompletedJob、SuccessfulDeleteという3 Eventを1分間に発行する (厳密にはSuccessfulDeleteはHistoryLimitに達したタイミングからしか発行されない)
Spam filetrが用いるgetSpamKeyファンクションはEventのSourceとInvolvedObjectを見てキーを計算するため、これら3種類のEventは同じEventとして判定される
最初の25トークンは1分間に3トークンずつ消費される。5分に1トークン補充されるが9分を経過した辺りでトークンが枯渇し始める。以後5分ごとにトークンが補充されるがそれは (Aggregated) SuccessfulCreate Eventに消費されてしまうため、SawCompletedJobとSuccessfulDeleteは以後通知されなくなる

補足 Events

以下SuccessfulCreate、 SawCompletedJob、SuccessfulDeleteのinvolvedObjectとsourceです。

SuccessfulCreate Event

apiVersion: v1
kind: Event
involvedObject:
  apiVersion: batch/v1
  kind: CronJob
  name: hello
  namespace: default
  resourceVersion: "289520"
  uid: 5f3cfeca-8a83-452a-beb9-7a5f9c1eff63
source:
  component: cronjob-controller
...
reason: SuccessfulCreate
message: Created job hello-28025408

SawCompletedJob Event

apiVersion: v1
kind: Event
involvedObject:
  apiVersion: batch/v1
  kind: CronJob
  name: hello
  namespace: default
  resourceVersion: "289020"
  uid: 5f3cfeca-8a83-452a-beb9-7a5f9c1eff63
source:
  component: cronjob-controller
...
reason: SawCompletedJob
message: 'Saw completed job: hello-28025408, status: Complete'

SuccessfulDelete Event

apiVersion: v1
kind: Event
involvedObject:
  apiVersion: batch/v1
  kind: CronJob
  name: hello
  namespace: default
  resourceVersion: "289520"
  uid: 5f3cfeca-8a83-452a-beb9-7a5f9c1eff63
source:
  component: cronjob-controller
...
reason: SuccessfulDelete
message: Deleted job hello-28025408