Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Can no longer pull with docker 1.8.1 if the user only has pull access #22

Closed
silverbp opened this issue Aug 19, 2015 · 30 comments
Closed
Assignees

Comments

@silverbp
Copy link

see

moby/moby#15640

I guess it's supposed to return the token with the appropriate rights and it's the registries responsibility to deny access.

Which makes since from an SSO kind of implementation with a JWT.

in 1.8.1 docker is requesting push and pull for just a pull, not sure why they changed that.

@rojer
Copy link
Collaborator

rojer commented Aug 20, 2015

looking

@rojer
Copy link
Collaborator

rojer commented Aug 20, 2015

pushed new images, should be ok now

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Oh excellent! Thank you @rojer I will try it.

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Hmm, still not working for me, but I am not sure this is the issue. Here is the output of docker daemon -D

Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.602029727-04:00" level=debug msg="Calling POST /auth"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.602099561-04:00" level=info msg="POST /v1.20/auth"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.602348541-04:00" level=debug msg="pinging registry endpoint https://reg.local/v0/"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.602399888-04:00" level=debug msg="attempting v2 ping for registry endpoint https://reg.local/v2/"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.623881875-04:00" level=debug msg="attempting v2 login to registry endpoint https://reg.local/v2/"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.623947239-04:00" level=debug msg="trying \"bearer\" auth challenge with params map[realm:https://reg.local:5001/auth service:reg.local scope:]"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.668058639-04:00" level=debug msg="error trying auth challenge \"bearer\": token auth attempt to https://reg.local/v2/ realm \"https://reg.local:5001/auth\" failed with status: 401 Unauthorized"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.668135216-04:00" level=error msg="Handler for POST /auth returned error: no successful auth challenge for https://reg.local/v2/ - errors: [token auth attempt to https://reg.local/v2/ realm \"https://reg.local:5001/auth\" failed with status: 401 Unauthorized]"
Aug 21 09:15:28 reg docker[15598]: time="2015-08-21T09:15:28.668185040-04:00" level=error msg="HTTP Error" err="no successful auth challenge for https://reg.local/v2/ - errors: [token auth attempt to https://reg.local/v2/ realm \"https://reg.local:5001/auth\" failed with status: 401 Unauthorized]" statusCode=500

And my config file:

server:  # Server settings.
  # Address to listen on.
  addr: ":5001"
  # TLS certificate and key.
  certificate: "/certs/registry.crt"
  key: "/certs/registry.key"

token:  # Settings for the tokens.
  issuer: "reg.local"  # Must match issuer in the Registry config.
  expiration: 900

# Static user map.
users:
  # Password is specified as a BCrypt hash. Use htpasswd -B to generate.
  "admin":
    password: "$2y$05$SirvKgES6jlgIKDqElQgAu6.3d.czANNYnyPe6SJy4exvAW0cpUjW"
  "avid":
    # password is 12345678
    password: "$2y$05$NZ694lx3DXadnm/Z3QXo9OVc5TFbAUSlYVjN4HvT.dDNDpdpUY3SC"
  "avi2":
    # password is 12345678
    password: "$2y$05$NZ694lx3DXadnm/Z3QXo9OVc5TFbAUSlYVjN4HvT.dDNDpdpUY3SC"
  "": {}  # Allow anonymous (no "docker login") access.

acl:
  # Admin has full access to everything.
  - match: {account: "admin"}
    actions: ["*"]
  # User "avid" has full access to avid/* images
  - match: {account: "avid", name: "avid/*"}
    actions: ["*"]
  # User "avi2" has full access to avi2/* images but nothing else.
  - match: {account: "avid", name: "avi2/*"}
    actions: ["*"]
  # User "avid" has full access to it/* images
  - match: {account: "avid", name: "it/*"}
    actions: ["*"]
  # All logged in users can pull all images.
  - match: {account: "/.+/"}
    actions: ["pull"]
  # All anonymous users can pull all images.
  - match: {account: ""}
    actions: ["pull"]
  # Access is denied by default.

I am trying to push avid/foo and logging in as avid.

However, if I do an explicit curl it works:

# curl -ik --user avid:12345678 'https://localhost:5001/auth?service=reg.local&scope=repository:avid/foo:push,pull'
HTTP/1.1 200 OK
Content-Type: application/json
Date: Fri, 21 Aug 2015 13:18:52 GMT
Content-Length: 587

