kubelet: Force deleted pods can fail to move out of terminating

If a CRI error occurs during the terminating phase after a pod is
force deleted (API or static) then the housekeeping loop will not
deliver updates to the pod worker which prevents the pod's state
machine from progressing. The pod will remain in the terminating
phase but no further attempts to terminate or cleanup will occur
until the kubelet is restarted.

The pod worker now maintains a store of the pods state that it is
attempting to reconcile and uses that to resync unknown pods when
SyncKnownPods() is invoked, so that failures in sync methods for
unknown pods no longer hang forever.

The pod worker's store tracks desired updates and the last update
applied on podSyncStatuses. Each goroutine now synchronizes to
acquire the next work item, context, and whether the pod can start.
This synchronization moves the pending update to the stored last
update, which will ensure third parties accessing pod worker state
don't see updates before the pod worker begins synchronizing them.

As a consequence, the update channel becomes a simple notifier
(struct{}) so that SyncKnownPods can coordinate with the pod worker
to create a synthetic pending update for unknown pods (i.e. no one
besides the pod worker has data about those pods). Otherwise the
pending update info would be hidden inside the channel.

In order to properly track pending updates, we have to be very
careful not to mix RunningPods (which are calculated from the
container runtime and are missing all spec info) and config-
sourced pods. Update the pod worker to avoid using ToAPIPod()
and instead require the pod worker to directly use
update.Options.Pod or update.Options.RunningPod for the
correct methods. Add a new SyncTerminatingRuntimePod to prevent
accidental invocations of runtime only pod data.

Finally, fix SyncKnownPods to replay the last valid update for
undesired pods which drives the pod state machine towards
termination, and alter HandlePodCleanups to:

- terminate runtime pods that aren't known to the pod worker
- launch admitted pods that aren't known to the pod worker

Any started pods receive a replay until they reach the finished
state, and then are removed from the pod worker. When a desired
pod is detected as not being in the worker, the usual cause is
that the pod was deleted and recreated with the same UID (almost
always a static pod since API UID reuse is statistically
unlikely). This simplifies the previous restartable pod support.
We are careful to filter for active pods (those not already
terminal or those which have been previously rejected by
admission). We also force a refresh of the runtime cache to
ensure we don't see an older version of the state.

Future changes will allow other components that need to view the
pod worker's actual state (not the desired state the podManager
represents) to retrieve that info from the pod worker.

Several bugs in pod lifecycle have been undetectable at runtime
because the kubelet does not clearly describe the number of pods
in use. To better report, add the following metrics:

  kubelet_desired_pods: Pods the pod manager sees
  kubelet_active_pods: "Admitted" pods that gate new pods
  kubelet_mirror_pods: Mirror pods the kubelet is tracking
  kubelet_working_pods: Breakdown of pods from the last sync in
    each phase, orphaned state, and static or not
  kubelet_restarted_pods_total: A counter for pods that saw a
    CREATE before the previous pod with the same UID was finished
  kubelet_orphaned_runtime_pods_total: A counter for pods detected
    at runtime that were not known to the kubelet. Will be
    populated at Kubelet startup and should never be incremented
    after.

Add a metric check to our e2e tests that verifies the values are
captured correctly during a serial test, and then verify them in
detail in unit tests.

Adds 23 series to the kubelet /metrics endpoint.
This commit is contained in:
Clayton Coleman
2022-10-18 11:54:49 -04:00
parent c5a1f0188b
commit 6b9a381185
13 changed files with 2970 additions and 676 deletions

View File

