null principal in attribute resolver
Daniele Russo
ruda76 at gmail.com
Mon Nov 28 15:57:58 GMT 2011
Hi, below the most important rows of the debug log of idp.
I hope someone can help me.
10:40:57.898 - INFO [Shibboleth-Access:74] -
20111128T094057Z|93.70.49.139|www.inarcassa.it:443
|/profile/SAML2/Redirect/SSO|
10:40:57.899 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86]
- shibboleth.HandlerManager: Looking up profile handler for request path:
/SAML2/Redirect/SSO
10:40:57.899 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:97]
- shibboleth.HandlerManager: Located profile handler of the following type
for the request path: edu.internet2.middleware.shibboleth.idp.
profile.saml2.SSOProfileHandler
10:40:57.899 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:323] -
LoginContext key cookie was not present in request
10:40:57.899 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:160]
- Incoming request does not contain a login context, processing as first
leg of request
10:40:57.899 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:312]
- Decoding message with decoder binding
'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect'
10:40:57.901 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for
https://www.inarcassa.it/shibboleth
10:40:57.901 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134]
- No custom relying party configuration found for
https://www.inarcassa.it/shibboleth, looking up configu
ration based on metadata groups.
10:40:57.901 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://www.inarcassa.it/shibboleth. Usi
ng default relying party configuration.
10:40:57.901 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:333]
- Decoded request from relying party 'https://www.inarcassa.it/shibboleth'
10:40:57.902 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for
https://www.inarcassa.it/shibboleth
10:40:57.902 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134]
- No custom relying party configuration found for
https://www.inarcassa.it/shibboleth, looking up configu
ration based on metadata groups.
10:40:57.902 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://www.inarcassa.it/shibboleth. Usi
ng default relying party configuration.
10:40:57.902 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:203]
- Creating login context and transferring control to authentication engine
10:40:57.903 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] -
Storing LoginContext to StorageService partition loginContexts, key
35552361-5d87-444b-b305-0ca58d7e64fe
10:40:57.903 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:216]
- Redirecting user to authentication engine at
https://www.inarcassa.it:443/idp/AuthnEngine
10:40:57.983 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -
Processing incoming request
10:40:57.983 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] -
Beginning user authentication process.
10:40:57.983 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:286] -
Filtering configured LoginHandlers:
{urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=
edu.internet2.middleware.shibboleth.idp.authn.pr
ovider.PreviousSessionLoginHandler at 1e73498,
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 2e1b6c
}
10:40:57.983 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:335] -
Filtering out previous session login handler because there is no existing
IdP session
10:40:57.983 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:388] -
Forced authentication is required, filtering possible login handlers
accordingly
10:40:57.984 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:409] -
Authentication handlers remaining after forced authentication requirement
filtering: {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtect
edTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 2e1b6c
}
10:40:57.984 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:467] -
Selecting appropriate login handler from filtered set
{urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middl
eware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 2e1b6c}
10:40:57.984 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:500] -
Authenticating user with login handler of type
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler
10:40:57.984 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] -
Storing LoginContext to StorageService partition loginContexts, key
0f036b58-d567-4517-b7ea-b6d28ca6f7a5
10:40:57.984 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66]
- Redirecting to https://www.inarcassa.it:443/idp/Authn/UserPassword
10:40:58.063 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150]
- Redirecting to login page /login.jsp
....
10:41:00.117 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:778]
- Encoding response to SAML request _0cf7fef8f3c9c338a5da4459da3e9a85 from
relying party https://www.inarcassa.it/shibboleth
10:41:00.120 - INFO [Shibboleth-Audit:970] -
20111128T094100Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_0cf7fef8f3c9c338a5da4459da3e9a85|
https://www.inarcassa.it/shibboleth|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://ww
w.inarcassa.it/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_28c086360316f84ec2ff95d645460ed0|YYYYYYYYYY|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|Profilo,CodiceEnte,Contatti,CodiceFiscale,Ruol
o,CodiceUtente,Matricola,|||
10:41:03.302 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
ZGZlN2JmZTVlNmM2MDA4NDc1Zjk5Mjg2MmRiZWM0NGM2ODVkYmYzMjFjNDk2Y2RhOGM4MzVhZjEwYTE1YjMyMg==
- session must
have timed out
....
10:41:20.328 - INFO [Shibboleth-Access:74] -
20111128T094120Z|93.70.49.139|www.inarcassa.it:443
|/profile/SAML2/Redirect/SSO|
10:41:20.328 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86]
- shibboleth.HandlerManager: Looking up profile handler for request path:
/SAML2/Redirect/SSO
10:41:20.329 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:97]
- shibboleth.HandlerManager: Located profile handler of the following type
for the request path:
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
10:41:20.329 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:163]
- Incoming request contains a login context, processing as second leg of
request
10:41:20.329 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:572] -
Unbinding LoginContext
10:41:20.329 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:598] -
Expiring LoginContext cookie
10:41:20.329 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:607] -
Removing LoginContext, with key 0f036b58-d567-4517-b7ea-b6d28ca6f7a5, from
StorageService partition loginContexts
10:41:20.330 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for
https://www.inarcassa.it/shibboleth
10:41:20.330 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134]
- No custom relying party configuration found for
https://www.inarcassa.it/shibboleth, looking up configuration based on
metadata groups.
10:41:20.330 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://www.inarcassa.it/shibboleth. Using default relying party
configuration.
10:41:20.331 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:472]
- Resolving attributes for principal 'null' for SAML request from relying
party 'https://www.inarcassa.it/shibboleth'
....
10:41:20.429 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:778]
- Encoding response to SAML request _37239fdb6e3f76b3008ee0249f7c3518 from
relying party https://www.inarcassa.it/shibboleth
10:41:20.431 - INFO [Shibboleth-Audit:970] -
20111128T094120Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_37239fdb6e3f76b3008ee0249f7c3518|
https://www.inarcassa.it/shibboleth|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://www.inarcassa.it/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_4cee0f36347dd1617d516a89775a489f||||||
2011/11/22 Paul Hethmon <paul.hethmon at clareitysecurity.com>
> You need to set your IdP logging level to debug and follow what happens
> in the logs for these cases.
>
> --
>
> Paul Hethmon
> Chief Software Architect
> Clareity Security, LLC
> o) 865.824.1350
> c) 865.250.3517
> e) paul.hethmon at clareitysecurity.com
>
>
> From: Daniele Russo <ruda76 at gmail.com>
> Reply-To: Shibboleth Users <users at shibboleth.net>
> Date: Tue, 22 Nov 2011 17:56:28 +0100
> To: Shibboleth Users <users at shibboleth.net>
> Subject: Re: null principal in attribute resolver
>
> Anyone have this same problem?
> No solutions?
>
> 2011/11/21 Daniele Russo <ruda76 at gmail.com>
>
>> Hi all, I have a strange problem with shibboleth IDP 2.3.5.
>> IDP is configured with UsernamePassword login handler, I use tigish
>> library to authenticate users on the DB.
>> All works, but occasionally IDP doesn't return attributes to SP and this
>> strange problem only occurs in production enviroment.
>> In debugging I noticed that the principal is enhanced in the
>> authentication phase, while in the attribute resolver phase is null.
>> This problem occurs with various operating systems and browsers.
>>
>> Mozilla/5.0 (Windows; U; Windows NT 6.0; it; rv:1.9.2.23) Gecko/20110920
>> Firefox/3.6.23
>> Mozilla/5.0 (Windows NT 5.1; rv:7.0.1) Gecko/20100101 Firefox/7.0.1
>>
>> Thanks
>>
>> Daniele
>>
>>
> -- To unsubscribe from this list send an email to
> users-unsubscribe at shibboleth.net
>
> --
> To unsubscribe from this list send an email to
> users-unsubscribe at shibboleth.net
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20111128/488e9df5/attachment-0001.html
More information about the users
mailing list