Need to modify AuthnContextClassRef in ExternalAuth

Tue Dec 22 12:06:12 EST 2015

OK,

I actually got a slightly different result on this go, using enriched logs. Here is the relevant log data:

2015-12-22 17:45:06,616 - DEBUG [org.opensaml.storage.impl.client.PopulateClientStorageLoadContext:120] - Profile Action PopulateClientStorageLoadContext: ClientStorageServices requiring load: [shibboleth.ClientSessionStorageService, shibboleth.ClientPersistentStorageService]
2015-12-22 17:45:06,651 - DEBUG [org.opensaml.storage.impl.client.LoadClientStorageServices:203] - Profile Action LoadClientStorageServices: No cookie data present, initializing StorageService 'shibboleth.ClientSessionStorageService' to empty state
2015-12-22 17:45:06,651 - TRACE [org.opensaml.storage.impl.client.ClientStorageService:411] - StorageService shibboleth.ClientSessionStorageService: Initializing empty storage state into session
2015-12-22 17:45:06,653 - DEBUG [org.opensaml.storage.impl.client.LoadClientStorageServices:203] - Profile Action LoadClientStorageServices: No cookie data present, initializing StorageService 'shibboleth.ClientPersistentStorageService' to empty state
2015-12-22 17:45:06,653 - TRACE [org.opensaml.storage.impl.client.ClientStorageService:411] - StorageService shibboleth.ClientPersistentStorageService: Initializing empty storage state into session
2015-12-22 17:45:06,657 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:115] - Profile Action InitializeAuthenticationContext: Created authentication context: AuthenticationContext{initiationInstant=2015-12-22T17:45:06.657+01:00, isPassive=false, forceAuthn=true, hintedName=null, potentialFlows=[], activeResults=[], attemptedFlow=null, signaledFlowId=null, authenticationStateMap={}, resultCacheable=true, initialAuthenticationResult=null, authenticationResult=null, completionInstant=1970-01-01T01:00:00.000+01:00}
2015-12-22 17:45:06,663 - DEBUG [net.shibboleth.idp.authn.impl.InitializeRequestedPrincipalContext:111] - Profile Action InitializeRequestedPrincipalContext: Profile configuration does not include any default authentication methods
2015-12-22 17:45:06,668 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.ProcessRequestedAuthnContext:146] - Profile Action ProcessRequestedAuthnContext: AuthnRequest did not contain a RequestedAuthnContext, nothing to do
2015-12-22 17:45:06,742 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:126] - Profile Action PopulateAuthenticationContext: Installing custom PrincipalEvalPredicateFactoryRegistry into AuthenticationContext
2015-12-22 17:45:06,743 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:167] - Profile Action PopulateAuthenticationContext: Installed 1 authentication flows into AuthenticationContext
2015-12-22 17:45:06,747 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedSessionManager:707] - Performing primary lookup on session ID 146abed13771dddaac6b25f0b61e2c8973853af72b0450f87e836ace2f343fbd
2015-12-22 17:45:06,748 - DEBUG [org.opensaml.storage.AbstractMapBackedStorageService:283] - Read failed, context '146abed13771dddaac6b25f0b61e2c8973853af72b0450f87e836ace2f343fbd' not found
2015-12-22 17:45:06,748 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedSessionManager:715] - Primary lookup failed for session ID 146abed13771dddaac6b25f0b61e2c8973853af72b0450f87e836ace2f343fbd
2015-12-22 17:45:06,748 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:131] - Profile Action PopulateSessionContext: No session found for client
2015-12-22 17:45:06,752 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:72] - Profile Action FilterFlowsByForcedAuthn: Retaining flow authn/External, it supports forced authentication
2015-12-22 17:45:06,753 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:84] - Profile Action FilterFlowsByForcedAuthn: Potential authentication flows left after filtering: {authn/External=AuthenticationFlowDescriptor{flowId=authn/External, supportsPassive=true, supportsForcedAuthentication=true, lifetime=3600000, inactivityTimeout=1800000}}
2015-12-22 17:45:06,756 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByPassivity:53] - Profile Action FilterFlowsByPassivity: Request does not have passive requirement, nothing to do
2015-12-22 17:45:06,759 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2015-12-22 17:45:06,762 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:257] - Profile Action SelectAuthenticationFlow: No specific Principals requested
2015-12-22 17:45:06,763 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:269] - Profile Action SelectAuthenticationFlow: Forced authentication requested, selecting an inactive flow
2015-12-22 17:45:06,763 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:334] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/External
2015-12-22 17:45:09,534 - INFO [net.shibboleth.idp.authn.impl.ValidateExternalAuthentication:107] - Profile Action ValidateExternalAuthentication: External authentication succeeded for Subject: [UsernamePrincipal{username=170001010017}, AuthnContextClassRefPrincipal{authnContextClassRef=http://id.elegnamnden.se/loa/1.0/loa3}]
2015-12-22 17:45:09,570 - DEBUG [net.shibboleth.idp.authn.impl.PopulateSubjectCanonicalizationContext:79] - Profile Action PopulateSubjectCanonicalizationContext: Installing 2 canonicalization flows into SubjectCanonicalizationContext
2015-12-22 17:45:09,574 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/x500 for applicability...
2015-12-22 17:45:09,575 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:106] - Profile Action SelectSubjectCanonicalizationFlow: Canonicalization flow c14n/x500 was not applicable to this request
2015-12-22 17:45:09,575 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/simple for applicability...
2015-12-22 17:45:09,575 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:83] - Profile Action SelectSubjectCanonicalizationFlow: Selecting canonicalization flow c14n/simple
2015-12-22 17:45:09,616 - DEBUG [net.shibboleth.idp.authn.AbstractSubjectCanonicalizationAction:226] - Profile Action SimpleSubjectCanonicalization: trimming whitespace of input string '170001010017'
2015-12-22 17:45:09,621 - DEBUG [net.shibboleth.idp.session.impl.DetectIdentitySwitch:148] - Profile Action DetectIdentitySwitch: No previous session found, nothing to do
2015-12-22 17:45:09,626 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeAuthentication:137] - Profile Action FinalizeAuthentication: Canonical principal name was established as '170001010017'
2015-12-22 17:45:09,626 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeAuthentication:186] - Profile Action FinalizeAuthentication: Request did not have explicit authentication requirements, result is accepted
2015-12-22 17:45:09,631 - DEBUG [net.shibboleth.idp.session.impl.UpdateSessionWithAuthenticationResult:221] - Profile Action UpdateSessionWithAuthenticationResult: Creating new session for principal 170001010017
2015-12-22 17:45:09,644 - ERROR [net.shibboleth.idp.authn:-2] - Uncaught runtime exception
net.shibboleth.utilities.java.support.logic.ConstraintViolationException: Storage object was not present in session
	at net.shibboleth.utilities.java.support.logic.Constraint.isNotNull(Constraint.java:227)
