feature: support image pull progress timeout #6150

fuweid · 2021-10-24T16:58:03Z

Kubelet sends the PullImage request without timeout, because the image size
is unknown and timeout is hard to defined. The pulling request might run
into 0B/s speed, if containerd can't receive any packet in that connection.
For this case, the containerd should cancel the PullImage request.

Although containerd provides ingester manager to track the progress of pulling
request, for example `ctr image pull` shows the console progress bar, it needs
more CPU resources to open/read the ingested files to get status.

In order to support progress timeout feature with lower overhead, this
patch uses http.RoundTripper wrapper to track active progress. That
wrapper will increase active-request number and return the
countingReadCloser wrapper for http.Response.Body. Each bytes-read
can be count and the active-request number will be descreased when the
countingReadCloser wrapper has been closed. For the progress tracker,
it can check the active-request number and bytes-read at intervals. If
there is no any progress, the progress tracker should cancel the
request.

NOTE: For each blob data, the containerd will make sure that the content
writer is opened before sending http request to the registry. Therefore, the
progress reporter can rely on the active-request number.

fixed: #4984

Signed-off-by: Wei Fu [email protected]

k8s-ci-robot · 2021-10-24T16:58:05Z

Skipping CI for Draft Pull Request.
If you want CI signal for your change, please convert it to an actual PR.
You can still manually trigger a test run with /test all

theopenlab-ci · 2021-10-24T17:44:00Z

Build succeeded.

containerd-build-arm64 : SUCCESS in 4m 58s (non-voting)
containerd-test-arm64 : SUCCESS in 6m 03s (non-voting)
containerd-integration-test-arm64 : FAILURE in 30m 46s (non-voting)

fuweid · 2021-10-25T00:25:11Z

/test all

theopenlab-ci · 2021-10-25T00:49:08Z

Build succeeded.

containerd-build-arm64 : SUCCESS in 4m 30s (non-voting)
containerd-test-arm64 : SUCCESS in 6m 11s (non-voting)
containerd-integration-test-arm64 : SUCCESS in 25m 17s (non-voting)

theopenlab-ci · 2021-10-25T18:31:49Z

Build succeeded.

containerd-build-arm64 : SUCCESS in 4m 26s (non-voting)
containerd-test-arm64 : SUCCESS in 5m 57s (non-voting)
containerd-integration-test-arm64 : SUCCESS in 26m 01s (non-voting)

dcantah · 2021-11-02T00:40:44Z

pkg/cri/config/config.go

 	NetNSMountsUnderStateDir bool `toml:"netns_mounts_under_state_dir" json:"netnsMountsUnderStateDir"`
+	// ImagePullProgressDeadline is the option that If no pulling progress
+	// is made before this deadline, the image pulling will be cancelled.
+	ImagePullProgressDeadline string `toml:"image_pull_progress_deadline" json:"imagePullProgressDeadline"`


Would be good to note that the format expected is the go duration format like the comment for StreamIdleTimeout calls out above. https://golang.org/pkg/time/#ParseDuration

nod let's use the description format from stream idle above if we stick to this being a timeout

updated with image_pull_progress_timeout and used description comment like stream_idle_timeout.

dcantah · 2021-11-02T00:43:50Z

pkg/cri/server/image_pull.go

+					WithField("lastSeenBytesRead", lastSeenBytesRead).
+					WithField("lastSeenTimestamp", lastSeenTimestamp).
+					WithField("reportInterval", reportInterval).
+					Tracef("the progress of pulling %v", reporter.ref)


Would it make sense for the ref to be on a WithField also instead (and the text to just change to "progress for image pull")?

qiutongs · 2021-11-02T17:55:26Z

pkg/cri/config/config_unix.go

 		ImageDecryption: ImageDecryption{
 			KeyModel: KeyModelNode,
 		},
+		ImagePullProgressDeadline: time.Minute.String(),


@ruiwen-zhao See if you have concern on the 1 minute default

I am concerning if this may break current customer...

