[draft] how to reproduce a race condition issue between kubelet and docker #40
Comments
|
This is also reproducible with a newer docker version, too. [docker 20.10.23 + k8s 1.21.14 + dockershim] $ docker version
Client:
Version: 20.10.23
API version: 1.41
Go version: go1.18.10
Git commit: 7155243
Built: Thu Jan 19 17:30:35 2023
OS/Arch: linux/amd64
Context: default
Experimental: true
Server: Docker Engine - Community
Engine:
Version: 20.10.23
API version: 1.41 (minimum version 1.12)
Go version: go1.18.10
Git commit: 6051f14
Built: Thu Jan 19 17:36:08 2023
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: v1.7.0
GitCommit: 1fbd70374134b891f97ce19c70b6e50c7b9f4e0d
runc:
Version: 1.1.5
GitCommit: f19387a6bec4944c770f7668ab51c4348d9c2f38
docker-init:
Version: 0.19.0
GitCommit: de40ad0(without minikube iso change) |
|
This seems to be not reproducible with [docker 19.03.11 + k8s 1.26.3 + cri-dockerd] (as of yet) $ docker version
Client: Docker Engine - Community
Version: 19.03.11
API version: 1.40
Go version: go1.13.10
Git commit: 42e35e61f3
Built: Mon Jun 1 09:09:53 2020
OS/Arch: linux/amd64
Experimental: false
Server: Docker Engine - Community
Engine:
Version: 19.03.11
API version: 1.40 (minimum version 1.12)
Go version: go1.13.10
Git commit: 42e35e61f3
Built: Mon Jun 1 09:16:24 2020
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: v1.2.13
GitCommit: 7ad184331fa3e55e52b890ea95e65ba581ae3429
runc:
Version: 1.1.5
GitCommit: f19387a6bec4944c770f7668ab51c4348d9c2f38
docker-init:
Version: 0.18.0
GitCommit: fec3683
$ kubectl version
Server Version: version.Info{Major:"1", Minor:"26", GitVersion:"v1.26.3", GitCommit:"9e644106593f3f4aa98f8a84b23db5fa378900bd", GitTreeState:"clean", BuildDate:"2023-03-15T13:33:12Z", GoVersion:"go1.19.7", Compiler:"gc", Platform:"linux/amd64"} |
|
Also reproducible with [docker 19.03.11 + k8s 1.21.14 + cri-dockerd] |
|
Non-reproducible with [docker 19.03.11 + k8s 1.22.17 + dockershim] |
|
Non-reproducible with [docker 19.03.11 + k8s 1.20.15 + dockershim] |
|
With a diff like below: diff --git a/pkg/kubelet/kuberuntime/kuberuntime_manager.go b/pkg/kubelet/kuberuntime/kuberuntime_manager.go
index d83e75e300a..f5ef1aebf25 100644
--- a/pkg/kubelet/kuberuntime/kuberuntime_manager.go
+++ b/pkg/kubelet/kuberuntime/kuberuntime_manager.go
@@ -606,11 +606,21 @@ func (m *kubeGenericRuntimeManager) computePodActions(pod *v1.Pod, podStatus *ku
return changes
}
+ for _, cs := range podStatus.ContainerStatuses {
+ klog.InfoS("computePodActions", "podUID", pod.UID, "containerName", cs.Name, "state", cs.State, "id", cs.ID.ID)
+ }
+
// Number of running containers to keep.
keepCount := 0
// check the status of containers.
for idx, container := range pod.Spec.Containers {
containerStatus := podStatus.FindContainerStatusByName(container.Name)
+ if containerStatus != nil {
+ klog.InfoS("Container status", "containerName", container.Name, "pod", klog.KObj(pod),
+ "containerID", containerStatus.ID.ID, "state", containerStatus.State, "total", len(podStatus.ContainerStatuses))
+ } else {
+ klog.InfoS("Container status is nil", "containerName", container.Name, "pod", klog.KObj(pod), "total", len(podStatus.ContainerStatuses))
+ }
// Call internal container post-stop lifecycle hook for any non-running container so that any
// allocated cpus are released immediately. If the container is restarted, cpus will be re-allocated
@@ -1019,6 +1029,9 @@ func (m *kubeGenericRuntimeManager) GetPodStatus(uid kubetypes.UID, name, namesp
}
return nil, err
}
+ for _, cs := range containerStatuses {
+ klog.InfoS("GetPodStatus", "podUID", uid, "containerName", cs.Name, "state", cs.State, "id", cs.ID.ID)
+ }
m.logReduction.ClearID(podFullName)
return &kubecontainer.PodStatus{
diff --git a/pkg/kubelet/pleg/generic.go b/pkg/kubelet/pleg/generic.go
index 3b9ba505e7b..3f1712be056 100644
--- a/pkg/kubelet/pleg/generic.go
+++ b/pkg/kubelet/pleg/generic.go
@@ -386,7 +386,7 @@ func (g *GenericPLEG) updateCache(pod *kubecontainer.Pod, pid types.UID) error {
if klog.V(6).Enabled() {
klog.V(6).ErrorS(err, "PLEG: Write status", "pod", klog.KRef(pod.Namespace, pod.Name), "podStatus", status)
} else {
- klog.V(4).ErrorS(err, "PLEG: Write status", "pod", klog.KRef(pod.Namespace, pod.Name))
+ klog.ErrorS(err, "PLEG: Write status", "pod", klog.KRef(pod.Namespace, pod.Name), "timestamp", timestamp.String())
}
if err == nil {
// Preserve the pod IP across cache updates if the new IP is empty.
diff --git a/pkg/kubelet/pod_workers.go b/pkg/kubelet/pod_workers.go
index fcf059f56e3..982f4a4d69a 100644
--- a/pkg/kubelet/pod_workers.go
+++ b/pkg/kubelet/pod_workers.go
@@ -22,7 +22,7 @@ import (
"sync"
"time"
- "k8s.io/api/core/v1"
+ v1 "k8s.io/api/core/v1"
"k8s.io/apimachinery/pkg/types"
"k8s.io/apimachinery/pkg/util/runtime"
"k8s.io/apimachinery/pkg/util/sets"
@@ -171,6 +171,7 @@ func (p *podWorkers) managePodLoop(podUpdates <-chan UpdatePodOptions) {
p.recorder.Eventf(update.Pod, v1.EventTypeWarning, events.FailedSync, "error determining status: %v", err)
return err
}
+ klog.InfoS("managePodLoop", "podUID", podUID, "lastSyncTime", lastSyncTime.String(), "containers", len(status.ContainerStatuses))
err = p.syncPodFn(syncPodOptions{
mirrorPod: update.MirrorPod,
pod: update.Pod,In and in and the overall timeline: We do see Somewhere, |
|
This seems to be the solution: diff --git a/pkg/kubelet/kubelet_pods.go b/pkg/kubelet/kubelet_pods.go
index b610b47ff7f..5aabf594500 100644
--- a/pkg/kubelet/kubelet_pods.go
+++ b/pkg/kubelet/kubelet_pods.go
@@ -1819,7 +1819,7 @@ func (kl *Kubelet) convertToAPIContainerStatuses(pod *v1.Pod, podStatus *kubecon
}
// Make the latest container status comes first.
- sort.Sort(sort.Reverse(kubecontainer.SortContainerStatusesByCreationTime(podStatus.ContainerStatuses)))
+ // sort.Sort(sort.Reverse(kubecontainer.SortContainerStatusesByCreationTime(podStatus.ContainerStatuses)))
// Set container statuses according to the statuses seen in pod status
containerSeen := map[string]int{}
for _, cStatus := range podStatus.ContainerStatuses { |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
This is just a draft, and thus is not meant to be organized at all. (A better version will be shared later).
minikube
We need to build a specialized minikube iso image with the following diff on top of minikube HEAD (at the time of writing).
Then run the following commands to build the iso image:
If the commands above run successfully, we should see a new iso image built:
Once we have it, we can launch a k8s cluster with the following command:
$ minikube start --driver=virtualbox --cpus=4 --memory=8g --iso-url=file://$(pwd)/out/minikube-amd64.iso --kubernetes-version=v1.21.14apply the following pod specs
I have crafted an example app here - https://github.com/zhouhaibing089/goapp. It is a simple goapp listening on the provided port and when requested, it echos something like
"Hello from port 1234".Note that I injected a 10% failure rate to simulate container restart case.
see the issues happening
If you are not super unlucky (which means easy to reproduce), you should see something like:
One or few of them simply can't start. For example, if we look at the goapp-19 above:
And if we try to get the log for container
p1263:This is pretty interesting, how could it happen? If we log in to the host, and run a
docker ps:It appears that there is already a container running for
goapp-19/p1263. So why did kubelet try to create another container?add logs to kubelet
We can apply the following diff on top of kubelet (from v1.21.14) to inspect container status during each pod sync loop:
And then compile a new version as well as copy it into minikube:
With the new binary, we can restart kubelet inside minikube with:
see logs in action
Now trying to reproduce it again (see above).
And same as the previous observation, we can there is already a container running:
logs that we have added
Here are the logs that we added earlier:
In this loop, from container
p1234top1263, onlyp1251has a nil container status:Now if take a closer look at the running container for
p1251(see above):It was created at
"2023-04-29T23:29:50.726134045Z"and started at"2023-04-29T23:29:51.432835852Z", yet in the coming loop, docker didn't report its status at all.The text was updated successfully, but these errors were encountered: