Bug 1749468

New info, found this in the kube-controller-manager log. This means that since the pod is being reported with an init container that has no cpu usage listed, the pod is not being considered in the metrics list for calculating the replica count

2019-09-05T17:10:05.117720430+00:00 stderr F I0905 17:10:05.117602       1 rest_metrics_client.go:84] missing resource metric cpu for container empty-init in pod play/mongo-ss-0

This routine looks like this

// GetResourceMetric gets the given resource metric (and an associated oldest timestamp)
// for all pods matching the specified selector in the given namespace
func (c *resourceMetricsClient) GetResourceMetric(resource v1.ResourceName, namespace string, selector labels.Selector) (PodMetricsInfo, time.Time, error) {
        metrics, err := c.client.PodMetricses(namespace).List(metav1.ListOptions{LabelSelector: selector.String()})
        if err != nil {
                return nil, time.Time{}, fmt.Errorf("unable to fetch metrics from resource metrics API: %v", err)
        }

        if len(metrics.Items) == 0 {
                return nil, time.Time{}, fmt.Errorf("no metrics returned from resource metrics API")
        }

        res := make(PodMetricsInfo, len(metrics.Items))

        for _, m := range metrics.Items {
                podSum := int64(0)
                missing := len(m.Containers) == 0
                for _, c := range m.Containers {
                        resValue, found := c.Usage[v1.ResourceName(resource)]
                        if !found {
                                missing = true
                                klog.V(2).Infof("missing resource metric %v for container %s in pod %s/%s", resource, c.Name, namespace, m.Name)
                                break // containers loop
                        }
                        podSum += resValue.MilliValue()
                }

                if !missing {
                        res[m.Name] = PodMetric{
                                Timestamp: m.Timestamp.Time,
                                Window:    m.Window.Duration,
                                Value:     int64(podSum),
                        }
                }
        }

        timestamp := metrics.Items[0].Timestamp.Time

        return res, timestamp, nil
}

imho, init containers must either not be included in the rest metrics result if they are completed, or they must be reported with a cpu value (probably 0)

Just to be explicit, the obvious workaround here is to eliminate the init container(s).

There are at least a couple of different ways to do this in many situations:

1) refactor the init logic into the entrypoint(s) of the other container(s) so that the main container processes are not started until the init conditions are met

2) replace the init container(s) with sidecar container(s) that perform the init functions but never exit. Then gate the start of the main container processes on the creation of a secret, or a file lock in a shared file system on the pod, etc, and open the gate from the sidecar after the init conditions are met and before it loops forever ...

3) others?

I believe that I have found the source of this bug and I will be working on potential solutions. The problem stems from podmetrics treating containers and initContainers the same, so once an initContainer has finished running, it has no CPU metrics. When HPA sees that the CPU metrics are missing from the podmetrics, it returns no metrics at all.

See https://github.com/kubernetes/kubernetes/blob/3aa59f7f3077642592dc8a864fcef8ba98699894/pkg/controller/podautoscaler/metrics/rest_metrics_client.go#L84-L86

I'll update this bug once we have a solution proposed.

*** Bug 1780742 has been marked as a duplicate of this bug. ***

Hi Joel,

yes that's what I had found empirically too, that specific error message appeared in my log
https://bugzilla.redhat.com/show_bug.cgi?id=1749468#c1


(In reply to Joel Smith from comment #13)
> I believe that I have found the source of this bug and I will be working on
> potential solutions. The problem stems from podmetrics treating containers
> and initContainers the same, so once an initContainer has finished running,
> it has no CPU metrics. When HPA sees that the CPU metrics are missing from
> the podmetrics, it returns no metrics at all.
> 
> See
> https://github.com/kubernetes/kubernetes/blob/
> 3aa59f7f3077642592dc8a864fcef8ba98699894/pkg/controller/podautoscaler/
> metrics/rest_metrics_client.go#L84-L86
> 
> I'll update this bug once we have a solution proposed.

I think we are much closer to identifying a root cause on this issue. This comment will provide a lot of the findings from my work along with some ideas for potential fixes.

I believe that this specific cause is only evident when using CRI-O as a runtime and cAdvisor for the kubelet statistics. This is the current state of affairs for OCP 4.x.

Root cause summary:

The root cause appears to be that when an init container exits, its cgroup slices are partially cleaned up, but not fully cleaned up. Specifically, the memory slice is cleaned up (by systemd), but the cpuset isn't. This results in cAdvisor providing partial statistics for the init container. The partial metrics (i.e. CPU, but no memory) will prevent HPA from taking any action on the pod as it considers the missing metrics to be an error.

Details:

When running a pod with an init container, once the init container exits, the container still remains in cri-o with status Exited. 

Via oc get --server http://<node>:10255 --raw /metrics/cadvisor
cAdvisor shows CPU metrics like container_spec_cpu_shares but is missing memory metrics like  container_spec_memory_reservation_limit_bytes. That's because after the container exits,

/sys/fs/cgroup/cpuset/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod<podid>.slice/crio-<cid>.scope

still exists, but 

/sys/fs/cgroup/memory/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod<pid>.slice/crio-<cid>.scope

doesn't. As I understand it, since we create the cpuset slice in runc without systemd's knowledge, systemd shouldn't remove it. runc does eventually remove it, but not until the Exited container is completely removed from the system (which usually won't happen until the pod is deleted or restarted).