yeah i am ok with this default. If there is no data transferred within 1 min, then most likely the image pull is gonna fail.

That said, I am with Qiutong and would like to stay on the safer side. Can we make the default to 2m, which is the default RuntimeRequestTimeout used by kubelet (code), so that this change will not change existing kubernetes behavior?

@ruiwen-zhao If my memory is correct, the code you mentioned is used to connect to server, not for pulling request. And the kubelet doesn't add timeout for pulling request. That is why kubelet use image_pull_progress_deadline(default=1m) for dockershim.

pkg/cri/server/image_pull.go

ruiwen-zhao · 2021-11-03T05:58:37Z

pkg/cri/config/config.go

 	}
+
+	// Validation for image_pull_progress_deadline
+	if c.ImagePullProgressDeadline != "" {


nit: Maybe the config name should be something like ImagePullProgressTimeout to align with the existing StreamIdleTimeout?

hmm is it a connection timeout or progress rate minimum

Yeah. I updated with ImagePullProgressTimeout. PTAL.

ruiwen-zhao · 2021-11-03T06:06:18Z

pkg/cri/config/config_unix.go

 		ImageDecryption: ImageDecryption{
 			KeyModel: KeyModelNode,
 		},
+		ImagePullProgressDeadline: time.Minute.String(),


yeah i am ok with this default. If there is no data transferred within 1 min, then most likely the image pull is gonna fail.

That said, I am with Qiutong and would like to stay on the safer side. Can we make the default to 2m, which is the default RuntimeRequestTimeout used by kubelet (code), so that this change will not change existing kubernetes behavior?

ruiwen-zhao · 2021-11-03T06:27:20Z

pkg/cri/server/image_pull.go

+// active pull requests once.
+func (r *countingReadCloser) Close() error {
+	err := r.rc.Close()
+	r.once.Do(r.reqReporter.decRequest)


for my own education: when would the responseCloser be closed multiple times?

Ideally, it will be closed only once. Just in case :) because the Close is allowed to call multiple times.

mikebrow

Interesting feature!

Maybe consider making this more about meeting an acceptable progress rate minimum over time than a any progress at all timeout value? Say n MB / d seconds ... first number KB/MB/GB second number ms/sec/min give them two values to set in one string.

mikebrow · 2021-11-04T01:33:01Z

pkg/cri/config/config.go

 	NetNSMountsUnderStateDir bool `toml:"netns_mounts_under_state_dir" json:"netnsMountsUnderStateDir"`
+	// ImagePullProgressDeadline is the option that If no pulling progress
+	// is made before this deadline, the image pulling will be cancelled.
+	ImagePullProgressDeadline string `toml:"image_pull_progress_deadline" json:"imagePullProgressDeadline"`


nod let's use the description format from stream idle above if we stick to this being a timeout

mikebrow · 2021-11-04T01:34:18Z

pkg/cri/config/config.go

 	}
+
+	// Validation for image_pull_progress_deadline
+	if c.ImagePullProgressDeadline != "" {


hmm is it a connection timeout or progress rate minimum

fuweid · 2021-11-18T16:10:15Z

Maybe consider making this more about meeting an acceptable progress rate minimum over time than a any progress at all timeout value? Say n MB / d seconds ... first number KB/MB/GB second number ms/sec/min give them two values to set in one string.

@mikebrow I was thinking to use content service's status to get the rate. But it consumes more CPU resources to get that status (open 5 file to get one ingest's status). And in this patch, I use http.RoundTripper wrapper to report the pulling status. It can work for timeout setting, not for rate here because sometimes the pulling request will wait for other requests to release content writer. If uses rate here, it will not accurate.

theopenlab-ci · 2021-11-18T16:27:52Z

Build succeeded.

containerd-build-arm64 : SUCCESS in 4m 24s (non-voting)
containerd-test-arm64 : SUCCESS in 5m 39s (non-voting)
containerd-integration-test-arm64 : FAILURE in 27m 31s (non-voting)

fuweid · 2021-11-21T03:07:10Z

