Sporadic exceptions when calling UserSessionService.getSession()

[mikemayors]

In the virgo logs I'm getting an ExecutionException when calling UserSessionService.getSession (see attached stacktrace - sensitive info is overwritten with 'xx')  

vSphere client SDK doesn't document exceptions for UserSessionService or how to work around them.  Can we get any pointers on how to root cause these failures?  It's a linked mode setup (2 VCs) with a standalone PSC. 



Best,

Mike
 

[mikemayors]

Clarification: The exception is seen in the virgo logs of the first linked vCenter, but the SDK URL in the exception corresponds to the 2nd linked vCenter.

[mikemayors]

↵Last bit of info:

Seeing a lot of these on the 2nd linked vCenter:
 

[2016-05-10T16:28:44.454Z] [ERROR] data-service-pool-173707     70082363 100649 200587 c.v.v.client.sso.admin.impl.PrincipalManagerPropertyProvider      Error while extracting local SSO users with spec :

com.vmware.vsphere.client.sso.admin.model.FindDomainUserSpec {

  domainName = root.sys

  criteria = 

} com.vmware.vsphere.client.sso.admin.exception.SsoBackendException: A vCenter Single Sign-On service error occurred

at com.vmware.vsphere.client.sso.admin.exception.FallbackExceptionTransformer.transform(FallbackExceptionTransformer.java:30)

at com.vmware.vsphere.client.sso.admin.exception.BackendExceptionTransformer.transformException(BackendExceptionTransformer.java:96)

at com.vmware.vsphere.client.sso.admin.impl.AdminServiceBase.transformBackendException(AdminServiceBase.java:94)

at com.vmware.vsphere.client.sso.admin.impl.PrincipalManagementServiceImpl.findUsers(PrincipalManagementServiceImpl.java:300)

at com.vmware.vsphere.client.sso.admin.impl.PrincipalManagerPropertyProvider.getLocalSsoUsers(PrincipalManagerPropertyProvider.java:92)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter.invokeMethod(ServicePropertyProviderAdapter.java:285)

at com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter.getProperties(ServicePropertyProviderAdapter.java:127)

at com.vmware.vise.data.query.impl.DataManager.getDataFromPropertyProvider(DataManager.java:1312)

at com.vmware.vise.data.query.impl.DataManager.getResultFromPropertyProvider(DataManager.java:1283)

at com.vmware.vise.data.query.impl.DataManager.access$000(DataManager.java:67)

at com.vmware.vise.data.query.impl.DataManager$1.run(DataManager.java:858)

at com.vmware.vise.util.concurrent.ExecutorUtil$2.run(ExecutorUtil.java:187)

at com.vmware.vise.util.concurrent.ExecutorUtil$ThreadContextPropagatingRunnable.run(ExecutorUtil.java:584)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

 

[2016-05-10T16:28:44.454Z] [WARN ] data-service-pool-173707     70082363 100649 200587 com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter    A PropertyProviderBean method's execution took too long: 105421 milliseconds. The method failed with an exception: null (Provider instance: com.vmware.vsphere.client.sso.admin.impl.PrincipalManagerPropertyProvider@66f986e, method: public com.vmware.vim.binding.sso.admin.PersonUser[] com.vmware.vsphere.client.sso.admin.impl.PrincipalManagerPropertyProvider.getLocalSsoUsers(java.lang.Object,com.vmware.vsphere.client.sso.admin.model.FindDomainUserSpec) throws com.vmware.vsphere.client.sso.admin.SsoException, property: ref: urn:vri:sso:PrincipalManager:pm-0, method args: [urn:vri:sso:PrincipalManager:pm-0, com.vmware.vsphere.client.sso.admin.model.FindDomainUserSpec@18480f8c]) 

