Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Shibboleth: tooling for debugging SAML assertions #2916

Closed
pdurbin opened this issue Feb 4, 2016 · 5 comments
Closed

Shibboleth: tooling for debugging SAML assertions #2916

pdurbin opened this issue Feb 4, 2016 · 5 comments
Assignees
@kcondon
Labels
Component: Code Infrastructure formerly "Feature: Code Infrastructure" Feature: Account & User Info Feature: Superuser Dashboard Type: Feature a feature request
Milestone
4.4

Comments

@pdurbin
Copy link
Member

pdurbin commented Feb 4, 2016

When chatting with @ecr2c @shlake and others about troubles they've had getting Shibboleth configured I mentioned over the phone and later in a support ticket that there's an undocumented database setting that may help them reason about assertions being made via SAML by their Identity Provider by increasing logging in the Glassfish's server.log.

This issue is about either making that (or another) database setting official by documenting it or at least documenting how to increase the logging level as explained at http://guides.dataverse.org/en/4.2.3/developers/debugging.html (as well as making sure debugging lines are logged at appropriate levels).
@pdurbin pdurbin self-assigned this Feb 4, 2016
@pdurbin pdurbin mentioned this issue Feb 9, 2016
Closed
20 tasks
@pdurbin pdurbin mentioned this issue Mar 3, 2016
Closed
pdurbin added a commit that referenced this issue Mar 3, 2016
@pdurbin
Shib: add more debug logging #2916 #2939
f901d9f 
- Some debugging relates to groups #105
- Some code cleanup.
@pdurbin
Copy link
Member Author

pdurbin commented Mar 3, 2016

I just pushed f901d9f to the 2939-shib branch. I decide that more logging is really what sysadmins need so I added more, including information about Shibboleth groups (all groups really). This is not controlled by a database setting anymore. As I hinted at above, you can just change the logging level on the fly by following http://guides.dataverse.org/en/4.2.3/developers/debugging.html . Mostly for @kcondon 's benefit when testing all of #2939 I left the logging level at "info" but we can reduce some or all of it to "fine" to only show by default what's most important or interesting. As of this writing, here's how it looks when a new user logs in via Shib and clicks the button to confirm the creation of the account:

[2016-03-03T14:18:04.209-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684209] [levelValue: 800] [[
  shib values: [Shib-Identity-Provider: https://idp.testshib.org/idp/shibboleth, eppn: myself@testshib.org, uid: myself, cn: Me Myself And I, givenName: Me Myself, sn: And I, telephoneNumber: 555-5555, affiliation: Member@testshib.org;Staff@testshib.org, unscoped-affiliation: Member;Staff, entitlement: urn:mace:dir:entitlement:common-lib-terms, persistent-id: https://idp.testshib.org/idp/shibboleth!https://shibtest.dataverse.org/sp!RuyCiLvUcgmKqyh/rOQPh+wyR7s=]]]

[2016-03-03T14:18:04.210-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684210] [levelValue: 800] [[
  The SAML assertion for "Shib-Identity-Provider" (required) was "https://idp.testshib.org/idp/shibboleth".]]

[2016-03-03T14:18:04.210-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684210] [levelValue: 800] [[
  The SAML assertion for "eppn" (required) was "myself@testshib.org".]]

[2016-03-03T14:18:04.211-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684211] [levelValue: 800] [[
  The SAML assertion for "givenName" (required) was "Me Myself".]]

[2016-03-03T14:18:04.211-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684211] [levelValue: 800] [[
  The SAML assertion for "sn" (required) was "And I".]]

[2016-03-03T14:18:04.211-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684211] [levelValue: 800] [[
  The SAML assertion for "mail" was null. Please contact support.]]

[2016-03-03T14:18:04.211-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684211] [levelValue: 800] [[
  For https://idp.testshib.org/idp/shibboleth (which as of this writing doesn't provide the mail attribute) setting email address to value of eppn: myself@testshib.org]]

[2016-03-03T14:18:04.211-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684211] [levelValue: 800] [[
  The SAML assertion for "uid" (optional) was "myself".]]

[2016-03-03T14:18:04.211-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684211] [levelValue: 800] [[
  friendly looking identifer (backend will enforce uniqueness):myself]]

[2016-03-03T14:18:04.257-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684257] [levelValue: 800] [[
  Trying to get affiliation from disco feed URL: https://shibtest.dataverse.org/Shibboleth.sso/DiscoFeed]]

[2016-03-03T14:18:04.288-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684288] [levelValue: 800] [[
  Couldn't find authenticated user based on https://idp.testshib.org/idp/shibboleth|myself@testshib.org]]

[2016-03-03T14:18:04.290-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.authorization.AuthenticationServiceBean] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684290] [levelValue: 800] [[
  no user found using myself@testshib.org]]

[2016-03-03T14:18:04.290-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=53 _ThreadName=jk-connector(3)] [timeMillis: 1457032684290] [levelValue: 800] [[
  Debug summary: Could not find an auth user based on email address (state: PROMPT_TO_CREATE_NEW_ACCOUNT).]]

[2016-03-03T14:18:09.739-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=54 _ThreadName=jk-connector(4)] [timeMillis: 1457032689739] [levelValue: 800] [[
  created user @myself]]

[2016-03-03T14:18:09.747-0500] [glassfish 4.1] [INFO] [] [edu.harvard.iq.dataverse.Shib] [tid: _ThreadID=54 _ThreadName=jk-connector(4)] [timeMillis: 1457032689747] [levelValue: 800] [[
  Groups for user 11 (@myself): [Authenticated Users (:authenticated-users), All Users (:AllUsers), All testshib.org Shibboleth Users (&shib/2)]]]

When I was working on this I was reminded of http://stackoverflow.com/questions/30193117/iterate-through-all-servletrequest-attributes#comment49933342_30193117 and http://shibboleth.1660669.n2.nabble.com/Why-doesn-t-Java-s-request-getAttributeNames-show-Shibboleth-attributes-tp7616427p7616591.html but I couldn't figure out how to print out JkEnvVar. Oh well, I left a reminder in the code about this.

Also, #105 about a GUI to see what groups you are in is out of scope for the current effort underway in #2939 but I did add a little bit of debug output which you can see in the last line of output above. I think this will come in handy when Shib groups are tested in #1533 (or whatever issue we use to verify that institutional groups developed in #1401 are still working).

A lot of the debugging code is in edu.harvard.iq.dataverse.Shib but I'm hoping to rename this to edu.harvard.iq.dataverse.authorization.providers.shib.ShibPage to get it out of the default package and get in line with our naming convention for backing beans. Once that is done I can document how to increase the logging level and just refer to the whole "shib" package.

pdurbin added a commit that referenced this issue Mar 8, 2016
@pdurbin
improved Shibboleth docs #2953 #2939
21bd0e8 
- Documente API to migrate Shib user to local #2915.
- Add Debugging section for #2916.
- Document identity federation stuff #2937.
- Reference :AllowSignup as part of "remote only" #2838.
@bencomp
Copy link
Contributor

bencomp commented Mar 9, 2016

I like where you're going with this, @pdurbin. :)
In the long run I'd like this information logged in a single line (or object of some sort), so that I don't have to collate related log messages during automated processing of logs.

@pdurbin pdurbin mentioned this issue Mar 9, 2016
Closed
pdurbin added a commit that referenced this issue Mar 15, 2016
@pdurbin
Shib: remove old debugging code #2916 #2939
5c19ca0
@pdurbin pdurbin mentioned this issue Mar 16, 2016
Merged
11 tasks
@pdurbin
Copy link
Member Author

pdurbin commented Mar 18, 2016

@bencomp please try out the war file at https://build.hmdc.harvard.edu:8443/job/shibtest.dataverse.org-build-2939-shib/1/edu.harvard.iq$dataverse/artifact/edu.harvard.iq/dataverse/4.3/dataverse-4.3.war and let me know what you think. I'm happy to make adjustments.

I'm passing this issue to QA. Shibboleth debugging is no longer tied to a boolean in the database. Rather than showing stuff in the UI which is confusing for users, I added more logging and documented how you can control the verbosity at http://guides.dataverse.org/en/2939-shib/installation/shibboleth.html#debugging

The fix is in pull request #3025.

@pdurbin pdurbin assigned kcondon and unassigned pdurbin Mar 18, 2016
@pdurbin pdurbin mentioned this issue Mar 28, 2016
Closed
pdurbin added a commit that referenced this issue Mar 30, 2016
@pdurbin
Shib: turn down logging #2916 #3034
af72a7b
@pdurbin
Copy link
Member Author

pdurbin commented Mar 30, 2016

In af72a7b I turned down the Shib logging. As @kcondon and I discussed, the way to turn it back up is at runtime as described at http://guides.dataverse.org/en/2939-shib/installation/shibboleth.html#debugging

@kcondon
Copy link
Contributor

kcondon commented Mar 31, 2016

OK, works, closing.

@kcondon kcondon closed this as completed Mar 31, 2016
@pdurbin pdurbin added this to the 4.4 milestone Jun 30, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@kcondon kcondon

Labels
Component: Code Infrastructure formerly "Feature: Code Infrastructure" Feature: Account & User Info Feature: Superuser Dashboard Type: Feature a feature request
Projects
None yet
Milestone
4.4
Development

No branches or pull requests
3 participants
@pdurbin @bencomp @kcondon