oauth2: Duplicate requests to /oauth2/token cause 500

[jshearer]

When writing a client that interacts with Hydra, I accidentally made 2 requests to exchange my authorization code for a refresh/access/id token instead of just one. One of the requests (not always the second -- I suspect this has something to do with database racing or something?) will 500 while the other will happily return the correct info.

The exception is here:

github.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2.(*AuthorizeExplicitGrantHandler).PopulateTokenEndpointResponse
	/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2/flow_authorize_code_token.go:113
github.com/ory/hydra/vendor/github.com/ory/fosite.(*Fosite).NewAccessResponse
	/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/access_response_writer.go:36
github.com/ory/hydra/oauth2.(*Handler).TokenHandler
	/go/src/github.com/ory/hydra/oauth2/handler.go:380
github.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm
	/go/src/github.com/ory/hydra/oauth2/handler.go:118
github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter.(*Router).ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter/router.go:299
github.com/ory/hydra/vendor/github.com/urfave/negroni.Wrap.func1
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:41
github.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33
github.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33
net/http.HandlerFunc.ServeHTTP
	/usr/local/go/src/net/http/server.go:1918
github.com/ory/hydra/cmd/server.(*Handler).rejectInsecureRequests
	/go/src/github.com/ory/hydra/cmd/server/handler.go:205
github.com/ory/hydra/cmd/server.(*Handler).(github.com/ory/hydra/cmd/server.rejectInsecureRequests)-fm
	/go/src/github.com/ory/hydra/cmd/server/handler.go:113
github.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33
github.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33
github.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus/middleware.go:136
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33
github.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33
github.com/ory/hydra/metrics.(*MetricsManager).ServeHTTP
	/go/src/github.com/ory/hydra/metrics/middleware.go:172
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33
github.com/ory/hydra/vendor/github.com/urfave/negroni.(*Negroni).ServeHTTP
	/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:73
github.com/ory/hydra/vendor/github.com/rs/cors.(*Cors).Handler.func1
	/go/src/github.com/ory/hydra/vendor/github.com/rs/cors/cors.go:200
net/http.HandlerFunc.ServeHTTP
	/usr/local/go/src/net/http/server.go:1918
github.com/ory/hydra/vendor/github.com/gorilla/context.ClearHandler.func1
	/go/src/github.com/ory/hydra/vendor/github.com/gorilla/context/context.go:141
net/http.HandlerFunc.ServeHTTP
	/usr/local/go/src/net/http/server.go:1918
net/http.serverHandler.ServeHTTP
	/usr/local/go/src/net/http/server.go:2619
net/http.(*conn).serve
	/usr/local/go/src/net/http/server.go:1801
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:2337

Logs from around the event:

time="2018-04-27T01:35:39Z" level=info msg="started handling request" method=POST remote=8.41.64.211 request=/oauth2/token
time="2018-04-27T01:35:39Z" level=info msg="started handling request" method=POST remote=8.41.64.211 request=/oauth2/token
time="2018-04-27T01:35:39Z" level=error msg="An error occurred" debug=": not_found" error=server_error
time="2018-04-27T01:35:39Z" level=debug msg="Stack trace: \ngithub.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2.(*AuthorizeExplicitGrantHandler).PopulateTokenEndpointResponse\n\t/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2/flow_authorize_code_token.go:113\ngithub.com/ory/hydra/vendor/github.com/ory/fosite.(*Fosite).NewAccessResponse\n\t/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/access_response_writer.go:36\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:380\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:118\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:205\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:172\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"
time="2018-04-27T01:35:39Z" level=info msg="completed handling request" measure#https://<domain>.latency=529915858 method=POST remote=8.41.64.211 request=/oauth2/token status=500 text_status="Internal Server Error" took=529.915858ms
time="2018-04-27T01:35:40Z" level=info msg="completed handling request" measure#https://<domain>.latency=816992976 method=POST remote=8.41.64.211 request=/oauth2/token status=200 text_status=OK took=816.992976ms

This took a while to debug, but once I saw the duplicate requests, I knew that's what it had to be.

I guess this should be a 400 indicating that the authorization code has already been redeemed?

[aeneasr]

Thank you for reporting the issue, it should definitely be a 400 Bad Request response.

Which version are you on?

[aeneasr]

This is resolved on master