=== Failed
=== FAIL: gc/scheduler TestTrigger (0.01s)
    scheduler_test.go:135: GC wait timed out

    container_stats_test.go:364: 
        	Error Trace:	container_stats_test.go:364
        	Error:      	Received unexpected error:
        	            	unexpected stats length
        	            	github.com/containerd/containerd/integration.TestContainerListStatsWithIdSandboxIdFilter.func4
        	            		/home/runner/work/containerd/containerd/integration/container_stats_test.go:371
        	            	github.com/containerd/containerd/integration.Eventually
        	            		/home/runner/work/containerd/containerd/integration/main_test.go:324
        	            	github.com/containerd/containerd/integration.TestContainerListStatsWithIdSandboxIdFilter
        	            		/home/runner/work/containerd/containerd/integration/container_stats_test.go:364
        	            	testing.tRunner
        	            		/opt/hostedtoolcache/go/1.17.3/x64/src/testing/testing.go:1259
        	            	runtime.goexit
        	            		/opt/hostedtoolcache/go/1.17.3/x64/src/runtime/asm_amd64.s:1581
        	Test:       	TestContainerListStatsWithIdSandboxIdFilter

It seems there are two flaky test cases.

``` // from containerd#6150 (comment) container_stats_test.go:364: Error Trace: container_stats_test.go:364 Error: Received unexpected error: unexpected stats length github.com/containerd/containerd/integration.TestContainerListStatsWithIdSandboxIdFilter.func4 /home/runner/work/containerd/containerd/integration/container_stats_test.go:371 github.com/containerd/containerd/integration.Eventually /home/runner/work/containerd/containerd/integration/main_test.go:324 github.com/containerd/containerd/integration.TestContainerListStatsWithIdSandboxIdFilter /home/runner/work/containerd/containerd/integration/container_stats_test.go:364 testing.tRunner /opt/hostedtoolcache/go/1.17.3/x64/src/testing/testing.go:1259 runtime.goexit /opt/hostedtoolcache/go/1.17.3/x64/src/runtime/asm_amd64.s:1581 Test: TestContainerListStatsWithIdSandboxIdFilter ``` Add stats result for the purpose of debug. Signed-off-by: Wei Fu <[email protected]>

theopenlab-ci · 2022-04-21T16:13:00Z

Build succeeded.

containerd-build-arm64 : SUCCESS in 4m 34s (non-voting)
containerd-test-arm64 : SUCCESS in 5m 33s (non-voting)
containerd-integration-test-arm64 : SUCCESS in 25m 01s (non-voting)

fuweid · 2022-04-22T14:56:42Z

ping @kzys

kzys · 2022-04-22T16:33:10Z

integration/build_local_containerd_helper_test.go

+		if err != nil {
+			return nil, fmt.Errorf("failed to get instance of service %q: %w", s, err)
+		}
+		if i == nil {
+			return nil, fmt.Errorf("instance of service %q not found", s)
+		}


Is there a case where i == nil but err == nil? I generally don't handle that case, assuming the function would return either of them, not both.

It depends on the Plugin init function. For now, I agree with you there is no such case.
However, the Registration type doesn't require that InitFn must return non-nil instance.
If the plugin is used to check something without creating new object, it can return nil.

And it is copied from pkg/cri/cri.go. If we require InitFn return non-nil instance, I can file the following pr to update it.

integration/image_pull_timeout_test.go

kzys · 2022-04-22T16:39:53Z

integration/image_pull_timeout_test.go

+	errCh := make(chan error)
+	go func() {
+		defer close(errCh)
+
+		_, err := criService.PullImage(ctx, &runtimeapi.PullImageRequest{
+			Image: &runtimeapi.ImageSpec{
+				Image: pullProgressTestImageName,
+			},
+		})
+		errCh <- err
+	}()


How about using errgroup instead?

I need to use select statement with timeout and release the content lock.
If uses errgroup, it looks complicated.

kzys · 2022-04-22T16:40:20Z

integration/image_pull_timeout_test.go

