oauth2: investigate panic #512

aeneasr · 2017-06-13T11:34:41Z

No description provided.

k-zaher · 2017-06-13T11:38:16Z

Here is the log I get (maybe could help)

INFO[0012] started handling request                      method=POST remote="[::1]:58879" request="/oauth2/token"
2017/06/13 12:55:51 http: panic serving [::1]:58879: runtime error: invalid memory address or nil pointer dereference
goroutine 15 [running]:
net/http.(*conn).serve.func1(0xc4202bcc80)
    /usr/local/opt/go/libexec/src/net/http/server.go:1721 +0xd0
panic(0x162f3a0, 0x1a01680)
    /usr/local/opt/go/libexec/src/runtime/panic.go:489 +0x2cf
github.com/ory/hydra/vendor/github.com/ory/fosite/handler/openid.(*DefaultSession).SetExpiresAt(0x0, 0x16deaad, 0xc, 0xed0d1c9c7, 0xc408ea2c87, 0x1a1cb00)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/handler/openid/strategy_jwt.go:55 +0x26
github.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).HandleTokenEndpointRequest(0xc4202ca500, 0x19d8e80, 0xc420014270, 0x19dcaa0, 0xc4200a5760, 0x19d0f00, 0xc4204141e0)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2/flow_refresh.go:66 +0x68c
github.com/ory/hydra/vendor/github.com/ory/fosite.(*Fosite).NewAccessRequest(0xc4202ee090, 0x19d8e80, 0xc420014270, 0xc420410400, 0x19da0a0, 0xc4204030b0, 0xc, 0x22, 0x6, 0x15f7740)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/access_request_handler.go:78 +0x409
github.com/ory/hydra/oauth2.(*Handler).TokenHandler(0xc4202f93b0, 0x300c128, 0xc4203f3440, 0xc420410400, 0x0, 0x0, 0x0)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/oauth2/handler.go:261 +0x179
github.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm(0x300c128, 0xc4203f3440, 0xc420410400, 0x0, 0x0, 0x0)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/oauth2/handler.go:106 +0x66
github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter.(*Router).ServeHTTP(0xc420288e10, 0x300c128, 0xc4203f3440, 0xc420410400)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter/router.go:299 +0x750
github.com/ory/hydra/vendor/github.com/urfave/negroni.Wrap.func1(0x300c128, 0xc4203f3440, 0xc420410400, 0xc420404880)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:41 +0x4d
github.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP(0xc4202d3580, 0x300c128, 0xc4203f3440, 0xc420410400, 0xc420404880)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24 +0x4e
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP(0x19d31c0, 0xc4202d3580, 0xc4202d35e0, 0x300c128, 0xc4203f3440, 0xc420410400)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33 +0xb4
github.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm(0x300c128, 0xc4203f3440, 0xc420410400)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33 +0x60
net/http.HandlerFunc.ServeHTTP(0xc420404860, 0x300c128, 0xc4203f3440, 0xc420410400)
    /usr/local/opt/go/libexec/src/net/http/server.go:1942 +0x44
github.com/ory/hydra/cmd/server.(*Handler).rejectInsecureRequests(0xc42026ecd0, 0x300c128, 0xc4203f3440, 0xc420410400, 0xc420404860)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/cmd/server/handler.go:143 +0x65
github.com/ory/hydra/cmd/server.(*Handler).(github.com/ory/hydra/cmd/server.rejectInsecureRequests)-fm(0x300c128, 0xc4203f3440, 0xc420410400, 0xc420404860)
    /Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/cmd/server/handler.go:58 +0x52
github.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP(0xc4202d18b0, 0x300c128, 0xc4203f3440, 0xc420410400, 0xc420404860)

aeneasr · 2017-06-13T11:38:54Z

Looks like the session isn't properly instantiated, I'll write a failing test case first

aeneasr · 2017-06-13T13:50:18Z

@kimooz are you using the SQL backend?

k-zaher · 2017-06-13T13:51:06Z

Yes a Postgres DB

aeneasr · 2017-06-13T13:51:34Z

Ok because I just tried to write a failing test case for this using the memory manager and it didn't result in an error.

aeneasr · 2017-06-13T14:06:26Z

What hydra version are you on? How are you starting the image? Is this a fork? Are you by any chance working together with @wyattanderson ?

I can't reproduce this issue with the demo set up, refreshing a refresh token works totally fine here.

To resolve this, I need to know what you're doing. Please give as much detail as possible.

aeneasr · 2017-06-13T14:06:57Z

Proof that this works (latest master):

