Closed yuyanj143 closed 1 year ago
Thanks for your report.
Yes, this does look somewhat similar to https://github.com/containers/image/issues/1083 , and the cause is unknown. With EOF
(and not unexpected EOF
) it seems like a code bug somewhere, whether or not there is some underlying infrastructure issue ultimately causing the transfer to fail.
If you can reproduce this on-demand, that’s valuable.
PATCH $url
entry corresponding to the Patch $url
error message fragment (curiously that’s missing in the above log). Is the time difference between the PATCH
log entry and the ultimate failure close to some suspiciously round number like 30/60/… seconds?vendor/github.com/containers/image/v5/docker/docker_client.go:makeRequestToResolvedURL makeRequestToResolvedURL
and on every return
path, add a log entry to record which return path was used, and with what error value. E.g. something like
func (c *dockerClient) makeRequestToResolvedURL(ctx context.Context, method string, url *url.URL, headers map[string][]string, stream io.Reader, streamLen int64, auth sendAuth, extraScope *authScope) (*http.Response, error) {
…
logrus.Errorf("makeRequestToResolvedURL RETURN 1: returning %#v, %#v; context %#v, %#v", res, err, stream, attempts)
return res, err
…
logrus.Errorf("makeRequestToResolvedURL RETURN 2: returning %#v, ctx.Err())
return nil, ctx.Err()
and the like. After that identifies where the code failed, that could either be enough to identify the cause directly, or it will identify a function that failed (in this case, it’s very likely (but not, strictly speaking, 100% certain) that it’s inside makeRequestToResolvedURL
, probably in net/http.Client.Do
)), and that one can be traced in a similar way. It’s likely that the standard library in /usr/local/go
will need (temporarily!) instrumenting the same way…
Thanks @mtrmac for your reply!
It does seem like the EOF is coming from client.Do
in makeRequestToResolvedURLOnce
DEBU[0001] ####################### in makeRequestToResolvedURLOnce Making PATCH request to https://my.private.repo/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D
DEBU[0001] ####################### in makeRequestToResolvedURLOnce before client.Do - method PATCH, stream &uploadreader.UploadReader{mutex:sync.Mutex{state:0, sema:0x0}, reader:(*io.teeReader)(0xc0002f0f40), terminationError:error(nil)} @ 2022-04-27 20:18:36.508113597 +0000 UTC m=+1.050623237
DEBU[0001] ###################################################################################################################
Copying blob 3a82b9fe4e3b skipped: already exists
Copying blob 5dfaa45a4854 skipped: already exists
Copying blob a757b484827e skipped: already exists
Copying blob 832fc2dcccb6 done
ERRO[0130] ####################### in makeRequestToResolvedURLOnce RETURN 3: err from client.Do - method PATCH, res (*http.Response)(nil), err &url.Error{Op:"Patch", URL:"https://my.private.repo/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D", Err:(*errors.errorString)(0xc000070060)}, stream &uploadreader.UploadReader{mutex:sync.Mutex{state:0, sema:0x0}, reader:(*io.teeReader)(0xc0002f0f40), terminationError:error(nil)} @ 2022-04-27 20:20:45.910428175 +0000 UTC m=+130.452937839
INFO[0130] ####################### in makeRequestToResolvedURL RETURN 1: res (*http.Response)(nil), err &url.Error{Op:"Patch", URL:"https://my.private.repo/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D", Err:(*errors.errorString)(0xc000070060)}, stream &uploadreader.UploadReader{mutex:sync.Mutex{state:0, sema:0x0}, reader:(*io.teeReader)(0xc0002f0f40), terminationError:error(nil)}, attempts 1
ERRO[0130] ####################### in docker_iamge_dest.go:PutBlob err from makeRequestToResolvedURL PATCH &url.Error{Op:"Patch", URL:"https://my.private.repo/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D", Err:(*errors.errorString)(0xc000070060)}
DEBU[0130] ####################### in copy.go:copyBlobFromStream RETURN err from PutBlob @ 2022-04-27 20:20:45.910538118 +0000 UTC m=+130.453047828
ERRO[0130] ####################### in copy.go:copyLayer err from copyLayerFromStream Error writing blob: Patch "https://my.private.repo/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D": EOF
FATA[0130] Error writing blob: Patch "https://my.private.repo/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D": EOF
Interestingly, the docker registry logs show that the HTTP PATCH request for the blob was successful but with http.response.written=0
:
time="2022-04-27T20:18:36.606746326Z" level=info msg="authorized request" go.version=go1.14.6 http.request.contenttype="application/octet-stream" http.request.host=my.private.repo http.request.id=db66ee85-d9b2-4cca-a5a6-89193d8fddbd http.request.method=PATCH http.request.remoteaddr="10.245.156.71:35770" http.request.uri="/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D" http.request.useragent="Go-http-client/1.1" vars.name="u/momo/test_images/jupyter_singleuser" vars.uuid=fe635bff-d3ca-49b4-893d-76fd48e5f460
time="2022-04-27T20:23:50.117097012Z" level=info msg="response completed" go.version=go1.14.6 http.request.contenttype="application/octet-stream" http.request.host=my.private.repo http.request.id=db66ee85-d9b2-4cca-a5a6-89193d8fddbd http.request.method=PATCH http.request.remoteaddr="10.245.156.71:35770" http.request.uri="/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D" http.request.useragent="Go-http-client/1.1" http.response.duration=5m13.511523807s http.response.status=202 http.response.written=0
10.245.156.71 - - [27/Apr/2022:20:18:36 +0000] "PATCH /v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=M2CY5Cx9zZdurLSYr8JNKu-otW3qyhTKg9OjxUJ8gJ97Ik5hbWUiOiJ1L3l1eWFuai90ZXN0X2ltYWdlcy9qdXB5dGVyX3NpbmdsZXVzZXIiLCJVVUlEIjoiZmU2MzViZmYtZDNjYS00OWI0LTg5M2QtNzZmZDQ4ZTVmNDYwIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDIyLTA0LTI3VDIwOjE4OjM2LjQzNDQxMjc4M1oifQ%3D%3D HTTP/1.1" 202 0 "" "Go-http-client/1.1"
I also tried to capture the packets, seeing the following logs:
...
20:19:45.412555 IP (tos 0x0, ttl 64, id 2022, offset 0, flags [DF], proto TCP (6), length 1400)
client > server: Flags [.], cksum 0x843e (incorrect -> 0x7d93), seq 1819353947:1819355295, ack 3513, win 502, options [nop,nop,TS val 117955162 ecr 2225082029], length 1348
20:19:45.412555 IP (tos 0x0, ttl 64, id 2023, offset 0, flags [DF], proto TCP (6), length 1400)
client > server: Flags [.], cksum 0x843e (incorrect -> 0x958b), seq 1819355295:1819356643, ack 3513, win 502, options [nop,nop,TS val 117955162 ecr 2225082029], length 1348
20:19:45.419938 IP (tos 0x0, ttl 255, id 53898, offset 0, flags [DF], proto TCP (6), length 52)
server > client: Flags [.], cksum 0x8d2d (correct), seq 3513, ack 1820283697, win 13788, options [nop,nop,TS val 2225082037 ecr 117955169], length 0
20:19:45.419956 IP (tos 0x0, ttl 255, id 53899, offset 0, flags [DF], proto TCP (6), length 52)
server > client: Flags [.], cksum 0x50b1 (correct), seq 3513, ack 1820299181, win 13788, options [nop,nop,TS val 2225082037 ecr 117955169], length 0
20:20:00.656080 IP (tos 0x0, ttl 64, id 2772, offset 0, flags [DF], proto TCP (6), length 52)
client > server: Flags [.], cksum 0x7efa (incorrect -> 0x4914), seq 1820299180, ack 3513, win 502, options [nop,nop,TS val 117970405 ecr 2225082037], length 0
20:20:00.656708 IP (tos 0x0, ttl 255, id 53900, offset 0, flags [DF], proto TCP (6), length 52)
server > client: Flags [.], cksum 0x152d (correct), seq 3513, ack 1820299181, win 13788, options [nop,nop,TS val 2225097273 ecr 117955169], length 0
20:20:15.760077 IP (tos 0x0, ttl 64, id 2773, offset 0, flags [DF], proto TCP (6), length 52)
client > server: Flags [.], cksum 0x7efa (incorrect -> 0xd28f), seq 1820299180, ack 3513, win 502, options [nop,nop,TS val 117985509 ecr 2225097273], length 0
20:20:15.760706 IP (tos 0x0, ttl 255, id 53901, offset 0, flags [DF], proto TCP (6), length 52)
server > client: Flags [.], cksum 0xda2c (correct), seq 3513, ack 1820299181, win 13788, options [nop,nop,TS val 2225112377 ecr 117955169], length 0
20:20:30.864078 IP (tos 0x0, ttl 64, id 2774, offset 0, flags [DF], proto TCP (6), length 52)
client > server: Flags [.], cksum 0x7efa (incorrect -> 0x5c8f), seq 1820299180, ack 3513, win 502, options [nop,nop,TS val 118000613 ecr 2225112377], length 0
20:20:30.864705 IP (tos 0x0, ttl 255, id 53902, offset 0, flags [DF], proto TCP (6), length 52)
server > client: Flags [.], cksum 0x9f2c (correct), seq 3513, ack 1820299181, win 13788, options [nop,nop,TS val 2225127481 ecr 117955169], length 0
20:20:45.910257 IP (tos 0x0, ttl 255, id 53903, offset 0, flags [DF], proto TCP (6), length 52)
server > client: Flags [F.], cksum 0x6465 (correct), seq 3513, ack 1820299181, win 13788, options [nop,nop,TS val 2225142527 ecr 117955169], length 0
20:20:45.910355 IP (tos 0x0, ttl 64, id 2775, offset 0, flags [DF], proto TCP (6), length 76)
client > server: Flags [P.], cksum 0x7f12 (incorrect -> 0x0e25), seq 1820299181:1820299205, ack 3514, win 502, options [nop,nop,TS val 118015660 ecr 2225142527], length 24
20:20:45.910376 IP (tos 0x0, ttl 64, id 2776, offset 0, flags [DF], proto TCP (6), length 52)
client > server: Flags [F.], cksum 0x7efa (incorrect -> 0xabe6), seq 1820299205, ack 3514, win 502, options [nop,nop,TS val 118015660 ecr 2225142527], length 0
20:20:45.910977 IP (tos 0x0, ttl 255, id 0, offset 0, flags [DF], proto TCP (6), length 40)
server > client: Flags [R], cksum 0xa8c7 (correct), seq 3427670409, win 0, length 0
20:20:45.911007 IP (tos 0x0, ttl 255, id 0, offset 0, flags [DF], proto TCP (6), length 40)
server > client: Flags [R], cksum 0xa8c7 (correct), seq 3427670409, win 0, length 0
The timeline looks like this:
20:18:36.508113597 client sends PATCH request
20:18:36.606746326 server receives request
20:19:45.419956 note in my terminal, it says Copying blob 832fc2dcccb6 done, but nothing happens it just hangs there
20:20:45.910257 server sends FIN,ACK
20:20:45.910376 client sends FIN,ACK
20:20:45.910428175 skopeo returns EOF error
20:20:45.911007 connection closed
20:23:50.117097012 server logs response completed
I'm not sure if these logs are helpful or how to read these as this is way out of my comfort zone :c, does it mean that the registry server decides to terminate the connection for whatever reason (perhaps due to a timeout/deadline setting somewhere?) and that caused EOF?
Thanks @mtrmac for your reply! It does seem like the EOF is coming from
client.Do
inmakeRequestToResolvedURLOnce
INFO[0130] ####################### in makeRequestToResolvedURL RETURN 1: res (*http.Response)(nil), err &url.Error{Op:"Patch", URL:"https://my.private.repo/v2/u/momo/test_images/jupyter_singleuser/blobs/uploads/fe635bff-d3ca-49b4-893d-76fd48e5f460?_state=…", Err:(*errors.errorString)(0xc000070060)}, stream &uploadreader.UploadReader{mutex:sync.Mutex{state:0, sema:0x0}, reader:(*io.teeReader)(0xc0002f0f40), terminationError:error(nil)}, attempts 1
OK, that seems to be consistent with the hypotheses so far.
ERRO[0130] ####################### in docker_iamge_dest.go:PutBlob err from makeRequestToResolvedURL Interestingly, the docker registry logs show that the HTTP PATCH request for the blob was successful but with
http.response.written=0
:
That is fine; the registry only needs to confirm that the upload succeeded, it is not expected to return any data. (https://github.com/distribution/distribution/blob/edf5aa3c399f3c7e9b7250676050e4691846bbaa/registry/handlers/blobupload.go#L352 ).
So if the server has successfully processed the upload (implying it was correctly and completely sent), there is really no data to read…
One avenue would be to just continue this kind of tracing inside the standard library (though, fair warning, the HTTP stack is fairly complex).
A friendly reminder that this issue had no activity for 30 days.
For the record, one possible path where the net/http
stack can return io.EOF
and not an “unexpected EOF” is if the server reads the request, and cleanly closes the connection without producing any response header. Reported as https://github.com/golang/go/issues/53472 .
A friendly reminder that this issue had no activity for 30 days.
@hanakawamomo is this still outstanding? At least https://github.com/tetrateio/tetrate-service-bridge-sandbox/pull/146 suggests that Skopeo is now being used.
Closing, assuming that this got resolved. Please reopen if that’s not the case.
Hi all, I'm trying to copy a fairly large image (10GB) from my local OCI-layout directory to my private docker registry hosted on s3 using:
skopeo --debug --insecure-policy copy --dest-creds=user.momo:pwd oci:/home/momo/oci:new docker://my-private-registry
but this is consistently failing with EOF errors:
Additional info: skopeo version: 1.3.0 docker-registry version: 2.7.1 cat /etc/*release
registry config:
I've tried the following and they work:
I suspect this is somewhat similar to issue 1083 but mine doesn't involve a slow/fast pipe as I'm copying from the local directory. I'm looking for some tips how to debug and if there's any workaround (I'm open to patch skopeo) for pushing large images with skopeo. Thanks!