Cloud Native Computing Foundation KubeCon + CloudNativeCon North America 2020 - Virtual, 4 Dec 2020

Previous Meeting Next Meeting

⏯

youtube image

►

From YouTube: How the OOM-Killer Deleted My Namespace, and Other Kubernetes Tales - Laurent Bernaille, Datadog

Description

Don’t miss out! Join us at our upcoming event: KubeCon + CloudNativeCon Europe 2021 Virtual from May 4–7, 2021. Learn more at https://kubecon.io. The conference features presentations from developers and end users of Kubernetes, Prometheus, Envoy, and all of the other CNCF-hosted projects.

How the OOM-Killer Deleted My Namespace, and Other Kubernetes Tales - Laurent Bernaille, Datadog

Running Kubernetes at scale is challenging and you can often end up in situations where you have to debug complex and unexpected issues. This requires understanding in detail how the different components work and interact with each other. Over the last 3 years, Datadog migrated most of its workloads to Kubernetes and now manages dozens of clusters consisting of thousands of nodes each. During this journey, engineers have debugged complex issues with root causes that were sometimes very surprising. In this talk Laurent and Tabitha will share some of these stories, including a favorite: how a complex interaction between familiar Kubernetes components allowed an OOM-killer invocation to trigger the deletion of a namespace.

https://sched.co/ekDO

A

Hello, everyone I'm very happy to literally present today- I'd rather be in the same room as you are, but we can do that hopefully next year.

A

um So first of all, let me introduce myself, I'm lauren bernard, I'm staff engineer at datadog, and I work on communities topics mostly and today I'm going to share a few stories of incidents we had from which we learned a lot and I'm going to share what we learned during this incident.

A

In case you don't know, datadog we're a sas based monitoring company.

A

I gave some figures on the left-hand side of the slides, but today we're not going to talk about datadog the product, we're going to talk about our infrastructure and to give you an idea, because this is what will matter today, we're running dozens of kubernetes cluster, some of them up to 4 000 nodes, and we have tens of thousands of nodes and we're growing pretty fast.

A

In terms of context, uh we've shared a few stories about our migration to kubernetes over the last two years, and I gave some examples there and what has changed in the meantime is our infrastructure has kept growing and it's getting bigger and we found new scalability issues and also much more complex problems and doing this.

A

um We've faced a lot of issues and, and today I've picked three different incidents that I personally like for different reasons and the first one is actually the title of this talk and uh and we're going to talk about this incident, because it's interesting how interaction between different components made. This very surprising event happen.

A

So this incident started when an engineer reached out to us and told us: well my name space and everything in it is gone. um Of course.

A

The first thing we did is help the team recover and redeploy everything, but then we wanted to understand what had happened right so we started the investigation and the first thing we did is look at audit logs to see what happened and, of course, we found a lot of deletion, calls for every single thing in the namespace right from replica sets to events and deployments, and of course this was matching perfectly the issue the engineer has seen.

A

However, we didn't see the delete, namespace call, so the initial call that should have triggered this event and, of course the question became. Why was the namespace deleted so we're looking at audit logs and we couldn't find anything and we're zooming out zooming out? Looking at all the events for the specific namespace and after zooming out enough, we discover a delete, call on the namespace four days before the one highlighted there. So this is when the namespace was successfully deleted.

A

However, this successful namespace deletion happened on the certains when the resource edition happened four days later.

A

So, of course, we reached out to the engineer that did the delete call and we were like why. Why did you delete the namespace? What happens and he told us? Well, I didn't delete the namespace, so it was all very weird and we started discussing and he explained to her that he was migrating to a new deployment method. So, let's take a look at how deployments work at databack v1 version of our deployment methods is the one on this slide. Where engineers would modify the charts it would go through ci.

A

We would create a rounded chart with everything in it and at a later time, another engineer would trigger a deployment using spinnaker that would retrieve the run the chart and use cube, ctl applied to apply to the cluster fairly straightforward.

A

This was working fine, but we were trying to make things better and we decided to move to a new version that is described here where all the first part is the same. But at the end to deploy to the cluster we are using home upgrade instead of cuba city applied.

