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

504 Timeout when refreshing token #1295

Closed
paulrostorp opened this issue Feb 28, 2019 · 14 comments
Closed

504 Timeout when refreshing token #1295

paulrostorp opened this issue Feb 28, 2019 · 14 comments

Comments

@paulrostorp
Copy link

paulrostorp commented Feb 28, 2019

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:
- name: LOG_LEVEL
value: "debug"
- name: OAUTH2_SHARE_ERROR_DEBUG
value: "true"
- name: ACCESS_TOKEN_LIFESPAN
value: 2m
- name: CORS_ENABLED
value: "true"
- name: CORS_ALLOWED_ORIGINS
value: ""
- name: CORS_ALLOWED_HEADERS
value: "Origin,X-Requested-With,Content-Type,Accept,authorization"
- name: HTTPS_ALLOW_TERMINATION_FROM
value: 10.244.0.0/16
- name: OAUTH2_ISSUER_URL
value: https://oauth2.polluxis.me/
- name: OAUTH2_CONSENT_URL
value: https://auth.polluxis.me/consent
- name: OAUTH2_LOGIN_URL
value: https://auth.polluxis.me/login
- name: DATABASE_URL
value: postgres://
**?sslmode=disable
- name: SYSTEM_SECRET
value: **

@aeneasr
Copy link
Member

aeneasr commented Feb 28, 2019

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
Copy link
Member

aeneasr commented Mar 1, 2019

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

@paulrostorp
Copy link
Author

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
Copy link
Member

aeneasr commented Mar 1, 2019

Can you include more log info please?

@aeneasr
Copy link
Member

aeneasr commented Mar 1, 2019

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
Copy link
Member

aeneasr commented Mar 1, 2019

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

@paulrostorp
Copy link
Author

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
Copy link
Member

aeneasr commented Mar 1, 2019

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
Copy link
Author

paulrostorp commented Mar 1, 2019

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
Copy link
Member

aeneasr commented Mar 1, 2019

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
Copy link
Author

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
Copy link
Member

aeneasr commented Mar 1, 2019

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.

@aeneasr aeneasr closed this as completed Mar 1, 2019
@paulrostorp
Copy link
Author

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
Copy link
Member

aeneasr commented Mar 6, 2019

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 :)

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

2 participants