claims are not collected/transmitted to the client

[dominique-p]

Hello, The shibboleth-oidc extension was installed on our lab Shibboleth IdP instance, and I am testing it with the simple-web-app client.

Authentication works but not the transmission of claims: except for the username "testuser" simple-web-app/user shows no values for the claims. The attribute-resolver and attribute-filter work OK (cf lines 1-10 in the log extract for the latter). What is strange is that the login flow is supposed to display an approval page (views/intercept/attribute-release.vm) but the browser is sent back to simple-web-app without displaying anything. The form in system/views/oidc/approve.vm is used (a log line "mylog4" was added in it, cf line 49 of the log extract), but the claim list is already empty (line 48). In fact the preceding processing of scopes does not fill in that list. You'll find a log extract taken during a client authentication in http://pastebin.com/vrtgPY2k

I have tried hard to debug this, but I am at loss of ideas on how to continue (not being a java/spring developer doesn't help).

• Any idea of what to check to identify what goes wrong?

Thanks in advance for your lights!

[mmoayyed]

I'd need to see you resolver/filter files to say for sure. Could you attach those please?

[dominique-p]

Thanks for your prompt reply! You'll find the requested files them in attachment. But I already verified that this was not the problem: as the log extract shows (line 1-10) 10 attribute values have been collected and passed the filter. attribute-resolver-oidc.txt attribute-filter-oidc.txt

[mmoayyed]

Thanks. This is generally a symptom of this module failing to find an attribute release context in the profile request context. (Apologies if this just sounds too confusing) I can try to step into this and diagnose it, but it would help if you could explain the set of changes you may have applied if any, besides the attribute resolver/filtering rules. What else is modified? and how have you deployed the module?

[mmoayyed]

I ran through the setup. Some screenshots for you to review:

I made zero changes to the module. Most just made sure attributes/claims are resolved and released. At this point, this points to a misconfig on your side. Look into your IdP logs and you may find the root cause.

[dominique-p]

Essentially the instructions described in the section "Default IdP Configuration" of https://github.com/uchicago/shibboleth-oidc#user-content-default-idp-configuration were applied to a working installation of an 3.2.1 IdP based on the SWITCH AAI "distribution" (https://www.switch.ch/aai/guides/idp/). That means we started from and IdP installation with quite a few modifications made by SWITCH on the vanilla distribution. About attribute-release: in the files provided on github it seems that attribute-release is configured for the oidc login (cf OIDC.LoginConfiguration in relying-party.xml and oidc-protocol-system.xml). But as I mentioned the user is not shown the attribute-release.vm page (and I checked: there is no previous agreement for the user and the "client" relying party in the StorageRecords DB).

• Trying to fix that might be a next step? I just tried the other way round and removed the 'p:postAuthenticationFlows="attribute-release"' from these two files: the result is not affected (the list of non username claims remains empty).

A side issue: if either of the following directives is enabled in logback.xml

   <logger name="org.springframework.webflow" level="DEBUG" /> 
    <logger name="org.springframework.security" level="DEBUG />

then the behavior of the authentication session changes after submitting the password: in the first case it causes a "An error occurred: FlowExecutionException" reported to the user, in the second case it is "An error occurred: NullPointerException". cf log extract in attachments. log_FlowExecutionException.txt log_NullPointerException.txt

• Did you observe this as well? In any case this "Heisenberg" effect is not helping the debugging. :-(

[mmoayyed]

In any case this "Heisenberg" effect is not helping the debugging

Agreed; it's increasingly to difficult to review and make suggestions without seeing the thing in action. I especially wonder why in the world would changing "log levels" have anything to do with IdP core functionality?! That is bizarre and I submit to you that the issue is caused by something outside the IdP core somehow. Not sure what, but I have yet to witness/observe those issues. I am almost sure this is not a bug (as the certification process would have surely blocked approval if the IdP was unable to release attributes/claims)

What I would like to ask is, if you can share your "entire IdP" with me, so I can:

1. Verify steps taken for the default config. Sometimes a second pair of eyes is a good thing and it's entirely possible I have missed something in the docs.
2. Step through the changes with a debugger and figure out why or how things are getting nowhere.

You're also welcome to run the "overlay" option and see if the behavior persists.

If you also do need any additional logging anywhere in the OIDC module such that those would help clarify the flow of things, by all means please LMK and I'll gladly make those changes to make sense out of all this.

[mmoayyed]

I should add that if you prefer, I'd be glad to set up a shared screen session to review the configuration with you and perhaps suggest a fix here or there assuming sharing is not an option.

This would of course be something we'd schedule some time to our mutual agreement. (Assuming you're CET)

[dominique-p]

Hi, I saw your last message only after sending mine. I am very well aware that "this points to a misconfig " but as I said I am at loss of ideas for what to check or try next. As for the "Look into your IdP logs and you may find the root cause", well I have lost track on how many hours I have pored over the logs after every trial and error, but I don't see anything odd (difficult since I don't know what looks right). The authentication part, attribute resolving and filtering are OK. What follows attribute filtering is all in the log that was submitted (http://pastebin.com/vrtgPY2k):

• do you see some hint at a root cause in there? Alternatively,
• could you provide me with a DEBUG level log of a working session that would show what is different from the log I submitted?

[mmoayyed]

• I do not. Your logs show that the AttributeReleaseContext that is captured into what is called a ProfileRequestContext simply isnt there to be found. That's all I can tell you.
• Sure. I'll put together something tomorrow.

[dominique-p]

Crossed messages again! OK for a shared screen: see email.

[mmoayyed]

Logs from start to finish:

2017-01-20 17:04:53,673 - INFO [net.shibboleth.idp.log.LogbackLoggingService:240] - Shibboleth IdP Version 3.3.0
2017-01-20 17:04:53,677 - INFO [net.shibboleth.idp.log.LogbackLoggingService:241] - Java version='1.8.0_112' vendor='Oracle Corporation'
2017-01-20 17:04:53,682 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.LoggingService': Reload time set to: 300000, starting refresh thread
2017-01-20 17:04:53,761 - INFO [org.opensaml.core.config.InitializationService:48] - Initializing OpenSAML using the Java Services API
2017-01-20 17:04:53,836 - INFO [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:206] - Algorithm failed runtime support check, will not be usable: http://www.w3.org/2001/04/xmlenc#ripemd160
2017-01-20 17:04:53,841 - INFO [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:206] - Algorithm failed runtime support check, will not be usable: http://www.w3.org/2001/04/xmldsig-more#hmac-ripemd160
2017-01-20 17:04:53,853 - INFO [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:206] - Algorithm failed runtime support check, will not be usable: http://www.w3.org/2001/04/xmldsig-more#rsa-ripemd160
2017-01-20 17:04:54,808 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.AttributeFilterService': Performing initial load
2017-01-20 17:04:54,809 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.AttributeFilterService': Reloading service configuration
2017-01-20 17:04:54,814 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/attribute-filter.xml]
2017-01-20 17:04:54,848 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeFilterPolicyGroupParser:66] - Parsing attribute filter policy group ShibbolethFilterPolicy
2017-01-20 17:04:54,850 - DEBUG [net.shibboleth.idp.attribute.filter.spring.BaseFilterParser:169] - Element 'AttributeFilterPolicy' 'id' attribute 'default' is mapped to '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeFilterPolicy:default'
2017-01-20 17:04:54,851 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeFilterPolicyParser:84] - Parsing configuration for attribute filter policy: default
2017-01-20 17:04:54,864 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,865 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,866 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,867 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,867 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,868 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,869 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,869 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,870 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,871 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,871 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,872 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,872 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,872 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,873 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,874 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,874 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,875 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,875 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2017-01-20 17:04:54,876 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581] - Refreshing ApplicationContext:shibboleth.AttributeFilterService: startup date [Fri Jan 20 17:04:54 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:04:54,915 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeFilterServiceStrategy:54] - Creating Attribute Filter ShibbolethAttributeFilter with  1 Policies
2017-01-20 17:04:54,918 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.AttributeFilterService': Completed reload and swapped in latest configuration for service 'shibboleth.AttributeFilterService'
2017-01-20 17:04:54,918 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.AttributeFilterService': Reload complete
2017-01-20 17:04:54,919 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.AttributeFilterService': Reload time set to: 900000, starting refresh thread
2017-01-20 17:04:54,965 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.AttributeResolverService': Performing initial load
2017-01-20 17:04:54,966 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.AttributeResolverService': Reloading service configuration
2017-01-20 17:04:54,968 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/attribute-resolver.xml]
2017-01-20 17:04:55,017 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: name
2017-01-20 17:04:55,018 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,019 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'name': Setting displayNames {en_US=Name}
2017-01-20 17:04:55,020 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'name': Setting sourceAttributeID name
2017-01-20 17:04:55,020 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: given_name
2017-01-20 17:04:55,021 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,021 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'given_name': Setting displayNames {en_US=Given Name}
2017-01-20 17:04:55,022 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'given_name': Setting sourceAttributeID given_name
2017-01-20 17:04:55,022 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: family_name
2017-01-20 17:04:55,023 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,023 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'family_name': Setting displayNames {en_US=Family Name}
2017-01-20 17:04:55,023 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'family_name': Setting sourceAttributeID family_name
2017-01-20 17:04:55,024 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: middle_name
2017-01-20 17:04:55,024 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,025 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'middle_name': Setting displayNames {en_US=Middle Name}
2017-01-20 17:04:55,025 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'middle_name': Setting sourceAttributeID middle_name
2017-01-20 17:04:55,025 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: nickname
2017-01-20 17:04:55,026 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,026 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'nickname': Setting displayNames {en_US=Nickname}
2017-01-20 17:04:55,027 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'nickname': Setting sourceAttributeID nickname
2017-01-20 17:04:55,027 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: preferred_username
2017-01-20 17:04:55,027 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,028 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'preferred_username': Setting sourceAttributeID preferred_username
2017-01-20 17:04:55,028 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: profile
2017-01-20 17:04:55,029 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,029 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'profile': Setting displayNames {en_US=Profile}
2017-01-20 17:04:55,029 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'profile': Setting sourceAttributeID profile
2017-01-20 17:04:55,030 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: picture
2017-01-20 17:04:55,030 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,031 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'picture': Setting displayNames {en_US=Picture}
2017-01-20 17:04:55,031 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'picture': Setting sourceAttributeID picture
2017-01-20 17:04:55,031 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: website
2017-01-20 17:04:55,031 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,032 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'website': Setting displayNames {en_US=Website}
2017-01-20 17:04:55,032 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'website': Setting sourceAttributeID website
2017-01-20 17:04:55,033 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: email
2017-01-20 17:04:55,033 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,033 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'email': Setting displayNames {en_US=Email}
2017-01-20 17:04:55,034 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'email': Setting sourceAttributeID email
2017-01-20 17:04:55,034 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: email_verified
2017-01-20 17:04:55,035 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,035 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'email_verified': Setting sourceAttributeID email_verified
2017-01-20 17:04:55,036 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: gender
2017-01-20 17:04:55,036 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,036 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'gender': Setting displayNames {en_US=Gender}
2017-01-20 17:04:55,037 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'gender': Setting sourceAttributeID gender
2017-01-20 17:04:55,037 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: birthdate
2017-01-20 17:04:55,037 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,038 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'birthdate': Setting displayNames {en_US=Birth Date}
2017-01-20 17:04:55,038 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'birthdate': Setting sourceAttributeID birthdate
2017-01-20 17:04:55,039 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: zoneinfo
2017-01-20 17:04:55,039 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,039 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'zoneinfo': Setting sourceAttributeID zoneinfo
2017-01-20 17:04:55,040 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: locale
2017-01-20 17:04:55,040 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,040 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'locale': Setting sourceAttributeID locale
2017-01-20 17:04:55,041 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: phone_number
2017-01-20 17:04:55,041 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,041 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'phone_number': Setting displayNames {en_US=Phone Number}
2017-01-20 17:04:55,042 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'phone_number': Setting sourceAttributeID phone_number
2017-01-20 17:04:55,042 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: phone_number_verified
2017-01-20 17:04:55,043 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,043 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'phone_number_verified': Setting sourceAttributeID phone_number_verified
2017-01-20 17:04:55,044 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: address
2017-01-20 17:04:55,044 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,044 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:95] - Attribute Definition 'address': Setting displayNames {en_US=Address}
2017-01-20 17:04:55,045 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'address': Setting sourceAttributeID address
2017-01-20 17:04:55,045 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for AttributeDefinition plugin with id: updated_at
2017-01-20 17:04:55,045 - INFO [net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54] - Parsing configuration for Dependency with pluginId: staticAttributes
2017-01-20 17:04:55,046 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.BaseAttributeDefinitionParser:116] - Attribute Definition 'updated_at': Setting sourceAttributeID updated_at
2017-01-20 17:04:55,050 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for DataConnector plugin with id: staticAttributes
2017-01-20 17:04:55,052 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.ad.impl.ScriptedAttributeDefinitionParser:103] - Data Connector 'staticAttributes': Script: 

IdPAttribute = Java.type("net.shibboleth.idp.attribute.IdPAttribute");
StringAttributeValue = Java.type("net.shibboleth.idp.attribute.StringAttributeValue");
HashSet = Java.type("java.util.HashSet");
Integer = Java.type("java.lang.Integer");

logger = org.slf4j.LoggerFactory.getLogger("net.shibboleth.idp.attribute");

logger.info("**********************************************************");
logger.info("Resolving attributes for {}", resolutionContext.principal);

