Quick tip: Logging Outgoing HTTP Requests in Keycloak Server

Hello Keycloak Users,

If you want to debug the outgoing http-client requests sent from Keycloak via the HttpClientProvider used by SimpleHTTP that are for example used for backchannel logout requests, you could configure the following:

Configure the following JVM System Property:
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog

… and configure the following loggers via JBoss CLI configuration:

echo SETUP: Configure HTTP log levels
/subsystem=logging/logger=org.apache.http:add(level=${env.KEYCLOAK_LOGLEVEL_HTTP_CLIENT:DEBUG})
/subsystem=logging/logger=org.apache.http.wire:add(level=${env.KEYCLOAK_LOGLEVEL_HTTP_CLIENT_WIRE:DEBUG})

This leads to log entries on DEBUG level similar to the following lines:

acme-keycloak_1  | 11:56:24,161 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 >> "GET /auth/realms/acme-internal/protocol/openid-connect/userinfo HTTP/1.1[\r][\n]"
acme-keycloak_1  | 11:56:24,161 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 >> "Authorization: Bearer eyJh....KdyG0VkaP8iyg[\r][\n]"
acme-keycloak_1  | 11:56:24,161 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 >> "Host: id.acme.test:8443[\r][\n]"
acme-keycloak_1  | 11:56:24,161 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
acme-keycloak_1  | 11:56:24,161 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.13 (Java/11.0.12)[\r][\n]"
acme-keycloak_1  | 11:56:24,161 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]"
acme-keycloak_1  | 11:56:24,161 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 >> "[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "Cache-Control: no-cache[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "X-XSS-Protection: 1; mode=block[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "X-Frame-Options: SAMEORIGIN[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "Referrer-Policy: no-referrer[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "Date: Thu, 09 Sep 2021 11:56:24 GMT[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "Connection: keep-alive[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "Strict-Transport-Security: max-age=31536000; includeSubDomains[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "X-Content-Type-Options: nosniff[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "Content-Type: application/json[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "Content-Length: 199[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "[\r][\n]"
acme-keycloak_1  | 11:56:24,173 DEBUG [org.apache.http.wire] (default task-1) http-outgoing-0 << "{"sub":"c3d4da23-fe54-473b-a9aa-aa6d4615a571","email_verified":true,"name":"Theo Tester","preferred_username":"tester","locale":"en","given_name":"Theo","family_name":"Tester","email":"tester@local"}"
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << HTTP/1.1 200 OK
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << Cache-Control: no-cache
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << X-XSS-Protection: 1; mode=block
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << X-Frame-Options: SAMEORIGIN
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << Referrer-Policy: no-referrer
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << Date: Thu, 09 Sep 2021 11:56:24 GMT
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << Connection: keep-alive
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << Strict-Transport-Security: max-age=31536000; includeSubDomains
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << X-Content-Type-Options: nosniff
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << Content-Type: application/json
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.headers] (default task-1) http-outgoing-0 << Content-Length: 199
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.impl.execchain.MainClientExec] (default task-1) Connection can be kept alive indefinitely
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] (default task-1) Connection [id: 0][route: {s}->https://id.acme.test:8443] can be kept alive indefinitely
acme-keycloak_1  | 11:56:24,174 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] (default task-1) http-outgoing-0: set socket timeout to 0
acme-keycloak_1  | 11:56:24,175 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] (default task-1) Connection released: [id: 0][route: {s}->https://id.acme.test:8443][total available: 1; route allocated: 1 of 64; total allocated: 1 of 128]

Cheers,
Thomas

9 Likes