[2016-05-10T16:28:44.455Z] [ERROR] data-service-pool-173707     70082363 100649 200587 com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter    Error when fetching property {vsphere:domainUsers} from property provider {class com.vmware.vsphere.client.sso.admin.impl.PrincipalManagerPropertyProvider} com.vmware.vsphere.client.sso.admin.SsoException: Error while extracting local SSO users

at com.vmware.vsphere.client.sso.admin.impl.PrincipalManagerPropertyProvider.getLocalSsoUsers(PrincipalManagerPropertyProvider.java:98)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter.invokeMethod(ServicePropertyProviderAdapter.java:285)

at com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter.getProperties(ServicePropertyProviderAdapter.java:127)

at com.vmware.vise.data.query.impl.DataManager.getDataFromPropertyProvider(DataManager.java:1312)

at com.vmware.vise.data.query.impl.DataManager.getResultFromPropertyProvider(DataManager.java:1283)

at com.vmware.vise.data.query.impl.DataManager.access$000(DataManager.java:67)

at com.vmware.vise.data.query.impl.DataManager$1.run(DataManager.java:858)

at com.vmware.vise.util.concurrent.ExecutorUtil$2.run(ExecutorUtil.java:187)

at com.vmware.vise.util.concurrent.ExecutorUtil$ThreadContextPropagatingRunnable.run(ExecutorUtil.java:584)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

Caused by: com.vmware.vsphere.client.sso.admin.exception.SsoBackendException: A vCenter Single Sign-On service error occurred

at com.vmware.vsphere.client.sso.admin.exception.FallbackExceptionTransformer.transform(FallbackExceptionTransformer.java:30)

at com.vmware.vsphere.client.sso.admin.exception.BackendExceptionTransformer.transformException(BackendExceptionTransformer.java:96)

at com.vmware.vsphere.client.sso.admin.impl.AdminServiceBase.transformBackendException(AdminServiceBase.java:94)

at com.vmware.vsphere.client.sso.admin.impl.PrincipalManagementServiceImpl.findUsers(PrincipalManagementServiceImpl.java:300)

at com.vmware.vsphere.client.sso.admin.impl.PrincipalManagerPropertyProvider.getLocalSsoUsers(PrincipalManagerPropertyProvider.java:92)

... 15 common frames omitted

[2016-05-10T16:28:44.470Z] [WARN ] http-bio-9090-exec-56        70082363 100649 200587 com.vmware.vise.data.query.profiling.ProfilingUtil                The Data Service detected slow execution:

The query batch execution took too long: 105437 milliseconds.

[2016-05-10T16:28:44.454Z] [ERROR] data-service-pool-173707     70082363 100649 200587 c.v.v.client.sso.admin.impl.PrincipalManagerPropertyProvider      Error while extracting local SSO users with spec :

com.vmware.vsphere.client.sso.admin.model.FindDomainUserSpec {

  domainName = root.sys

  criteria = 

} com.vmware.vsphere.client.sso.admin.exception.SsoBackendException: A vCenter Single Sign-On service error occurred

    at com.vmware.vsphere.client.sso.admin.exception.FallbackExceptionTransformer.transform(FallbackExceptionTransformer.java:30)

    at com.vmware.vsphere.client.sso.admin.exception.BackendExceptionTransformer.transformException(BackendExceptionTransformer.java:96)

    at com.vmware.vsphere.client.sso.admin.impl.AdminServiceBase.transformBackendException(AdminServiceBase.java:94)

    at com.vmware.vsphere.client.sso.admin.impl.PrincipalManagementServiceImpl.findUsers(PrincipalManagementServiceImpl.java:300)

    at com.vmware.vsphere.client.sso.admin.impl.PrincipalManagerPropertyProvider.getLocalSsoUsers(PrincipalManagerPropertyProvider.java:92)

    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    at java.lang.reflect.Method.invoke(Unknown Source)

    at com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter.invokeMethod(ServicePropertyProviderAdapter.java:285)

    at com.vmware.vise.data.query.impl.ServicePropertyProviderAdapter.getProperties(ServicePropertyProviderAdapter.java:127)

    at com.vmware.vise.data.query.impl.DataManager.getDataFromPropertyProvider(DataManager.java:1312)

    at com.vmware.vise.data.query.impl.DataManager.getResultFromPropertyProvider(DataManager.java:1283)

    at com.vmware.vise.data.query.impl.DataManager.access$000(DataManager.java:67)

    at com.vmware.vise.data.query.impl.DataManager$1.run(DataManager.java:858)

    at com.vmware.vise.util.concurrent.ExecutorUtil$2.run(ExecutorUtil.java:187)

    at com.vmware.vise.util.concurrent.ExecutorUtil$ThreadContextPropagatingRunnable.run(ExecutorUtil.java:584)

    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

    at java.lang.Thread.run(Unknown Source)