A

So it looks very similar right, but there's a difference if you use the first message and you have a chart with three resources, a b and c, and you create a new version of this chart with new versions of b and c and where you remove a when you do cubesat apply, b and c will be updated, of course, but a will remain because cubesat yellow won't delete it.

A

However, when you use helm upgrade helm is keeping track of the resources you deployed. So it's going to see that a is not there anymore and it will remove it. So that's a big difference right. If you remove something from your chart, it's not going to be in the cluster anymore, and so what happened here is the chart was refactored and the name space was moved out of the chart, and so when the chart was reapplied using helm, the namespace was defeated.

A

So now we understand why the name says was deleted, but what was very surprising was. Why did it take four days so to understand what what had happened? uh We had to look at the namespace controller code, and here on this slide, you can see the function responsible for handling the delete name. Space call and this function is, is made of two important parts. The first part is getting all the resources in the namespace all the available resources and the second part is iterating over all these api resources and deleting them pretty simple right.

A

Let's zoom on the discover all api resources parts. If you look at this, this is how the namespace controller discover all the api resources that are namespace, and if you can see the path I highlight it there. You can see that if the discovery call fails, then the function immediately returns, which means, if you can't discover all resources in the cluster. The content of the messages won't be deleted.

A

Note that this behavior has changed in kubernetes 116., um but this is what happened there um when we saw that we looked at the code from the controller manager where the namespace controller is running and in the logs we saw many of currencies of this line. That says I'm unable to retrieve the complete list of api server apis, because this one is not answering and the metrics one.

A

So the problem with this log that that make uh that makes it a bit hard to to pass. Is that there's no context? You don't know that this log is coming from the namespace controller, so it's hard to link to the incident, but now that we know that uh this is the error from the discovery call and we have potential likely codes, the metrics api.

A

So let's talk about the metrics api.

A

So if you're familiar with kubernetes, you've probably heard about metric server, metric server is an additional controller, provide providing metrics about nodes and pods, and so you can do qtl tab, for instance, or use horizontal port autoscaling and it registers an api service which is an additional set of coins apis and in that case, uh metrics. Api and it's managed by an external controller and when this api service is registered, two pieces of information are provided the additional apis you're providing and where to forward this api call.

A

In that case, the metric server controller in the cube system namespace.

A

So let's go back to the series of events so far on february 13th, the name space was deleted in the next four days. The namespace controller failed to list resources and and, as a consequence, dylan didn't delete the content of the namespace and then something happened on the 17th that unblocked the namespace controller. And then everything was deleted.

A

So we looked at advanced on metric server and we discovered that on this date the metric server was um killed and it restarted and afterwards it was working. Fine and everything wasn't blocked and everything was defeated.

A

So the next question was, but why was metric 7? Failing so to understand this? We need to look at how metric server is deployed in our setup, so metric server is using a certificate so to verify its identity, and we have to rotate the certificate and we use a sidecar to generate a certificate on a regular basis and signal metric server to reload.

A

So that works completely fine, but it requires a specific cointest feature which is called shared namespace, so the sidecar can actually find metric server and for this feature to work, you need two things. You need to modify the spec of your pod, but you also need feature gates on the api server and, most importantly, for our example here on the cubelet in terms of how metric server was deployed, it was running on a set of nodes where we run all our controllers, and this was working completely fine except it wasn't exactly like this.

A

It was actually looking like this. So what I want to highlight in this new diagram is that nodes were a bit different. We had recent nodes where the feature gate was enabled and old nodes where the feature gate was missing.

A

So when we had deployed metric server, it had been deployed on a new node and everything was fine and at one point it was rescheduled on an old mode and seeing something failing, because the site car wasn't able to signal metric server, so matrix server didn't reload its certificate and then api server was failing to contact it.

A

So here is the overall sequence of events sometime before the 13th network. Server was rescheduled on a note, note and discovery calls failed and after being um killed, it picked up the very recent certificate that the stat car I generated from disk and everything was working fine again, and in our case it was a bad thing, because when everything started working fine again, everything was deleted.

A

