Shibboleth Developers

[Paul Hethmon <>]

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