[vesuvius_prime]

It looks like there are SSO problems. Can you, please, examine the SSO logs on the PSC?

[mikemayors]

Sure thing! I'll try grabbing those today and will post any error messages that stand out.

Just to be clear, should I be inspecting the paths provided on this article? https://pubs.vmware.com/vsphere-60/index.jsp?topic=%2Fcom.vmware.vsphere.troubleshooting.doc%2FGUID-...

"Most logs are located in C:\ProgramData\VMware\CIS\logs. Common logs are available in all implementations. Other logs are unique to certain deployment options (Management Node or Platform Services Controller).

For Platform Services Controller node deployments, additional runtime logs are located at C:\ProgramData\VMware\CIS\runtime\VMwareSTSService\logs, including logs for these services:

VMware Secure Token Service

VMware Identity Management Service"

For Platform Services Controller node deployments, additional runtime logs are located at C:\ProgramData\VMware\CIS\runtime\VMwareSTSService\logs, including logs for these services:

■

VMware Secure Token Service

■

VMware Identity Management Service

[mikemayors]

Oops, looks like this the right article: https://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=21131...

[vesuvius_prime]

I only have an embedded CISwin 6.0 and an embedded CISwin 6.0 U1 at the moment and in them the log directory is C:\ProgramData\VMware\vCenterServer\logs\sso. Unfortunately, currently I don't have a standalone Windows-based PSC, but I have a standalone Linux-based PSC and the SSO log directory there is /var/log/vmware/sso.

[mikemayors]

My bad this is actually a VCSA appliance.  I downloaded the vm-support.tgz file but I don't see an sso directory in /var/log/vmware.  Do you know which of these directories (attached screenshot) would most likely have information for triaging issues between the PSC and the vCenters?  Thanks again, this is my first time ever looking at the PSC log bundle.

Best,

Mike

[vesuvius_prime]

Hi, the screenshot seems to show the directories of a management node, not a PSC node. I guess SSO is installed on some other machine. Can you examine the Web Client's log and see the messages logged by, say, class SsoUtilInternal? There should be messages there showing which machine hosts SSO. Another way to verify this is to enable network monitoring in your browser and to see the URL to which the Web Client will redirect for the login page. The machine hosting the login page should be the machine hosting SSO.

[mikemayors]

Ok I got got them.  I opened websso.log and saw some messages that looked important:

[2016-04-01T22:05:10.063Z tomcat-http--37  ERROR com.vmware.identity.BaseSsoController] SSO Request responded with REDIRECT 302 Substatus code: null

[2016-04-01T22:05:10.084Z tomcat-http--37  DEBUG com.vmware.identity.SecurityRequestWrapperFilter] X-Forwarded-Proto set to https, so encapsulate it with secure request.

[2016-04-01T22:05:08.275Z tomcat-http--37  DEBUG com.vmware.identity.samlservice.impl.SamlServiceImpl] Creating SAML Logout Response status:urn:oasis:names:tc:SAML:2.0:status:Responder, substatus: null, message:Internal Processing Error

Let me know if you have any pointers or if there's other files I should be taking a look at. Thanks again, really appreciate your help and responsiveness.

