アップストリーム開発における flake テストの調査手順を記載する。

既に flake テストの調査手順があるか聞く https://kubernetes.slack.com/archives/C09QZ4DQB/p1576721594002200 調査手順書はないみたい。 Ben さんと Liggit さんの頭の中にある。と思ったらあった。 https://github.com/kubernetes/community/blob/master/contributors/devel/sig-testing/flaky-tests.md
特定の Flake issue を調査、解決し、その経験をドキュメントとして提案する。

手順

Face test failure which is not related to the PR.
Check how frequently the failure happens according to https://testgrid.k8s.io e.g. https://testgrid.k8s.io/presubmits-kubernetes-nonblocking#pull-kubernetes-e2e-kind&include-filter-by-regex=Kubectl%20Port%20forwarding
Check that is recognized as flake in the community. https://github.com/kubernetes/kubernetes/issues?q=is%3Aopen+is%3Aissue+label%3Akind%2Fflake
If not recognized, create an issue for that with kind/flake Click Flaking Test
Assign yourself for the issue if nobody is assigned.

https://github.com/kubernetes/community/blob/master/contributors/devel/sig-testing/flaky-tests.md を理解する。

Flaky tests

たまにテストが失敗することは flaky だ。我々の PR 統合プロセスは全てのテストが成功しないと通過しないことになっている。そして我々は異なる CI システム上において複数の組み合わせのテストを実行しているのだ。その結果、小さな確率であったとしても flake は人々にとって PR の待ち時間を発生させる多くの痛みをもたらすものになってしまう。

その結果、保守的にテストを書くことがとても重要となっている。「（flakeが）ほとんど発生しない」というようなテストであったとしても、数千回とテストを流すような状況では、flake が発生することになる。しかも Flake を再現させることはとても難しいため、Flake が発生したときの状況を適切に把握するためのテストログはとても重要となっている。

注目すべきは、Unit testsや Integration tests であろうと Flake が発生することがある。しかし多くは end-to-end テストで発生することが多いだろう。

Hunting Flakes

Flake 問題を解消するための次のツールがある。

go.k8s.io/triage: テスト失敗レポート。過去2週間の失敗したテストをジョブ名、テスト名で表示
testgrid.k8s.io: Flakeの発生状況を表示
velodrome.k8s.io: bigquery を使ったテスト結果調査用ダッシュボード
flakeテスト一覧: https://github.com/kubernetes/kubernetes/issues?q=is%3Aopen+is%3Aissue+label%3Akind%2Fflake

Expectations when a flaky test is assigned to you

我々はランダムにあなたに Flake 問題の解決のアサインを行うわけではない。これらの問題をすすんで受け入れてくれるととてもありがたい。しかし PR のマージがブロックされるなどの重大な問題が発生した場合、我々は早くその問題を解消する必要がある。そこでいくつかのガイドラインが以下の通りある。

もしも Flake テストがアサインされたならば、他のだれかに引き継がないのであれば、あなたがすることが最も重要となる。もしもあまりにも多くのFlakeテストをアサインされたのであれば、他の誰かを探す必要がある。その探すことはあなたの責任だ。
その Flake テストを再現させるためのリーズナブルな努力を行うべきだ。1時間から半日、その問題に集中することがリーズナブルな努力といえるだろう。それを超えるならば、助けを求めることはリーズナブルだろう。
Flake を再現できたのであれば、あなたは修正できるだろう。もしくは十分な情報と指示と共に、誰かに修正してもらうことをお願いすることができるだろう。
一度、Flake を直したと思う変更を行った場合でも、対応する Issue 自体は Close せずに Open したままにしておく。
もしも Flake を再現できない場合、Close してはならない。少なくともマージから2時間は Close してはならない。
もしも Flake の Issue がオープンしてから再現できず、そして3ヶ月発生していないことを確認したら、そのFlake issue をCloseするタイミングとしてリーズナブルだろう。なぜClose するのかもClose する際には記載すること。
もしも Flake を解消できないと考えたならば、 [Flaky] のラベルをテストに追加することを検討しよう。そのようなテストは通常のテストジョブから外れ、Flake 専用ジョブでのみ実行されるようになる。

