debug code does not display expected output (claims or scopes)

[dominique-p]

It seems that some debugging code does not display the expected values in the following log lines:

2017-01-20 17:05:10,105 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:229] - Response will contain the following scopes
2017-01-20 17:05:10,107 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
...
2017-01-20 17:05:10,122 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:282] - Final claims for system scope address are
2017-01-20 17:05:10,123 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:274] - Processing system scope phone for the following claims: [phone_number_verified, phone_number]
2017-01-20 17:05:10,124 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:282] - Final claims for system scope phone are
2017-01-20 17:05:10,124 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:233] - Response will contain the following claims for scopes
2017-01-20 17:05:10,524 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do

One would expect a list of claims after "Final claims for system scope phone are" and "Response will contain the following claims for scopes" and a list of scopes after "Response will contain the following scopes". At least this what the code should do, cf. https://github.com/uchicago/shibboleth-oidc/blob/master/idp-oidc-impl/src/main/java/net/shibboleth/idp/oidc/flow/PreAuthorizeUserApprovalAction.java#L282 https://github.com/uchicago/shibboleth-oidc/blob/master/idp-oidc-impl/src/main/java/net/shibboleth/idp/oidc/flow/PreAuthorizeUserApprovalAction.java#L233 https://github.com/uchicago/shibboleth-oidc/blob/master/idp-oidc-impl/src/main/java/net/shibboleth/idp/oidc/flow/PreAuthorizeUserApprovalAction.java#L229

Note: the above log lines were extracted from the log posted in another issue's comment: https://github.com/uchicago/shibboleth-oidc/issues/30#issuecomment-274073279

[dominique-p]

Blow you'll find a patch to PreAuthorizeUserApprovalAction.java that fixes the issue. I thought it would help me to see more details about my other issue https://github.com/uchicago/shibboleth-oidc/issues/30#issuecomment-274073279 but it did not bring anything new. :-(

diff PreAuthorizeUserApprovalAction.java.01 PreAuthorizeUserApprovalAction.java
229c229
<         log.debug("Response will contain the following scopes", sortedScopes);
---
>         log.debug("Response will contain the following scopes {}", sortedScopes);
233c233
<         log.debug("Response will contain the following claims for scopes", claimsForScopes.keySet());
---
>         log.debug("Response will contain the following claims for scopes {}", claimsForScopes.keySet());
282c282
<                 log.debug("Final claims for system scope {} are", systemScope.getValue(), claimValues);
---
>                 log.debug("Final claims for system scope {} are {}", systemScope.getValue(), claimValues);

[mmoayyed]

Excellent. Would you mind turning these into a pull request? Are you familiar with that process?

[dominique-p]

Not yet, though I am learning... :-)

But the old school patch command should work for you: patch -b PreAuthorizeUserApprovalAction.java /tmp/PreAuthorizeUserApprovalAction.java.patch.txt

Note: The attached patch file was generated with diff -u PreAuthorizeUserApprovalAction.java.01 PreAuthorizeUserApprovalAction.java >/tmp/PreAuthorizeUserApprovalAction.java.patch.txt

PreAuthorizeUserApprovalAction.java.patch.txt

[mmoayyed]

Thank you. This is fixed, and I also found a few other instances where placeholders for logs were mismatched. Pushed.