null principal in attribute resolver

Tue Nov 29 12:32:52 GMT 2011

Anyone can help me?

Thanks

2011/11/28 Daniele Russo <ruda76 at gmail.com>

> 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<http://w.inarcassa.it/idp/shibboleth%7Curn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST%7C_28c086360316f84ec2ff95d645460ed0%7CYYYYYYYYYY%7Curn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport%7CProfilo,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/20111129/e495a7a9/attachment-0001.html 