k8s.io/test-infra@v0.0.0-20240520184403-27c6b4c223d8/docs/post-mortems/2019-03-26.md

# March 26th, 2019 Boskos Outage

All times in PDT (UTC-7).

## Summary

The Boskos instance responsible for vending GCP projects to test jobs got stuck in a crash loop
due to a hidden bug that was unexpectedly deployed at night. Consequently, all jobs that needed
a project from boskos (including a required job for all kubernetes/kubernetes PRs) failed for
just over nine hours, while on-call was sleeping.

## Impact

All jobs depending on boskos failed between 2019-02-25 23:04 and 2019-02-26 08:12. As a result
it was impossible to merge any PR in kubernetes/kubernetes during those nine hours, because
`pull-kubernetes-e2e-gce` would always fail. There were similar effects on other projects during
this time period. On `pull-kubernetes-e2e-gce` alone, 70 failures were caused by this outage.

## Root Cause

A [bug was introduced](https://github.com/kubernetes/test-infra/commit/02110870507abdeb93dfd6205c70f82145f8993c#r32917192)
in a commit that landed in December last year, that when deployed would cause Boskos to be unable
to start up. Nobody actually attempted to deploy Boskos until last week (2019-03-20). However, while
the StatefulSet that runs Boskos was successfully updated, the actual pod was not replaced due to
lack of any configuration to do so, and nobody noticed the lack of functional change.

At around 17:20, several hours before the outage, we started upgrading the Prow clusters from Kubernetes
1.11 to 1.13. The build cluster has 150 nodes, and each update takes five minutes, so for this entire
process to complete would take about ten hours. Several hours later, nothing looked amiss, and we
went to bed.

At 23:04 the node running the only Boskos pod was drained to be replaced with a 1.13 node, and boskos
was moved to a new node. At this point it used the StatefulSet's spec, which specified a newer image
version with the bug. As a result, boskos was never able to come up on the new node.

## Detection

Users reported issues at 02:50 (via GitHub), 05:16 and 06:27 (both via Slack). While monitoring
[clearly shows the failure](http://velodrome.k8s.io/dashboard/db/boskos-dashboard?orgId=1&from=1553576353087&to=1553615983139),
no alerting caught it.

## Resolution

Once the bug was found, a new image was built and deployed at 10:04. Boskos recovered immediately,
and the projects left hanging open were cleaned up over the next few minutes. Tests began passing
shortly thereafter.

## Lessons Learned

### What went well

- Once people were around to deal with it, the problem was resolved in fairly short order.

### What went poorly

- Beginning a ten-hour deploy process shortly after 5pm when we only have coverage until 6pm is probably inadvisable
- Deployments should be monitored to verify that some actual deployment actually occurred (or, if that's not feasible, not performed at all)
- Boskos' StatefulSet is not configured to perform updates, leading to surprising lack of action
- It appears that the change committed in December was never tested
- Unlike much of Prow, boskos deployments are handled manually, increasing the room for error

### Where we got lucky

We didn't, really.

## Action Items

- Update Boskos' configuration so deployments actually happen as expected ([#11956](https://github.com/kubernetes/test-infra/issues/11956))
- Automate Boskos deploys ([#11957](https://github.com/kubernetes/test-infra/issues/11957))
- Improve alerting around boskos status ([#11953](https://github.com/kubernetes/test-infra/issues/11953))

## Timeline

- [12-05 16:21] Crashloop bug preventing Boskos from updating is introduced
- [03-20 16:46] Boskos StatefulSet spec is updated but the pod is not updated
- [03-26 17:40] Kubernetes node upgrade is initiated on the build cluster
- [03-26 23:04] The node hosting boskos is drained. The replacement pod is stuck in a crash loop. (**outage starts**)
- [03-26 02:50] The outage is reported on GitHub by @mborsz
- [03-26 05:16] The outage is reported on Slack by @chenk008
- [03-26 06:27] The outage is reported on Slack again by @liggitt
- [03-26 07:16] @Katharine wakes up and notices the Slack reports
- [03-26 07:37] @liggitt finds the cause of the failure
- [03-26 08:10] @Katharine successfully deploys a fixed Boskos (**outage ends**)

## Apendix

### #sig-testing chat log

> liggitt [6:27 AM]  
> @Katharine is the "Something went wrong: failed to prepare test environment: --provider=gce boskos failed to acquire project: Post http://boskos.test-pods.svc.cluster.local./acquire?type=gce-project&state=free&dest=busy&owner=pull-kubernetes-e2e-gce" error related to the tot -> snowflake ID change or is that unrelated? (edited) 
> 
> liggitt [6:27 AM]  
> seeing that on all e2e-gce jobs
> 
> Katharine   [07:16 AM]  
Haven't made the snowflake ID change yet so hope it's not preemptively related
>
>liggitt   [07:17 AM]  
>heh, ok
>
>liggitt   [07:17 AM]  
>"winter is coming"
>
>Katharine   [07:20 AM]  
>That is a lot of failures
>
>Katharine   [07:20 AM]  
>```Post http://boskos.test-pods.svc.cluster.local./acquire?type=gce-project&state=free&dest=busy&owner=pull-kubernetes-e2e-gce: dial tcp 10.63.250.132:80: i/o timeout```
>
>Katharine   [07:21 AM]  
>Looks like boskos died completely shortly before midnight PT
>
>liggitt   [07:23 AM]  
>ah
>
>Katharine   [07:24 AM]  
>Strongly suspect the k8s upgrade we did yesterday evening
>
>Katharine   [07:25 AM]  
>```{"error":"CustomResourceDefinition.apiextensions.k8s.io \"resources.boskos.k8s.io\" is invalid: [spec.versions: Invalid value: []apiextensions.CustomResourceDefinitionVersion(nil): must have exactly one version marked as storage version, status.storedVersions: Invalid value: []string(nil): must have at least one stored version]","level":"fatal","msg":"unable to create a CRD client","time":"2019-03-26T09:44:13Z"}```
>
>liggitt   [07:26 AM]  
>did the CRD manifest just change?

>Katharine   [3 hours ago]  
>Not that I know of but there have been a few boskos-adjacent changes lately. Plus a k8s upgrade from 1.11 to 1.13
>
>Katharine   [3 hours ago]  
>I've gotta go for a few minutes
>
>Katharine   [3 hours ago]  
>Also -> #testing-ops

### #testing-ops chat log

>Katharine [7:22 AM]  
>Boskos seems to have gone down  
Looks like it's complaining about CRDs  
Possibly maybe related to that k8s upgrade?  
Timing is off though  
```{"error":"CustomResourceDefinition.apiextensions.k8s.io \"resources.boskos.k8s.io\" is invalid: [spec.versions: Invalid value: []apiextensions.CustomResourceDefinitionVersion(nil): must have exactly one version marked as storage version, status.storedVersions: Invalid value: []string(nil): must have at least one stored version]","level":"fatal","msg":"unable to create a CRD client","time":"2019-03-26T09:44:13Z"}```  
Be right back
>
>liggitt [7:28 AM]  
joined #testing-ops along with Draven.
>
>liggitt [7:37 AM]  
looks like https://github.com/kubernetes/test-infra/commit/02110870507abdeb93dfd6205c70f82145f8993c#r32917192
>
>Katharine [7:39 AM]  
That took a remarkably long time to show up
>
>liggitt [7:40 AM]  
wouldn't have noticed until it got deployed on a new cluster with the CRD missing (edited) 
>
>Katharine [7:40 AM]  
yup
>
>liggitt [7:40 AM]  
clearly, we need CI CI :-D
>
>chenk008 [7:41 AM]  
joined #testing-ops.
>
>dims [7:41 AM]  
turtles all the way down :slightly_smiling_face:
>
>liggitt [7:49 AM]  
I opened https://github.com/kubernetes/test-infra/pull/11947  
I'm not sure what else is required to push a new version of boskos live, so feel free to close that if there's a more complete fix needed
>Katharine [7:52 AM]  
I'm working on it  
unfortunately I'm working on it from a car with a laptop at 5% battery and no physical gnubby so it's an adventure  
(TouchID saves the day, mostly)
>
>liggitt [7:53 AM]  
:car: :fearful: :battery:
>
>Katharine [7:57 AM]  
Made it to the office!
>
>Katharine [8:10 AM]  
we should have a boskos  
yup  
hopefully it recovers  
looks like the janitors are cleaning up the mess and we should be back soon enough  
...meanwhile I'm going to commit these changes.  
Thanks for finding the bug @liggitt!  
https://github.com/kubernetes/test-infra/pull/11949 could use a [retroactive] lgtm from anyone who feels like it
>
>dims [8:20 AM]  
:lgtm:
>
>Katharine [8:21 PM]  
Well that was an uncomfortably exciting morning.

## #testing-ops postmortem thread

>fejta   [8:23 AM]  
Is this related to the cluster upgrade??
>
>Katharine   [8:23 AM]  
My best guess is yes
>
>Katharine   [8:24 AM]  
There was a boskos bug introduced in December that didn't matter until 11pm last night
>
>liggitt   [8:24 AM]  
affected creation of the boskos CRD in new clusters (edited)
>
>liggitt   [8:24 AM]  
and apparently there wasn't a new cluster between December and last night
>
>fejta   [8:40 AM]  
what do you mean by new cluster?
>
>fejta   [8:40 AM]  
I guess upgrading a cluster constitutes a new cluster?
>
>liggitt   [8:40 AM]  
a cluster which did not already have the boskos CRD installed (edited)
>
>fejta   [8:40 AM]  
I upgraded the service and build clusters yesterday, but didn't create any
>
>liggitt   [8:41 AM]  
actually, looks like it would have failed even on existing clusters
>
>liggitt   [8:41 AM]  
so we were using the pre-december version of boskos prior to yesterday?
>
>fejta   [8:41 AM]  
um, no?
>
>Katharine   [8:42 AM]  
No, we were using one from last week
>
>fejta   [8:42 AM]  
The only thing I did was click the upgrade cluster button on the GKE cloud console
>
>Katharine   [8:42 AM]  
And we were still using it until I changed it this morning
>
>fejta   [8:42 AM]  
(also the cluster's nodepools) (edited)
>
>Katharine   [8:42 AM]  
It looks like it got spun up on another node when the one it was on was drained and then crash looped forever
>
>fejta   [8:43 AM]  
maybe something changed between 1.11 and 1.13?
>
>fejta   [8:43 AM]  
in how a bad CRD is handled?
>
>liggitt   [8:44 AM]  
no... the thing it was trying to create would never have been valid
>
>liggitt   [8:44 AM]  
so https://github.com/kubernetes/test-infra/pull/11576/files#diff-7eea92bcdf0c3e4ba5ad151d80562646L89 bumped boskos last week
>
>liggitt   [8:44 AM]  
from a version that would have worked (pre-december) to a version that did not work
>
>liggitt   [8:44 AM]  
and that new version was live and effective?
>
>liggitt   [8:45 AM]  
(I don't know how those manifest changes get rolled out)
>
>fejta   [8:45 AM]  
ideally we should make them auto-deploy like the rest of prow on merge
>
>Katharine   [8:45 AM]  
In boskos' case, manually
>
>liggitt   [8:45 AM]  
is it possible an old working version (boskos:v20180405-12e892d69) was still running until the nodes got drained last night as part of the upgrade? (edited)
>
>liggitt   [8:45 AM]  
ah
>
>fejta   [8:46 AM]  
what would happen if we applied the change last week that was bad?
>
>Katharine   [8:46 AM]  
It's possible someone tried to bump it but it wasn't actually bumped and just kept running an old version
>
>Katharine   [8:46 AM]  
Then when the one pod it has was drained anyway it tried bringing up a new one
>
>fejta   [8:47 AM]  
Is the fact that boskos is a statefulset relevant?
>
>fejta   [8:47 AM]  
(why is it a statefulset? how does applying changes to a statefulset differ from a deployment?)
>
>Katharine   [9:09 AM]  
Checked the audit logs, pod was indeed still running `gcr.io/k8s-testimages/boskos:v20180405-12e892d69` until yesterday despite the statefulset being changed.
>
>fejta   [9:11 AM]  
IMO we should switch it to a deployment
>
>fejta   [9:11 AM]  
I don't think it is stateful so much as a deployment with a PVC
>
>Katharine   [9:12 AM]  
That is also what it looks like to me but Seb probably has the context there
>
>Katharine   [9:17 AM]  
Audit logs also indicate that we tried to update it last week, but nothing happened
>
>Katharine   [9:18 AM]  
so that completes the story