Problem with SPNEGO after successfully kerberos auth

Maxi Fernández melvinsoft at gmail.com
Wed Apr 20 13:33:29 EDT 2016 

Hi all! I'm new on the list.

This is my second deploy with shibboleth and the first using the SPNEGO
auth.

I think I'm in the final stage of the configuration, because the log is
telling me that that principal is authenticating but then the logs out
this, and the principal name in the logs is ok, but then in the SAML
response is releasing this.

<saml2p:Status>
        <saml2p:StatusCode
Value="urn:oasis:names:tc:SAML:2.0:status:Requester">
            <saml2p:StatusCode
Value="urn:oasis:names:tc:SAML:2.0:status:NoAuthnContext"/>
        </saml2p:StatusCode>
        <saml2p:StatusMessage>An error occurred.</saml2p:StatusMessage>
    </saml2p:Status>

I know the problem is in this part:

2016-04-20 17:45:36,373 - DEBUG
[net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:477] - Profile
Action SelectAuthenticationFlow: Checking for an inactive flow or active
result compatible with operator 'exact' and principal
'urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport'
2016-04-20 17:45:36,374 - DEBUG
[net.shibboleth.idp.authn.principal.PrincipalEvalPredicateFactoryRegistry:80]
- 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'

But I don't know how to solve it.

Thanks to all in advance.

Maxi

This are the logs:

