3 Replies Latest reply on Mar 18, 2014 5:45 PM by Julio Tapia

    Cannot create cluster VSA

    Viatori Lurker

      ERROR - Customize VM on host host-123 failed
      java.lang.Exception: Client side time out waiting for task to comeplete
      I cant understand that error

      config without Vlan. the hardware is 100% compatible.

       

       

      VSA Manager.log

       

      2012-12-11 06:07:17,718 85 [IphlpManager] [pool-3-thread-1] INFO  - Found adapter for IP address: 192.168.2.210
      name = Подключение по локальной сети
        netmask = 255.255.255.0
        gateway=192.168.2.254
      2012-12-11 06:07:17,765 43 [SimplePBEStringEncryptor] [pool-3-thread-1] INFO  - Retrived encryption data from VC registry key
      2012-12-11 06:07:17,780 116 [KeystoreX509TrustManager] [pool-3-thread-1] INFO  - Loading from trust store: C:/ProgramData/VMware/VSA Manager/security/keystore.jks
      2012-12-11 06:07:20,791 162 [DbUpgrade] [pool-3-thread-1] INFO  - Checking vsaDB consistency
      2012-12-11 06:07:20,900 150 [DbUpgrade] [pool-3-thread-1] INFO  - Backing up vsaDB
      2012-12-11 06:07:22,398 57 [ExtService] [pool-3-thread-1] INFO  - Login to VC
      2012-12-11 06:07:24,816 105 [KeyStoreConfig] [Timeout guard] INFO  - loading keystore from classpath: rui.pfx
      2012-12-11 06:07:24,816 111 [KeyStoreConfig] [Timeout guard] INFO  - keystore is loaded.
      2012-12-11 06:07:24,831 97 [CustomSslSocketFactory] [Timeout guard] INFO  - SSL Socket factory initialized
      2012-12-11 06:07:25,549 41 [SanityServices] [pool-3-thread-1] INFO  - Starting license enforcement
      2012-12-11 06:07:25,565 63 [SanityServices] [pool-3-thread-1] INFO  - Start monitoring VSAManager.log at Ср 2012.12.12 at 02:00:00 AM GMT+04:00
      2012-12-11 06:07:26,064 96 [SessionService] [pool-3-thread-1] INFO  - Finished initializing all context tasks
      2012-12-11 06:07:26,189 119 [SvaLicenseManager] [LicenseManager-1] INFO  - Changing license assignment manager to FEATURE
      2012-12-11 06:07:26,345 145 [SvaLicenseManager] [LicenseManager-1] INFO  - Days before license expiration :: 59
      2012-12-11 06:07:26,345 85 [SvaLicenseManager] [LicenseManager-1] INFO  - License verified and found satisfactory
      2012-12-11 06:07:26,594 235 [Utils] [pool-3-thread-1] INFO  - Retrieve dev.property: test.on=false
      2012-12-11 06:12:25,846 1479 [ClusterService] [SanityService-3] INFO  - No Hosts have been added/removed since: 12-12-11 04:35:32
      2012-12-11 06:13:25,565 363 [ExtManager] [tomcat-http--40] INFO  - /sva-scriptConfig.xml : <?xml version="1.0"?>
      <scriptConfiguration version="1.0">
      <key>com.vmware.sva</key>
      <description>VSA Manager</description>
      <extension parent="InventoryView.Datacenter">
         <title locale="en">VSA Manager</title>
         <url>https://192.168.2.210:443/VSAManager/SVAUI/SVA.jsp</url>
      </extension>
      <extension parent="MainMenus.Help">
         <title locale="en">VSA Manager Help</title>
         <url>https://192.168.2.210:443/VSAManager/SVAUI/help/en_US/index.html</url>
      </extension>
      </scriptConfiguration>

      2012-12-11 06:13:47,594 83 [SVAManager] [tomcat-http--25] INFO  - Requesting creation of a user session from http session context
      2012-12-11 06:13:47,604 113 [UserSession] [tomcat-http--25] INFO  - Http session ID is C68F860B15A1635F3B95FD895A49E116
      2012-12-11 06:13:47,604 117 [UserSession] [tomcat-http--25] INFO  - vc Session ID 522b9a15-384c-d397-6aaf-cf80efbaead0
      2012-12-11 06:13:47,604 118 [UserSession] [tomcat-http--25] INFO  - Datacenter moref is Datacenter:datacenter-21
      2012-12-11 06:13:47,604 130 [UserSession] [tomcat-http--25] INFO  - Starting to enumerate values for FlexSession
      2012-12-11 06:13:47,604 139 [UserSession] [tomcat-http--25] ERROR - Unable to display value for attribute__flexSession
      2012-12-11 06:13:47,604 136 [UserSession] [tomcat-http--25] INFO  - Attribute Name extensionMoref--Attribute Value: Datacenter:datacenter-21
      2012-12-11 06:13:47,604 136 [UserSession] [tomcat-http--25] INFO  - Attribute Name vcSessionId--Attribute Value: 522b9a15-384c-d397-6aaf-cf80efbaead0
      2012-12-11 06:13:47,614 177 [UserSession] [tomcat-http--25] INFO  - Creating a User session using sessionId 522b9a15-384c-d397-6aaf-cf80efbaead0
      2012-12-11 06:13:47,624 107 [VCUserSession] [tomcat-http--25] INFO  - Creating a VC User session using sessionId 522b9a15-384c-d397-6aaf-cf80efbaead0
      2012-12-11 06:13:49,164 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:49,344 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:49,344 124 [MappingService] [tomcat-http--20] INFO  - Context for datacenter datacenter-21 has not been set up yet.
      2012-12-11 06:13:49,354 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:49,514 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:49,594 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:49,754 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:49,754 124 [MappingService] [tomcat-http--20] INFO  - Context for datacenter datacenter-21 has not been set up yet.
      2012-12-11 06:13:49,904 196 [UserSession] [tomcat-http--25] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:50,124 196 [UserSession] [tomcat-http--25] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:50,164 124 [MappingService] [tomcat-http--25] INFO  - Context for datacenter datacenter-21 has not been set up yet.
      2012-12-11 06:13:50,774 196 [UserSession] [tomcat-http--39] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:50,854 196 [UserSession] [tomcat-http--25] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:50,944 196 [UserSession] [tomcat-http--39] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:50,944 124 [MappingService] [tomcat-http--39] INFO  - Context for datacenter datacenter-21 has not been set up yet.
      2012-12-11 06:13:50,944 196 [UserSession] [tomcat-http--39] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:51,074 235 [Utils] [tomcat-http--25] INFO  - Retrieve dev.property: host.audit=false
      2012-12-11 06:13:51,134 196 [UserSession] [tomcat-http--39] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:51,144 196 [UserSession] [tomcat-http--39] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:51,324 196 [UserSession] [tomcat-http--39] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:51,324 124 [MappingService] [tomcat-http--39] INFO  - Context for datacenter datacenter-21 has not been set up yet.
      2012-12-11 06:13:51,424 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:51,444 235 [Utils] [tomcat-http--25] INFO  - Retrieve dev.property: evc.config=false
      2012-12-11 06:13:51,554 235 [Utils] [tomcat-http--25] INFO  - Retrieve dev.property: ovf.local=true
      2012-12-11 06:13:51,554 235 [Utils] [tomcat-http--25] INFO  - Retrieve dev.property: ovf.relative.path=/ovf/sva_OVF10.ovf
      2012-12-11 06:13:51,554 721 [Utils] [tomcat-http--25] INFO  - Retrieved default ovf url: file:///C:/Program Files/VMware/Infrastructure/tomcat/webapps/VSAManager/ovf/sva_OVF10.ovf
      2012-12-11 06:13:51,584 196 [UserSession] [tomcat-http--20] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:13:51,614 124 [MappingService] [tomcat-http--20] INFO  - Context for datacenter datacenter-21 has not been set up yet.
      2012-12-11 06:13:51,984 200 [OvfData] [tomcat-http--25] INFO  - Default disk size 1000 MB
      2012-12-11 06:13:52,104 213 [OvfData] [tomcat-http--25] INFO  - Total system disk size 9216 MB
      2012-12-11 06:13:52,104 216 [OvfData] [tomcat-http--25] INFO  - Total initial reserved disk size 22528 MB
      2012-12-11 06:13:52,924 474 [VCUserSession] [tomcat-http--25] INFO  - Host Info retrieved - HostDao [refMorID=host-126, name=192.168.2.201, processorTypes=[intel, intel], statusDetails=Status is ONLINE, auditPassed=false, auditReport=null, isHCL=false, netmask=255.255.255.0, gateway=192.168.2.254, subnet=192.168.2.0, totalCapacityInBytes=3994319585280, freeCapacityInBytes=3993282543616, usedCapacityInBytes=1037041664, usedOtherCapacityInBytes=14995685376, totalVsaCapacityInBytes=3979323899904, freeVsaCapacityInBytes=3979323899904, usedVsaCapacityInBytes=0, minVsaCapacityInBytes=18253611008, reservedVsaCapacityInBytes=13958643712, status=ONLINE, group=UNSUPPORTED, vsaHost=false, hostAgentApiVersion=5.1, hostAgentVersion=5.1.0]
      2012-12-11 06:13:52,974 235 [Utils] [tomcat-http--25] INFO  - Retrieve dev.property: evc.config=false
      2012-12-11 06:13:53,024 235 [Utils] [tomcat-http--25] INFO  - Retrieve dev.property: ovf.local=true
      2012-12-11 06:13:53,024 235 [Utils] [tomcat-http--25] INFO  - Retrieve dev.property: ovf.relative.path=/ovf/sva_OVF10.ovf
      2012-12-11 06:13:53,024 721 [Utils] [tomcat-http--25] INFO  - Retrieved default ovf url: file:///C:/Program Files/VMware/Infrastructure/tomcat/webapps/VSAManager/ovf/sva_OVF10.ovf
      2012-12-11 06:13:53,104 200 [OvfData] [tomcat-http--25] INFO  - Default disk size 1000 MB
      2012-12-11 06:13:53,184 213 [OvfData] [tomcat-http--25] INFO  - Total system disk size 9216 MB
      2012-12-11 06:13:53,184 216 [OvfData] [tomcat-http--25] INFO  - Total initial reserved disk size 22528 MB
      2012-12-11 06:13:53,414 474 [VCUserSession] [tomcat-http--25] INFO  - Host Info retrieved - HostDao [refMorID=host-123, name=192.168.2.200, processorTypes=[intel, intel], statusDetails=Status is ONLINE, auditPassed=false, auditReport=null, isHCL=false, netmask=255.255.255.0, gateway=192.168.2.254, subnet=192.168.2.0, totalCapacityInBytes=3994319585280, freeCapacityInBytes=3993282543616, usedCapacityInBytes=1037041664, usedOtherCapacityInBytes=14995685376, totalVsaCapacityInBytes=3979323899904, freeVsaCapacityInBytes=3979323899904, usedVsaCapacityInBytes=0, minVsaCapacityInBytes=18253611008, reservedVsaCapacityInBytes=13958643712, status=ONLINE, group=UNSUPPORTED, vsaHost=false, hostAgentApiVersion=5.1, hostAgentVersion=5.1.0]
      2012-12-11 06:13:53,614 85 [IphlpManager] [tomcat-http--25] INFO  - Found adapter for IP address: 192.168.2.210
      name = Подключение по локальной сети
        netmask = 255.255.255.0
        gateway=192.168.2.254
      2012-12-11 06:14:17,331 126 [SVAManager] [tomcat-http--20] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:14:47,381 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:15:17,401 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:15:47,421 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:16:17,421 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:16:47,481 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:17:17,481 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:17:25,634 76 [CheckVSAHostUpgradedTask] [SanityService-5] INFO  - VSA Clusters successfully checked for memory-overcommitment options
      2012-12-11 06:17:25,894 1479 [ClusterService] [SanityService-1] INFO  - No Hosts have been added/removed since: 12-12-11 04:35:32
      2012-12-11 06:17:47,513 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:18:17,553 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:18:47,583 126 [SVAManager] [tomcat-http--25] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:19:17,618 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:19:47,638 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:20:17,672 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:20:47,672 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:21:17,672 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:21:47,726 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:22:17,753 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:22:25,943 1479 [ClusterService] [SanityService-1] INFO  - No Hosts have been added/removed since: 12-12-11 04:35:32
      2012-12-11 06:22:47,843 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:23:18,173 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:23:35,193 196 [UserSession] [tomcat-http--40] INFO  - **** extenMoref **** Datacenter:datacenter-21
      2012-12-11 06:23:35,363 235 [Utils] [tomcat-http--40] INFO  - Retrieve dev.property: ovf.local=true
      2012-12-11 06:23:35,363 235 [Utils] [tomcat-http--40] INFO  - Retrieve dev.property: ovf.relative.path=/ovf/sva_OVF10.ovf
      2012-12-11 06:23:35,363 721 [Utils] [tomcat-http--40] INFO  - Retrieved default ovf url: file:///C:/Program Files/VMware/Infrastructure/tomcat/webapps/VSAManager/ovf/sva_OVF10.ovf
      2012-12-11 06:23:35,383 235 [Utils] [tomcat-http--40] INFO  - Retrieve dev.property: vm.rollback=true
      2012-12-11 06:23:35,513 45 [DefaultJobRunner] [pool-109-thread-1] INFO  - Starting job. JobName:ClusterCreation-datacenter-21
      2012-12-11 06:23:35,523 58 [DefaultJobRunner] [pool-109-thread-1] INFO  - Starting Task group. TaskGroupName:ClusterCreation-PreHostReboot
      2012-12-11 06:23:35,553 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:TaskInitCreateCluster
      2012-12-11 06:23:35,553 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:TaskInitCreateCluster
      2012-12-11 06:23:36,123 353 [Utils] [pool-109-thread-1] INFO  - Persisting host: host-126
      2012-12-11 06:23:36,213 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-Back End @ hostmoref: host-126
      2012-12-11 06:23:36,233 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-Front End @ hostmoref: host-126
      2012-12-11 06:23:36,243 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-NFS @ hostmoref: host-126
      2012-12-11 06:23:36,253 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-VMotion @ hostmoref: host-126
      2012-12-11 06:23:36,323 353 [Utils] [pool-109-thread-1] INFO  - Persisting host: host-123
      2012-12-11 06:23:36,333 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-Back End @ hostmoref: host-123
      2012-12-11 06:23:36,343 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-Front End @ hostmoref: host-123
      2012-12-11 06:23:36,373 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-NFS @ hostmoref: host-123
      2012-12-11 06:23:36,383 361 [Utils] [pool-109-thread-1] INFO  - Persisting svaNetwork: VSA-VMotion @ hostmoref: host-123
      2012-12-11 06:23:36,413 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:TaskInitCreateCluster
      2012-12-11 06:23:36,413 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:TaskInitCreateCluster
      2012-12-11 06:23:36,413 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:LogParams
      2012-12-11 06:23:36,413 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:LogParams
      2012-12-11 06:23:36,413 101 [TaskLogClusterCreationParams] [pool-109-thread-1] INFO  - Dump VSA Cluster Configuration

      VSA Management Network Settings
                   IP Address        Netmask           Gateway/Interface  
      Cluster   : 192.168.2.212     255.255.255.0     192.168.2.254      
      VSAManager Service: 192.168.2.210     255.255.255.0     Подключение по локальной сети


      VSA VM Network Settings :  host-126
                   IP Address        Netmask           Gateway           Vlan ID
      Management: 192.168.2.215     255.255.255.0     192.168.2.254     0      
      NFS       : 192.168.2.216     255.255.255.0     192.168.2.254     0      
      Backend   : 192.168.10.2      255.255.255.0     -                 0      
      Feature   : 192.168.2.218     255.255.255.0     192.168.2.254     0     

      VSA VM Network Settings :  host-123
                   IP Address        Netmask           Gateway           Vlan ID
      Management: 192.168.2.213     255.255.255.0     192.168.2.254     0      
      NFS       : 192.168.2.214     255.255.255.0     192.168.2.254     0      
      Backend   : 192.168.10.1      255.255.255.0     -                 0      
      Feature   : 192.168.2.217     255.255.255.0     192.168.2.254     0     

      OVF Location: file:///C:/Program Files/VMware/Infrastructure/tomcat/webapps/VSAManager/ovf/sva_OVF10.ovf
      Eager Zero  : false

      2012-12-11 06:23:36,413 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:LogParams
      2012-12-11 06:23:36,413 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:LogParams
      2012-12-11 06:23:36,413 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:ClusterExists
      2012-12-11 06:23:36,413 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:ClusterExists
      2012-12-11 06:23:36,463 427 [SessionService] [pool-109-thread-1] INFO  - Cluster create in progress for DC: datacenter-21
      2012-12-11 06:23:36,463 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:ClusterExists
      2012-12-11 06:23:36,463 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:ClusterExists
      2012-12-11 06:23:36,463 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:AuditHostGroup
      2012-12-11 06:23:36,463 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:AuditHostGroup
      2012-12-11 06:23:38,543 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: evc.config=false
      2012-12-11 06:23:38,543 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:AuditHostGroup
      2012-12-11 06:23:38,543 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:AuditHostGroup
      2012-12-11 06:23:38,543 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:NetworkConfigValidation
      2012-12-11 06:23:38,543 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:NetworkConfigValidation
      2012-12-11 06:23:45,533 414 [NetworkConfigValidator] [pool-109-thread-1] INFO  - Cluster's subnet is 192.168.2.0. Gateway is 192.168.2.254
      2012-12-11 06:23:45,543 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:NetworkConfigValidation
      2012-12-11 06:23:45,543 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:NetworkConfigValidation
      2012-12-11 06:23:45,543 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:Audit2N-LV
      2012-12-11 06:23:45,543 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:Audit2N-LV
      2012-12-11 06:23:45,633 53 [MessagingService] [pool-109-thread-1] INFO  - Axis2 attachement temp dir is C:\Program Files\VMware\Infrastructure\tomcat\temp
      2012-12-11 06:23:45,643 72 [MessagingService] [pool-109-thread-1] INFO  - Using server endpoint for PSVA: https://192.168.2.210:4336/services/pseudosvaservice
      2012-12-11 06:23:46,843 115 [PseudoSVAConfigurator] [pool-109-thread-1] INFO  - Successfully accepted certificate for PSVA: 192.168.2.210 Certificate: [
      [
        Version: V3
        Subject: CN=sva, O=VMware
        Signature Algorithm: SHA1withRSA, OID = 1.2.840.113549.1.1.5

        Key:  Sun RSA public key, 1024 bits
        modulus: 103830147811061690411944855570358091973823792620622200953830118645150819147770716667636140192625829917412569379264415104957392757777542997955807273296970483566753641698594811647618464989890161594764495453013753257234391909152382456313797832480552764860025119078188234050920198431299850164121348361199434123761
        public exponent: 65537
        Validity: [From: Tue Dec 11 01:17:41 GMT+04:00 2012,
                     To: Thu Nov 17 01:17:41 GMT+04:00 2112]
        Issuer: CN=sva, O=VMware
        SerialNumber: [    50c65175]

      ]
        Algorithm: [SHA1withRSA]
        Signature:
      0000: 7D 3B B0 C4 EE C4 1F E9   73 A6 FD 72 48 23 91 41  .;......s..rH#.A
      0010: 26 BF 87 D4 3C 62 81 EA   5C 67 90 70 53 28 CB F8  &...<b..\g.pS(..
      0020: E0 75 D7 2A E7 17 0E 85   84 16 AD D4 07 6F 9C AD  .u.*.........o..
      0030: BA AF B2 AD A6 E4 EB 7E   39 3E 8C 3A 5D EE 09 4D  ........9>.:]..M
      0040: 3E DF 60 FD DF A9 26 D8   45 D8 C8 97 AF AA 4B 3A  >.`...&.E.....K:
      0050: 30 B6 4A 8F AB 0F 42 D3   6B 23 F0 0F 1A FE E8 B8  0.J...B.k#......
      0060: 52 93 04 24 94 BA 0E D8   D3 95 58 BA 2C 21 9A AF  R..$......X.,!..
      0070: B9 2B C2 35 E0 6E FF 9E   AA 5C 4E B7 D9 45 8E 8A  .+.5.n...\N..E..

      ]
      2012-12-11 06:23:47,203 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: com.vmware.sva.manager.security.ssl.factory=null
      2012-12-11 06:23:47,223 72 [MessagingService] [pool-109-thread-1] INFO  - Using server endpoint for PSVA: https://192.168.2.210:4336/services/pseudosvaservice
      2012-12-11 06:23:47,413 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:Audit2N-LV
      2012-12-11 06:23:47,413 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:Audit2N-LV
      2012-12-11 06:23:47,413 65 [DefaultJobRunner] [pool-109-thread-1] INFO  - TaskGroup execution finished successfully. TaskGroupName:ClusterCreation-PreHostReboot
      2012-12-11 06:23:47,413 58 [DefaultJobRunner] [pool-109-thread-1] INFO  - Starting Task group. TaskGroupName:Set Hosts VMFS Heap Size
      2012-12-11 06:23:47,423 49 [DefaultTaskRunner] [pool-110-thread-1] INFO  - Notifying listeners of task begin. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:23:47,423 69 [DefaultTaskRunner] [pool-110-thread-1] INFO  - Starting execution of task. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:23:47,423 49 [DefaultTaskRunner] [pool-110-thread-2] INFO  - Notifying listeners of task begin. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:23:47,423 69 [DefaultTaskRunner] [pool-110-thread-2] INFO  - Starting execution of task. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:23:47,723 71 [DefaultTaskRunner] [pool-110-thread-2] INFO  - Task execution finished with result:true. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:23:47,723 73 [DefaultTaskRunner] [pool-110-thread-2] INFO  - Notifying listeners of task end. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:23:47,733 71 [DefaultTaskRunner] [pool-110-thread-1] INFO  - Task execution finished with result:true. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:23:47,733 73 [DefaultTaskRunner] [pool-110-thread-1] INFO  - Notifying listeners of task end. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:23:47,733 65 [DefaultJobRunner] [pool-109-thread-1] INFO  - TaskGroup execution finished successfully. TaskGroupName:Set Hosts VMFS Heap Size
      2012-12-11 06:23:47,733 58 [DefaultJobRunner] [pool-109-thread-1] INFO  - Starting Task group. TaskGroupName:ClusterCreation-PostHostReboot
      2012-12-11 06:23:47,733 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:Run2NLV
      2012-12-11 06:23:47,733 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:Run2NLV
      2012-12-11 06:23:47,733 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:Run2NLV
      2012-12-11 06:23:47,733 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:Run2NLV
      2012-12-11 06:23:47,733 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:AddTagsToHosts
      2012-12-11 06:23:47,733 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:AddTagsToHosts
      2012-12-11 06:23:47,863 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:AddTagsToHosts
      2012-12-11 06:23:47,863 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:AddTagsToHosts
      2012-12-11 06:23:47,863 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:NetworkConfig
      2012-12-11 06:23:47,863 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:NetworkConfig
      2012-12-11 06:23:48,173 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:23:48,243 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: network.config=true
      2012-12-11 06:23:48,353 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:23:48,483 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:23:48,493 51 [PNICSelectorImpl] [pool-109-thread-1] INFO  - Getting NICs to use for switch vSwitch0
      2012-12-11 06:23:48,513 51 [PNICSelectorImpl] [pool-109-thread-1] INFO  - Getting NICs to use for switch vSwitch1
      2012-12-11 06:23:52,473 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:23:52,563 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:23:52,563 51 [PNICSelectorImpl] [pool-109-thread-1] INFO  - Getting NICs to use for switch vSwitch0
      2012-12-11 06:23:52,563 51 [PNICSelectorImpl] [pool-109-thread-1] INFO  - Getting NICs to use for switch vSwitch1
      2012-12-11 06:23:57,083 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:NetworkConfig
      2012-12-11 06:23:57,083 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:NetworkConfig
      2012-12-11 06:23:57,083 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:ConfigureHA
      2012-12-11 06:23:57,083 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:ConfigureHA
      2012-12-11 06:23:57,083 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: ha.config=true
      2012-12-11 06:23:57,083 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: ha.config=true
      2012-12-11 06:23:57,163 82 [HAClusterConfigurator] [pool-109-thread-1] INFO  - Now configuring admission control.
      2012-12-11 06:23:57,563 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: evc.config=false
      2012-12-11 06:24:18,203 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:24:38,473 258 [HAClusterConfigurator] [pool-109-thread-1] INFO  - Task of configuring HA on host 192.168.2.200 succeeded
      2012-12-11 06:24:38,563 258 [HAClusterConfigurator] [pool-109-thread-1] INFO  - Task of configuring HA on host 192.168.2.201 succeeded
      2012-12-11 06:24:38,563 71 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task execution finished with result:true. TaskID:ConfigureHA
      2012-12-11 06:24:38,563 73 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task end. TaskID:ConfigureHA
      2012-12-11 06:24:38,563 49 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task begin. TaskID:InstallsVSAVMs
      2012-12-11 06:24:38,563 69 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting execution of task. TaskID:InstallsVSAVMs
      2012-12-11 06:24:38,583 40 [TaskInstallVSAVMs] [pool-109-thread-1] INFO  - VSA VMs will be installed from index:0
      2012-12-11 06:24:38,643 200 [OvfData] [pool-109-thread-1] INFO  - Default disk size 1000 MB
      2012-12-11 06:24:38,703 213 [OvfData] [pool-109-thread-1] INFO  - Total system disk size 9216 MB
      2012-12-11 06:24:38,703 216 [OvfData] [pool-109-thread-1] INFO  - Total initial reserved disk size 22528 MB
      2012-12-11 06:24:38,703 45 [TaskInstallVSAVMs] [pool-109-thread-1] INFO  - OVF Data initialized
      2012-12-11 06:24:38,703 147 [VCUserSession] [pool-109-thread-1] INFO  - OVF import
      2012-12-11 06:24:38,743 182 [VAppImporter] [TaskExecutionService-1] INFO  - Set flag for contiguous allocation
      2012-12-11 06:24:38,743 182 [VAppImporter] [TaskExecutionService-2] INFO  - Set flag for contiguous allocation
      2012-12-11 06:24:40,743 208 [VAppImporter] [TaskExecutionService-1] INFO  -
      Host "192.168.2.201" new configuration values for contiguous allocation:
                   VMFS3.EnableSVAVMFS -    1             
                   Misc.VmkStressEnable-    0            

      2012-12-11 06:24:40,813 505 [VAppImporter] [TaskExecutionService-1] INFO  - Host host-126's VMFS datastore datastore2 state is green
      2012-12-11 06:24:41,173 235 [Utils] [TaskExecutionService-1] INFO  - Retrieve dev.property: disk.size.default=false
      2012-12-11 06:24:41,393 1107 [VAppImporter] [TaskExecutionService-1] INFO  -
      Host "192.168.2.201" VMFS datastore disk data (bytes)
                   free space          -    3993282543616 
                   system disk space   -    9663676416    
                   user selected space -    true          
                   user selected value -    3993282543616 
                   reserved disk space -    23622320128   
                   data disk number    -    16            
                   data disk size      -    248103763968 

      2012-12-11 06:24:41,393 356 [VAppImporter] [TaskExecutionService-1] INFO  - Set data disk size 236610 MB
      2012-12-11 06:24:42,463 208 [VAppImporter] [TaskExecutionService-2] INFO  -
      Host "192.168.2.200" new configuration values for contiguous allocation:
                   VMFS3.EnableSVAVMFS -    1             
                   Misc.VmkStressEnable-    0            

      2012-12-11 06:24:42,533 505 [VAppImporter] [TaskExecutionService-2] INFO  - Host host-123's VMFS datastore datastore1 state is green
      2012-12-11 06:24:42,673 235 [Utils] [TaskExecutionService-2] INFO  - Retrieve dev.property: disk.size.default=false
      2012-12-11 06:24:42,873 1107 [VAppImporter] [TaskExecutionService-2] INFO  -
      Host "192.168.2.200" VMFS datastore disk data (bytes)
                   free space          -    3993282543616 
                   system disk space   -    9663676416    
                   user selected space -    true          
                   user selected value -    3993282543616 
                   reserved disk space -    23622320128   
                   data disk number    -    16            
                   data disk size      -    248103763968 

      2012-12-11 06:24:42,873 356 [VAppImporter] [TaskExecutionService-2] INFO  - Set data disk size 236610 MB
      2012-12-11 06:24:48,363 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:24:52,623 869 [VAppImporter] [Thread-117] INFO  - LeaseProgressUpdater threads starts
      2012-12-11 06:24:53,043 869 [VAppImporter] [Thread-118] INFO  - LeaseProgressUpdater threads starts
      2012-12-11 06:25:18,433 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:25:48,613 126 [SVAManager] [tomcat-http--40] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:26:15,283 403 [FileLoader] [TaskExecutionService-2] INFO  - Uploaded file takes 82 seconds
      2012-12-11 06:26:15,293 357 [FileLoader] [TaskExecutionService-2] INFO  - Uploaded file created on server
      2012-12-11 06:26:15,293 802 [VAppImporter] [TaskExecutionService-2] INFO  - Uploaded file: sva_system1.vmdk
      2012-12-11 06:26:16,573 403 [FileLoader] [TaskExecutionService-2] INFO  - Uploaded file takes 1 seconds
      2012-12-11 06:26:16,593 357 [FileLoader] [TaskExecutionService-2] INFO  - Uploaded file created on server
      2012-12-11 06:26:16,593 802 [VAppImporter] [TaskExecutionService-2] INFO  - Uploaded file: sva_system2.vmdk
      2012-12-11 06:26:16,603 625 [VAppImporter] [TaskExecutionService-2] INFO  - Uploading of the entity is successful
      2012-12-11 06:26:18,423 403 [FileLoader] [TaskExecutionService-1] INFO  - Uploaded file takes 85 seconds
      2012-12-11 06:26:18,433 357 [FileLoader] [TaskExecutionService-1] INFO  - Uploaded file created on server
      2012-12-11 06:26:18,433 802 [VAppImporter] [TaskExecutionService-1] INFO  - Uploaded file: sva_system1.vmdk
      2012-12-11 06:26:18,743 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:26:19,483 890 [VAppImporter] [Thread-118] INFO  - LeaseProgressUpdater thread breaks
      2012-12-11 06:26:19,653 403 [FileLoader] [TaskExecutionService-1] INFO  - Uploaded file takes 1 seconds
      2012-12-11 06:26:19,673 357 [FileLoader] [TaskExecutionService-1] INFO  - Uploaded file created on server
      2012-12-11 06:26:19,673 802 [VAppImporter] [TaskExecutionService-1] INFO  - Uploaded file: sva_system2.vmdk
      2012-12-11 06:26:19,683 625 [VAppImporter] [TaskExecutionService-1] INFO  - Uploading of the entity is successful
      2012-12-11 06:26:20,203 405 [VAppImporter] [TaskExecutionService-2] INFO  - Deploy VM VSA-1 took 97s
      2012-12-11 06:26:23,093 890 [VAppImporter] [Thread-117] INFO  - LeaseProgressUpdater thread breaks
      2012-12-11 06:26:23,263 405 [VAppImporter] [TaskExecutionService-1] INFO  - Deploy VM VSA-0 took 100s
      2012-12-11 06:26:25,053 281 [SVAVMConfigurator] [TaskExecutionService-3] INFO  - Configuring the VM resources for the newly created VM
      2012-12-11 06:26:25,243 281 [SVAVMConfigurator] [TaskExecutionService-4] INFO  - Configuring the VM resources for the newly created VM
      2012-12-11 06:26:25,353 974 [SVAVMConfigurator] [TaskExecutionService-4] INFO  - Reconfigured VM to mark all disks as independent
      2012-12-11 06:26:25,353 974 [SVAVMConfigurator] [TaskExecutionService-3] INFO  - Reconfigured VM to mark all disks as independent
      2012-12-11 06:26:26,993 326 [SVAVMConfigurator] [TaskExecutionService-3] INFO  - Configuring CPU/MEM allocation and page sharing for VM VSA-0 completed
      2012-12-11 06:26:27,003 327 [SVAVMConfigurator] [TaskExecutionService-3] INFO  - marking all non system disk as independent for VSA-0 completed
      2012-12-11 06:26:27,003 235 [Utils] [TaskExecutionService-3] INFO  - Retrieve dev.property: network.config=true
      2012-12-11 06:26:28,363 326 [SVAVMConfigurator] [TaskExecutionService-4] INFO  - Configuring CPU/MEM allocation and page sharing for VM VSA-1 completed
      2012-12-11 06:26:28,373 327 [SVAVMConfigurator] [TaskExecutionService-4] INFO  - marking all non system disk as independent for VSA-1 completed
      2012-12-11 06:26:28,373 235 [Utils] [TaskExecutionService-4] INFO  - Retrieve dev.property: network.config=true
      2012-12-11 06:26:48,823 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:27:18,933 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:27:25,993 1479 [ClusterService] [SanityService-4] INFO  - No Hosts have been added/removed since: 12-12-11 04:35:32
      2012-12-11 06:27:48,993 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:28:19,083 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:28:31,883 645 [SVAVMConfigurator] [TaskExecutionService-3] ERROR - Customize VM on host host-126 failed
      java.lang.Exception: Client side time out waiting for task to comeplete
      at com.vmware.sva.manager.service.VCTaskService.waitForTaskToComplete(VCTaskService.java:173)
      at com.vmware.sva.manager.config.SVAVMConfigurator.powerOnVM(SVAVMConfigurator.java:426)
      at com.vmware.sva.manager.config.SVAVMConfigurator.initializeVM(SVAVMConfigurator.java:262)
      at com.vmware.sva.manager.config.SVAVMConfigurator.customizeSvaVM(SVAVMConfigurator.java:708)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:643)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:80)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)
      2012-12-11 06:28:33,103 645 [SVAVMConfigurator] [TaskExecutionService-4] ERROR - Customize VM on host host-123 failed
      java.lang.Exception: Client side time out waiting for task to comeplete
      at com.vmware.sva.manager.service.VCTaskService.waitForTaskToComplete(VCTaskService.java:173)
      at com.vmware.sva.manager.config.SVAVMConfigurator.powerOnVM(SVAVMConfigurator.java:426)
      at com.vmware.sva.manager.config.SVAVMConfigurator.initializeVM(SVAVMConfigurator.java:262)
      at com.vmware.sva.manager.config.SVAVMConfigurator.customizeSvaVM(SVAVMConfigurator.java:708)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:643)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:80)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)
      2012-12-11 06:28:33,223 313 [VCUserSession] [pool-109-thread-1] ERROR - Customize VM on host host-123failed.
      java.util.concurrent.ExecutionException: java.lang.Exception: Client side time out waiting for task to comeplete
      at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222)
      at java.util.concurrent.FutureTask.get(FutureTask.java:83)
      at com.vmware.sva.manager.dao.VCUserSession.installSvaVms(VCUserSession.java:306)
      at com.vmware.sva.manager.jobservices.tasks.TaskInstallVSAVMs.execute(TaskInstallVSAVMs.java:47)
      at com.vmware.sva.manager.jobservices.impl.DefaultTaskRunner.handleTaskStart(DefaultTaskRunner.java:70)
      at com.vmware.sva.manager.jobservices.impl.DefaultTaskRunner.call(DefaultTaskRunner.java:33)
      at com.vmware.sva.manager.jobservices.impl.SyncTaskGroup.execute(SyncTaskGroup.java:46)
      at com.vmware.sva.manager.jobservices.impl.DefaultJobRunner.run(DefaultJobRunner.java:60)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)
      Caused by: java.lang.Exception: Client side time out waiting for task to comeplete
      at com.vmware.sva.manager.service.VCTaskService.waitForTaskToComplete(VCTaskService.java:173)
      at com.vmware.sva.manager.config.SVAVMConfigurator.powerOnVM(SVAVMConfigurator.java:426)
      at com.vmware.sva.manager.config.SVAVMConfigurator.initializeVM(SVAVMConfigurator.java:262)
      at com.vmware.sva.manager.config.SVAVMConfigurator.customizeSvaVM(SVAVMConfigurator.java:708)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:643)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:80)
      ... 5 more
      2012-12-11 06:28:33,223 315 [VCUserSession] [pool-109-thread-1] ERROR - Cancelling the running customization tasks
      2012-12-11 06:28:33,223 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: vm.rollback=true
      2012-12-11 06:28:33,223 333 [VCUserSession] [pool-109-thread-1] INFO  - Deleting all the installed VM
      2012-12-11 06:28:49,223 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:29:01,733 89 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task exception. TaskID:InstallsVSAVMs
      2012-12-11 06:29:01,753 80 [DefaultJobRunner] [pool-109-thread-1] ERROR - Exception caught. Starting rollback for job if rollback support . JobName:ClusterCreation-datacenter-21
      java.util.concurrent.ExecutionException: java.lang.Exception: Client side time out waiting for task to comeplete
      at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222)
      at java.util.concurrent.FutureTask.get(FutureTask.java:83)
      at com.vmware.sva.manager.dao.VCUserSession.installSvaVms(VCUserSession.java:306)
      at com.vmware.sva.manager.jobservices.tasks.TaskInstallVSAVMs.execute(TaskInstallVSAVMs.java:47)
      at com.vmware.sva.manager.jobservices.impl.DefaultTaskRunner.handleTaskStart(DefaultTaskRunner.java:70)
      at com.vmware.sva.manager.jobservices.impl.DefaultTaskRunner.call(DefaultTaskRunner.java:33)
      at com.vmware.sva.manager.jobservices.impl.SyncTaskGroup.execute(SyncTaskGroup.java:46)
      at com.vmware.sva.manager.jobservices.impl.DefaultJobRunner.run(DefaultJobRunner.java:60)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)
      Caused by: java.lang.Exception: Client side time out waiting for task to comeplete
      at com.vmware.sva.manager.service.VCTaskService.waitForTaskToComplete(VCTaskService.java:173)
      at com.vmware.sva.manager.config.SVAVMConfigurator.powerOnVM(SVAVMConfigurator.java:426)
      at com.vmware.sva.manager.config.SVAVMConfigurator.initializeVM(SVAVMConfigurator.java:262)
      at com.vmware.sva.manager.config.SVAVMConfigurator.customizeSvaVM(SVAVMConfigurator.java:708)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:643)
      at com.vmware.sva.manager.config.SVAVMConfigurator.call(SVAVMConfigurator.java:80)
      ... 5 more
      2012-12-11 06:29:01,753 109 [DefaultJobRunner] [pool-109-thread-1] INFO  - Rollback started for job. JobName:ClusterCreation-datacenter-21
      2012-12-11 06:29:01,753 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:InstallsVSAVMs
      2012-12-11 06:29:01,753 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:InstallsVSAVMs
      2012-12-11 06:29:01,753 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: vm.rollback=true
      2012-12-11 06:29:01,783 304 [CleanupUtils] [pool-109-thread-1] INFO  - Powering off and deleting all SVA VMs
      2012-12-11 06:29:01,783 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:InstallsVSAVMs
      2012-12-11 06:29:01,783 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:InstallsVSAVMs
      2012-12-11 06:29:01,783 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:ConfigureHA
      2012-12-11 06:29:01,783 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:ConfigureHA
      2012-12-11 06:29:01,783 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: ha.config=true
      2012-12-11 06:29:18,931 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:ConfigureHA
      2012-12-11 06:29:18,931 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:ConfigureHA
      2012-12-11 06:29:18,931 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:NetworkConfig
      2012-12-11 06:29:18,931 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:NetworkConfig
      2012-12-11 06:29:18,931 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: network.config=true
      2012-12-11 06:29:19,019 259 [CleanupUtils] [pool-109-thread-1] INFO  - Reverting network configuration on all SVA Hosts.
      2012-12-11 06:29:19,019 235 [Utils] [pool-109-thread-1] INFO  - Retrieve dev.property: network.config=true
      2012-12-11 06:29:19,019 269 [CleanupUtils] [pool-109-thread-1] INFO  - Received 2 SVA Hosts
      2012-12-11 06:29:19,050 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:29:19,113 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:29:19,113 51 [PNICSelectorImpl] [pool-109-thread-1] INFO  - Getting NICs to use for switch vSwitch0
      2012-12-11 06:29:19,222 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:29:23,783 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:29:23,863 102 [PhysicalNetworkConfiguration] [pool-109-thread-1] INFO  - Initializing the current network configuration
      2012-12-11 06:29:23,863 51 [PNICSelectorImpl] [pool-109-thread-1] INFO  - Getting NICs to use for switch vSwitch0
      2012-12-11 06:29:25,773 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:NetworkConfig
      2012-12-11 06:29:25,773 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:NetworkConfig
      2012-12-11 06:29:25,773 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:AddTagsToHosts
      2012-12-11 06:29:25,773 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:AddTagsToHosts
      2012-12-11 06:29:25,943 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:AddTagsToHosts
      2012-12-11 06:29:25,943 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:AddTagsToHosts
      2012-12-11 06:29:25,943 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:Run2NLV
      2012-12-11 06:29:25,943 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:Run2NLV
      2012-12-11 06:29:25,943 72 [MessagingService] [pool-109-thread-1] INFO  - Using server endpoint for PSVA: https://192.168.2.210:4336/services/pseudosvaservice
      2012-12-11 06:29:29,323 46 [TaskRun2NLV] [pool-109-thread-1] INFO  - Destroyed VCS with best effort
      2012-12-11 06:29:29,323 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:Run2NLV
      2012-12-11 06:29:29,323 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:Run2NLV
      2012-12-11 06:29:29,323 122 [DefaultJobRunner] [pool-109-thread-1] INFO  - TaskGroup rolled back successfully.TaskGroupName:ClusterCreation-PostHostReboot
      2012-12-11 06:29:29,323 83 [AsyncTaskGroup] [pool-109-thread-1] INFO  - Cancelling running tasks for taskGroup. TaskGroupName:Set Hosts VMFS Heap Size
      2012-12-11 06:29:29,323 116 [DefaultTaskRunner] [pool-110-thread-3] INFO  - Notifying listeners of task rollback. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:29:29,323 136 [DefaultTaskRunner] [pool-110-thread-3] INFO  - Starting rollback of task. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:29:29,323 138 [DefaultTaskRunner] [pool-110-thread-3] INFO  - Task rollback finished with result:true. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:29:29,323 140 [DefaultTaskRunner] [pool-110-thread-3] INFO  - Notifying listeners of task rollback end. TaskID:SetVMFSHeapSizehost-126
      2012-12-11 06:29:29,323 116 [DefaultTaskRunner] [pool-110-thread-4] INFO  - Notifying listeners of task rollback. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:29:29,323 136 [DefaultTaskRunner] [pool-110-thread-4] INFO  - Starting rollback of task. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:29:29,323 138 [DefaultTaskRunner] [pool-110-thread-4] INFO  - Task rollback finished with result:true. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:29:29,323 140 [DefaultTaskRunner] [pool-110-thread-4] INFO  - Notifying listeners of task rollback end. TaskID:SetVMFSHeapSizehost-123
      2012-12-11 06:29:29,323 122 [DefaultJobRunner] [pool-109-thread-1] INFO  - TaskGroup rolled back successfully.TaskGroupName:Set Hosts VMFS Heap Size
      2012-12-11 06:29:29,323 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:Audit2N-LV
      2012-12-11 06:29:29,323 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:Audit2N-LV
      2012-12-11 06:29:29,323 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:Audit2N-LV
      2012-12-11 06:29:29,323 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:Audit2N-LV
      2012-12-11 06:29:29,323 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:NetworkConfigValidation
      2012-12-11 06:29:29,323 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:NetworkConfigValidation
      2012-12-11 06:29:29,323 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:NetworkConfigValidation
      2012-12-11 06:29:29,323 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:NetworkConfigValidation
      2012-12-11 06:29:29,323 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:AuditHostGroup
      2012-12-11 06:29:29,333 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:AuditHostGroup
      2012-12-11 06:29:29,333 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:AuditHostGroup
      2012-12-11 06:29:29,333 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:AuditHostGroup
      2012-12-11 06:29:29,333 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:ClusterExists
      2012-12-11 06:29:29,333 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:ClusterExists
      2012-12-11 06:29:29,333 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:ClusterExists
      2012-12-11 06:29:29,333 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:ClusterExists
      2012-12-11 06:29:29,333 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:LogParams
      2012-12-11 06:29:29,333 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:LogParams
      2012-12-11 06:29:29,333 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:LogParams
      2012-12-11 06:29:29,333 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:LogParams
      2012-12-11 06:29:29,333 116 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback. TaskID:TaskInitCreateCluster
      2012-12-11 06:29:29,333 136 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Starting rollback of task. TaskID:TaskInitCreateCluster
      2012-12-11 06:29:29,453 196 [MappingService] [pool-109-thread-1] INFO  - Removing context for datacenter-21
      2012-12-11 06:29:29,681 83 [TaskInitCreateCluster] [pool-109-thread-1] INFO  - Released license for datacenter: datacenter-21
      2012-12-11 06:29:29,681 138 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Task rollback finished with result:true. TaskID:TaskInitCreateCluster
      2012-12-11 06:29:29,683 140 [DefaultTaskRunner] [pool-109-thread-1] INFO  - Notifying listeners of task rollback end. TaskID:TaskInitCreateCluster
      2012-12-11 06:29:29,683 122 [DefaultJobRunner] [pool-109-thread-1] INFO  - TaskGroup rolled back successfully.TaskGroupName:ClusterCreation-PreHostReboot
      2012-12-11 06:29:29,683 84 [DefaultJobRunner] [pool-109-thread-1] ERROR - Rollback finished successfully for job. JobName:ClusterCreation-datacenter-21
      2012-12-11 06:29:29,683 92 [DefaultJobRunner] [pool-109-thread-1] INFO  - Notifying listeners of job exception for job: ClusterCreation-datacenter-21
      2012-12-11 06:29:49,331 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:30:19,516 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:30:49,686 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:31:19,736 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:31:49,756 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:32:19,805 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:32:26,044 1479 [ClusterService] [SanityService-5] INFO  - No Hosts have been added/removed since: 12-12-11 04:35:32
      2012-12-11 06:32:49,814 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:33:19,843 126 [SVAManager] [tomcat-http--33] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:33:49,875 126 [SVAManager] [tomcat-http--4] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:34:19,899 126 [SVAManager] [tomcat-http--4] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:34:49,932 126 [SVAManager] [tomcat-http--4] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:35:19,982 126 [SVAManager] [tomcat-http--4] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:35:50,012 126 [SVAManager] [tomcat-http--4] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:36:20,012 126 [SVAManager] [tomcat-http--4] INFO  - VSA Manager dummyPing invoked.
      2012-12-11 06:36:50,012 126 [SVAManager] [tomcat-http--4] INFO  - VSA Manager dummyPing invoked.