Library requesting OAuth 2 token endpoint twice during callback

[cburmeister]

We're using Hydra as our Identity Provider. In our scenario -- somewhere during the callback you can see that this library is requesting our token endpoint a second time which causes the provider to return a 400:

hydra-86bc4bd495-g594p hydra {"level":"info","method":"POST","msg":"started handling request","remote":"10.22.10.132:36366","request":"/oauth2/token","time":"2019-11-21T21:24:29Z"}
hydra-86bc4bd495-g594p hydra {"level":"info","measure#hydra/public: https://accounts.staging.discogs.com/.latency":380633105,"method":"POST","msg":"completed handling request","remote":"10.22.10.132:36366","request":"/oauth2/token","status":200,"text_status":"OK","time":"2019-11-21T21:24:30Z","took":380633105}
[...]
hydra-86bc4bd495-g594p hydra {"level":"info","method":"GET","msg":"started handling request","remote":"10.22.10.132:36374","request":"/.well-known/jwks.json","time":"2019-11-21T21:24:30Z"}
hydra-86bc4bd495-g594p hydra {"level":"info","measure#hydra/public: https://accounts.staging.discogs.com/.latency":11210835,"method":"GET","msg":"completed handling request","remote":"10.22.10.132:36374","request":"/.well-known/jwks.json","status":200,"text_status":"OK","time":"2019-11-21T21:24:30Z","took":11210835}
[...]
hydra-86bc4bd495-g594p hydra {"level":"info","method":"POST","msg":"started handling request","remote":"10.22.10.132:37056","request":"/oauth2/token","time":"2019-11-21T21:25:00Z"}
hydra-86bc4bd495-g594p hydra {"description":"The provided authorization grant (e.g., authorization code, resource owner credentials) or refresh token is invalid, expired, revoked, does not match the redirection URI used in the authorization request, or was issued to another client","error":"invalid_grant","hint":"The authorization code has already been used.","level":"error","msg":"An error occurred","time":"2019-11-21T21:25:00Z"}
hydra-86bc4bd495-g594p hydra {"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*AuthorizeExplicitGrantHandler).HandleTokenEndpointRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.30.0/handler/oauth2/flow_authorize_code_token.go:70\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.30.0/access_request_handler.go:89\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:548\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2007\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2007\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/go/src/github.com/ory/hydra/x/tls_termination.go:55\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/ory/x/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.73/metricsx/middleware.go:261\ngithub.com/urfave/negroni.middleware.ServeHTTP\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/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\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2802\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1890\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357","time":"2019-11-21T21:25:00Z"}
hydra-86bc4bd495-g594p hydra {"level":"info","measure#hydra/public: https://accounts.staging.discogs.com/.latency":165936318,"method":"POST","msg":"completed handling request","remote":"10.22.10.132:37056","request":"/oauth2/token","status":400,"text_status":"Bad Request","time":"2019-11-21T21:25:00Z","took":165936318}

It's obvious why the second request to the endpoint failed, the authorization code has already been used to obtain a token... I just can't determine why the library isn't returning a 302 during the callback as it should but instead attempting to request the token endpoint a second time.

Here's our settings.py:

LOGIN_REDIRECT_URL = '/labels'
LOGIN_REDIRECT_URL_FAILURE = '/'
LOGOUT_REDIRECT_URL = '/'
OIDC_OP_AUTHORIZATION_ENDPOINT = os.environ['OIDC_OP_AUTHORIZATION_ENDPOINT']
OIDC_OP_JWKS_ENDPOINT = os.environ['OIDC_OP_JWKS_ENDPOINT']
OIDC_OP_TOKEN_ENDPOINT = os.environ['OIDC_OP_TOKEN_ENDPOINT']
OIDC_OP_USER_ENDPOINT = os.environ['OIDC_OP_USER_ENDPOINT']
OIDC_RP_CLIENT_ID = os.environ['OIDC_RP_CLIENT_ID']
OIDC_RP_CLIENT_SECRET = os.environ['OIDC_RP_CLIENT_SECRET']
OIDC_RP_SCOPES = 'openid offline'
OIDC_RP_SIGN_ALGO = 'RS256'
OIDC_STORE_ID_TOKEN = True
OIDC_TOKEN_USE_BASIC_AUTH = True

Any help would be appreciated!

[pkimber]

I just had the same issue, but it just went away. No idea why :cry:

[cburmeister]

Turns out this was due to a misconfiguration on our end, the downstream the client was unable to reach our OAuth server when trying to access the /userinfo endpoint.