In the beginning of February (2014) i wrote a blog post about the faet that Smart card authentication does not work with vCloud Automation Center 6.0, you can find the blog post here. This blog post will be about another login problem i saw at a customer, running vCloud Automation Center 6. SP1 (6.0.1) a few days back.

One of the employees at the customer showed me something quite strange. He filled in the User name and Password and hit the Login button:

The login screen/web page just flicker and come back without either User name and/or password filled in.

The funny (or not that funny) thing is that the user can log on to the vSphere 5.5 environment without any problem. My customer uses the vCAC Single Sign On (SSO) Appliance and not the the Windows based vSphere SSO so there is definitely a difference between the SSO versions in vCAC and vSphere.

I checked the catalina.out log file located in the directory:

• /storage/log/vmware/vcac/ on the vCAC Appliance
• /storage/log/vmware/sso/ on the vCAC SSO Appliance.

Didn’t find anything obvious explaining this strange behavior in the log files. See the log files in the end of the blog post. Since other users could login we focused on the directory service used for user authentication, Microsoft Active Directory (AD) 2008 R2.

I didn’t found any problem with the AD user account so the next thing i did was comparing the AD group belonging compared to another user without the same problem. It turned out that the user with the problem belongs to 20+ AD groups compared with the other user not having the same problem.

Without knowing what to look for i started to scan through the AD groups and i found one group, probably created a long time ago and upgraded from an earlier AD version, that looked kind of strage.
There were three groups added to the group and the one that draw my attention was the Authenticated Users group since it didn’t have any Permissions at all.

I added the Read permission for the Authenticated Users group in the group and then the user could log on.

I realize that this is something that will probably not be seen many times but i thought it was worth sharing anyway.

Below you’ll find the catalina.out log files from both the vCAC Appliance and the vCAC SSO Appliance.

————————————————————————————————-

Log Files

vCAC Appliance Log file
tail -f /var/log/vcac/catalina.out

