Logging improvements for message tracing

Description

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.

Environment

None

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 AM
Edited

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.

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?

Completed

Details

Assignee

Reporter

Fix versions

Created January 23, 2024 at 3:20 PM
Updated April 4, 2024 at 11:47 AM
Resolved April 4, 2024 at 11:47 AM