Unable to refresh RSA keys for JWK signing

[taland]

Hi. I faced with an issue setting up Hydra in pair with OathKeeper. Following the guidelines I have run Hydra, but when I starting with OathKeeper it fails with an "Unable to refresh RSA keys for JWK signing" error.

Using:

• Hydra v0.11.6
• OathKeeper 0.0.29

OathKeeper log:

time="2018-02-28T09:19:21Z" level=error msg="Unable to refresh RSA keys for JWK signing" error="Expected status code 200 but got 403" retry=0

Hydra log:

hydra_1 | time="2018-02-28T09:19:21Z" level=info msg="started handling request" method=POST remote="172.18.0.4:39010" request=/oauth2/token hydra_1 | time="2018-02-28T09:19:21Z" level=info msg="started handling request" method=POST remote="172.18.0.4:39012" request=/oauth2/token hydra_1 | time="2018-02-28T09:19:21Z" level=info msg="completed handling request" measure#http://localhost:4444.latency=90761997 method=POST remote="172.18.0.4:39010" request=/oauth2/token status=200 text_status=OK took=90.761997ms hydra_1 | time="2018-02-28T09:19:21Z" level=info msg="started handling request" method=GET remote="172.18.0.4:39010" request="/keys/oathkeeper:id-token/private" hydra_1 | time="2018-02-28T09:19:21Z" level=info msg="Access granted" client_id=oathkeeper-client request="&{[] [] { 2018-02-28 09:19:21.148473 +0000 +0000 0xc420494000 [hydra.introspect hydra.warden hydra.keys.] [hydra.introspect hydra.warden hydra.keys.] map[grant_type:[client_credentials] scope:[hydra.introspect hydra.warden hydra.keys.]] 0xc42030b250}}" result="&{oathkeeper-client [hydra.introspect hydra.warden hydra.keys.] http://localhost:4444 oathkeeper-client 2018-02-28 09:19:21.148473 +0000 +0000 2018-02-28 10:19:21.236134569 +0000 UTC map[]}" subject=oathkeeper-client hydra_1 | time="2018-02-28T09:19:21Z" level=error msg="An error occurred while handling a request" code=404 details="[]" error=": Not found" reason= request-id= status= trace="Stack trace: \ngithub.com/ory/hydra/jwk.(SQLManager).GetKey\n\t/go/src/github.com/ory/hydra/jwk/manager_sql.go:139\ngithub.com/ory/hydra/jwk.(Handler).GetKey\n\t/go/src/github.com/ory/hydra/jwk/handler.go:210\ngithub.com/ory/hydra/jwk.(Handler).GetKey-fm\n\t/go/src/github.com/ory/hydra/jwk/handler.go:70\ngithub.com/ory/hydra/vendor/github.com/julienschmidt/httprouter.(Router).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter/router.go:299\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.Wrap.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:41\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\ngithub.com/ory/hydra/cmd/server.(Handler).rejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:200\ngithub.com/ory/hydra/cmd/server.(Handler).(github.com/ory/hydra/cmd/server.rejectInsecureRequests)-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:113\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus.(Middleware).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus/middleware.go:136\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/metrics.(MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/middleware.go:157\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(Negroni).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:73\ngithub.com/ory/hydra/vendor/github.com/rs/cors.(Cors).Handler.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/rs/cors/cors.go:200\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\ngithub.com/ory/hydra/vendor/github.com/gorilla/context.ClearHandler.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/gorilla/context/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2619\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1801\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:2337" writer=JSON hydra_1 | time="2018-02-28T09:19:21Z" level=info msg="completed handling request" measure#http://localhost:4444.latency=8060668 method=GET remote="172.18.0.4:39010" request="/keys/oathkeeper:id-token/private" status=404 text_status="Not Found" took=8.060668ms

Digging into the code of OathKeeper I found it depends on github.com/ory/hydra@v0.9.14. And since it fails in the following line https://github.com/ory/oathkeeper/blob/master/rsakey/manager_hydra.go#L42 I did not find GetJsonWebKey method within JWKApi interface implemented for github.com/ory/hydra@v0.11.6. It seems latest version of OathKeeper is incompatible with latest of Hydra. Could you please advice what to do or probably share some drawbacks of using OathKeeper with latest version of Hydra?

Thanks in advance.

[aeneasr]

Right, version 0.10.x works fine but a breaking change was introduced in 0.11.6 which changed the way JWK names are generated.

Thus, oathkeeper doesn't work because it relies on the default key name generation which causes the 404. I'll dig into it and supply a fix! :)

[aeneasr]

Sorry, this change will land in 1.0.0, it did not land in 0.11.0.

I just ran the tests with v0.11.6 and it works, so it's either some fluke or misconfiguration in your environment.

[taland]

Thank you for your quick reply.

I'v managed to move further and currently Oathkeeper raises the same error:

level=error msg="Unable to refresh RSA keys for JWK signing" error="Expected status code 200 but got 403"

but Hydra complains:

The client is not allowed to request scope hydra.introspect

When added hydra.introspect scope to the client scopes:

The client is not allowed to request scope hydra.keys.*

And finally:

hydra_1 | time="2018-03-01T10:51:43Z" level=info msg="Access denied" client_id=oathkeeper-client error="Request was denied by default: request_forbidden" reason="The policy decision point denied the request" request="&{rn:hydra:keys:oathkeeper:id-token create map[]}" scopes="[hydra.keys.create]" subject=oathkeeper-client hydra_1 | time="2018-03-01T10:51:43Z" level=error msg="An error occurred while handling a request" code=403 details="[]" error="Request was denied by default: request_forbidden" reason="You are not allowed to perform this action." request-id= status=Forbidden

So it seems the policy is not configured correctly (taken from here):

{ "id": "oathkeeper-policy", "subjects": [ "oathkeeper-client" ], "effect": "allow", "resources": [ "rn:hydra:warden:allowed", "rn:hydra:warden:token:allowed", "rn:hydra:keys:oathkeeper:id-token<.*>" ], "actions": [ "decide", "get" ] }

Could you please point me where an error could be? or maybe there is some another documentation which can explain me more.

[aeneasr]

Right, it seems like the client definition is off:

{
  "id": "oathkeeper-client",
  "client_secret": "something-secure",
  "scope": "hydra.warden",
  "grant_types": ["client_credentials"],
  "response_types": ["token"]
}

should be:

{
  "id": "oathkeeper-client",
  "client_secret": "something-secure",
  "scope": "hydra.warden hydra.keys.* hydra.introspect",
  "grant_types": ["client_credentials"],
  "response_types": ["token"]
}

[taland]

Yeah, but unfortunately even using the correct client definition Hydra complains: level=info msg="Access denied" client_id=oathkeeper-client error="Request was denied by default: request_forbidden" reason="The policy decision point denied the request" request="&{rn:hydra:keys:oathkeeper:id-token create map[]}" scopes="[hydra.keys.create]" subject=oathkeeper-client

And as I can understand the "rn:hydra:keys:oathkeeper:id-token<.*>" resource was declared by oathkeeper-policy policy. However, Hydra decides to deny the request. Why?

[aeneasr]

Right, seems like the create action is missing:

{
  "id": "oathkeeper-policy",
  "subjects": [
    "oathkeeper-client"
  ],
  "effect": "allow",
  "resources": [
    "rn:hydra:warden:allowed",
    "rn:hydra:warden:token:allowed",
    "rn:hydra:keys:oathkeeper:id-token<.*>",
  ],
  "actions": [
    "decide",
    "get"
  ]
}

should be

{
  "subjects": [
    "${OATHKEEPER_CLIENT_ID}"
  ],
  "effect": "allow",
  "resources": [
    "rn:hydra:keys:${HYDRA_JWK_SET_ID}<.*>",
    "rn:hydra:warden:<.*>",
    "rn:hydra:oauth2:tokens"
  ],
  "actions": [
    "decide",
    "get",
    "create",
    "introspect",
    "update",
    "delete"
  ]
}

ps: obviously, please replace the subject / resource ids :)

[taland]

Ok, now I see Hydra has granted access for oathkeeper-client user. But there is still an error in Hydra logs occurred while oathkeeper requests RSA keys for JWK signing:

pq: duplicate key value violates unique constraint "hydra_jwk_pkey"

I am sure the hydra_jwt table did not contain any private/public tokens related to oathkeeper:id-token subject before OathKeeper docker container had been run first time. Any thoughts?

Attached stack if it may help: Stack trace: \ngithub.com/ory/hydra/jwk.(*SQLManager).AddKeySet\n\t/go/src/github.com/ory/hydra/jwk/manager_sql.go:123\ngithub.com/ory/hydra/jwk.(*Handler).Create\n\t/go/src/github.com/ory/hydra/jwk/handler.go:339\ngithub.com/ory/hydra/jwk.(*Handler).Create-fm\n\t/go/src/github.com/ory/hydra/jwk/handler.go:71\ngithub.com/ory/hydra/vendor/github.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter/router.go:299\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.Wrap.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:41\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\ngithub.com/ory/hydra/cmd/server.(*Handler).rejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:201\ngithub.com/ory/hydra/cmd/server.(*Handler).(github.com/ory/hydra/cmd/server.rejectInsecureRequests)-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:114\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus/middleware.go:136\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/metrics.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/middleware.go:183\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:73\ngithub.com/ory/hydra/vendor/github.com/rs/cors.(*Cors).Handler.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/rs/cors/cors.go:200\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\ngithub.com/ory/hydra/vendor/github.com/gorilla/context.ClearHandler.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/gorilla/context/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2619\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1801\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:2337

[aeneasr]

That might be due to some issues that occurred while you were testing. One possibility is to delete all keys from hydra related to oathkeeper, to use another key name (make sure to update the policy as well), or to recreate the database

[taland]

Now, it seems to unable find the key.

The database was recreated. Hydra image is oryd/hydra:v0.10.10-alpine Oathkeeper image is oryd/oathkeeper:v0.0.29

hydra_1 | time="2018-03-01T12:54:33Z" level=info msg="started handling request" method=POST remote="172.18.0.4:39802" request="/keys/oathkeeper:id-token-2" hydra_1 | time="2018-03-01T12:54:33Z" level=error msg="An error occurred while handling a request" code=404 details="[]" error=": Not found" reason= request-id= status= trace="Stack trace: \ngithub.com/ory/hydra/jwk.(SQLManager).GetKey\n\t/go/src/github.com/ory/hydra/jwk/manager_sql.go:139\ngithub.com/ory/hydra/jwk.(Handler).GetKey\n\t/go/src/github.com/ory/hydra/jwk/handler.go:208\ngithub.com/ory/hydra/jwk.(Handler).GetKey-fm\n\t/go/src/github.com/ory/hydra/jwk/handler.go:68\ngithub.com/ory/hydra/vendor/github.com/julienschmidt/httprouter.(Router).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter/router.go:299\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.Wrap.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:41\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\ngithub.com/ory/hydra/cmd/server.(Handler).rejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:201\ngithub.com/ory/hydra/cmd/server.(Handler).(github.com/ory/hydra/cmd/server.rejectInsecureRequests)-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:114\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus.(Middleware).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus/middleware.go:136\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/metrics.(MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/middleware.go:183\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33\ngithub.com/ory/hydra/vendor/github.com/urfave/negroni.(Negroni).ServeHTTP\n\t/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:73\ngithub.com/ory/hydra/vendor/github.com/rs/cors.(Cors).Handler.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/rs/cors/cors.go:200\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\ngithub.com/ory/hydra/vendor/github.com/gorilla/context.ClearHandler.func1\n\t/go/src/github.com/ory/hydra/vendor/github.com/gorilla/context/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2619\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1801\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:2337" writer=JSON hydra_1 | time="2018-03-01T12:54:33Z" level=info msg="completed handling request" measure#http://localhost:4444.latency=6412805 method=GET remote="172.18.0.4:39804" request="/keys/oathkeeper:id-token-2/private" status=404 text_status="Not Found" took=6.412805ms

[aeneasr]

Could you show the oathkeeper logs please?

[taland]

oathkeeper_1 | time="2018-03-01T12:54:33Z" level=info msg="Listening on :4456.\n" oathkeeper_1 | time="2018-03-01T12:54:33Z" level=info msg="Listening on :4455.\n" oathkeeper_1 | time="2018-03-01T12:54:39Z" level=error msg="Unable to refresh RSA keys for JWK signing" error="Expected status code 200 but got 500" retry=0

[aeneasr]

This is really confusing, it shows 500 in the one log, 404 in the other..can you please include the complete logs (docker log <image>) for both services and add them to a gist?

[aeneasr]

Having one 404 error is expected by the way, oathkeeper looks for the key first - if it doesn't find it it creates the key

[taland]

Sure, please see the logs: https://gist.github.com/taland/83557a97dc9b7ff261354c4d55aa9a6c

Also I have added docker-compose.yml which I used for my test.

[aeneasr]

It seems like it fails initially, but then works, see:

hydra_1 | time="2018-03-01T13:19:36Z" level=info msg="Access granted" client_id=oathkeeper-client-2 request="&{[] [] { 2018-03-01 13:19:31.546919 +0000 +0000 0xc42014e100 [hydra.introspect hydra.warden hydra.keys.] [hydra.introspect hydra.warden hydra.keys.] map[grant_type:[client_credentials] scope:[hydra.introspect hydra.warden hydra.keys.]] 0xc42017e0d0}}" result="&{oathkeeper-client-2 [hydra.introspect hydra.warden hydra.keys.] http://localhost:4444 oathkeeper-client-2 2018-03-01 13:19:31.546919 +0000 +0000 2018-03-01 14:19:31.629293766 +0000 UTC map[]}" subject=oathkeeper-client-2 hydra_1 | time="2018-03-01T13:19:36Z" level=info msg="completed handling request" measure#http://localhost:4444.latency=8591802 method=GET remote="172.18.0.4:39862" request="/keys/oathkeeper:id-token-2/private" status=200 text_status=OK took=8.591802ms

Also, it does not seem like oathkeeper fails again. What issue are you facing exactly?

[taland]

Yeah, right. Now it sorted. Thank you for your help with the policy definition.

[aeneasr]

It would be awesome if you could update the docs - they are located here: https://github.com/ory/oathkeeper/tree/master/docs

Thank you! Keeping this issue open until docs are improved

[taland]

Sure.