[vesuvius_prime]

websso.log will probably not be very useful in this particular case. Have a look at the other logs in the directory, e.g. vmware-identity-sts.log, vmware-sts-idmd.log. I'm not an SSO expert, so I don't really know which file will be most useful, but one or more of these files are likely to contain errors similar to what you see reported in the Web Client's log.

[mikemayors]

Alright, ready?

I see the following messages recently in lookupServer.log, but I see them on both PSCs so it's not clear if this is benign:

016-04-01T18:29:21.458Z pool-2-thread-1  INFO  com.vmware.vim.lookup.impl.LdapStorage] Getting service; serviceId=118337da-4639-4237-999c-5ae1d4778e82, siteId=NY-DR

[2016-04-01T18:29:21.459Z pool-2-thread-1  ERROR com.vmware.identity.interop.ldap.LinuxLdapClientLibrary] Exception when calling ldap_search_s: base=cn=118337da-4639-4237-999c-5ae1d4778e82,cn=ServiceRegistrations,cn=LookupService,cn=NY-DR,cn=sites,cn=configuration,dc=vsphere,dc=local, scope=2, filter=(objectclass=*), attrs=null, attrsonly=0

com.vmware.identity.interop.ldap.NoSuchObjectLdapException: No such object

LDAP error [code: 32]

  at com.vmware.identity.interop.ldap.LdapErrorChecker$22.RaiseLdapError(LdapErrorChecker.java:325)

  at com.vmware.identity.interop.ldap.LdapErrorChecker.CheckError(LdapErrorChecker.java:826)

  at com.vmware.identity.interop.ldap.LinuxLdapClientLibrary.CheckError(LinuxLdapClientLibrary.java:1066)

  at com.vmware.identity.interop.ldap.LinuxLdapClientLibrary.ldap_search_s(LinuxLdapClientLibrary.java:702)

  at com.vmware.identity.interop.ldap.LdapConnection$3.call(LdapConnection.java:342)

  at com.vmware.identity.interop.ldap.LdapConnection$3.call(LdapConnection.java:339)

  at com.vmware.identity.interop.ldap.LdapConnection.execute(LdapConnection.java:73)

  at com.vmware.identity.interop.ldap.LdapConnection.search(LdapConnection.java:338)

  at com.vmware.identity.interop.ldap.LdapConnection.search(LdapConnection.java:307)

  at com.vmware.vim.lookup.impl.LdapStorage$11.apply(LdapStorage.java:677)

  at com.vmware.vim.lookup.impl.LdapStorage$11.apply(LdapStorage.java:670)

  at com.vmware.vim.lookup.impl.LdapStorage.applyServiceEntryFunctionImpl(LdapStorage.java:642)

  at com.vmware.vim.lookup.impl.LdapStorage.applyServiceEntryFunctionImpl(LdapStorage.java:621)

  at com.vmware.vim.lookup.impl.LdapStorage.applyServiceEntryFunction(LdapStorage.java:607)

  at com.vmware.vim.lookup.impl.LdapStorage.getServiceEntry(LdapStorage.java:835)

  at com.vmware.vim.lookup.impl.LdapStorage.access$1500(LdapStorage.java:70)

  at com.vmware.vim.lookup.impl.LdapStorage$6.action(LdapStorage.java:476)

  at com.vmware.vim.lookup.impl.LdapStorage$6.action(LdapStorage.java:473)

  at com.vmware.vim.lookup.impl.LdapStorage$LdapQuery.execute(LdapStorage.java:1959)

  at com.vmware.vim.lookup.impl.LdapStorage.get(LdapStorage.java:473)

  at com.vmware.vim.lookup.impl.ServiceRegistrationImpl.get(ServiceRegistrationImpl.java:54)

  at com.vmware.vim.lookup.vlsi.ServiceRegistrationImpl$1.call(ServiceRegistrationImpl.java:67)

  at com.vmware.vim.lookup.vlsi.ServiceRegistrationImpl$1.call(ServiceRegistrationImpl.java:61)

  at com.vmware.vim.lookup.vlsi.util.VmodlEnhancer.invokeVmodlMethod(VmodlEnhancer.java:68)

  at com.vmware.vim.lookup.vlsi.ServiceRegistrationImpl.create(ServiceRegistrationImpl.java:61)

  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

  at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

  at java.lang.reflect.Method.invoke(Unknown Source)

  at com.vmware.vim.vmomi.server.impl.InvocationTask.run(InvocationTask.java:66)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at java.lang.Thread.run(Unknown Source)