2014-0X-XX 10:20:02,475 [tomcat-http–42] [extensibility] INFO com.vmware.vcac.core.extensibility.controller.PluginServiceController.getExtensions:140 – Looking up extensions for extension point [[csp.catalog.resource.operations]]
2014-0X-XX 10:20:03,474 [tomcat-http–4] [extensibility] INFO com.vmware.vcac.core.extensibility.controller.PluginServiceController.getExtensions:140 – Looking up extensions for extension point [[csp.catalog.resource.operations]]
2014-0X-XX 10:20:03,505 [taskScheduler-1] [catalog] INFO com.vmware.vcac.catalog.service.impl.EntitlementServiceImpl.expireEntitlements:323 – Scheduled Entitlement Expiry service starts at Wed Feb 19 10:20:03 CET 2014.
2014-0X-XX 10:20:44,601 [tomcat-http–43] [shell-ui] INFO com.vmware.identity.websso.client.endpoint.SsoRequestSender.getRequestUrl:158 – Producing redirect url
2014-0X-XX 10:20:44,604 [tomcat-http–43] [shell-ui] INFO com.vmware.identity.websso.client.endpoint.SsoRequestSender.createRenewable:282 – Added Renewable condition
2014-0X-XX 10:20:44,604 [tomcat-http–43] [shell-ui] INFO com.vmware.identity.websso.client.endpoint.SsoRequestSender.createDelegable:290 – Added Delegable condition
2014-0X-XX 10:20:44,605 [tomcat-http–43] [shell-ui] INFO com.vmware.identity.websso.client.endpoint.SsoRequestSender.getRequestUrl:245 – Destination URL: https://vcacsso1.vcdx56.com:7444/websso/SAML2/SSO/VCDX56
2014-0X-XX 10:20:44,608 [tomcat-http–43] [shell-ui] INFO com.vmware.identity.websso.client.endpoint.SsoRequestSender.createRequestString:361 – Message to be signed: SAMLRequest=zVXfb5swEP5XkN%2FBQGjaWiVVl6xatXbNmmya9jI55misgc18BtL%2FfoYkHcq6KurTXu3zd9%2BP47i43JSF14BBqVVKoiAkHiihM6keU%2FJlee2fkcvJBfKyqNhVbdfqAX7VgNZz7xSy%2FiIltVFMc5TIFC8BmRVscXV3y%2BIgZJXRVgtdEO8KEYx1jaZaYV2CWYBppIAblcEmJa71zCFLxW1PZm1thYxS5NmqEVwg6ijgGQaY8wCBnSZJQltYuXPadYvpYnFPrz8S71obAT3blOS8QCDezSwlP%2FLR%2BERAPMpOouw8j7KzGPgpP1utxqMxj6LcleGcI8oG%2FjxErB1DtFzZlMRhlPhh7Efny%2FCcxSFLkmAcJt%2BJN9%2FJfCfV1rzXPFlti5B9WC7n%2Fvx%2BsewBGpmB%2BeSqU7IXzatqKJrmP4n3dR%2BXgyL7cHqe5vhY%2BD4MMjk0%2BrAnrqEo%2FFr67oJq8%2Bg8pl2HvfklWJ5xyy%2FokMqWWFyxTtDNbK4LKZ4G%2FOLj56YodDs1wK0zxpoa%2BoRLbl8H6E5k5ud9Kas609CCssRbzDtOn2teyFyC%2BXvU3uoAoTvVzI14Jjt7cSj56EgOUXYgjXuyZevINmXLDQRClxTFGkqOlFtr%2FB6YukmNaZjQ9xunuRsXJDuQDcpnjLZtg3YUdJLiMIzot7vbRY%2Fly37khfPa1TP7VDnvu%2FbsARS0fFXA0p29IPg%2FojqDAh6HVOlhOM9DultrkPVrwxVY2Ng3TetUlxU3ErsPFDZc2F2abIg8LVzYD5APOhw9G6%2BWCSY6aHfcLbJWm6xbTCCcsqXhCitt7NaGF%2FnsLfqHIZP9Jz78FUx%2BAw%3D%3D&RelayState=aHR0cHM6Ly9zYWRidmNhY2FwcDEuYWRzLnNmYS5zZS9zaGVsbC11aS1hcHAvb3JnL0ZLLw%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256
2014-0X-XX 10:20:44,616 [tomcat-http–43] [shell-ui] INFO com.vmware.identity.websso.client.endpoint.SsoRequestSender.getRequestUrl:256 – Redirect URL: https://vcacsso1.vcdx56.com:7444/websso/SAML2/SSO/VCDX56?SAMLRequest=zVXfb5swEP5XkN%2FBQGjaWiVVl6xatXbNmmya9jI55misgc18BtL%2FfoYkHcq6KurTXu3zd9%2BP47i43JSF14BBqVVKoiAkHiihM6keU%2FJlee2fkcvJBfKyqNhVbdfqAX7VgNZz7xSy%2FiIltVFMc5TIFC8BmRVscXV3y%2BIgZJXRVgtdEO8KEYx1jaZaYV2CWYBppIAblcEmJa71zCFLxW1PZm1thYxS5NmqEVwg6ijgGQaY8wCBnSZJQltYuXPadYvpYnFPrz8S71obAT3blOS8QCDezSwlP%2FLR%2BERAPMpOouw8j7KzGPgpP1utxqMxj6LcleGcI8oG%2FjxErB1DtFzZlMRhlPhh7Efny%2FCcxSFLkmAcJt%2BJN9%2FJfCfV1rzXPFlti5B9WC7n%2Fvx%2BsewBGpmB%2BeSqU7IXzatqKJrmP4n3dR%2BXgyL7cHqe5vhY%2BD4MMjk0%2BrAnrqEo%2FFr67oJq8%2Bg8pl2HvfklWJ5xyy%2FokMqWWFyxTtDNbK4LKZ4G%2FOLj56YodDs1wK0zxpoa%2BoRLbl8H6E5k5ud9Kas609CCssRbzDtOn2teyFyC%2BXvU3uoAoTvVzI14Jjt7cSj56EgOUXYgjXuyZevINmXLDQRClxTFGkqOlFtr%2FB6YukmNaZjQ9xunuRsXJDuQDcpnjLZtg3YUdJLiMIzot7vbRY%2Fly37khfPa1TP7VDnvu%2FbsARS0fFXA0p29IPg%2FojqDAh6HVOlhOM9DultrkPVrwxVY2Ng3TetUlxU3ErsPFDZc2F2abIg8LVzYD5APOhw9G6%2BWCSY6aHfcLbJWm6xbTCCcsqXhCitt7NaGF%2FnsLfqHIZP9Jz78FUx%2BAw%3D%3D&RelayState=aHR0cHM6Ly9zYWRidmNhY2FwcDEuYWRzLnNmYS5zZS9zaGVsbC11aS1hcHAvb3JnL0ZLLw%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&Signature=L%2BZOnMb2EDWyORE5ymUu66VKjKE2lFKAmG23izzNj%2FHazVzK%2FiMWrrPP7Q5BBGk4Pbz3vMoRLGttdjrvNh7VDYNLpl67fH96SDtnMfLVtiafiOaIqXMSNOkulavjzO7pp4fsia%2Bd%2FU%2FQ79SdrJ3KXHJZ2npEQAgS380VxtKry9nx6ea8dUPVfrd5aEe4dHv0D1Da6aw57%2F8Ff%2Fb2qeWqYEysFcY%2FjNGsbiAHbFMqwg%2BHgrrYAQitzJIbkPf8FdAvxpblFGuh%2BwM8OoYF8c9uTWNUpqdhZ4eqHwy0Ja2eb6KT5zOmGyUSI5Dvv3NRnvDvMnmh2NHKbi994hg3HKqiow%3D%3D
2014-0X-XX 10:20:44,616 [tomcat-http–43] [shell-ui] INFO com.vmware.identity.websso.client.MessageStoreImpl.add:221 – New MessageStore entry added:%s , store size: %s

