MFA with specific authnContextClassRef

Wed Aug 8 18:14:07 EDT 2018

Sorry if this is too much, tried to snip some of it

2018-08-08 15:03:26,764 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:72] - Profile Action FilterFlowsByForcedAuthn: Retaining flow authn/MFA, it supports forced authentication
2018-08-08 15:03:26,764 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:84] - Profile Action FilterFlowsByForcedAuthn: Potential authentication flows left after filtering: {authn/MFA=AuthenticationFlowDescriptor{flowId=authn/MFA, supportsPassive=true, supportsForcedAuthentication=true, lifetime=28800000, inactivityTimeout=28800000}}
2018-08-08 15:03:26,775 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2018-08-08 15:03:26,786 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:370] - Profile Action SelectAuthenticationFlow: Specific principals requested with 'exact' operator: [AuthnContextClassRefPrincipal{authnContextClassRef=https://refeds.org/profile/mfa}]
2018-08-08 15:03:26,787 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:383] - Profile Action SelectAuthenticationFlow: Forced authentication requested, selecting an inactive flow
2018-08-08 15:03:26,787 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:407] - Profile Action SelectAuthenticationFlow: Checking for an inactive flow compatible with operator 'exact' and principal 'https://refeds.org/profile/mfa'
2018-08-08 15:03:26,788 - DEBUG [net.shibboleth.idp.authn.principal.PrincipalEvalPredicateFactoryRegistry:82] - Registry located predicate factory of type 'net.shibboleth.idp.authn.principal.impl.ExactPrincipalEvalPredicateFactory' for principal type 'class net.shibboleth.idp.saml.authn.principal.AuthnContextClassRefPrincipal' and operator 'exact'
2018-08-08 15:03:26,789 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/MFA
2018-08-08 15:03:26,797 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/system/flows/authn/mfa-authn-beans.xml]
2018-08-08 15:03:26,804 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/system/flows/authn/../../../conf/authn/mfa-authn-config.xml]
2018-08-08 15:03:26,810 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:843] - Overriding bean definition for bean 'shibboleth.authn.MFA.TransitionMap' with a different definition: replacing [Generic bean: class [org.springframework.beans.factory.config.MapFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Generic bean: class [org.springframework.beans.factory.config.MapFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-08-08 15:03:26,811 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [authn/MFA]: startup date [Wed Aug 08 15:03:26 PDT 2018]; parent: WebApplicationContext for namespace 'idp-servlet'
2018-08-08 15:03:26,812 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope at 4ca537dc] to [org.springframework.web.context.request.RequestScope at 76d630f8]
2018-08-08 15:03:26,912 - DEBUG [net.shibboleth.idp.authn.impl.PopulateMultiFactorAuthenticationContext:164] - Profile Action PopulateMultiFactorAuthenticationContext: 0 active result(s) extracted for possible reuse
2018-08-08 15:03:26,923 - DEBUG [net.shibboleth.idp.authn.impl.TransitionMultiFactorAuthentication:195] - Profile Action TransitionMultiFactorAuthentication: Applying MFA transition rule to determine initial state
2018-08-08 15:03:26,924 - DEBUG [net.shibboleth.idp.authn.impl.TransitionMultiFactorAuthentication:214] - Profile Action TransitionMultiFactorAuthentication: MFA flow transition after 'proceed' event to 'authn/Password' flow
2018-08-08 15:03:26,935 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/system/flows/authn/password-authn-beans.xml]
2018-08-08 15:03:26,942 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/system/flows/authn/../../../conf/authn/password-authn-config.xml]
2018-08-08 15:03:26,947 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/conf/authn/jaas-authn-config.xml]
2018-08-08 15:03:26,953 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [authn/Password]: startup date [Wed Aug 08 15:03:26 PDT 2018]; parent: WebApplicationContext for namespace 'idp-servlet'
2018-08-08 15:03:26,954 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope at a8c9b31] to [org.springframework.web.context.request.RequestScope at 4aaa54ba]
2018-08-08 15:03:27,108 - DEBUG [net.shibboleth.idp.authn.impl.ExtractUsernamePasswordFromBasicAuth:115] - Profile Action ExtractUsernamePasswordFromBasicAuth: No appropriate Authorization header found
2018-08-08 15:03:27,227 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:780] - No UIInfo or logos returning null
2018-08-08 15:03:27,228 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:524] - No description matching the languages found, returning null
2018-08-08 15:03:28,864 - DEBUG [net.shibboleth.idp.authn.AbstractExtractionAction:137] - Profile Action ExtractUsernamePasswordFromFormRequest: Trimming whitespace of input string 'XXXX'
2018-08-08 15:03:28,865 - DEBUG [net.shibboleth.idp.authn.AbstractExtractionAction:142] - Profile Action ExtractUsernamePasswordFromFormRequest: Converting input string 'XXXX' to lowercase
2018-08-08 15:03:28,927 - DEBUG [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:243] - Profile Action ValidateUsernamePasswordAgainstJAAS: Attempting to authenticate user 'XXXX' via 'ShibUserPassAuth'
2018-08-08 15:03:28,928 - DEBUG [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:337] - Profile Action ValidateUsernamePasswordAgainstJAAS: Using custom JAAS configuration type JavaLoginConfig with parameters of type java.security.URIParameter
2018-08-08 15:03:29,708 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:246] - Profile Action ValidateUsernamePasswordAgainstJAAS: Login by 'XXXX' succeeded
2018-08-08 15:03:29,714 - DEBUG [net.shibboleth.idp.authn.AbstractValidationAction:341] - Profile Action ValidateUsernamePasswordAgainstJAAS: Adding custom Principal(s) defined on underlying flow descriptor
2018-08-08 15:03:29,722 - DEBUG [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:243] - Profile Action ValidateUsernamePasswordAgainstJAAS: Attempting to authenticate user 'XXXX' via 'ShibUserPassAuth'
2018-08-08 15:03:29,723 - DEBUG [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:337] - Profile Action ValidateUsernamePasswordAgainstJAAS: Using custom JAAS configuration type JavaLoginConfig with parameters of type java.security.URIParameter
2018-08-08 15:03:30,736 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:246] - Profile Action ValidateUsernamePasswordAgainstJAAS: Login by 'XXXX' succeeded
2018-08-08 15:03:30,737 - DEBUG [net.shibboleth.idp.authn.AbstractValidationAction:341] - Profile Action ValidateUsernamePasswordAgainstJAAS: Adding custom Principal(s) defined on underlying flow descriptor
2018-08-08 15:03:30,764 - DEBUG [net.shibboleth.idp.authn.impl.PopulateSubjectCanonicalizationContext:79] - Profile Action PopulateSubjectCanonicalizationContext: Installing 2 canonicalization flows into SubjectCanonicalizationContext
2018-08-08 15:03:30,793 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/system/flows/c14n/subject-c14n-beans.xml]
2018-08-08 15:03:30,806 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [c14n]: startup date [Wed Aug 08 15:03:30 PDT 2018]; parent: WebApplicationContext for namespace 'idp-servlet'
2018-08-08 15:03:30,806 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope at 70c99c81] to [org.springframework.web.context.request.RequestScope at 143637a9]
2018-08-08 15:03:30,860 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/x500 for applicability...
2018-08-08 15:03:30,861 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:106] - Profile Action SelectSubjectCanonicalizationFlow: Canonicalization flow c14n/x500 was not applicable to this request
2018-08-08 15:03:30,861 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/simple for applicability...

