ContentLength mismatch in blob upload

[deitch]

I am having an intermittent issue with ContentLength mismatch. It may be registry-side related, I cannot reproduce it reliably, but if I call a lot of pushes, it does show up with some regularity.

I ran with debug logging enabled, here is what I got, when pushing an image from linuxkit, filtered some of the irrelevant data out:

INFO[0555] index.docker.io/linuxkit/containerd@sha256:5dd3ad98ff8da74de6ceb9c609bb0b7302f4b305663507c38efc56b243b34c6f: digest: sha256:5dd3ad98ff8da74de6ceb9c609bb0b7302f4b305663507c38efc56b243b34c6f size: 1311
DEBU[0555] --> PUT https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866
DEBU[0555] PUT /v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866 HTTP/1.1
DEBU[0555] Host: index.docker.io
DEBU[0555] User-Agent: go-containerregistry/v0.4.1-0.20210208222243-cbafe638a7a9
DEBU[0555] Content-Length: 1821
DEBU[0555] Authorization: <redacted>
DEBU[0555] Content-Type: application/vnd.oci.image.index.v1+json
DEBU[0555] Accept-Encoding: gzip
DEBU[0555]
DEBU[0555] ... lots of json  ...
DEBU[0555] <-- 401 https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866 (156.197508ms)
DEBU[0555] HTTP/1.1 401 Unauthorized
DEBU[0555] Connection: close
DEBU[0555] Content-Length: 240
DEBU[0555] Content-Type: application/json
DEBU[0555] Date: Wed, 28 Apr 2021 09:15:23 GMT
DEBU[0555] Docker-Distribution-Api-Version: registry/2.0
DEBU[0555] Www-Authenticate: Bearer realm="https://auth.docker.io/token",service="registry.docker.io",scope="repository:linuxkit/containerd:pull,push",error="invalid_token"
DEBU[0555]
DEBU[0555] {"errors":[{"code":"UNAUTHORIZED","message":"authentication required","detail":[{"Type":"repository","Class":"","Name":"linuxkit/containerd","Action":"pull"},{"Type":"repository","Class":"","Name":"linuxkit/containerd","Action":"push"}]}]}
DEBU[0555]
DEBU[0555] --> GET https://auth.docker.io/token?scope=repository%3Alinuxkit%2Fcontainerd%3Apush%2Cpull&scope=repository%3Alinuxkit%2Fcontainerd%3Apull%2Cpush&service=registry.docker.io [body redacted: basic token response contains credentials]
DEBU[0555] GET /token?scope=repository%3Alinuxkit%2Fcontainerd%3Apush%2Cpull&scope=repository%3Alinuxkit%2Fcontainerd%3Apull%2Cpush&service=registry.docker.io HTTP/1.1
DEBU[0555] Host: auth.docker.io
DEBU[0555] User-Agent: go-containerregistry/v0.4.1-0.20210208222243-cbafe638a7a9
DEBU[0555] Authorization: <redacted>
DEBU[0555] Accept-Encoding: gzip
DEBU[0555]
DEBU[0555]
DEBU[0556] <-- 200 https://auth.docker.io/token?scope=repository%3Alinuxkit%2Fcontainerd%3Apush%2Cpull&scope=repository%3Alinuxkit%2Fcontainerd%3Apull%2Cpush&service=registry.docker.io (695.513841ms) [body redacted: basic token response contains credentials]
DEBU[0556] HTTP/1.1 200 OK
DEBU[0556] Transfer-Encoding: chunked
DEBU[0556] Content-Type: application/json
DEBU[0556] Date: Wed, 28 Apr 2021 09:15:24 GMT
DEBU[0556] Strict-Transport-Security: max-age=31536000
DEBU[0556]
DEBU[0556]
DEBU[0556] --> PUT https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866
DEBU[0556] Failed to dump request PUT https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866: http: ContentLength=1821 with Body length 0
DEBU[0556] <-- http: ContentLength=1821 with Body length 0 PUT https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866 (553.890807ms)
Put "https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866": http: ContentLength=1821 with Body length 0

It tries to put a manifest, gets a 401, goes to authorize, goes back with it, and gets an error. It doesn't look like it is an http error, but I cannot tell from the logs.

Interestingly, that error line looks like it comes from here, but based on that code, it should not error out. Yet in this case it definitely does with a non-zero exit code (which I wish I had thought to capture).

When I reran, it went just fine:

DEBU[0023] --> PUT https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866
DEBU[0023] PUT /v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866 HTTP/1.1
DEBU[0023] Host: index.docker.io
DEBU[0023] User-Agent: go-containerregistry/v0.4.1-0.20210208222243-cbafe638a7a9
DEBU[0023] Content-Length: 1821
DEBU[0023] Authorization: <redacted>
DEBU[0023] Content-Type: application/vnd.oci.image.index.v1+json
DEBU[0023] Accept-Encoding: gzip
DEBU[0023]
DEBU[0023] ... lots of json content ...
DEBU[0023] <-- 201 https://index.docker.io/v2/linuxkit/containerd/manifests/cc02c2af9c928c2faeccbe4edc78bd297ad91866 (316.634923ms)
DEBU[0023] HTTP/1.1 201 Created
DEBU[0023] Content-Length: 0
DEBU[0023] Date: Wed, 28 Apr 2021 09:29:33 GMT
DEBU[0023] Docker-Content-Digest: sha256:ebd295492eff4e096bfeaa4f09cc4013c629a72c41056afee26a49419b47a75d
DEBU[0023] Docker-Distribution-Api-Version: registry/2.0
DEBU[0023] Location: https://index.docker.io/v2/linuxkit/containerd/manifests/sha256:ebd295492eff4e096bfeaa4f09cc4013c629a72c41056afee26a49419b47a75d
DEBU[0023] Strict-Transport-Security: max-age=31536000
DEBU[0023]
INFO[0023] linuxkit/containerd:cc02c2af9c928c2faeccbe4edc78bd297ad91866: digest: sha256:ebd295492eff4e096bfeaa4f09cc4013c629a72c41056afee26a49419b47a75d size: 1821