Introspection failure: is mod_oauth2 changing the endpoint?

[EML-github]

I have a site (example.com) which uses mod_auth_openidc for various webapps, and mod_oauth2 for CLI access. The site also runs Keycloak, with everything behind Apache. Currently, I'm testing mod_oauth2 using git, with git-credential-manager (GCM). This fails, and it looks like mod_oauth2 has (slightly) changed the introspection endpoint such that it no longer matches the original token issuer (which was the local Keycloak).

I'm on liboauth2 1.5.2, mod_oauth2 3.3.1.2.

There are three Apache accesses, which are (more details in the log output below):

(1) I carry out a git clone from the command line, and GCM issues
GET /git/test/info/refs?service=git-upload-pack HTTP/1.1\r\n
This has basic authorisation, and a base64-encoded token which looks good. The issuer is shown as https://example.com/keycloak/realms/vserver, which is as expected.

(2) mod_oauth2 then carries out two introspection POSTs. I don't understand why there are two; the first is incoming, so I presume is a redirection; the second is a POST out to the introspection endpoint. The token sent to Keycloak is the one from git, and still has an issuer of https://example.com/keycloak/realms/vserver.

This final Keycloak access has:

POST /realms/vserver/protocol/openid-connect/token/introspect HTTP/1.1\r\n
Host: example.com\r\n
X-Forwarded-Proto: https\r\n
X-Forwarded-Host: example.com\r\n
X-Forwarded-Server: www.example.com\r\n

The endpoint is wrong: it's shown as /realms. The first POST correctly shows /keycloak/realms. So, basically, the problem appears to be that the first POST in the log output shows /keycloak/realms, but this has gone in the second POST. Any idea why this should be?

The Apache config is:

  ScriptAlias  /git/ /usr/lib/git-core/git-http-backend/
  <Location /git>
    AuthType oauth2
    OAuth2AcceptTokenIn basic
    OAuth2TokenVerify   introspect https://example.com/keycloak/realms/vserver/protocol/openid-connect/token/introspect introspect.ssl_verify=false
    Require claim "resource_access.openid-web.roles:VCS"
    LogLevel oauth2:debug
  </Location>

Abbreviated mod_dumpio log output below. Unfortunately, the LogLevel oauth2:debug doesn't seem to do anything:

[dumpio:trace7] [client 90.254.224.170:41876] mod_dumpio:   GET /git/test/info/refs?service=git-upload-pack HTTP/1.1\r\n
[dumpio:trace7] [client 90.254.224.170:41876] mod_dumpio:   Host: example.com\r\n
[dumpio:trace7] [client 90.254.224.170:41876] mod_dumpio:   Authorization: Basic <base64-token>
[dumpio:trace7] [client 90.254.224.170:41876] mod_dumpio:   User-Agent: git/2.34.1\r\n
[dumpio:trace7] [client 90.254.224.170:41876] mod_dumpio:   Git-Protocol: version=2\r\n
[auth_openidc:debug] [client 90.254.224.170:41876]          oidc_authz_checker: enter: (r->user=(null)) require_args=""resource_access.openid-web.roles:VCS""
[dumpio:trace7] [client 194.163.188.170:39852] mod_dumpio:  POST /keycloak/realms/vserver/protocol/openid-connect/token/introspect HTTP/1.1\r\n
[dumpio:trace7] [client 194.163.188.170:39852] mod_dumpio:  Host: example.com\r\n
[dumpio:trace7] [client 194.163.188.170:39852] mod_dumpio:  User-Agent: liboauth2-1.5.2\r\n
[auth_openidc:debug] [client 194.163.188.170:39852]         oidc_util_request_matches_url: comparing "/keycloak/realms/vserver/protocol/openid-connect/token/introspect"=="/oauth2callback"
[dumpio:trace7] [client 194.163.188.170:39852] mod_dumpio:  token=<token>&token_type_hint=access_token
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         POST /realms/vserver/protocol/openid-connect/token/introspect HTTP/1.1\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         Host: example.com\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         User-Agent: liboauth2-1.5.2\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         X-Forwarded-Proto: https\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         X-Forwarded-Port: 443\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         X-Forwarded-For: 194.163.188.170\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         X-Forwarded-Host: example.com\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         X-Forwarded-Server: www.example.com\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         token=<token>&token_type_hint=access_token
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         HTTP/1.1 401 Unauthorized\r\n
[dumpio:trace7] [remote 127.0.0.1:8095] mod_dumpio:         {"error":"invalid_request","error_description":"Authentication failed."}

[zandbelt]

I think I've encountered problems with oauth2:debug, though most probably it is overwritten elsewhere in your setup (I see mod_auth_openidc debug logs have been enabled as well, that must come from elsewhere); better de-duplicate or run with the global "debug" level

[EML-github]

Unfortunately, that's easier said than done. Apache logging seems a bit flakey. I can't find any way to get dumpio:trace7 to co-exist with a global debug, or anything else that debugs mod_oauth2:

1. Doesn't work: global dumpio:trace7, with global debug: only trace7
2. Doesn't work: both dumpio:trace7 and debug in <Location />: only trace7
3. Doesn't work: both dumpio:trace7 and oauth2:debug in <Location /> (no output at all!)
4. Does work: global dumpio:trace7, with mod_auth_openidc:debug in <Location />
5. etc....

[EML-github]

Debug, without dumpio trace:

[Tue Feb 13 16:14:10.141631 2024] [auth_openidc:debug] [pid 8047] src/util.c(1388): [client 194.163.188.170:59890] oidc_util_request_matches_url: comparing "/keycloak/realms/vserver/protocol/openid-connect/token/introspect"=="/oauth2callback"
[Tue Feb 13 16:14:10.141650 2024] [proxy:debug] [pid 8047] mod_proxy.c(1503): [client 194.163.188.170:59890] AH01143: Running scheme http handler (attempt 0)
[Tue Feb 13 16:14:10.141654 2024] [proxy:debug] [pid 8047] proxy_util.c(2531): AH00942: http: has acquired connection for (localhost)
[Tue Feb 13 16:14:10.141678 2024] [proxy:debug] [pid 8047] proxy_util.c(2587): [client 194.163.188.170:59890] AH00944: connecting http://localhost:8095/realms/vserver/protocol/openid-connect/token/introspect to localhost:8095
[Tue Feb 13 16:14:10.141683 2024] [proxy:debug] [pid 8047] proxy_util.c(2810): [client 194.163.188.170:59890] AH00947: connected /realms/vserver/protocol/openid-connect/token/introspect to localhost:8095

So, it looks like the problem is the Keycloak proxy setting:

  <Location /keycloak/>
    ProxyPass        http://localhost:8095/
    ProxyPassReverse http://localhost:8095/
    Header           unset X-Frame-Options
    Require          all granted
  </Location>

So the introspection access arrives back at Apache and is proxied locally without the /keycloak. This is how the webapp accesses work, but it breaks CLI accesses via mod_oauth2. This has got my head spinning a bit - I'll post a fix when I find it.

[EML-github]

It turns out that, if you get everything else right, this path mismatch doesn't actually matter - Keycloak is smart enough to fix it up and then returns an 'active:true'.

On the logging issue: I've seen other people complaining about this, but the answer is basically that you can't have multiple LogLevel directives; they over-write each other. This single server-level directive turns on all relevant logging (the dump_io module is required to get the headers):

DumpIOInput  On
DumpIOOutput On
LogLevel     debug dumpio:trace7 rewrite:trace6