attr = new IdPAttribute("name");
set = new HashSet();
set.add(new StringAttributeValue("Admin"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("given_name");
set = new HashSet();
if (resolutionContext.principal.equals("casuser")) {
    set.add(new StringAttributeValue("James"));
} else {
    set.add(new StringAttributeValue("Jim"));
}
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("family_name");
set = new HashSet();
if (resolutionContext.principal.equals("casuser")) {
    set.add(new StringAttributeValue("Hicks"));
} else {
    set.add(new StringAttributeValue("Hickster"));
}
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("preferred_username");
set = new HashSet();
set.add(new StringAttributeValue("jsmith"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("email");
set = new HashSet();
set.add(new StringAttributeValue("jsmith@somewhere.org"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("middle_name");
set = new HashSet();
set.add(new StringAttributeValue("Ken"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("nickname");
set = new HashSet();
set.add(new StringAttributeValue("TheAdmin"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("preferred_username");
set = new HashSet();
set.add(new StringAttributeValue("MrSmith"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("profile");
set = new HashSet();
set.add(new StringAttributeValue("https://example.com/profile"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("picture");
set = new HashSet();
set.add(new StringAttributeValue("https://example.com/profile/image.jpg"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("website");
set = new HashSet();
set.add(new StringAttributeValue("https://example.com"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("email_verified");
set = new HashSet();
set.add(new StringAttributeValue("true"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("gender");
set = new HashSet();
set.add(new StringAttributeValue("Male"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("birthdate");
set = new HashSet();
set.add(new StringAttributeValue("1980-07-16"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("zoneinfo");
set = new HashSet();
set.add(new StringAttributeValue("America/Los_Angeles"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("locale");
set = new HashSet();
set.add(new StringAttributeValue("en_US"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("phone_number");
set = new HashSet();
set.add(new StringAttributeValue("+14255551212"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("phone_number_verified");
set = new HashSet();
set.add(new StringAttributeValue("true"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("address");
set = new HashSet();
set.add(new StringAttributeValue("201 Street Name, Gilbert AZ 85258"));
attr.setValues(set);
connectorResults.add(attr);

attr = new IdPAttribute("updated_at");
set = new HashSet();
set.add(new StringAttributeValue("2800012"));
attr.setValues(set);
connectorResults.add(attr);

2017-01-20 17:04:55,053 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581] - Refreshing ApplicationContext:shibboleth.AttributeResolverService: startup date [Fri Jan 20 17:04:55 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:04:55,714 - DEBUG [net.shibboleth.idp.attribute.resolver.spring.impl.AttributeResolverServiceStrategy:66] - Creating Attribute Resolver ShibbolethAttributeResolver with 19 Attribute Definition(s), 1 Data Connector(s) and 0 Principal Connector(s)
2017-01-20 17:04:55,717 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:511] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if data connector 'staticAttributes' is has a circular dependency
2017-01-20 17:04:55,718 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'website' has a circular dependency
2017-01-20 17:04:55,718 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'zoneinfo' has a circular dependency
2017-01-20 17:04:55,719 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'email_verified' has a circular dependency
2017-01-20 17:04:55,719 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'birthdate' has a circular dependency
2017-01-20 17:04:55,719 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'address' has a circular dependency
2017-01-20 17:04:55,720 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'gender' has a circular dependency
2017-01-20 17:04:55,720 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'profile' has a circular dependency
2017-01-20 17:04:55,720 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'phone_number_verified' has a circular dependency
2017-01-20 17:04:55,720 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'preferred_username' has a circular dependency
2017-01-20 17:04:55,721 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'given_name' has a circular dependency
2017-01-20 17:04:55,721 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'middle_name' has a circular dependency
2017-01-20 17:04:55,721 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'locale' has a circular dependency
2017-01-20 17:04:55,721 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'picture' has a circular dependency
2017-01-20 17:04:55,722 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'updated_at' has a circular dependency
2017-01-20 17:04:55,722 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'name' has a circular dependency
2017-01-20 17:04:55,722 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'nickname' has a circular dependency
2017-01-20 17:04:55,722 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'phone_number' has a circular dependency
2017-01-20 17:04:55,723 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'family_name' has a circular dependency
2017-01-20 17:04:55,723 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:516] - Attribute Resolver 'ShibbolethAttributeResolver': Checking if attribute definition 'email' has a circular dependency
2017-01-20 17:04:55,723 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.AttributeResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.AttributeResolverService'
2017-01-20 17:04:55,723 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.AttributeResolverService': Reload complete
2017-01-20 17:04:55,724 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.AttributeResolverService': Reload time set to: 900000, starting refresh thread
2017-01-20 17:04:55,736 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.NameIdentifierGenerationService': Performing initial load
2017-01-20 17:04:55,737 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.NameIdentifierGenerationService': Reloading service configuration
2017-01-20 17:04:55,739 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/saml-nameid.xml]
2017-01-20 17:04:55,755 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/system/conf/saml-nameid-system.xml]
2017-01-20 17:04:55,763 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581] - Refreshing ApplicationContext:shibboleth.NameIdentifierGenerationService: startup date [Fri Jan 20 17:04:55 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:04:55,846 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.NameIdentifierGenerationService': Completed reload and swapped in latest configuration for service 'shibboleth.NameIdentifierGenerationService'
2017-01-20 17:04:55,847 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.NameIdentifierGenerationService': Reload complete
2017-01-20 17:04:55,847 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.NameIdentifierGenerationService': Reload time set to: 900000, starting refresh thread
2017-01-20 17:04:55,866 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.RelyingPartyResolverService': Performing initial load
2017-01-20 17:04:55,866 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.RelyingPartyResolverService': Reloading service configuration
2017-01-20 17:04:55,868 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/relying-party.xml]
2017-01-20 17:04:55,882 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/credentials.xml]
2017-01-20 17:04:55,888 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/system/conf/relying-party-system.xml]
2017-01-20 17:04:55,903 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581] - Refreshing ApplicationContext:shibboleth.RelyingPartyResolverService: startup date [Fri Jan 20 17:04:55 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:04:56,453 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.MetadataResolverService': Performing initial load
2017-01-20 17:04:56,453 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.MetadataResolverService': Reloading service configuration
2017-01-20 17:04:56,458 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/metadata-providers.xml]
2017-01-20 17:04:56,557 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/system/conf/metadata-providers-system.xml]
2017-01-20 17:04:56,564 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581] - Refreshing ApplicationContext:shibboleth.MetadataResolverService: startup date [Fri Jan 20 17:04:56 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:04:56,596 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.MetadataResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.MetadataResolverService'
2017-01-20 17:04:56,597 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.MetadataResolverService': Reload complete
2017-01-20 17:04:56,795 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.RelyingPartyResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.RelyingPartyResolverService'
2017-01-20 17:04:56,796 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.RelyingPartyResolverService': Reload complete
2017-01-20 17:04:56,796 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.RelyingPartyResolverService': Reload time set to: 900000, starting refresh thread
2017-01-20 17:04:56,811 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.ReloadableAccessControlService': Performing initial load
2017-01-20 17:04:56,811 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.ReloadableAccessControlService': Reloading service configuration
2017-01-20 17:04:56,813 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/access-control.xml]
2017-01-20 17:04:56,829 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/system/conf/access-control-system.xml]
2017-01-20 17:04:56,838 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581] - Refreshing ApplicationContext:shibboleth.ReloadableAccessControlService: startup date [Fri Jan 20 17:04:56 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:04:56,882 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.ReloadableAccessControlService': Completed reload and swapped in latest configuration for service 'shibboleth.ReloadableAccessControlService'
2017-01-20 17:04:56,882 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.ReloadableAccessControlService': Reload complete
2017-01-20 17:04:56,883 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.ReloadableAccessControlService': Reload time set to: 300000, starting refresh thread
2017-01-20 17:04:56,895 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.ReloadableCASServiceRegistry': Performing initial load
2017-01-20 17:04:56,896 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.ReloadableCASServiceRegistry': Reloading service configuration
2017-01-20 17:04:56,898 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/conf/cas-protocol.xml]
2017-01-20 17:04:56,909 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581] - Refreshing ApplicationContext:shibboleth.ReloadableCASServiceRegistry: startup date [Fri Jan 20 17:04:56 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:04:56,931 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.ReloadableCASServiceRegistry': Completed reload and swapped in latest configuration for service 'shibboleth.ReloadableCASServiceRegistry'
2017-01-20 17:04:56,931 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.ReloadableCASServiceRegistry': Reload complete
2017-01-20 17:04:56,931 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.ReloadableCASServiceRegistry': Reload time set to: 900000, starting refresh thread
2017-01-20 17:05:00,833 - INFO [com.zaxxer.hikari.HikariDataSource:95] - Hikari pool HikariPool-0 is starting.
2017-01-20 17:05:00,837 - WARN [com.zaxxer.hikari.util.DriverDataSource:68] - Registered driver with driverClassName=org.hsqldb.jdbcDriver was not found, trying direct instantiation.
2017-01-20 17:05:01,805 - INFO [net.shibboleth.ext.spring.context.DelimiterAwareApplicationContext:581] - Refreshing WebApplicationContext for namespace 'idp-servlet': startup date [Fri Jan 20 17:05:01 IRST 2017]; parent: Root WebApplicationContext
2017-01-20 17:05:01,992 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'admin.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/admin/admin-abstract-flow.xml]'
2017-01-20 17:05:01,992 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'status' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/admin/status-flow.xml]'
2017-01-20 17:05:01,992 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'admin/resolvertest' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/admin/resolvertest-flow.xml]'
2017-01-20 17:05:01,993 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'admin/reload-service' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/admin/reload-service-flow.xml]'
2017-01-20 17:05:01,993 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'admin/reload-metadata' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/admin/reload-metadata-flow.xml]'
2017-01-20 17:05:01,994 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'admin/metrics' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/admin/metrics-flow.xml]'
2017-01-20 17:05:01,994 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'admin/storage' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/admin/storage-flow.xml]'
2017-01-20 17:05:01,994 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'Logout' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/logout/logout-flow.xml]'
2017-01-20 17:05:01,995 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'PropagateLogout' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/logout/logout-propagation-flow.xml]'
2017-01-20 17:05:01,995 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'logoutprop/cas' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/logout/propagation/cas-flow.xml]'
2017-01-20 17:05:01,995 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'logoutprop/saml2' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/logout/propagation/saml2-flow.xml]'
2017-01-20 17:05:01,996 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'saml.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml-abstract-flow.xml]'
2017-01-20 17:05:01,996 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'saml1.sso.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml1/sso-abstract-flow.xml]'
2017-01-20 17:05:01,997 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'saml2.sso.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/sso-abstract-flow.xml]'
2017-01-20 17:05:01,997 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'saml2.slo.front.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/slo-front-abstract-flow.xml]'
2017-01-20 17:05:01,997 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'Shibboleth/SSO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml1/sso-unsolicited-flow.xml]'
2017-01-20 17:05:01,997 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML1/SOAP/AttributeQuery' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml1/attribute-query-flow.xml]'
2017-01-20 17:05:01,998 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML1/SOAP/ArtifactResolution' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml1/artifact-resolution-flow.xml]'
2017-01-20 17:05:01,998 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/POST/SSO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/sso-post-flow.xml]'
2017-01-20 17:05:01,999 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/POST-SimpleSign/SSO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/sso-post-flow.xml]'
2017-01-20 17:05:01,999 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/Redirect/SSO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/sso-redirect-flow.xml]'
2017-01-20 17:05:02,000 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/Unsolicited/SSO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/sso-unsolicited-flow.xml]'
2017-01-20 17:05:02,000 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/SOAP/ECP' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/sso-ecp-flow.xml]'
2017-01-20 17:05:02,001 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/POST/SLO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/slo-post-flow.xml]'
2017-01-20 17:05:02,001 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/POST-SimpleSign/SLO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/slo-post-flow.xml]'
2017-01-20 17:05:02,002 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/Redirect/SLO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/slo-redirect-flow.xml]'
2017-01-20 17:05:02,003 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/SOAP/SLO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/slo-back-flow.xml]'
2017-01-20 17:05:02,003 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/SOAP/AttributeQuery' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/attribute-query-flow.xml]'
2017-01-20 17:05:02,003 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'SAML2/SOAP/ArtifactResolution' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/artifact-resolution-flow.xml]'
2017-01-20 17:05:02,004 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'IDWSF/SSOS' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/idwsf-ssos-flow.xml]'
2017-01-20 17:05:02,004 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn.events' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../conf/authn/authn-events-flow.xml]'
2017-01-20 17:05:02,005 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/authn-abstract-flow.xml]'
2017-01-20 17:05:02,005 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn-initial' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/initial-authn-flow.xml]'
2017-01-20 17:05:02,005 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/authn-flow.xml]'
2017-01-20 17:05:02,005 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/IPAddress' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/ipaddress-authn-flow.xml]'
2017-01-20 17:05:02,006 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/RemoteUserInternal' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/remoteuser-internal-authn-flow.xml]'
2017-01-20 17:05:02,006 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/Password' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/password-authn-flow.xml]'
2017-01-20 17:05:02,007 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/RemoteUser' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/remoteuser-authn-flow.xml]'
2017-01-20 17:05:02,007 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/X509' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/x509-authn-flow.xml]'
2017-01-20 17:05:02,007 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/X509Internal' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/x509-internal-authn-flow.xml]'
2017-01-20 17:05:02,008 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/SPNEGO' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/spnego-authn-flow.xml]'
2017-01-20 17:05:02,008 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/External' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/external-authn-flow.xml]'
2017-01-20 17:05:02,008 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/Duo' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/duo-authn-flow.xml]'
2017-01-20 17:05:02,009 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/MFA' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/authn/mfa-authn-flow.xml]'
2017-01-20 17:05:02,009 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n.events' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../conf/c14n/subject-c14n-events-flow.xml]'
2017-01-20 17:05:02,009 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-abstract-flow.xml]'
2017-01-20 17:05:02,009 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-flow.xml]'
2017-01-20 17:05:02,010 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/simple' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/simple-subject-c14n-flow.xml]'
2017-01-20 17:05:02,010 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/x500' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/x500-subject-c14n-flow.xml]'
2017-01-20 17:05:02,010 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/attribute' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/attribute-sourced-subject-c14n-flow.xml]'
2017-01-20 17:05:02,011 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/SAML2Transient' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,011 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/SAML2CryptoTransient' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,011 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/SAML2Persistent' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,012 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/SAML2Transform' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,012 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/SAML1Transient' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,013 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/SAML1CryptoTransient' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,013 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/SAML1Transform' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,013 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'c14n/LegacyPrincipalConnector' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/c14n/subject-c14n-saml-default-flow.xml]'
2017-01-20 17:05:02,014 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept.events' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../conf/intercept/intercept-events-flow.xml]'
2017-01-20 17:05:02,014 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/intercept/intercept-abstract-flow.xml]'
2017-01-20 17:05:02,014 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/intercept/intercept-flow.xml]'
2017-01-20 17:05:02,015 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/context-check' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/intercept/context-check-flow.xml]'
2017-01-20 17:05:02,015 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/expiring-password' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/intercept/expiring-password-flow.xml]'
2017-01-20 17:05:02,016 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/terms-of-use' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/intercept/terms-of-use-flow.xml]'
2017-01-20 17:05:02,016 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/attribute-release' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/intercept/attribute-release-flow.xml]'
2017-01-20 17:05:02,016 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'security-policy.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/security-abstract-flow.xml]'
2017-01-20 17:05:02,016 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/security-policy/shibboleth-sso' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml1/sso-security-flow.xml]'
2017-01-20 17:05:02,017 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/security-policy/saml2-sso' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/sso-security-flow.xml]'
2017-01-20 17:05:02,017 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/security-policy/saml2-ecp' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/ecp-security-flow.xml]'
2017-01-20 17:05:02,017 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/security-policy/saml2-slo' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/slo-security-flow.xml]'
2017-01-20 17:05:02,017 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/security-policy/saml2-idwsf-ssos' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/saml2/idwsf-ssos-security-flow.xml]'
2017-01-20 17:05:02,018 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'intercept/security-policy/saml-soap' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/saml/soap-security-flow.xml]'
2017-01-20 17:05:02,018 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas.abstract' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/cas-abstract-flow.xml]'
2017-01-20 17:05:02,019 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas.abstractValidate' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/validate-abstract-flow.xml]'
2017-01-20 17:05:02,019 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas/login' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/login/login-flow.xml]'
2017-01-20 17:05:02,019 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas/proxy' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/proxy/proxy-flow.xml]'
2017-01-20 17:05:02,020 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas/serviceValidate' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/serviceValidate/serviceValidate-flow.xml]'
2017-01-20 17:05:02,020 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas/proxyValidate' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/proxyValidate/proxyValidate-flow.xml]'
2017-01-20 17:05:02,020 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas/samlValidate' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/samlValidate/samlValidate-flow.xml]'
2017-01-20 17:05:02,021 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas/validate' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/cas/validate/validate-flow.xml]'
2017-01-20 17:05:02,021 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'cas/logout' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/logout/logout-flow.xml]'
2017-01-20 17:05:02,021 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'client-storage/read' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/client-storage/client-storage-read-flow.xml]'
2017-01-20 17:05:02,021 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'client-storage/write' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/client-storage/client-storage-write-flow.xml]'
2017-01-20 17:05:02,022 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'oidc/login' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/../system/flows/oidc/login/login-flow.xml]'
2017-01-20 17:05:02,024 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/conditions/account-locked' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/authn/conditions/account-locked/account-locked-flow.xml]'
2017-01-20 17:05:02,024 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/conditions' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/authn/conditions/conditions-flow.xml]'
2017-01-20 17:05:02,025 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/conditions/expired-password' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/authn/conditions/expired-password/expired-password-flow.xml]'
2017-01-20 17:05:02,025 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'authn/conditions/expiring-password' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/authn/conditions/expiring-password/expiring-password-flow.xml]'
2017-01-20 17:05:02,025 - DEBUG [net.shibboleth.idp.profile.spring.factory.FlowDefinitionRegistryFactoryBean:240] - Registered flow ID 'user/prefs' using 'file [/Users/Misagh/Workspace/GitWorkspace/shibboleth-oidc/idp-webapp-overlay/target/idp-webapp-overlay-3.3.0/idp/flows/user/prefs/prefs-flow.xml]'
2017-01-20 17:05:02,188 - INFO [net.shibboleth.idp.authn.impl.RemoteUserAuthServlet:193] - RemoteUserAuthServlet will process REMOTE_USER, along with attributes [] and headers []
2017-01-20 17:05:06,716 - DEBUG [net.shibboleth.idp.oidc.config.ShibbolethOAuth2RequestFactory:57] - Authorization request contains acr_values. Decoding and storing values into the request
2017-01-20 17:05:06,967 - DEBUG [net.shibboleth.idp.oidc.flow.InitializeLoginAction:52] - Profile Action InitializeLoginAction: Initializing login action
2017-01-20 17:05:07,090 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:246] - Constructing authorization request
2017-01-20 17:05:07,091 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:358] - Added request parameter scope with value openid email address profile phone
2017-01-20 17:05:07,091 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:358] - Added request parameter acr_values with value mfa-gauth,mfa-duo
2017-01-20 17:05:07,092 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:358] - Added request parameter response_type with value code
2017-01-20 17:05:07,092 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:358] - Added request parameter redirect_uri with value https://mmoayyed.unicon.net:9443/simple-web-app/openid_connect_login
2017-01-20 17:05:07,092 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:358] - Added request parameter state with value 3a9331a7fd66d
2017-01-20 17:05:07,093 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:358] - Added request parameter nonce with value 76192c002225
2017-01-20 17:05:07,093 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:358] - Added request parameter client_id with value client
2017-01-20 17:05:07,094 - DEBUG [net.shibboleth.idp.oidc.config.ShibbolethOAuth2RequestFactory:57] - Authorization request contains acr_values. Decoding and storing values into the request
2017-01-20 17:05:07,094 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:217] - Loading client by id client
2017-01-20 17:05:07,095 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:115] - Found client client.
2017-01-20 17:05:07,095 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:235] - Removed login hint attribute from session
2017-01-20 17:05:07,096 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:195] - Success. Proceeding with building the authorization context based on the request
2017-01-20 17:05:07,096 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthorizationRequestContextAction:202] - Returning final event success
2017-01-20 17:05:07,108 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client
2017-01-20 17:05:07,108 - DEBUG [net.shibboleth.idp.oidc.flow.BuildRelyingPartyContextAction:93] - Profile Action BuildRelyingPartyContextAction: Setting up RP context for verified relying party client
2017-01-20 17:05:07,109 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthenticationContextAction:62] - Created client entity descriptor for client
2017-01-20 17:05:07,120 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:293] - Resolving relying party configuration
2017-01-20 17:05:07,121 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:314] - No relying party configurations are applicable, returning the default configuration shibboleth.DefaultRelyingParty
2017-01-20 17:05:07,121 - DEBUG [net.shibboleth.idp.profile.impl.SelectRelyingPartyConfiguration:136] - Profile Action SelectRelyingPartyConfiguration: Found relying party configuration shibboleth.DefaultRelyingParty for request
2017-01-20 17:05:07,133 - DEBUG [net.shibboleth.idp.oidc.flow.CheckAuthenticationRequiredAction:84] - Profile Action CheckAuthenticationRequiredAction: Checking whether authentication is required
2017-01-20 17:05:07,133 - DEBUG [net.shibboleth.idp.oidc.flow.CheckAuthenticationRequiredAction:129] - IdP session not found
2017-01-20 17:05:07,134 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthenticationContextAction:97] - Profile Action BuildAuthenticationContextAction: Building authentication context
2017-01-20 17:05:07,136 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthenticationContextAction:118] - Authentication context does not require force authN for client
2017-01-20 17:05:07,286 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:200] - Profile Action PopulateAuthenticationContext: Installed 1 potential authentication flows into AuthenticationContext
2017-01-20 17:05:07,302 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client
2017-01-20 17:05:07,327 - DEBUG [net.shibboleth.idp.authn.impl.InitializeRequestedPrincipalContext:117] - Profile Action InitializeRequestedPrincipalContext: Leaving existing RequestedPrincipalContext in place
2017-01-20 17:05:07,335 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile Action FilterFlowsByForcedAuthn: Request does not have forced authentication requirement, nothing to do
2017-01-20 17:05:07,342 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2017-01-20 17:05:07,355 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:370] - Profile Action SelectAuthenticationFlow: Specific principals requested with 'exact' operator: [AuthnContextClassRefPrincipal{authnContextClassRef=urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport}]
2017-01-20 17:05:07,357 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:386] - Profile Action SelectAuthenticationFlow: No active results available, selecting an inactive flow
2017-01-20 17:05:07,358 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:407] - Profile Action SelectAuthenticationFlow: Checking for an inactive flow compatible with operator 'exact' and principal 'urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport'
2017-01-20 17:05:07,359 - DEBUG [net.shibboleth.idp.authn.principal.PrincipalEvalPredicateFactoryRegistry:82] - Registry located predicate factory of type 'net.shibboleth.idp.authn.principal.impl.ExactPrincipalEvalPredicateFactory' for principal type 'class net.shibboleth.idp.saml.authn.principal.AuthnContextClassRefPrincipal' and operator 'exact'
2017-01-20 17:05:07,361 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/Password
2017-01-20 17:05:07,623 - DEBUG [net.shibboleth.idp.authn.impl.ExtractUsernamePasswordFromBasicAuth:115] - Profile Action ExtractUsernamePasswordFromBasicAuth: No appropriate Authorization header found
2017-01-20 17:05:09,242 - DEBUG [net.shibboleth.idp.authn.AbstractExtractionAction:137] - Profile Action ExtractUsernamePasswordFromFormRequest: Trimming whitespace of input string 'casuser'
2017-01-20 17:05:09,263 - DEBUG [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:243] - Profile Action ValidateUsernamePasswordAgainstJAAS: Attempting to authenticate user 'casuser' via 'ShibUserPassAuth'
2017-01-20 17:05:09,263 - DEBUG [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:337] - Profile Action ValidateUsernamePasswordAgainstJAAS: Using custom JAAS configuration type JavaLoginConfig with parameters of type java.security.URIParameter
2017-01-20 17:05:09,267 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstJAAS:246] - Profile Action ValidateUsernamePasswordAgainstJAAS: Login by 'casuser' succeeded
2017-01-20 17:05:09,269 - DEBUG [net.shibboleth.idp.authn.AbstractValidationAction:341] - Profile Action ValidateUsernamePasswordAgainstJAAS: Adding custom Principal(s) defined on underlying flow descriptor
2017-01-20 17:05:09,277 - DEBUG [net.shibboleth.idp.authn.impl.PopulateSubjectCanonicalizationContext:79] - Profile Action PopulateSubjectCanonicalizationContext: Installing 2 canonicalization flows into SubjectCanonicalizationContext
2017-01-20 17:05:09,438 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/x500 for applicability...
2017-01-20 17:05:09,439 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:106] - Profile Action SelectSubjectCanonicalizationFlow: Canonicalization flow c14n/x500 was not applicable to this request
2017-01-20 17:05:09,440 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/simple for applicability...
2017-01-20 17:05:09,440 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:83] - Profile Action SelectSubjectCanonicalizationFlow: Selecting canonicalization flow c14n/simple
2017-01-20 17:05:09,517 - DEBUG [net.shibboleth.idp.authn.AbstractSubjectCanonicalizationAction:226] - Profile Action SimpleSubjectCanonicalization: trimming whitespace of input string 'casuser'
2017-01-20 17:05:09,528 - DEBUG [net.shibboleth.idp.session.impl.DetectIdentitySwitch:148] - Profile Action DetectIdentitySwitch: No previous session found, nothing to do
2017-01-20 17:05:09,535 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeAuthentication:137] - Profile Action FinalizeAuthentication: Canonical principal name was established as 'casuser'
2017-01-20 17:05:09,535 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeAuthentication:242] - Profile Action FinalizeAuthentication: Checking result for compatibility with operator 'exact' and principal 'urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport'
2017-01-20 17:05:09,536 - DEBUG [net.shibboleth.idp.authn.principal.PrincipalEvalPredicateFactoryRegistry:82] - Registry located predicate factory of type 'net.shibboleth.idp.authn.principal.impl.ExactPrincipalEvalPredicateFactory' for principal type 'class net.shibboleth.idp.saml.authn.principal.AuthnContextClassRefPrincipal' and operator 'exact'
2017-01-20 17:05:09,536 - DEBUG [net.shibboleth.idp.authn.impl.FinalizeAuthentication:262] - Profile Action FinalizeAuthentication: Principal 'urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport' in authentication result satisfies request for principal 'urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport'
2017-01-20 17:05:09,544 - DEBUG [net.shibboleth.idp.session.impl.UpdateSessionWithAuthenticationResult:221] - Profile Action UpdateSessionWithAuthenticationResult: Creating new session for principal casuser
2017-01-20 17:05:09,551 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedSessionManager:533] - Created new session 64abe5965c45bbec3cc9190e082e346b8b952c3fa9e8d9171d0b77f05bf28885 for principal casuser
2017-01-20 17:05:09,551 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedIdPSession:569] - Saving AuthenticationResult for flow authn/Password in session 64abe5965c45bbec3cc9190e082e346b8b952c3fa9e8d9171d0b77f05bf28885
2017-01-20 17:05:09,563 - DEBUG [net.shibboleth.idp.oidc.flow.BuildAuthenticationContextAction:68] - Located relying party context with id client
2017-01-20 17:05:09,577 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:213] - Attribute Resolver 'ShibbolethAttributeResolver': Initiating attribute resolution
2017-01-20 17:05:09,578 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:221] - Attribute Resolver 'ShibbolethAttributeResolver': Attempting to resolve the following attribute definitions [website, zoneinfo, email_verified, birthdate, address, gender, profile, phone_number_verified, preferred_username, given_name, middle_name, locale, picture, updated_at, name, nickname, phone_number, family_name, email]
2017-01-20 17:05:09,579 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'website'
2017-01-20 17:05:09,580 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:367] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving data connector staticAttributes
2017-01-20 17:05:09,581 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:179] - Data Connector 'staticAttributes': adding to-be-populated attribute set connectorResults to script context
2017-01-20 17:05:09,581 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:182] - Data Connector 'staticAttributes': adding current attribute resolution contexts to script context
2017-01-20 17:05:09,656 - INFO [net.shibboleth.idp.attribute:8] - **********************************************************
2017-01-20 17:05:09,676 - INFO [net.shibboleth.idp.attribute:9] - Resolving attributes for casuser
2017-01-20 17:05:09,778 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'updated_at' has 1 values.
2017-01-20 17:05:09,779 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'phone_number' has 1 values.
2017-01-20 17:05:09,780 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'website' has 1 values.
2017-01-20 17:05:09,780 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'picture' has 1 values.
2017-01-20 17:05:09,781 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'address' has 1 values.
2017-01-20 17:05:09,781 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'gender' has 1 values.
2017-01-20 17:05:09,782 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'profile' has 1 values.
2017-01-20 17:05:09,782 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'family_name' has 1 values.
2017-01-20 17:05:09,782 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'email' has 1 values.
2017-01-20 17:05:09,783 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'zoneinfo' has 1 values.
2017-01-20 17:05:09,783 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'locale' has 1 values.
2017-01-20 17:05:09,784 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'preferred_username' has 1 values.
2017-01-20 17:05:09,785 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'nickname' has 1 values.
2017-01-20 17:05:09,785 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'phone_number_verified' has 1 values.
2017-01-20 17:05:09,786 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'middle_name' has 1 values.
2017-01-20 17:05:09,786 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'preferred_username' has 1 values.
2017-01-20 17:05:09,786 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'name' has 1 values.
2017-01-20 17:05:09,787 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'email_verified' has 1 values.
2017-01-20 17:05:09,787 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'given_name' has 1 values.
2017-01-20 17:05:09,788 - DEBUG [net.shibboleth.idp.attribute.resolver.dc.impl.ScriptedDataConnector:231] - Data Connector 'staticAttributes': Attribute 'birthdate' has 1 values.
2017-01-20 17:05:09,788 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:139] - Data Connector 'staticAttributes': produced the following 19 attributes during resolution [website, zoneinfo, address, email_verified, birthdate, gender, profile, phone_number_verified, preferred_username, locale, middle_name, given_name, picture, updated_at, nickname, name, phone_number, family_name, email]
2017-01-20 17:05:09,788 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'website': Values '[StringAttributeValue{value=https://example.com}]'
2017-01-20 17:05:09,789 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'zoneinfo': Values '[StringAttributeValue{value=America/Los_Angeles}]'
2017-01-20 17:05:09,789 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'address': Values '[StringAttributeValue{value=201 Street Name, Gilbert AZ 85258}]'
2017-01-20 17:05:09,790 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'email_verified': Values '[StringAttributeValue{value=true}]'
2017-01-20 17:05:09,790 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'birthdate': Values '[StringAttributeValue{value=1980-07-16}]'
2017-01-20 17:05:09,790 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'gender': Values '[StringAttributeValue{value=Male}]'
2017-01-20 17:05:09,791 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'profile': Values '[StringAttributeValue{value=https://example.com/profile}]'
2017-01-20 17:05:09,791 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'phone_number_verified': Values '[StringAttributeValue{value=true}]'
2017-01-20 17:05:09,792 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'preferred_username': Values '[StringAttributeValue{value=MrSmith}]'
2017-01-20 17:05:09,793 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'locale': Values '[StringAttributeValue{value=en_US}]'
2017-01-20 17:05:09,793 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'middle_name': Values '[StringAttributeValue{value=Ken}]'
2017-01-20 17:05:09,794 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'given_name': Values '[StringAttributeValue{value=James}]'
2017-01-20 17:05:09,794 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'picture': Values '[StringAttributeValue{value=https://example.com/profile/image.jpg}]'
2017-01-20 17:05:09,795 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'updated_at': Values '[StringAttributeValue{value=2800012}]'
2017-01-20 17:05:09,796 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'nickname': Values '[StringAttributeValue{value=TheAdmin}]'
2017-01-20 17:05:09,796 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'name': Values '[StringAttributeValue{value=Admin}]'
2017-01-20 17:05:09,797 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'phone_number': Values '[StringAttributeValue{value=+14255551212}]'
2017-01-20 17:05:09,797 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'family_name': Values '[StringAttributeValue{value=Hicks}]'
2017-01-20 17:05:09,798 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'email': Values '[StringAttributeValue{value=jsmith@somewhere.org}]'
2017-01-20 17:05:09,798 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:385] - Attribute Resolver 'ShibbolethAttributeResolver': Data connector 'staticAttributes' resolved the following attributes: [website, zoneinfo, address, email_verified, birthdate, gender, profile, phone_number_verified, preferred_username, locale, middle_name, given_name, picture, updated_at, nickname, name, phone_number, family_name, email]
2017-01-20 17:05:09,800 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'website'
2017-01-20 17:05:09,801 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'website': produced an attribute with the following values [StringAttributeValue{value=https://example.com}]
2017-01-20 17:05:09,803 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'website' produced an attribute with 1 values
2017-01-20 17:05:09,804 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'zoneinfo'
2017-01-20 17:05:09,805 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'zoneinfo'
2017-01-20 17:05:09,805 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'zoneinfo': produced an attribute with the following values [StringAttributeValue{value=America/Los_Angeles}]
2017-01-20 17:05:09,806 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'zoneinfo' produced an attribute with 1 values
2017-01-20 17:05:09,806 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'email_verified'
2017-01-20 17:05:09,807 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'email_verified'
2017-01-20 17:05:09,807 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'email_verified': produced an attribute with the following values [StringAttributeValue{value=true}]
2017-01-20 17:05:09,808 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'email_verified' produced an attribute with 1 values
2017-01-20 17:05:09,808 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'birthdate'
2017-01-20 17:05:09,809 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'birthdate'
2017-01-20 17:05:09,810 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'birthdate': produced an attribute with the following values [StringAttributeValue{value=1980-07-16}]
2017-01-20 17:05:09,810 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'birthdate' produced an attribute with 1 values
2017-01-20 17:05:09,811 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'address'
2017-01-20 17:05:09,812 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'address'
2017-01-20 17:05:09,812 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'address': produced an attribute with the following values [StringAttributeValue{value=201 Street Name, Gilbert AZ 85258}]
2017-01-20 17:05:09,813 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'address' produced an attribute with 1 values
2017-01-20 17:05:09,814 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'gender'
2017-01-20 17:05:09,814 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'gender'
2017-01-20 17:05:09,815 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'gender': produced an attribute with the following values [StringAttributeValue{value=Male}]
2017-01-20 17:05:09,816 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'gender' produced an attribute with 1 values
2017-01-20 17:05:09,816 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'profile'
2017-01-20 17:05:09,817 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'profile'
2017-01-20 17:05:09,817 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'profile': produced an attribute with the following values [StringAttributeValue{value=https://example.com/profile}]
2017-01-20 17:05:09,818 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'profile' produced an attribute with 1 values
2017-01-20 17:05:09,818 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'phone_number_verified'
2017-01-20 17:05:09,819 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'phone_number_verified'
2017-01-20 17:05:09,819 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'phone_number_verified': produced an attribute with the following values [StringAttributeValue{value=true}]
2017-01-20 17:05:09,819 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'phone_number_verified' produced an attribute with 1 values
2017-01-20 17:05:09,820 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'preferred_username'
2017-01-20 17:05:09,820 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'preferred_username'
2017-01-20 17:05:09,821 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'preferred_username': produced an attribute with the following values [StringAttributeValue{value=MrSmith}]
2017-01-20 17:05:09,822 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'preferred_username' produced an attribute with 1 values
2017-01-20 17:05:09,822 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'given_name'
2017-01-20 17:05:09,823 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'given_name'
2017-01-20 17:05:09,823 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'given_name': produced an attribute with the following values [StringAttributeValue{value=James}]
2017-01-20 17:05:09,824 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'given_name' produced an attribute with 1 values
2017-01-20 17:05:09,824 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'middle_name'
2017-01-20 17:05:09,826 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'middle_name'
2017-01-20 17:05:09,826 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'middle_name': produced an attribute with the following values [StringAttributeValue{value=Ken}]
2017-01-20 17:05:09,827 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'middle_name' produced an attribute with 1 values
2017-01-20 17:05:09,828 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'locale'
2017-01-20 17:05:09,828 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'locale'
2017-01-20 17:05:09,829 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'locale': produced an attribute with the following values [StringAttributeValue{value=en_US}]
2017-01-20 17:05:09,830 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'locale' produced an attribute with 1 values
2017-01-20 17:05:09,830 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'picture'
2017-01-20 17:05:09,831 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'picture'
2017-01-20 17:05:09,831 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'picture': produced an attribute with the following values [StringAttributeValue{value=https://example.com/profile/image.jpg}]
2017-01-20 17:05:09,832 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'picture' produced an attribute with 1 values
2017-01-20 17:05:09,833 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'updated_at'
2017-01-20 17:05:09,834 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'updated_at'
2017-01-20 17:05:09,834 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'updated_at': produced an attribute with the following values [StringAttributeValue{value=2800012}]
2017-01-20 17:05:09,835 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'updated_at' produced an attribute with 1 values
2017-01-20 17:05:09,835 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'name'
2017-01-20 17:05:09,836 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'name'
2017-01-20 17:05:09,837 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'name': produced an attribute with the following values [StringAttributeValue{value=Admin}]
2017-01-20 17:05:09,837 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'name' produced an attribute with 1 values
2017-01-20 17:05:09,838 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'nickname'
2017-01-20 17:05:09,838 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'nickname'
2017-01-20 17:05:09,839 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'nickname': produced an attribute with the following values [StringAttributeValue{value=TheAdmin}]
2017-01-20 17:05:09,840 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'nickname' produced an attribute with 1 values
2017-01-20 17:05:09,840 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'phone_number'
2017-01-20 17:05:09,841 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'phone_number'
2017-01-20 17:05:09,841 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'phone_number': produced an attribute with the following values [StringAttributeValue{value=+14255551212}]
2017-01-20 17:05:09,842 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'phone_number' produced an attribute with 1 values
2017-01-20 17:05:09,843 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'family_name'
2017-01-20 17:05:09,843 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'family_name'
2017-01-20 17:05:09,844 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'family_name': produced an attribute with the following values [StringAttributeValue{value=Hicks}]
2017-01-20 17:05:09,844 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'family_name' produced an attribute with 1 values
2017-01-20 17:05:09,844 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'email'
2017-01-20 17:05:09,845 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'email'
2017-01-20 17:05:09,846 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'email': produced an attribute with the following values [StringAttributeValue{value=jsmith@somewhere.org}]
2017-01-20 17:05:09,846 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'email' produced an attribute with 1 values
2017-01-20 17:05:09,847 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:231] - Attribute Resolver 'ShibbolethAttributeResolver': Finalizing resolved attributes
2017-01-20 17:05:09,848 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition website result
2017-01-20 17:05:09,851 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'website' has 1 values after post-processing
2017-01-20 17:05:09,852 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition zoneinfo result
2017-01-20 17:05:09,853 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'zoneinfo' has 1 values after post-processing
2017-01-20 17:05:09,853 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition email_verified result
2017-01-20 17:05:09,854 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'email_verified' has 1 values after post-processing
2017-01-20 17:05:09,854 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition birthdate result
2017-01-20 17:05:09,855 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'birthdate' has 1 values after post-processing
2017-01-20 17:05:09,855 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition address result
2017-01-20 17:05:09,856 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'address' has 1 values after post-processing
2017-01-20 17:05:09,856 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition gender result
2017-01-20 17:05:09,856 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'gender' has 1 values after post-processing
2017-01-20 17:05:09,857 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition profile result
2017-01-20 17:05:09,857 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'profile' has 1 values after post-processing
2017-01-20 17:05:09,857 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition phone_number_verified result
2017-01-20 17:05:09,858 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'phone_number_verified' has 1 values after post-processing
2017-01-20 17:05:09,858 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition preferred_username result
2017-01-20 17:05:09,859 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'preferred_username' has 1 values after post-processing
2017-01-20 17:05:09,859 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition given_name result
2017-01-20 17:05:09,860 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'given_name' has 1 values after post-processing
2017-01-20 17:05:09,860 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition middle_name result
2017-01-20 17:05:09,860 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'middle_name' has 1 values after post-processing
2017-01-20 17:05:09,861 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition locale result
2017-01-20 17:05:09,861 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'locale' has 1 values after post-processing
2017-01-20 17:05:09,861 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition picture result
2017-01-20 17:05:09,862 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'picture' has 1 values after post-processing
2017-01-20 17:05:09,862 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition updated_at result
2017-01-20 17:05:09,862 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'updated_at' has 1 values after post-processing
2017-01-20 17:05:09,863 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition name result
2017-01-20 17:05:09,863 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'name' has 1 values after post-processing
2017-01-20 17:05:09,864 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition nickname result
2017-01-20 17:05:09,864 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'nickname' has 1 values after post-processing
2017-01-20 17:05:09,864 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition phone_number result
2017-01-20 17:05:09,865 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'phone_number' has 1 values after post-processing
2017-01-20 17:05:09,865 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition family_name result
2017-01-20 17:05:09,866 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'family_name' has 1 values after post-processing
2017-01-20 17:05:09,866 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition email result
2017-01-20 17:05:09,867 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'email' has 1 values after post-processing
2017-01-20 17:05:09,867 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:236] - Attribute Resolver 'ShibbolethAttributeResolver': Final resolved attribute collection: [website, zoneinfo, address, email_verified, birthdate, gender, profile, phone_number_verified, preferred_username, locale, middle_name, given_name, picture, updated_at, nickname, name, phone_number, family_name, email]
2017-01-20 17:05:09,881 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:125] - Attribute filtering engine 'ShibbolethAttributeFilter'  Beginning process of filtering the following 19 attributes: [website, zoneinfo, address, email_verified, birthdate, gender, profile, phone_number_verified, preferred_username, locale, middle_name, given_name, picture, updated_at, nickname, name, phone_number, family_name, email]
2017-01-20 17:05:09,882 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:128] - Attribute Filter Policy 'default'  Checking if attribute filter policy is active
2017-01-20 17:05:09,882 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPolicyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/PolicyRequirementRule:_fd110ca3fc9cc51f65690a91ee6c4497': Found attribute requester: client
2017-01-20 17:05:09,883 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:135] - Attribute Filter Policy 'default'  Policy is active for this request
2017-01-20 17:05:09,883 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:162] - Attribute Filter Policy 'default'  Applying attribute filter policy to current set of attributes: [website, zoneinfo, address, email_verified, birthdate, gender, profile, phone_number_verified, preferred_username, locale, middle_name, given_name, picture, updated_at, nickname, name, phone_number, family_name, email]
2017-01-20 17:05:09,884 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_aed038b4c34cdef04a8e68d9cb29b1b7'  Filtering values for attribute 'name' which currently contains 1 values
2017-01-20 17:05:09,884 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_aed038b4c34cdef04a8e68d9cb29b1b7'  Filter has permitted the release of 1 values for attribute 'name'
2017-01-20 17:05:09,885 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_0db08a867766cfafe675630522e3ad2f'  Filtering values for attribute 'given_name' which currently contains 1 values
2017-01-20 17:05:09,885 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_0db08a867766cfafe675630522e3ad2f'  Filter has permitted the release of 1 values for attribute 'given_name'
2017-01-20 17:05:09,886 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e706b66aab5efb3853559682e944284c'  Filtering values for attribute 'family_name' which currently contains 1 values
2017-01-20 17:05:09,886 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e706b66aab5efb3853559682e944284c'  Filter has permitted the release of 1 values for attribute 'family_name'
2017-01-20 17:05:09,887 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_cd4561b3c752cd1c8e1713e2563bb047'  Filtering values for attribute 'middle_name' which currently contains 1 values
2017-01-20 17:05:09,887 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_cd4561b3c752cd1c8e1713e2563bb047'  Filter has permitted the release of 1 values for attribute 'middle_name'
2017-01-20 17:05:09,887 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_0856e6235d7a3a05ab6942a9e97636de'  Filtering values for attribute 'nickname' which currently contains 1 values
2017-01-20 17:05:09,888 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_0856e6235d7a3a05ab6942a9e97636de'  Filter has permitted the release of 1 values for attribute 'nickname'
2017-01-20 17:05:09,889 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_7fd6857f5f63815c18f40d06874986f8'  Filtering values for attribute 'preferred_username' which currently contains 1 values
2017-01-20 17:05:09,889 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_7fd6857f5f63815c18f40d06874986f8'  Filter has permitted the release of 1 values for attribute 'preferred_username'
2017-01-20 17:05:09,889 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_87e6ef9c92180bd23494475a2157ee5c'  Filtering values for attribute 'profile' which currently contains 1 values
2017-01-20 17:05:09,890 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_87e6ef9c92180bd23494475a2157ee5c'  Filter has permitted the release of 1 values for attribute 'profile'
2017-01-20 17:05:09,890 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_fac3c602827208cbcfacc77d1eb18cae'  Filtering values for attribute 'email' which currently contains 1 values
2017-01-20 17:05:09,891 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_fac3c602827208cbcfacc77d1eb18cae'  Filter has permitted the release of 1 values for attribute 'email'
2017-01-20 17:05:09,892 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_ea2bbf84f97a51c82b5626f5fd6976e6'  Filtering values for attribute 'email_verified' which currently contains 1 values
2017-01-20 17:05:09,892 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_ea2bbf84f97a51c82b5626f5fd6976e6'  Filter has permitted the release of 1 values for attribute 'email_verified'
2017-01-20 17:05:09,893 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_a1a882e16a33661e147324e62f306dd6'  Filtering values for attribute 'birthdate' which currently contains 1 values
2017-01-20 17:05:09,893 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_a1a882e16a33661e147324e62f306dd6'  Filter has permitted the release of 1 values for attribute 'birthdate'
2017-01-20 17:05:09,894 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_b2a57c660df0a0a063136d09e644c8d5'  Filtering values for attribute 'zoneinfo' which currently contains 1 values
2017-01-20 17:05:09,894 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_b2a57c660df0a0a063136d09e644c8d5'  Filter has permitted the release of 1 values for attribute 'zoneinfo'
2017-01-20 17:05:09,895 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_49dd1d0c0807f07f5b218944f702bd21'  Filtering values for attribute 'locale' which currently contains 1 values
2017-01-20 17:05:09,896 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_49dd1d0c0807f07f5b218944f702bd21'  Filter has permitted the release of 1 values for attribute 'locale'
2017-01-20 17:05:09,896 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e4485feb168e66122d86a95db7f20f4b'  Filtering values for attribute 'phone_number' which currently contains 1 values
2017-01-20 17:05:09,897 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e4485feb168e66122d86a95db7f20f4b'  Filter has permitted the release of 1 values for attribute 'phone_number'
2017-01-20 17:05:09,898 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_766ad7d00c5642d653a50e27f4b642ed'  Filtering values for attribute 'address' which currently contains 1 values
2017-01-20 17:05:09,898 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_766ad7d00c5642d653a50e27f4b642ed'  Filter has permitted the release of 1 values for attribute 'address'
2017-01-20 17:05:09,899 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_2b6e92f55f5d0721614966e1c75b2197'  Filtering values for attribute 'updated_at' which currently contains 1 values
2017-01-20 17:05:09,899 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_2b6e92f55f5d0721614966e1c75b2197'  Filter has permitted the release of 1 values for attribute 'updated_at'
2017-01-20 17:05:09,900 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_b7ef4d6dd96f0c8a46e29645cebade6c'  Filtering values for attribute 'picture' which currently contains 1 values
2017-01-20 17:05:09,901 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_b7ef4d6dd96f0c8a46e29645cebade6c'  Filter has permitted the release of 1 values for attribute 'picture'
2017-01-20 17:05:09,901 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_71c3f77ad6d436ac7348a34e1df4868a'  Filtering values for attribute 'website' which currently contains 1 values
2017-01-20 17:05:09,902 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_71c3f77ad6d436ac7348a34e1df4868a'  Filter has permitted the release of 1 values for attribute 'website'
2017-01-20 17:05:09,903 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_183257a4bccc449306c6b5ea198170e4'  Filtering values for attribute 'gender' which currently contains 1 values
2017-01-20 17:05:09,903 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_183257a4bccc449306c6b5ea198170e4'  Filter has permitted the release of 1 values for attribute 'gender'
2017-01-20 17:05:09,904 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_c034a68c46603e640bf6ac7f8b73b32b'  Filtering values for attribute 'phone_number_verified' which currently contains 1 values
2017-01-20 17:05:09,904 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_c034a68c46603e640bf6ac7f8b73b32b'  Filter has permitted the release of 1 values for attribute 'phone_number_verified'
2017-01-20 17:05:09,905 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'website' remained after filtering
2017-01-20 17:05:09,906 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'zoneinfo' remained after filtering
2017-01-20 17:05:09,906 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'address' remained after filtering
2017-01-20 17:05:09,907 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'email_verified' remained after filtering
2017-01-20 17:05:09,907 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'birthdate' remained after filtering
2017-01-20 17:05:09,908 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'gender' remained after filtering
2017-01-20 17:05:09,909 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'profile' remained after filtering
2017-01-20 17:05:09,909 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'phone_number_verified' remained after filtering
2017-01-20 17:05:09,910 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'preferred_username' remained after filtering
2017-01-20 17:05:09,911 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'locale' remained after filtering
2017-01-20 17:05:09,911 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'middle_name' remained after filtering
2017-01-20 17:05:09,912 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'given_name' remained after filtering
2017-01-20 17:05:09,912 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'picture' remained after filtering
2017-01-20 17:05:09,913 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'updated_at' remained after filtering
2017-01-20 17:05:09,913 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'nickname' remained after filtering
2017-01-20 17:05:09,914 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'name' remained after filtering
2017-01-20 17:05:09,914 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'phone_number' remained after filtering
2017-01-20 17:05:09,915 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'family_name' remained after filtering
2017-01-20 17:05:09,916 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'email' remained after filtering
2017-01-20 17:05:10,080 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.PopulateProfileInterceptorContext:126] - Profile Action PopulateProfileInterceptorContext: Installing flow intercept/attribute-release into interceptor context
2017-01-20 17:05:10,081 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.SpringSecurityAuthenticationTokenFactory:78] - Found an authentication context in the profile request context
2017-01-20 17:05:10,082 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.SpringSecurityAuthenticationTokenFactory:82] - Found requested principal context context with matching principal urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
2017-01-20 17:05:10,083 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.SpringSecurityAuthenticationTokenFactory:88] - Adding authority urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
2017-01-20 17:05:10,084 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.SpringSecurityAuthenticationTokenFactory:94] - Adding authority authn/Password
2017-01-20 17:05:10,086 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.SpringSecurityAuthenticationTokenFactory:106] - Created user details object for casuser with authorities [ROLE_USER]
2017-01-20 17:05:10,087 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.SpringSecurityAuthenticationTokenFactory:110] - Final authentication token authorities are [ROLE_USER, AuthenticationClassRefAuthority,urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport, AuthenticationMethodRefAuthority,authn/Password]
2017-01-20 17:05:10,088 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:201] - Stored authentication [net.shibboleth.idp.oidc.client.userinfo.authn.SpringSecurityAuthenticationToken@ed3e04eb: Principal: net.shibboleth.idp.authn.context.SubjectContext@372e3de8; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.core.userdetails.User@211a7920: Username: casuser; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_USER; Granted Authorities: ROLE_USER, AuthenticationClassRefAuthority,urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport, AuthenticationMethodRefAuthority,authn/Password] into Spring security context
2017-01-20 17:05:10,092 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:219] - Built initial response for client org.mitre.oauth2.model.ClientDetailsEntity@730a140b and redirect uri https://mmoayyed.unicon.net:9443/simple-web-app/openid_connect_login
2017-01-20 17:05:10,104 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:224] - System scopes retrieved based on the authorization request scope [address, email, openid, phone, profile] are [SystemScope [id=4, value=address, description=physical address, icon=null, defaultScope=true, restricted=false, structured=false, structuredParamDescription=null, structuredValue=null], SystemScope [id=3, value=email, description=email address, icon=null, defaultScope=true, restricted=false, structured=false, structuredParamDescription=null, structuredValue=null], SystemScope [id=1, value=openid, description=log in using your identity, icon=null, defaultScope=true, restricted=false, structured=false, structuredParamDescription=null, structuredValue=null], SystemScope [id=5, value=phone, description=telephone number, icon=null, defaultScope=true, restricted=false, structured=false, structuredParamDescription=null, structuredValue=null], SystemScope [id=2, value=profile, description=basic profile information, icon=null, defaultScope=true, restricted=false, structured=false, structuredParamDescription=null, structuredValue=null]]
2017-01-20 17:05:10,105 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:229] - Response will contain the following scopes
2017-01-20 17:05:10,107 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:10,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:10,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:10,112 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":null,"preferred_username":"casuser","given_name":null,"family_name":null,"middle_name":null,"nickname":null,"profile":null,"picture":null,"website":null,"gender":null,"zoneinfo":null,"locale":null,"updated_at":null,"birthdate":null,"email":null,"email_verified":null,"phone_number":null,"phone_number_verified":null}
2017-01-20 17:05:10,114 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:263] - Located UserInfo object from principal name casuser
2017-01-20 17:05:10,115 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:268] - UserInfo translated to JSON is:
{"sub":"casuser","name":null,"preferred_username":"casuser","given_name":null,"family_name":null,"middle_name":null,"nickname":null,"profile":null,"picture":null,"website":null,"gender":null,"zoneinfo":null,"locale":null,"updated_at":null,"birthdate":null,"email":null,"email_verified":null,"phone_number":null,"phone_number_verified":null}
2017-01-20 17:05:10,116 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:274] - Processing system scope openid for the following claims: [sub]
2017-01-20 17:05:10,118 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:279] - Added claim sub with value casuser
2017-01-20 17:05:10,118 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:282] - Final claims for system scope openid are
2017-01-20 17:05:10,119 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:274] - Processing system scope profile for the following claims: [website, zoneinfo, birthdate, gender, profile, preferred_username, given_name, middle_name, locale, picture, updated_at, name, nickname, family_name]
2017-01-20 17:05:10,119 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:279] - Added claim preferred_username with value casuser
2017-01-20 17:05:10,120 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:282] - Final claims for system scope profile are
2017-01-20 17:05:10,121 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:274] - Processing system scope email for the following claims: [email, email_verified]
2017-01-20 17:05:10,121 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:282] - Final claims for system scope email are
2017-01-20 17:05:10,122 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:274] - Processing system scope address for the following claims: [address]
2017-01-20 17:05:10,122 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:282] - Final claims for system scope address are
2017-01-20 17:05:10,123 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:274] - Processing system scope phone for the following claims: [phone_number_verified, phone_number]
2017-01-20 17:05:10,124 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:282] - Final claims for system scope phone are
2017-01-20 17:05:10,124 - DEBUG [net.shibboleth.idp.oidc.flow.PreAuthorizeUserApprovalAction:233] - Response will contain the following claims for scopes
2017-01-20 17:05:10,524 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2017-01-20 17:05:10,533 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:101] - Profile Action SelectProfileInterceptorFlow: Checking flow intercept/attribute-release for applicability...
2017-01-20 17:05:10,533 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:84] - Profile Action SelectProfileInterceptorFlow: Selecting flow intercept/attribute-release
2017-01-20 17:05:10,960 - DEBUG [net.shibboleth.idp.consent.storage.impl.ConsentSerializer:105] - symbolics '{email=100, homePhone=101, homePostalAddress=102, mobileNumber=103, pagerNumber=104, commonName=105, surname=106, locality=107, stateProvince=108, street=109, organizationName=110, organizationalUnit=111, title=112, postalAddress=113, postalCode=114, postOfficeBox=115, telephoneNumber=116, givenName=117, initials=118, departmentNumber=200, displayName=201, employeeNumber=202, employeeType=203, jpegPhoto=204, preferredLanguage=205, eduPersonAffiliation=300, eduPersonEntitlement=301, eduPersonNickname=302, eduPersonOrgDN=303, eduPersonOrgUnitDN=304, eduPersonPrimaryAffiliation=305, eduPersonPrimaryOrgUnitDN=306, eduPersonPrincipalName=307, eduPersonScopedAffiliation=308, eduPersonAssurance=309}'
2017-01-20 17:05:11,090 - DEBUG [net.shibboleth.idp.consent.flow.impl.InitializeConsentContext:47] - Profile Action InitializeConsentContext: Created consent context 'ConsentContext{previousConsents={}, chosenConsents={}}'
2017-01-20 17:05:11,099 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.InitializeAttributeReleaseContext:47] - Profile Action InitializeAttributeReleaseContext: Created attribute release context 'AttributeReleaseContext{consentableAttributes={}}'
2017-01-20 17:05:11,121 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.AbstractAttributeReleaseAction:153] - Profile Action PopulateAttributeReleaseContext: Found attributeContext 'net.shibboleth.idp.attribute.context.AttributeContext@29564089'
2017-01-20 17:05:11,123 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.PopulateAttributeReleaseContext:99] - Profile Action PopulateAttributeReleaseContext: Consentable attributes '{address=IdPAttribute{id=address, displayNames={en_US=Address}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=201 Street Name, Gilbert AZ 85258}]}, birthdate=IdPAttribute{id=birthdate, displayNames={en_US=Birth Date}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=1980-07-16}]}, email=IdPAttribute{id=email, displayNames={en_US=Email}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=jsmith@somewhere.org}]}, email_verified=IdPAttribute{id=email_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}, family_name=IdPAttribute{id=family_name, displayNames={en_US=Family Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Hicks}]}, gender=IdPAttribute{id=gender, displayNames={en_US=Gender}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Male}]}, given_name=IdPAttribute{id=given_name, displayNames={en_US=Given Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=James}]}, locale=IdPAttribute{id=locale, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=en_US}]}, middle_name=IdPAttribute{id=middle_name, displayNames={en_US=Middle Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Ken}]}, name=IdPAttribute{id=name, displayNames={en_US=Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Admin}]}, nickname=IdPAttribute{id=nickname, displayNames={en_US=Nickname}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=TheAdmin}]}, phone_number=IdPAttribute{id=phone_number, displayNames={en_US=Phone Number}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=+14255551212}]}, phone_number_verified=IdPAttribute{id=phone_number_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}, picture=IdPAttribute{id=picture, displayNames={en_US=Picture}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile/image.jpg}]}, preferred_username=IdPAttribute{id=preferred_username, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=MrSmith}]}, profile=IdPAttribute{id=profile, displayNames={en_US=Profile}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile}]}, updated_at=IdPAttribute{id=updated_at, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=2800012}]}, website=IdPAttribute{id=website, displayNames={en_US=Website}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com}]}, zoneinfo=IdPAttribute{id=zoneinfo, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=America/Los_Angeles}]}}'
2017-01-20 17:05:11,162 - DEBUG [net.shibboleth.idp.consent.logic.impl.FlowIdLookupFunction:69] - Current flow id is 'intercept/attribute-release'
2017-01-20 17:05:11,163 - DEBUG [net.shibboleth.idp.consent.logic.impl.JoinFunction:81] - Result 'casuser:client'
2017-01-20 17:05:11,164 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:53] - Profile Action ReadConsentFromStorage: Read storage record 'null' with context 'intercept/attribute-release' and key 'casuser:client'
2017-01-20 17:05:11,165 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:57] - Profile Action ReadConsentFromStorage: No storage record for context 'intercept/attribute-release' and key 'casuser:client'
2017-01-20 17:05:11,167 - DEBUG [net.shibboleth.idp.consent.logic.impl.FlowIdLookupFunction:69] - Current flow id is 'intercept/attribute-release'
2017-01-20 17:05:11,168 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:53] - Profile Action ReadConsentFromStorage: Read storage record 'null' with context 'intercept/attribute-release' and key 'casuser'
2017-01-20 17:05:11,169 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.ReadConsentFromStorage:57] - Profile Action ReadConsentFromStorage: No storage record for context 'intercept/attribute-release' and key 'casuser'
2017-01-20 17:05:11,187 - DEBUG [net.shibboleth.idp.consent.flow.impl.PopulateConsentContext:65] - Profile Action PopulateConsentContext: Populating consents: [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:11,188 - DEBUG [net.shibboleth.idp.consent.logic.impl.IsConsentRequiredPredicate:109] - Consent is required, no previous consents
2017-01-20 17:05:11,196 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:11,197 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:11,197 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:11,197 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:11,198 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:11,198 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:11,198 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:11,199 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:11,199 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:11,199 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:11,199 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:11,200 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:11,200 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:11,200 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:11,200 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:11,201 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:11,201 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:11,201 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:11,201 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:11,202 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:11,202 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:11,202 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:11,202 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:11,203 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:11,203 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":null,"preferred_username":"casuser","given_name":null,"family_name":null,"middle_name":null,"nickname":null,"profile":null,"picture":null,"website":null,"gender":null,"zoneinfo":null,"locale":null,"updated_at":null,"birthdate":null,"email":null,"email_verified":null,"phone_number":null,"phone_number_verified":null}
2017-01-20 17:05:13,375 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:13,375 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:13,375 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:13,377 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:13,377 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:13,377 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:13,377 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:13,377 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:13,377 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:13,377 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:13,378 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:13,378 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:13,378 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:13,378 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:13,378 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:13,379 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:13,379 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:13,379 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":null,"preferred_username":"casuser","given_name":null,"family_name":null,"middle_name":null,"nickname":null,"profile":null,"picture":null,"website":null,"gender":null,"zoneinfo":null,"locale":null,"updated_at":null,"birthdate":null,"email":null,"email_verified":null,"phone_number":null,"phone_number_verified":null}
2017-01-20 17:05:13,387 - DEBUG [net.shibboleth.idp.consent.flow.impl.ExtractConsent:81] - Profile Action ExtractConsent: Extracted consent ids '[address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]' from request parameter '_shib_idp_consentIds'
2017-01-20 17:05:13,387 - DEBUG [net.shibboleth.idp.consent.flow.impl.ExtractConsent:93] - Profile Action ExtractConsent: Consent context 'ConsentContext{previousConsents={}, chosenConsents={address=Consent{id=address, value=null, isApproved=true}, birthdate=Consent{id=birthdate, value=null, isApproved=true}, email=Consent{id=email, value=null, isApproved=true}, email_verified=Consent{id=email_verified, value=null, isApproved=true}, family_name=Consent{id=family_name, value=null, isApproved=true}, gender=Consent{id=gender, value=null, isApproved=true}, given_name=Consent{id=given_name, value=null, isApproved=true}, locale=Consent{id=locale, value=null, isApproved=true}, middle_name=Consent{id=middle_name, value=null, isApproved=true}, name=Consent{id=name, value=null, isApproved=true}, nickname=Consent{id=nickname, value=null, isApproved=true}, phone_number=Consent{id=phone_number, value=null, isApproved=true}, phone_number_verified=Consent{id=phone_number_verified, value=null, isApproved=true}, picture=Consent{id=picture, value=null, isApproved=true}, preferred_username=Consent{id=preferred_username, value=null, isApproved=true}, profile=Consent{id=profile, value=null, isApproved=true}, updated_at=Consent{id=updated_at, value=null, isApproved=true}, website=Consent{id=website, value=null, isApproved=true}, zoneinfo=Consent{id=zoneinfo, value=null, isApproved=true}}}'
2017-01-20 17:05:13,407 - INFO [Shibboleth-Consent-Audit.OIDC:241] - 20170120T133513Z|client|AttributeReleaseConsent|casuser|address,birthdate,email,email_verified,family_name,gender,given_name,locale,middle_name,name,nickname,phone_number,phone_number_verified,picture,preferred_username,profile,updated_at,website,zoneinfo||true,true,true,true,true,true,true,true,true,true,true,true,true,true,true,true,true,true,true
2017-01-20 17:05:13,416 - DEBUG [net.shibboleth.idp.consent.logic.impl.FlowIdLookupFunction:69] - Current flow id is 'intercept/attribute-release'
2017-01-20 17:05:13,416 - DEBUG [net.shibboleth.idp.consent.logic.impl.JoinFunction:81] - Result 'casuser:client'
2017-01-20 17:05:13,416 - DEBUG [net.shibboleth.idp.consent.logic.impl.JoinFunction:81] - Result 'casuser:_key_idx'
2017-01-20 17:05:13,417 - DEBUG [net.shibboleth.idp.consent.storage.impl.ConsentSerializer:209] - Serialized '{address=Consent{id=address, value=null, isApproved=true}, birthdate=Consent{id=birthdate, value=null, isApproved=true}, email=Consent{id=email, value=null, isApproved=true}, email_verified=Consent{id=email_verified, value=null, isApproved=true}, family_name=Consent{id=family_name, value=null, isApproved=true}, gender=Consent{id=gender, value=null, isApproved=true}, given_name=Consent{id=given_name, value=null, isApproved=true}, locale=Consent{id=locale, value=null, isApproved=true}, middle_name=Consent{id=middle_name, value=null, isApproved=true}, name=Consent{id=name, value=null, isApproved=true}, nickname=Consent{id=nickname, value=null, isApproved=true}, phone_number=Consent{id=phone_number, value=null, isApproved=true}, phone_number_verified=Consent{id=phone_number_verified, value=null, isApproved=true}, picture=Consent{id=picture, value=null, isApproved=true}, preferred_username=Consent{id=preferred_username, value=null, isApproved=true}, profile=Consent{id=profile, value=null, isApproved=true}, updated_at=Consent{id=updated_at, value=null, isApproved=true}, website=Consent{id=website, value=null, isApproved=true}, zoneinfo=Consent{id=zoneinfo, value=null, isApproved=true}}' as '[{"id":"address"},{"id":"birthdate"},{"id":100},{"id":"email_verified"},{"id":"family_name"},{"id":"gender"},{"id":"given_name"},{"id":"locale"},{"id":"middle_name"},{"id":"name"},{"id":"nickname"},{"id":"phone_number"},{"id":"phone_number_verified"},{"id":"picture"},{"id":"preferred_username"},{"id":"profile"},{"id":"updated_at"},{"id":"website"},{"id":"zoneinfo"}]'
2017-01-20 17:05:13,419 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.CreateResult:79] - Profile Action CreateResult: Created consent result 'ConsentResult{id=null, context=intercept/attribute-release, key=casuser:client, value=[{"id":"address"},{"id":"birthdate"},{"id":100},{"id":"email_verified"},{"id":"family_name"},{"id":"gender"},{"id":"given_name"},{"id":"locale"},{"id":"middle_name"},{"id":"name"},{"id":"nickname"},{"id":"phone_number"},{"id":"phone_number_verified"},{"id":"picture"},{"id":"preferred_username"},{"id":"profile"},{"id":"updated_at"},{"id":"website"},{"id":"zoneinfo"}], expiration=1516455313418}'
2017-01-20 17:05:13,419 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.AbstractConsentIndexedStorageAction:177] - Profile Action CreateResult: Read storage record 'null' with context 'intercept/attribute-release' and key 'casuser:_key_idx'
2017-01-20 17:05:13,419 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.AbstractConsentIndexedStorageAction:279] - Profile Action CreateResult: Will not prune storage records, number of keys '0' is less than max number of records '10'
2017-01-20 17:05:13,419 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.AbstractConsentIndexedStorageAction:198] - Profile Action CreateResult: Read storage record 'null' with context 'intercept/attribute-release' and key 'casuser:_key_idx'
2017-01-20 17:05:13,420 - DEBUG [net.shibboleth.idp.consent.flow.storage.impl.AbstractConsentIndexedStorageAction:202] - Profile Action CreateResult: Creating storage index with key 'casuser:client'
2017-01-20 17:05:13,420 - DEBUG [net.shibboleth.idp.consent.storage.impl.CollectionSerializer:90] - Serialized '[casuser:client]' as '["casuser:client"]'
2017-01-20 17:05:13,427 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.AbstractAttributeReleaseAction:153] - Profile Action ReleaseAttributes: Found attributeContext 'net.shibboleth.idp.attribute.context.AttributeContext@29564089'
2017-01-20 17:05:13,427 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:64] - Profile Action ReleaseAttributes: Consents '{address=Consent{id=address, value=null, isApproved=true}, birthdate=Consent{id=birthdate, value=null, isApproved=true}, email=Consent{id=email, value=null, isApproved=true}, email_verified=Consent{id=email_verified, value=null, isApproved=true}, family_name=Consent{id=family_name, value=null, isApproved=true}, gender=Consent{id=gender, value=null, isApproved=true}, given_name=Consent{id=given_name, value=null, isApproved=true}, locale=Consent{id=locale, value=null, isApproved=true}, middle_name=Consent{id=middle_name, value=null, isApproved=true}, name=Consent{id=name, value=null, isApproved=true}, nickname=Consent{id=nickname, value=null, isApproved=true}, phone_number=Consent{id=phone_number, value=null, isApproved=true}, phone_number_verified=Consent{id=phone_number_verified, value=null, isApproved=true}, picture=Consent{id=picture, value=null, isApproved=true}, preferred_username=Consent{id=preferred_username, value=null, isApproved=true}, profile=Consent{id=profile, value=null, isApproved=true}, updated_at=Consent{id=updated_at, value=null, isApproved=true}, website=Consent{id=website, value=null, isApproved=true}, zoneinfo=Consent{id=zoneinfo, value=null, isApproved=true}}'
2017-01-20 17:05:13,427 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:67] - Profile Action ReleaseAttributes: Attributes before release '{website=IdPAttribute{id=website, displayNames={en_US=Website}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com}]}, zoneinfo=IdPAttribute{id=zoneinfo, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=America/Los_Angeles}]}, address=IdPAttribute{id=address, displayNames={en_US=Address}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=201 Street Name, Gilbert AZ 85258}]}, email_verified=IdPAttribute{id=email_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}, birthdate=IdPAttribute{id=birthdate, displayNames={en_US=Birth Date}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=1980-07-16}]}, gender=IdPAttribute{id=gender, displayNames={en_US=Gender}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Male}]}, profile=IdPAttribute{id=profile, displayNames={en_US=Profile}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile}]}, phone_number_verified=IdPAttribute{id=phone_number_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}, preferred_username=IdPAttribute{id=preferred_username, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=MrSmith}]}, locale=IdPAttribute{id=locale, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=en_US}]}, middle_name=IdPAttribute{id=middle_name, displayNames={en_US=Middle Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Ken}]}, given_name=IdPAttribute{id=given_name, displayNames={en_US=Given Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=James}]}, picture=IdPAttribute{id=picture, displayNames={en_US=Picture}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile/image.jpg}]}, updated_at=IdPAttribute{id=updated_at, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=2800012}]}, nickname=IdPAttribute{id=nickname, displayNames={en_US=Nickname}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=TheAdmin}]}, name=IdPAttribute{id=name, displayNames={en_US=Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Admin}]}, phone_number=IdPAttribute{id=phone_number, displayNames={en_US=Phone Number}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=+14255551212}]}, family_name=IdPAttribute{id=family_name, displayNames={en_US=Family Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Hicks}]}, email=IdPAttribute{id=email, displayNames={en_US=Email}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=jsmith@somewhere.org}]}}'
2017-01-20 17:05:13,428 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=website, displayNames={en_US=Website}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com}]}' will be released because consent is approved
2017-01-20 17:05:13,428 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=zoneinfo, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=America/Los_Angeles}]}' will be released because consent is approved
2017-01-20 17:05:13,429 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=address, displayNames={en_US=Address}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=201 Street Name, Gilbert AZ 85258}]}' will be released because consent is approved
2017-01-20 17:05:13,429 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=email_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}' will be released because consent is approved
2017-01-20 17:05:13,429 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=birthdate, displayNames={en_US=Birth Date}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=1980-07-16}]}' will be released because consent is approved
2017-01-20 17:05:13,430 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=gender, displayNames={en_US=Gender}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Male}]}' will be released because consent is approved
2017-01-20 17:05:13,430 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=profile, displayNames={en_US=Profile}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile}]}' will be released because consent is approved
2017-01-20 17:05:13,430 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=phone_number_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}' will be released because consent is approved
2017-01-20 17:05:13,431 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=preferred_username, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=MrSmith}]}' will be released because consent is approved
2017-01-20 17:05:13,431 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=locale, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=en_US}]}' will be released because consent is approved
2017-01-20 17:05:13,431 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=middle_name, displayNames={en_US=Middle Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Ken}]}' will be released because consent is approved
2017-01-20 17:05:13,431 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=given_name, displayNames={en_US=Given Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=James}]}' will be released because consent is approved
2017-01-20 17:05:13,431 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=picture, displayNames={en_US=Picture}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile/image.jpg}]}' will be released because consent is approved
2017-01-20 17:05:13,432 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=updated_at, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=2800012}]}' will be released because consent is approved
2017-01-20 17:05:13,432 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=nickname, displayNames={en_US=Nickname}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=TheAdmin}]}' will be released because consent is approved
2017-01-20 17:05:13,432 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=name, displayNames={en_US=Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Admin}]}' will be released because consent is approved
2017-01-20 17:05:13,432 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=phone_number, displayNames={en_US=Phone Number}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=+14255551212}]}' will be released because consent is approved
2017-01-20 17:05:13,433 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=family_name, displayNames={en_US=Family Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Hicks}]}' will be released because consent is approved
2017-01-20 17:05:13,433 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:85] - Profile Action ReleaseAttributes: Attribute 'IdPAttribute{id=email, displayNames={en_US=Email}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=jsmith@somewhere.org}]}' will be released because consent is approved
2017-01-20 17:05:13,433 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:94] - Profile Action ReleaseAttributes: Releasing attributes '{website=IdPAttribute{id=website, displayNames={en_US=Website}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com}]}, zoneinfo=IdPAttribute{id=zoneinfo, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=America/Los_Angeles}]}, address=IdPAttribute{id=address, displayNames={en_US=Address}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=201 Street Name, Gilbert AZ 85258}]}, email_verified=IdPAttribute{id=email_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}, birthdate=IdPAttribute{id=birthdate, displayNames={en_US=Birth Date}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=1980-07-16}]}, gender=IdPAttribute{id=gender, displayNames={en_US=Gender}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Male}]}, profile=IdPAttribute{id=profile, displayNames={en_US=Profile}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile}]}, phone_number_verified=IdPAttribute{id=phone_number_verified, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=true}]}, preferred_username=IdPAttribute{id=preferred_username, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=MrSmith}]}, locale=IdPAttribute{id=locale, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=en_US}]}, middle_name=IdPAttribute{id=middle_name, displayNames={en_US=Middle Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Ken}]}, given_name=IdPAttribute{id=given_name, displayNames={en_US=Given Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=James}]}, picture=IdPAttribute{id=picture, displayNames={en_US=Picture}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=https://example.com/profile/image.jpg}]}, updated_at=IdPAttribute{id=updated_at, displayNames={}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=2800012}]}, nickname=IdPAttribute{id=nickname, displayNames={en_US=Nickname}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=TheAdmin}]}, name=IdPAttribute{id=name, displayNames={en_US=Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Admin}]}, phone_number=IdPAttribute{id=phone_number, displayNames={en_US=Phone Number}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=+14255551212}]}, family_name=IdPAttribute{id=family_name, displayNames={en_US=Family Name}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=Hicks}]}, email=IdPAttribute{id=email, displayNames={en_US=Email}, displayDescriptions={}, encoders=[], values=[StringAttributeValue{value=jsmith@somewhere.org}]}}'
2017-01-20 17:05:13,434 - DEBUG [net.shibboleth.idp.consent.flow.ar.impl.ReleaseAttributes:96] - Profile Action ReleaseAttributes: Not releasing attributes '{}'
2017-01-20 17:05:13,442 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.WriteProfileInterceptorResultToStorage:68] - Profile Action WriteProfileInterceptorResultToStorage: No results available from interceptor context, nothing to store
2017-01-20 17:05:13,442 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:52] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do
2017-01-20 17:05:13,443 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:65] - Profile Action SelectProfileInterceptorFlow: Moving completed flow intercept/attribute-release to completed set, selecting next one
2017-01-20 17:05:13,443 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:80] - Profile Action SelectProfileInterceptorFlow: No flows available to choose from
2017-01-20 17:05:13,542 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:13,543 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:13,543 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:13,543 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,544 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:13,544 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:13,544 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute address is authorized for release. Mapping...
2017-01-20 17:05:13,544 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:13,545 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute birthdate is authorized for release. Mapping...
2017-01-20 17:05:13,545 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:13,545 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email is authorized for release. Mapping...
2017-01-20 17:05:13,545 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:13,546 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email_verified is authorized for release. Mapping...
2017-01-20 17:05:13,546 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:13,546 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute family_name is authorized for release. Mapping...
2017-01-20 17:05:13,546 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:13,547 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute gender is authorized for release. Mapping...
2017-01-20 17:05:13,547 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:13,547 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute given_name is authorized for release. Mapping...
2017-01-20 17:05:13,547 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:13,547 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute locale is authorized for release. Mapping...
2017-01-20 17:05:13,548 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:13,548 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute middle_name is authorized for release. Mapping...
2017-01-20 17:05:13,548 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:13,548 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute name is authorized for release. Mapping...
2017-01-20 17:05:13,548 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:13,548 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute nickname is authorized for release. Mapping...
2017-01-20 17:05:13,549 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:13,549 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number is authorized for release. Mapping...
2017-01-20 17:05:13,549 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:13,549 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number_verified is authorized for release. Mapping...
2017-01-20 17:05:13,549 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:13,550 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute picture is authorized for release. Mapping...
2017-01-20 17:05:13,550 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:13,550 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute preferred_username is authorized for release. Mapping...
2017-01-20 17:05:13,550 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:13,550 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute profile is authorized for release. Mapping...
2017-01-20 17:05:13,550 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:13,551 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute updated_at is authorized for release. Mapping...
2017-01-20 17:05:13,551 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:13,551 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute website is authorized for release. Mapping...
2017-01-20 17:05:13,551 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:13,551 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute zoneinfo is authorized for release. Mapping...
2017-01-20 17:05:13,552 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":"Admin","preferred_username":"MrSmith","given_name":"James","family_name":"Hicks","middle_name":"Ken","nickname":"TheAdmin","profile":"https://example.com/profile","picture":"https://example.com/profile/image.jpg","website":"https://example.com","gender":"Male","zoneinfo":"America/Los_Angeles","locale":"en_US","updated_at":"2800012","birthdate":"1980-07-16","email":"jsmith@somewhere.org","email_verified":true,"phone_number":"+14255551212","phone_number_verified":true,"address":{"formatted":"201 Street Name, Gilbert AZ 85258","street_address":null,"locality":null,"region":null,"postal_code":null,"country":null}}
2017-01-20 17:05:13,638 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:13,638 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:13,639 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:13,639 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,639 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:13,640 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:13,640 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute address is authorized for release. Mapping...
2017-01-20 17:05:13,640 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:13,640 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute birthdate is authorized for release. Mapping...
2017-01-20 17:05:13,641 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:13,641 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email is authorized for release. Mapping...
2017-01-20 17:05:13,641 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:13,641 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email_verified is authorized for release. Mapping...
2017-01-20 17:05:13,642 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:13,642 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute family_name is authorized for release. Mapping...
2017-01-20 17:05:13,642 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:13,642 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute gender is authorized for release. Mapping...
2017-01-20 17:05:13,643 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:13,643 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute given_name is authorized for release. Mapping...
2017-01-20 17:05:13,643 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:13,643 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute locale is authorized for release. Mapping...
2017-01-20 17:05:13,644 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:13,644 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute middle_name is authorized for release. Mapping...
2017-01-20 17:05:13,644 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:13,644 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute name is authorized for release. Mapping...
2017-01-20 17:05:13,645 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:13,645 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute nickname is authorized for release. Mapping...
2017-01-20 17:05:13,645 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:13,646 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number is authorized for release. Mapping...
2017-01-20 17:05:13,646 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:13,646 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number_verified is authorized for release. Mapping...
2017-01-20 17:05:13,646 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:13,647 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute picture is authorized for release. Mapping...
2017-01-20 17:05:13,647 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:13,647 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute preferred_username is authorized for release. Mapping...
2017-01-20 17:05:13,647 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:13,648 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute profile is authorized for release. Mapping...
2017-01-20 17:05:13,648 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:13,648 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute updated_at is authorized for release. Mapping...
2017-01-20 17:05:13,648 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:13,649 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute website is authorized for release. Mapping...
2017-01-20 17:05:13,649 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:13,649 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute zoneinfo is authorized for release. Mapping...
2017-01-20 17:05:13,650 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":"Admin","preferred_username":"MrSmith","given_name":"James","family_name":"Hicks","middle_name":"Ken","nickname":"TheAdmin","profile":"https://example.com/profile","picture":"https://example.com/profile/image.jpg","website":"https://example.com","gender":"Male","zoneinfo":"America/Los_Angeles","locale":"en_US","updated_at":"2800012","birthdate":"1980-07-16","email":"jsmith@somewhere.org","email_verified":true,"phone_number":"+14255551212","phone_number_verified":true,"address":{"formatted":"201 Street Name, Gilbert AZ 85258","street_address":null,"locality":null,"region":null,"postal_code":null,"country":null}}
2017-01-20 17:05:13,808 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:13,809 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:13,809 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:13,809 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,809 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:13,809 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:13,809 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute address is authorized for release. Mapping...
2017-01-20 17:05:13,810 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:13,810 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute birthdate is authorized for release. Mapping...
2017-01-20 17:05:13,810 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:13,810 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email is authorized for release. Mapping...
2017-01-20 17:05:13,810 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:13,811 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email_verified is authorized for release. Mapping...
2017-01-20 17:05:13,811 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:13,811 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute family_name is authorized for release. Mapping...
2017-01-20 17:05:13,811 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:13,812 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute gender is authorized for release. Mapping...
2017-01-20 17:05:13,812 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:13,812 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute given_name is authorized for release. Mapping...
2017-01-20 17:05:13,812 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:13,812 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute locale is authorized for release. Mapping...
2017-01-20 17:05:13,813 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:13,813 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute middle_name is authorized for release. Mapping...
2017-01-20 17:05:13,813 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:13,813 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute name is authorized for release. Mapping...
2017-01-20 17:05:13,814 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:13,814 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute nickname is authorized for release. Mapping...
2017-01-20 17:05:13,814 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:13,815 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number is authorized for release. Mapping...
2017-01-20 17:05:13,815 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:13,815 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number_verified is authorized for release. Mapping...
2017-01-20 17:05:13,815 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:13,816 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute picture is authorized for release. Mapping...
2017-01-20 17:05:13,816 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:13,816 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute preferred_username is authorized for release. Mapping...
2017-01-20 17:05:13,816 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:13,817 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute profile is authorized for release. Mapping...
2017-01-20 17:05:13,817 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:13,817 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute updated_at is authorized for release. Mapping...
2017-01-20 17:05:13,817 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:13,818 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute website is authorized for release. Mapping...
2017-01-20 17:05:13,818 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:13,818 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute zoneinfo is authorized for release. Mapping...
2017-01-20 17:05:13,819 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":"Admin","preferred_username":"MrSmith","given_name":"James","family_name":"Hicks","middle_name":"Ken","nickname":"TheAdmin","profile":"https://example.com/profile","picture":"https://example.com/profile/image.jpg","website":"https://example.com","gender":"Male","zoneinfo":"America/Los_Angeles","locale":"en_US","updated_at":"2800012","birthdate":"1980-07-16","email":"jsmith@somewhere.org","email_verified":true,"phone_number":"+14255551212","phone_number_verified":true,"address":{"formatted":"201 Street Name, Gilbert AZ 85258","street_address":null,"locality":null,"region":null,"postal_code":null,"country":null}}
2017-01-20 17:05:13,919 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoService:80] - Locating client client for username casuser
2017-01-20 17:05:13,920 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:13,920 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:13,921 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:13,921 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,921 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:13,921 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:13,922 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute address is authorized for release. Mapping...
2017-01-20 17:05:13,922 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:13,922 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute birthdate is authorized for release. Mapping...
2017-01-20 17:05:13,923 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:13,923 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email is authorized for release. Mapping...
2017-01-20 17:05:13,923 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:13,923 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email_verified is authorized for release. Mapping...
2017-01-20 17:05:13,924 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:13,924 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute family_name is authorized for release. Mapping...
2017-01-20 17:05:13,924 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:13,924 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute gender is authorized for release. Mapping...
2017-01-20 17:05:13,925 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:13,925 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute given_name is authorized for release. Mapping...
2017-01-20 17:05:13,925 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:13,925 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute locale is authorized for release. Mapping...
2017-01-20 17:05:13,926 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:13,926 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute middle_name is authorized for release. Mapping...
2017-01-20 17:05:13,926 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:13,926 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute name is authorized for release. Mapping...
2017-01-20 17:05:13,927 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:13,927 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute nickname is authorized for release. Mapping...
2017-01-20 17:05:13,927 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:13,927 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number is authorized for release. Mapping...
2017-01-20 17:05:13,927 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:13,927 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number_verified is authorized for release. Mapping...
2017-01-20 17:05:13,928 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:13,928 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute picture is authorized for release. Mapping...
2017-01-20 17:05:13,928 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:13,928 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute preferred_username is authorized for release. Mapping...
2017-01-20 17:05:13,928 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:13,929 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute profile is authorized for release. Mapping...
2017-01-20 17:05:13,929 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:13,929 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute updated_at is authorized for release. Mapping...
2017-01-20 17:05:13,930 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:13,930 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute website is authorized for release. Mapping...
2017-01-20 17:05:13,930 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:13,930 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute zoneinfo is authorized for release. Mapping...
2017-01-20 17:05:13,931 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":"Admin","preferred_username":"MrSmith","given_name":"James","family_name":"Hicks","middle_name":"Ken","nickname":"TheAdmin","profile":"https://example.com/profile","picture":"https://example.com/profile/image.jpg","website":"https://example.com","gender":"Male","zoneinfo":"America/Los_Angeles","locale":"en_US","updated_at":"2800012","birthdate":"1980-07-16","email":"jsmith@somewhere.org","email_verified":true,"phone_number":"+14255551212","phone_number_verified":true,"address":{"formatted":"201 Street Name, Gilbert AZ 85258","street_address":null,"locality":null,"region":null,"postal_code":null,"country":null}}
2017-01-20 17:05:13,932 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:126] - Request max_age extension null
2017-01-20 17:05:13,932 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:128] - Request idtoken extension null
2017-01-20 17:05:13,932 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:130] - Client require authN time null
2017-01-20 17:05:13,933 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:314] - Request contains max_age extension. auth_time set to 1484919309
2017-01-20 17:05:13,933 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:380] - Evaluating authority AuthenticationClassRefAuthority,urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport of the authentication
2017-01-20 17:05:13,933 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:385] - Added acr claim as
2017-01-20 17:05:13,934 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:380] - Evaluating authority ROLE_USER of the authentication
2017-01-20 17:05:13,934 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:380] - Evaluating authority AuthenticationMethodRefAuthority,authn/Password of the authentication
2017-01-20 17:05:13,934 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:391] - Added amr claim as
2017-01-20 17:05:13,934 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:334] - Claim expiration is set to Fri Jan 20 17:15:13 IRST 2017
2017-01-20 17:05:13,935 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:140] - issuer is set to https://mmoayyed.unicon.net:8443/idp/
2017-01-20 17:05:13,935 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:143] - sub is set to casuser
2017-01-20 17:05:13,935 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:146] - audience is set to client
2017-01-20 17:05:13,936 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:150] - JWT id is set to cd5300b7-3181-47f9-840a-1291cbc8428e
2017-01-20 17:05:13,936 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:301] - nonce is set to 76192c002225
2017-01-20 17:05:13,936 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:196] - Client client is configured to ignore encryption
2017-01-20 17:05:13,936 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:351] - Client client required a signed idToken with signing alg of RS256 and kid rsa1
2017-01-20 17:05:13,937 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:361] - Using the default signer service to sign the idToken. Default signing alg is RS256
2017-01-20 17:05:13,962 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:170] - Mapping the idToken to the authentication of client client
2017-01-20 17:05:13,962 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.authn.ShibbolethAcrAwareTokenService:177] - Configured scopes for the idToken scope id-token are [id-token]
2017-01-20 17:05:14,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:14,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:14,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:14,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:14,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:14,109 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:14,109 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute address is authorized for release. Mapping...
2017-01-20 17:05:14,109 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:14,109 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute birthdate is authorized for release. Mapping...
2017-01-20 17:05:14,109 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:14,109 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email is authorized for release. Mapping...
2017-01-20 17:05:14,109 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:14,110 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email_verified is authorized for release. Mapping...
2017-01-20 17:05:14,110 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:14,110 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute family_name is authorized for release. Mapping...
2017-01-20 17:05:14,110 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:14,110 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute gender is authorized for release. Mapping...
2017-01-20 17:05:14,110 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:14,110 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute given_name is authorized for release. Mapping...
2017-01-20 17:05:14,111 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:14,111 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute locale is authorized for release. Mapping...
2017-01-20 17:05:14,111 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:14,111 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute middle_name is authorized for release. Mapping...
2017-01-20 17:05:14,111 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:14,112 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute name is authorized for release. Mapping...
2017-01-20 17:05:14,112 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:14,112 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute nickname is authorized for release. Mapping...
2017-01-20 17:05:14,112 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:14,113 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number is authorized for release. Mapping...
2017-01-20 17:05:14,113 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:14,113 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number_verified is authorized for release. Mapping...
2017-01-20 17:05:14,113 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:14,113 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute picture is authorized for release. Mapping...
2017-01-20 17:05:14,114 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:14,114 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute preferred_username is authorized for release. Mapping...
2017-01-20 17:05:14,114 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:14,114 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute profile is authorized for release. Mapping...
2017-01-20 17:05:14,114 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:14,114 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute updated_at is authorized for release. Mapping...
2017-01-20 17:05:14,114 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:14,115 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute website is authorized for release. Mapping...
2017-01-20 17:05:14,115 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:14,115 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute zoneinfo is authorized for release. Mapping...
2017-01-20 17:05:14,115 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":"Admin","preferred_username":"MrSmith","given_name":"James","family_name":"Hicks","middle_name":"Ken","nickname":"TheAdmin","profile":"https://example.com/profile","picture":"https://example.com/profile/image.jpg","website":"https://example.com","gender":"Male","zoneinfo":"America/Los_Angeles","locale":"en_US","updated_at":"2800012","birthdate":"1980-07-16","email":"jsmith@somewhere.org","email_verified":true,"phone_number":"+14255551212","phone_number_verified":true,"address":{"formatted":"201 Street Name, Gilbert AZ 85258","street_address":null,"locality":null,"region":null,"postal_code":null,"country":null}}
2017-01-20 17:05:14,133 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoService:80] - Locating client client for username casuser
2017-01-20 17:05:14,133 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:100] - Set userinfo preferred username to casuser
2017-01-20 17:05:14,134 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:103] - Set userinfo sub claim to casuser
2017-01-20 17:05:14,134 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:106] - Setting preferred username to casuser
2017-01-20 17:05:14,134 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:14,134 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:112] - Consentable attributes are [address, birthdate, email, email_verified, family_name, gender, given_name, locale, middle_name, name, nickname, phone_number, phone_number_verified, picture, preferred_username, profile, updated_at, website, zoneinfo]
2017-01-20 17:05:14,135 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute address
2017-01-20 17:05:14,135 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute address is authorized for release. Mapping...
2017-01-20 17:05:14,135 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute birthdate
2017-01-20 17:05:14,136 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute birthdate is authorized for release. Mapping...
2017-01-20 17:05:14,136 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email
2017-01-20 17:05:14,136 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email is authorized for release. Mapping...
2017-01-20 17:05:14,136 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute email_verified
2017-01-20 17:05:14,136 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute email_verified is authorized for release. Mapping...
2017-01-20 17:05:14,137 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute family_name
2017-01-20 17:05:14,137 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute family_name is authorized for release. Mapping...
2017-01-20 17:05:14,137 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute gender
2017-01-20 17:05:14,137 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute gender is authorized for release. Mapping...
2017-01-20 17:05:14,137 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute given_name
2017-01-20 17:05:14,138 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute given_name is authorized for release. Mapping...
2017-01-20 17:05:14,138 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute locale
2017-01-20 17:05:14,138 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute locale is authorized for release. Mapping...
2017-01-20 17:05:14,138 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute middle_name
2017-01-20 17:05:14,138 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute middle_name is authorized for release. Mapping...
2017-01-20 17:05:14,139 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute name
2017-01-20 17:05:14,139 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute name is authorized for release. Mapping...
2017-01-20 17:05:14,139 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute nickname
2017-01-20 17:05:14,139 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute nickname is authorized for release. Mapping...
2017-01-20 17:05:14,140 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number
2017-01-20 17:05:14,140 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number is authorized for release. Mapping...
2017-01-20 17:05:14,140 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute phone_number_verified
2017-01-20 17:05:14,140 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute phone_number_verified is authorized for release. Mapping...
2017-01-20 17:05:14,141 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute picture
2017-01-20 17:05:14,141 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute picture is authorized for release. Mapping...
2017-01-20 17:05:14,141 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute preferred_username
2017-01-20 17:05:14,142 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute preferred_username is authorized for release. Mapping...
2017-01-20 17:05:14,142 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute profile
2017-01-20 17:05:14,142 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute profile is authorized for release. Mapping...
2017-01-20 17:05:14,142 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute updated_at
2017-01-20 17:05:14,143 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute updated_at is authorized for release. Mapping...
2017-01-20 17:05:14,143 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute website
2017-01-20 17:05:14,143 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute website is authorized for release. Mapping...
2017-01-20 17:05:14,144 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:116] - Processing userinfo claim for attribute zoneinfo
2017-01-20 17:05:14,144 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:120] - Attribute zoneinfo is authorized for release. Mapping...
2017-01-20 17:05:14,144 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:130] - Final userinfo object constructed from attributes is
 {"sub":"casuser","name":"Admin","preferred_username":"MrSmith","given_name":"James","family_name":"Hicks","middle_name":"Ken","nickname":"TheAdmin","profile":"https://example.com/profile","picture":"https://example.com/profile/image.jpg","website":"https://example.com","gender":"Male","zoneinfo":"America/Los_Angeles","locale":"en_US","updated_at":"2800012","birthdate":"1980-07-16","email":"jsmith@somewhere.org","email_verified":true,"phone_number":"+14255551212","phone_number_verified":true,"address":{"formatted":"201 Street Name, Gilbert AZ 85258","street_address":null,"locality":null,"region":null,"postal_code":null,"country":null}}

