search

OpenIDC / mod_auth_openidc

OpenID Certified™ OpenID Connect Relying Party implementation for Apache HTTP Server 2.x
Apache License 2.0
973 stars 325 forks source link

redirect loop #181

Closed ashishdeole closed 7 years ago

ashishdeole commented 7 years ago

Hi,

Thanks for the quick response. After making the suggested changes, the issue https://github.com/pingidentity/mod_auth_openidc/issues/180 is no longer faced.

But the browser seems to be going in redirect loop.

We are new to openid connect and sincerely apologise. I have gone through the wiki pages, but could not get the solution.

Thanks and Regards Ashish

ashishdeole commented 7 years ago

Below are the related logs from server [2016-10-13T05:58:33.4278-04:00] [OHS] [WARNING:32] [OHS-9999] [mod_auth_openidc.c] [client_id: 10.19.0.17] [host_id: cifasoa-dt-a1d.ula.comcast.net] [host_addr: 10.252.115.39] [tid: 140576693364480] [user: applmgr] [ecid: 005Ffkb2ndu9_aspGgk3yf0000om00005N] [rid: 0] [VirtualHost: main] oidc_proto_get_key_from_jwks: oidc_jwk_parse_json failed: [src/jose.c:251: oidc_jwk_parse]: JWK parsing failed: invalid argument [file: jwk.c, function: cjose_jwk_create_EC_spec, line: 913]\n\n

[2016-10-13T05:58:33.4282-04:00] [OHS] [WARNING:32] [OHS-9999] [mod_auth_openidc.c] [client_id: 10.19.0.17] [host_id: cifasoa-dt-a1d.ula.comcast.net] [host_addr: 10.252.115.39] [tid: 140576693364480] [user: applmgr] [ecid: 005Ffkb2ndu9_aspGgk3yf0000om00005N] [rid: 0] [VirtualHost: main] oidc_proto_get_key_from_jwks: oidc_jwk_parse_json failed: [src/jose.c:251: oidc_jwk_parse]: JWK parsing failed: invalid argument [file: jwk.c, function: cjose_jwk_create_EC_spec, line: 913]\n\n

[2016-10-13T05:58:33.7403-04:00] [OHS] [WARNING:32] [OHS-9999] [mod_auth_openidc.c] [client_id: 10.19.0.17] [host_id: cifasoa-dt-a1d.ula.comcast.net] [host_addr: 10.252.115.39] [tid: 140576693364480] [user: applmgr] [ecid: 005Ffkb4CuS9_aspGgk3yf0000om00005O] [rid: 0] [VirtualHost: main] oidc_check_max_session_duration: maximum session duration exceeded for user: adeole001c@websec-dev.cable.comcast.com

zandbelt commented 7 years ago

Unless this turns out in to a bug it is better to do this conversation via the e-mail list; can you send me (hzandbelt@pingidentity.com) the complete Apache log and perhaps in the mean time set OIDCSessionMaxDuration 86400 to see if that changes the behaviour?

solsson commented 7 years ago

I get a similar oidc_jwk_parse_json failed.

I've confirmed the issue in https://github.com/Reposoft/openidc-keycloak-test/tree/v2. A working configuration with mod_auth_openidc 1.8.9 and Keycloak 1.9.8 was upgraded to mod_auth_openidc 2.0.0. After login in Keycloak you return to apache to see Error: OpenID Connect Provider error: Error in handling response type.. Reload the page and you get status 500 at http://[openidc]/protected/redirect_uri?state=...&code=...

Logs for that sequence looks as follows:

