Status manager does not normalize ephemeral container statuses

[hshiina]

What happened?

EphemeralContainerStatuses is not normalized in normalizeStatus() in the status manager: https://github.com/kubernetes/kubernetes/blob/cade1dddd81eba338df85de7b5d17324a87243b5/pkg/kubelet/status/status_manager.go#L1026-L1043

This does not seem to cause any user facing problem because EphemeralContainerStatuses is sorted before passed to the status manager and timestamps are normalized at marshaling to create a patch: https://github.com/kubernetes/kubernetes/blob/cade1dddd81eba338df85de7b5d17324a87243b5/pkg/kubelet/kubelet_pods.go#L2336

https://github.com/kubernetes/kubernetes/blob/cade1dddd81eba338df85de7b5d17324a87243b5/pkg/kubelet/status/status_manager.go#L873

However, an unexpected behavior is caused internally because timestamps are not normalized. If the log verbosity is 3 or larger, the following messages are logged periodically in kubelet when an ephemeral container exists:

May 14 20:10:33 kind-control-plane kubelet[720]: I0514 20:10:33.437155  720 status_manager.go:230] "Syncing all statuses"
May 14 20:10:33 kind-control-plane kubelet[720]: I0514 20:10:33.438512  720 status_manager.go:984] "Pod status is inconsistent with cached status for pod, a reconciliation should be triggered" pod="default/ephemeral-demo" statusDiff=<
May 14 20:10:33 kind-control-plane kubelet[720]:          &v1.PodStatus{
May 14 20:10:33 kind-control-plane kubelet[720]:                ... // 8 identical fields
May 14 20:10:33 kind-control-plane kubelet[720]:                PodIPs:             {{IP: "10.244.0.5"}},
May 14 20:10:33 kind-control-plane kubelet[720]:                StartTime:          s"2024-05-14 20:09:21 +0000 UTC",
May 14 20:10:33 kind-control-plane kubelet[720]:        -       InitContainerStatuses: nil,
May 14 20:10:33 kind-control-plane kubelet[720]:        +       InitContainerStatuses: []v1.ContainerStatus{},
May 14 20:10:33 kind-control-plane kubelet[720]:                ContainerStatuses:  {{Name: "ephemeral-demo", State: {Running: &{StartedAt: {Time: s"2024-05-14 20:09:23 +0000 UTC"}}}, Ready: true, Image: "registry.k8s.io/pause:3.1", ...}},
May 14 20:10:33 kind-control-plane kubelet[720]:                QOSClass:           "BestEffort",
May 14 20:10:33 kind-control-plane kubelet[720]:                EphemeralContainerStatuses: []v1.ContainerStatus{
May 14 20:10:33 kind-control-plane kubelet[720]:                        {
May 14 20:10:33 kind-control-plane kubelet[720]:                                Name: "debugger-qk87g",
May 14 20:10:33 kind-control-plane kubelet[720]:                                State: v1.ContainerState{
May 14 20:10:33 kind-control-plane kubelet[720]:                                        Waiting:    nil,
May 14 20:10:33 kind-control-plane kubelet[720]:        -                               Running:    &v1.ContainerStateRunning{StartedAt: v1.Time{Time: s"2024-05-14 20:09:35 +0000 UTC"}},
May 14 20:10:33 kind-control-plane kubelet[720]:        +                               Running:    &v1.ContainerStateRunning{StartedAt: v1.Time{Time: s"2024-05-14 20:09:35.697513091 +0000 UTC"}},
May 14 20:10:33 kind-control-plane kubelet[720]:                                        Terminated: nil,
May 14 20:10:33 kind-control-plane kubelet[720]:                                },
May 14 20:10:33 kind-control-plane kubelet[720]:                                LastTerminationState: {},
May 14 20:10:33 kind-control-plane kubelet[720]:                                Ready:              false,
May 14 20:10:33 kind-control-plane kubelet[720]:                                ... // 7 identical fields
May 14 20:10:33 kind-control-plane kubelet[720]:                        },
May 14 20:10:33 kind-control-plane kubelet[720]:                },
May 14 20:10:33 kind-control-plane kubelet[720]:                Resize:             "",
May 14 20:10:33 kind-control-plane kubelet[720]:                ResourceClaimStatuses: nil,
May 14 20:10:33 kind-control-plane kubelet[720]:          }
May 14 20:10:33 kind-control-plane kubelet[720]:  >

This message is emitted here: https://github.com/kubernetes/kubernetes/blob/cade1dddd81eba338df85de7b5d17324a87243b5/pkg/kubelet/status/status_manager.go#L984-L988

After needsReconcile() returns true, syncPod() is called. This does not look so harmful because unchaged gets true eventually:

https://github.com/kubernetes/kubernetes/blob/cade1dddd81eba338df85de7b5d17324a87243b5/pkg/kubelet/status/status_manager.go#L873-L881

API is called once unnecessarily in syncPod(), though: https://github.com/kubernetes/kubernetes/blob/cade1dddd81eba338df85de7b5d17324a87243b5/pkg/kubelet/status/status_manager.go#L843

What did you expect to happen?

It might be better to normalize ephemeral container statuses, at least timestamps, in the status manager to avoid this unexpected behavior.

How can we reproduce it (as minimally and precisely as possible)?

Set the log verbosity of kubelet to 3 or larger. Then, create an ephemeral container like this.

Anything else we need to know?

No response

Kubernetes version

```console $ kubectl version # paste output here Client Version: v1.29.4 Kustomize Version: v5.0.4-0.20230601165947-6ce0bf390ce3 Server Version: v1.29.2 ```

Cloud provider

None

OS version

```console # On Linux: $ cat /etc/os-release # paste output here $ uname -a # paste output here # On Windows: C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture # paste output here ```

Install tools

Container runtime (CRI) and version (if applicable)

Related plugins (CNI, CSI, ...) and versions (if applicable)

[hshiina]

/sig node

[zhifei92]

@hshiina This is a bug. Can you submit a PR to fix it? If not, I'd be happy to work on it

[hshiina]

@zhifei92 If you are interested, please feel free to assign yourself.

[zhifei92]

@zhifei92 If you are interested, please feel free to assign yourself.

thx

[zhifei92]

/assign

[ffromani]

/triage accepted /priority important-longterm