Private registry, no login prompt

[runcom]

I've setup a private registry with TLS and auth from the official registry:2 repository with:

docker run -d -p 5000:5000 --restart=always --name registry \
  -v `pwd`/auth:/auth \
  -e "REGISTRY_AUTH=htpasswd" \
  -e "REGISTRY_AUTH_HTPASSWD_REALM=Registry Realm" \
  -e REGISTRY_AUTH_HTPASSWD_PATH=auth/htpasswd \
  -v `pwd`/certs:/certs \
  -e REGISTRY_HTTP_TLS_CERTIFICATE=certs/domain.crt \
  -e REGISTRY_HTTP_TLS_KEY=certs/domain.key \
  registry:2

When I'm trying to pull an image (even if it doesn't exists) I get the following:

docker pull myregistrydomain.com:5000/runcom/busybox

Using default tag: latest
Error response from daemon: Get https://myregistrydomain.com:5000/v2/runcom/busybox/manifests/latest: no basic auth credentials
Get http://myregistrydomain.com:5000/v2/: malformed HTTP response "\x15\x03\x01\x00\x02\x02"

The following logs appear in the daemon:

Jan 07 11:02:34 fedora docker[9189]: time="2016-01-07T11:02:34.965646745+01:00" level=debug msg="Calling POST /v1.22/images/create"
Jan 07 11:02:34 fedora docker[9189]: time="2016-01-07T11:02:34.965773537+01:00" level=debug msg="POST /v1.22/images/create?fromImage=myregistrydomain.com%3A5000%2Fruncom%2Fbusybox%3Alatest"
Jan 07 11:02:34 fedora docker[9189]: time="2016-01-07T11:02:34.966759943+01:00" level=debug msg="Trying to pull myregistrydomain.com:5000/runcom/busybox from https://myregistrydomain.com:5000 v2"
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T10:02:35Z" level=warning msg="error authorizing context: basic authentication challenge for realm \"Registry Realm\": invalid authorization credential" go.version=go1.5.2 http.request.host="myregistrydomain.com:5000" http.request.id=9a22bdf9-4183-4c24-a1d7-6f31ab08ecdd http.request.method=GET http.request.remoteaddr="172.17.0.1:53818" http.request.uri="/v2/" http.request.useragent="docker/1.10.0-dev go/go1.5.2 git-commit/3442339 kernel/4.2.8-300.fc23.x86_64 os/linux arch/amd64" instance.id=1b6e47c7-b1af-4ad2-a826-4f4969766831 version=v2.2.1 
Jan 07 11:02:35 fedora docker[9189]: 172.17.0.1 - - [07/Jan/2016:10:02:35 +0000] "GET /v2/ HTTP/1.1" 401 87 "" "docker/1.10.0-dev go/go1.5.2 git-commit/3442339 kernel/4.2.8-300.fc23.x86_64 os/linux arch/amd64"
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T11:02:35.020740801+01:00" level=debug msg="Pulling ref from V2 registry: myregistrydomain.com:5000/runcom/busybox:latest"
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T11:02:35.021232235+01:00" level=debug msg="Error trying v2 registry: Get https://myregistrydomain.com:5000/v2/runcom/busybox/manifests/latest: no basic auth credentials"
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T11:02:35.021328760+01:00" level=debug msg="Trying to pull myregistrydomain.com:5000/runcom/busybox from http://myregistrydomain.com:5000 v2"
Jan 07 11:02:35 fedora docker[9189]: 2016/01/07 10:02:35 http: TLS handshake error from 172.17.0.1:53820: tls: first record does not look like a TLS handshake
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T11:02:35.022414402+01:00" level=warning msg="Error getting v2 registry: Get http://myregistrydomain.com:5000/v2/: malformed HTTP response \"\\x15\\x03\\x01\\x00\\x02\\x02\""
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T11:02:35.022502404+01:00" level=debug msg="Skipping v1 endpoint https://myregistrydomain.com:5000 because v2 registry was detected"
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T11:02:35.022555257+01:00" level=debug msg="Skipping v1 endpoint http://myregistrydomain.com:5000 because v2 registry was detected"
Jan 07 11:02:35 fedora docker[9189]: time="2016-01-07T11:02:35.022693453+01:00" level=error msg="Handler for POST /v1.22/images/create returned error: Get https://myregistrydomain.com:5000/v2/runcom/busybox/manifests/latest: no basic auth credentials\nGet http://myregistrydomain.com:5000/v2/: malformed HTTP response \"\\x15\\x03\\x01\\x00\\x02\\x02\""

I'm using the latest master code:

docker version        

Client:
 Version:      1.10.0-dev
 API version:  1.22
 Go version:   go1.5.2
 Git commit:   3442339
 Built:        Thu Jan  7 10:38:18 2016
 OS/Arch:      linux/amd64
 Experimental: true