So key takeaway, api server extensions are great because you can extend your api, uh your kubernetes cluster, to have new apis, and but they can be tricky if the api is not used very much. These extensions can be done for days without any any impact right. However, some controllers rely this api to be available to work properly and can trigger issues.

A

In addition, the communication between the api server and api services is tricky to do right in terms of security and, if you're interested, I really invite you to go and see this talk by tabisa, a colleague of mine, where you learn a lot about tls and api service extensions.

A

So we're now going to talk about a very different incident, and I really like this one, because um it's a low-level bug that also involved networking, which I tend to like quite a bit.

A

So luckily, this incident only happened in staging, but it's still interesting, so we're sharing what we learned from it. So we run our nodes in kubernetes and to do that, of course we have to build images and an engineer on the team pushed a small change and when we were testing this new image, we noted that nodes were becoming not ready after a few days, and what was weird is that change was in no way related to the cubelet or the runtime.

A

But of course uh the nodes were not working, so we couldn't promote to production.

A

So we started investigation and the simplest thing to do was to describe the node, and we can see this message here where the cubelet was not ready, because the container runtime was down container runtime is down well, we use continuity at the run time, and so the first thing we did is check.

A

If continuity was working properly and crstl seemed to say well, yeah content is working fine, so we went back to the cube that logs and we found this line that were interesting, especially the one I highlighted at the in the middle of the slide status from runtime service failed. So we wondered. Maybe we can use your ictl to do the status call it turned out. There is a ci et cetera method to do that, and, and so we we wanted to do it with sierra ctl, there's no cri cgl status sub command.

A

However, there is an info sub command that looks very close, and so we checked in the code and if you call cricitl info, it actually invokes uh the status, cri method and look. We did cricgr info and everything was completely blocked.

A

So now we know that there was definitely an issue and that the qubit was right. So we looked at the code of the status function in continuity and it doesn't do much except invoking this function here, netplugin.status so well. The next step was to look at this function.

A

This function is not really doing much, as you can see, it's basically verifying that you've successfully passed cni configuration and, of course, this error. We already know it's going to tell you that the network is not ready and it's very clear in the queue that logs. However, it's not what we're seeing there we're seeing a timeout, and if you look at the code closely, you will see that on line 126, we have a lock attempt.

A

We have something that hangs. We have a lock. Could this be related?

A

So what we did next is take a dump of all the goroutines from containergy to find blocked ones, and we found quite a lot of them and, as you can see here, all these school routines are blocked, trying to acquire luck and there's a different one. Every two minutes, which is interesting because the errors we were seeing in the cube black were also happening every two minutes, and if we look at the stack trace from one of them, we can see that the lines match exactly what we're looking at before uh in in the code.

A

So it's exactly the problem right. The lock is the problem, so it definitely seems sienna related now, so, let's bypass uh continuity and the cubelet and see if we can reproduce more simply. So what we did is we simply created a network namespace and used this very convenient tool, cni tool that will invoke cni without going through the cuban container.

A

It worked fine and, as you can see at the bottom of the slide, the networking was set up, okay and were able to to being outside of the network namespace. So everything was okay.

A

The next step was we tried to delete uh the network namespace and this completely blocked two, so we actually had identified at that point that the digital was a problem, and after doing that, we looked at the process tree and we found this command here that had been blocked.

A

For quite some time, so let's talk about uh how we do cni in this cluster, we use the lift cni plugin, which we've been extremely happy with, and the delete calls fails for one of the plugin a numbered ptp here and what we did is we modified the code of this plugin to add additional logs and after a few tests.

A

We tracked the problem to this called this call here and what's weird is this is a call from the net link library, so a low level net link library, it's not a code from the listing plugin.

A

So we went to the netflix repo to look for clues and we found this pull request where it actually says that this function specifically doesn't work for knl, 420 and needed to be fixed, and I really want to say to thank daniel baltman for finding the problem in fixing it because, after updating the netlink library in our cni plugin, everything started working perfectly okay again.

A

