MFA with specific authnContextClassRef

Wed Aug 8 18:15:49 EDT 2018

Also I'll add... before it errors it does challenge me with both password and duo. Just after those pass I get the error

--   
Shawn
perdo at fastmail.com

On Wed, Aug 8, 2018, at 6:14 PM, Shawn wrote:
> 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
> -- 
> 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