+	select {
+	case <-time.After(defaultImagePullProgressTimeout * 5):
+		// release the lock
+		cleanupWriters()


Wouldn't it be covered by defer above?

Yes. But I need to release the content lock manually and then the PullImage goroutine can continue to pull and return nil-error.

integration/image_pull_timeout_test.go

pkg/cri/config/config.go

kzys · 2022-04-22T16:44:19Z

pkg/cri/config/config_unix.go

-		CDISpecDirs: []string{"/etc/cdi", "/var/run/cdi"},
+		EnableCDI:                false,
+		CDISpecDirs:              []string{"/etc/cdi", "/var/run/cdi"},
+		ImagePullProgressTimeout: time.Minute.String(),


Do you want to change the default behavior here?

It is aligned with kubelet default config. 😂
I think we can set this feature as default behavior, since it is improvement~

pkg/cri/server/image_pull.go

Kubelet sends the PullImage request without timeout, because the image size is unknown and timeout is hard to defined. The pulling request might run into 0B/s speed, if containerd can't receive any packet in that connection. For this case, the containerd should cancel the PullImage request. Although containerd provides ingester manager to track the progress of pulling request, for example `ctr image pull` shows the console progress bar, it needs more CPU resources to open/read the ingested files to get status. In order to support progress timeout feature with lower overhead, this patch uses http.RoundTripper wrapper to track active progress. That wrapper will increase active-request number and return the countingReadCloser wrapper for http.Response.Body. Each bytes-read can be count and the active-request number will be descreased when the countingReadCloser wrapper has been closed. For the progress tracker, it can check the active-request number and bytes-read at intervals. If there is no any progress, the progress tracker should cancel the request. NOTE: For each blob data, the containerd will make sure that the content writer is opened before sending http request to the registry. Therefore, the progress reporter can rely on the active-request number. fixed: containerd#4984 Signed-off-by: Wei Fu <[email protected]>

theopenlab-ci · 2022-04-26T18:12:27Z

Build succeeded.

containerd-build-arm64 : SUCCESS in 4m 15s (non-voting)
containerd-test-arm64 : SUCCESS in 5m 37s (non-voting)
containerd-integration-test-arm64 : SUCCESS in 24m 42s (non-voting)

dmcgowan

LGTM

I still think we can refactor the progress stuff out of CRI but we can think about that interface a little more

fuweid · 2022-05-03T01:34:01Z

I still think we can refactor the progress stuff out of CRI but we can think about that interface a little more

Agree. I will open issue to track this.

fuweid force-pushed the support-4984 branch from 20bc71a to d92e9bc Compare October 24, 2021 17:11

fuweid force-pushed the support-4984 branch from d92e9bc to 82adeeb Compare October 25, 2021 00:22

fuweid force-pushed the support-4984 branch from 82adeeb to 80de326 Compare October 25, 2021 17:48

fuweid changed the title ~~[WIP] feature: Support image pull progress deadline~~ feature: Support image pull progress deadline Oct 25, 2021

fuweid marked this pull request as ready for review October 25, 2021 17:48

fuweid force-pushed the support-4984 branch 3 times, most recently from 07ba1ca to 63860e9 Compare October 25, 2021 18:04

fuweid requested review from dmcgowan and mikebrow October 25, 2021 18:04

dcantah reviewed Nov 2, 2021

View reviewed changes

qiutongs reviewed Nov 2, 2021

View reviewed changes

ruiwen-zhao reviewed Nov 3, 2021

View reviewed changes

mikebrow reviewed Nov 4, 2021

View reviewed changes

fuweid added this to the 1.6 milestone Nov 17, 2021

fuweid changed the title ~~feature: Support image pull progress deadline~~ [WIP] feature: Support image pull progress deadline Nov 17, 2021

fuweid force-pushed the support-4984 branch from 63860e9 to 45e8e3b Compare November 18, 2021 15:53

fuweid changed the title ~~[WIP] feature: Support image pull progress deadline~~ feature: Support image pull progress timeout Nov 18, 2021

fuweid force-pushed the support-4984 branch from 45e8e3b to 5169e5d Compare November 18, 2021 15:57

fuweid force-pushed the support-4984 branch from 5169e5d to 73b9bde Compare November 21, 2021 03:10

fuweid force-pushed the support-4984 branch from 7258cc8 to b3cae40 Compare April 21, 2022 15:45

kzys requested changes Apr 22, 2022

View reviewed changes

fuweid force-pushed the support-4984 branch from b3cae40 to 2d1a701 Compare April 26, 2022 15:54

fuweid force-pushed the support-4984 branch from 2d1a701 to 00d102d Compare April 26, 2022 16:02

kzys approved these changes Apr 26, 2022

View reviewed changes

dmcgowan approved these changes Apr 26, 2022

View reviewed changes

dmcgowan merged commit 6e0231f into containerd:main Apr 26, 2022

fuweid deleted the support-4984 branch April 27, 2022 01:34

fuweid mentioned this pull request Jun 24, 2022

No information in the logs on the dowload progress while pulling images #4211

Closed

pacoxu mentioned this pull request Aug 3, 2022

image pulling related metrics: time & thoughout by registry #7241

Closed

ruiwen-zhao mentioned this pull request Oct 7, 2022

KEP-3542: СRI image pulling with progress notification kubernetes/enhancements#3547

Closed

pacoxu mentioned this pull request Oct 12, 2022

promoting use of parallel image pulls kubernetes/kubernetes#108405

Open

7 tasks

dmcgowan mentioned this pull request Dec 10, 2022

Prepare release notes for v1.7.0-beta.1 #7793

Merged

cardyok mentioned this pull request Dec 21, 2022

add timeout to httpReadSeeker #7822

Closed

dmcgowan mentioned this pull request Jan 3, 2023

Prepare release notes for v1.7.0-beta.2 #7903

Merged

dmcgowan mentioned this pull request Jan 28, 2023

Prepare release notes for v1.7.0-beta.3 #8014

Merged

dmcgowan mentioned this pull request Feb 15, 2023

Prepare release notes for v1.7.0 beta.4 #8110

Merged

This was referenced Feb 25, 2023

Prepare release notes for v1.7.0-rc.0 #8162

Merged

Prepare release notes for v1.7.0-rc.1 #8192

Merged

This was referenced Mar 7, 2023

Add release notes for v1.7.0-rc.2 #8216

Merged

Prepare release notes for v1.7.0-rc.3 #8233

Merged

Prepare release notes for v1.7.0 #8242

Merged

fiunchinho mentioned this pull request Apr 18, 2023

CAPA Kubernetes v1.24 giantswarm/roadmap#2237

Closed

andyzhangx mentioned this pull request Nov 8, 2023

fix: increase ImagePullProgressTimeout as 10min #9347

Closed

saschagrunert mentioned this pull request Mar 14, 2024

Support image pull progress timeout cri-o/cri-o#7885

Closed

feature: support image pull progress timeout #6150

feature: support image pull progress timeout #6150

Uh oh!

Conversation

fuweid commented Oct 24, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

k8s-ci-robot commented Oct 24, 2021

Uh oh!

theopenlab-ci bot commented Oct 24, 2021

Uh oh!

fuweid commented Oct 25, 2021

Uh oh!

theopenlab-ci bot commented Oct 25, 2021

Uh oh!

theopenlab-ci bot commented Oct 25, 2021

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mikebrow left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

fuweid commented Nov 18, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

theopenlab-ci bot commented Nov 18, 2021

Uh oh!

fuweid commented Nov 21, 2021

Uh oh!

theopenlab-ci bot commented Apr 21, 2022

Uh oh!

fuweid commented Apr 22, 2022

Uh oh!

Choose a reason for hiding this comment

Uh oh!

This comment was marked as duplicate.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

fuweid commented Oct 24, 2021 •

edited

Loading

fuweid commented Nov 18, 2021 •

edited

Loading