@@ -24,6 +24,8 @@ import (
"github.com/onsi/ginkgo/v2"
"github.com/onsi/gomega"
"github.com/onsi/gomega/gstruct"
"github.com/prometheus/common/model"
v1 "k8s.io/api/core/v1"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/types"
@@ -133,6 +135,38 @@ var _ = SIGDescribe("MirrorPodWithGracePeriod", func() {
ginkgo.Context("and the container runtime is temporarily down during pod termination [NodeConformance] [Serial] [Disruptive]", func() {
ginkgo.It("the mirror pod should terminate successfully", func(ctx context.Context) {
ginkgo.By("verifying the pod is described as syncing in metrics")
gomega.Eventually(ctx, getKubeletMetrics, 5*time.Second, time.Second).Should(gstruct.MatchKeys(gstruct.IgnoreExtras, gstruct.Keys{
"kubelet_working_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_working_pods{config="desired", lifecycle="sync", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="sync", static="true"}`: timelessSample(1),
`kubelet_working_pods{config="orphan", lifecycle="sync", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="sync", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="sync", static="unknown"}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminating", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminating", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminating", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminating", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="terminating", static="unknown"}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminated", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminated", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminated", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminated", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="terminated", static="unknown"}`: timelessSample(0),
}),
"kubelet_mirror_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_mirror_pods`: timelessSample(1),
}),
"kubelet_active_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_active_pods{static=""}`: timelessSample(0),
`kubelet_active_pods{static="true"}`: timelessSample(1),
}),
"kubelet_desired_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_desired_pods{static=""}`: timelessSample(0),
`kubelet_desired_pods{static="true"}`: timelessSample(1),
}),
}))
ginkgo.By("delete the static pod")
err := deleteStaticPod(podPath, staticPodName, ns)
framework.ExpectNoError(err)
@@ -152,17 +186,104 @@ var _ = SIGDescribe("MirrorPodWithGracePeriod", func() {
return err
}, 2*time.Minute, time.Second*5).ShouldNot(gomega.Succeed())
ginkgo.By("verifying the mirror pod is running")
gomega.Consistently(ctx, func(ctx context.Context) error {
return checkMirrorPodRunning(ctx, f.ClientSet, mirrorPodName, ns)
}, 19*time.Second, 200*time.Millisecond).Should(gomega.BeNil())
ginkgo.By("verifying the pod is described as terminating in metrics")
gomega.Eventually(ctx, getKubeletMetrics, 5*time.Second, time.Second).Should(gstruct.MatchKeys(gstruct.IgnoreExtras, gstruct.Keys{
"kubelet_working_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_working_pods{config="desired", lifecycle="sync", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="sync", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="sync", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="sync", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="sync", static="unknown"}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminating", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminating", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminating", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminating", static="true"}`: timelessSample(1),
`kubelet_working_pods{config="runtime_only", lifecycle="terminating", static="unknown"}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminated", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminated", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminated", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminated", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="terminated", static="unknown"}`: timelessSample(0),
}),
"kubelet_mirror_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_mirror_pods`: timelessSample(1),
}),
"kubelet_active_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_active_pods{static=""}`: timelessSample(0),
// TODO: the pod is still running and consuming resources, it should be considered in
// admission https://github.com/kubernetes/kubernetes/issues/104824 for static pods at
// least, which means it should be 1
`kubelet_active_pods{static="true"}`: timelessSample(0),
}),
"kubelet_desired_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_desired_pods{static=""}`: timelessSample(0),
`kubelet_desired_pods{static="true"}`: timelessSample(0),
})}))
ginkgo.By("start the container runtime")
err = startContainerRuntime()
framework.ExpectNoError(err, "expected no error starting the container runtime")
gomega.Consistently(ctx, func(ctx context.Context) error {
ginkgo.By(fmt.Sprintf("verifying that the mirror pod (%s/%s) is running", ns, mirrorPodName))
err := checkMirrorPodRunning(ctx, f.ClientSet, mirrorPodName, ns)
ginkgo.By("waiting for the container runtime to start")
gomega.Eventually(ctx, func(ctx context.Context) error {
r, _, err := getCRIClient()
if err != nil {
return fmt.Errorf("expected mirror pod (%s/%s) to be running but it was not: %v", ns, mirrorPodName, err)
return fmt.Errorf("error getting CRI client: %w", err)
}
status, err := r.Status(ctx, true)
if err != nil {
return fmt.Errorf("error checking CRI status: %w", err)
}
framework.Logf("Runtime started: %#v", status)
return nil
}, time.Second*30, time.Second*5).Should(gomega.Succeed())
}, 2*time.Minute, time.Second*5).Should(gomega.Succeed())
ginkgo.By(fmt.Sprintf("verifying that the mirror pod (%s/%s) stops running after about 30s", ns, mirrorPodName))
// from the time the container runtime starts, it should take a maximum of:
// 20s (grace period) + 2 sync transitions * 1s + 2s between housekeeping + 3s to detect CRI up +
// 2s overhead
// which we calculate here as "about 30s", so we try a bit longer than that but verify that it is
// tightly bounded by not waiting longer (we want to catch regressions to shutdown)
time.Sleep(30 * time.Second)
gomega.Eventually(ctx, func(ctx context.Context) error {
return checkMirrorPodDisappear(ctx, f.ClientSet, mirrorPodName, ns)
}, time.Second*3, time.Second).Should(gomega.Succeed())
ginkgo.By("verifying the pod finishes terminating and is removed from metrics")
gomega.Eventually(ctx, getKubeletMetrics, 15*time.Second, time.Second).Should(gstruct.MatchKeys(gstruct.IgnoreExtras, gstruct.Keys{
"kubelet_working_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_working_pods{config="desired", lifecycle="sync", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="sync", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="sync", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="sync", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="sync", static="unknown"}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminating", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminating", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminating", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminating", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="terminating", static="unknown"}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminated", static=""}`: timelessSample(0),
`kubelet_working_pods{config="desired", lifecycle="terminated", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminated", static=""}`: timelessSample(0),
`kubelet_working_pods{config="orphan", lifecycle="terminated", static="true"}`: timelessSample(0),
`kubelet_working_pods{config="runtime_only", lifecycle="terminated", static="unknown"}`: timelessSample(0),
}),
"kubelet_mirror_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_mirror_pods`: timelessSample(0),
}),
"kubelet_active_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_active_pods{static=""}`: timelessSample(0),
`kubelet_active_pods{static="true"}`: timelessSample(0),
}),
"kubelet_desired_pods": gstruct.MatchElements(sampleLabelID, 0, gstruct.Elements{
`kubelet_desired_pods{static=""}`: timelessSample(0),
`kubelet_desired_pods{static="true"}`: timelessSample(0),
}),
}))
})
ginkgo.AfterEach(func(ctx context.Context) {
@@ -246,3 +367,8 @@ func checkMirrorPodRunningWithUID(ctx context.Context, cl clientset.Interface, n
}
return nil
}
func sampleLabelID(element interface{}) string {
el := element.(*model.Sample)
return el.Metric.String()
}

View File

@@ -18,7 +18,6 @@ package e2enode
import (
"context"
goerrors "errors"
"fmt"
"os"
"path/filepath"
@@ -411,7 +410,10 @@ func checkMirrorPodDisappear(ctx context.Context, cl clientset.Interface, name,
if apierrors.IsNotFound(err) {
return nil
}
return goerrors.New("pod not disappear")
if err == nil {
return fmt.Errorf("mirror pod %v/%v still exists", namespace, name)
}
return fmt.Errorf("expect mirror pod %v/%v to not exist but got error: %w", namespace, name, err)
}
func checkMirrorPodRunning(ctx context.Context, cl clientset.Interface, name, namespace string) error {