registry 2.6.0: 503 on push behind a load balancer (works with 2.5.1)

[auguster]

I noticed a breaking change in registry 2.6.0, I was unable to push to it though login and pull worked fine.
The client kept getting 503 errors on upload while the registry was responding with 202. The fact that I don't have the same error code on both side tells me that my load balancer in between (haproxy with SSL termination) cannot route the upload request to the registry and send this 503 error to the client.

It would seem that registry 2.6.0 has a different way of uploading content. I guess there is authentification, then some kind of upload handshake and then it goes wrong. Is the client trying to send content using a different path ?

Here is the log from the client:

dockerd[1392]:` time="2017-01-29T13:43:25.783189911+01:00" level=error msg="Upload failed, retrying: received unexpected HTTP status: 503 Service Unavailable"

And here is the log from the server, I replaced the ip and hosts with their semantic meaning:

time="2017-01-29T12:38:06Z" level=info msg="redis not configured" go.version=go1.7.3 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
time="2017-01-29T12:38:06Z" level=info msg="Starting upload purge in 44m0s" go.version=go1.7.3 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
time="2017-01-29T12:38:06Z" level=info msg="using inmemory blob descriptor cache" go.version=go1.7.3 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
time="2017-01-29T12:38:06Z" level=info msg="listening on [::]:5000" go.version=go1.7.3 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
time="2017-01-29T12:43:25Z" level=warning msg="error authorizing context: basic authentication challenge for realm \"Registry Realm\": invalid authorization credential" go.version=go1.7.3 http.request.host=**<registry's FQDN>** http.request.id=19dd7446-9c07-4b36-8df5-24dc0be526dc http.request.method=GET http.request.remoteaddr=**<docker client ip address>** http.request.uri="/v2/" http.request.useragent="docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))" instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
**<load balancer 1 ip address>** - - [29/Jan/2017:12:43:25 +0000] "GET /v2/ HTTP/1.1" 401 87 "" "docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))"
time="2017-01-29T12:43:26Z" level=info msg="response completed" go.version=go1.7.3 http.request.host=**<registry's FQDN>** http.request.id=e27f716e-b125-4f2e-95e7-b7907d7ca972 http.request.method=POST http.request.remoteaddr=**<docker client ip address>** http.request.uri="/v2/ressource/blobs/uploads/?from=builder&mount=sha256%3Ac0cb142e43453ebb1f82b905aa472e6e66017efd43872135bc5372e4fac04031" http.request.useragent="docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))" http.response.duration=192.830871ms http.response.status=201 http.response.written=0 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
**<load balancer 2 ip address>** - - [29/Jan/2017:12:43:26 +0000] "POST /v2/ressource/blobs/uploads/?from=builder&mount=sha256%3Ac0cb142e43453ebb1f82b905aa472e6e66017efd43872135bc5372e4fac04031 HTTP/1.1" 201 0 "" "docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))"
time="2017-01-29T12:43:26Z" level=info msg="response completed" go.version=go1.7.3 http.request.host=**<registry's FQDN>** http.request.id=96345795-e331-4c15-afbb-90441f1f257f http.request.method=POST http.request.remoteaddr=**<docker client ip address>** http.request.uri="/v2/ressource/blobs/uploads/" http.request.useragent="docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))" http.response.duration=210.820412ms http.response.status=202 http.response.written=0 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
**<load balancer 3 ip address>** - - [29/Jan/2017:12:43:26 +0000] "POST /v2/ressource/blobs/uploads/ HTTP/1.1" 202 0 "" "docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))"
time="2017-01-29T12:43:26Z" level=info msg="response completed" go.version=go1.7.3 http.request.host=**<registry's FQDN>** http.request.id=ee92a4af-ef6c-4ef6-a7a2-ae394bcd3def http.request.method=POST http.request.remoteaddr=**<docker client ip address>** http.request.uri="/v2/ressource/blobs/uploads/" http.request.useragent="docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))" http.response.duration=216.313907ms http.response.status=202 http.response.written=0 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
**<load balancer 3 ip address>** - - [29/Jan/2017:12:43:26 +0000] "POST /v2/ressource/blobs/uploads/ HTTP/1.1" 202 0 "" "docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))"
time="2017-01-29T12:43:26Z" level=info msg="response completed" go.version=go1.7.3 http.request.host=**<registry's FQDN>** http.request.id=49d66d19-e4c6-4458-948c-3e3659602c98 http.request.method=HEAD http.request.remoteaddr=**<docker client ip address>** http.request.uri="/v2/ressource/blobs/sha256:c0cb142e43453ebb1f82b905aa472e6e66017efd43872135bc5372e4fac04031" http.request.useragent="docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))" http.response.contenttype="application/octet-stream" http.response.duration=14.645215ms http.response.status=200 http.response.written=0 instance.id=513dff4f-5fb1-4fe3-a7b1-d1e875a96570 version=v2.6.0 
**<load balancer 4 ip address>** - - [29/Jan/2017:12:43:26 +0000] "HEAD /v2/ressource/blobs/sha256:c0cb142e43453ebb1f82b905aa472e6e66017efd43872135bc5372e4fac04031 HTTP/1.1" 200 0 "" "docker/1.13.0 go/go1.7.3 git-commit/49bf474 kernel/3.16.0-4-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.13.0 \\(linux\\))"

From what I see the http.request.remoteaddr is my client's external IP address, so I guess Honor X-Forwarded-Port and Forwarded headers (in 2.6.0 changelog) works. I notice that the http.request.id changes on every request.

I don't see anything wrong in those log. I'm not sure what else to provide to help diagnose the issue.

Anyway, I fall back to registry 2.5.1 and it works again.

[chendo]

Unsure if our issue is related. We were unable to push on 2.6 from Docker 1.12.1 as it would error with http: server gave HTTP response to HTTPS client.

The registry is running inside Docker behind an ELB.

Logs on the registry says it received the request:

time="2017-02-06T00:17:37Z" level=info msg="response completed" go.version=go1.7.3 http.request.host=<registry> http.request.id=9b2dc73d-b08f-4bb3-8f39-d14e7d1854ce http.request.method=POST http.request.remoteaddr=172.31.14.152 http.request.uri="/v2/<image>/blobs/uploads/" http.request.useragent="docker/1.12.3 go/go1.6.3 git-commit/6b644ec kernel/3.10.0-327.el7.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.12.3 \\(linux\\))" http.response.duration=47.295888ms http.response.status=202 http.response.written=0 instance.id=c9745e5a-ba29-4a07-8748-dd9ca4b204a6 version=v2.6.0 
172.31.59.35 - - [06/Feb/2017:00:17:37 +0000] "POST /v2/<image>/blobs/uploads/ HTTP/1.1" 202 0 "" "docker/1.12.3 go/go1.6.3 git-commit/6b644ec kernel/3.10.0-327.el7.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/1.12.3 \\(linux\\))"

We tried downgrading our registry to 2.5 and everything works again.

[omerxx]

Encountered a similar issue to @auguster. Falling back to 2.2 working fine.
Update: 2.5 is ok too.
2.6 is the problem

[gouthamve]

Am running into the same issue which I mis-diagnosed as being caused by minio: minio/minio#3779.

I am not using SSL and am using fabio as a reverse proxy. Logs for the failure attached here: http://pastebin.com/BxLmuigb

No clue what is going wrong, the client reports this: https://i.imgur.com/Udi9KMu.png before ending with: https://i.imgur.com/DrhamqO.png

[auguster]

@gouthamve looking at your screenshot, I can confirm that it looks like the issue I had.

[dmcgowan]

@auguster thanks for report, trying to better understand how I could reproduce and debug this issue.

I don't see anything wrong in those log. I'm not sure what else to provide to help diagnose the issue.

Do you have any in the load balancer logs which may indicate why the 503 was returned. Was it return on the same request as the 202 or was the 202 followed up by a request which caused a 503? My guess would be that the upload URL location was created incorrectly and the subsequent request caused the 503. If that is the case it would be helpful to know what that second request looked like.

[auguster]

@dmcgowan It's not very practical to figure out those log, I have four load balancer behind a type A DNS containing the 4 IPs. So the logs might be spread on those 4 LBs. I'll see if I can take 3 LBs down during a maintenance window to have everything on the same LB. As I said, it's not very practical, but I'll try :)

[jlrigau]

Same issue with a registry 2.6.0 running behind an ELB.

It works well with a registry 2.5.1 :/

[dmcgowan]

I want to apologize to everyone who has encountered this issue, we have identified the issue and will issue a 2.6.1 once it is patched. For details on the problem take a look at #2219. I will close this issue once we have a release with the fix.

[dmcgowan]

Please test and verify the release candidate with this fix registry:2.6.1-rc.2