Pass event created timestamp correctly to cache #124297

hshiina · 2024-04-12T18:20:04Z

What type of PR is this?

/kind bug

What this PR does / why we need it:

CreatedAt timestamp of ContainerEventResponse should be passed as nanoseconds to time.Unix().

This fix may mitigate #123087. I guess this issue happens as following:
Usually, a container created event is delivered while a pod worker is creating a pod at SyncPod() and the created status is cached by the PLEG. After SyncPod(), the pod worker waits at GetNewerThan() until a next event (container started) happens because the cached container status is older than lastSyncTime. However, due to the bug in this PR, the modified time of the cached status is so much newer because a nanoseconds value is set as seconds. Then, the pod worker gets a created container status from the cache and goes into SyncPod() soon. Then, the worker creates another container.

By fixing the timestamp, a pod worker is blocked at GetNewerThan() as expected. However, it is blocked much longer than the Generic PLEG in cases where the worker is woken up without a cache update by the PLEG such as a pod termination (issue #124704). In order to unblock the stuck worker as early as the Generic PLEG, this fix also makes the Evented PLEG update the global cache as frequently as the Generic PLEG.

Which issue(s) this PR fixes:

Fixes #124704

Special notes for your reviewer:

Does this PR introduce a user-facing change?

NONE

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

`CreatedAt` timestamp of `ContainerEventResponse` should be passed as nanoseconds to `time.Unix()`.

k8s-ci-robot · 2024-04-12T18:20:08Z

Please note that we're already in Test Freeze for the release-1.30 branch. This means every merged PR will be automatically fast-forwarded via the periodic ci-fast-forward job to the release branch of the upcoming v1.30.0 release.

Fast forwards are scheduled to happen every 6 hours, whereas the most recent run was: Fri Apr 12 13:49:11 UTC 2024.

k8s-ci-robot · 2024-04-12T18:20:12Z

Welcome @hshiina!

It looks like this is your first PR to kubernetes/kubernetes 🎉. Please refer to our pull request process documentation to help your PR have a smooth ride to approval.

You will be prompted by a bot to use commands during the review process. Do not be afraid to follow the prompts! It is okay to experiment. Here is the bot commands documentation.

You can also check if kubernetes/kubernetes has its own contribution guidelines.

You may want to refer to our testing guide if you run into trouble with your tests not passing.

If you are having difficulty getting your pull request seen, please follow the recommended escalation practices. Also, for tips and tricks in the contribution process you may want to read the Kubernetes contributor cheat sheet. We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to Kubernetes. 😃

k8s-ci-robot · 2024-04-12T18:20:13Z

Hi @hshiina. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

bart0sh · 2024-04-13T15:03:38Z

/triage accepted
/priority important-longterm
/ok-to-test
/cc

bart0sh · 2024-04-13T15:50:40Z

pkg/kubelet/pleg/evented.go

@@ -264,7 +264,7 @@ func (e *EventedPLEG) processCRIEvents(containerEventsResponseCh chan *runtimeap
 			}
 			shouldSendPLEGEvent = true
 		} else {
-			if e.cache.Set(podID, status, err, time.Unix(event.GetCreatedAt(), 0)) {
+			if e.cache.Set(podID, status, err, time.Unix(0, event.GetCreatedAt())) {


@hshiina great catch! Thank you!
/lgtm

bart0sh · 2024-04-13T15:51:33Z

/assign @mrunalp @derekwaynecarr @dchen1107
for approval

rphillips · 2024-05-07T18:54:19Z

/test pull-kubernetes-e2e-kind-evented-pleg
/test pull-kubernetes-e2e-kind-beta-features
/test pull-kubernetes-node-crio-cgrpv1-evented-pleg-e2e

rphillips · 2024-05-07T19:30:47Z

cc @harche

rphillips · 2024-05-07T19:40:02Z

failure looks unrelated... retesting

/test pull-kubernetes-node-crio-cgrpv1-evented-pleg-e2e

sairameshv · 2024-05-08T02:51:27Z

The failure seems to be expected as described in this bug

E2eNode Suite: [It] [sig-node] [NodeFeature:SidecarContainers] Containers Lifecycle should not hang in termination if terminated during initialization expand_less	14s
{ failed [FAILED] should delete in < 5 seconds, took 8.044552
Expected
    <float64>: 8.044551982
to be <
    <int64>: 5
In [It] at: k8s.io/kubernetes/test/e2e_node/container_lifecycle_test.go:2961 @ 05/07/24 20:11:30.288
}

There are some cases where a pod worker is woken up without a cache update by the PLEG such as a pod termination. Then, the worker gets stuck in `cache.GetNewerThan()` till the global cache timestamp is updated by the PLEG. In order to unblock the stuck worker as early as the Generic PLEG, this fix makes the Evented PLEG update the global cache as frequently as the Generic PLEG.

k8s-ci-robot · 2024-05-08T08:53:06Z

New changes are detected. LGTM label has been removed.

k8s-ci-robot · 2024-05-08T08:53:42Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: hshiina
Once this PR has been reviewed and has the lgtm label, please ask for approval from dchen1107. For more information see the Kubernetes Code Review Process.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

pkg/kubelet/OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

hshiina · 2024-05-08T08:54:58Z

/test pull-kubernetes-e2e-kind-evented-pleg
/test pull-kubernetes-e2e-kind-beta-features
/test pull-kubernetes-node-crio-cgrpv1-evented-pleg-e2e

harche · 2024-05-08T13:29:40Z

/cc @pacoxu

hshiina · 2024-05-13T15:02:37Z

A failure in pull-kubernetes-node-e2e-containerd seems to be caused because a regular container and a postStart hook start asynchronously.

{ failed [FAILED] couldn't find that PostStart-regular-1 ever started, got
0) 2024-05-08 09:07:01.942 +0000 UTC init-1 Starting
1) 2024-05-08 09:07:01.979 +0000 UTC init-1 Started
2) 2024-05-08 09:07:02.007 +0000 UTC init-1 Delaying
3) 2024-05-08 09:07:03.023 +0000 UTC init-1 Exiting
4) 2024-05-08 09:07:03.729 +0000 UTC PostStart-regular-1 Starting
5) 2024-05-08 09:07:03.735 +0000 UTC regular-1 Starting
6) 2024-05-08 09:07:03.754 +0000 UTC PostStart-regular-1 Started
7) 2024-05-08 09:07:03.755 +0000 UTC regular-1 Started
8) 2024-05-08 09:07:03.77 +0000 UTC regular-1 Delaying
9) 2024-05-08 09:07:03.771 +0000 UTC PostStart-regular-1 Delaying
10) 2024-05-08 09:07:04.789 +0000 UTC PostStart-regular-1 Exiting
11) 2024-05-08 09:07:13.862 +0000 UTC regular-1 Exiting
In [It] at: k8s.io/kubernetes/test/e2e_node/container_lifecycle_test.go:286 @ 05/08/24 09:07:17.158
}