Remote PSC:

About a few weeks ago (when we were seeing the problem) I see these messages in ssoAdminServer.log:

[2016-05-05T20:54:21.810Z pool-12-thread-5 opId=1DC17333-00000148-55 INFO  com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl] [User {Name: vpxd-2978ba27-9059-4a9b-954e-e9a1494979b9, Domain: vsphere.local} with role 'ConfigurationUser'] Find at most 5000 principals by criteria searchString=, domain=root.sys

[2016-05-05T20:54:36.863Z pool-12-thread-5 opId=1DC17333-00000148-55 ERROR com.vmware.identity.admin.server.ims.impl.PrincipalManagementImpl] Idm client exception

com.vmware.identity.idm.IDMException

  at com.vmware.identity.idm.server.ServerUtils.getRemoteException(ServerUtils.java:136)

  at com.vmware.identity.idm.server.IdentityManager.find(IdentityManager.java:8883)

  at sun.reflect.GeneratedMethodAccessor25.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

  at java.lang.reflect.Method.invoke(Unknown Source)

  at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)

  at sun.rmi.transport.Transport$2.run(Unknown Source)

  at sun.rmi.transport.Transport$2.run(Unknown Source)

  at java.security.AccessController.doPrivileged(Native Method)

  at sun.rmi.transport.Transport.serviceCall(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.access$400(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(Unknown Source)

  at java.security.AccessController.doPrivileged(Native Method)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at java.lang.Thread.run(Unknown Source)

  at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(Unknown Source)

  at sun.rmi.transport.StreamRemoteCall.executeCall(Unknown Source)

  at sun.rmi.server.UnicastRef.invoke(Unknown Source)

  at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(Unknown Source)

  at java.rmi.server.RemoteObjectInvocationHandler.invoke(Unknown Source)

  at com.sun.proxy.$Proxy107.find(Unknown Source)

  at com.vmware.identity.idm.client.CasIdmClient.find(CasIdmClient.java:1779)

  at com.vmware.identity.admin.server.ims.impl.PrincipalManagementImpl.find(PrincipalManagementImpl.java:559)

  at com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl$13.call(PrincipalDiscoveryServiceImpl.java:390)

  at com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl$13.call(PrincipalDiscoveryServiceImpl.java:379)

  at com.vmware.identity.admin.vlsi.util.VmodlEnhancer.invokeVmodlMethod(VmodlEnhancer.java:161)

  at com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl.find(PrincipalDiscoveryServiceImpl.java:379)

  at sun.reflect.GeneratedMethodAccessor152.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

  at java.lang.reflect.Method.invoke(Unknown Source)

  at com.vmware.vim.vmomi.server.impl.InvocationTask.run(InvocationTask.java:66)

  at com.vmware.vim.vmomi.server.common.impl.RunnableWrapper$1.run(RunnableWrapper.java:48)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at java.lang.Thread.run(Unknown Source)

[2016-05-05T20:54:36.863Z pool-12-thread-5 opId=1DC17333-00000148-55 ERROR com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl] Idm client exception: null

com.vmware.identity.admin.server.ims.PrincipalManagementException: Idm client exception: null

  at com.vmware.identity.admin.server.ims.impl.PrincipalManagementImpl.logAndThrow(PrincipalManagementImpl.java:2728)

  at com.vmware.identity.admin.server.ims.impl.PrincipalManagementImpl.find(PrincipalManagementImpl.java:561)

  at com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl$13.call(PrincipalDiscoveryServiceImpl.java:390)

  at com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl$13.call(PrincipalDiscoveryServiceImpl.java:379)

  at com.vmware.identity.admin.vlsi.util.VmodlEnhancer.invokeVmodlMethod(VmodlEnhancer.java:161)

  at com.vmware.identity.admin.vlsi.PrincipalDiscoveryServiceImpl.find(PrincipalDiscoveryServiceImpl.java:379)

  at sun.reflect.GeneratedMethodAccessor152.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

  at java.lang.reflect.Method.invoke(Unknown Source)

  at com.vmware.vim.vmomi.server.impl.InvocationTask.run(InvocationTask.java:66)

  at com.vmware.vim.vmomi.server.common.impl.RunnableWrapper$1.run(RunnableWrapper.java:48)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at java.lang.Thread.run(Unknown Source)

Local PSC:

I also see the following messages in ssoAdminServer.log on the local PSC (few weeks ago, when we were seeing issues):

[2016-05-08T14:27:47.990Z pool-13-thread-4 opId=b4e18db3-88d9-49ba-bcda-1bf08774596c ERROR com.vmware.identity.vlsi.RoleBasedAuthorizer] Saml token structure error

com.vmware.vim.vmomi.server.exception.InvalidSignatureException: com.vmware.vim.sso.client.exception.InvalidTimingException: Token expiration date: Sat May 07 14:27:38 UTC 2016 is in the past.

  at com.vmware.vim.vmomi.server.security.impl.WsSecurityMessage.unmarshalAuthnToken(WsSecurityMessage.java:244)

  at com.vmware.vim.vmomi.server.security.impl.WsSecurityMessage.findAuthenticationInfo(WsSecurityMessage.java:213)

  at com.vmware.vim.vmomi.server.security.impl.RequestSignatureValidatorImpl.validateMessage(RequestSignatureValidatorImpl.java:57)

  at com.vmware.vim.vmomi.server.impl.ActivationImpl.findSamlToken(ActivationImpl.java:154)

  at com.vmware.identity.vlsi.RoleBasedAuthorizer.findTokenFromRequest(RoleBasedAuthorizer.java:188)

  at com.vmware.identity.vlsi.RoleBasedAuthorizer.authorize(RoleBasedAuthorizer.java:111)

  at com.vmware.vim.vmomi.server.PrivilegeChecker.validate(PrivilegeChecker.java:101)

  at com.vmware.vim.vmomi.server.impl.ValidationStartTask.run(ValidationStartTask.java:67)

  at com.vmware.vim.vmomi.server.common.impl.RunnableWrapper$1.run(RunnableWrapper.java:48)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at java.lang.Thread.run(Unknown Source)

Caused by: com.vmware.vim.sso.client.exception.InvalidTimingException: Token expiration date: Sat May 07 14:27:38 UTC 2016 is in the past.

  at com.vmware.identity.token.impl.SamlTokenImpl.validateWithinTokenLifePeriod(SamlTokenImpl.java:836)

  at com.vmware.identity.token.impl.SamlTokenImpl.validate(SamlTokenImpl.java:536)

  at com.vmware.vim.sso.client.DefaultTokenFactory.createTokenFromDom(DefaultTokenFactory.java:98)

  at com.vmware.vim.vmomi.server.security.impl.WsSecurityMessage.unmarshalAuthnToken(WsSecurityMessage.java:239)

  ... 11 more

[2016-05-09T21:03:27.525Z pool-17-thread-5 opId= ERROR com.vmware.vim.vmomi.server.impl.DispatcherImpl] Internal server error during dispatch

com.vmware.vim.vmomi.server.exception.ServiceUnavailableException: Failed to create session

  at com.vmware.vim.vmomi.server.impl.DispatcherImpl.dispatch(DispatcherImpl.java:301)

  at com.vmware.vim.vmomi.server.http.impl.CorrelationDispatcherTask.run(CorrelationDispatcherTask.java:58)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at java.lang.Thread.run(Unknown Source)

I see this in vmware-identity-sts.log around the same date on the local PSC:

[2016-05-10T13:51:48.602Z tomcat-http--1 vsphere.local        7842f926-4684-40ae-b400-6a3d54359402 TRACE com.vmware.identity.sts.auth.impl.UNTAuthenticator] Starting to authenticate principal: c_aferrar@root.sys

[2016-05-10T13:51:49.277Z tomcat-http--1 vsphere.local        7842f926-4684-40ae-b400-6a3d54359402 DEBUG com.vmware.identity.sts.InvalidCredentialsException] About to censor authentication failure

com.vmware.identity.sts.InvalidCredentialsException: IDM rejected authentication by UPN

  at com.vmware.identity.sts.auth.impl.UNTAuthenticator.authenticate(UNTAuthenticator.java:72)

  at com.vmware.identity.sts.auth.impl.CompositeAuthenticator.authenticate(CompositeAuthenticator.java:44)

  at com.vmware.identity.sts.auth.impl.CompositeAuthenticatorPerformanceDecorator$1.call(CompositeAuthenticatorPerformanceDecorator.java:54)

  at com.vmware.identity.sts.auth.impl.CompositeAuthenticatorPerformanceDecorator$1.call(CompositeAuthenticatorPerformanceDecorator.java:51)

  at com.vmware.identity.performanceSupport.PerformanceDecorator.exec(PerformanceDecorator.java:36)

  at com.vmware.identity.sts.auth.impl.CompositeAuthenticatorPerformanceDecorator.authenticate(CompositeAuthenticatorPerformanceDecorator.java:51)

  at com.vmware.identity.sts.impl.STSImpl.issue(STSImpl.java:127)

  at com.vmware.identity.sts.impl.MultiTenantSTSImpl.issue(MultiTenantSTSImpl.java:50)

  at com.vmware.identity.sts.impl.MultiTenantSTSImplPerformanceDecorator$2.call(MultiTenantSTSImplPerformanceDecorator.java:89)

  at com.vmware.identity.sts.impl.MultiTenantSTSImplPerformanceDecorator$2.call(MultiTenantSTSImplPerformanceDecorator.java:86)

  at com.vmware.identity.performanceSupport.PerformanceDecorator.exec(PerformanceDecorator.java:36)

  at com.vmware.identity.sts.impl.MultiTenantSTSImplPerformanceDecorator.issue(MultiTenantSTSImplPerformanceDecorator.java:86)

  at com.vmware.identity.sts.ws.StsServiceImpl.issue(StsServiceImpl.java:159)

  at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

  at java.lang.reflect.Method.invoke(Unknown Source)

  at com.sun.xml.ws.api.server.InstanceResolver$1.invoke(InstanceResolver.java:250)

  at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:150)

  at com.sun.xml.ws.server.sei.EndpointMethodHandler.invoke(EndpointMethodHandler.java:261)

  at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:100)

  at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:641)

  at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:600)

  at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:585)

  at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:482)

  at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:314)

  at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:608)

  at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:259)

  at com.sun.xml.ws.transport.http.servlet.ServletAdapter.invokeAsync(ServletAdapter.java:213)

  at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doGet(WSServletDelegate.java:159)

  at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doPost(WSServletDelegate.java:194)

  at com.sun.xml.ws.transport.http.servlet.WSServlet.doPost(WSServlet.java:80)

  at javax.servlet.http.HttpServlet.service(HttpServlet.java:646)

  at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

  at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

  at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)

  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)

  at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)

  at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)

  at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)

  at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)

  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)

  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)

  at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)

  at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)

  at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

  at java.lang.Thread.run(Unknown Source)

