2017-07-31 18:30:58,793 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedSessionManager:533] - Created new session da831be6d6a19e8e686a5202edd6fa30d4ae619fca732525e55a650f0e694c96 for principal sriebeling
2017-07-31 18:30:58,798 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedIdPSession:561] - Saving AuthenticationResult for flow authn/Password in session da831be6d6a19e8e686a5202edd6fa30d4ae619fca732525e55a650f0e694c96
2017-07-31 18:30:59,368 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:183] - Attribute Resolver 'ShibbolethAttributeResolver': Initiating attribute resolution
2017-07-31 18:30:59,369 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:191] - Attribute Resolver 'ShibbolethAttributeResolver': Attempting to resolve the following attribute definitions [uid]
2017-07-31 18:30:59,374 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'uid': produced an attribute with the following values [StringAttributeValue{value=sriebeling}]
2017-07-31 18:30:59,487 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:272] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'uid' produced an attribute with 1 values
2017-07-31 18:30:59,490 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:201] - Attribute Resolver 'ShibbolethAttributeResolver': Finalizing resolved attributes
2017-07-31 18:30:59,491 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:434] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition uid result
2017-07-31 18:30:59,491 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:446] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'uid' has 1 values after post-processing
2017-07-31 18:30:59,492 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:206] - Attribute Resolver 'ShibbolethAttributeResolver': Final resolved attribute collection: [uid]
2017-07-31 18:30:59,511 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:108] - Attribute filtering engine 'ShibbolethAttributeFilter'  Beginning process of filtering the following 1 attributes: [uid]
2017-07-31 18:30:59,512 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:125] - Attribute Filter Policy 'SSOMED'  Checking if attribute filter policy is active
2017-07-31 18:30:59,512 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPolicyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/PolicyRequirementRule:_87ee9238db6$
2017-07-31 18:30:59,513 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:132] - Attribute Filter Policy 'SSOMED'  Policy is active for this request
2017-07-31 18:30:59,513 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:159] - Attribute Filter Policy 'SSOMED'  Applying attribute filter policy to current set of attributes: [uid]
2017-07-31 18:30:59,513 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_91e4f9bbf6e53ced78d980aa3478201e'  Filtering values f$
2017-07-31 18:30:59,518 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_91e4f9bbf6e53ced78d980aa3478201e'  Filter has permitt$
2017-07-31 18:30:59,519 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:125] - Attribute Filter Policy 'example2'  Checking if attribute filter policy is active
2017-07-31 18:30:59,519 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPolicyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/Rule:_a17f21340f08cbe54b3b32d8e3b6$
2017-07-31 18:30:59,519 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:132] - Attribute Filter Policy 'example2'  Policy is active for this request
2017-07-31 18:30:59,520 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:159] - Attribute Filter Policy 'example2'  Applying attribute filter policy to current set of attributes: [uid]
2017-07-31 18:30:59,520 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:167] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'uid' remained after filtering
2017-07-31 18:30:59,535 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.PopulateProfileInterceptorContext:126] - Profile Action PopulateProfileInterceptorContext: Installing flow intercept/attribute-release into interceptor context
2017-07-31 18:30:59,537 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2017-07-31 18:30:59,538 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:101] - Profile Action SelectProfileInterceptorFlow: Checking flow intercept/attribute-release for applicability...
2017-07-31 18:30:59,538 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:84] - Profile Action SelectProfileInterceptorFlow: Selecting flow intercept/attribute-release
2017-07-31 18:31:03,394 - DEBUG [net.shibboleth.idp.consent.storage.impl.ConsentSerializer:104] - symbolics '{postOfficeBox=115, commonName=105, eduPersonPrimaryAffiliation=305, eduPersonNickname=302, mobileNumber=103, title=112, initial$
2017-07-31 18:31:03,886 - DEBUG [net.shibboleth.idp.consent.flow.impl.InitializeConsentContext:47] - Profile Action InitializeConsentContext: Created consent context 'ConsentContext{previousConsents={}, chosenConsents={}}'
2017-07-31 18:31:03,894 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.InitializeAttributeReleaseContext:47] - Profile Action InitializeAttributeReleaseContext: Created attribute release context 'AttributeReleaseContext{consentableAttr$
2017-07-31 18:31:03,911 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.AbstractAttributeReleaseAction:153] - Profile Action PopulateAttributeReleaseContext: Found attributeContext 'net.shibboleth.idp.attribute.context.AttributeContext@$
2017-07-31 18:31:04,718 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.PopulateAttributeReleaseContext:99] - Profile Action PopulateAttributeReleaseContext: Consentable attributes '{uid=IdPAttribute{id=uid, displayNames={}, displayDesc$
2017-07-31 18:31:04,752 - DEBUG [net.shibboleth.idp.consent.logic.impl.FlowIdLookupFunction:69] - Current flow id is 'intercept/attribute-release'
2017-07-31 18:31:04,756 - DEBUG [net.shibboleth.idp.consent.logic.impl.JoinFunction:81] - Result 'sriebeling:https://sso-med1.imib.rwth-aachen.de/shibboleth'
2017-07-31 18:31:04,757 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:53] - Profile Action ReadConsentFromStorage: Read storage record 'null' with context 'intercept/attribute-release' and key 'sriebeling:h$
2017-07-31 18:31:04,757 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:57] - Profile Action ReadConsentFromStorage: No storage record for context 'intercept/attribute-release' and key 'sriebeling:https://sso$
2017-07-31 18:31:04,767 - DEBUG [net.shibboleth.idp.consent.logic.impl.FlowIdLookupFunction:69] - Current flow id is 'intercept/attribute-release'
2017-07-31 18:31:04,769 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:53] - Profile Action ReadConsentFromStorage: Read storage record 'null' with context 'intercept/attribute-release' and key 'sriebeling'
2017-07-31 18:31:04,769 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:57] - Profile Action ReadConsentFromStorage: No storage record for context 'intercept/attribute-release' and key 'sriebeling'
2017-07-31 18:31:04,781 - DEBUG [net.shibboleth.idp.consent.flow.impl.PopulateConsentContext:65] - Profile Action PopulateConsentContext: Populating consents: [uid]
2017-07-31 18:31:04,789 - DEBUG [net.shibboleth.idp.consent.logic.impl.IsConsentRequiredPredicate:109] - Consent is required, no previous consents
2017-07-31 18:31:04,900 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:360] - Found matching scheme, returning name of 'sso-med1.imib.rwth-aachen.de'
2017-07-31 18:31:04,900 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:529] - No description matching the languages found, returning null
2017-07-31 18:31:04,901 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:661] - No UIInfo or InformationURLs returning null
2017-07-31 18:31:04,901 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:686] - No UIInfo or PrivacyStatementURLs returning null
2017-07-31 18:31:04,901 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:783] - No UIInfo or logos returning null
2017-07-31 18:31:04,901 - DEBUG [net.shibboleth.idp.ui.context.RelyingPartyUIContext:566] - No Organization, OrganizationName or names, returning null
2017-07-31 18:31:08,836 - DEBUG [net.shibboleth.idp.consent.flow.impl.ExtractConsent:80] - Profile Action ExtractConsent: Extracted consent ids '[uid]' from request parameter '_shib_idp_consentIds'
2017-07-31 18:31:08,837 - DEBUG [net.shibboleth.idp.consent.flow.impl.ExtractConsent:92] - Profile Action ExtractConsent: Consent context 'ConsentContext{previousConsents={}, chosenConsents={uid=Consent{id=uid, value=null, isApproved=tru$
2017-07-31 18:31:08,966 - INFO [Shibboleth-Consent-Audit.SSO:241] - 20170731T163108Z|https://sso-med1.imib.rwth-aachen.de/shibboleth|AttributeReleaseConsent|sriebeling|uid||true
2017-07-31 18:31:08,986 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.AbstractAttributeReleaseAction:153] - Profile Action ReleaseAttributes: Found attributeContext 'net.shibboleth.idp.attribute.context.AttributeContext@65f0c6e9'
2017-07-31 18:31:08,987 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:64] - Profile Action ReleaseAttributes: Consents '{uid=Consent{id=uid, value=null, isApproved=true}}'
2017-07-31 18:31:08,988 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:67] - Profile Action ReleaseAttributes: Attributes before release '{uid=IdPAttribute{id=uid, displayNames={}, displayDescriptions={}, encoders=[ne$
2017-07-31 18:31:08,989 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=uid, displayNames={}, displayDescriptions={}, encoders=[net.shibboleth.idp.saml$
2017-07-31 18:31:08,994 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:94] - Profile Action ReleaseAttributes: Releasing attributes '{uid=IdPAttribute{id=uid, displayNames={}, displayDescriptions={}, encoders=[net.shi$
2017-07-31 18:31:09,260 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:96] - Profile Action ReleaseAttributes: Not releasing attributes '{}'
2017-07-31 18:31:09,262 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.WriteProfileInterceptorResultToStorage:68] - Profile Action WriteProfileInterceptorResultToStorage: No results available from interceptor context, nothing to st$
2017-07-31 18:31:09,266 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2017-07-31 18:31:09,267 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:65] - Profile Action SelectProfileInterceptorFlow: Moving completed flow intercept/attribute-release to completed set, selecting ne$
2017-07-31 18:31:09,268 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:80] - Profile Action SelectProfileInterceptorFlow: No flows available to choose from
2017-07-31 18:31:09,798 - DEBUG [net.shibboleth.idp.saml.profile.impl.BaseAddAuthenticationStatementToAssertion:170] - Profile Action AddAuthnStatementToAssertion: Attempting to add an AuthenticationStatement to outgoing Assertion
2017-07-31 18:31:13,080 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.AddAuthnStatementToAssertion:165] - Profile Action AddAuthnStatementToAssertion: Added AuthenticationStatement to Assertion _3eda99de39391d2c9437306b050350b1
2017-07-31 18:31:13,691 - DEBUG [net.shibboleth.idp.saml.profile.impl.BaseAddAttributeStatementToAssertion:229] - Profile Action AddAttributeStatementToAssertion: Attempting to add an AttributeStatement to outgoing Assertion
2017-07-31 18:31:13,692 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.AddAttributeStatementToAssertion:174] - Profile Action AddAttributeStatementToAssertion: Attempting to encode attribute uid as a SAML 2 Attribute
2017-07-31 18:31:13,692 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.AddAttributeStatementToAssertion:188] - Profile Action AddAttributeStatementToAssertion: Encoding attribute uid as a SAML 2 Attribute
2017-07-31 18:31:13,692 - DEBUG [net.shibboleth.idp.saml.attribute.encoding.AbstractSAMLAttributeEncoder:154] - Beginning to encode attribute uid
2017-07-31 18:31:13,715 - DEBUG [net.shibboleth.idp.saml.attribute.encoding.SAMLEncoderSupport:73] - Encoding value sriebeling of attribute uid
2017-07-31 18:31:13,721 - DEBUG [net.shibboleth.idp.saml.attribute.encoding.AbstractSAMLAttributeEncoder:191] - Completed encoding 1 values for attribute uid
2017-07-31 18:31:13,802 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.AddAttributeStatementToAssertion:118] - Profile Action AddAttributeStatementToAssertion: Adding constructed AttributeStatement to Assertion _3eda99de39391d2c9437$
2017-07-31 18:31:14,159 - DEBUG [net.shibboleth.idp.saml.profile.logic.DefaultNameIdentifierFormatStrategy:100] - Configuration specifies the following formats: []
2017-07-31 18:31:14,160 - DEBUG [net.shibboleth.idp.saml.profile.logic.DefaultNameIdentifierFormatStrategy:110] - No formats specified in configuration or in metadata, returning default
2017-07-31 18:31:14,950 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.DecorateDelegatedAssertion:585] - Found Assertion with AuthnStatement to decorate in outbound Response
2017-07-31 18:31:14,955 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.DecorateDelegatedAssertion:288] - Issuance of delegated was not indicated, skipping assertion decoration
2017-07-31 18:31:17,879 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:159] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.BasicMessageHandlerCh$
2017-07-31 18:31:17,879 - 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$
2017-07-31 18:31:18,755 - 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
2017-07-31 18:31:18,854 - DEBUG [net.shibboleth.idp.profile.impl.RecordResponseComplete:89] - Profile Action RecordResponseComplete: Record response complete
2017-07-31 18:31:18,858 - INFO [Shibboleth-Audit.SSO:241] - 20170731T163118Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_891161f925dea5e00157cf2e426baf27|https://sso-med1.imib.rwth-aachen.de/shibboleth|http://shibboleth.net/ns/pr$