So as a summary, uh what happened here is: well, um we configured packer to use the latest boot 1904 and at one point the latest ubuntu changed from channel 415 to 5.4 and, as we've just seen, we had an issue with uh candle 420 and the reason the behavior was so weird and it took a few days for things to break was it was a test cluster and this bug only happened on pert deletion. So you need the pod to be deleted to actually trigger it.

A

So key takeaways from this incident is, we tend to consider nodes as abstract compute resources, but we need to remember that nodes are actually instances where you have a kernel distribution hardware and all these things can fail and also remember that error messages can be pretty misleading. Here we have the logs in the qubit were saying that the runtime was down when actually only some parts of the runtime was was down and it was hard to diagnose we're now getting to uh the last story.

A

I want to share with you today and, and this one you're gonna say it's pretty straightforward in terms of what happens. However, we learned quite a lot from it and I want to share that with you.

A

So the prompt started with user reporting connectivity issues to a cluster, and when we checked api server they were not doing very well so, and they were not doing very well because well, they were restarting, they couldn't reach hdd. So the next step was well. Let's look at lcd and well, as you can see from this graph here, memory usage etsy wasn't doing very well either it was even getting um killed, which is not a great thing for et right.

A

So what we know to start the investigation is well. The cluster size is basically the same as it was um a week before we haven't done any upgrades to the control plane, so it's very likely that something changed in the cluster and especially something that interacts with the api server.

A

So, let's look at the number of requests the api server are are serving, and if we look at this graph here, we can see spikes of requests at the time of the incident and especially spike in list calls.

A

We are we're now uh going to talk about list calls because list calls are very expensive so to understand why they are very expensive. We need to understand how api cyber caching works, so api server to make it very simple, are big caches in front of that cd and when they start they list resources and they start watching these resources to update the cache.

A

So that's pretty simple right and then, when client want to access api servers, they can do get all these calls and what is very important here as you're going to see in the next few slides is when you get at least a resource.

A

Ideally, you say which research version you want, because every single resource in kubernetes has a resource version, and this allows you to get a consistent version. I mean whichever api server you connect to.

A

If you specify a resource version, you're going to get the same answer and also, if you do an update, you specify the resource version you want to update, which prevents conflicts when two processes want to update the same resource right, because if the resource has changed, your update code will fail, and you will get this error that you've probably already seen that says resource version too old and then you have to retry, and so, if you do a get on list and set a resource version to something, you'll get this version from the cache of the api server.

A

There is a specific case where you set resolution to zero, which will give you the latest version from the cache. However, what about when you're not setting a resource version? In that case, api server completely bypass the cache and actually gets data directly from a cd and the reason it does.

A

That is because, since you're not specifying anything you're getting the most consistent data, you can get and what's important is this: is the behavior you you have when you use cube ctl get, but it's also the default behavior you get when you use client go the default library used to make use to make communities clients it's going to be exactly the same.

A

So let's illustrate the difference.

A

So, as I was saying, a cube, ctl is only is never setting resource version, so we have to use curl and in this example, I'm getting all the parts in the cluster. In the first example, I'm not setting a resource version, and it takes more than four seconds and in the second case, when I'm setting resource version equals zero, it's much faster, like all almost three times faster.

A

I did this test on a pretty large cluster, which explains why it's taking so long, but also I'm using table view. I'm not getting. The full json object, just a summary version, and I did that to minimize transfer time, because on this cluster, the full json was about one gigabyte.

A

Something that I want to point out is sometimes you want to get a very specific resource and you use label filters label selectors and in that case the the amount of resources you're going to get from the api server is going to be very small, a few parts and in this example here I'm getting only pods from app a and in in that case, it's uh less than five pods, and you can see something interesting here. If I don't set resource version, it's still taking 3.6 seconds it's faster than before, but not that much.

A

However, if I set resource version to zero, it's extremely fast and the reason for this is when you're not setting resource version, all pods are still going to be retrieved from lcd and filtering will happen on the api server, whereas when you set a resource version, the api server with filter will filter locally from its cache. And, of course, this is going to be extremely fast.

A

If you, if you've used a client go to build controllers, um you've probably heard about informers and informers are a way to have clients that are, if much more efficient in the way they talk to the api server because they maintain a cache of the resources they're interested in and they receive events when they change and they're optimized to to be very nice with the api server. So what they do is when they start they do a list and set resource version to zero.