Caused by: com.vmware.identity.sts.idm.InvalidCredentialsException: com.vmware.identity.idm.IDMLoginException: Native platform error [code: -1765328378][null][null]

  at com.vmware.identity.sts.idm.impl.AuthenticatorImpl.authenticate(AuthenticatorImpl.java:79)

  at com.vmware.identity.sts.auth.impl.UNTAuthenticator.authenticate(UNTAuthenticator.java:64)

  ... 52 more

Caused by: com.vmware.identity.idm.IDMLoginException: Native platform error [code: -1765328378][null][null]

  at com.vmware.identity.idm.server.ServerUtils.getRemoteException(ServerUtils.java:102)

  at com.vmware.identity.idm.server.IdentityManager.authenticate(IdentityManager.java:8279)

  at sun.reflect.GeneratedMethodAccessor692.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

  at java.lang.reflect.Method.invoke(Unknown Source)

  at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)

  at sun.rmi.transport.Transport$2.run(Unknown Source)

  at sun.rmi.transport.Transport$2.run(Unknown Source)

  at java.security.AccessController.doPrivileged(Native Method)

  at sun.rmi.transport.Transport.serviceCall(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.access$400(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(Unknown Source)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(Unknown Source)

  at java.security.AccessController.doPrivileged(Native Method)

  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

  at java.lang.Thread.run(Unknown Source)

  at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(Unknown Source)

  at sun.rmi.transport.StreamRemoteCall.executeCall(Unknown Source)

  at sun.rmi.server.UnicastRef.invoke(Unknown Source)

  at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(Unknown Source)

  at java.rmi.server.RemoteObjectInvocationHandler.invoke(Unknown Source)

  at com.sun.proxy.$Proxy109.authenticate(Unknown Source)

  at com.vmware.identity.idm.client.CasIdmClient.authenticate(CasIdmClient.java:1035)

  at com.vmware.identity.sts.idm.impl.AuthenticatorImpl.authenticate(AuthenticatorImpl.java:69)

  ... 53 more

Is any of this helpful?  I'm not sure where to go from here.  Also not sure why we can login to both vCenters just fine using LDAP.  Thanks again, cheers

[vesuvius_prime]

>Thanks again, cheers

  I'll be glad if I can help solve this.

I think that the most important problems are the ones in ssoAdminServer.log on the Remote and the Local PSC. Let me ask around to see if somebody can figure out what these errors might indicate. (I myself am not very knowledgeable in the SSO internals.)

[vesuvius_prime]

Some preliminary information about the native platform error from ssoAdminServer.log on the local PSC:

Code -1765328378 corresponds to 96C73A06 in hex. Here's the description of this Kerberos error code:

96C73A06  Client principal is not found in security registry.

Explanation:

The client principal in a Kerberos request was not found in the registry database.

User response:

Add the client principal to the registry database and then retry the request.

I'm not sure if this will help you, but I'm posting it just in case. I'm awaiting a response to an email I wrote about this issue. Then I may have some more useful info. Or maybe somebody else will take over from here. We'll see...

[vesuvius_prime]

Hi again. Are you willing to file an SR for this issue? The SSO guys are willing to look into this but they will need a SR and a support bundle with all the logs.

[mikemayors]

Sure, what is an SR? Is this the same as a VMware developer support case? (Developer Center Partner Network)

[vesuvius_prime]

I believe they meant a Service Request to the Global Support Services (GSS). I don't know if the following is useful: http://www.vmware.com/files/pdf/support/VMware-Support-GSS-BR-EN.pdf. I googled for it.    I will also get additional info and will let you know.

[thomsonac]

I hope you can help.  I've spent an inordinate amount of timing trying to track down sporadic permission issues that occur with AD logins.  This is the only post I could find through google with this error code, Native platform error [code: -1765328378], and the symptoms appear to be identical to ours.

We have an SR but the first level engineer hasn't been the most helpful.  SR16298659111