2015-12-22 17:45:09,648 - WARN [org.opensaml.profile.action.impl.LogEvent:76] - An error event occurred while processing the request: RuntimeException
2015-12-22 17:45:09,649 - DEBUG [org.opensaml.saml.common.profile.logic.DefaultLocalErrorPredicate:181] - Error event RuntimeException will be handled locally

Adding to this is that I in the browser can find the shib_idp_session cookie with value: 146abed13771dddaac6b25f0b61e2c8973853af72b0450f87e836ace2f343fbd 
I also have a valid JSESSIONID 

I can’t find neither the word JSESSIONID nor the JSESSIONID value in the log. Should ?
However, I’m pretty sure the JSESSIONID is reaching the server, or else, also server side storage would fail, and that works.

I may try later to mirror this IdP on another server that runs true java 8, but I can’t change Java on this server right now.
The tomcat is a real Tomcat from Apache version 8.0.30, freshly downloaded for this IdP.

/Stefan

On 22/12/15 17:43, "users on behalf of Cantor, Scott" <users-bounces at shibboleth.net on behalf of cantor.2 at osu.edu> wrote:

>On 12/22/15, 11:40 AM, "users on behalf of Stefan Santesson" <users-bounces at shibboleth.net on behalf of stefan at aaa-sec.com> wrote:
>
>
>>
>>No, the external servlet is compiled to a jar-with-dependencies.jar and added to edit-webapp/WEB-INF/lib and included from the IdP web.xml
>>Common dependencies with IdP is declared as “provided”, like hibernate and OpenSAML v3 since it shares the IdP class loader.
>
>Ok. I'm running out of ideas then, and since you're not using real Java, my only suggestion is probably trying that (and if the Tomcat isn't a real one from Apache, that too).
>
>But I'll see what the logs show.
>
>I would also, I guess, wonder if you can verify with a trace that the JSESSIONID cookie is making it to the server in all of the requests. That's really the linchpin here.
>
>-- Scott
>
>>
>-- 
>To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net