{"token":"eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkNMVUQ6TjVBSzpFRzJNOjZBR0E6VkFMQjo1MkZIOlJCTVg6SEpENDozWkxUOkI3RFM6VURRQzpPVE83In0.eyJpc3MiOiJyZWcubG9jYWwiLCJzdWIiOiJhdmlkIiwiYXVkIjoicmVnLmxvY2FsIiwiZXhwIjoxNDQwMTY0MDMyLCJuYmYiOjE0NDAxNjMxMzEsImlhdCI6MTQ0MDE2MzEzMiwianRpIjoiNDIxODQ4ODQ3NTA3NDAzMDM1NyIsImFjY2VzcyI6W3sidHlwZSI6InJlcG9zaXRvcnkiLCJuYW1lIjoiYXZpZC9mb28iLCJhY3Rpb25zIjpbInB1bGwiLCJwdXNoIl19XX0.QilpTFxv2GvT5YUATZEgIdIcWQJ6HzkSob7lbbk2BkXodcBwo8aCFC0WHc8jWREeDi3f7uvd3Hq-OcobktvQVs-skMvw2fZzSvdXNwEHf9K0Z8pnJF3M1HECw3idIncRCYP3Txjmtr07c8DGLN7eNZVINykZYS15LfgzQv7RbW4"}

That is true even if I try a non-existent scope. So the curl is working, but still getting a 401 when the docker daemon tries it.

# docker version
Client:
 Version:      1.8.1
 API version:  1.20
 Go version:   go1.4.2
 Git commit:   d12ea79
 Built:        Thu Aug 13 02:19:43 UTC 2015
 OS/Arch:      linux/amd64

Server:
 Version:      1.8.1
 API version:  1.20
 Go version:   go1.4.2
 Git commit:   d12ea79
 Built:        Thu Aug 13 02:19:43 UTC 2015
 OS/Arch:      linux/amd64

?

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Hmm, same thing for an anonymous pull:

Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.680297790-04:00" level=debug msg="Calling POST /images/create"
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.680348295-04:00" level=info msg="POST /v1.20/images/create?fromImage=reg.local%2Favid%2Fimage%3Alatest"
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.680558519-04:00" level=debug msg="Trying to pull reg.local/avid/image from https://reg.local v2"
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.706250594-04:00" level=debug msg="Pulling tag from V2 registry: \"latest\""
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.727005994-04:00" level=debug msg="Error trying v2 registry: Get https://reg.local/v2/avid/image/manifests/latest: token auth attempt for registry: https://reg.local:5001/auth?account=avi2&scope=repository%3Aavid%2Fimage%3Apush%2Cpull&service=reg.local request failed with status: 401 Unauthorized"
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.727071041-04:00" level=debug msg="Trying to pull reg.local/avid/image from https://reg.local v1"
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.727189436-04:00" level=debug msg="attempting v2 ping for registry endpoint https://reg.local/v2/"
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.747586914-04:00" level=debug msg="[registry] Calling GET https://reg.local/v1/repositories/avid/image/images"
Aug 21 09:22:43 reg docker[15598]: time="2015-08-21T09:22:43.772432490-04:00" level=debug msg="Not continuing with error: Error: image avid/image:latest not found"

Strange that docker_auth is returning 401 to docker daemon... and again, curl works.

Any way to enable debugging on it?

@rojer rojer reopened this Aug 21, 2015
@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

yes, add --v=2 and --alsologtostderr auth server command line
paste output here, i'd like to have a look

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Hmm, OK, so part of it was cached login information. I cleared it out, restarted all, and now it works at least partially.

I cleared out the cache in ~/.docker/config.json. Now:

  • pull without login: returns a token correctly as anonymous
  • push without login: returns a token correctly as anonymous
  • login: doesn't quite work. I actually get the token back, but it must be misconfigured or something, because I still get a 401

Here are the logs from docker_auth