Reproducing unit test flakes

unit test Flakeの発生方法（省略）

Hunting flaky unit tests in Kubernetes

unit test flake のデバッグ方法（省略）

https://prow.k8s.io/view/gcs/kubernetes-jenkins/pr-logs/pull/86634/pull-kubernetes-e2e-kind/1210642026224160769 を調査

k/k の issues/86678 として登録済み。
testgrid の内容から今日 12/27 に2回発生していることを確認。
Prow(例: https://prow.k8s.io/view/gcs/kubernetes-jenkins/pr-logs/pull/86634/pull-kubernetes-e2e-kind/1210642026224160769) から、問題発生時のテストコードを特定。
```
test/e2e/kubectl/portforward.go:458
Dec 27 19:35:36.087: Pod did not start running: timed out waiting for the condition
test/e2e/kubectl/portforward.go:361
```

テスト内容を把握する

458                 ginkgo.It("should support forwarding over websockets", func() {
459                         doTestOverWebSockets("0.0.0.0", f)
460                 })

351 func doTestOverWebSockets(bindAddress string, f *framework.Framework) {
352         config, err := framework.LoadConfig()
353         framework.ExpectNoError(err, "unable to get base config")
354
355         ginkgo.By("Creating the pod")
356         pod := pfPod("def", "10", "10", "100", fmt.Sprintf("%s", bindAddress))
357         if _, err := f.ClientSet.CoreV1().Pods(f.Namespace.Name).Create(pod); err != nil {
358                 framework.Failf("Couldn't create pod: %v", err)
359         }
360         if err := f.WaitForPodReady(pod.Name); err != nil {
361                 framework.Failf("Pod did not start running: %v", err)
362         }

bindAddress が 0.0.0.0 で Pod をスタートしようとしたところ、タイムアウトした模様

エラー発生したテストコードを更に深堀する

513 // WaitForPodReady waits for the pod to flip to ready in the namespace.
514 func (f *Framework) WaitForPodReady(podName string) error {
515         return e2epod.WaitTimeoutForPodReadyInNamespace(f.ClientSet, podName, f.Namespace.Name, PodStartTimeout)
516 }

88         // PodStartTimeout is how long to wait for the pod to be started.
89         // Initial pod start can be delayed O(minutes) by slow docker pulls.
90         // TODO: Make this 30 seconds once #4566 is resolved.
91         PodStartTimeout = 5 * time.Minute

待ち時間は5分と設定されており、ここでタイムアウトしているが TODOを見ると30秒が適切とある。よって、5分でタイムアウトしているのは異状の模様。

タイムアウトしたときの Pod のステータスが知りたい。

360 // WaitTimeoutForPodReadyInNamespace waits the given timeout diration for the
361 // specified pod to be ready and running.
362 func WaitTimeoutForPodReadyInNamespace(c clientset.Interface, podName, namespace string, timeout time.Duration) error {
363         return wait.PollImmediate(poll, timeout, podRunningAndReady(c, podName, namespace))
364 }

179 func podRunningAndReady(c clientset.Interface, podName, namespace string) wait.ConditionFunc {
180         return func() (bool, error) {
181                 pod, err := c.CoreV1().Pods(namespace).Get(podName, metav1.GetOptions{})
182                 if err != nil {
183                         return false, err
184                 }
185                 switch pod.Status.Phase {
186                 case v1.PodFailed, v1.PodSucceeded:
187                         return false, conditions.ErrPodCompleted
188                 case v1.PodRunning:
189                         return podutil.IsPodReady(pod), nil
190                 }
191                 return false, nil
192         }
193 }

Pod Status の状態表示メッセージを追加: k/kubernetes/pull/86733

もうちょっと簡単（たぶん）そうな flake として https://prow.k8s.io/view/gcs/kubernetes-jenkins/pr-logs/pull/86731/pull-kubernetes-integration/1211724206971031553 既に liggit さんが認識済み: k/kubernetes/issues/86334

--- FAIL: TestPreemption (35.00s)
    preemption_test.go:402: Test [basic pod preemption with filter]: Error running pause pod: Pod preemptiom8b9f36ec-65bf-49a4-a52d-13682e88c910/victim-pod didn't schedule successfully. Error: timed out waiting for the condition

テストコード test/integration/scheduler/preemption_test.go

 394         for _, test := range tests {
 395                 filter.Tokens = test.initTokens
 396                 filter.Unresolvable = test.unresolvable
 397                 pods := make([]*v1.Pod, len(test.existingPods))
 398                 // Create and run existingPods.
 399                 for i, p := range test.existingPods {
 400                         pods[i], err = runPausePod(cs, p)
 401                         if err != nil {
 402                                 t.Fatalf("Test [%v]: Error running pause pod: %v", test.description, err) ここでエラー
 403                         }
 404                 }

失敗したテストケース

 195                 {
 196                         description: "basic pod preemption with filter",
 197                         initTokens:  1,
 198                         existingPods: []*v1.Pod{
 199                                 initPausePod(context.clientSet, &pausePodConfig{
 200                                         Name:      "victim-pod",
 201                                         Namespace: context.ns.Name,
 202                                         Priority:  &lowPriority,
 203                                         Resources: &v1.ResourceRequirements{Requests: v1.ResourceList{
 204                                                 v1.ResourceCPU:    *resource.NewMilliQuantity(200, resource.DecimalSI),
 205                                                 v1.ResourceMemory: *resource.NewQuantity(200, resource.DecimalSI)},
 206                                         },
 207                                 }),
 208                         },
 209                         pod: initPausePod(cs, &pausePodConfig{
 210                                 Name:      "preemptor-pod",
 211                                 Namespace: context.ns.Name,
 212                                 Priority:  &highPriority,
 213                                 Resources: &v1.ResourceRequirements{Requests: v1.ResourceList{
 214                                         v1.ResourceCPU:    *resource.NewMilliQuantity(200, resource.DecimalSI),
 215                                         v1.ResourceMemory: *resource.NewQuantity(200, resource.DecimalSI)},
 216                                 },
 217                         }),
 218                         preemptedPodIndexes: map[int]struct{}{0: {}},
 219                 },

pause Pod がスケジュールされるのを待っているところでタイムアウトした模様ログから namespace: preemptiom8b9f36ec-65bf-49a4-a52d-13682e88c910 の victim-pod という名前の Pod 下記のログから 1 しかない node が一杯でスケジュールに失敗した模様

I1230 19:30:34.283711  109369 scheduler.go:608] Attempting to schedule pod: preemptiom8b9f36ec-65bf-49a4-a52d-13682e88c910/victim-pod
I1230 19:30:34.284256  109369 factory.go:436] Unable to schedule preemptiom8b9f36ec-65bf-49a4-a52d-13682e88c910/victim-pod: no fit: 0/1 nodes are available: 1 can't fit victim-pod.; waiting

気になるメッセージ I1230 19:30:24.284904 109369 generic_scheduler.go:1055] Node node1 is a potential node for preemption.