————————————————————————————————-

vCAC SSO Appliance log file
tail -f /storage/log/vmware/sso/catalina.out

014-02-19 10:20:44,827 INFO [BaseSsoController] Responded with REDIRECT 302, target https://vcacsso1.vcdx56.com:7444/websso/SAML2/SSO/VCDX56?SAMLRequest=zVXfb5swEP5XkN%2FBQGjaWiVVl6xatXbNmmya9jI55misgc18BtL%2FfoYkHcq6KurTXu3zd9%2BP47i43JSF14BBqVVKoiAkHiihM6keU%2FJlee2fkcvJBfKyqNhVbdfqAX7VgNZz7xSy%2FiIltVFMc5TIFC8BmRVscXV3y%2BIgZJXRVgtdEO8KEYx1jaZaYV2CWYBppIAblcEmJa71zCFLxW1PZm1thYxS5NmqEVwg6ijgGQaY8wCBnSZJQltYuXPadYvpYnFPrz8S71obAT3blOS8QCDezSwlP%2FLR%2BERAPMpOouw8j7KzGPgpP1utxqMxj6LcleGcI8oG%2FjxErB1DtFzZlMRhlPhh7Efny%2FCcxSFLkmAcJt%2BJN9%2FJfCfV1rzXPFlti5B9WC7n%2Fvx%2BsewBGpmB%2BeSqU7IXzatqKJrmP4n3dR%2BXgyL7cHqe5vhY%2BD4MMjk0%2BrAnrqEo%2FFr67oJq8%2Bg8pl2HvfklWJ5xyy%2FokMqWWFyxTtDNbK4LKZ4G%2FOLj56YodDs1wK0zxpoa%2BoRLbl8H6E5k5ud9Kas609CCssRbzDtOn2teyFyC%2BXvU3uoAoTvVzI14Jjt7cSj56EgOUXYgjXuyZevINmXLDQRClxTFGkqOlFtr%2FB6YukmNaZjQ9xunuRsXJDuQDcpnjLZtg3YUdJLiMIzot7vbRY%2Fly37khfPa1TP7VDnvu%2FbsARS0fFXA0p29IPg%2FojqDAh6HVOlhOM9DultrkPVrwxVY2Ng3TetUlxU3ErsPFDZc2F2abIg8LVzYD5APOhw9G6%2BWCSY6aHfcLbJWm6xbTCCcsqXhCitt7NaGF%2FnsLfqHIZP9Jz78FUx%2BAw%3D%3D&RelayState=aHR0cHM6Ly9zYWRidmNhY2FwcDEuYWRzLnNmYS5zZS9zaGVsbC11aS1hcHAvb3JnL0ZLLw%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&Signature=L%2BZOnMb2EDWyORE5ymUu66VKjKE2lFKAmG23izzNj%2FHazVzK%2FiMWrrPP7Q5BBGk4Pbz3vMoRLGttdjrvNh7VDYNLpl67fH96SDtnMfLVtiafiOaIqXMSNOkulavjzO7pp4fsia%2Bd%2FU%2FQ79SdrJ3KXHJZ2npEQAgS380VxtKry9nx6ea8dUPVfrd5aEe4dHv0D1Da6aw57%2F8Ff%2Fb2qeWqYEysFcY%2FjNGsbiAHbFMqwg%2BHgrrYAQitzJIbkPf8FdAvxpblFGuh%2BwM8OoYF8c9uTWNUpqdhZ4eqHwy0Ja2eb6KT5zOmGyUSI5Dvv3NRnvDvMnmh2NHKbi994hg3HKqiow%3D%3D&passwordEntry=1
2014-0X-XX 10:20:44,834 INFO [SsoController] Welcome to SP-initiated AuthnRequest handler, PASSWORD entry form! The client locale is sv_SE, tenant is VCDX56
2014-0X-XX 10:20:44,834 DEBUG [DefaultIdmAccessorFactory] DefaultIdmAccessorFactory constructor
2014-0X-XX 10:20:44,834 DEBUG [DefaultIdmAccessorFactory] DefaultIdmAccessorFactory getIdmAccessor
2014-0X-XX 10:20:44,834 DEBUG [CasIdmAccessor] CasIdmAccessor constructor called
2014-0X-XX 10:20:44,834 DEBUG [CasIdmAccessor] setTenant: VCDX56
2014-0X-XX 10:20:44,834 DEBUG [CasIdmAccessor] getBrandName
2014-0X-XX 10:20:44,839 INFO [SsoController] Accessing Tenant VCDX56, brand name string <img id=’topSplash’ src=’../../resources/img/AppBgPattern.png’><img id=’brand’ src=’../../resources/img/vmwareLogoBigger.png’><span>VMware^&reg; vCloud Automation Center^&trade;</span><style type=’text/css’>body { background: #3075ab; /* Old browsers */ background: -moz-linear-gradient(top, #3a8dc8 0%, #183a62 100%); /* FF3.6+ */ background: -webkit-gradient(linear, left top, left bottom, color-stop(0%, #3a8dc8), color-stop(100%, #183a62)); /* Chrome,Safari4+ */ background: -webkit-linear-gradient(top, #3a8dc8 0%, #183a62 100%); /* Chrome10+,Safari5.1+ */ background: -o-linear-gradient(top, #3a8dc8 0%, #183a62 100%); /* Opera 11.10+ */ background: -ms-linear-gradient(top, #3a8dc8 0%, #183a62 100%); /* IE10+ */ background: linear-gradient(to bottom, #3a8dc8 0%, #183a62 100%); /* W3C */ filter: progid:DXImageTransform.Microsoft.gradient( startColorstr=’#3a8dc8′, endColorstr=’#183a62′, GradientType=0); /* IE6-9 */ background-repeat: no-repeat; margin : 0; font-size : 12px; font-family : Arial, Helvetica, sans-serif; color: #87ceff; margin: 0; font-size: 12px; font-family: Arial, Helvetica, sans-serif;}#topSplash { position: absolute; top: 0; left: 0; z-index: 1;}#brand { position: absolute; top: 55px; left: 44px; z-index: 2;}#tenantBrand { top: 0; left: 0; margin: 0; padding: 0; width: 100%;}#tenantBrand span { position: absolute; top: 345px; left: 424px; color: #FFF; font-size: 21px;}#tenantBrand sup { font-size: 11px;}#loginForm { background-image: url(../../resources/img/divider.png);}.loginLabel { color: #FFFFFF;}#productName { top: 365px;}#response { color: #87CEFF;}#footer { background-color: 090B0D; color: #838689;}</style>
2014-0X-XX 10:20:54,683 DEBUG [SessionCleanupWrapper] Check existing sessions
2014-0X-XX 10:20:54,684 DEBUG [SessionManagerImpl] Returning all sessions
2014-0X-XX 10:21:02,917 INFO [SsoController] Welcome to SP-initiated AuthnRequest handler! The client locale is sv_SE, tenant is VCDX56
2014-0X-XX 10:21:02,918 INFO [SsoController] Request URL is https://vcacsso1.vcdx56.com:7444/websso/SAML2/SSO/VCDX56
2014-0X-XX 10:21:02,918 DEBUG [SsoController] castleAuthHeader is Basic bWFnbnVzYUBhZHM6VGVzdDEyMzQ=
2014-0X-XX 10:21:02,918 DEBUG [SsoController] Password authenticator chosen
2014-0X-XX 10:21:02,918 DEBUG [AuthnRequestState] Constructing from request https://vcacsso1.vcdx56.com:7444/websso/SAML2/SSO/VCDX56?SAMLRequest=zVXfb5swEP5XkN%2FBQGjaWiVVl6xatXbNmmya9jI55misgc18BtL%2FfoYkHcq6KurTXu3zd9%2BP47i43JSF14BBqVVKoiAkHiihM6keU%2FJlee2fkcvJBfKyqNhVbdfqAX7VgNZz7xSy%2FiIltVFMc5TIFC8BmRVscXV3y%2BIgZJXRVgtdEO8KEYx1jaZaYV2CWYBppIAblcEmJa71zCFLxW1PZm1thYxS5NmqEVwg6ijgGQaY8wCBnSZJQltYuXPadYvpYnFPrz8S71obAT3blOS8QCDezSwlP%2FLR%2BERAPMpOouw8j7KzGPgpP1utxqMxj6LcleGcI8oG%2FjxErB1DtFzZlMRhlPhh7Efny%2FCcxSFLkmAcJt%2BJN9%2FJfCfV1rzXPFlti5B9WC7n%2Fvx%2BsewBGpmB%2BeSqU7IXzatqKJrmP4n3dR%2BXgyL7cHqe5vhY%2BD4MMjk0%2BrAnrqEo%2FFr67oJq8%2Bg8pl2HvfklWJ5xyy%2FokMqWWFyxTtDNbK4LKZ4G%2FOLj56YodDs1wK0zxpoa%2BoRLbl8H6E5k5ud9Kas609CCssRbzDtOn2teyFyC%2BXvU3uoAoTvVzI14Jjt7cSj56EgOUXYgjXuyZevINmXLDQRClxTFGkqOlFtr%2FB6YukmNaZjQ9xunuRsXJDuQDcpnjLZtg3YUdJLiMIzot7vbRY%2Fly37khfPa1TP7VDnvu%2FbsARS0fFXA0p29IPg%2FojqDAh6HVOlhOM9DultrkPVrwxVY2Ng3TetUlxU3ErsPFDZc2F2abIg8LVzYD5APOhw9G6%2BWCSY6aHfcLbJWm6xbTCCcsqXhCitt7NaGF%2FnsLfqHIZP9Jz78FUx%2BAw%3D%3D&RelayState=aHR0cHM6Ly9zYWRidmNhY2FwcDEuYWRzLnNmYS5zZS9zaGVsbC11aS1hcHAvb3JnL0ZLLw%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&Signature=L%2BZOnMb2EDWyORE5ymUu66VKjKE2lFKAmG23izzNj%2FHazVzK%2FiMWrrPP7Q5BBGk4Pbz3vMoRLGttdjrvNh7VDYNLpl67fH96SDtnMfLVtiafiOaIqXMSNOkulavjzO7pp4fsia%2Bd%2FU%2FQ79SdrJ3KXHJZ2npEQAgS380VxtKry9nx6ea8dUPVfrd5aEe4dHv0D1Da6aw57%2F8Ff%2Fb2qeWqYEysFcY%2FjNGsbiAHbFMqwg%2BHgrrYAQitzJIbkPf8FdAvxpblFGuh%2BwM8OoYF8c9uTWNUpqdhZ4eqHwy0Ja2eb6KT5zOmGyUSI5Dvv3NRnvDvMnmh2NHKbi994hg3HKqiow%3D%3D&passwordSupplied=1
2014-0X-XX 10:21:02,918 DEBUG [DefaultIdmAccessorFactory] DefaultIdmAccessorFactory constructor
2014-0X-XX 10:21:02,918 DEBUG [DefaultIdmAccessorFactory] DefaultIdmAccessorFactory getIdmAccessor
2014-0X-XX 10:21:02,918 DEBUG [CasIdmAccessor] CasIdmAccessor constructor called
2014-0X-XX 10:21:02,919 DEBUG [AuthnRequestState] Relay state specified was https://vcacapp1.vcdx56.com/shell-ui-app/org/VCDX56/
2014-0X-XX 10:21:02,919 DEBUG [AuthnRequestState] parseRequestForTenant, tenant VCDX56
2014-0X-XX 10:21:02,919 DEBUG [CasIdmAccessor] setTenant: VCDX56
2014-0X-XX 10:21:02,919 DEBUG [CasIdmAccessor] getCertificatesForRelyingParty null
2014-0X-XX 10:21:02,978 DEBUG [CasIdmAccessor] getIdpEntityId
2014-0X-XX 10:21:02,987 DEBUG [CasIdmAccessor] setTenant: VCDX56
2014-0X-XX 10:21:02,987 DEBUG [AuthnRequestStateCookieWrapper] AuthnRequestStateCookieWrapper.preAuthenticate is called
2014-0X-XX 10:21:02,987 DEBUG [CasIdmAccessor] getTenant: VCDX56
2014-0X-XX 10:21:02,987 DEBUG [AuthnRequestStatePasswordAuthenticationFilter] AuthnRequestStatePasswordAuthenticationFilter.preAuthenticate is called
2014-0X-XX 10:21:02,987 DEBUG [AuthnRequestStatePasswordAuthenticationFilter] authHeader is Basic bWFnbnVzYUBhZHM6VGVzdDEyMzQ=
2014-0X-XX 10:21:02,987 DEBUG [AuthnRequestStatePasswordAuthenticationFilter] authData is bWFnbnVzYUBhZHM6VGVzdDEyMzQ=
2014-0X-XX 10:21:02,987 DEBUG [SamlServiceImpl] Decoding SAML AuthnRequest: org.apache.catalina.connector.RequestFacade@7c28093
2014-0X-XX 10:21:02,987 DEBUG [SamlServiceImpl] Decoding SAML object: org.apache.catalina.connector.RequestFacade@7c28093
2014-0X-XX 10:21:02,989 DEBUG [CasIdmAccessor] setTenant: VCDX56
2014-0X-XX 10:21:02,989 DEBUG [CasIdmAccessor] getCertificatesForRelyingParty https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata
2014-0X-XX 10:21:03,059 DEBUG [CasIdmAccessor] getIdpEntityId
2014-0X-XX 10:21:03,069 DEBUG [SamlServiceImpl] Verify signature, message SAMLRequest=zVXfb5swEP5XkN%2FBQGjaWiVVl6xatXbNmmya9jI55misgc18BtL%2FfoYkHcq6KurTXu3zd9%2BP47i43JSF14BBqVVKoiAkHiihM6keU%2FJlee2fkcvJBfKyqNhVbdfqAX7VgNZz7xSy%2FiIltVFMc5TIFC8BmRVscXV3y%2BIgZJXRVgtdEO8KEYx1jaZaYV2CWYBppIAblcEmJa71zCFLxW1PZm1thYxS5NmqEVwg6ijgGQaY8wCBnSZJQltYuXPadYvpYnFPrz8S71obAT3blOS8QCDezSwlP%2FLR%2BERAPMpOouw8j7KzGPgpP1utxqMxj6LcleGcI8oG%2FjxErB1DtFzZlMRhlPhh7Efny%2FCcxSFLkmAcJt%2BJN9%2FJfCfV1rzXPFlti5B9WC7n%2Fvx%2BsewBGpmB%2BeSqU7IXzatqKJrmP4n3dR%2BXgyL7cHqe5vhY%2BD4MMjk0%2BrAnrqEo%2FFr67oJq8%2Bg8pl2HvfklWJ5xyy%2FokMqWWFyxTtDNbK4LKZ4G%2FOLj56YodDs1wK0zxpoa%2BoRLbl8H6E5k5ud9Kas609CCssRbzDtOn2teyFyC%2BXvU3uoAoTvVzI14Jjt7cSj56EgOUXYgjXuyZevINmXLDQRClxTFGkqOlFtr%2FB6YukmNaZjQ9xunuRsXJDuQDcpnjLZtg3YUdJLiMIzot7vbRY%2Fly37khfPa1TP7VDnvu%2FbsARS0fFXA0p29IPg%2FojqDAh6HVOlhOM9DultrkPVrwxVY2Ng3TetUlxU3ErsPFDZc2F2abIg8LVzYD5APOhw9G6%2BWCSY6aHfcLbJWm6xbTCCcsqXhCitt7NaGF%2FnsLfqHIZP9Jz78FUx%2BAw%3D%3D&RelayState=aHR0cHM6Ly9zYWRidmNhY2FwcDEuYWRzLnNmYS5zZS9zaGVsbC11aS1hcHAvb3JnL0ZLLw%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256, sigAlg SHA256withRSA, signature L+ZOnMb2EDWyORE5ymUu66VKjKE2lFKAmG23izzNj/HazVzK/iMWrrPP7Q5BBGk4Pbz3vMoRLGttdjrvNh7VDYNLpl67fH96SDtnMfLVtiafiOaIqXMSNOkulavjzO7pp4fsia+d/U/Q79SdrJ3KXHJZ2npEQAgS380VxtKry9nx6ea8dUPVfrd5aEe4dHv0D1Da6aw57/8Ff/b2qeWqYEysFcY/jNGsbiAHbFMqwg+HgrrYAQitzJIbkPf8FdAvxpblFGuh+wM8OoYF8c9uTWNUpqdhZ4eqHwy0Ja2eb6KT5zOmGyUSI5Dvv3NRnvDvMnmh2NHKbi994hg3HKqiow==
2014-0X-XX 10:21:03,070 DEBUG [SamlServiceImpl] signature verifies: true
2014-0X-XX 10:21:03,070 DEBUG [AuthnRequestStateValidator] Validating request com.vmware.identity.samlservice.AuthnRequestState@6a589d05
2014-0X-XX 10:21:03,070 DEBUG [CasIdmAccessor] getTenant: VCDX56
2014-0X-XX 10:21:03,070 DEBUG [CasIdmAccessor] getAcsForRelyingParty https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata, index 0, URL null, binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST
2014-0X-XX 10:21:03,080 DEBUG [CasIdmAccessor] getAuthnRequestsSignedForRelyingParty https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata
2014-0X-XX 10:21:03,139 DEBUG [AuthnRequestState] authenticate, tenant VCDX56
2014-0X-XX 10:21:03,139 DEBUG [CasIdmAccessor] setTenant: VCDX56
2014-0X-XX 10:21:03,139 DEBUG [AuthnRequestStateCookieWrapper] AuthnRequestStateCookieWrapper.authenticate is called
2014-0X-XX 10:21:03,139 DEBUG [CasIdmAccessor] getTenant: VCDX56
2014-0X-XX 10:21:03,139 DEBUG [AuthnRequestStatePasswordAuthenticationFilter] AuthnRequestStatePasswordAuthenticationFilter.authenticate is called
2014-0X-XX 10:21:03,139 DEBUG [AuthnRequestStatePasswordAuthenticationFilter] authHeader is Basic bWFnbnVzYUBhZHM6VGVzdDEyMzQ=
2014-0X-XX 10:21:03,140 DEBUG [AuthnRequestStatePasswordAuthenticationFilter] authData is bWFnbnVzYUBhZHM6VGVzdDEyMzQ=
2014-0X-XX 10:21:03,140 DEBUG [CasIdmAccessor] password authenticate
2014-0X-XX 10:21:03,161 DEBUG [SessionManagerImpl] Adding Session [principalId={Name: magnusa, Domain: vcdx56.com}, expireDate=Wed Feb 19 18:21:03 CET 2014, authnMethod=PASSWORD, logoutRequestData=null, participants=[]]
2014-0X-XX 10:21:03,161 DEBUG [CasIdmAccessor] setTenant: VCDX56
2014-0X-XX 10:21:03,161 DEBUG [AuthnRequestState] create token authority for tenant VCDX56
2014-0X-XX 10:21:03,173 DEBUG [DefaultSamlAuthorityFactory] Created token authority.
2014-0X-XX 10:21:03,173 DEBUG [SessionManagerImpl] Querying _0b705a4269af5b2e668aca4eef16b41b
2014-0X-XX 10:21:03,173 DEBUG [SessionManagerImpl] Found Session [principalId={Name: magnusa, Domain: vcdx56.com}, expireDate=Wed Feb 19 18:21:03 CET 2014, authnMethod=PASSWORD, logoutRequestData=null, participants=[]]
2014-0X-XX 10:21:03,173 DEBUG [CasIdmAccessor] getAcsForRelyingParty https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata, index 0, URL null, binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST
2014-0X-XX 10:21:03,184 DEBUG [AuthnRequestState] create token spec for principal {Name: magnusa, Domain: vcdx56.com}
2014-0X-XX 10:21:03,184 DEBUG [AuthnRequestState] relying party url https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata, identityFormat http://schemas.xmlsoap.org/claims/UPN
2014-0X-XX 10:21:03,184 DEBUG [AuthnRequestState] authn method PASSWORD session Session [principalId={Name: magnusa, Domain: vcdx56.com}, expireDate=Wed Feb 19 18:21:03 CET 2014, authnMethod=PASSWORD, logoutRequestData=null, participants=[]]
2014-0X-XX 10:21:03,184 DEBUG [AuthnRequestState] inResponseTo _f365ce23d51d9f1d82ea7a8bb636a11f recipient https://vcacapp1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/sso
2014-0X-XX 10:21:03,184 DEBUG [AuthnRequestState] audience https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata
2014-0X-XX 10:21:03,184 DEBUG [AuthnRequestState] building Attribute Definition collection, identity format is http://schemas.xmlsoap.org/claims/UPN
2014-0X-XX 10:21:03,184 DEBUG [SessionManagerImpl] Updating Session [principalId={Name: magnusa, Domain: vcdx56.com}, expireDate=Wed Feb 19 18:21:03 CET 2014, authnMethod=PASSWORD, logoutRequestData=null, participants=[SessionParticipant [sessionId=_5beee54d3e4780c9217196ef545f16cc, relyingPartyUrl=https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata]]]
2014-0X-XX 10:21:03,184 DEBUG [SessionManagerImpl] Removing _0b705a4269af5b2e668aca4eef16b41b
2014-0X-XX 10:21:03,184 DEBUG [SessionManagerImpl] Adding Session [principalId={Name: magnusa, Domain: vcdx56.com}, expireDate=Wed Feb 19 18:21:03 CET 2014, authnMethod=PASSWORD, logoutRequestData=null, participants=[SessionParticipant [sessionId=_5beee54d3e4780c9217196ef545f16cc, relyingPartyUrl=https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata]]]
2014-0X-XX 10:21:03,184 DEBUG [TokenAuthorityImpl] Started issuing token for spec:SamlTokenSpec [lifespan=TimePeriod [startTime=Wed Feb 19 10:19:48 CET 2014, endTime=Wed Feb 19 10:36:03 CET 2014], confirmation=Confirmation [type=http://docs.oasis-open.org/ws-sx/ws-trust/200512/Bearer, inResponseTo=_f365ce23d51d9f1d82ea7a8bb636a11f, recipient=https://vcacapp1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/sso, certificate=null], authentication=AuthenticationData [principalId={Name: magnusa, Domain: vcdx56.com}, authnTime=Wed Feb 19 10:21:03 CET 2014, authnMethod=PASSWORD, identityAttr=http://schemas.xmlsoap.org/claims/UPN], delegationSpec=DelegationSpec [delegate=null, delegable=true, history=null], renewSpec=RenewSpec [renewable=true, renew=false, remaining=0], audience=[https://vcacsso1.vcdx56.com/shell-ui-app/org/VCDX56/saml/websso/metadata], adviceReq=[], advicePresent=[], attributeNames=[http://schemas.xmlsoap.org/claims/UPN, http://schemas.xmlsoap.org/ws/2005/05/identity/claims/givenname, http://vmware.com/schemas/attr-names/2011/07/isSolution, http://schemas.xmlsoap.org/ws/2005/05/identity/claims/surname, http://rsa.com/schemas/attr-names/2009/01/GroupIdentity], signatureAlgorithm=null]
2014-0X-XX 10:21:03,184 DEBUG [TokenAuthorityImpl] Issue instant time: Wed Feb 19 10:21:03 CET 2014
2014-0X-XX 10:21:03,184 DEBUG [DefaultIdmAccessorFactory] DefaultIdmAccessorFactory constructor
2014-0X-XX 10:21:03,185 DEBUG [DefaultIdmAccessorFactory] DefaultIdmAccessorFactory getIdmAccessor
2014-0X-XX 10:21:03,185 DEBUG [CasIdmAccessor] CasIdmAccessor constructor called
2014-0X-XX 10:21:03,185 DEBUG [CasIdmAccessor] setTenant: VCDX56
2014-0X-XX 10:21:03,185 DEBUG [CasIdmAccessor] getIdpEntityId
2014-0X-XX 10:21:03,194 DEBUG [CasIdmAccessor] getSAMLAuthorityChain
2014-0X-XX 10:21:03,195 DEBUG [CasIdmAccessor] getSAMLAuthorityPrivateKey
2014-0X-XX 10:21:03,197 DEBUG [CasIdmAccessor] getMaximumBearerTokenLifetime
2014-0X-XX 10:21:03,198 DEBUG [CasIdmAccessor] getMaximumHoKTokenLifetime
2014-0X-XX 10:21:03,199 DEBUG [CasIdmAccessor] getDelegationCount
2014-0X-XX 10:21:03,200 DEBUG [CasIdmAccessor] getRenewCount
2014-0X-XX 10:21:03,201 DEBUG [CasIdmAccessor] getSAMLAuthorityChains
2014-0X-XX 10:21:03,203 DEBUG [CasIdmAccessor] getClockTolerance
2014-0X-XX 10:21:03,204 DEBUG [CasIdmAccessor] getExternalIdps
2014-0X-XX 10:21:03,205 DEBUG [CasIdmAccessor] getTenantSignatureAlgorithm
2014-0X-XX 10:21:03,206 DEBUG [TokenLifetimeRemediator] Token start time will get value from rst:Lifetime
2014-0X-XX 10:21:03,206 DEBUG [TokenLifetimeRemediator] Token start time will be Wed Feb 19 10:19:48 CET 2014
2014-0X-XX 10:21:03,206 DEBUG [TokenLifetimeRemediator] Remediated token end time is Wed Feb 19 10:24:48 CET 2014
2014-0X-XX 10:21:03,207 DEBUG [TokenLifetimeRemediator] Token end time will be Wed Feb 19 10:24:48 CET 2014
2014-0X-XX 10:21:03,207 DEBUG [DelegationHandler] Token final delegate list is []
2014-0X-XX 10:21:03,207 DEBUG [DelegationHandler] Token final delegation count is 10
2014-0X-XX 10:21:03,207 DEBUG [TokenAuthorityImpl] http://www.w3.org/2001/04/xmldsig-more#rsa-sha256 signature algorithm will be used for signing the token.