with 1.7.1 , session keeps being lost / reinitialized

[gdestuynder]

Environment

• lua-resty-openidc version 1.7.1
• OpenID Connect provider is auth0

Expected behaviour

Web site authenticates the user and the session of the user is kept until the session expires

Actual behaviour

Web site re-authenticate the user for every single request

Minimized example

git clone https://github.com/mozilla-iam/mozilla.oidc.accessproxy
cd mozilla.oidc.accessproxy
# edit the local.env (see readme) for client id/secrets
make build
make compose

and browse to localhost

Notes

Reverting to 1.6.1 fixes that behavior. I haven't looked at what changed exactly, I suspect due to session:start() changes or some of the race condition fixes though
Or, alternatively, maybe the session should be setup differently before calling the library (in which case a change in the readme would be nice)

[zandbelt]

would you have a server debug log as well?

[zandbelt]

@bodewig any clue?

[bodewig]

well, https://github.com/mozilla-iam/mozilla.oidc.accessproxy/blob/master/etc/conf.d/openidc_layer.lua#L15 destroys the session whenever an error occurs - it might be a good idea to log the actual error. It is quite possible the error is related to the session change, but it could also be triggered by any other change between 1.6.1 and 1.7.1.

As I haven't got any Auth0 or AWS setup to play with I have tried to hack server.lua to use a local Keycloak installation and can not confirm the problem - but this doesn't say much as - without the AWS app behind the proxy - I only see the authenticate call succeeding followed by a 500 on my side when the real / URI is navigated.

@gdestuynder we really need to know what err contains when your code destroys the session.

[bodewig]

Just a random idea.

In one of my $work projects we use ORY Hydra which announces to support multiple token auth methods but the method you are expected to use is configured with the client. By default lua-resty-openidc picks the first method announced it supports, which may be the wrong one in our case.

If Auth0 does something similar then it might announce client_secret_jwt before the auth method your client is supposed to use. In 1.6.1 we didn't support this method, in 1.7.1 we do. This would require you to explicitly configure token_auth_method with 1.7.1 when it has not been necessary with 1.6.1

This is just one example where authenticate in 1.7.1 may return an error because of a change that is completely unrelated to the changes in our session handling code.

[gdestuynder]

@fiji-flo ^ in case you're able to send the logs or test this before i do - @bodewig theory sounds very likely - we should try setting token_auth_method to see if this work

[zandbelt]

Any progress on this one?

[gdestuynder]

Hi,
I got some logs from @fiji-flo and saw this:

token_endpoint_auth_methods_supported":["client_secret_basic","client_secret_post"] <= auth0 announces these token auth methods.
then later:
2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:1066: openidc_get_token_auth_method(): 1 => client_secret_basic

thus as per #249 (comment) we most likely need to configure token_auth_method to be client_secret_post

[bodewig]

In this case lua-resty-openidc picks client_secret_basic anyway (as it is the first one supported by server and client. I still think it would be very useful to know what the original err says when this error occurs.

[gdestuynder]

I got these from @fiji-flo :)

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:470: openidc_discover(): openidc_discover: URL is: https://auth.mozilla.auth0.com/.well-known/openid-configuration

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:476: openidc_discover(): discovery data not in cache, making call to discovery endpoint

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:357: openidc_configure_proxy(): openidc_configure_proxy : don't use http proxy

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] http.lua:633: send_request(): 

GET /.well-known/openid-configuration HTTP/1.1

User-Agent: lua-resty-http/0.12 (Lua) ngx_lua/10013

