# February 8th, 2019 - Prow responding slow & Partial outage

Created By: [Sen Lu]  
Last Modified: 2019-02-08

## Summary

[K8s Prow instance](prow.k8s.io) was scheduling test jobs onto prow service cluster,
which causes these jobs not finishing (won't start because of missing credentials), and the
service cluster running out of resources. 

## Impact

The jobs got scheduled onto service cluster was not able to start due to missing volumes. (Between
1:46pm - 5:30pm)

All other prow controllers are becoming very slow & unusable (~5min delay for a response from hook)
(Between 4:06pm (first notice) - 5:30pm)


## Root Cause

Our build-cluster secret literally defines a "default" cluster alias which points to our build cluster,
which is not respected by the new client refactor, and by default prow schedules all workloads into the
service cluster (which is the default cluster alias).

See https://github.com/kubernetes/test-infra/pull/11209 for more context.


<!-- TODO(krzyzacy): better understand why this is not deterministic
  https://github.com/kubernetes/test-infra/pull/11263#issuecomment-463312588
 -->

## Detection

https://github.com/kubernetes/test-infra/pull/11200#issuecomment-461988355

When @krzyzacy was poking around a PR, suddenly cats not working! @krzyzacy poked githubstatus.com
where everything is fine, but everything seems fine, @krzyzacy poked on slack, and fount out [prow node
is running at > 100% CPU and Memory](https://kubernetes.slack.com/archives/C7J9RP96G/p1549671585603700)

And then @krzyzacy poked `test-pods` namespace and found out there are 600 pending pods stuck because of
not finding the right secret.

## Resolution

We rolled back prow before the problematic PR.

## Lessons learned

### What went well

- people are still around and we actively identified and mitigated the issue

### What went poorly

- It's AGAIN Friday afternoon

- The behavior is not deterministic

- We really need a real staging Prow :-) We usually depend on each other for something like: hey openshift prow runs fine, so bump k8s prow should be safe, however each prow has different set ups, like how build cluster is defined, etc, so ideally for k8s prow we should have a very similar staging area..

### Where we got lucky

- It's Friday afternoon... and oncall first noticed the problem and we mitigate the issue before EoD

## Action items

- We need to be more careful when deploying sweeping prow changes, aka, have more e2e tests, or have a
  real staging Prow should give us more confidence.

## Timeline

All times in PST, on February 8th 2019

* [13:20] Prow's auto-generated bump PR is merged (https://github.com/kubernetes/test-infra/pull/11172), triggering a deploy.
          And Prow start to schedule workloads onto service cluster.
* [16:04] @krzyzacy noticed Prow is responding very slow, was suspecting a github issue again, but github reports all normal
* [16:19] @krzyzacy found out the CPU/memory usage for prow service nodes are abnormally high
* [16:21] @krzyzacy found out there are hundreds of pending pods in the service cluster, which should live in our build cluster
          and from GKE console it shows there are 225 unschedulable pods
* [16:31] Other people, like @cblecker, start to find out prow had network issues
* [16:40] @krzyzacy rolled Prow back to `v20190206-b01b288` which is before the prow bump
          in the meantime @Katharine cleaned up all the pods & prowjobs in the service cluster
* [16:44] @krzyzacy figured out we need a manual deployment, but missing permission to do so, filed https://github.com/kubernetes/test-infra/issues/11206
* [16:50] @krzyzacy deployed the revert manually via kubectl apply
* [17:07] @krzyzacy found the issue persisted, and confused
* [17:15] @stevekuznetsov asked `does your cluster yaml literally define a "default" cluster alias?` and figured out the issue
* [17:25] @stevekuznetsov sent out a fix as https://github.com/kubernetes/test-infra/pull/11209
          @krzyzacy rolled Prow back to `v20190125-2aca69d` which is before the bug is introduced
* [17:59] @krzyzacy cleaned up all wrong pods and prowjobs again, and confirmed Prow is healthy.
* [18:09] @krzyzacy notified k-dev mailing list

## Appendix 

### #testing-ops chat logs

> krzyzacy [1:46 PM]
we are on `v20190208-c35c7e3` now
`label-sync-1549660620-8nsx4             0/1       OOMKilled   0          29m` /shrug? :thisisfineparrot:

> krzyzacy [4:06 PM]
anyone seeing webhook issues? @stevekuznetsov @munnerz
or actually - `@krzyzacy: https://thecatapi.com appears to be down` :disappointed:

> Katharine [4:09 PM]
I am generally having issues accessing prow.k8s.io (edited) 

> krzyzacy [4:15 PM]
```
time="2019-02-09T00:11:37Z" level=warning msg="Metric families 'name:\"go_memstats_sys_bytes\" help:\"Number of bytes obtained from system.\" type:GAUGE metric:<label:<name:\"instance\" value:\"hook-d5bd467f9-vr6hk\" > label:<name:\"job\" value:\"hook\" > gauge:<value:1.42801144e+08 > > ' and 'name:\"go_memstats_sys_bytes\" help:\"Number of bytes obtained by system. Sum of all system allocations.\" type:GAUGE metric:<label:<name:\"instance\" value:\"ghproxy-79c4f7695b-zmnhx\" > label:<name:\"job\" value:\"ghproxy\" > gauge:<value:5.33741372e+09 > > metric:<label:<name:\"instance\" value:\"plank-7d5d4bdb65-c2475\" > label:<name:\"job\" value:\"plank\" > gauge:<value:1.056411896e+09 > > metric:<label:<name:\"instance\" value:\"plank-7854db4c49-h9zpn\" > label:<name:\"job\" value:\"plank\" > gauge:<value:1.265917176e+09 > > ' are inconsistent, help and type of the latter will have priority. This is bad. Fix your pushed metrics!" source="diskmetricstore.go:114"
```

what does that mean :confused: (edited) 

> krzyzacy [4:19 PM]
`gke-prow-default-pool-116f5d3e-bl6h   4022m        102%      13681Mi         110%` that's also worrisome...

> krzyzacy [4:21 PM]
there are hundreds of pods in the service cluster?

> cblecker [4:31 PM]
replied to a thread:
I'm seeing jobs that are failing on network stuff, failing to upload logs to GCS, and bot commands that aren't responding at all.View newer replies

> bentheelder [4:37 PM]
days since prow k8s client bugs: 0

> krzyzacy [4:40 PM]
https://github.com/kubernetes/test-infra/pull/11205
krzyzacy
#11205 Revert "Bump prow from v20190206-b01b288 to v20190208-c35c7e3"

> bentheelder [4:42 PM]
also seeing errors doing /lgtm, assigning is failing

> Katharine [4:42 PM]
I think this is all just fallout from it being crazy overloaded (edited) 

> Katharine [4:42 PM]
110% is not a reasonable amount of scheduling

> stevekuznetsov [4:54 PM]
man
deploy friday evening
they said
it will be fine they said

> bentheelder [4:55 PM]
[:fire: :fire_engine:  ongoing]

> stevekuznetsov [5:00 PM]
Question by the way @Katharine @bentheelder @krzyzacy are you using cpu/mem requests and limits? _very_ surprised that schduler was able to starve core prow services from doing things -- obviously scheduling to the service cluster is not what you wanted but also...

> krzyzacy [5:01 PM]
we have limits for build cluster!

> stevekuznetsov [5:02 PM]
Shouldn't the limits be on the Pods?
Oh you're saying no prow service deployments have limits/requests

> fejta [5:03 PM]
So we're scheduling all jobs in the service cluster?

> stevekuznetsov [5:03 PM]
not anymore
but that was the symptom seen
@fejta Sen posted the startup logs for the "good" plank deployment here
krzyzacy
```
senlu@senlu:~/work/src/k8s.io/test-infra/prow/cluster$ kubectl logs plank-64c7c5cbd4-fx5g6
{"component":"plank","level":"info","msg":"Loading cluster contexts...","time":"2019-02-09T00:50:01Z"}
{"component":"plank","level":"info","msg":"* in-cluster","time":"2019-02-09T00:50:01Z"}
{"component":"plank","level":"info","msg":"* test-infra-trusted","time":"2019-02-09T00:50:01Z"}
{"component":"plank","level":"info","msg":"* default","time":"2019-02-09T00:50:01Z"}
```
 Show more
From a thread in #testing-opsFeb 8thView reply
has not posted a "bad" one yet

krzyzacy [5:04 PM]
```
E  {"level":"info","component":"plank","msg":"Loading cluster contexts..."} 
E  {"component":"plank","msg":"* in-cluster","level":"info"} 
E  {"component":"plank","msg":"* k8s-tpu-operator","level":"info"} 
E  {"component":"plank","msg":"* security","level":"info"} 
E  {"component":"plank","msg":"* test-infra-trusted","level":"info"} 
E  {"component":"plank","msg":"* default","level":"info"}
``` 
is that enough?

> stevekuznetsov [5:05 PM]
is there a diff between the two?
The "good" one seems to have

```
{"component":"plank","level":"info","msg":"* gke_rules-k8s_us-central1-f_testing","time":"2019-02-09T00:50:01Z"}
```
whereas the bad one does not?
Which is the alias for the service cluster?

> stevekuznetsov [5:06 PM]
(why is the kubeconfig for the service cluster even in your clusters yaml given to plank to schedule pods????)

> stevekuznetsov [5:06 PM]
Also I need to jump but if you confirm the SHA bounds that @Katharine posted ... there is no suspicious code change in that deployment AFAICT

```
$ git log --no-merges --pretty='%cd | %h | %<(20)%an | %s' --date=short b01b288..c35c7e3 -- prow/ ':!prow/config.yaml' ':!prow/plugins.yaml' ':!prow/cluster'
2019-02-07 | 73ab4a815 | Kyle Weaver          | Deck: add missing org to GitHub links
2019-02-07 | 4bef440ea | Katharine Berry      | Satisfy the TypeScript linter.
2019-02-07 | fabe99ef2 | Katharine Berry      | Update prow/cmd/deck/static/prow/prow.ts
2019-02-07 | f58a0539c | Matthias Bertschy    | Adding PluginHelp.Config for size
2019-02-06 | acdf2fbb3 | Benjamin Elder       | register help for buildifier
2019-02-06 | 9d5466153 | Mikhail Konovalov    | update broken link
2019-01-26 | e9312fed6 | Alvaro Aleman        | Fix spyglass cell generation when using spyglass as primary viewer
```

> Katharine [5:07 PM]
We've tracked the start of bad scheduling to three minutes after the last deploy

> krzyzacy [5:07 PM]
I think the problem persists after I revert back to wednesday

> stevekuznetsov [5:07 PM]
Do you have API server audit logs for your secrets?
Are you certain your secrets did not change?

> Katharine [5:08 PM]
(maybe the deployer itself is busted?)

> stevekuznetsov [5:08 PM]
oh okay so per @fejta the issue is an incorrect _namespace_ in the correct _cluster_

> Katharine [5:09 PM]
Incorrect jobs in the correct namespace in the wrong cluster

> stevekuznetsov [5:09 PM]
ah

> Katharine [5:09 PM]
There are jobs that should go there, but they are not these ones

> stevekuznetsov [5:09 PM]
can you confirm that your cluster yaml file has the correct alias mapping to the correct cluster
were you also seeing trusted jobs scheduled to the normal build clsuter
was it jobs _regardless of alias_ scheduling to the trusted cluster
or was it only jobs for the normal build alias scheduling to the build cluster

> Katharine [5:10 PM]
I haven't checked, don't know if anyone else has. Will take a look at what's going on there

> stevekuznetsov [5:10 PM]
Is it still going on?
(audit logs for the secret holding your cluster yaml would be huge)

> Katharine [5:11 PM]
apparently yes.

> krzyzacy [5:12 PM]
hummmm - the one from Wednesday seems to be good?
(but not anymore?)

> Katharine [5:13 PM]
we were still creating pods in the build cluster after we started also creating them in the service cluster

> krzyzacy [5:13 PM]
```
senlu@senlu:~/work/src/k8s.io/test-infra/prow/cluster$ kubectl get secret
NAME                     TYPE                                  DATA      AGE
build-cluster            Opaque                                1         352d
```

that didn't got a change

> fejta [5:13 PM]
I don't think it is that exciting, just a bad release

> fejta [5:14 PM]
`kubectl --context=prow get pods --namespace=test-pods -o yaml  | grep prow.k8s.io/job`
basically just looks like everything is scheduling in the service cluster now
```
$ kubectl --context=prow-builds get pods --namespace=test-pods -o yaml  | grep prow.k8s.io/job | wc -l
     532
fejta-macbookpro:test-infra fejta$ kubectl --context=prow get pods --namespace=test-pods -o yaml  | grep prow.k8s.io/job | wc -l
    1308
```

> stevekuznetsov [5:15 PM]
```
kubectl --context=prow get pods --namespace=test-pods -o "jsonpath={.items[*].spec.job}" | tr ' ' $'\n' | sort | uniq -c | sort -nr
```
hrm
so it looks like the "default" cluster was used for normal jobs in the past
does your cluster yaml literally define a "default" cluster alias?

> fejta [5:17 PM]
yes

> stevekuznetsov [5:18 PM]
I think I see the bug
very interesting
I think this is just not deterministic
but is a bad commit from before
always latent

> bentheelder [5:19 PM]
replied to a thread:
A lot of these were already cleaned up. Everything in the wrong cluster means nothing running ...?
Plus prow is non-responsive / broken in general because the services cluster is overloaded.View newer replies

> krzyzacy [5:21 PM]
hummm
shall we roll back to last week?

> fejta [5:21 PM]
yes
these client refactors are a dud :stuck_out_tongue:
We really ought not to have refactored every binary at once, and gotten some signal that things work first. Oh well.
We should consider reverting plank to use the old client until we can prove things work correctly for the other binaries.
Not sure how much trouble that will be at this point.

> stevekuznetsov [5:24 PM]
you want to revert to at least `ca4be59af7dc673b3b5fb3a16711bee21b4e736a`

> bentheelder [5:24 PM]
aside: this failure mode is odd https://github.com/kubernetes/sig-release/pull/467#issuecomment-461994843 (edited) 

> stevekuznetsov [5:24 PM]
reverting commit to `plank` should be fine

> krzyzacy [5:25 PM]
https://github.com/kubernetes/test-infra/pull/11205
krzyzacy
#11205 Revert prow to v20190125-2aca69d
This reverts commit e6a015b.

/assign @BenTheElder @Katharine
Assignees
Katharine, BenTheElder
Labels
approved, area/config, area/prow, area/prow/bump, cncf-cla: yes, sig/testing, size/M
kubernetes/test-infraFeb 8thAdded by GitHub
I believe if we only revert plank, sinker will also be busted
lol I start to type things like `kubectl commit --amend`

> krzyzacy [5:59 PM]
```
senlu@senlu:~/work/src/k8s.io/test-infra/prow$ kubectl top nodes
NAME                                  CPU(cores)   CPU%      MEMORY(bytes)   MEMORY%   
gke-prow-default-pool-116f5d3e-1t67   85m          2%        5228Mi          42%       
gke-prow-default-pool-116f5d3e-2jr0   141m         3%        2948Mi          23%       
gke-prow-default-pool-116f5d3e-3s34   212m         5%        4702Mi          37%       
gke-prow-default-pool-116f5d3e-8q5f   351m         8%        3905Mi          31%       
gke-prow-default-pool-116f5d3e-bl6h   2349m        59%       3519Mi          28%       
gke-prow-default-pool-116f5d3e-csc4   252m         6%        3359Mi          27%       
gke-prow-default-pool-116f5d3e-qdpu   70m          1%        2505Mi          20%       
gke-prow-default-pool-116f5d3e-rdf6   1531m        39%       1721Mi          13%       
gke-prow-ghproxy-2cc2c707-n3p7        76m          0%        2574Mi          9%        
senlu@senlu:~/work/src/k8s.io/test-infra/prow$ kubectl get po -n=test-pods
NAME                                   READY     STATUS    RESTARTS   AGE
a17e4af9-2c0c-11e9-b21b-0a580a6c0715   2/2       Running   0          9m
cm-acme-http-solver-qswmf              1/1       Running   0          9m
cm-acme-http-solver-vfcsk              1/1       Running   0          9m
```

things should be fine now - there's also a pending fix https://github.com/kubernetes/test-infra/pull/11209 - will send out an email to k-dev shortly.
stevekuznetsov
#11209 Don't overwrite a provided literal default client
Signed-off-by: Steve Kuznetsov skuznets@redhat.com

This fixes the issue we had today

/assign @fejta @cjwagner  
/cc @BenTheElder @krzyzacy
Assignees
fejta, cjwagner
Labels
approved, area/prow, cncf-cla: yes, sig/testing, size/XS
kubernetes/test-infraFeb 8thAdded by GitHub

---
