null principal in attribute resolver

Tue Nov 29 13:11:47 GMT 2011

Have you noticed that the same user tries to login two times in a few
seconds?
The second request contains the login context that is removed without
redirect to login page.

Below the first login attemps:
10:40:59.604 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:170]
- Attempting to authenticate user XXXXXXXXXXXX
10:40:59.767 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:178]
- Successfully authenticated user XXXXXXXXXXXX
10:40:59.767 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:144] -
Returning control to authentication engine
10:40:59.767 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -
Processing incoming request
10:40:59.768 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:517] -
Completing user authentication process
10:40:59.768 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:588] -
Validating authentication was performed successfully
10:40:59.768 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:699] -
Updating session information for principal XXXXXXXXXXXX
10:40:59.768 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:703] -
Creating shibboleth session for principal XXXXXXXXXXXX
10:40:59.769 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:809] -
Adding IdP session cookie to HTTP response
10:40:59.769 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:718] -
Recording authentication and service information in Shibboleth session for
principal: IN2797738biw
10:40:59.769 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:563] -
User XXXXXXXXXXXX authenticated with method
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
10:40:59.769 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] -
Returning control to profile handler
10:40:59.770 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] -
Redirecting user to profile handler at
https://www.inarcassa.it:443/idp/profile/SAML2/Redirect/SSO
10:41:00.031 - INFO [Shibboleth-Access:74] -
20111128T094100Z|79.20.163.100|www.inarcassa.it:443
|/profile/SAML2/Redirect/SSO|
10:41:00.032 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86]
- shibboleth.HandlerManager: Looking up profile handler for request path:
/SAML2/Redirect/SSO
10:41:00.032 - 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:00.032 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:163]
- Incoming request contains a login context, processing as second leg of
request
10:41:00.032 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:572] -
Unbinding LoginContext
10:41:00.032 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:598] -
Expiring LoginContext cookie
10:41:00.033 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:607] -
Removing LoginContext, with key 1a400362-c2f8-41e3-9780-72216663fee6, from
StorageService partition loginContexts
10:41:00.033 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for
https://www.inarcassa.it/shibboleth
10:41:00.033 - 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:41:00.033 - 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:41:00.034 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:472]
- Resolving attributes for principal 'XXXXXXXXXXXX' for SAML request from
relying party 'https://www.inarcassa.it/shibboleth'

The second request without redirect to login page:
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 configu
ration 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. Usi
ng 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'

Thanks

2011/11/29 Chad La Joie <lajoie at itumi.biz>

> Well, when you posted your logs you removed almost anything that
> indicates what happened during authentication.  So that might be a
> good place to start looking.
>
> On Tue, Nov 29, 2011 at 07:32, Daniele Russo <ruda76 at gmail.com> wrote:
> > Anyone can help me?
>
> --
> Chad La Joie
> www.itumi.biz
> trusted identities, delivered
> --
> 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/b5b8bb11/attachment.html 