Unable to do strict issuer verification

[chris-crunchr]

According to the example apache config, I can force strict issuer verification with the verify.iss=required option. However, when I set this option to required it fails, while it succeeds with optional.

My config looks like this:

OAuth2TokenVerify metadata https://<domain>/.well-known/openid-configuration metadata.ssl_verify=false&verify.iss=required

One interesting excerpt from the logs:

[Wed Apr 19 11:53:49.360956 2023] [oauth2:debug] [pid 110463:tid 140637177321216] src/jose.c(1040): [client 127.0.0.1:52514] _oauth2_jose_jwt_validate_iss: enter: iss=(null), validate=required

This suggests to me that the value of iss is not passed along.

I'm using KeyCloak as my IdP and verified that the iss field in token corresponds with the issuer field in the metadata.

[chris-crunchr]

Looked a bit further into it and found the one (and only) call site of _oauth2_jose_jwt_validate_iss here, which in turn seems to be only called from here. The latter call site hardcodes the iss parameter to NULL. Then in _oauth2_jose_jwt_validate_iss there is an explicit NULL check on iss, causing this behavior AFAIK.

As far as I understand the code, the iss parameter should be the value from the metadata.

[zandbelt]

it was not implemented yet, since the most common configs don't provide this value, but issuer validation when the verification was configured through metadata was just added; thanks for reporting and digging in!

[chris-crunchr]

Awesome! I was sifting through the code to find a way to fix it, but you fixed it before I could even find a suitable starting point. Thanks!

[zandbelt]

edit: it needed 44a3892 as well...

[chris-crunchr]

Is it possible for you to create a new release with this patch? Or provide details on how to do it myself? I'm trying to create a deb myself, but its a bit finicky. Also, it would help us track the exact version used.

[chris-crunchr]

This is great! Thanks again! 🙏

[chris-crunchr]

Not entirely sure how this works. I see the release jobs are finished, but there is no new item on the release page. Should I just wait, or is there a step missing?

[zandbelt]

hold on, still building...

[zandbelt]

https://github.com/OpenIDC/liboauth2/releases/tag/v1.5.1

[chris-crunchr]

Ah, thought the release job in github actions was enough. Thanks!

[chris-crunchr]

Finally got a round testing this, but it still seems broken! I get the exact same message as before (iss=(null), validate=required). Double checked I'm actually using 1.5.1.

[zandbelt]

are you sure there is an "Issuer" value in the configured metadata document? if so, can you debug trace what happens?

[chris-crunchr]

Verified it and keycloak does provide a issuer key in the metadata (is the uppercase relevant?). Anyway, tried to isolate the relevant logs as much as possible and ran it again with LogLevel trace3 and got this:

[Tue May 02 14:36:53 2023] [rewrite:trace2] mod_rewrite.c(483): 127.0.0.1 - - [<DOMAIN>/sid#7ffa79c6c4b8][rid#7ffa7a6140a0/initial] init rewrite engine with requested uri /api/cdsf
[Tue May 02 14:36:53 2023] [rewrite:trace3] mod_rewrite.c(483): 127.0.0.1 - - [<DOMAIN>/sid#7ffa79c6c4b8][rid#7ffa7a6140a0/initial] applying pattern '^' to uri '/api/cdsf'
[Tue May 02 14:36:53 2023] [rewrite:trace3] mod_rewrite.c(483): 127.0.0.1 - - [<DOMAIN>/sid#7ffa79c6c4b8][rid#7ffa7a6140a0/initial] applying pattern '^/xyz(.*)' to uri '/api/cdsf'
[Tue May 02 14:36:53 2023] [rewrite:trace3] mod_rewrite.c(483): 127.0.0.1 - - [<DOMAIN>/sid#7ffa79c6c4b8][rid#7ffa7a6140a0/initial] applying pattern '^/xyz(.*)' to uri '/api/cdsf'
[Tue May 02 14:36:53 2023] [rewrite:trace1] mod_rewrite.c(483): 127.0.0.1 - - [<DOMAIN>/sid#7ffa79c6c4b8][rid#7ffa7a6140a0/initial] pass through /api/cdsf
[Tue May 02 14:36:53 2023] [proxy:trace2] mod_proxy.c(687): AH03461: attempting to match URI path '/api/cdsf' against prefix '/auth' for proxying
[Tue May 02 14:36:53 2023] [proxy:trace2] mod_proxy.c(687): AH03461: attempting to match URI path '/api/cdsf' against prefix '/' for proxying
[Tue May 02 14:36:53 2023] [proxy:trace1] mod_proxy.c(773): AH03464: URI path '/api/cdsf' matches proxy handler 'proxy:http://localhost:3305/api/cdsf'
[Tue May 02 14:36:53 2023] [authz_core:debug] mod_authz_core.c(817): AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Tue May 02 14:36:53 2023] [authz_core:debug] mod_authz_core.c(817): AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue May 02 14:36:53 2023] [auth_kerb:debug] src/mod_auth_kerb.c(1963): kerb_authenticate_user entered with user (NULL) and auth_type oauth2
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(158): _oauth2_http_request_header_set_add_sanitized: Host: <DOMAIN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(158): _oauth2_http_request_header_set_add_sanitized: User-Agent: curl/7.68.0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(158): _oauth2_http_request_header_set_add_sanitized: Accept: */*
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(158): _oauth2_http_request_header_set_add_sanitized: Authorization: Bearer <TOKEN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/server/apache.c(326): oauth2_apache_request_context_init: created request context: 0x7ffa580024d0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/mod_oauth2.c(179): oauth2_check_user_id_handler: incoming request: "/api/cdsf?(null)" ap_is_initial_req=1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/mod_oauth2.c(98): oauth2_request_handler: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/proto.c(212): _oauth2_get_source_token_from_envvar: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/server/apache.c(538): oauth2_apache_get_envvar: get environment variable: access_token
[Tue May 02 14:36:53 2023] [oauth2:debug] src/proto.c(224): _oauth2_get_source_token_from_envvar: no source token found in access_token environment variable
[Tue May 02 14:36:53 2023] [oauth2:debug] src/proto.c(45): _oauth2_get_source_token_from_header: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(921): oauth2_nv_list_get: Authorization=Bearer <TOKEN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/proto.c(58): _oauth2_get_source_token_from_header: Authorization header found
[Tue May 02 14:36:53 2023] [oauth2:debug] src/proto.c(84): _oauth2_get_source_token_from_header: leave: <TOKEN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/oauth2.c(827): oauth2_token_verify: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(316): oauth2_cache_get: enter: key=<TOKEN>, type=shm, decrypt=0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(235): _oauth2_cache_hash_key: enter: key=<TOKEN>, algo=(null)
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(122): oauth2_jose_hash_bytes: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(172): oauth2_jose_hash_bytes: leave: 1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(250): _oauth2_cache_hash_key: leave: hashed key: 47fdb4ba22fee58acadeefd08e1e2d23240c5c9fe9bfe4f13144e353b2c7833a
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(254): oauth2_cache_shm_get: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(317): oauth2_cache_shm_get: leave: 1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(350): oauth2_cache_get: leave: cache miss for key: <TOKEN> return: 0 bytes
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(2078): oauth2_jose_resolve_from_uri: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(316): oauth2_cache_get: enter: key=https://<DOMAIN>/auth/realms/<REALM>/.well-known/openid-configuration, type=shm, decrypt=0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(235): _oauth2_cache_hash_key: enter: key=https://<DOMAIN>/auth/realms/<REALM>/.well-known/openid-configuration, algo=(null)
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(122): oauth2_jose_hash_bytes: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(172): oauth2_jose_hash_bytes: leave: 1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(250): _oauth2_cache_hash_key: leave: hashed key: 988bd6a77b65d86eb21429e5bf0534bac3381240086903f0166641b4b6571e4b
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(254): oauth2_cache_shm_get: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(282): oauth2_cache_shm_get: found: 988bd6a77b65d86eb21429e5bf0534bac3381240086903f0166641b4b6571e4b (expires=1683103349, now=1683031013)
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(289): oauth2_cache_shm_get: not expired: 988bd6a77b65d86eb21429e5bf0534bac3381240086903f0166641b4b6571e4b
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(317): oauth2_cache_shm_get: leave: 1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(350): oauth2_cache_get: leave: cache hit for key: https://<DOMAIN>/auth/realms/<REALM>/.well-known/openid-configuration return: 6716 bytes
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(2125): oauth2_jose_resolve_from_uri: leave: {"issuer":"https://<DOMAIN>/auth/realms/<REALM>", ... }
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(974): oauth2_jose_jwt_header_peek: decoding: <TOKEN> (1425-1314=111)
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(165): _oauth2_cjose_base64_decode: enter: len=111
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(189): _oauth2_cjose_base64_decode: leave: len=83
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(984): oauth2_jose_jwt_header_peek: decoded: {"alg":"RS256","typ" : "JWT","kid" : "yhMjOwJxUyc9xTtTdqKGwwQxmDSoTBGUcKdEvTwLBrg"}
[Tue May 02 14:36:53 2023] [oauth2:debug] src/oauth2.c(526): _oauth2_metadata_verify_callback: JWT token: header={"alg":"RS256","typ" : "JWT","kid" : "yhMjOwJxUyc9xTtTdqKGwwQxmDSoTBGUcKdEvTwLBrg"}
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(974): oauth2_jose_jwt_header_peek: decoding: <TOKEN> (1425-1314=111)
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(165): _oauth2_cjose_base64_decode: enter: len=111
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(189): _oauth2_cjose_base64_decode: leave: len=83
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(984): oauth2_jose_jwt_header_peek: decoded: {"alg":"RS256","typ" : "JWT","kid" : "yhMjOwJxUyc9xTtTdqKGwwQxmDSoTBGUcKdEvTwLBrg"}
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(1253): oauth2_jose_jwt_verify: enter: JWT token header={"alg":"RS256","typ" : "JWT","kid" : "yhMjOwJxUyc9xTtTdqKGwwQxmDSoTBGUcKdEvTwLBrg"}
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(2078): oauth2_jose_resolve_from_uri: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(316): oauth2_cache_get: enter: key=https://<DOMAIN>/auth/realms/<REALM>/protocol/openid-connect/certs, type=shm, decrypt=0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(235): _oauth2_cache_hash_key: enter: key=https://<DOMAIN>/auth/realms/<REALM>/protocol/openid-connect/certs, algo=(null)
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(122): oauth2_jose_hash_bytes: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(172): oauth2_jose_hash_bytes: leave: 1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(250): _oauth2_cache_hash_key: leave: hashed key: 79dc4e24341451581fadfecf57d0862bcfb581e440a511aa25ba131122526923
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(254): oauth2_cache_shm_get: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(282): oauth2_cache_shm_get: found: 79dc4e24341451581fadfecf57d0862bcfb581e440a511aa25ba131122526923 (expires=1683103350, now=1683031013)
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(289): oauth2_cache_shm_get: not expired: 79dc4e24341451581fadfecf57d0862bcfb581e440a511aa25ba131122526923
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache/shm.c(317): oauth2_cache_shm_get: leave: 1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/cache.c(350): oauth2_cache_get: leave: cache hit for key: https://<DOMAIN>/auth/realms/<REALM>/protocol/openid-connect/certs return: 2989 bytes
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(2125): oauth2_jose_resolve_from_uri: leave: {"keys":[<KEYS>]}
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(2024): _oauth2_jose_jwks_uri_resolve_response_callback: skipping key because of non-matching "use": "enc"
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(924): _oauth2_jose_jwt_verify_jwk: enter: jws kid=yhMjOwJxUyc9xTtTdqKGwwQxmDSoTBGUcKdEvTwLBrg, jwk kid=yhMjOwJxUyc9xTtTdqKGwwQxmDSoTBGUcKdEvTwLBrg
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(936): _oauth2_jose_jwt_verify_jwk: cjose_jws_verify returned true
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(949): _oauth2_jose_jwt_verify_jwk: leave: rc=1
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(1317): oauth2_jose_jwt_verify: got plaintext (len=727): <PLAIN_TOKEN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(1206): _oauth2_jose_jwt_payload_validate: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(1040): _oauth2_jose_jwt_validate_iss: enter: iss=(null), validate=required
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(1080): _oauth2_jose_jwt_validate_iss: leave: 0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(1231): _oauth2_jose_jwt_payload_validate: leave: 0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/jose.c(1348): oauth2_jose_jwt_verify: leave: 0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/oauth2.c(312): _oauth2_introspect_verify: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(807): _oauth2_http_url_encode_list: processing: token=<TOKEN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(280): oauth2_url_encode: enter: token
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(305): oauth2_url_encode: leave: token
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(280): oauth2_url_encode: enter: <TOKEN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(305): oauth2_url_encode: leave: <TOKEN>
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(807): _oauth2_http_url_encode_list: processing: token_type_hint=access_token
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(280): oauth2_url_encode: enter: token_type_hint
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(305): oauth2_url_encode: leave: token_type_hint
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(280): oauth2_url_encode: enter: access_token
[Tue May 02 14:36:53 2023] [oauth2:debug] src/util.c(305): oauth2_url_encode: leave: access_token
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(883): oauth2_http_url_form_encode: data=token=<TOKEN>&token_type_hint=access_token
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(979): oauth2_http_call: enter: url=https://<DOMAIN>/auth/realms/<REALM>/protocol/openid-connect/token/introspect, data=token=<TOKEN>&token_type_hint=access_token, ctx=[ ssl_verify=false hdr=[ Content-Type=application/x-www-form-urlencoded ] cookie=[ ] ]
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(1102): oauth2_http_call: HTTP response code=401
[Tue May 02 14:36:53 2023] [oauth2:debug] src/http.c(1120): oauth2_http_call: leave [1]: {"error":"invalid_request","error_description":"Authentication failed."}
[Tue May 02 14:36:53 2023] [oauth2:debug] src/oauth2.c(394): _oauth2_introspect_verify: leave: 0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/oauth2.c(867): oauth2_token_verify: leave: 0
[Tue May 02 14:36:53 2023] [oauth2:debug] src/server/apache.c(368): oauth2_apache_return_www_authenticate: enter
[Tue May 02 14:36:53 2023] [oauth2:debug] src/server/apache.c(460): oauth2_apache_hdr_out_add: WWW-Authenticate: Bearer error="invalid_token", error_description="Token could not be verified."
[Tue May 02 14:36:53 2023] [oauth2:debug] src/server/apache.c(392): oauth2_apache_return_www_authenticate: leave
[Tue May 02 14:36:53 2023] [oauth2:debug] src/mod_oauth2.c(144): oauth2_request_handler: leave
[Tue May 02 14:36:53 2023] [core:trace3] request.c(117): auth phase 'check user' gave status 401: /api/cdsf
[Tue May 02 14:36:53 2023] [http:trace3] http_filters.c(1125): Response sent with status 401
[Tue May 02 14:36:53 2023] [oauth2:debug] src/server/apache.c(335): oauth2_apache_request_context_free: dispose request context: 0x7ffa580024d0

[zandbelt]

that really looks like you're still on 1.5.0, can you check the info log message at startup?