A

So they get data from the cache and then they sell a watch based on the resource version they get.

A

There are some edge cases and reconnections which can trigger a list without resource version set, which is bad as we said before, because then the call will make it to a cd but note that in kubernetes 120 um it should be much better, because watch reconnection should avoid these very expensive calls.

A

So, as a summary remember, that list calls go to lcd by default and can have a huge impact on your cluster.

A

Even if you use label filter and only get a very small sets of of pods or notes, for instance- and the main message is avoid lists and use informers- something that I wanted to point out too is when you use cube. Ctl gets you actually uses. You actually use a list with resource version not set, which is bad to it with that cd, and I believe that group scale could have an option that will that would allow you to set the result version to zero.

A

So you get data from the cache, so it would be much faster and make for a much better user experience. It would be much better for lcd and the control plane in general with a small trade-off, because you will, you will have a small inconsistency window, because uh the api server could be a bit behind at city.

A

I really wanted to to thank uh voytek for his help. Getting this right, I'm sure a few precisions remained, but it helps he helped a lot and thanks again boydek.

A

Let's go back to the incident, so we know the problem comes from lisco. The next step is to identify which application is making these calls so we're getting back to audit logs and, as I was saying before, audit logs are very convenient because they can tell you what happened and when and who did it, but they also contain information about when the request started.

A

Anyway, it was finished, so you can compute the query time and in the graph here uh we're showing the accumulated query time police called by user and, as you can see here, we have a single user that is responsible for more than two days of query time over 20 minutes, which, if you do the math is about 100 uh thread processing list calls at any given time during this window. That's that's a lot.

A

um This is the same view aggregated over a week in the table form, and you can see here that this specific user here is uh using about 30 of uh query time for fps ever that's that's a lot.

A

So as you've made, as you may have seen on the previous slides, uh the user responsible for this was called node group controller. So, let's talk about nerd group controller. It's an analysis controller. We built to allow team to create pools of nodes uh where they can specify the instance type they want to use, for instance, and we've used it extensively for two years.

A

Without any problem, however, we had just deployed a recent upgrade to provide deletion protection and avoid deleting node groups that were running workloads, and so what uh this feature was doing is check each but were still running and refuse deletion. If workloads were still running in there.

A

Technically, this is implemented as an admission controller uh and if you see another delete, call the controller would list all the nodes based on labels.

A

Remember that even when, when you do that, even if the number of nodes you get is small you're still going to hit lcd and get all the nodes and what's important for the next uh step is that some groups are can can be a bit big and then uh the next step is to list all the parts for these nodes, but remember that getting all the parts for this nodes also mean getting all the parts from lcd and filtering on the api server to make things worse, all these calls were made in parallel.

A

So that's a lot of calls making it directly to lcd and of course this is what broke at cd and triggered the incident.

A

So what we learned here is lease calls are very dangerous, because the volume of data can be extremely large and they will hit hcd most of the time, and so I said it before, but I'm saying it again because it's an important message use informers whenever you can also audit logs are extremely useful. Not only can they tell you who did what and when, but they can also tell you which user are responsible for query time, which is very helpful when your api server are overloaded, because then you can know what is happening.

A

So in conclusion, I shared this incident because I found that they were a very good occasion to learn a lot about the inner workings of kubernetes and that's something I wanted to share as a very quick summary of what we learned today.

A

Api service extensions are extremely powerful, but they can harm your cluster, so be very careful in how you monitor them, and we tend to forget that nodes are not abstract resources, which is tempting, especially when you run on cloud right. You just create a vm, it works, but yeah you will.

A

You can have kernel issues and level real issues, and especially for you running large clusters, um you probably need to understand how api server caching is working, because it's very important because it controls the performance of your cluster, be extremely careful careful with how clients interact with the pi server and avoid list calls.

A

I know I've said it a few times, but it's important where we're done for today, if you're interested in in diving into kubernetes and and managing large clusters, we're hiring, um don't they to to reach out to me either by email or twitter or through the kundalini slack. Thank you very much.