[dominique-p]

Thanks for the logs. One difference is the selection of the attribute-release flow. The reference does select it:

2017-01-20 17:05:10,533 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:84] - Profile Action SelectProfileInterceptorFlow: Selecting flow intercept/attribute-release

but not on my installation:

2017-01-20 20:35:50,617 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:106] - jsessionID:8E8359620BADFA94050D7988415455A9 - Profile Action SelectProfileInterceptorFlow: Flow intercept/attribute-release was not applicable to this request

This explains why the attributes release page was not displayed. I'll try to fix that, although I don't quite see why it would affect transmitting the claims (i.e. if the attributes release page is not displayed then it should be OK to release them as OIDC claims).

[mmoayyed]

Yes it most certainly should be OK to release them without consent, and if you find that it's not, that would be a bug.

[dominique-p]

It seems that the construction of the claims list depends on the existence of a AttributeReleaseContext. At least that is what a local reading of the code suggests (no else clause to the if (getAttributeReleaseContext() != null) in ShibbolethUserInfoRepository.java): https://github.com/uchicago/shibboleth-oidc/blob/9a63faeca4367dc38031a7f0baec1aee1414100c/idp-oidc-impl/src/main/java/net/shibboleth/idp/oidc/client/userinfo/ShibbolethUserInfoRepository.java#L108