テスト目的の理解

test/integration/scheduler/preemption_test.go プリエンプション（英: preemption）は、マルチタスクのコンピュータシステムが実行中のタスクを一時的に中断する動作であり、基本的にそのタスク自体の協力は不要で、後でそのタスクを再実行するという意味も含む。このような動作をコンテキストスイッチと呼ぶ。通常、保護されたタスクか、システムの一部であるプリエンプティブスケジューラが行う。それらは、システム内の他のタスクに割り込み、後でそれらタスクを再開させることができる。「プリエンプト」とは「先取りする、差し替える」の意。

仮説: 前テストによる Node リソースの消費

テストの準備段階として、node1 という特定ノードを作成し、その後テストケースでループし、そのループ内で　Pod の作成を行う。今回はそのループ内での Pod 作成処理で Node リソース部族による Pod スケジューリング失敗が発生、Flake している状況となっている。 1つの仮定として、Pod の Cleanup 処理が最後まで行われずに次のテストに移行、リソース不足が発生していることが考えられる。方法は複数ある

テストをテストケースではなく、完全分離する。リソースを分離することが出来、他テストからの影響を防げる。一方、複数リソースを使うことにより、多くのリソースを消費することになる。
Cleanup 処理を強化する。

Integration flake のローカルでの実行方法

unit testと同じ方法でいける？

Unit testでの Flake 再現方法

$ go install golang.org/x/tools/cmd/stress
$ ls
BUILD  kubelet_client.go  kubelet_client_test.go

パッケージ名 + ".test" のファイルが生成 -c フラグはテストのビルドを行うもの。

$ go test -c -race
...
$ ls
BUILD  client.test  kubelet_client.go  kubelet_client_test.go
$ stress ./client.test -test.run=FlakyTest
4 runs so far, 0 failures
9 runs so far, 0 failures
14 runs so far, 0 failures
19 runs so far, 0 failures
23 runs so far, 0 failures
...

-race フラグはよくわからないので golang に問い合わせ中。go/issues/36329 -race フラグは go help build コマンドで以下のように表示されるもの

        -race
                enable data race detection.
                Supported only on linux/amd64, freebsd/amd64, darwin/amd64 and windows/amd64.

同じ手順を Integration test に対しても行ってみる。 -test.run フラグに FlakyTest を指定しないとテストが実行されないっぽい。（ xxx runs so far, が増えない) このフラグには Flake しているテスト名（TestPreemptionなど）を指定するものだと思っていたけど、違うのか？

test/e2e/kubectl/portforward.go:447
Jan  7 17:17:40.246: Expected "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx" from server, got "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"
test/e2e/kubectl/portforward.go:333

のデバッグ問題の e2e テストコードは次の通り

