Document and improve PSC register errors

[andrewtchin]

A user had these errors:

Feb 13 12:03:58 Photon start_fileserver.sh[830]: 03:57 UTC 2018]; root of context hierarchy]\n[10][I][2018-02-13T12:03:57.803Z][1][VmodlContextImpl][loadVmodlPackage][Package com.vmware.vim.binding.vmodl loaded in 17 millis]\n[11][I][2018-02-13T12:03:57.              803Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][prepareRefresh][Refreshing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@68567e20: startup date [Tue Feb 13 12:03:57 UTC 2018]; root of          context hierarchy]\n[12][I][2018-02-13T12:03:57.804Z][1][XmlBeanDefinitionReader][loadBeanDefinitions][Loading XML bean definitions from class path resource [com/vmware/vim/binding/sso/context.xml]]\n[13][I][2018-02-13T12:03:57.                                        953Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][doClose][Closing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@68567e20: startup date [Tue Feb 13 12:03:57 UTC 2018]; root of context            hierarchy]\n[14][I][2018-02-13T12:03:57.953Z][1][VmodlContextImpl][loadVmodlPackage][Package com.vmware.vim.binding.sso loaded in 149 millis]\n[15][W][2018-02-13T12:03:58.069Z][1][SiteAffinityServerEndpointProvider][logWarning][CDC not configured java.lang.           NoClassDefFoundError: com/vmware/identity/cdc/CdcFactory]\nException in thread \"main\" com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminClientException: General SSO failure. Invalid host, port or tenant.\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.          admin.SsoAdminClientFactoryImpl.createSSOAdminClient(SsoAdminClientFactoryImpl.java:148)\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminFacade.registerOrRetrieveSolutionUser(SsoAdminFacade.java:172)\n\tat com.vmware.admiral.auth.idm.psc.saml.util.       SsoPscCommand.register(SsoPscCommand.java:83)\n\tat com.vmware.admiral.auth.idm.psc.util.PscCommand.execute(PscCommand.java:37)\n\tat com.vmware.admiral.auth.idm.psc.util.PscCommand.main(PscCommand.java:47)\nCaused by: com.vmware.vim.sso.admin.exception.              InternalError: General failure.\n\tat com.vmware.vim.sso.admin.client
Feb 13 12:03:58 Photon start_fileserver.sh[830]: .vmomi.impl.VmomiClientCommand.execute(VmomiClientCommand.java:211)\n\tat com.vmware.vim.sso.admin.client.vmomi.impl.VmomiClientCommand.executeEnsuringNoDomainError(VmomiClientCommand.java:217)\n\tat com.vmware.        vim.sso.admin.client.vmomi.impl.AdminClientImpl.createServiceContent(AdminClientImpl.java:334)\n\tat com.vmware.vim.sso.admin.client.vmomi.impl.AdminClientImpl.<init>(AdminClientImpl.java:107)\n\tat com.vmware.vim.sso.admin.client.vmomi.VmomiClientFactory.            createAdminClient(VmomiClientFactory.java:64)\n\tat com.vmware.vim.sso.admin.client.vmomi.VmomiClientFactory.createAdminClient(VmomiClientFactory.java:54)\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminClientFactoryImpl.                                  createSSOAdminClient(SsoAdminClientFactoryImpl.java:123)\n\t... 4 more\nCaused by: com.vmware.vim.vmomi.client.common.UnexpectedStatusCodeException: Unexpected status code: 404\n\tat com.vmware.vim.vmomi.client.common.Response$Status.getStatus(Response.java:          58)\n\tat com.vmware.vim.vmomi.client.http.impl.HttpExchangeBase.parseResponse(HttpExchangeBase.java:150)\n\tat com.vmware.vim.vmomi.client.http.impl.HttpExchange.run(HttpExchange.java:48)\n\tat com.vmware.vim.vmomi.client.http.impl.HttpProtocolBindingBase.           executeRunnable(HttpProtocolBindingBase.java:226)\n\tat com.vmware.vim.vmomi.client.http.impl.HttpProtocolBindingImpl.send(HttpProtocolBindingImpl.java:109)\n\tat com.vmware.vim.vmomi.client.common.impl.MethodInvocationHandlerImpl$CallExecutor.                        sendCall(MethodInvocationHandlerImpl.java:581)\n\tat com.vmware.vim.vmomi.client.common.impl.MethodInvocationHandlerImpl$CallExecutor.executeCall(MethodInvocationHandlerImpl.java:562)\n\tat com.vmware.vim.vmomi.client.common.impl.MethodInvocationHandlerImpl.          completeCall(MethodInvocationHandlerImpl.java:344)\n\tat com.vmware.vim.vmomi.client.common.impl.MethodInvocationHandlerImpl.invokeOperation(MethodInvocationHandlerImpl.java:304)\n\tat com.vmware.vim.vmomi.client.common.impl.MethodInvocationHandlerImpl.               invoke(MethodInvocationHandlerImpl.java:178)\n\tat com.sun.proxy.$Proxy25.ret
Feb 13 12:03:58 Photon start_fileserver.sh[830]: rieveServiceContent(Unknown Source)\n\tat com.vmware.vim.sso.admin.client.vmomi.impl.AdminClientImpl$1.actionCommand(AdminClientImpl.java:339)\n\tat com.vmware.vim.sso.admin.client.vmomi.impl.AdminClientImpl$1.         actionCommand(AdminClientImpl.java:334)\n\tat com.vmware.vim.sso.admin.client.vmomi.impl.VmomiClientCommand.execute(VmomiClientCommand.java:103)\n\t... 10 more\n"
Feb 13 12:03:58 Photon start_fileserver.sh[830]: time="2018-02-13T12:03:58Z" level=debug msg="exit status 1"

 332 Feb 13 13:29:02 vcapp01-container start_fileserver.sh[770]: time="2018-02-13T13:29:02Z" level=info msg="Error running PSC register command for harbor: [0][I][2018-02-13T13:29:01.027Z][1][SsoPscCommand][register][Initializing...]\n[1][I][2018-02-13T13:29:01.           034Z][1][SsoPscCommand][register][Registering...]\n[2][I][2018-02-13T13:29:01.056Z][1][SsoPscCommand][deleteFile][Removal of file: '/etc/vmware/psc/harbor/psc-config.keystore' result: true]\n[3][I][2018-02-13T13:29:01.                                                  647Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][prepareRefresh][Refreshing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@27a8c74e: startup date [Tue Feb 13 13:29:01 UTC 2018]; root of          context hierarchy]\n[4][I][2018-02-13T13:29:01.676Z][1][XmlBeanDefinitionReader][loadBeanDefinitions][Loading XML bean definitions from class path resource [com/vmware/vim/binding/vmodl/context_v2.xml]]\n[5][I][2018-02-13T13:29:01.                                     865Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][doClose][Closing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@27a8c74e: startup date [Tue Feb 13 13:29:01 UTC 2018]; root of context            hierarchy]\n[6][I][2018-02-13T13:29:01.867Z][1][VmodlContextImpl][loadVmodlPackage][Package com.vmware.vim.binding.vmodl loaded in 235 millis]\n[7][I][2018-02-13T13:29:01.                                                                                                 867Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][prepareRefresh][Refreshing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@3c0be339: startup date [Tue Feb 13 13:29:01 UTC 2018]; root of          context hierarchy]\n[8][I][2018-02-13T13:29:01.868Z][1][XmlBeanDefinitionReader][loadBeanDefinitions][Loading XML bean definitions from class path resource [com/vmware/vim/binding/vmodl/context_v2.xml]]\n[9][I][2018-02-13T13:29:01.                                     886Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][doClose][Closing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@3c0be339: startup date [Tue Feb 13 13:2
 333 Feb 13 13:29:02 vcapp01-container start_fileserver.sh[770]: 9:01 UTC 2018]; root of context hierarchy]\n[10][I][2018-02-13T13:29:01.886Z][1][VmodlContextImpl][loadVmodlPackage][Package com.vmware.vim.binding.vmodl loaded in 18 millis]\n[11][I][2018-02-13T13:29:       01.887Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][prepareRefresh][Refreshing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@68567e20: startup date [Tue Feb 13 13:29:01 UTC 2018]; root of       context hierarchy]\n[12][I][2018-02-13T13:29:01.887Z][1][XmlBeanDefinitionReader][loadBeanDefinitions][Loading XML bean definitions from class path resource [com/vmware/vim/binding/sso/context.xml]]\n[13][I][2018-02-13T13:29:02.                                        010Z][1][VmodlContextImpl$NonValidatingClassPathXmlApplicationContext][doClose][Closing com.vmware.vim.vmomi.core.types.impl.VmodlContextImpl$NonValidatingClassPathXmlApplicationContext@68567e20: startup date [Tue Feb 13 13:29:01 UTC 2018]; root of context            hierarchy]\n[14][I][2018-02-13T13:29:02.010Z][1][VmodlContextImpl][loadVmodlPackage][Package com.vmware.vim.binding.sso loaded in 123 millis]\n[15][W][2018-02-13T13:29:02.082Z][1][SiteAffinityServerEndpointProvider][logWarning][CDC not configured java.lang.           NoClassDefFoundError: com/vmware/identity/cdc/CdcFactory]\n[16][W][2018-02-13T13:29:02.222Z][1][SiteAffinityServerEndpointProvider][logWarning][CDC not configured java.lang.NoClassDefFoundError: com/vmware/identity/cdc/CdcFactory]\n[17][I][2018-02-13T13:29:02.        248Z][1][AdminClientImpl][<init>][Client was created successfully]\n[18][W][2018-02-13T13:29:02.248Z][1][SiteAffinityServerEndpointProvider][logWarning][CDC not configured java.lang.NoClassDefFoundError: com/vmware/identity/cdc/CdcFactory]\n[main] WARN com.           vmware.vim.sso.client.impl.SoapBindingImpl - Could not load VECS keystore: java.security.KeyStoreException: VKS not found\n[main] INFO com.vmware.identity.token.impl.Util - Reading resources from zip file path=[/etc/vmware/admiral/admiral-auth-psc-1.2.0-SNAPSHOT-     command.jar] \n[main] INFO com.vmware.identity.token.impl.Util
 334 Feb 13 13:29:02 vcapp01-container start_fileserver.sh[770]: - Reading resources from decoded zip file path=[/etc/vmware/admiral/admiral-auth-psc-1.2.0-SNAPSHOT-command.jar] \n[main] WARN com.vmware.vim.sso.client.impl.SiteAffinityServiceDiscovery - CDC not            configured java.lang.NoClassDefFoundError: com/vmware/identity/cdc/CdcFactory\n[main] ERROR com.vmware.vim.sso.client.impl.SoapBindingImpl - SOAP fault\ncom.sun.xml.internal.ws.fault.ServerSOAPFaultException: Client received SOAP Fault from server: The time now       Tue Feb 13 22:18:39 UTC 2018 does not fall in the request lifetime interval extended with clock tolerance of 600000 ms: [ Tue Feb 13 13:19:02 UTC 2018; Tue Feb 13 13:49:02 UTC 2018). This might be due to a clock skew problem. Please see the server log to find         more detail regarding exact cause of the failure.\n\tat com.sun.xml.internal.ws.fault.SOAP11Fault.getProtocolException(SOAP11Fault.java:178)\n\tat com.sun.xml.internal.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:116)\n\tat com.sun.xml.             internal.ws.client.dispatch.DispatchImpl.doInvoke(DispatchImpl.java:259)\n\tat com.sun.xml.internal.ws.client.dispatch.DispatchImpl.invoke(DispatchImpl.java:289)\n\tat com.vmware.vim.sso.client.impl.SoapBindingImpl.sendMessage(SoapBindingImpl.java:161)\n\tat com.     vmware.vim.sso.client.impl.SoapBindingImpl.sendMessage(SoapBindingImpl.java:114)\n\tat com.vmware.vim.sso.client.impl.SecurityTokenServiceImpl$RequestResponseProcessor.sendRequest(SecurityTokenServiceImpl.java:927)\n\tat com.vmware.vim.sso.client.impl.                SecurityTokenServiceImpl$RequestResponseProcessor.executeRoundtrip(SecurityTokenServiceImpl.java:857)\n\tat com.vmware.vim.sso.client.impl.SecurityTokenServiceImpl.acquireToken(SecurityTokenServiceImpl.java:140)\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.         admin.SsoAdminClientFactoryImpl.createSSOAdminClient(SsoAdminClientFactoryImpl.java:140)\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminFacade.registerOrRetrieveSolutionUser(SsoAdminFacade.java:172)\n\tat com.vmware.admiral.auth.idm.psc.saml.util.       SsoPscCommand.register(SsoPscCommand.ja
 335 Feb 13 13:29:02 vcapp01-container start_fileserver.sh[770]: va:83)\n\tat com.vmware.admiral.auth.idm.psc.util.PscCommand.execute(PscCommand.java:37)\n\tat com.vmware.admiral.auth.idm.psc.util.PscCommand.main(PscCommand.java:47)\n[main] INFO com.vmware.vim.sso.        client.impl.SecurityTokenServiceImpl$RequestResponseProcessor - Request message has expired. Server message: ns0:MessageExpired: The time now Tue Feb 13 22:18:39 UTC 2018 does not fall in the request lifetime interval extended with clock tolerance of 600000 ms:       [ Tue Feb 13 13:19:02 UTC 2018; Tue Feb 13 13:49:02 UTC 2018). This might be due to a clock skew problem.\n[main] INFO com.vmware.vim.sso.client.impl.SecurityTokenServiceImpl$RequestResponseProcessor - Server returned 'request expired' less than 0 seconds after       request was issued, but it shouldn't have expired for at least 600 seconds.\nException in thread \"main\" com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminClientException: Server returned 'request expired' less than 0 seconds after request was issued, but       it shouldn't have expired for at least 600 seconds.\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminClientFactoryImpl.createSSOAdminClient(SsoAdminClientFactoryImpl.java:156)\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminFacade.            registerOrRetrieveSolutionUser(SsoAdminFacade.java:172)\n\tat com.vmware.admiral.auth.idm.psc.saml.util.SsoPscCommand.register(SsoPscCommand.java:83)\n\tat com.vmware.admiral.auth.idm.psc.util.PscCommand.execute(PscCommand.java:37)\n\tat com.vmware.admiral.auth.      idm.psc.util.PscCommand.main(PscCommand.java:47)\nCaused by: com.vmware.vim.sso.client.exception.TimeSynchronizationException: Server returned 'request expired' less than 0 seconds after request was issued, but it shouldn't have expired for at least 600 seconds.      \n\tat com.vmware.vim.sso.client.impl.SecurityTokenServiceImpl$RequestResponseProcessor.checkTimeSyncronization(SecurityTokenServiceImpl.java:901)\n\tat com.vmware.vim.sso.client.impl.SecurityTokenServiceImpl$RequestResponseProcessor.                                  executeRoundtrip(SecurityTokenServiceImpl.java:8
 336 Feb 13 13:29:02 vcapp01-container start_fileserver.sh[770]: 59)\n\tat com.vmware.vim.sso.client.impl.SecurityTokenServiceImpl.acquireToken(SecurityTokenServiceImpl.java:140)\n\tat com.vmware.admiral.auth.idm.psc.saml.sso.admin.SsoAdminClientFactoryImpl.               createSSOAdminClient(SsoAdminClientFactoryImpl.java:140)\n\t... 4 more\n"
 337 Feb 13 13:29:02 vcapp01-container start_fileserver.sh[770]: time="2018-02-13T13:29:02Z" level=debug msg="exit status 1"

Based on the wiki https://github.com/vmware/admiral/wiki/Troubleshooting-VIC#1-psc-registration-errors-during-the-setup the parameters are incorrect, but the issue was resolved when the user entered proper DNS settings to the VIC appliance.

To improve error messages and user experience, could we please do the following:

• Document all possible failures that can occur when running the PSC jar
• Improve logging of the PSC jar to output user readable error messages after the stacktrace
• Have the PSC jar return different return code for each error so that the VIC appliance can provide better error messages in case of PSC registration failure
• Document PSC jar return codes and the associated user facing error message this can be put in https://github.com/vmware/vic-product/tree/master/installer/docs/integration