Because of #124668, RunTogether() requires a regular container start before a postStart hook. It might be better to add StartDelay here:

kubernetes/test/e2e_node/container_lifecycle_test.go

Lines 255 to 259 in 8e5b26b

    
           Command: ExecCommand(prefixedName(PostStartPrefix, regular1), execCommand{ 
        
           	Delay:         1, 
        
           	ExitCode:      0, 
        
           	ContainerName: regular1, 
        
           }),

hshiina · 2024-05-14T10:02:57Z

A failure in pull-kubernetes-node-crio-cgrpv1-evented-pleg-e2e looks the same issue described in #124743.

Expected
    <int64>: 29479
to be within 1000 of ~
    <int>: 32000
In [It] at: k8s.io/kubernetes/test/e2e_node/container_lifecycle_test.go:2876 @ 05/08/24 09:19:49.794

hshiina · 2024-05-18T14:18:24Z

/test pull-kubernetes-node-e2e-containerd

hshiina · 2024-05-18T15:08:42Z

/test pull-kubernetes-e2e-kind-beta-features

hshiina · 2024-05-18T15:41:46Z

/test pull-kubernetes-e2e-kind-evented-pleg

hshiina · 2024-05-19T09:54:04Z

/test pull-kubernetes-e2e-kind-evented-pleg

k8s-ci-robot · 2024-05-19T10:24:36Z

@hshiina: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
pull-kubernetes-node-crio-cgrpv1-evented-pleg-e2e	`dbc4734`	link	false	`/test pull-kubernetes-node-crio-cgrpv1-evented-pleg-e2e`
pull-kubernetes-e2e-kind-evented-pleg	`dbc4734`	link	false	`/test pull-kubernetes-e2e-kind-evented-pleg`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. I understand the commands that are listed here.

hshiina · 2024-05-19T14:42:48Z

One of failures in pull-kubernetes-e2e-kind-evented-pleg looks the same issue as #123087:

{ failed [FAILED] 2 containers failed which is more than allowed 1
In [It] at: k8s.io/kubernetes/test/e2e/network/service.go:1270 @ 05/19/24 10:14:07.319
}

I guess the bind error in the log was caused because two containers were created.

  I0519 10:14:07.285073   66190 runners.go:195] Running kubectl logs on non-ready containers in services-1503
  I0519 10:14:07.318684 66190 kubectl_utils.go:128] Logs of services-1503/nodeport-test-xwqf5:nodeport-test on node kind-worker2
  I0519 10:14:07.318727 66190 kubectl_utils.go:129]  : STARTLOG
  I0519 10:14:03.496089   	1 log.go:245] Error from net.Listen(): listen tcp :9376: bind: address already in use

  ENDLOG for container services-1503:nodeport-test-xwqf5:nodeport-test
  I0519 10:14:07.318794 66190 service.go:1270] Unexpected error:
  	<*errors.errorString | 0xc00128ecf0>:
  	2 containers failed which is more than allowed 1
  	{
      	s: "2 containers failed which is more than allowed 1",
  	}
  [FAILED] in [It] - k8s.io/kubernetes/test/e2e/network/service.go:1270 @ 05/19/24 10:14:07.319