aeneasr · 2017-06-13T14:14:44Z

@kimooz can you please include at least 10 lines of the log before the panic?

k-zaher · 2017-06-13T14:20:52Z

No I am not :)

I agree that it works because this only happened to me twice in 3 weeks!

I will attach more info once it happen again

sorry :s

aeneasr · 2017-06-13T14:21:52Z

@kimooz do you have a custom consent endpoint? Is this endpoint setting, for example, id token or access token data?

wyattanderson · 2017-06-13T14:32:20Z

We're not working together, but this is the same stack trace I was seeing. I haven't yet had time to put together a reproducer, but my setup:

Using a PostgreSQL DB
Using a custom consent endpoint

aeneasr · 2017-06-13T14:35:31Z

@wyattanderson are you setting id_ext or at_ext?

k-zaher · 2017-06-13T14:36:21Z

only id_ext for me

aeneasr · 2017-06-13T15:15:12Z

@kimooz is id_ext always set? e.g. are all requests openid connect?

k-zaher · 2017-06-13T15:17:26Z

Yes all requests with authorization flow uses openid scope and the consent includes id_ext

aeneasr · 2017-06-13T15:19:06Z

Ok so it's improbable that this is the root cause of the issue, because if it was, the error would happen more frequently, right?

k-zaher · 2017-06-13T15:21:25Z

The Error happens if the access token is expired and I am using the refresh token endpoint to refresh it. However if the Access Token is still valid I can refresh without any errors!

aeneasr · 2017-06-13T15:22:24Z

Are you by any chance flushing expired access tokens from the database?

k-zaher · 2017-06-13T15:23:56Z

No I don't, Didn't know that Hydra already provides a tool for that :)

aeneasr · 2017-06-13T15:25:06Z

It doesn't, just trying to narrow the scope ;)

aeneasr · 2017-06-14T08:06:39Z

kimooz @wyattanderson if this happens again, could you please share the log + ~50 previous lines, plus (if possible) the payload of the consent response? This is now blocking for the 1.0.0 release because panics are not nice.

k-zaher · 2017-06-14T13:21:43Z

@arekkas It just happened again!!

INFO[3922] started handling request                      method=POST remote="[::1]:58964" request="/oauth2/introspect"
ERRO[3922] An error occurred                             error="Validator returned error A validator returned an error: Token expired: Token is inactive because it is malformed, expired or otherwise invalid"
INFO[3922] completed handling request                    measure#hydra.localhost.latency=4023782 method=POST remote="[::1]:58964" request="/oauth2/introspect" status=200 text_status=OK took=4.023782ms
INFO[3922] started handling request                      method=POST remote="[::1]:58965" request="/oauth2/token"
2017/06/14 15:19:16 http: panic serving [::1]:58965: runtime error: invalid memory address or nil pointer dereference
goroutine 1032 [running]:
net/http.(*conn).serve.func1(0xc4202ba460)
	/usr/local/opt/go/libexec/src/net/http/server.go:1721 +0xd0
panic(0x162f3a0, 0x1a01680)
	/usr/local/opt/go/libexec/src/runtime/panic.go:489 +0x2cf