2016-04-20 17:45:36,260 - DEBUG
[net.shibboleth.idp.session.impl.PopulateSessionContext:131] - Profile
Action PopulateSessionContext: No session found for client
2016-04-20 17:45:36,263 - DEBUG
[net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:126] - Profile
Action PopulateAuthenticationContext: Installing custom
PrincipalEvalPredicateFactoryRegistry into AuthenticationContext
2016-04-20 17:45:36,264 - DEBUG
[net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:167] - Profile
Action PopulateAuthenticationContext: Installed 1 authentication flows into
AuthenticationContext
2016-04-20 17:45:36,264 - DEBUG
[net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile
Action FilterFlowsByForcedAuthn: Request does not have forced
authentication requirement, nothing to do
2016-04-20 17:45:36,265 - DEBUG
[net.shibboleth.idp.authn.impl.FilterFlowsByPassivity:53] - Profile Action
FilterFlowsByPassivity: Request does not have passive requirement, nothing
to do
2016-04-20 17:45:36,266 - DEBUG
[net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile
Action FilterFlowsByNonBrowserSupport: Request does not have non-browser
requirement, nothing to do
2016-04-20 17:45:36,268 - DEBUG
[net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:257] - Profile
Action SelectAuthenticationFlow: No specific Principals requested
2016-04-20 17:45:36,269 - DEBUG
[net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:292] - Profile
Action SelectAuthenticationFlow: No usable active results available,
selecting an inactive flow
2016-04-20 17:45:36,271 - DEBUG
[net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:334] - Profile
Action SelectAuthenticationFlow: Selecting inactive authentication flow
authn/SPNEGO
2016-04-20 17:45:36,273 - DEBUG
[net.shibboleth.idp.authn.spnego.impl.SPNEGOAutoLoginManager:97] -
Auto-login has been disabled.
2016-04-20 17:45:36,306 - DEBUG
[net.shibboleth.idp.authn.spnego.impl.GSSContextAcceptor:175] - Validating
the first GSS input token against service principal: HTTP/
moocs.mydomain.com at MYDOMAIN.COM
2016-04-20 17:45:36,327 - DEBUG
[net.shibboleth.idp.authn.spnego.impl.SPNEGOAuthnController:175] - GSS
security context is complete
2016-04-20 17:45:36,327 - INFO
[net.shibboleth.idp.authn.spnego.impl.SPNEGOAuthnController:188] -
SPNEGO/Kerberos authentication succeeded for principal: GRT3214 at MYDOMAIN.COM
2016-04-20 17:45:36,337 - INFO
[net.shibboleth.idp.authn.impl.ValidateExternalAuthentication:107] -
Profile Action ValidateExternalAuthentication: External authentication
succeeded for Subject: [UsernamePrincipal{username=GRT3214 at MYDOMAIN.COM},
GRT3214 at MYDOMAIN.COM]
2016-04-20 17:45:36,339 - DEBUG
[net.shibboleth.idp.authn.AbstractValidationAction:311] - Profile Action
ValidateExternalAuthentication: Adding custom Principal(s) defined on
underlying flow descriptor
2016-04-20 17:45:36,341 - DEBUG
[net.shibboleth.idp.authn.impl.PopulateSubjectCanonicalizationContext:79] -
Profile Action PopulateSubjectCanonicalizationContext: Installing 2
canonicalization flows into SubjectCanonicalizationContext
2016-04-20 17:45:36,342 - DEBUG
[net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] -
Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization
flow c14n/x500 for applicability...
2016-04-20 17:45:36,342 - DEBUG
[net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:106] -
Profile Action SelectSubjectCanonicalizationFlow: Canonicalization flow
c14n/x500 was not applicable to this request
2016-04-20 17:45:36,343 - DEBUG
[net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] -
Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization
flow c14n/simple for applicability...
2016-04-20 17:45:36,343 - DEBUG
[net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:83] -
Profile Action SelectSubjectCanonicalizationFlow: Selecting
canonicalization flow c14n/simple
2016-04-20 17:45:36,345 - DEBUG
[net.shibboleth.idp.authn.AbstractSubjectCanonicalizationAction:226] -
Profile Action SimpleSubjectCanonicalization: trimming whitespace of input
string 'GRT3214 at MYDOMAIN.COM'
2016-04-20 17:45:36,346 - DEBUG
[net.shibboleth.idp.authn.AbstractSubjectCanonicalizationAction:244] -
Profile Action SimpleSubjectCanonicalization: applying replacement
expression '^(.+)@MYDOMAIN\.COM$' against input 'GRT3214 at MYDOMAIN.COM'
2016-04-20 17:45:36,346 - DEBUG
[net.shibboleth.idp.authn.AbstractSubjectCanonicalizationAction:247] -
Profile Action SimpleSubjectCanonicalization: result of replacement is
'GRT3214'
2016-04-20 17:45:36,348 - DEBUG
[net.shibboleth.idp.authn.impl.FinalizeAuthentication:137] - Profile Action
FinalizeAuthentication: Canonical principal name was established as
'GRT3214'
2016-04-20 17:45:36,348 - DEBUG
[net.shibboleth.idp.authn.impl.FinalizeAuthentication:186] - Profile Action
FinalizeAuthentication: Request did not have explicit authentication
requirements, result is accepted
2016-04-20 17:45:36,349 - DEBUG
[net.shibboleth.idp.session.impl.UpdateSessionWithAuthenticationResult:221]
- Profile Action UpdateSessionWithAuthenticationResult: Creating new
session for principal GRT3214
2016-04-20 17:45:36,352 - DEBUG
[net.shibboleth.idp.session.impl.StorageBackedSessionManager:533] - Created
new session
85ec3e84a247d61b5725a4c6f9619c85736cfbf514626a219f73a771389bf5e7 for
principal GRT3214
2016-04-20 17:45:36,353 - DEBUG
[net.shibboleth.idp.session.impl.StorageBackedIdPSession:561] - Saving
AuthenticationResult for flow authn/SPNEGO in session
85ec3e84a247d61b5725a4c6f9619c85736cfbf514626a219f73a771389bf5e7
2016-04-20 17:45:36,355 - DEBUG
[net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:115]
- Profile Action InitializeAuthenticationContext: Created authentication
context:
AuthenticationContext{initiationInstant=2016-04-20T17:45:36.355+02:00,
isPassive=false, forceAuthn=false, hintedName=null, potentialFlows=[],
activeResults=[], attemptedFlow=null, signaledFlowId=null,
authenticationStateMap={}, resultCacheable=true,
initialAuthenticationResult=AuthenticationResult{authenticationFlowId=authn/SPNEGO,
authenticatedPrincipal=GRT3214 at MYDOMAIN.COM,
authenticationInstant=2016-04-20T17:45:36.339+02:00,
lastActivityInstant=2016-04-20T17:45:36.339+02:00},
authenticationResult=null, completionInstant=1970-01-01T01:00:00.000+01:00}
2016-04-20 17:45:36,356 - DEBUG
[net.shibboleth.idp.authn.impl.InitializeRequestedPrincipalContext:111] -
Profile Action InitializeRequestedPrincipalContext: Profile configuration
does not include any default authentication methods
2016-04-20 17:45:36,358 - DEBUG
[net.shibboleth.idp.saml.saml2.profile.impl.ProcessRequestedAuthnContext:188]
- Profile Action ProcessRequestedAuthnContext: RequestedPrincipalContext
created with operator exact and 1 custom principal(s)
2016-04-20 17:45:36,360 - DEBUG
[net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:126] - Profile
Action PopulateAuthenticationContext: Installing custom
PrincipalEvalPredicateFactoryRegistry into AuthenticationContext
2016-04-20 17:45:36,361 - DEBUG
[net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:167] - Profile
Action PopulateAuthenticationContext: Installed 1 authentication flows into
AuthenticationContext
2016-04-20 17:45:36,362 - DEBUG
[net.shibboleth.idp.session.impl.PopulateSessionContext:131] - Profile
Action PopulateSessionContext: No session found for client
2016-04-20 17:45:36,364 - DEBUG
[net.shibboleth.idp.session.impl.ExtractActiveAuthenticationResults:112] -
Profile Action ExtractActiveAuthenticationResults: authentication result
authn/SPNEGO is active, copying from session
2016-04-20 17:45:36,369 - DEBUG
[net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile
Action FilterFlowsByForcedAuthn: Request does not have forced
authentication requirement, nothing to do
2016-04-20 17:45:36,370 - DEBUG
[net.shibboleth.idp.authn.impl.FilterFlowsByPassivity:53] - Profile Action
FilterFlowsByPassivity: Request does not have passive requirement, nothing
to do
2016-04-20 17:45:36,371 - DEBUG
[net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile
Action FilterFlowsByNonBrowserSupport: Request does not have non-browser
requirement, nothing to do
2016-04-20 17:45:36,372 - DEBUG
[net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:366] - Profile
Action SelectAuthenticationFlow: Specific principals requested with 'exact'
operator:
[AuthnContextClassRefPrincipal{authnContextClassRef=urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport}]
2016-04-20 17:45:36,373 - DEBUG
[net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:477] - Profile
Action SelectAuthenticationFlow: Checking for an inactive flow or active
result compatible with operator 'exact' and principal
'urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport'
2016-04-20 17:45:36,374 - DEBUG
[net.shibboleth.idp.authn.principal.PrincipalEvalPredicateFactoryRegistry:80]
- 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'
2016-04-20 17:45:36,375 - INFO
[net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:507] - Profile
Action SelectAuthenticationFlow: None of the potential authentication flows
can satisfy the request
2016-04-20 17:45:36,377 - WARN
[org.opensaml.profile.action.impl.LogEvent:76] - An error event occurred
while processing the request: RequestUnsupported
2016-04-20 17:45:36,379 - DEBUG
[org.opensaml.saml.common.profile.logic.DefaultLocalErrorPredicate:184] -
Error event RequestUnsupported will be handled with response
2016-04-20 17:45:36,381 - DEBUG
[org.opensaml.saml.saml2.profile.impl.AbstractResponseShellAction:217] -
Profile Action AddStatusResponseShell: Setting Issuer to
https://moocs/idp/shibboleth
2016-04-20 17:45:36,385 - DEBUG
[org.opensaml.saml.common.profile.impl.AddInResponseToToResponse:110] -
Profile Action AddInResponseToToResponse: Attempting to add InResponseTo to
outgoing Response
2016-04-20 17:45:36,406 - DEBUG
[org.opensaml.saml.saml2.profile.impl.AddStatusToResponse:195] - Profile
Action AddStatusToResponse: Detailed errors are disabled
2016-04-20 17:45:36,407 - DEBUG
[org.opensaml.saml.saml2.profile.impl.AddStatusToResponse:224] - Profile
Action AddStatusToResponse: Setting StatusMessage to defaulted value
2016-04-20 17:45:36,413 - DEBUG
[net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:159] -
Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of
type 'org.opensaml.messaging.handler.impl.BasicMessageHandlerChain' on
OUTBOUND message context
2016-04-20 17:45:36,414 - DEBUG
[net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] -
Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on
message context containing a message of type
'org.opensaml.saml.saml2.core.impl.ResponseImpl'
2016-04-20 17:45:36,415 - DEBUG
[org.opensaml.saml.common.binding.impl.SAMLOutboundDestinationHandler:62] -
Adding destination to outbound SAML 2 protocol message:
http://students.mydomain.com/auth/complete/tpa-saml/
2016-04-20 17:45:36,416 - DEBUG
[org.opensaml.saml.common.binding.security.impl.EndpointURLSchemeSecurityHandler:52]
- Message Handler:  Checking outbound endpoint for allowed URL scheme:
http://students.mydomain.com/auth/complete/tpa-saml/
2016-04-20 17:45:36,417 - DEBUG
[org.opensaml.saml.common.SAMLObjectSupport:56] - Examing signed object for
content references with exclusive canonicalization transform
2016-04-20 17:45:36,418 - DEBUG
[org.opensaml.saml.common.SAMLObjectSupport:70] - Saw exclusive transform,
declaring non-visible namespaces on signed object
2016-04-20 17:45:36,420 - DEBUG
[org.opensaml.saml.common.SAMLObjectContentReference:165] - Adding list of
inclusive namespaces for signature exclusive canonicalization transform
2016-04-20 17:45:36,442 - DEBUG
[net.shibboleth.idp.saml.profile.impl.SpringAwareMessageEncoderFactory:100]
- Looking up message encoder based on binding URI:
urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST
2016-04-20 17:45:36,444 - DEBUG
[org.opensaml.saml.saml2.binding.encoding.impl.HTTPPostEncoder:159] -
Invoking Velocity template to create POST body
2016-04-20 17:45:36,445 - DEBUG
[org.opensaml.saml.saml2.binding.encoding.impl.HTTPPostEncoder:192] -
Encoding action url of 'http://students.mydomain.com/auth/complete/tpa-saml/'
with encoded value 'http&#x3a;&#x2f;&#x2f;students.mydomain.com
&#x2f;auth&#x2f;complete&#x2f;tpa-saml&#x2f;'
2016-04-20 17:45:36,446 - DEBUG
[org.opensaml.saml.saml2.binding.encoding.impl.HTTPPostEncoder:198] -
Marshalling and Base64 encoding SAML message
2016-04-20 17:45:36,449 - DEBUG
[org.opensaml.saml.saml2.binding.encoding.impl.HTTPPostEncoder:220] -
Setting RelayState parameter to: 'testshib', encoded as 'testshib'
2016-04-20 17:45:36,456 - DEBUG [PROTOCOL_MESSAGE:70] -
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20160420/32dc7dd2/attachment-0001.html>

More information about the users mailing list