Is this a bug? Or is there another part of the shibboleth-oidc code that should construct the list of claims when the attribute release consent flow is not configured?

A side issue: A curious thing about this part of the code of ShibbolethUserInfoRepository is that it is called 8 times in the session for which you provided a log extract (cf. below).

• Is this normal? (I would think that once the claims are established there no need to extract them from the attribute release context again).

grep 'Found attribute release context. Locating consentable attributes...' /var/tmp/logok.txt 
2017-01-20 17:05:11,197 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,376 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,543 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,639 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,809 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:13,921 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:14,108 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...
2017-01-20 17:05:14,134 - DEBUG [net.shibboleth.idp.oidc.client.userinfo.ShibbolethUserInfoRepository:109] - Found attribute release context. Locating consentable attributes...

[dominique-p]

Found it! The attribute-release flow was not selected because in our lab installation the property idp.consent.allowPerAttribute had the value true. It is used in an activationCondition for shibboleth.consent.AttributeReleaseFlow in profile-intercept-system.xml (cf. http://svn.shibboleth.net/view/java-identity-provider/tags/3.1.2/idp-conf/src/main/resources/system/conf/profile-intercept-system.xml?view=markup#l46 ) After setting idp.consent.allowPerAttribute to the default false the simple-web-app/user page now shows all the claims that are available!

I was blinded because when using Shibboleth/SAML to authentify for a SP then the attribute-release flow was selected anyway. It means then that the other part of the OR in the activateCondition (net.shibboleth.idp.saml.profile.config.logic.IncludeAttributeStatementPredicate) behaves differently for oidc (evaluates to false):

• Is this a bug? (i.e. what is different in shibboleth-oidc from the Shibboleth/SAML case in the evaluation of IncludeAttributeStatementPredicate when idp.consent.allowPerAttribute is true?)

• Can you reproduce that? (i.e. set idp.consent.allowPerAttribute to true and observe that the attribute release flow is not selected and the claim list is not constructed , as well as, in the Shibboleth/SAML case, the attribute release flow is still selected).

If you can reproduce it it would look more and more like a bug that shibboleth-oidc does not construct the claims list when the attribute-release flow is not selected (cf. previous comment).

[dominique-p]

This explanation about the activateCondition of the attribute release flow might shed some light on this issue: puzzled about the activationCondition of the AttributeReleaseFlow http://shibboleth.1660669.n2.nabble.com/puzzled-about-the-activationCondition-of-the-AttributeReleaseFlow-td7631029.html

There is also a warning note on the ConsentConfiguration page of the Shibboleth documentation that gives some context: https://wiki.shibboleth.net/confluence/display/IDP30/ConsentConfiguration#ConsentConfiguration-AttributeReleaseConsent

Scott Cantor is clear: in case the attribute release flow is not applicable then the attributes that passed the filter policy should be transmitted to the client.

• Is it an option to add a includeAttributeStatement to the OIDC login profile?
• Would it be useful? I.e. I am not sure about the implications of the last comment: The problem of consent for back channel exchanges of data, be it SAML, OAuth, or anything else, is a different sort of problem that needs different solutions than anything we have built to date. Because /idp/profile/oidc/userinfo allows access to attributes without the need of a browser, i.e. is a back channel, unless shibboleth-oidc contains code that saves the per attribute user decision, then it cannot work.

In absence of a more global solution in shibboleth-oidc, one would have to configure idp.consent.allowPerAttribute=false for each OIDC client. May be it is possible with the method described in Attribute Consent http://shibboleth.1660669.n2.nabble.com/Attribute-Consent-td7630998.html and RelyingParty configuration overrides https://wiki.shibboleth.net/confluence/display/IDP30/RelyingPartyConfiguration#RelyingPartyConfiguration-Overrides

• Is there a way to identify any OIDC client with one overriding predicate? (i.e. to have just one override statement for all.) May be by setting something in the oidcClients descriptions in conf/oidc-protocol.xml?

[mmoayyed]

Closing in favor of #44