292 func doTestMustConnectSendDisconnect(bindAddress string, f *framework.Framework) {
293         ginkgo.By("Creating the target pod")
294         pod := pfPod("abc", "10", "10", "100", fmt.Sprintf("%s", bindAddress))
295         if _, err := f.ClientSet.CoreV1().Pods(f.Namespace.Name).Create(pod); err != nil {
296                 framework.Failf("Couldn't create pod: %v", err)
297         }
298         if err := e2epod.WaitForPodReady(f, pod.Name); err != nil {
299                 framework.Failf("Pod did not start running: %v", err)
300         }
301
302         ginkgo.By("Running 'kubectl port-forward'")
303         cmd := runPortForward(f.Namespace.Name, pod.Name, 80)
304         defer cmd.Stop()
305
306         ginkgo.By("Dialing the local port")
307         addr, err := net.ResolveTCPAddr("tcp", fmt.Sprintf("127.0.0.1:%d", cmd.port))
308         if err != nil {
309                 framework.Failf("Error resolving tcp addr: %v", err)
310         }
311         conn, err := net.DialTCP("tcp", nil, addr)
312         if err != nil {
313                 framework.Failf("Couldn't connect to port %d: %v", cmd.port, err)
314         }
315         defer func() {
316                 ginkgo.By("Closing the connection to the local port")
317                 conn.Close()
318         }()
319
320         ginkgo.By("Sending the expected data to the local port")
321         fmt.Fprint(conn, "abc")
322
323         ginkgo.By("Closing the write half of the client's connection")
324         conn.CloseWrite()
325
326         ginkgo.By("Reading data from the local port")
327         fromServer, err := ioutil.ReadAll(conn)
328         if err != nil {
329                 framework.Failf("Unexpected error reading data from the server: %v", err)
330         }
331
332         if e, a := strings.Repeat("x", 100), string(fromServer); e != a {
333                 framework.Failf("Expected %q from server, got %q", e, a)
334         }

333 行目で 100 文字の x を受信する予定がそれより短い x を受信している事によりエラーになっている。 x の長さはエラーになる場合も一定ではない。0のときもあるし 70 位のときもある。

294行目で Pod を作成している。

 62 func pfPod(expectedClientData, chunks, chunkSize, chunkIntervalMillis string, bindAddress string) *v1.Pod {
# pfPod("abc", "10", "10", "100", fmt.Sprintf("%s", bindAddress))

つまり

expedtedClientData: "abc"
chunks: "10"
chunkSize: "10"
chunkIntervalMillis: "100"
bindAddress: bindAddress

これらの値は agnhost コンテナイメージの環境変数として渡される。テストは、

作成した agnhost Pod のポートフォワーディングを行い
そこ（ローカルホストのポート）に TCP 接続して
文字列 "abc" を送信
ローカルホストのポートからデータを受信
100 文字の x を受信していることを確認している。ここで100文字未満の x を受信しエラーになっている。

たぶん、3 から 4 の間が短いから？でも 4 は ioutil.ReadAll(conn) で実装されていて、これが err を返さないときは EOF までデータを読んでいるはずなので、Pod の送信処理は終わっているはず？

agnhost の動作を確認する agnhost とは: https://github.com/kubernetes/kubernetes/tree/master/test/images/agnhost#agnhost

Linux と Windows ではテストに関連して重要な違いが複数ある。
たとえば、DNS suffix list は `/etc/resolv.conf` が Linux のものだが、Windows ではそのようなものは存在しない。同じ情報は別の方法で取り出されるだろう。
このような違いに対処するため、aghnost は作られた。

agnhost は 拡張可能な CLI であり、どのような OS においても同じように振る舞い、同じ結果を出力するように設計されている。この agnhost という名前は agnostic (... に依存しない) と host という言葉から命名された。
このコンテナイメージは OS 間の違いを生めることにより同じテストを実行することができるように、テスト目的で作られている。
...

今回は port-forward-tester が問題の機能なので以下を理解する。 https://github.com/kubernetes/kubernetes/tree/master/test/images/agnhost#port-forward-tester

port-forward-tester は TCP コネクションを指定されたアドレスとポートにおいて Listen する。
オプションとして、データの受信のチェックと、設定された数のデータチャンクを設定されたインターバルで送信する。
この port-forward-tester は以下の環境変数を利用する。
- EXPECTED_CLIENT_DATA: "abc" これが設定された場合、request は同じデータを送信したかチェックする。
- CHUNKS: "10" いくつの数のデータチャンクがレスポンスに書かれるかを指定する
- CHUNK_SIZE: "10" 1つのデータチャンクの想定サイズを指定する
- CHUNK_INTERVAL: "100" chunkIntervalMillis として指定。チャンク間の待ち時間を指定する

文字列 x はハードコーディングされている？ → ただしい、ハードコーディングされている。

126         chunks := getEnvInt("CHUNKS")
127         chunkSize := getEnvInt("CHUNK_SIZE")
128         chunkInterval := getEnvInt("CHUNK_INTERVAL")
129
130         stringData := strings.Repeat("x", chunkSize)   ★ここ
131         data := []byte(stringData)
132
133         for i := 0; i < chunks; i++ {
134                 written, err := conn.Write(data)
135                 if written != chunkSize {
136                         fmt.Printf("Expected to write %d bytes from client, but wrote %d instead. err=%v\n", chunkSize, written, err)
137                         os.Exit(4)
138                 }
139                 if err != nil {
140                         fmt.Printf("Write err: %v\n", err)
141                 }
142                 if i+1 < chunks {
143                         time.Sleep(time.Duration(chunkInterval) * time.Millisecond)
144                 }
145         }

agnhost ポッド側でエラーが発生して異状終了している？ -> 正しい。136行目で以下のエラーで異常終了している。 write tcp 127.0.0.1:80->127.0.0.1:41222: write: broken pipe

conn.Write(data) の error が write tcp 127.0.0.1:80->127.0.0.1:46988: write: broken pipe

oomichi / try-kubernetes

Write how to dig flake test in Kubernetes community #108

手順