github.com/ory/hydra/vendor/github.com/ory/fosite/handler/openid.(*DefaultSession).SetExpiresAt(0x0, 0x16deaad, 0xc, 0xed0d33ce4, 0xc41d00f6d3, 0x1a1cb00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/handler/openid/strategy_jwt.go:55 +0x26
github.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).HandleTokenEndpointRequest(0xc420249e40, 0x19d8e80, 0xc420014270, 0x19dcaa0, 0xc42048a0b0, 0x19d0f00, 0xc4203d0380)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/handler/oauth2/flow_refresh.go:66 +0x68c
github.com/ory/hydra/vendor/github.com/ory/fosite.(*Fosite).NewAccessRequest(0xc42008ef30, 0x19d8e80, 0xc420014270, 0xc4204f6c00, 0x19da0a0, 0xc4205021a0, 0xf52, 0x22, 0x6, 0x15f7740)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/ory/fosite/access_request_handler.go:78 +0x409
github.com/ory/hydra/oauth2.(*Handler).TokenHandler(0xc42024d680, 0x1f84000, 0xc42049e100, 0xc4204f6c00, 0x0, 0x0, 0x0)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/oauth2/handler.go:261 +0x179
github.com/ory/hydra/oauth2.(*Handler).TokenHandler-fm(0x1f84000, 0xc42049e100, 0xc4204f6c00, 0x0, 0x0, 0x0)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/oauth2/handler.go:106 +0x66
github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter.(*Router).ServeHTTP(0xc420288e10, 0x1f84000, 0xc42049e100, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/julienschmidt/httprouter/router.go:299 +0x750
github.com/ory/hydra/vendor/github.com/urfave/negroni.Wrap.func1(0x1f84000, 0xc42049e100, 0xc4204f6c00, 0xc4203d00e0)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:41 +0x4d
github.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP(0xc4202c1920, 0x1f84000, 0xc42049e100, 0xc4204f6c00, 0xc4203d00e0)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24 +0x4e
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP(0x19d31c0, 0xc4202c1920, 0xc4202c1980, 0x1f84000, 0xc42049e100, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33 +0xb4
github.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm(0x1f84000, 0xc42049e100, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33 +0x60
net/http.HandlerFunc.ServeHTTP(0xc4203d00c0, 0x1f84000, 0xc42049e100, 0xc4204f6c00)
	/usr/local/opt/go/libexec/src/net/http/server.go:1942 +0x44
github.com/ory/hydra/cmd/server.(*Handler).rejectInsecureRequests(0xc420270c30, 0x1f84000, 0xc42049e100, 0xc4204f6c00, 0xc4203d00c0)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/cmd/server/handler.go:143 +0x65
github.com/ory/hydra/cmd/server.(*Handler).(github.com/ory/hydra/cmd/server.rejectInsecureRequests)-fm(0x1f84000, 0xc42049e100, 0xc4204f6c00, 0xc4203d00c0)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/cmd/server/handler.go:58 +0x52
github.com/ory/hydra/vendor/github.com/urfave/negroni.HandlerFunc.ServeHTTP(0xc420304460, 0x1f84000, 0xc42049e100, 0xc4204f6c00, 0xc4203d00c0)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:24 +0x4e
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP(0x19d31c0, 0xc420304460, 0xc4202c1960, 0x1f84000, 0xc42049e100, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33 +0xb4
github.com/ory/hydra/vendor/github.com/urfave/negroni.(middleware).ServeHTTP-fm(0x1f84000, 0xc42049e100, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33 +0x60
github.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP(0xc4202999e0, 0x1f84000, 0xc42049e100, 0xc4204f6c00, 0xc4203d0040)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/meatballhat/negroni-logrus/middleware.go:135 +0x2a6
github.com/ory/hydra/vendor/github.com/urfave/negroni.middleware.ServeHTTP(0x19d0cc0, 0xc4202999e0, 0xc4202c1940, 0x1f84000, 0xc42049e100, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:33 +0xb4
github.com/ory/hydra/vendor/github.com/urfave/negroni.(*Negroni).ServeHTTP(0xc4203023f0, 0x19d8480, 0xc4203da000, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/urfave/negroni/negroni.go:73 +0x118
github.com/ory/hydra/vendor/github.com/gorilla/context.ClearHandler.func1(0x19d8480, 0xc4203da000, 0xc4204f6c00)
	/Users/kareemdiaa/BrickYard/go/src/github.com/ory/hydra/vendor/github.com/gorilla/context/context.go:141 +0x8b
net/http.HandlerFunc.ServeHTTP(0xc4202c19c0, 0x19d8480, 0xc4203da000, 0xc4204f6c00)
	/usr/local/opt/go/libexec/src/net/http/server.go:1942 +0x44
net/http.serverHandler.ServeHTTP(0xc4200a73f0, 0x19d8480, 0xc4203da000, 0xc4204f6c00)
	/usr/local/opt/go/libexec/src/net/http/server.go:2568 +0x92
net/http.(*conn).serve(0xc4202ba460, 0x19d8e40, 0xc420284200)
	/usr/local/opt/go/libexec/src/net/http/server.go:1825 +0x612
created by net/http.(*Server).Serve
	/usr/local/opt/go/libexec/src/net/http/server.go:2668 +0x2ce
INFO[3922] started handling request                      method=GET remote="[::1]:58966" request="/oauth2/auth?client_id=1505adc3-25b6-44ec-8df3-37eed603e7eb&nonce=5e5d5911c86bcbaa2f7479c20222fadc&redirect_uri=http%3A%2F%2Flocalhost%3A3000%2Foauth%2Fcallback&response_type=code&scope=openid+hydra+offline&state=0e4b84452e905255e8ef7d40d3206432"
INFO[3922] completed handling request                    measure#hydra.localhost.latency=63095130 method=GET remote="[::1]:58966" request="/oauth2/auth?client_id=1505adc3-25b6-44ec-8df3-37eed603e7eb&nonce=5e5d5911c86bcbaa2f7479c20222fadc&redirect_uri=http%3A%2F%2Flocalhost%3A3000%2Foauth%2Fcallback&response_type=code&scope=openid+hydra+offline&state=0e4b84452e905255e8ef7d40d3206432" status=302 text_status=Found took=63.09513ms

aeneasr · 2017-06-14T13:41:15Z

Thank you! Could you share the consent payload as well?

k-zaher · 2017-06-14T13:43:59Z

{
  jti:   decoded_challenge['jti'],
  aud: decoded_challenge['aud'],
  exp: decoded_challenge['exp'],
  scp: decoded_challenge['scp'],
  sub: user.uuid,
  iat: Time.now.to_i,
  id_ext: user.as_json,
  at_ext: {}
}

k-zaher · 2017-06-14T13:45:20Z

you are not asking for actual values right? :)

aeneasr · 2017-06-14T13:45:23Z

user.as_json is just some json object right?

k-zaher · 2017-06-14T13:46:39Z

yes it is just a normal json object

nothing special in it

aeneasr · 2017-06-16T09:54:04Z

I can not reproduce this. Please check that you have the most recent tag installed.

aeneasr · 2017-06-16T10:02:25Z

Since you're apparently on the latest version, please create a reproducible step-by-step guide that includes your whole environment (including consent app), otherwise it's just random guessing by me

k-zaher · 2017-06-16T13:31:39Z

Seems that the issue is caused by the id_ext. if the id_ext in the consent response contains a nested object like organisation in the following example

{
    "id"=>1,
    "first_name"=>"Kareem",
    "last_name"=>"Diaa",
    "email"=>"admin@admin.com",
    "organisation" => {"name" => "sdfsfsdf", "id" => "sdasdasd"}
}

The panic bug occurs and even more the refreshed access token loses the subject!

I am using Hydra 0.9.6 (complied from source) with PostgreSQL 9.6

Closes #512

aeneasr changed the title ~~oauth2: resolve refresh token issue~~ oauth2: investigate panic Jun 13, 2017

aeneasr added the bug Something is not working. label Jun 14, 2017

aeneasr added this to the 1.0.0: stable release milestone Jun 14, 2017

aeneasr self-assigned this Jun 14, 2017

aeneasr removed the bug Something is not working. label Jun 16, 2017

aeneasr removed this from the 1.0.0: stable release milestone Jun 16, 2017

aeneasr pushed a commit that referenced this issue Jun 17, 2017

oauth2: added failing test case for #512

97d169a

aeneasr pushed a commit that referenced this issue Jun 17, 2017

oauth2: resolve session issue with deep nested session

043d60d

Closes #512

aeneasr pushed a commit that referenced this issue Jun 17, 2017

oauth2: added failing test case for #512

6c9ed85

aeneasr pushed a commit that referenced this issue Jun 17, 2017

oauth2: resolve session issue with deep nested session

700fa81

Closes #512

aeneasr pushed a commit that referenced this issue Jun 17, 2017

oauth2: added failing test case for #512

0f98e88

aeneasr closed this as completed in a89a470 Jun 17, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

oauth2: investigate panic #512

oauth2: investigate panic #512

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

wyattanderson commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017 •

edited

Loading

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 14, 2017 •

edited

Loading

k-zaher commented Jun 14, 2017

aeneasr commented Jun 14, 2017

k-zaher commented Jun 14, 2017

k-zaher commented Jun 14, 2017

aeneasr commented Jun 14, 2017

k-zaher commented Jun 14, 2017

aeneasr commented Jun 16, 2017

aeneasr commented Jun 16, 2017

k-zaher commented Jun 16, 2017

oauth2: investigate panic #512

oauth2: investigate panic #512

Comments

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

wyattanderson commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017 • edited Loading

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

k-zaher commented Jun 13, 2017

aeneasr commented Jun 13, 2017

aeneasr commented Jun 14, 2017 • edited Loading

k-zaher commented Jun 14, 2017

aeneasr commented Jun 14, 2017

k-zaher commented Jun 14, 2017

k-zaher commented Jun 14, 2017

aeneasr commented Jun 14, 2017

k-zaher commented Jun 14, 2017

aeneasr commented Jun 16, 2017

aeneasr commented Jun 16, 2017

k-zaher commented Jun 16, 2017

k-zaher commented Jun 13, 2017 •

edited

Loading

aeneasr commented Jun 14, 2017 •

edited

Loading