Shibboleth Developers

[Chad La Joie <>]

I doubt there is a bug here, just a misunderstanding of how things
actually work.

When you log in to the first SP the IdP creates a session for you.
Within that session is a Subject.  A Subject can contain multiple
Principals.  As you perform more authentication events those Principals
get added to the Subject.  Any of those principals is considered a valid
identifier for the user.

Now, by turning off the previous session login handler you've
essentially told the IdP to always for authentication.  So every time an
SP makes and authn request the IdP is going to prompt for
authentication.  Since the user has a session already each time the user
authenticates they're going to pick up a new Principal in their Subject.

Now, Subject treats Principals as a set (i.e. unordered, no duplicates,
no null).  So when getPrincpalName is called, on the session, the first
of an unordered collection is returned.  So, I'm guessing, if you look
in to the Subject you'll see two UsernamePrincipals, one saying 'user1'
and one saying 'user2'.  Which is exactly what you told the IdP was
supposed to happen.

On 3/31/10 9:54 PM, Paul Hethmon wrote:
> Ok, here¹s the short scenario:
> 
> 1. User accesses SP with browser, redirected to IdP
> 2. Login at IdP with principal name of "user2"
> 3. Logout locally at the SP, not a SLO/SAML logout, just kill session with
> SP
> 4. With same browser, second user accesses SP, redirected
> 5. Login at IdP with principal name of "user1"
> 6. SP receives NameID of "user2" and not "user1"
> 
> Shibboleth 2.1.5 with SLO (though not using). The PreviousSession handler is
> not enabled.
> 
> Here's a log snippet of the first login, the first few lines showing my
> login servlet reporting the login id.
> 
> 20:19:03.493 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:612] -
> [http-172.16.14.216-80-3:] - user2 -- User authentication successful,
> returning to AuthenticationEngine.
> 20:19:03.493 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1204] -
> [http-172.16.14.216-80-3:] - user2 -- Submiting transactionID of
> [a14ea875-0452-4958-adb6-111569030f5f-4b6ab11f] with result [true]
> 20:19:04.111 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1250] -
> [http-172.16.14.216-80-3:] - user2 -- HTTP status is OK for transactionID of
> [a14ea875-0452-4958-adb6-111569030f5f-4b6ab11f]
> 20:19:04.111 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1262] -
> [http-172.16.14.216-80-3:] - user2 -- releasing HTTP connection
> 20:19:04.112 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:143] -
> [http-172.16.14.216-80-3:] - Returning control to authentication engine
> 20:19:04.112 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:296] -
> [http-172.16.14.216-80-3:] - LoginContext not bound to HTTP request,
> retrieving it from storage service
> 20:19:04.112 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:307] -
> [http-172.16.14.216-80-3:] - LoginContext key is
> 'cc3f3333-16f2-4e81-a1e5-dc7fcfefeb8d'
> 20:19:04.112 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:310] -
> [http-172.16.14.216-80-3:] - parition: loginContexts
> 20:19:04.113 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:198] -
> [http-172.16.14.216-80-3:] - Processing incoming request
> 20:19:04.113 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:296] -
> [http-172.16.14.216-80-3:] - LoginContext not bound to HTTP request,
> retrieving it from storage service
> 20:19:04.113 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:307] -
> [http-172.16.14.216-80-3:] - LoginContext key is
> 'cc3f3333-16f2-4e81-a1e5-dc7fcfefeb8d'
> 20:19:04.113 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:310] -
> [http-172.16.14.216-80-3:] - parition: loginContexts
> 20:19:04.113 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:477] -
> [http-172.16.14.216-80-3:] - Completing user authentication process
> 20:19:04.113 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:537] -
> [http-172.16.14.216-80-3:] - Validating authentication was performed
> successfully
> 20:19:04.113 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:640] -
> [http-172.16.14.216-80-3:] - Updating session information for principal
> user2
> 20:19:04.114 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:657] -
> [http-172.16.14.216-80-3:] - Recording authentication and service
> information in Shibboleth session for principal: user2
> 20:19:04.114 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:512] -
> [http-172.16.14.216-80-3:] - User user2 authenticated with method
> urn:oasis:names:tc:SAML:2.0:ac:classes:Password
> 20:19:04.114 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:160] -
> [http-172.16.14.216-80-3:] - Returning control to profile handler
> 20:19:04.114 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:296] -
> [http-172.16.14.216-80-3:] - LoginContext not bound to HTTP request,
> retrieving it from storage service
> 20:19:04.114 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:307] -
> [http-172.16.14.216-80-3:] - LoginContext key is
> 'cc3f3333-16f2-4e81-a1e5-dc7fcfefeb8d'
> 
> So the response from that goes back to the SP just fine. Then the local SP
> logout and another login. Here as it comes in:
> 
> 20:19:43.829 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:181
> ] - [http-172.16.14.216-80-3:] - Creating login context and transferring
> control to authentication engine
> 20:19:43.831 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:198] -
> [http-172.16.14.216-80-3:] - Processing incoming request
> 20:19:43.831 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:228] -
> [http-172.16.14.216-80-3:] - Beginning user authentication process.
> 20:19:43.831 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:232] -
> [http-172.16.14.216-80-3:] - Existing IdP session available for principal
> user2
> 20:19:43.831 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:334] -
> [http-172.16.14.216-80-3:] - Filtering configured login handlers by
> requested athentication methods.
> 
> So Shib if finding the session cookie and connecting it to the first
> principal name. We then go into authentication:
> 
> 20:19:52.030 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:612] -
> [http-172.16.14.216-80-3:] - user1 -- User authentication successful,
> returning to AuthenticationEngine.
> 20:19:52.031 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1204] -
> [http-172.16.14.216-80-3:] - user1 -- Submiting transactionID of
> [42e06f6a-4510-4e10-ae8b-08d2ef8d49c5-b0a22f5e] with result [true]
> 20:19:52.371 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1250] -
> [http-172.16.14.216-80-3:] - user1 -- HTTP status is OK for transactionID of
> [42e06f6a-4510-4e10-ae8b-08d2ef8d49c5-b0a22f5e]
> 20:19:52.372 - DEBUG
> [com.clareity.jaguar.shibboleth.authn.ClareityLoginServlet:1262] -
> [http-172.16.14.216-80-3:] - user1 -- releasing HTTP connection
> 20:19:52.373 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:143] -
> [http-172.16.14.216-80-3:] - Returning control to authentication engine
> 20:19:52.373 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:296] -
> [http-172.16.14.216-80-3:] - LoginContext not bound to HTTP request,
> retrieving it from storage service
> 20:19:52.373 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:307] -
> [http-172.16.14.216-80-3:] - LoginContext key is
> 'ac4785e3-c88f-43f0-a9f2-9df16033018d'
> 20:19:52.373 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:310] -
> [http-172.16.14.216-80-3:] - parition: loginContexts
> 20:19:52.373 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:198] -
> [http-172.16.14.216-80-3:] - Processing incoming request
> 20:19:52.374 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:296] -
> [http-172.16.14.216-80-3:] - LoginContext not bound to HTTP request,
> retrieving it from storage service
> 20:19:52.374 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:307] -
> [http-172.16.14.216-80-3:] - LoginContext key is
> 'ac4785e3-c88f-43f0-a9f2-9df16033018d'
> 20:19:52.374 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:310] -
> [http-172.16.14.216-80-3:] - parition: loginContexts
> 20:19:52.374 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:477] -
> [http-172.16.14.216-80-3:] - Completing user authentication process
> 20:19:52.374 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:537] -
> [http-172.16.14.216-80-3:] - Validating authentication was performed
> successfully
> 20:19:52.374 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:640] -
> [http-172.16.14.216-80-3:] - Updating session information for principal
> user1
> 20:19:52.375 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:657] -
> [http-172.16.14.216-80-3:] - Recording authentication and service
> information in Shibboleth session for principal: user1
> 20:19:52.375 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:512] -
> [http-172.16.14.216-80-3:] - User user1 authenticated with method
> urn:oasis:names:tc:SAML:2.0:ac:classes:Password
> 20:19:52.375 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:160] -
> [http-172.16.14.216-80-3:] - Returning control to profile handler
> 20:19:52.375 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:296] -
> [http-172.16.14.216-80-3:] - LoginContext not bound to HTTP request,
> retrieving it from storage service
> 20:19:52.375 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:307] -
> [http-172.16.14.216-80-3:] - LoginContext key is
> 'ac4785e3-c88f-43f0-a9f2-9df16033018d'
> 20:19:52.375 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:310] -
> [http-172.16.14.216-80-3:] - parition: loginContexts
> 20:19:52.376 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:170] -
> [http-172.16.14.216-80-3:] - Returning control to profile handler at:
> /profile/SAML2/Redirect/SSO
> 20:19:52.376 - INFO [Shibboleth-Access:73] - [http-172.16.14.216-80-3:] -
> 20100401T011952Z|172.16.14.9|idp.winnipeg.safemls.net:80|/profile/SAML2/Redi
> rect/SSO|
> 20:19:52.376 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85
> ] - [http-172.16.14.216-80-3:] - shibboleth.HandlerManager: Looking up
> profile handler for request path: /SAML2/Redirect/SSO
> 20:19:52.376 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:93
> ] - [http-172.16.14.216-80-3:] - shibboleth.HandlerManager: Located profile
> handler of the following type for the request path:
> edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
> 20:19:52.376 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:148
> ] - [http-172.16.14.216-80-3:] - Incoming request contains a login context,
> processing as second leg of request
> 20:19:52.377 - DEBUG
> [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRely
> ingPartyConfigurationManager:126] - [http-172.16.14.216-80-3:] - Looking up
> relying party configuration for http://macbook/saml/sp
> 20:19:52.377 - DEBUG
> [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRely
> ingPartyConfigurationManager:132] - [http-172.16.14.216-80-3:] - No custom
> relying party configuration found for http://macbook/
> saml/sp, looking up configuration based on metadata groups.
> 20:19:52.377 - DEBUG
> [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRely
> ingPartyConfigurationManager:155] - [http-172.16.14.216-80-3:] - No custom
> or group-based relying party configuration found for
> http://macbook/saml/sp. Using default relying party configuration.
> 20:19:52.379 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileH
> andler:459] - [http-172.16.14.216-80-3:] - Resolving attributes for
> principal 'user2' for SAML request from relying party 'http:
> //macbook/saml/sp'
> 20:19:52.379 - DEBUG
> [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.Shib
> bolethAttributeResolver:118] - [http-172.16.14.216-80-3:] -
> shibboleth.AttributeResolver resolving attributes for principal user2
> 20:19:52.379 - DEBUG
> [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.Shib
> bolethAttributeResolver:249] - [http-172.16.14.216-80-3:] - Specific
> attributes for principal user2 were not requested, resolving all attributes.
> 
> So we've authenticated as "user1" at this point, but after seeing Shib with
> "user1", it switches to "user2".
> 
> In my servlet, I am using:
> 
> request.setAttribute(LoginHandler.PRINCIPAL_NAME_KEY, loginId);
> 
> To set the principal name.
> 
> In the method AuthenticationEngine.getLoginHandlerSubject, we have:
> 
>     protected Subject getLoginHandlerSubject(HttpServletRequest httpRequest)
>       throws AuthenticationException {
>       
>       Subject subject = (Subject)
>         httpRequest.getAttribute(LoginHandler.SUBJECT_KEY);
>       Principal principal = (Principal)
>         httpRequest.getAttribute(LoginHandler.PRINCIPAL_KEY);
>       String principalName = DatatypeHelper.safeTrimOrNullString((String)
>         httpRequest.getAttribute(LoginHandler.PRINCIPAL_NAME_KEY));
> 
>       if (subject == null && (principal != null || principalName != null)) {
>         subject = new Subject();
>         if (principal == null) {
>           principal = new UsernamePrincipal(principalName);
>         }
>         subject.getPrincipals().add(principal);
>       }
> 
>       return subject;
>     }
> 
> So I'm only ever setting the principalName value, which appears to be ok
> according to the javadocs for LoginHandler.java. But looking at this code,
> if the previous session created an actual Principal (which it would) and
> kept it with the session (and then the subsequent request), then my new
> principalName would be ignored.
> 
> So after writing all of this, it seems evident I need to go ahead and create
> a Principal object in my code and set it in the request to replace anything
> that might be there, so I'll be trying that in a few minutes.
> 
> If that does work and I get the principal I expect, I'll file a bug.
> 
> Apologies for the horrendous formatting of the email, Entourage is the one
> MS program I still have to use.
> 
> thanks,
> 
> Paul
> 
> 
> 

-- 
Chad La Joie
www.itumi.biz
trusted identities, delivered