I don’t think it is enough to wait for the cache to be updated once at GetNewerThan() without confirming if it is updated as expected. After a pod worker starts a container in SyncPod(), if the pod worker enters syncPod() again before a container started event is delivered, the worker tries to create the container again. Because pod workers do not remember what they requested the container runtime to do, they compute actions in SyncPod() only by seeing cached container statuses. So, before entering SyncPod() again, cached statuses of all containers that were requested to start need to be updated by PLEG. However, just calling cache.GetNewerThan() once does not guarantee that all events are received by PLEG, especially in a case of Evented PLEG where events are delivered independently.

hshiina · 2024-05-19T19:01:00Z

I posted another PR (#124953) to try solving the remaining problem.

I think it's still worth merging this PR at first in order to improve the Evented PLEG even though there is still an unsolved problem.

pacoxu · 2024-05-20T03:23:08Z

/test pull-kubernetes-e2e-kind-alpha-beta-features
/test pull-kubernetes-e2e-kind-alpha-features

Pass event created timestamp correctly to cache

7612858

`CreatedAt` timestamp of `ContainerEventResponse` should be passed as nanoseconds to `time.Unix()`.

k8s-ci-robot added release-note-none Denotes a PR that doesn't merit a release note. kind/bug Categorizes issue or PR as related to a bug. size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Apr 12, 2024

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Apr 12, 2024

k8s-ci-robot added needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Apr 12, 2024

k8s-ci-robot added needs-priority Indicates a PR lacks a `priority/foo` label and requires one. area/kubelet sig/node Categorizes an issue or PR as relevant to SIG Node. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Apr 12, 2024

k8s-ci-robot requested review from dchen1107 and krmayankk April 12, 2024 18:20

bart0sh added this to Triage in SIG Node PR Triage Apr 12, 2024

k8s-ci-robot requested a review from bart0sh April 13, 2024 15:03

bart0sh moved this from Triage to Needs Reviewer in SIG Node PR Triage Apr 13, 2024

bart0sh reviewed Apr 13, 2024

View reviewed changes

k8s-ci-robot assigned bart0sh Apr 13, 2024

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Apr 13, 2024

k8s-ci-robot assigned dchen1107, derekwaynecarr and mrunalp Apr 13, 2024

hshiina mentioned this pull request May 6, 2024

Pod phase transition is slower when EventedPLEG is enabled #124704

Open

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label May 8, 2024

k8s-ci-robot requested review from bart0sh, derekwaynecarr and mrunalp May 8, 2024 08:53

k8s-ci-robot requested a review from pacoxu May 8, 2024 13:29

hshiina mentioned this pull request May 19, 2024

[WIP] Wait for PLEG events along with requests to runtime #124953

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Pass event created timestamp correctly to cache #124297

Pass event created timestamp correctly to cache #124297

hshiina commented Apr 12, 2024 •

edited

k8s-ci-robot commented Apr 12, 2024

k8s-ci-robot commented Apr 12, 2024

k8s-ci-robot commented Apr 12, 2024

bart0sh commented Apr 13, 2024

bart0sh Apr 13, 2024

bart0sh commented Apr 13, 2024

rphillips commented May 7, 2024

rphillips commented May 7, 2024

rphillips commented May 7, 2024

sairameshv commented May 8, 2024

k8s-ci-robot commented May 8, 2024

k8s-ci-robot commented May 8, 2024

hshiina commented May 8, 2024

harche commented May 8, 2024

hshiina commented May 13, 2024

hshiina commented May 14, 2024

hshiina commented May 18, 2024

hshiina commented May 18, 2024

hshiina commented May 18, 2024

hshiina commented May 19, 2024

k8s-ci-robot commented May 19, 2024

hshiina commented May 19, 2024

hshiina commented May 19, 2024

pacoxu commented May 20, 2024

Pass event created timestamp correctly to cache #124297

Are you sure you want to change the base?

Pass event created timestamp correctly to cache #124297

Conversation

hshiina commented Apr 12, 2024 • edited

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot commented Apr 12, 2024

k8s-ci-robot commented Apr 12, 2024

k8s-ci-robot commented Apr 12, 2024

bart0sh commented Apr 13, 2024

bart0sh Apr 13, 2024

Choose a reason for hiding this comment

bart0sh commented Apr 13, 2024

rphillips commented May 7, 2024

rphillips commented May 7, 2024

rphillips commented May 7, 2024

sairameshv commented May 8, 2024

k8s-ci-robot commented May 8, 2024

k8s-ci-robot commented May 8, 2024

hshiina commented May 8, 2024

harche commented May 8, 2024

hshiina commented May 13, 2024

hshiina commented May 14, 2024

hshiina commented May 18, 2024

hshiina commented May 18, 2024

hshiina commented May 18, 2024

hshiina commented May 19, 2024

k8s-ci-robot commented May 19, 2024

hshiina commented May 19, 2024

hshiina commented May 19, 2024

pacoxu commented May 20, 2024

hshiina commented Apr 12, 2024 •

edited