I started testing with the Kubernetes Metrics Server, which is an implementation of the Kubernetes Metrics API. We don't use it in OCP but we use prometheus to implement that same API.  I found that if Metrics Server can get CPU or memory statistics, but not both, it ignores all metrics for a pod. This prevents HPA from being able to scale any pod with an init container. 

The behavior with our prometheus-backed metrics endpoint on OCP is a little different. It provides the CPU metrics, but because it doesn't also provide the memory metrics, the HPA ignores all metrics for the entire pod because it considers it an error that it can't get both CPU and memory.

For runtimes that don't use cAdvisor for their pod statistics, code has been added to kubelet's CRI stats provider where missing memory or CPU stats are added with zero values for any terminated containers. This allows Metrics Server to track them, thus also allowing HPA to handle pods with init containers. This would also allow HPA to handle them in the prometheus case too.

When CRI-O is used, the Kubelet is still relying upon cAdvisor for the Kubelet's statistics.
https://github.com/kubernetes/kubernetes/blob/master/pkg/kubelet/cadvisor/util.go#L78
If CRI-O provided the metrics instead via the CRI, the Kubelet would populate the missing fields. 
https://github.com/kubernetes/kubernetes/pull/74336/files

Potential ways to address the problem:

There are several places this could be fixed. Which makes the most sense? Possible ideas:

* CRI-O and/or runc? Should CRI-O be cleaning up the cpuset cgroup for an exited container? Should it leave the memory cgroup? In our team discussion today we said that the memory cgroup is cleaned up by systemd. We're going to explore having CRI-O clean up the cpuset cgroup as soon as the container goes to the Exited state.

* Core k8s? Should the system tell the runtime to remove the container as soon as it has exited successfully? In our team meeting, we said that, no, the Kubelet always keeps around at least the most recently exited container so that its logs are available.


* Kubelet statistics? Should the Kubelet statistics handle missing memory metrics in cases where CPU metrics are provided? This PR fixes the issue for me, but I don't know what side effects it might cause. https://github.com/kubernetes/kubernetes/pull/88734 We would get the same result by reversing the logic so that the CPU metrics are removed if the memory ones aren't present. There is already similar logic in the CRI statistics codepath, so maybe an argument can be made for this approach. See https://github.com/kubernetes/kubernetes/pull/74336/files for that fix.

* Metrics Server? (We don't use it so any changes won't fix our issues, but one could argue that it has a bug in that it isn't resilient in the face of the missing metrics)


* HPA? One could argue that it should handle missing metrics better. Perhaps it should use the previous reading for any missing metric or zero if there was no previous reading. But that could also be considered a bug. The danger there is that we don't want it to make scale decisions based upon bad data and how can it tell the difference between no data because the container is gone and no data because of a failure in the metrics pipeline?

How to reproduce (as minimally as possible):

Step 1. Get a node with a running kubelet. If you already have a K8s or OCP cluster, you can just use a node there. I also was able to reproduce this with a minimal K8s hack/local-up-cluster.sh cluster. Here are some instructions for creating one in case it is helpful for reproducing.

a. Clone upstream https://github.com/kubernetes/kubernetes
b. Make sure that your podman cni network won't conflict with your cri-o pod network. Check to make sure that /etc/cni/net.d/87-podman-bridge.conflist and /etc/cni/net.d/100-crio-bridge.conf don't use the same range. I changed my podman range to 10.87.0.0/16 and left my cri-o one at 10.88.0.0.16
c. Make sure cri-o is running: sudo systemctl start crio
d. Run the following from your local kubernetes git workspace, changing the 10.88.0.1 to whatever the first host would be in the range from /etc/cni/net.d/100-crio-bridge.conf.

HOSTNAME_OVERRIDE=10.88.0.1 KUBELET_HOST=10.88.0.1 SERVICE_CLUSTER_IP_RANGE=10.2.0.0/24 FIRST_SERVICE_CLUSTER_IP=10.2.0.1 KUBE_DNS_SERVER_IP=10.2.0.10 NET_PLUGIN=podman CGROUP_DRIVER=systemd CONTAINER_RUNTIME=remote CONTAINER_RUNTIME_ENDPOINT='unix:///var/run/crio/crio.sock' ./hack/local-up-cluster.sh

Step 2. Make sure that you have a valid kubeconfig with admin rights.  If using a local-up-cluster, that will probably be:
export KUBECONFIG=/var/run/kubernetes/admin.kubeconfig

Step 3. Create a deployment for a simple pod with an init container:

cat <<EOF oc create -f -
---
apiVersion: apps/v1
kind: Deployment
metadata:
  name: busybox-deployment
  labels:
    app: busybox
spec:
  replicas: 1
  selector:
    matchLabels:
      app: busybox
  template:
    metadata:
      labels:
        app: busybox
    spec:
      automountServiceAccountToken: false
      containers:
      - image: gcr.io/google-containers/busybox:latest
        name: busybox
        command: ["/bin/sh"]
        args: ["-c", "while sleep 3600; do echo sleeping another hour; done; echo Exiting"]
        resources:
          requests:
            cpu: 100m
            memory: 100Mi
      initContainers:
      - command: [ "sh", "-c", "echo The app is running! && sleep 60" ]
        image: gcr.io/google-containers/busybox:latest
        name: init
EOF

4. As soon as the init container has exited (after one minute), look at the kubelet's pod statistics:

oc get --server http://10.88.0.1:10255 --raw '/stats/summary?only_cpu_and_memory=true' | less

(change 10.88.0.1 to the address of your kubelet if different).

You should see that for the exited init container, the CPU stats are there but the memory stats aren't.

Likewise, you should see that the memory cgroup slice has been deleted but the cpuset cgroup slice hasn't.

Kir is going to explore the possibility of having CRI-O clean up the cpuset cgroup slice for Exited containers.

Reproduced locally.

If runc is not using systemd, none of cgroups get removed until "runc delete" is called.


If runc is asked to use systemd, it creates half of cgroups via systemd (and those are cleaned up by systemd), half manually (and those are not removed until "runc delete" is called). The ones that are not removed (that is, on my system) are:

* freezer
* perf_event
* net_cls,net_prio
* hugetlb
* cpuset

Now, removing the /sys/fs/cgroup/cpuset/..../crio-$CTID.scope directory fixes the issue, i.e. information about stopped init container memory usage no longer appears in /stats/summary.

The question is -- why do we create cpuset group? AFAIK Kubernetes do not support cpusets at all (see https://github.com/kubernetes/kubernetes/issues/10570), although Docker and runc does.

Apparently, runc creates all the cgroups, whether the limits are set or not. I can think of two reasons to do that:
 - to allow getting usage statistics;
 - to allow setting some limits later.

Now, systemd does not support setting cpuset controller parameters (it has CPUAffinity= but it uses sched_setaffinity(2) and not cpusets.cpus).

Anyway, I was just trying hard to find a way to not introduce a hack of removing a cgroup (either by not creating it in the first place, or using systemd to create it, etc).

Alas, I see no way of doing it. Dirty dirty hack will follow.

One option is calling runc delete after we have persisted the stopped state for a container. That way we don't have to go in and care about a particular cgroup
and we rely on runc delete doing it for us instead.

I'm simultaneously pursuing a fix in the kubelet's cadvisor stat's provider. I think it's good if we can get both in, but either one will (hopefully) take care of the issue. My WIP PR is https://github.com/kubernetes/kubernetes/pull/88734 and I'll update this bug once I'm a little further along (need to add some unit tests).

> One option is calling runc delete after we have persisted the stopped state for a container.

I was thinking about that as well, but that changes too much. For one thing, currently a stopped container is shown in `runc list` as stopped, and after the change the stopped containers will magically disappear.

I believe the proper fix belongs to whoever gather the statistics. Since kubernetes do not set/use cpuset cgroup controller, the usage info from this controller must not be reported.

If you can point me out to a component that is reading those cgroup files, I can look into fixing it.

I have a PR upstream that fixes this by adding zero-valued statistics for exited containers. I'm picking it back to Origin, so I'll take this bug back. Thanks, Kir, for looking into the crio approach to fixing it, and sorry that it wasn't straightforward to address.

Cherry-pick origin PR is https://github.com/openshift/origin/pull/24653

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:2409

Created attachment 1713524 [details]
dc with initContainer

Re-closing. The symptoms of the new bug seem to be the same, but it is a different cause. We'll use #1867477 to track the new issue.

Sorry, I meant to link to the other bug: https://bugzilla.redhat.com/show_bug.cgi?id=1867477

*** This bug has been marked as a duplicate of bug 1867477 ***