Losing Previous Session Cookie
Christopher Bland
chris at fdu.edu
Mon Mar 5 23:31:19 GMT 2012
Hello All,
I'm having a problem with previous session on a new v2.3.5 IDP. After
initial authentication, if I clear my SP cookies and login again, I can
see where the previous session is found. However it gets lost.
17:32:41.149 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] -
Attempting to retrieve IdP session cookie.
17:32:41.149 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:115] -
Found IdP session cookie.
17:32:41.152 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:75] -
Updating IdP session activity time and adding session object to the request
17:32:41.155 - INFO [Shibboleth-Access:74] -
20120305T223241Z|132.238.11.198|idp1.fdu.edu:443|/profile/SAML2/Redirect/SSO|
17:32:41.155 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86]
- shibboleth.HandlerManager: Looking up profile handler for request
path: /SAML2/Redirect/SSO
17:32:41.155 - 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
17:32:41.155 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:323] -
LoginContext key cookie was not present in request
17:32:41.155 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:160]
- Incoming request does not contain a login context, processing as first
leg of request
17:32:41.155 - 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'
17:32:41.155 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:76] - Beginning to
decode message from inbound transport of type:
org.opensaml.ws.transport.http.HttpServletRequestAdapter
17:32:41.156 - DEBUG
[org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:90] -
Decoded RelayState: ss:mem:dcec36aa1a52c6e9e7ba17057a91ff48
17:32:41.156 - DEBUG
[org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:127] -
Base64 decoding and inflating SAML message
17:32:41.156 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:183] - Parsing
message stream into DOM document
17:32:41.157 - TRACE
[org.opensaml.ws.message.decoder.BaseMessageDecoder:190] - Resultant DOM
message was:
<?xml version="1.0" encoding="UTF-8"?><samlp:AuthnRequest
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"
AssertionConsumerServiceURL="https://webcampus-dev.fdu.edu/Shibboleth.sso/SAML2/POST"
Destination="https://idp1.fdu.edu/idp/pr
ofile/SAML2/Redirect/SSO" ID="_3a5e1920fd02897a1e1fd6b214266611"
IssueInstant="2012-03-05T22:32:41Z"
ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST"
Version="2.0"><saml:Issuer xmlns:saml="urn:oasis:names:tc:SAML:2.0:as
sertion">https://webcampus-dev.fdu.edu/shibboleth</saml:Issuer><samlp:NameIDPolicy
AllowCreate="1"/></samlp:AuthnRequest>
17:32:41.157 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:193] - Unmarshalling
message DOM
17:32:41.157 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:95] - Starting to
unmarshall DOM element {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
17:32:41.161 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:144] - Targeted QName
checking is not available for this unmarshaller, DOM Element
{urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest was not verified
17:32:41.161 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:185] - Building
XMLObject for {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
17:32:41.161 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:101] - Unmarshalling
attributes of DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
17:32:41.161 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute AssertionConsumerServiceURL
17:32:41.161 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute
AssertionConsumerServiceURL is neither a schema type nor namespace,
calling processAttribute()
17:32:41.161 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute Destination
17:32:41.162 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute
Destination is neither a schema type nor namespace, calling
processAttribute()
17:32:41.162 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute ID
17:32:41.162 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute ID
is neither a schema type nor namespace, calling processAttribute()
17:32:41.162 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute IssueInstant
17:32:41.162 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute
IssueInstant is neither a schema type nor namespace, calling
processAttribute()
17:32:41.162 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute ProtocolBinding
17:32:41.163 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute
ProtocolBinding is neither a schema type nor namespace, calling
processAttribute()
17:32:41.163 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute Version
17:32:41.163 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute
Version is neither a schema type nor namespace, calling processAttribute()
17:32:41.163 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute {http://www.w3.org/2000/xmlns/}samlp
17:32:41.163 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:251] -
{http://www.w3.org/2000/xmlns/}samlp is a namespace declaration, adding
it to the list of namespaces on the XMLObject
17:32:41.163 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:113] - Unmarshalling
other child nodes of DOM Element
{urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
17:32:41.165 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:316] - Unmarshalling
child elements of XMLObject
{urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
17:32:41.165 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:333] - Unmarshalling
child element {urn:oasis:names:tc:SAML:2.0:assertion}Issuerwith
unmarshaller org.opensaml.saml2.core.impl.IssuerUnmarshaller
17:32:41.165 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:95] - Starting to
unmarshall DOM element {urn:oasis:names:tc:SAML:2.0:assertion}Issuer
17:32:41.165 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:144] - Targeted QName
checking is not available for this unmarshaller, DOM Element
{urn:oasis:names:tc:SAML:2.0:assertion}Issuer was not verified
17:32:41.165 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:185] - Building
XMLObject for {urn:oasis:names:tc:SAML:2.0:assertion}Issuer
17:32:41.165 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:101] - Unmarshalling
attributes of DOM Element {urn:oasis:names:tc:SAML:2.0:assertion}Issuer
17:32:41.165 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute {http://www.w3.org/2000/xmlns/}saml
17:32:41.166 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:251] -
{http://www.w3.org/2000/xmlns/}saml is a namespace declaration, adding
it to the list of namespaces on the XMLObject
17:32:41.166 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:113] - Unmarshalling
other child nodes of DOM Element
{urn:oasis:names:tc:SAML:2.0:assertion}Issuer
17:32:41.166 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:316] - Unmarshalling
child elements of XMLObject
{urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
17:32:41.166 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:333] - Unmarshalling
child element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicywith
unmarshaller org.opensaml.saml2.core.impl.NameIDPolicyUnmarshaller
17:32:41.166 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:95] - Starting to
unmarshall DOM element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
17:32:41.166 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:144] - Targeted QName
checking is not available for this unmarshaller, DOM Element
{urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy was not verified
17:32:41.167 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:185] - Building
XMLObject for {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
17:32:41.167 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:101] - Unmarshalling
attributes of DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
17:32:41.167 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing
attribute AllowCreate
17:32:41.167 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute
AllowCreate is neither a schema type nor namespace, calling
processAttribute()
17:32:41.167 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:113] - Unmarshalling
other child nodes of DOM Element
{urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
17:32:41.167 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:205] - Message
succesfully unmarshalled
17:32:41.168 - DEBUG
[org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:105] -
Decoded SAML message
17:32:41.168 - DEBUG
[org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder:112] -
Extracting ID, issuer and issue instant from request
17:32:41.168 - DEBUG
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] -
Checking child metadata provider for entity descriptor with entity ID:
https://webcampus-dev.fdu.edu/shibboleth
*---------------*
17:32:41.173 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] -
Searching for entity descriptor with an entity ID of
https://webcampus-dev.fdu.edu/shibboleth
17:32:41.173 - TRACE
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] -
Entity descriptor for the ID https://webcampus-dev.fdu.edu/shibboleth
was found in index cache, returning
17:32:41.173 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://webcampus-dev.fdu.edu/shibbolet
h. Using default relying party configuration.
17:32:41.173 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:130] - Evaluating
security policy of type
'edu.internet2.middleware.shibboleth.common.security.ShibbolethSecurityPolicy'
for decoded message
17:32:41.174 - DEBUG [org.opensaml.util.storage.ReplayCache:92] -
Attempting to acquire lock for replay cache check
17:32:41.174 - DEBUG [org.opensaml.util.storage.ReplayCache:94] - Lock
acquired
17:32:41.174 - DEBUG [org.opensaml.util.storage.ReplayCache:105] -
Message ID _3a5e1920fd02897a1e1fd6b214266611 was not a replay
17:32:41.174 - DEBUG [org.opensaml.util.storage.ReplayCache:132] -
Writing message ID
https://webcampus-dev.fdu.edu/shibboleth_3a5e1920fd02897a1e1fd6b214266611 to
replay cache with expiration time 2012-03-05T17:37:41.174-05:00
17:32:41.174 - DEBUG
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:308] -
Checking child metadata provider for entity descriptor with entity ID:
https://webcampus-dev.fdu.edu/shibboleth
*---------------*
17:32:41.177 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] -
Searching for entity descriptor with an entity ID of
https://webcampus-dev.fdu.edu/shibboleth
17:32:41.177 - TRACE
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] -
Entity descriptor for the ID https://webcampus-dev.fdu.edu/shibboleth
was found in index cache, returning
17:32:41.177 - DEBUG
[org.opensaml.saml2.binding.security.SAML2AuthnRequestsSignedRule:92] -
SPSSODescriptor for entity ID 'https://webcampus-dev.fdu.edu/shibboleth'
does not require AuthnRequests to be signed
17:32:41.178 - INFO
[org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:100]
- SAML protocol message was not signed, skipping XML signature processing
17:32:41.178 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64]
- Evaluating simple signature rule of type:
org.opensaml.saml2.binding.security.SAML2HTTPRedirectDeflateSignatureRule
17:32:41.178 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:87]
- HTTP request was not signed via simple signature mechanism, skipping
17:32:41.178 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64]
- Evaluating simple signature rule of type:
org.opensaml.saml2.binding.security.SAML2HTTPPostSimpleSignRule
17:32:41.178 - DEBUG
[org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:81]
- Rule can not handle this request, skipping processing
17:32:41.178 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:85] - Successfully
decoded message.
17:32:41.178 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:191] -
Checking SAML message intended destination endpoint against receiver
endpoint
17:32:41.179 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:210] -
Intended message destination endpoint:
https://idp1.fdu.edu/idp/profile/SAML2/Redirect/SSO
17:32:41.179 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:211] -
Actual message receiver endpoint:
https://idp1.fdu.edu/idp/profile/SAML2/Redirect/SSO
17:32:41.179 - DEBUG
[org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:219] - SAML
message intended destination endpoint matched recipient endpoint
17:32:41.179 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:333]
- Decoded request from relying party
'https://webcampus-dev.fdu.edu/shibboleth'
17:32:41.179 - DEBUG
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] -
Checking child metadata provider for entity descriptor with entity ID:
https://webcampus-dev.fdu.edu/shibboleth
*
---------------
*17:32:41.184 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] -
Searching for entity descriptor with an entity ID of
https://webcampus-dev.fdu.edu/shibboleth
17:32:41.184 - TRACE
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] -
Entity descriptor for the ID https://webcampus-dev.fdu.edu/shibboleth
was found in index cache, returning
17:32:41.184 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
https://webcampus-dev.fdu.edu/shibbolet
h. Using default relying party configuration.
17:32:41.184 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:203]
- Creating login context and transferring control to authentication engine
17:32:41.185 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectMarshaller:95] - Starting to
marshall {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
17:32:41.185 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectMarshaller:240] - Targeted QName
checking is not available for this marshaller, XMLObject
{urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest was not verified
17:32:41.185 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectMarshaller:103] - Checking if
{urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest contains a cached DOM
representation
17:32:41.185 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectMarshaller:110] - Adopting DOM of
XMLObject into given Document
17:32:41.186 - TRACE
[org.opensaml.xml.io.AbstractXMLObjectMarshaller:114] - Setting DOM of
XMLObject as document element of given Document
17:32:41.186 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] -
Storing LoginContext to StorageService partition loginContexts, key
039f0631-ba7e-4b61-ae5e-313abc182f11
17:32:41.186 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:216]
- Redirecting user to authentication engine at
https://idp1.fdu.edu:443/idp/AuthnEngine
*Based on our working IDP this is where it should attempt to retrieve
IDP session cookie again but doesn't
*
17:32:41.197 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209]
- Processing incoming request
17:32:41.197 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:333] -
Looking up LoginContext with key 039f0631-ba7e-4b61-ae5e-313abc182f11
from StorageService parition: loginContexts
17:32:41.197 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] -
Retrieved LoginContext with key 039f0631-ba7e-4b61-ae5e-313abc182f11
from StorageService parition: loginContexts
17:32:41.198 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240]
- Beginning user authentication process.
17:32:41.198 - 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.p
rovider.PreviousSessionLoginHandler at dd6317,
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 94b0ca}
17:32:41.198 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:335]
- Filtering out previous session login handler because there is no
existing IdP session
17:32:41.198 - 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.midd
leware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 94b0ca}
17:32:41.198 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:500]
- Authenticating user with login handler of type
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler
17:32:41.198 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] -
Storing LoginContext to StorageService partition loginContexts, key
505f448d-ccc9-4a71-ab0b-41b2bf2e83fb
17:32:41.199 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66]
- Redirecting to https://idp1.fdu.edu:443/idp/Authn/UserPassword
17:32:41.214 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:333] -
Looking up LoginContext with key 505f448d-ccc9-4a71-ab0b-41b2bf2e83fb
from StorageService parition: loginContexts
17:32:41.214 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] -
Retrieved LoginContext with key 505f448d-ccc9-4a71-ab0b-41b2bf2e83fb
from StorageService parition: loginContexts
17:32:41.214 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:333] -
Looking up LoginContext with key 505f448d-ccc9-4a71-ab0b-41b2bf2e83fb
from StorageService parition: loginContexts
17:32:41.214 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] -
Retrieved LoginContext with key 505f448d-ccc9-4a71-ab0b-41b2bf2e83fb
from StorageService parition: loginContexts
17:32:41.214 - DEBUG
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] -
Checking child metadata provider for entity descriptor with entity ID:
https://webcampus-dev.fdu.edu/shibboleth
-Chris
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20120305/4c332644/attachment-0001.html
More information about the users
mailing list