Logging improvements for message tracing
Description
Environment
Activity
Scott CantorApril 4, 2024 at 11:46 AM
That’s fair, yet more reasons why shared secrets should never have made a comeback.

Henri MikkonenApril 4, 2024 at 7:23 AMEdited
Included the pretty-printing of the following token payloads on TRACE for the following appenders:
PROTOCOL_MESSAGE.OAUTH2:
request objects - both direct (
request=...
) and via reference (request_uri=...
)JWT access tokens
JWT refresh tokens
PROTOCOL_MESSAGE.OIDC:
ID tokens
Back-channel logout tokens
Similarly to pretty-printing the JSON request/response messages, by default, the shibboleth.oidc.JSONObjectMapper bean is exploited, but a custom ObjectMapper bean may be wired via idp.oidc.logging.objectMapper
-property.

Henri MikkonenApril 4, 2024 at 7:16 AM
I would probably suiggest using DEBUG and not TRACE, I think that’s what we do with the SAML protocol loggers. We just use the category to limit when they show up.
During the previous work on protocol message logging, I believe the main reason for leaving these raw OAuth2-protocol messages on TRACE was that in many cases they contain the raw client secrets. On DEBUG the protocol messages contain the authentication method (e.g. ...clientAuthentication=ClientAuthentication{clientId=test_rp_saml, method=client_secret_basic}...
, as TRACE reveals the all the raw headers including Authorization:[Basic dGV...
in that case.
Scott CantorMarch 14, 2024 at 12:48 PM
I would probably suiggest using DEBUG and not TRACE, I think that’s what we do with the SAML protocol loggers. We just use the category to limit when they show up.
My personal preference would be to log anything relevant to the protocol in the PROTOCOL_MESSAGE.OAUTH2 category (I guess we could also do OIDC there as a suffix for things specific to it, most people will be logging all or nothing anyway).
But honestly as long as it’s clear how to do it, that’s all that matters. The formatting there is a vast improvement, thank you.

Henri MikkonenMarch 14, 2024 at 12:12 PM
After just committed change, an example of the token response protocol message on TRACE is as follows:
2024-03-14 14:07:57,313 - - TRACE [PROTOCOL_MESSAGE.OAUTH2:165] - Outbound response
Headers:
Cache-Control:no-store
Content-Type:application/json; charset=UTF-8
Pragma:no-cache
Content:{
"access_token" : "PXR5ServerAXXXAAdzZWNyZXQyQF_EU3hsU1PWEYo9pw9V4P8VxTZD_tUnzmxW9MimW6WXai3dEsUwhmNGhnNeL0VScKARN6dOBNtMZwLIExF9RXixgLaxxC3N3KKA7uANjhbWe1PAXJjtQOA-8n3dMFp223JBbau5siJVin-ozBo1bOpdgs148oRDzjC8n-dc2VbvATAyUOr7QQ4jwstQ_O5m3IT_5bf7O38R1UPPSwS5FCJhxMQ_wJX9U4snra8WMc29vwGNTtO4Hg3oMKVi5WD7ES_2eop4mmnXJWiKcSjIunOiXRcAarB7-7Y3_AMKSQkqjcK2ZQBD5FtlsVNYR6dvOz5z8u8UDGLOpV4GDkg4zjjwpAeUbxSlAXOElnTxcjPCN86npCHC2eEtNIxQMoP1HA",
"scope" : "openid profile email",
"id_token" : "eyJraWQiOiJ0ZXN0a2V5UlMiLCJhbGciOiJSUzI1NiJ9.eyJhdF9oYXNoIjoiNDlnSjZBekplTnFWX1BVQjRhcTF2QSIsInN1YiI6Im1vY2siLCJhdWQiOiJtb2NrU2FtbENsaWVudElkIiwiY3VzdG9tRW1haWxOYW1lIjoiamRvZUBleGFtcGxlLm9yZyIsImF1dGhfdGltZSI6MTcxMDQxODA3NywiaXNzIjoiaHR0cHM6Ly9vcC5leGFtcGxlLm9yZyIsImV4cCI6MTcxMDQyMTY3NywiaWF0IjoxNzEwNDE4MDc3fQ.jZiMQuySdAGrQ_auTnVQcWxz8DxatGVwNmynN1YbCaCBi-bUgZ-a2zQOaeoTJR11n5YQrv8xQzdgA2ZItU5vjeLIHiJgySxg9HFfW5Tgp3RreRH4ZmqMtOjqbH1gaRtR7esmsrpJNEeu-A4TMVD_DowDe40_gspI04PL-PtC1hW4RFU-O7iTGeptFr8pKnkSQjpsIQuHk2km25MVITkX_6b5nyuwM18ANrXVu42hmGx0GOldmSJ7Ns_PzF0FmYXrcPChRCXjc9TxR69uK0ravgpFgeCAMxxDTUkOyJVjW7D8imu-W5lfQQLXLevqyVZ9li_VHt3PQMB72x-T1-Pfkw",
"token_type" : "Bearer",
"expires_in" : 600
}
(Previously the JSON was on single line.)
Secondly, it would be really nice to see traces of all the JWTs issued in JSON form and not strictly as encoded JOSE objects since those aren’t readable.
@Scott Cantor Should the contents of tokens (especially id_token in the example above) be human-readable in the protocol message trace, or is it satisfactory to have them human-readable via some other logger? Most probably from the logger of the SWF action that’s constructing the token?
Details
Assignee
Henri MikkonenHenri MikkonenReporter
Scott CantorScott CantorComponents
Fix versions
Details
Details
Assignee

I’d like to see some enhancements to the message logging if possible. Highest priority would be if Jackson supports some kind of pretty-printing option as it’s very hard to see things all jammed on one line.
Secondly, it would be really nice to see traces of all the JWTs issued in JSON form and not strictly as encoded JOSE objects since those aren’t readable.