2018-08-08 15:03:30,862 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:83] - Profile Action SelectSubjectCanonicalizationFlow: Selecting canonicalization flow c14n/simple
2018-08-08 15:03:30,874 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/system/flows/c14n/simple-subject-c14n-beans.xml]
2018-08-08 15:03:30,885 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp-dev/system/flows/c14n/../../../conf/c14n/simple-subject-c14n-config.xml]
2018-08-08 15:03:30,898 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [c14n/simple]: startup date [Wed Aug 08 15:03:30 PDT 2018]; parent: WebApplicationContext for namespace 'idp-servlet'
2018-08-08 15:03:30,898 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope at 4f7d168c] to [org.springframework.web.context.request.RequestScope at 4a62c58]
2018-08-08 15:03:30,967 - DEBUG [net.shibboleth.idp.authn.AbstractSubjectCanonicalizationAction:226] - Profile Action SimpleSubjectCanonicalization: trimming whitespace of input string 'XXXX'
2018-08-08 15:03:30,980 - DEBUG [net.shibboleth.idp.authn.impl.TransitionMultiFactorAuthentication:184] - Profile Action TransitionMultiFactorAuthentication: Preserving authentication result from 'authn/Password' flow
2018-08-08 15:03:30,981 - DEBUG [net.shibboleth.idp.authn.impl.TransitionMultiFactorAuthentication:197] - Profile Action TransitionMultiFactorAuthentication: Applying MFA transition rule to exit state 'authn/Password'
2018-08-08 15:03:31,168 - DEBUG [net.shibboleth.idp.authn.principal.PrincipalEvalPredicateFactoryRegistry:82] - Registry located predicate factory of type 'net.shibboleth.idp.authn.principal.impl.ExactPrincipalEvalPredicateFactory' for principal type 'class net.shibboleth.idp.saml.authn.principal.AuthnContextClassRefPrincipal' and operator 'exact'

