remote_user_claim oauth2_apache_set_request_user: remote user claim could not be found

[ainielse]

When configuring with

AuthType oauth2
OAuth2TargetPass remote_user_claim=appid
OAuth2TargetPass authn_header=myheader
Require valid-user

Everything works fine with the initial call, but the subsequent call fails with

oauth2_apache_set_request_user: remote user claim could not be found

I get the following debug output:

[Wed Jun 16 10:26:33.949565 2021] [oauth2:debug] [pid 119080] src/cache/shm.c(283): [client 10.8.225.116:53237] oauth2_cache_shm_get: not expired: b0d2ba31bb1...194b120df
[Wed Jun 16 10:26:33.949569 2021] [oauth2:debug] [pid 119080] src/cache/shm.c(309): [client 10.8.225.116:53237] oauth2_cache_shm_get: leave: 1
[Wed Jun 16 10:26:33.949573 2021] [oauth2:debug] [pid 119080] src/cache.c(318): [client 10.8.225.116:53237] oauth2_cache_get: leave: cache hit for key: https://adfs.drwholdings.com/adfs/discovery/keys return: 1496 bytes
[Wed Jun 16 10:26:33.949627 2021] [oauth2:debug] [pid 119080] src/jose.c(1932): [client 10.8.225.116:53237] oauth2_jose_resolve_from_uri: leave: {"keys":[{"kty":"RSA","use":"sig","alg":"RS256","kid":"Zl...o","x5t":"Zl...o","n":"oLpzVeOYlN3BDS9ZzJry...GdxH8\/iCwMRso8"]}]}
[Wed Jun 16 10:26:33.949764 2021] [oauth2:debug] [pid 119080] src/jose.c(805): [client 10.8.225.116:53237] _oauth2_jose_jwt_verify_jwk: enter: jws kid=ZldITKME80smHsCc_al8MypT-no, jwk kid=Zl...no
[Wed Jun 16 10:26:33.949900 2021] [oauth2:debug] [pid 119080] src/jose.c(816): [client 10.8.225.116:53237] _oauth2_jose_jwt_verify_jwk: cjose_jws_verify returned true
[Wed Jun 16 10:26:33.949911 2021] [oauth2:debug] [pid 119080] src/jose.c(824): [client 10.8.225.116:53237] _oauth2_jose_jwt_verify_jwk: leave: rc=1
[Wed Jun 16 10:26:33.949915 2021] [oauth2:debug] [pid 119080] src/jose.c(1185): [client 10.8.225.116:53237] oauth2_jose_jwt_verify: got plaintext (len=418): {"aud":"https://chhq-vudapex30.drwholdings.com/apex/okr_uat/aptest01/aptest01","iss":"http://adfs.drwholdings.com/adfs/services/trust","iat":1623857185,"nbf":1623857185,"exp":1623860785,"apptype":"Confidential","appid":"d2...21f3","authmethod":"http://schemas.microsoft.com/ws/2008/06/identity/authenticationmethod/password","auth_time":"2021-06-16T15:26:25.168Z","ver":"1.0","scp":"openid"}
[Wed Jun 16 10:26:33.949973 2021] [oauth2:debug] [pid 119080] src/jose.c(1079): [client 10.8.225.116:53237] _oauth2_jose_jwt_payload_validate: enter
[Wed Jun 16 10:26:33.949980 2021] [oauth2:debug] [pid 119080] src/jose.c(916): [client 10.8.225.116:53237] _oauth2_jose_jwt_validate_iss: enter: iss=(null), validate=optional
[Wed Jun 16 10:26:33.949982 2021] [oauth2:debug] [pid 119080] src/jose.c(955): [client 10.8.225.116:53237] _oauth2_jose_jwt_validate_iss: leave: 1
[Wed Jun 16 10:26:33.949983 2021] [oauth2:debug] [pid 119080] src/jose.c(969): [client 10.8.225.116:53237] _oauth2_jose_jwt_validate_exp: enter: validate=optional
[Wed Jun 16 10:26:33.949986 2021] [oauth2:debug] [pid 119080] src/jose.c(993): [client 10.8.225.116:53237] _oauth2_jose_jwt_validate_exp: "exp"=1623860785, 3592 seconds from now
[Wed Jun 16 10:26:33.949988 2021] [oauth2:debug] [pid 119080] src/jose.c(1007): [client 10.8.225.116:53237] _oauth2_jose_jwt_validate_exp: leave: 1
[Wed Jun 16 10:26:33.949990 2021] [oauth2:debug] [pid 119080] src/jose.c(1025): [client 10.8.225.116:53237] _oauth2_jose_jwt_validate_iat: enter: validate=optional, slack_before=140028818751498, slack_after=140033113718783
[Wed Jun 16 10:26:33.949992 2021] [oauth2:debug] [pid 119080] src/jose.c(1067): [client 10.8.225.116:53237] _oauth2_jose_jwt_validate_iat: leave: 1
[Wed Jun 16 10:26:33.950037 2021] [oauth2:debug] [pid 119080] src/jose.c(1104): [client 10.8.225.116:53237] _oauth2_jose_jwt_payload_validate: leave: 1
[Wed Jun 16 10:26:33.950093 2021] [oauth2:debug] [pid 119080] src/jose.c(1205): [client 10.8.225.116:53237] oauth2_jose_jwt_verify: leave: 1
[Wed Jun 16 10:26:33.950105 2021] [oauth2:debug] [pid 119080] src/cache.c(339): [client 10.8.225.116:53237] oauth2_cache_set: enter: key=eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsIng1dCI6IlpsZElUS01FODBzbUhzQ2NfYWw4TXlwVC1ubyIsImtpZCI6IlpsZElU...Yc-T-_HPut4pw, len=418, ttl(s)=300, type=shm, encrypt=0
[Wed Jun 16 10:26:33.950112 2021] [oauth2:debug] [pid 119080] src/cache.c(260): [client 10.8.225.116:53237] _oauth2_cache_hash_key: enter: key=eyJ0eXAiOiJKV1QiL...c-T-_HPut4pw, algo=(null)
[Wed Jun 16 10:26:33.950117 2021] [oauth2:debug] [pid 119080] src/jose.c(116): [client 10.8.225.116:53237] oauth2_jose_hash_bytes: enter
[Wed Jun 16 10:26:33.950123 2021] [oauth2:debug] [pid 119080] src/jose.c(166): [client 10.8.225.116:53237] oauth2_jose_hash_bytes: leave: 1
[Wed Jun 16 10:26:33.950128 2021] [oauth2:debug] [pid 119080] src/cache.c(275): [client 10.8.225.116:53237] _oauth2_cache_hash_key: leave: hashed key: f440e63a06b1329580ffcbd9a131786eb8a8c645a95e8999f17d8fb8a28abc76
[Wed Jun 16 10:26:33.950131 2021] [oauth2:debug] [pid 119080] src/cache/shm.c(341): [client 10.8.225.116:53237] oauth2_cache_shm_set: enter
[Wed Jun 16 10:26:33.950218 2021] [oauth2:debug] [pid 119080] src/cache/shm.c(437): [client 10.8.225.116:53237] oauth2_cache_shm_set: leave: 1
[Wed Jun 16 10:26:33.950228 2021] [oauth2:debug] [pid 119080] src/cache.c(368): [client 10.8.225.116:53237] oauth2_cache_set: leave: successfully stored: eyJ0eXAiOiJKV1QiLCJhbGc...DF9hNJNLMraqb-CmtSHBHkCA4QlqgYc-T-_HPut4pw
[Wed Jun 16 10:26:33.950264 2021] [oauth2:debug] [pid 119080] src/oauth2.c(798): [client 10.8.225.116:53237] oauth2_token_verify: leave: 1
[Wed Jun 16 10:26:33.950267 2021] [oauth2:error] [pid 119080] [client 10.8.225.116:53237] oauth2_apache_set_request_user: remote user claim could not be found
[Wed Jun 16 10:26:33.950270 2021] [oauth2:debug] [pid 119080] src/server/apache.c(324): [client 10.8.225.116:53237] oauth2_apache_return_www_authenticate: enter
[Wed Jun 16 10:26:33.950274 2021] [oauth2:debug] [pid 119080] src/server/apache.c(387): [client 10.8.225.116:53237] oauth2_apache_hdr_out_add: WWW-Authenticate: Bearer error="invalid_token", error_description="Could not determine remote user."
[Wed Jun 16 10:26:33.950277 2021] [oauth2:debug] [pid 119080] src/server/apache.c(348): [client 10.8.225.116:53237] oauth2_apache_return_www_authenticate: leave
[Wed Jun 16 10:26:33.950279 2021] [oauth2:debug] [pid 119080] src/mod_oauth2.c(153): [client 10.8.225.116:53237] oauth2_request_handler: leave
[Wed Jun 16 10:26:33.950471 2021] [oauth2:debug] [pid 119080] src/server/apache.c(292): [client 10.8.225.116:53237] oauth2_apache_request_context_free: dispose request context: 0x55a59a25e910

[zandbelt]

AFAICT that should work but perhaps you can try:

OAuth2TargetPass remote_user_claim=appid&authn_header=myheader

to see if there's a problem with parsing multiple OAuth2TargetPass statements

[ainielse]

I changed it to
OAuth2TargetPass remote_user_claim=appid&authn_header=myheader
but had the same result. It works the first time, the second and third attempts with the same bearer token error, and then the fourth attempt worked. I don't know if it the number of attempts or the time that it takes between them.

It seems to always work if I get a new bearer token.

Any thoughts? I can provide full error logs if that is helpful.

[zandbelt]

that seems like a bug then indeed: the full error log would be helpful

[zandbelt]

was this resolved?