New principal name is not updated to loginContext?

[Jani Hautam ä ki]

I am seeing some unexpected behaviour when I authenticate more than once
without clearing cookies from the browser in between the authentications.

I am using Shibboleth IdP v2.3.8, and the configuration is quite typical
I guess, but there's one exception from the "default" configuration:
<ph:LoginHandler xsi:type="ph:PreviousSession"> has been disabled from
handler.xml to help in the development of a localized version of login.jsp.
That way I'm able to get to the login page again when the SP makes the  
request, even though I just successfully authenticated myself.

That's the background, and here are the steps to (hopefully) reproduce
the strange behaviour:

The first time I authenaticate as "testi", everything goes well. The  
second time
(with cookies NOT cleared), I'll authenticate as "lhOBu". I am sent  
back to SP's
web page, but this time, however, the attributes sent to SP are not lhOBu's as
they should. Instead, the IdP resolves attributes for the first user account
     authenticated.

This is more clear from the logs.

The first authentication with the user "testi" has been made, and this log
excerpt is from the second authentication with user "lhOBu":

12:56:04.764 - TRACE  
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109]  
- Attempting to retrieve IdP session cookie.
12:56:04.765 - TRACE  
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:115]  
- Found IdP session cookie.
12:56:04.766 - TRACE  
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:75]  
- Updating IdP session activity time and adding session object to the  
request
12:56:04.766 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:170] - Attempting to authenticate user  
lhOBu
12:56:04.797 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:178] - Successfully authenticated user  
lhOBu
12:56:04.798 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:144] -  
Returning control to authentication engine
12:56:04.798 - TRACE  
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:335] -  
Looking up LoginContext with key e4d97882-48ce-4b25-a5cf-32a25daf3bfa  
from StorageService parition: loginContexts
12:56:04.799 - TRACE  
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:341] -  
Retrieved LoginContext with key e4d97882-48ce-4b25-a5cf-32a25daf3bfa  
from StorageService parition: loginContexts
12:56:04.800 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -  
Processing incoming request
12:56:04.800 - TRACE  
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:335] -  
Looking up LoginContext with key e4d97882-48ce-4b25-a5cf-32a25daf3bfa  
from StorageService parition: loginContexts
12:56:04.801 - TRACE  
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:341] -  
Retrieved LoginContext with key e4d97882-48ce-4b25-a5cf-32a25daf3bfa  
from StorageService parition: loginContexts

So far so good, but here:

12:56:04.802 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:514] -  
Completing user authentication process
12:56:04.802 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:585] -  
Validating authentication was performed successfully
12:56:04.803 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:696] -  
Updating session information for principal lhOBu
12:56:04.803 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:560] -  
User testi authenticated with method  
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
12:56:04.804 - DEBUG  
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] -  
Returning control to profile handler

This suggests that during updateUserSession() the method
authenticationPrincipal.getName() returns "lhOBu" which is as I expected,
but after that the control returns to the completeAuthentication() where
the call loginContext.getPrincipalName() returns the principal name who did
authenticated earlier - not the one that has just authenticated and whose
attributes should be sent to the SP. Instead, SP receives the attributes of
the earlier principal.

Could it be that the object "loginContext" does not get updated
when there's an existing session? Or is this a configuration or a user error?

--
Jani Hautamaki