cesanta_1 | I0821 13:42:23.174606       1 server.go:189] Request: &{Method:GET URL:/auth?account=avid&service=reg.local Proto:HTTP/1.1 ProtoMajor:1 ProtoMinor:1 Header:map[User-Agent:[docker/1.8.1 go/go1.4.2 git-commit/d12ea79 kernel/3.10.0-123.8.1.el7.x86_64 os/linux arch/amd64] Authorization:[Basic YXZpZDoxMjM0NTY3OA==] Accept-Encoding:[gzip]] Body:0xb42680 ContentLength:0 TransferEncoding:[] Close:false Host:reg.local:5001 Form:map[] PostForm:map[] MultipartForm:<nil> Trailer:map[] RemoteAddr:107.170.247.94:46522 RequestURI:/auth?account=avid&service=reg.local TLS:0xc2080e0800}
cesanta_1 | I0821 13:42:23.174966       1 server.go:220] Auth request: {avid:***@107.170.247.94:46522 {avid   }}
cesanta_1 | I0821 13:42:23.181835       1 server.go:103] Authn static avid -> true, %!s(<nil>)
cesanta_1 | I0821 13:42:23.188867       1 server.go:184] New token for {avid:***@107.170.247.94:46522 {avid   }}: {"iss":"reg.local","sub":"avid","aud":"reg.local","exp":1440165443,"nbf":1440164542,"iat":1440164543,"jti":"6307571486690413168","access":[]}
cesanta_1 | I0821 13:42:23.188968       1 server.go:250] {"token":"eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkNMVUQ6TjVBSzpFRzJNOjZBR0E6VkFMQjo1MkZIOlJCTVg6SEpENDozWkxUOkI3RFM6VURRQzpPVE83In0.eyJpc3MiOiJyZWcubG9jYWwiLCJzdWIiOiJhdmlkIiwiYXVkIjoicmVnLmxvY2FsIiwiZXhwIjoxNDQwMTY1NDQzLCJuYmYiOjE0NDAxNjQ1NDIsImlhdCI6MTQ0MDE2NDU0MywianRpIjoiNjMwNzU3MTQ4NjY5MDQxMzE2OCIsImFjY2VzcyI6W119.GUfC9--Vb8xAXIyu0n2jP2pfevWeZwxxbvvVaOeSy4Gwst7qMrR42QQ772hScZoPl_Smi47I29niQ4nE7QHUZru-W_nInQvE2A29iccdSN58ff11esyuBqnG1L7FqUo0r6lenDmXOOagsWNi2kEFBT1RbPyV7VHEqMxfSgl5VHY"}

And from docker:

Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.137500448-04:00" level=debug msg="Calling POST /auth"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.137645941-04:00" level=info msg="POST /v1.20/auth"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.137794947-04:00" level=debug msg="pinging registry endpoint https://reg.local/v0/"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.137866555-04:00" level=debug msg="attempting v2 ping for registry endpoint https://reg.local/v2/"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.159403219-04:00" level=debug msg="attempting v2 login to registry endpoint https://reg.local/v2/"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.159460198-04:00" level=debug msg="trying \"bearer\" auth challenge with params map[realm:https://reg.local:5001/auth service:reg.local scope:]"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.206966325-04:00" level=debug msg="error trying auth challenge \"bearer\": token auth attempt to https://reg.local/v2/ realm \"https://reg.local:5001/auth\" failed with status: 401 Unauthorized"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.207047639-04:00" level=error msg="Handler for POST /auth returned error: no successful auth challenge for https://reg.local/v2/ - errors: [token auth attempt to https://reg.local/v2/ realm \"https://reg.local:5001/auth\" failed with status: 401 Unauthorized]"
Aug 21 09:42:23 reg docker[15598]: time="2015-08-21T09:42:23.207092601-04:00" level=error msg="HTTP Error" err="no successful auth challenge for https://reg.local/v2/ - errors: [token auth attempt to https://reg.local/v2/ realm \"https://reg.local:5001/auth\" failed with status: 401 Unauthorized]" statusCode=500

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

And for the actual command:

[root@reg OP]# docker login reg.local
Username: avid
Password:
Email: ****
Error response from daemon: no successful auth challenge for https://reg.local/v2/ - errors: [token auth attempt to https://reg.local/v2/ realm "https://reg.local:5001/auth" failed with status: 401 Unauthorized]

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

really weird. immediately after logging at line 250 of server.go we return the token with status 200, yet registry claims it got 401. huh?

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Yeah, that's what I thought. That's why I ran daemon -D and attached it here. See anything?

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

For some comparison, the output from the docker daemon when I try to login to the official registry:

Aug 21 09:53:26 reg docker[15598]: time="2015-08-21T09:53:26.506600885-04:00" level=debug msg="Calling POST /auth"
Aug 21 09:53:26 reg docker[15598]: time="2015-08-21T09:53:26.506741835-04:00" level=info msg="POST /v1.20/auth"
Aug 21 09:53:26 reg docker[15598]: time="2015-08-21T09:53:26.575927177-04:00" level=debug msg="hostDir: /etc/docker/certs.d/https:/index.docker.io/v1"
Aug 21 09:53:26 reg docker[15598]: time="2015-08-21T09:53:26.576149419-04:00" level=debug msg="pinging registry endpoint https://index.docker.io/v1/"
Aug 21 09:53:26 reg docker[15598]: time="2015-08-21T09:53:26.576313294-04:00" level=debug msg="attempting v1 ping for registry endpoint https://index.docker.io/v1/"
Aug 21 09:53:26 reg docker[15598]: time="2015-08-21T09:53:26.576355242-04:00" level=debug msg="attempting v1 login to registry endpoint https://index.docker.io/v1/"

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

this is using v1

sorry, no idea - WFM with 1.8.1 and registry:2.0

rojer@nbt:~ master$ docker --version
Docker version 1.8.1, build d12ea79
rojer@nbt:~ master$ docker logout docker.cesanta.com:5000
Remove login credentials for docker.cesanta.com:5000
rojer@nbt:~ master$ docker login docker.cesanta.com:5000                                                                                                                                                                                       
Username: rojer@cesanta.com
Password: 
Email: rojer@cesanta.com
WARNING: login credentials saved in /home/rojer/.docker/config.json
Login Succeeded
rojer@nbt:~ master$

and daemon's output:

DEBU[0007] Calling POST /auth
INFO[0007] POST /v1.20/auth
DEBU[0007] hostDir: /etc/docker/certs.d/docker.cesanta.com:5000
DEBU[0007] pinging registry endpoint https://docker.cesanta.com:5000/v0/
DEBU[0007] attempting v2 ping for registry endpoint https://docker.cesanta.com:5000/v2/
DEBU[0008] attempting v2 login to registry endpoint https://docker.cesanta.com:5000/v2/
DEBU[0008] trying "bearer" auth challenge with params map[service:Docker registry scope: realm:https://docker.cesanta.com:5001/auth]

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

What do you get for the next line after `trying "bearer" "?

I am running registry 2.0.1. Cannot imagine it matters, but try it?

@silverbp
Copy link
Author

The fix worked for me using v2 and docker 1.8.1. We are using google authentication for pull but don't have anonymous pull enabled.

and registry 2.1.1

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

nothing, that's the last line

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

@silverbp what registry version?

@silverbp
Copy link
Author

I updated my post but it's 2.1.1

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

we're using google authn too, but the authn method shouldn't matter, as that clearly succeeds - after "Authn static avid -> true" it's over with authn.

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Yes, quite. If it is returning 200 - and the log says it is, and the curl says it is - then how can it possibly be giving me 401??

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

but most of all i'm puzzled by this discrepancy: i can't see how auth server can return anything but 200, and yet registry reports 401.

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

yeah, go figure...

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

docker 1.8.1, registry 2.0.1 and 2.1.1, cesanta/docker_auth:latest, how can this be happening??

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

PEBKAC!!

1 similar comment
@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

PEBKAC!!

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

@deitch ok, that happens. :)

@rojer rojer closed this as completed Aug 21, 2015
@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Sorry about that. Curious to know what it was?

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

sure, do tell. probably talking to a different instance or something.

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

I had copied over the registry yml from someplace else, and edited the environment, here is the relevant part. Do you see the type? :-(

  environment:
    REGISTRY_AUTH: token
    REGISTRY_AUTH_TOKEN_REALM: https://reg.local:5001/auth
    REGISTRY_AUTH_TOKEN_SERVICE: reg.local
    # HINT: LOOK AT THE NEXT LINE. SIGH!
    REGISTRY_AUTH_TOKEN_ISSUER: my.reg.local
    REGISTRY_AUTH_TOKEN_ROOTCERTBUNDLE: /certs/registry.crt

@deitch
Copy link
Contributor

deitch commented Aug 21, 2015

Oops, I accidentally didn't change the token issuer. Sigh. Like I said, PEBKAC.

@rojer
Copy link
Collaborator

rojer commented Aug 21, 2015

all right. so it did get the token, but the issuer was wrong. makes sense.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants