search

ory / hydra

The most scalable and customizable OpenID Certified™ OpenID Connect and OAuth Provider on the market. Become an OpenID Connect and OAuth2 Provider over night. Broad support for related RFCs. Written in Go, cloud native, headless, API-first. Available as a service on Ory Network and for self-hosters.
https://www.ory.sh/?utm_source=github&utm_medium=banner&utm_campaign=hydra
Apache License 2.0
15.5k stars 1.49k forks source link

504 Timeout when refreshing token #1295

Closed paulrostorp closed 5 years ago

paulrostorp commented 5 years ago

I am calling my refresh token function in the background (from inside cluster) and getting gateway timeout error. This function works and successfully refreshes the token when running outside my cluster. Note that I am terminating TLS at the edge and have configured hydra properly I believe (using HTTPS_ALLOW_TERMINATION_FROM environment variable). Anyways I get the following error:

{ HTTPError: Response code 504 (Gateway Timeout)
    at stream.catch.then.data (/usr/src/app/node_modules/got/index.js:386:13)
    at process._tickCallback (internal/process/next_tick.js:68:7)
  name: 'HTTPError',
  host: 'oauth2.polluxis.me',
  hostname: 'oauth2.polluxis.me',
  method: 'POST',
  path: '/oauth2/token',
  protocol: 'https:',
  url: 'https://oauth2.polluxis.me/oauth2/token',
  statusCode: 504,
  statusMessage: 'Gateway Timeout',
  headers:
   { 'content-length': '24',
     'content-type': 'text/plain',
     date: 'Thu, 28 Feb 2019 17:17:22 GMT',
     server: 'envoy',
     connection: 'close' } }

Meanwhile the hydra pod logs

time="2019-03-01T09:25:51Z" level=debug msg="Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).PopulateTokenEndpointResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/handler/oauth2/flow_refresh.go:129\ngithub.com/ory/fosite.(*Fosite).NewAccessResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/access_response_writer.go:36\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:572\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:172\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/router.go:334\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:297\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:62\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1333"
time="2019-03-01T09:25:51Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=3192799314 method=POST remote="10.244.92.0:43498" request=/oauth2/token request_id=a46b771e-2c47-42b4-9a38-b7acc4c33709 status=500 text_status="Internal Server Error" took=3.192799314s
time="2019-02-28T17:17:24Z" level=error msg="An error occurred" debug="context canceled" description="The authorization server encountered an unexpected condition that prevented it from fulfilling the request" error=server_error

What does the "context cancelled" mean ? How should I go about debugging this ?

Kubernetes: v1.12.2 Hydra: oryd/hydra:v1.0.0-rc.6_oryOS.10 DB: Postgres

Environment variables:

aeneasr commented 5 years ago

Please use the issue form, they are there for a reason. Without info on which version, database and all other relevant pieces this will be closed as invalid.

aeneasr commented 5 years ago

Also, please include some tracing information. You can usually enable tracing by setting the environment variable LOG_LEVEL=debug

paulrostorp commented 5 years ago

I was able to trace the error:

time="2019-03-01T09:25:51Z" level=debug msg="Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).PopulateTokenEndpointResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/handler/oauth2/flow_refresh.go:129\ngithub.com/ory/fosite.(*Fosite).NewAccessResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/access_response_writer.go:36\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:572\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:172\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/router.go:334\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:297\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:62\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1333"
aeneasr commented 5 years ago

Can you include more log info please?

aeneasr commented 5 years ago

Keep in mind that the more info you give, the easier it is to solve your issue. Redacting stuff doesn't help and there's also no sensible reason why it should be redacted as sensitive information is kept out of logs.

aeneasr commented 5 years ago

Please also include your configuration, here you can obviously redact info like system secrets etc.

paulrostorp commented 5 years ago

I updated the initial post. I had only removed the hostname but now you have it. Keep in mind everything works perfectly except refreshing the token in the background, which I do using "openid-client" node.js package (https://github.com/panva/node-openid-client) from my external authentication service through ambassador. Is there any other information you might need ?

aeneasr commented 5 years ago

Thank you for providing more info, that is really helpful. It doesn't seem like you have tracing enabled which might have caused this otherwise. Are you seeing any issues in the PostgreSQL logs?

Also could you please provide logs -+10 lines around the error?

Including @aaslamin in the convo: This seems to be related to passing down the context from *http.Request. Any ideas what could cause this?

paulrostorp commented 5 years ago

From the code in my Authservice the only error I get is the gateway timeout error from openid-client (which I get several times, which I assume is because of automatic retries from the library). However here are the headers of the incoming request :

Headers:  { host: 'polluxis.me',
  'content-length': '189',
  'x-forwarded-for': '91.151.49.42, 127.0.0.1,10.135.139.91,10.244.92.6',
  'x-forwarded-proto': 'https',
  'user-agent':
   'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.119 Safari/537.36',
  cookie:
   'connect.sid=s%3AwwXH4FMkyLIMbZR6D8oKrDQghRSo-hHy.yDVsXzd3LK4xy8IkzXUct3J83LoYFIfIz4ORuTRXPuo; openid=eyJhbGciOiJSUzI1NiIsImtpZCI6InB1YmxpYzo3MjlkNTJiZi02M2RiLTRhZTgtYjkwMC1hMTZkZmZiMTY3ODAiLCJ0eXAiOiJKV1QifQ.eyJhdF9oYXNoIjoiN2V3dVpQa08yeVJWbGJQdF9NeVN0dyIsImF1ZCI6WyIzNjZjZWIwNC03NTg1LTRiNzktODQ1ZC1iMzUyMjAzMjc5OWUiXSwiYXV0aF90aW1lIjoxNTUxNDMyMTYwLCJleHAiOjE1NTE0Mzc4NjYsImlhdCI6MTU1MTQzNDI2NiwiaXNzIjoiaHR0cHM6Ly9vYXV0aDIucG9sbHV4aXMubWUvIiwianRpIjoiYzIyOGU5NTQtZWJlNC00MGFmLTkyOWMtOGE2MDJhMTEyMjJlIiwibm9uY2UiOiIiLCJyYXQiOjE1NTE0MzQyNjAsInN1YiI6IjVjMzVjNzdjOTc2ZjA3NDk3YTRkYmU2MiJ9.SPvlydCbNuCOLBia-pK835RZ5brCba60WRP1yQTQnGJ_2sULzqOsEOVWLX8VRfemUqxC2JdsUbxzjLt5yT77qY0g6LO6Pe3BHi5MUshdiwD2DhBrKX9gFVvxLuZfytfHNTmNRwOVkpG8vzwoOHlCUQxu36Q27AhSBxEaxnik9JxrPTPGV1rL7PJ4QGVq6m4sQWff8EKCZNXF2CipBo38eILcXrdvtXT7t8qD5Y3gj9tQ_Bnuh6zu5hbeA9ralAmWYtFGxT8vSSRXCbLcyzmBOyvHTMMTOy2gN_38Xs2zhI9oK-LRYNFO-8rI1an1MxxrtuJ3_KySq8M9Wb9wOKM0LZJpv7XKk3WcLwUjj0aWfgMSSMRP3HyMfzxuI8oUCMDQHIZHfRALFZ5HSx87egarUX0kUP_1dQ0iWHjN-iCG5kjchl0NsSLiv9zjOyhjcppcTeTlAXwaDDuse8QAE5TnGKo7O900wZuQbGnBzSKx3yviU1hJHstC9k_ZOUO2ZLlCb8wc-7YYaKjB4-6OP8kfW-NdrJMHOngXaL_47WAI0lxyYPGhK77AkKkBuTiN2gG2flj_88LgLyZ6hcr6McehM7-ubyVWwv3ZqDShPeWHuKAfhTLqbrM836QsNUwKC1v3QBJPW8XiBCIUKm_xjCxWAhV0Phh6tzFo-QXLvIAcPOI',
  'x-envoy-internal': 'true',
  'x-envoy-expected-rq-timeout-ms': '5000' }

Here is a more complete log of the hydra pod, as you can see the error occurs 5 times from 5 simultaneous calls:

time="2019-03-01T09:57:47Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=45610597 method=GET remote="10.244.5.5:53290" request=/.well-known/jwks.json request_id=be0fec60-fae6-4512-b6a3-01eb6347285f status=200 text_status=OK took=45.610597ms
time="2019-03-01T09:57:47Z" level=info msg="started handling request" method=GET remote="10.244.92.0:54476" request=/userinfo request_id=22fd24fa-8e37-4a72-b153-2cc632f86cf2
time="2019-03-01T09:57:47Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=90443026 method=GET remote="10.244.92.0:54476" request=/userinfo request_id=22fd24fa-8e37-4a72-b153-2cc632f86cf2 status=200 text_status=OK took=90.443026ms
time="2019-03-01T10:03:12Z" level=info msg="started handling request" method=POST remote="10.244.92.0:56390" request=/oauth2/token request_id=00b257f0-a29e-444c-8410-5a5c082b204a
time="2019-03-01T10:03:12Z" level=info msg="started handling request" method=POST remote="10.244.5.5:55476" request=/oauth2/token request_id=81c5bb85-8557-4683-b26d-658b873291ba
time="2019-03-01T10:03:12Z" level=info msg="started handling request" method=POST remote="10.244.5.6:48620" request=/oauth2/token request_id=7ea6fd23-b30f-4459-abf6-819c2ccde087
time="2019-03-01T10:03:12Z" level=info msg="started handling request" method=POST remote="10.244.5.5:55480" request=/oauth2/token request_id=bc02654b-d9ab-4d8c-aa15-8b845b97af1b
time="2019-03-01T10:03:12Z" level=info msg="started handling request" method=POST remote="10.244.5.5:55482" request=/oauth2/token request_id=4272ce6c-98ce-486e-b44a-324a5c25647e
time="2019-03-01T10:03:16Z" level=error msg="An error occurred" debug="context canceled" description="The authorization server encountered an unexpected condition that prevented it from fulfilling the request" error=server_error
time="2019-03-01T10:03:16Z" level=debug msg="Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).PopulateTokenEndpointResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/handler/oauth2/flow_refresh.go:129\ngithub.com/ory/fosite.(*Fosite).NewAccessResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/access_response_writer.go:36\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:572\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:172\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/router.go:334\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:297\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:62\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1333"
time="2019-03-01T10:03:16Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=3945804798 method=POST remote="10.244.92.0:56390" request=/oauth2/token request_id=00b257f0-a29e-444c-8410-5a5c082b204a status=500 text_status="Internal Server Error" took=3.945804798s
time="2019-03-01T10:03:16Z" level=error msg="An error occurred" debug="context canceled" description="The authorization server encountered an unexpected condition that prevented it from fulfilling the request" error=server_error
time="2019-03-01T10:03:16Z" level=debug msg="Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).HandleTokenEndpointRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/handler/oauth2/flow_refresh.go:66\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/access_request_handler.go:89\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:535\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:172\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/router.go:334\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:297\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:62\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1333"
time="2019-03-01T10:03:16Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=4435322103 method=POST remote="10.244.5.5:55476" request=/oauth2/token request_id=81c5bb85-8557-4683-b26d-658b873291ba status=500 text_status="Internal Server Error" took=4.435322103s
time="2019-03-01T10:03:16Z" level=error msg="An error occurred" debug="context canceled" description="The authorization server encountered an unexpected condition that prevented it from fulfilling the request" error=server_error
time="2019-03-01T10:03:16Z" level=debug msg="Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).HandleTokenEndpointRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/handler/oauth2/flow_refresh.go:66\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/access_request_handler.go:89\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:535\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:172\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/router.go:334\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:297\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:62\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1333"
time="2019-03-01T10:03:16Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=4525815836 method=POST remote="10.244.5.5:55480" request=/oauth2/token request_id=bc02654b-d9ab-4d8c-aa15-8b845b97af1b status=500 text_status="Internal Server Error" took=4.525815836s
time="2019-03-01T10:03:16Z" level=error msg="An error occurred" debug="context canceled" description="The authorization server encountered an unexpected condition that prevented it from fulfilling the request" error=server_error
time="2019-03-01T10:03:16Z" level=debug msg="Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).HandleTokenEndpointRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/handler/oauth2/flow_refresh.go:66\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/access_request_handler.go:89\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:535\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:172\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/router.go:334\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:297\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:62\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1333"
time="2019-03-01T10:03:16Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=4718861143 method=POST remote="10.244.5.5:55482" request=/oauth2/token request_id=4272ce6c-98ce-486e-b44a-324a5c25647e status=500 text_status="Internal Server Error" took=4.718861143s
time="2019-03-01T10:03:17Z" level=error msg="An error occurred" debug="context canceled" description="The authorization server encountered an unexpected condition that prevented it from fulfilling the request" error=server_error
time="2019-03-01T10:03:17Z" level=debug msg="Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).PopulateTokenEndpointResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/handler/oauth2/flow_refresh.go:129\ngithub.com/ory/fosite.(*Fosite).NewAccessResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.28.0/access_response_writer.go:36\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:572\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:172\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v0.0.0-20180715161854-348b672cd90d/router.go:334\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:297\ngithub.com/ory/hydra/cmd/server.(*Handler).RejectInsecureRequests-fm\n\t/go/src/github.com/ory/hydra/cmd/server/handler.go:62\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.middleware.ServeHTTP-fm\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1333"
time="2019-03-01T10:03:17Z" level=info msg="completed handling request" measure#https://oauth2.polluxis.me/.latency=4890533254 method=POST remote="10.244.5.6:48620" request=/oauth2/token request_id=7ea6fd23-b30f-4459-abf6-819c2ccde087 status=500 text_status="Internal Server Error" took=4.890533254s

I unfortunately cannot provide postgre logs as I am using a external hosted service which doesn't provide me with logs. If necessary, I can setup a local instance and get the logs.

aeneasr commented 5 years ago

Ok, it seems like this request is taking a long time to execute - over 4 seconds! That's probably why it's being canceled. This could be an issue with your PostgreSQL database, missing indices or something else. Could you check if there are slow queries? You can also set up tracing in Hydra to debug this: https://www.ory.sh/docs/hydra/debugging#distributed-tracing

paulrostorp commented 5 years ago

The sql query call does take some time but not as much as the bcrypt function...

screenshot 2019-03-01 at 13 00 52 This time it doesn't even make it past the bcrypt call

screenshot 2019-03-01 at 12 44 48

When I trigger the refresh token method from a client outside the cluster ( through dummy express function) it looks like this: screenshot 2019-03-01 at 13 04 45

I'll setup another pg setup so I can look at the logs

aeneasr commented 5 years ago

BCrypt is supposed to take some time but obviously 3 seconds is too much. Maybe beef up the VM you're running hydra on? But it seems in general that the system is quite laggish - 1.5s for a SQL call is way too much.

I'm closing this issue because we know now that it is caused by a timeout as opposed to a bug. Feel free to post here though in case you have new findings.

paulrostorp commented 5 years ago

Just for reference, it would seem like the timeout issue was only a symptom of the real problem, which was that my background function was calling the openid-client refresh token method multiple times (which I mistook for the retry mechanism of the library). Regardless this issue was not directly related to hydra. Thank you @aeneasr for your aid in helping me track down the issue.

aeneasr commented 5 years ago

I see! It's probably still a good idea to beef up the system a bit in case you'll end up with multiple calls to that endpoint :)