Host: auth.mozilla.auth0.com

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:488: openidc_discover(): response data: {"issuer":"https://auth.mozilla.auth0.com/","authorization_endpoint":"https://auth.mozilla.auth0.com/authorize","token_endpoint":"https://auth.mozilla.auth0.com/oauth/token","userinfo_endpoint":"https://auth.mozilla.auth0.com/userinfo","mfa_challenge_endpoint":"https://auth.mozilla.auth0.com/mfa/challenge","jwks_uri":"https://auth.mozilla.auth0.com/.well-known/jwks.json","registration_endpoint":"https://auth.mozilla.auth0.com/oidc/register","revocation_endpoint":"https://auth.mozilla.auth0.com/oauth/revoke","scopes_supported":["openid","profile","offline_access","name","given_name","family_name","nickname","email","email_verified","picture","created_at","identities","phone","address"],"response_types_supported":["code","token","id_token","code token","code id_token","token id_token","code token id_token"],"response_modes_supported":["query","fragment","form_post"],"subject_types_supported":["public"],"id_token_signing_alg_values_supported":["HS256","RS256"],"token_endpoint_auth_methods_supported":["client_secret_basic","client_secret_post"],"claims_supported":["aud","auth_time","created_at","email","email_verified","exp","family_name","given_name","iat","identities","iss","name","nickname","phone_number","picture","sub"],"request_uri_parameter_supported":false}

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:86: openidc_cache_set(): cache set: success=true err=nil forcible=false

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:1066: openidc_get_token_auth_method(): 1 => client_secret_basic

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:1069: openidc_get_token_auth_method(): no configuration setting for option so select the first supported method specified by the OP: client_secret_basic

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:1083: openidc_get_token_auth_method(): token_endpoint_auth_method result set to client_secret_basic

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:1220: authenticate(): session.present=nil, session.data.id_token=false, session.data.authenticated=nil, opts.force_reauthorize=nil, opts.renew_access_token_on_expiry=nil, try_to_renew=true, token_expired=false

2019/04/05 19:11:46 [debug] 5#5: *1 [lua] openidc.lua:1245: authenticate(): Authentication is required - Redirecting to OP Authorization endpoint

2019/04/05 19:11:49 [debug] 5#5: *4 [lua] openidc.lua:1053: openidc_get_token_auth_method(): 1 => client_secret_basic

2019/04/05 19:11:49 [debug] 5#5: *4 [lua] openidc.lua:1055: openidc_get_token_auth_method(): configured value for token_endpoint_auth_method (client_secret_basic) found in token_endpoint_auth_methods_supported in metadata

2019/04/05 19:11:49 [debug] 5#5: *4 [lua] openidc.lua:1083: openidc_get_token_auth_method(): token_endpoint_auth_method result set to client_secret_basic

2019/04/05 19:11:49 [debug] 5#5: *4 [lua] openidc.lua:1186: authenticate(): Redirect URI path (/redirect_uri) is currently navigated -> Processing authorization response coming from OP

2019/04/05 19:11:49 [error] 5#5: *4 [lua] openidc.lua:1190: authenticate(): request to the redirect_uri_path but there's no session state found, client: 10.0.159.176, server: , request: "GET /redirect_uri?code=REDACTED&state=REDACTED HTTP/1.1", host: "dinopark.k8s.sso.mozilla.com", referrer: "https://auth.mozilla.auth0.com/authorize?state=REDACTED&protocol=oauth2&response_type=code&redirect_uri=REDACTED&nonce=REDACTED&scope=openid+email+profile&sso=true&connection=Mozilla-LDAP&tried_autologin=true&client_id=null"

2019/04/05 19:11:49 [debug] 5#5: *5 [lua] openidc.lua:1053: openidc_get_token_auth_method(): 1 => client_secret_basic

2019/04/05 19:11:49 [debug] 5#5: *5 [lua] openidc.lua:1055: openidc_get_token_auth_method(): configured value for token_endpoint_auth_method (client_secret_basic) found in token_endpoint_auth_methods_supported in metadata

2019/04/05 19:11:49 [debug] 5#5: *5 [lua] openidc.lua:1083: openidc_get_token_auth_method(): token_endpoint_auth_method result set to client_secret_basic

2019/04/05 19:11:49 [debug] 5#5: *5 [lua] openidc.lua:1198: authenticate(): Logout path (/logout) is currently navigated -> Processing local session removal before redirecting to next step of logout process

it doesn't provide err but at least its the full log

[bodewig]

The only thing we can see in this log is "there is no session" but not why there is none. I don't see any of the log messages that would be associated with lua-resty-openidc creating/refreshing new sessions. What we also see is the logout function being invoked, which is something your code must be doing as the normal auhenticate flow will not do it by itself.

We probably need to see the log from the point before the initial redirection to the OP happens until this error state occurs.

[gdestuynder]

yes the code will definitely call logout when err is set / when theres no session
but also, yeah, when @fiji-flo has time I hope he can paste more data here, including just a log statement for err

[zandbelt]

any news on this?

[zandbelt]

closing this for lack of information