Server:
 Version:      1.10.0-dev
 API version:  1.22
 Go version:   go1.5.2
 Git commit:   3442339
 Built:        Thu Jan  7 10:38:18 2016
 OS/Arch:      linux/amd64
 Experimental: true

I expected to receive a login prompt from reading the code (but probably I'm missing something)
Isn't the cli supposed to prompt me for login?

/cc @aaronlehmann @tonistiigi

[aaronlehmann]

I'm curious if this works as expected pre- #18590. There were some error handling changes there. What about with 1.9?

Another relevant change could be 31cdc63. I'm a bit suspicious of the way this flattens errors into strings. Maybe before the client got a HTTP-level error, and now it just gets an error string.

[runcom]

I'll test with 1.9 (not sure right now)
Also yes, errors flattened that way seem weird

[aaronlehmann]

I tried this with master and 1.9 and neither one prompts me for a login. So at least this doesn't seem like a regression from 1.9.

[runcom]

Alright, but I see there's a code path which should prompt for a login (afk now)

[runcom]

@aaronlehmann here https://github.com/docker/docker/blob/master/api/client/utils.go#L35

[runcom]

@aaronlehmann I thought the first attempt to pull would raise a 401 and go on from here https://github.com/docker/docker/blob/master/vendor/src/github.com/docker/engine-api/client/image_pull.go#L23 and ask for credentials but somehow it isn't happening (haven't dug yet enough)

[aaronlehmann]

What I don't know is where the daemon is supposed to return a 401 HTTP status to the client. Maybe some code existed to do this in some previous version. Now it just returns the error in the HTTP body as JSON: https://github.com/docker/docker/blob/master/api/server/router/local/image.go#L179

[runcom]

docker pull myregistrydomain.com:5000/runcom/busybox

Using default tag: latest
Error response from daemon: Get https://myregistrydomain.com:5000/v2/runcom/busybox/manifests/latest: no basic auth credentials
Get http://myregistrydomain.com:5000/v2/: malformed HTTP response "\x15\x03\x01\x00\x02\x02"

it seems from this log that the first is a 401, then a retry is performed (the first 401 error isn't returned but just saved), and the retry returns a 500 which will fail the if condition to login. Could it be like I said? (didn't check, but I remember errors are kind of stacked before returning them to the cli)

[aaronlehmann]

But even without the retry, I don't see anything that would pass the 401 status through to the client.

[runcom]

So if the code is there I suppose it was once working, maybe 1.8 or maybe support for login prompt was dropped and that's just dead code

[runcom]

also errors are different between private and public registry:

runcom at fedora in ~ docker push myregistrydomain.com:5000/runcom/busyboxtestn       
The push refers to a repository [myregistrydomain.com:5000/runcom/busyboxtestn]
5f70bf18a086: Retrying in 9 seconds 
2c84284818d1: Retrying in 9 seconds 
^C%                                                                                                                  

runcom at fedora in ~ docker push runcom/busyboxtestn                                                            2 ↵
The push refers to a repository [docker.io/runcom/busyboxtestn]
5f70bf18a086: Preparing 
2c84284818d1: Preparing 
unauthorized: access to the requested resource is not authorized

Not sure I can get not authorized with official registry but from private with latest master code:

docker pull myregistrydomain.com:5000/runcom/busyboxtestn                                  1 ↵
Using default tag: latest
Error response from daemon: Get http://myregistrydomain.com:5000/v2/: malformed HTTP response "\x15\x03\x01\x00\x02\x02"

[schmunk42]

We also saw this in our CI, when pushing to our private registry.

The situation was like the following: Two jobs built the latest image of i.e registry/foo/bar and then pushed it to the registry.

While the build process is isolated by custom COMPOSE_PROJECT_NAMEs, before pushing we need to tag the image as :latest - looks like the second tag happend during the first push.

I was able to watch the push, but for the last layers docker was retrying over and over.

Sorry, no logs or -D available at the moment. (docker 1.10)

[runcom]

@aaronlehmann @tonistiigi @calavera I tried this with 1.9 and this seems really a regression cause in 1.9 docker prompted for user+pass when pushing/pulling

[aaronlehmann]

I discussed this with @runcom a little and it sounds like the problem was related to the token server mock not returning a proper JSON error body. The push/pull code switches on error values returned by the docker/distribution client library, which come from parsing JSON in the body. If the body is missing, it doesn't get a meaningful error value like errcode.ErrorCodeUnauthorized.

So it sounds to me like there's no regression when the token server is returning well-formed errors, but we could certainly do better in cases where we only have a status code.

I'll open a ticket or PR against docker/distribution to improve this behavior.

[runcom]

What about push behavior? 1.9 did ask for credentials while 1.10 hangs at Retrying (which is fine with me)