...snipped attribute resolver...

2018-08-08 15:03:31,490 - DEBUG [net.shibboleth.idp.authn.impl.TransitionMultiFactorAuthentication:214] - Profile Action TransitionMultiFactorAuthentication: MFA flow transition after 'proceed' event to 'authn/Duo' flow
2018-08-08 15:03:31,501 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [authn/Duo]: startup date [Wed Aug 08 15:03:31 PDT 2018]; parent: WebApplicationContext for namespace 'idp-servlet'
2018-08-08 15:03:31,501 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope at 75fda559] to [org.springframework.web.context.request.RequestScope at 187d8c26]
2018-08-08 15:03:40,956 - DEBUG [net.shibboleth.idp.authn.impl.TransitionMultiFactorAuthentication:197] - Profile Action TransitionMultiFactorAuthentication: Applying MFA transition rule to exit state 'authn/Duo'
2018-08-08 15:03:40,957 - DEBUG [net.shibboleth.idp.authn.impl.TransitionMultiFactorAuthentication:219] - Profile Action TransitionMultiFactorAuthentication: MFA flow completing with event 'proceed'
2018-08-08 15:03:41,001 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeMultiFactorAuthentication:193] - Profile Action FinalizeMultiFactorAuthentication: MFA complete, producing merged result
2018-08-08 15:03:41,022 - DEBUG [net.shibboleth.idp.authn.impl.PopulateSubjectCanonicalizationContext:79] - Profile Action PopulateSubjectCanonicalizationContext: Installing 2 canonicalization flows into SubjectCanonicalizationContext
2018-08-08 15:03:41,024 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/x500 for applicability...
2018-08-08 15:03:41,025 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:106] - Profile Action SelectSubjectCanonicalizationFlow: Canonicalization flow c14n/x500 was not applicable to this request
2018-08-08 15:03:41,025 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/simple for applicability...
2018-08-08 15:03:41,026 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:83] - Profile Action SelectSubjectCanonicalizationFlow: Selecting canonicalization flow c14n/simple
2018-08-08 15:03:41,047 - DEBUG [net.shibboleth.idp.authn.AbstractSubjectCanonicalizationAction:226] - Profile Action SimpleSubjectCanonicalization: trimming whitespace of input string 'XXXX'
2018-08-08 15:03:41,089 - DEBUG [net.shibboleth.idp.session.impl.DetectIdentitySwitch:148] - Profile Action DetectIdentitySwitch: No previous session found, nothing to do
2018-08-08 15:03:41,113 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeAuthentication:137] - Profile Action FinalizeAuthentication: Canonical principal name was established as 'XXXX'
2018-08-08 15:03:41,114 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeAuthentication:242] - Profile Action FinalizeAuthentication: Checking result for compatibility with operator 'exact' and principal 'https://refeds.org/profile/mfa'
2018-08-08 15:03:41,115 - DEBUG [net.shibboleth.idp.authn.principal.PrincipalEvalPredicateFactoryRegistry:82] - Registry located predicate factory of type 'net.shibboleth.idp.authn.principal.impl.ExactPrincipalEvalPredicateFactory' for principal type 'class net.shibboleth.idp.saml.authn.principal.AuthnContextClassRefPrincipal' and operator 'exact'
2018-08-08 15:03:41,116 - WARN [net.shibboleth.idp.authn.impl.FinalizeAuthentication:179] - Profile Action FinalizeAuthentication: Authentication result for flow authn/MFA did not satisfy the request
2018-08-08 15:03:41,159 - WARN [org.opensaml.profile.action.impl.LogEvent:105] - A non-proceed event occurred while processing the request: RequestUnsupported
2018-08-08 15:03:41,161 - DEBUG [org.opensaml.saml.common.profile.logic.DefaultLocalErrorPredicate:184] - Error event RequestUnsupported will be handled with response

--   
Shawn
perdo at fastmail.com

On Wed, Aug 8, 2018, at 5:59 PM, Cantor, Scott wrote:
> > I was afraid it would turn out to be a subtle issue... Thank you
> 
> You can try a log excerpt and I'll certainly skim it for anything 
> obvious, but if it's anything in depth that's on the "paying" side I'm 
> afraid. Something has to be blocking it from completing the second 
> factor, so it just errors out with an insufficient result at the end.
> 
> -- Scott
> 
> -- 
> For Consortium Member technical support, see 
> https://wiki.shibboleth.net/confluence/x/coFAAg
> To unsubscribe from this list send an email to users-
> unsubscribe at shibboleth.net