openidc_1         | [Tue Oct 18 11:49:34.532931 2016] [auth_openidc:error] [pid 8:tid 140396597348096] [client 172.27.0.1:39082] oidc_proto_jwt_verify: JWT signature verification failed: [src/jose.c:835: oidc_jwt_verify]: could not verify signature against any of the (2) provided keys\n, referer: http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk
openidc_1         | [Tue Oct 18 11:49:34.532974 2016] [auth_openidc:error] [pid 8:tid 140396597348096] [client 172.27.0.1:39082] oidc_proto_parse_idtoken: id_token signature could not be validated, aborting, referer: http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk
openidc_1         | 172.27.0.1 - - [18/Oct/2016:11:49:34 +0000] "GET /protected/redirect_uri?state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&code=UWdVq8nyw0TkzyF6Kg0gSexVAtYZRU3vV08ii5UX-tw.b06efee9-77f9-4b8f-a8c4-f4ad268c24be HTTP/1.1" 200 335 "http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:49.0) Gecko/20100101 Firefox/49.0"
openidc_1         | 172.27.0.1 - - [18/Oct/2016:11:50:38 +0000] "GET /protected/redirect_uri?state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&code=UWdVq8nyw0TkzyF6Kg0gSexVAtYZRU3vV08ii5UX-tw.b06efee9-77f9-4b8f-a8c4-f4ad268c24be HTTP/1.1" 500 532 "http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:49.0) Gecko/20100101 Firefox/49.0"
openidc_1         | [Tue Oct 18 11:50:38.835111 2016] [auth_openidc:error] [pid 14:tid 140396588955392] [client 172.27.0.1:39092] oidc_restore_proto_state: no "mod_auth_openidc_state_Mb5pENDZ5EzTiIiIFVl-S6F9_u8" state cookie found, referer: http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk
openidc_1         | [Tue Oct 18 11:50:38.835199 2016] [auth_openidc:error] [pid 14:tid 140396588955392] [client 172.27.0.1:39092] oidc_unsolicited_proto_state: could not parse JWT from state: invalid unsolicited response: [src/jose.c:645: oidc_jwt_parse]: cjose_jws_import failed: invalid argument [file: jws.c, function: cjose_jws_import, line: 864]\n\n, referer: http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk
openidc_1         | [Tue Oct 18 11:50:38.835224 2016] [auth_openidc:error] [pid 14:tid 140396588955392] [client 172.27.0.1:39092] oidc_authorization_response_match_state: unable to restore state, referer: http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk
openidc_1         | [Tue Oct 18 11:50:38.835234 2016] [auth_openidc:error] [pid 14:tid 140396588955392] [client 172.27.0.1:39092] oidc_handle_authorization_response: invalid authorization response state and no default SSO URL is set, sending an error..., referer: http://keycloak:8080/auth/realms/Testrealm/protocol/openid-connect/auth?response_type=code&scope=openid%20email&client_id=testclient&state=Mb5pENDZ5EzTiIiIFVl-S6F9_u8&redirect_uri=http%3A%2F%2Fopenidc%2Fprotected%2Fredirect_uri&nonce=QCLP1XsSrY7vqdAGH7X5njW6lXNyt5g31DrT9a_Zgbk

I will investigate this further. Is there something specific I can look for?

zandbelt commented 7 years ago

could you please enter this in a new issue? this is clearly not a redirect loop happening but a token verification error; please provide logs with LogLevel set to debug

solsson commented 7 years ago

The new issue has an attached log. I thought it was a redirect loop because that's what I saw in our QA environment, and the response looked the same. I will be offline for a couple of hours but can look into that more closely later.

zandbelt commented 7 years ago

no problem; I'm interested in what happens in QA as well, thanks

solsson commented 7 years ago

With #184 in our production image I no longer have problems in QA. I suspect that the redirects I saw earlier were due to a memcached service that didn't respond. We use

OIDCSessionType server-cache:persistent
OIDCCacheType memcache
OIDCMemCacheServers memcached

In the logs, when memcached is down, I see repeated sequences of 2-4 times oidc_cache_memcache_set: apr_memcache_set returned an error; perhaps your memcache server is not available? followed by a status 200 (oddly?) GET /oauth2callback?state=fA6e....

solsson commented 7 years ago

I can confirm now that you get a redirect loop if you have authenticated to a host with the above memcached config then reload the page after memcached has gone unresponsive.

You get exactly 4 auth_openidc:error] [pid 6:tid 139756784494336] [client 10.0.2.1:65226] oidc_cache_memcache_set: apr_memcache_set returned an error; perhaps your memcache server is not available? before a redirect from /oauth2callback followed by another memcached error and a redirect back to /oauth2callback. My browser gave up after 7 rounds.

10.0.2.1 - 10.0.2.1 - authenticated.user [19/Oct/2016:12:15:23 +0000] "GET /oauth2callback?state=x4..&code=mg.. HTTP/1.1" 302 212 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:49.0) Gecko/20100101 Firefox/49.0"
[Wed Oct 19 12:15:23.934816 2016] [auth_openidc:error] [pid 6:tid 139756868421376] [client 10.0.2.1:65226] oidc_cache_memcache_set: apr_memcache_set returned an error; perhaps your memcache server is not available?
10.0.2.1 - 10.0.2.1 - - [19/Oct/2016:12:15:23 +0000] "GET /page HTTP/1.1" 302 484 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:49.0) Gecko/20100101 Firefox/49.0"

Let me know if you need this reproduced in the keycloak test repo with debug logging. Shouldn't be hard, but this was a production-like environment.

zandbelt commented 7 years ago

This is a different issue as well:

When I stop my memcache server, the login will still succeed but there will be no session so the next page hit will redirect to the Provider again; that is the expected behaviour, apparently you're observing something different.

Refreshing the page after an error occurs handling the authorization response should produce an error by design; the interesting thing is why you receive an error in the first place and I don't; I'm especially interested in the response that the browser receives after the memcache failure (it should be a normal response, not an error); can you open a new ticket to debug this.

update: addressed in #185

zandbelt commented 7 years ago

FYI: the issue of the original requestor has to do with storing the session expiry time in the session cache (oidc_check_max_session_duration: maximum session duration exceeded): apparently in some compilation environments the APR time formatting routines don't work or work differently.

solsson commented 7 years ago

Ok, thank you. This redirect loop is unimportant to us, as we need to move to clustered Redis instead for higher session cache availability. I just logged this here in case it is a symptom of some generic error handling regression.

zandbelt commented 7 years ago

I have opened a new issue #193 on this that is less cluttered with other information; this is where followup will happen.