2017-03-10 11:14:33,898 INFO [c.c.u.n.n.p.NiciraNvpApiVersion] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) NSX API VERSION: NOT PRESENT 2017-03-10 11:14:33,898 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Prepare NIC device based on NicTO: {"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"24671fca-3893-4479-89f7-07d8d4c61bf8","uuid":"452d44e4-f887-4027-8338-f952d69e58ec","ip":"10.1.1.151","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:55:92:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://973","isolationUri":"vlan://973","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"} 2017-03-10 11:14:33,904 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Prepare network on vmwaresvs vSwitch1 with name prefix: cloud.guest 2017-03-10 11:14:34,000 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Network cloud.guest.973.200.1-vSwitch1 is ready on vSwitch vSwitch1 2017-03-10 11:14:34,000 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Preparing NIC device on network cloud.guest.973.200.1-vSwitch1 2017-03-10 11:14:34,001 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Prepare NIC at new device {"operation":"ADD","device":{"addressType":"Manual","macAddress":"02:00:55:92:00:01","key":-3,"backing":{"network":{"value":"network-51","type":"Network"},"deviceName":"cloud.guest.973.200.1-vSwitch1"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":0}} 2017-03-10 11:14:34,001 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) find VM i-10-10-VM on host 2017-03-10 11:14:34,001 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) VM i-10-10-VM found in host cache 2017-03-10 11:14:34,029 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Configure VNC port for VM i-10-10-VM, port: 5949, host: 10.2.2.23 2017-03-10 11:14:35,437 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-2137c6a3) (logid:e63f1148) Begin cleanup expired async-jobs 2017-03-10 11:14:35,442 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-2137c6a3) (logid:e63f1148) End cleanup expired async-jobs 2017-03-10 11:14:35,753 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Look for disk device info for volume : ROOT-10-000001.vmdk with base name: ROOT-10-000001 2017-03-10 11:14:35,753 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Test against disk device, controller key: 200, unit number: 1 2017-03-10 11:14:35,753 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Test against disk backing : [45c4670109f63ae1b322192709c67bf8] i-10-10-VM/ROOT-10-000001.vmdk 2017-03-10 11:14:35,753 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Disk backing : [45c4670109f63ae1b322192709c67bf8] i-10-10-VM/ROOT-10-000001.vmdk matches ==> ide0:1 2017-03-10 11:14:35,787 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Found existing disk info from volume path: ROOT-10-000001 2017-03-10 11:14:35,787 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) Unsupported root disk device bus ide0:1 2017-03-10 11:14:35,787 INFO [c.c.h.v.u.VmwareHelper] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) [ignored]failed toi get message for exception: Unsupported root disk device bus ide0:1 2017-03-10 11:14:35,787 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-58:ctx-2833f73a 10.2.2.23, job-48/job-49, cmd: StartCommand) (logid:a7ff003b) StartCommand failed due to Exception: java.lang.Exception Message: Unsupported root disk device bus ide0:1 java.lang.Exception: Unsupported root disk device bus ide0:1 at com.cloud.hypervisor.vmware.resource.VmwareResource.resizeRootDisk(VmwareResource.java:2111) at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2029) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:467) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2017-03-10 11:14:35,790 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-58:ctx-2833f73a) (logid:a7ff003b) Seq 1-3028389274429948020: Response Received: 2017-03-10 11:14:35,791 DEBUG [c.c.a.t.Request] (DirectAgent-58:ctx-2833f73a) (logid:a7ff003b) Seq 1-3028389274429948020: Processing: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":10,"name":"i-10-10-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":50,"maxSpeed":100,"minRam":268435456,"maxRam":268435456,"hostName":"testvm","arch":"x86_64","os":"CentOS 5.3 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"J1L2pS6dc-YxD48_Qpe3dQ","params":{"deployvm":"true","dataDiskController":"osdefault","memoryOvercommitRatio":"1.0","nestedVirtualizationFlag":"false","rootdisksize":"4","cpuOvercommitRatio":"2.0","vmware.reserve.mem":"false","vmware.reserve.cpu":"false","nicAdapter":"E1000","rootDiskController":"ide"},"uuid":"8df10462-c45e-42b4-92ba-9e296abf6d98","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"dfefb860-f1bf-44b4-9cf7-d4797a89c421","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"45c46701-09f6-3ae1-b322-192709c67bf8","id":1,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1/?ROLE=Primary&STOREUUID=45c46701-09f6-3ae1-b322-192709c67bf8","isManaged":false}},"name":"ROOT-10","size":4294967296,"path":"ROOT-10-000001","volumeId":6,"vmName":"i-10-10-VM","accountId":10,"format":"OVA","provisioningType":"THIN","id":6,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-10-000001","type":"ROOT","_details":{"storageHost":"10.2.0.16","managed":"false","storagePort":"2049","volumeSize":"4294967296"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"24671fca-3893-4479-89f7-07d8d4c61bf8","uuid":"452d44e4-f887-4027-8338-f952d69e58ec","ip":"10.1.1.151","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:55:92:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://973","isolationUri":"vlan://973","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"}]},"result":false,"details":"StartCommand failed due to Exception: java.lang.Exception\nMessage: Unsupported root disk device bus ide0:1\n","wait":0}}] } 2017-03-10 11:14:35,791 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-58:ctx-2833f73a) (logid:a7ff003b) Seq 1-3028389274429948020: No more commands found 2017-03-10 11:14:35,791 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Seq 1-3028389274429948020: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, { StartAnswer } } 2017-03-10 11:14:35,796 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Unable to start VM on Host[-1-Routing] due to StartCommand failed due to Exception: java.lang.Exception Message: Unsupported root disk device bus ide0:1 2017-03-10 11:14:35,799 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Cleaning up resources for the vm VM[User|i-10-10-VM] in Starting state 2017-03-10 11:14:35,802 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Seq 1-3028389274429948021: Sending { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-10-10-VM","executeInSequence":true,"wait":0}}] } 2017-03-10 11:14:35,802 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Seq 1-3028389274429948021: Executing: { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-10-10-VM","executeInSequence":true,"wait":0}}] } 2017-03-10 11:14:35,803 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-116:ctx-b3b862fe) (logid:e25ea218) Seq 1-3028389274429948021: Executing request 2017-03-10 11:14:35,803 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-116:ctx-b3b862fe 10.2.2.23, job-48/job-49, cmd: StopCommand) (logid:a7ff003b) Executing resource StopCommand: {"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-10-10-VM","executeInSequence":true,"wait":0} 2017-03-10 11:14:35,813 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-116:ctx-b3b862fe 10.2.2.23, job-48/job-49, cmd: StopCommand) (logid:a7ff003b) find VM i-10-10-VM on host 2017-03-10 11:14:35,813 INFO [c.c.h.v.m.HostMO] (DirectAgent-116:ctx-b3b862fe 10.2.2.23, job-48/job-49, cmd: StopCommand) (logid:a7ff003b) VM i-10-10-VM not found in host cache 2017-03-10 11:14:35,813 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-116:ctx-b3b862fe 10.2.2.23, job-48/job-49, cmd: StopCommand) (logid:a7ff003b) load VM cache on host 2017-03-10 11:14:35,874 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-116:ctx-b3b862fe 10.2.2.23, job-48/job-49, cmd: StopCommand) (logid:a7ff003b) VM i-10-10-VM is already in stopped state 2017-03-10 11:14:35,877 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-116:ctx-b3b862fe) (logid:a7ff003b) Seq 1-3028389274429948021: Response Received: 2017-03-10 11:14:35,877 DEBUG [c.c.a.t.Request] (DirectAgent-116:ctx-b3b862fe) (logid:a7ff003b) Seq 1-3028389274429948021: Processing: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-10-10-VM is already in stopped state","wait":0}}] } 2017-03-10 11:14:35,877 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-116:ctx-b3b862fe) (logid:a7ff003b) Seq 1-3028389274429948021: No more commands found 2017-03-10 11:14:35,877 DEBUG [c.c.a.t.Request] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Seq 1-3028389274429948021: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, { StopAnswer } } 2017-03-10 11:14:35,884 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Service SecurityGroup is not supported in the network id=210 2017-03-10 11:14:35,886 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Changing active number of nics for network id=210 on -1 2017-03-10 11:14:35,897 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Asking VirtualRouter to release NicProfile[12-10-bce6aeb4-add5-40cf-a674-fd77b44f5050-10.1.1.151-null 2017-03-10 11:14:35,897 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Successfully released network resources for the vm VM[User|i-10-10-VM] 2017-03-10 11:14:35,897 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Successfully cleanued up resources for the vm VM[User|i-10-10-VM] in Starting state 2017-03-10 11:14:35,899 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Root volume is ready, need to place VM in volume's cluster 2017-03-10 11:14:35,906 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Deploy avoids pods: [], clusters: [], hosts: [1] 2017-03-10 11:14:35,906 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@7ab88384 2017-03-10 11:14:35,906 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 100, requested ram: 268435456 2017-03-10 11:14:35,907 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Is ROOT volume READY (pool already allocated)?: Yes 2017-03-10 11:14:35,907 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1 2017-03-10 11:14:35,907 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) The specified host is in avoid set 2017-03-10 11:14:35,907 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Cannot deploy to specified host, returning. 2017-03-10 11:14:35,930 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1 2017-03-10 11:14:35,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Hosts's actual total CPU: 4797 and CPU after applying overprovisioning: 9594 2017-03-10 11:14:35,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Hosts's actual total RAM: 8589398016 and RAM after applying overprovisioning: 8589398016 2017-03-10 11:14:35,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) release cpu from host: 1, old used: 1600,reserved: 0, actual total: 4797, total with overprovisioning: 9594; new used: 1500,reserved:0; movedfromreserved: false,moveToReserveredfalse 2017-03-10 11:14:35,935 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) release mem from host: 1, old used: 2147483648,reserved: 0, total: 8589398016; new used: 1879048192,reserved:0; movedfromreserved: false,moveToReserveredfalse 2017-03-10 11:14:35,949 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-10-10-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2017-03-10 11:14:35,949 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49 ctx-0126f3ed) (logid:a7ff003b) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-10-10-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2017-03-10 11:14:35,950 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 10, job origin: 48 2017-03-10 11:14:35,950 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Unable to complete AsyncJobVO {id:49, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAACnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 7509951710985, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Mar 10 11:11:05 UTC 2017}, job origin:48 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-10-10-VM]Scope=interface com.cloud.dc.DataCenter; id=1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:961) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4661) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4822) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:502) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2017-03-10 11:14:35,952 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Complete async job-49, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA1VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0xMC0xMC1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABVzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AAp4cAAAA8F0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEAABI1cQB-ABNxAH4AFHEAfgAVc3EAfgAR_____nQAJHN1bi5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHNxAH4AEQAAAD5xAH4AGHEAfgAZdAAGaW52b2tlc3EAfgARAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AHHNxAH4AEQAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAcc3EAfgARAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4AEQAAEtZxAH4AE3EAfgAUcQB-ACZzcQB-ABEAAABmdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-ABEAAAIqdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgARAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgARAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4AEQAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADZ0AA9jYWxsV2l0aENvbnRleHRzcQB-ABEAAAA1cQB-ADlxAH4ANnQADnJ1bldpdGhDb250ZXh0c3EAfgARAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAycQB-ADNzcQB-ABEAAAH2cQB-AC1xAH4ALnEAfgAzc3EAfgARAAAB_3QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA3c3EAfgARAAABCnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AM3NxAH4AEQAABHZ0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAml0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEhxAH4AM3NxAH4AEQAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AM3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFR4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcQB-AFMAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFYAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlcrLxCuun53i-AgAAeHAA 2017-03-10 11:14:35,953 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Publish async job-49 complete on message bus 2017-03-10 11:14:35,953 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Wake up jobs related to job-49 2017-03-10 11:14:35,953 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Update db status for job-49 2017-03-10 11:14:35,954 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Wake up jobs joined with job-49 and disjoin all subjobs created from job- 49 2017-03-10 11:14:35,964 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Done executing com.cloud.vm.VmWorkStart for job-49 2017-03-10 11:14:35,965 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-9:ctx-53271ae8 job-48/job-49) (logid:a7ff003b) Remove job-49 from job monitoring 2017-03-10 11:14:35,981 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-d13f2974) (logid:4bd7705a) Zone 1 is ready to launch secondary storage VM 2017-03-10 11:14:35,994 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48 ctx-da924d49) (logid:a7ff003b) Sync job-51 execution on object VmWorkJobQueue.10 2017-03-10 11:14:36,157 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-4fe2ed14) (logid:4887e311) Zone 1 is ready to launch console proxy 2017-03-10 11:14:36,182 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-61e92fb4) (logid:4f62228e) HostOutOfBandManagementStatsCollector is running... 2017-03-10 11:14:36,535 INFO [c.c.a.m.AgentManagerImpl] (AgentMonitor-1:ctx-426972ec) (logid:c9748616) Found the following agents behind on ping: [1] 2017-03-10 11:14:36,537 DEBUG [c.c.h.Status] (AgentMonitor-1:ctx-426972ec) (logid:c9748616) Ping timeout for agent 1, do invstigation 2017-03-10 11:14:36,538 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) Investigating why host 1 has disconnected with event PingTimeout 2017-03-10 11:14:36,539 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) checking if agent (1) is alive 2017-03-10 11:14:36,542 DEBUG [c.c.a.t.Request] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) Seq 1-3028389274429948022: Sending { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CheckHealthCommand":{"wait":50}}] } 2017-03-10 11:14:36,542 DEBUG [c.c.a.t.Request] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) Seq 1-3028389274429948022: Executing: { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CheckHealthCommand":{"wait":50}}] } 2017-03-10 11:14:36,542 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-59:ctx-798647d3) (logid:61af1a46) Seq 1-3028389274429948022: Executing request 2017-03-10 11:14:36,542 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-59:ctx-798647d3 10.2.2.23, cmd: CheckHealthCommand) (logid:4c6e2d25) Executing resource CheckHealthCommand: {"wait":50} 2017-03-10 11:14:36,570 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-59:ctx-798647d3) (logid:4c6e2d25) Seq 1-3028389274429948022: Response Received: 2017-03-10 11:14:36,570 DEBUG [c.c.a.t.Request] (DirectAgent-59:ctx-798647d3) (logid:4c6e2d25) Seq 1-3028389274429948022: Processing: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, [{"com.cloud.agent.api.CheckHealthAnswer":{"result":true,"details":"resource is alive","wait":0}}] } 2017-03-10 11:14:36,570 DEBUG [c.c.a.t.Request] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) Seq 1-3028389274429948022: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, { CheckHealthAnswer } } 2017-03-10 11:14:36,570 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) Details from executing class com.cloud.agent.api.CheckHealthCommand: resource is alive 2017-03-10 11:14:36,570 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) agent (1) responded to checkHeathCommand, reporting that agent is Up 2017-03-10 11:14:36,570 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) The agent from host 1 state determined is Up 2017-03-10 11:14:36,570 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) Agent is determined to be up and running 2017-03-10 11:14:36,570 DEBUG [c.c.h.Status] (AgentTaskPool-16:ctx-cf73b9c9) (logid:4c6e2d25) Transition:[Resource state = Enabled, Agent event = Ping, Host id = 1, name = 10.2.2.23] 2017-03-10 11:14:37,439 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0c0fe478) (logid:95dfeb3f) Execute sync-queue item: SyncQueueItemVO {id:12, queueId: 11, contentType: AsyncJob, contentId: 51, lastProcessMsid: 7509951710985, lastprocessNumber: 2, lastProcessTime: Fri Mar 10 11:14:37 UTC 2017, created: Fri Mar 10 11:14:35 UTC 2017} 2017-03-10 11:14:37,440 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0c0fe478) (logid:95dfeb3f) Schedule queued job-51 2017-03-10 11:14:37,446 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:56ec3ee7) Add job-51 into job monitoring 2017-03-10 11:14:37,452 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-c879c065) (logid:de62f70c) ===START=== 10.5.0.16 -- GET signature=LoKH18E%2BumJw3ssqNpgnzUVsFOY%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=a7ff003b-a183-4eb5-b20c-f8027d869cfb 2017-03-10 11:14:37,457 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Executing AsyncJobVO {id:51, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAACnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 7509951710985, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Mar 10 11:14:35 UTC 2017} 2017-03-10 11:14:37,458 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Run VM work job: com.cloud.vm.VmWorkStart for VM 10, job origin: 48 2017-03-10 11:14:37,461 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":10,"handlerName":"VirtualMachineManagerImpl"} 2017-03-10 11:14:37,469 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null 2017-03-10 11:14:37,469 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Successfully transitioned to start state for VM[User|i-10-10-VM] reservation id = 38d79f75-51f7-472e-ba88-ca485baab019 2017-03-10 11:14:37,471 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-c879c065 ctx-cc6a6b78 ctx-094739c8) (logid:de62f70c) ===END=== 10.5.0.16 -- GET signature=LoKH18E%2BumJw3ssqNpgnzUVsFOY%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=a7ff003b-a183-4eb5-b20c-f8027d869cfb 2017-03-10 11:14:37,473 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Trying to deploy VM, vm has dcId: 1 and podId: 1 2017-03-10 11:14:37,473 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Deploy avoids pods: null, clusters: null, hosts: null 2017-03-10 11:14:37,475 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Root volume is ready, need to place VM in volume's cluster 2017-03-10 11:14:37,476 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Vol[6|vm=10|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1 2017-03-10 11:14:37,482 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Deploy avoids pods: [], clusters: [], hosts: [] 2017-03-10 11:14:37,483 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@7ab88384 2017-03-10 11:14:37,483 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 100, requested ram: 268435456 2017-03-10 11:14:37,483 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Is ROOT volume READY (pool already allocated)?: Yes 2017-03-10 11:14:37,483 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Searching resources only under specified Cluster: 1 2017-03-10 11:14:37,492 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Checking resources in Cluster: 1 under Pod: 1 2017-03-10 11:14:37,492 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Looking for hosts in dc: 1 pod:1 cluster:1 2017-03-10 11:14:37,495 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] 2017-03-10 11:14:37,498 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] 2017-03-10 11:14:37,498 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Looking for speed=100Mhz, Ram=256 2017-03-10 11:14:37,503 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-5118ce3d) (logid:e34ab58e) ===START=== 10.1.0.1 -- GET command=listVirtualMachines&response=json&listAll=true&page=1&pagesize=20&_=1489144511527 2017-03-10 11:14:37,508 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Host: 1 has cpu capability (cpu:3, speed:1599) to support requested CPU: 1 and requested speed: 100 2017-03-10 11:14:37,508 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Checking if host: 1 has enough capacity for requested CPU: 100 and requested RAM: 268435456 , cpuOverprovisioningFactor: 2.0 2017-03-10 11:14:37,510 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Hosts's actual total CPU: 4797 and CPU after applying overprovisioning: 9594 2017-03-10 11:14:37,510 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Free CPU: 8094 , Requested CPU: 100 2017-03-10 11:14:37,510 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Free RAM: 6710349824 , Requested RAM: 268435456 2017-03-10 11:14:37,510 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Host has enough CPU and RAM available 2017-03-10 11:14:37,510 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) STATS: Can alloc CPU from host: 1, used: 1500, reserved: 0, actual total: 4797, total with overprovisioning: 9594; requested cpu:100,alloc_from_last_host?:false ,considerReservedCapacity?: true 2017-03-10 11:14:37,510 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) STATS: Can alloc MEM from host: 1, used: 1879048192, reserved: 0, total: 8589398016; requested mem: 268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true 2017-03-10 11:14:37,510 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Found a suitable host, adding to list: 1 2017-03-10 11:14:37,510 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Host Allocator returning 1 suitable hosts 2017-03-10 11:14:37,513 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Checking suitable pools for volume (Id, Type): (6,ROOT) 2017-03-10 11:14:37,513 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Volume has pool already allocated, checking if pool can be reused, poolId: 1 2017-03-10 11:14:37,514 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Planner need not allocate a pool for this volume since its READY 2017-03-10 11:14:37,514 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2017-03-10 11:14:37,514 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Checking if host: 1 can access any suitable storage pool for volume: ROOT 2017-03-10 11:14:37,515 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Host: 1 can access pool: 1 2017-03-10 11:14:37,517 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Found a potential host id: 1 name: 10.2.2.23 and associated storage pools for this VM 2017-03-10 11:14:37,518 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()] 2017-03-10 11:14:37,518 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Deployment found - P0=VM[User|i-10-10-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()] 2017-03-10 11:14:37,528 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-5118ce3d ctx-b68f094f) (logid:e34ab58e) ===END=== 10.1.0.1 -- GET command=listVirtualMachines&response=json&listAll=true&page=1&pagesize=20&_=1489144511527 2017-03-10 11:14:37,553 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null 2017-03-10 11:14:37,559 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Hosts's actual total CPU: 4797 and CPU after applying overprovisioning: 9594 2017-03-10 11:14:37,559 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) We are allocating VM, increasing the used capacity of this host:1 2017-03-10 11:14:37,559 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Current Used CPU: 1500 , Free CPU:8094 ,Requested CPU: 100 2017-03-10 11:14:37,559 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Current Used RAM: 1879048192 , Free RAM:6710349824 ,Requested RAM: 268435456 2017-03-10 11:14:37,559 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) CPU STATS after allocation: for host: 1, old used: 1500, old reserved: 0, actual total: 4797, total with overprovisioning: 9594; new used:1600, reserved:0; requested cpu:100,alloc_from_last:false 2017-03-10 11:14:37,559 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) RAM STATS after allocation: for host: 1, old used: 1879048192, old reserved: 0, total: 8589398016; new used: 2147483648, reserved: 0; requested mem: 268435456,alloc_from_last:false 2017-03-10 11:14:37,562 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) VM is being created in podId: 1 2017-03-10 11:14:37,564 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Network id=210 is already implemented 2017-03-10 11:14:37,575 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Service SecurityGroup is not supported in the network id=210 2017-03-10 11:14:37,578 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Changing active number of nics for network id=210 on 1 2017-03-10 11:14:37,583 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Asking VirtualRouter to prepare for Nic[12-10-38d79f75-51f7-472e-ba88-ca485baab019-10.1.1.151] 2017-03-10 11:14:37,597 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Service SecurityGroup is not supported in the network id=210 2017-03-10 11:14:37,600 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) CONFIG DHCP FOR SUBNETS RULES 2017-03-10 11:14:37,610 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Service SecurityGroup is not supported in the network id=210 2017-03-10 11:14:37,613 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) APPLYING VPC DHCP ENTRY RULES 2017-03-10 11:14:37,613 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Applying dhcp entry in network Ntwk[210|Guest|8] 2017-03-10 11:14:37,629 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948023: Sending { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:55:92:00:01","vmIpAddress":"10.1.1.151","vmName":"testvm","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:55:92:00:01","isDefault":true,"executeInSequence":false,"accessDetails":{"router.name":"r-11-VM","router.guest.ip":"10.1.1.1","router.ip":"10.2.6.226","zone.network.type":"Advanced"},"wait":0}}] } 2017-03-10 11:14:37,630 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948023: Executing: { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:55:92:00:01","vmIpAddress":"10.1.1.151","vmName":"testvm","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:55:92:00:01","isDefault":true,"executeInSequence":false,"accessDetails":{"router.name":"r-11-VM","router.guest.ip":"10.1.1.1","router.ip":"10.2.6.226","zone.network.type":"Advanced"},"wait":0}}] } 2017-03-10 11:14:37,630 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-8:ctx-f84a82f5) (logid:234e2ac7) Seq 1-3028389274429948023: Executing request 2017-03-10 11:14:37,630 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-8:ctx-f84a82f5 10.2.2.23, job-48/job-51, cmd: DhcpEntryCommand) (logid:a7ff003b) Use router's private IP for SSH control. IP : 10.2.6.226 2017-03-10 11:14:37,630 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-8:ctx-f84a82f5 10.2.2.23, job-48/job-51, cmd: DhcpEntryCommand) (logid:a7ff003b) Transforming com.cloud.agent.api.routing.DhcpEntryCommand to ConfigItems 2017-03-10 11:14:37,867 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-8:ctx-f84a82f5 10.2.2.23, job-48/job-51, cmd: DhcpEntryCommand) (logid:a7ff003b) Processing FileConfigItem, copying 222 characters to vm_dhcp_entry.json took 237ms 2017-03-10 11:14:37,867 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-8:ctx-f84a82f5 10.2.2.23, job-48/job-51, cmd: DhcpEntryCommand) (logid:a7ff003b) Run command on VR: 10.2.6.226, script: update_config.py with args: vm_dhcp_entry.json 2017-03-10 11:14:38,017 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) SeqA 3-974: Processing Seq 3-974: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2017-03-10 11:14:38,034 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) (logid:) SeqA 3-974: Sending Seq 3-974: { Ans: , MgmtId: 7509951710985, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2017-03-10 11:14:38,425 INFO [c.c.h.v.r.VmwareResource] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) Scan hung worker VM to recycle 2017-03-10 11:14:38,507 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) Ping from 1(10.2.2.23) 2017-03-10 11:14:38,507 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) Process host VM state report from ping process. host: 1 2017-03-10 11:14:38,515 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) Process VM state report. host: 1, number of records in report: 4 2017-03-10 11:14:38,515 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM state report. host: 1, vm id: 1, power state: PowerOn 2017-03-10 11:14:38,517 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM power state does not change, skip DB writing. vm id: 1 2017-03-10 11:14:38,517 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM state report. host: 1, vm id: 2, power state: PowerOn 2017-03-10 11:14:38,519 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM power state does not change, skip DB writing. vm id: 2 2017-03-10 11:14:38,519 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM state report. host: 1, vm id: 10, power state: PowerOff 2017-03-10 11:14:38,525 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM state report is updated. host: 1, vm id: 10, power state: PowerOff 2017-03-10 11:14:38,527 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) There is pending job or HA tasks working on the VM. vm id: 10, postpone power-change report by resetting power-change counters 2017-03-10 11:14:38,532 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM state report. host: 1, vm id: 11, power state: PowerOn 2017-03-10 11:14:38,535 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) VM power state does not change, skip DB writing. vm id: 11 2017-03-10 11:14:38,538 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-78:ctx-b3ae1ec1) (logid:a5275a82) Done with process of VM state report. host: 1 2017-03-10 11:14:40,676 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-68315531) (logid:326f33ed) AutoScaling Monitor is running... 2017-03-10 11:14:40,716 DEBUG [c.c.s.StatsCollector] (StatsCollector-6:ctx-884a3664) (logid:b58709c7) VmStatsCollector is running... 2017-03-10 11:14:41,183 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-27152e46) (logid:6dcb8a3f) HostOutOfBandManagementStatsCollector is running... 2017-03-10 11:14:41,404 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-8:ctx-f84a82f5 10.2.2.23, job-48/job-51, cmd: DhcpEntryCommand) (logid:a7ff003b) update_config.py execution result: true 2017-03-10 11:14:41,404 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-8:ctx-f84a82f5 10.2.2.23, job-48/job-51, cmd: DhcpEntryCommand) (logid:a7ff003b) Processing ScriptConfigItem, executing update_config.py vm_dhcp_entry.json took 3537ms 2017-03-10 11:14:41,404 WARN [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-8:ctx-f84a82f5 10.2.2.23, job-48/job-51, cmd: DhcpEntryCommand) (logid:a7ff003b) Expected 1 answers while executing DhcpEntryCommand but received 2 2017-03-10 11:14:41,407 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-8:ctx-f84a82f5) (logid:a7ff003b) Seq 1-3028389274429948023: Response Received: 2017-03-10 11:14:41,407 DEBUG [c.c.a.t.Request] (DirectAgent-8:ctx-f84a82f5) (logid:a7ff003b) Seq 1-3028389274429948023: Processing: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: null","null - success: [INFO] update_config.py :: Processing incoming file => vm_dhcp_entry.json\n[INFO] Processing JSON file vm_dhcp_entry.json\ntestvm testvm\n"],"result":true,"wait":0}}] } 2017-03-10 11:14:41,408 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948023: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, { GroupAnswer } } 2017-03-10 11:14:41,413 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Service SecurityGroup is not supported in the network id=210 2017-03-10 11:14:41,416 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) APPLYING VPC USERDATA RULES 2017-03-10 11:14:41,416 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Applying userdata and password entry in network Ntwk[210|Guest|8] 2017-03-10 11:14:41,428 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948024: Sending { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1.151","vmName":"testvm","executeInSequence":false,"accessDetails":{"router.name":"r-11-VM","router.guest.ip":"10.1.1.1","router.ip":"10.2.6.226","zone.network.type":"Advanced"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.151","vmName":"testvm","executeInSequence":false,"accessDetails":{"router.name":"r-11-VM","router.guest.ip":"10.1.1.1","router.ip":"10.2.6.226","zone.network.type":"Advanced"},"wait":0}}] } 2017-03-10 11:14:41,429 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948024: Executing: { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1.151","vmName":"testvm","executeInSequence":false,"accessDetails":{"router.name":"r-11-VM","router.guest.ip":"10.1.1.1","router.ip":"10.2.6.226","zone.network.type":"Advanced"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.151","vmName":"testvm","executeInSequence":false,"accessDetails":{"router.name":"r-11-VM","router.guest.ip":"10.1.1.1","router.ip":"10.2.6.226","zone.network.type":"Advanced"},"wait":0}}] } 2017-03-10 11:14:41,430 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-31:ctx-e8641ff1) (logid:983f05a7) Seq 1-3028389274429948024: Executing request 2017-03-10 11:14:41,430 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: SavePasswordCommand) (logid:a7ff003b) Use router's private IP for SSH control. IP : 10.2.6.226 2017-03-10 11:14:41,430 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: SavePasswordCommand) (logid:a7ff003b) Transforming com.cloud.agent.api.routing.SavePasswordCommand to ConfigItems 2017-03-10 11:14:41,655 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: SavePasswordCommand) (logid:a7ff003b) Processing FileConfigItem, copying 75 characters to vm_password.json took 225ms 2017-03-10 11:14:41,655 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: SavePasswordCommand) (logid:a7ff003b) Run command on VR: 10.2.6.226, script: update_config.py with args: vm_password.json 2017-03-10 11:14:42,068 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-a3d020a7) (logid:2f2df8af) HostStatsCollector is running... 2017-03-10 11:14:42,074 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-60:ctx-c0cfd463) (logid:9669243b) Seq 1-3028389274429948025: Executing request 2017-03-10 11:14:42,110 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-60:ctx-c0cfd463) (logid:2f2df8af) Seq 1-3028389274429948025: Response Received: 2017-03-10 11:14:42,110 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-a3d020a7) (logid:2f2df8af) Seq 1-3028389274429948025: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2017-03-10 11:14:42,482 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-c048b152) (logid:f6cdb7ad) ===START=== 10.5.0.16 -- GET signature=LoKH18E%2BumJw3ssqNpgnzUVsFOY%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=a7ff003b-a183-4eb5-b20c-f8027d869cfb 2017-03-10 11:14:42,500 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-c048b152 ctx-51b538fb ctx-c977927a) (logid:f6cdb7ad) ===END=== 10.5.0.16 -- GET signature=LoKH18E%2BumJw3ssqNpgnzUVsFOY%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=a7ff003b-a183-4eb5-b20c-f8027d869cfb 2017-03-10 11:14:42,713 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) (logid:) Ping from 3(v-2-VM) 2017-03-10 11:14:42,740 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) Ping from 2(s-1-VM) 2017-03-10 11:14:43,018 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 3-976: Processing Seq 3-976: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2017-03-10 11:14:43,023 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 3-976: Sending Seq 3-976: { Ans: , MgmtId: 7509951710985, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2017-03-10 11:14:43,177 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: SavePasswordCommand) (logid:a7ff003b) update_config.py execution result: true 2017-03-10 11:14:43,177 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: SavePasswordCommand) (logid:a7ff003b) Processing ScriptConfigItem, executing update_config.py vm_password.json took 1522ms 2017-03-10 11:14:43,177 WARN [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: SavePasswordCommand) (logid:a7ff003b) Expected 1 answers while executing SavePasswordCommand but received 2 2017-03-10 11:14:43,180 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: VmDataCommand) (logid:a7ff003b) Use router's private IP for SSH control. IP : 10.2.6.226 2017-03-10 11:14:43,180 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: VmDataCommand) (logid:a7ff003b) Transforming com.cloud.agent.api.routing.VmDataCommand to ConfigItems 2017-03-10 11:14:43,396 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: VmDataCommand) (logid:a7ff003b) Processing FileConfigItem, copying 606 characters to vm_metadata.json took 216ms 2017-03-10 11:14:43,396 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: VmDataCommand) (logid:a7ff003b) Run command on VR: 10.2.6.226, script: update_config.py with args: vm_metadata.json 2017-03-10 11:14:44,896 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: VmDataCommand) (logid:a7ff003b) update_config.py execution result: true 2017-03-10 11:14:44,896 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: VmDataCommand) (logid:a7ff003b) Processing ScriptConfigItem, executing update_config.py vm_metadata.json took 1500ms 2017-03-10 11:14:44,896 WARN [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-31:ctx-e8641ff1 10.2.2.23, job-48/job-51, cmd: VmDataCommand) (logid:a7ff003b) Expected 1 answers while executing VmDataCommand but received 2 2017-03-10 11:14:44,897 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-31:ctx-e8641ff1) (logid:a7ff003b) Seq 1-3028389274429948024: Response Received: 2017-03-10 11:14:44,904 DEBUG [c.c.a.t.Request] (DirectAgent-31:ctx-e8641ff1) (logid:a7ff003b) Seq 1-3028389274429948024: Processing: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: null","null - success: [INFO] update_config.py :: Processing incoming file => vm_password.json\n[INFO] Processing JSON file vm_password.json\n"],"result":true,"wait":0}},{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: null","null - success: [INFO] update_config.py :: Processing incoming file => vm_metadata.json\n[INFO] Processing JSON file vm_metadata.json\n"],"result":true,"wait":0}}] } 2017-03-10 11:14:44,904 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948024: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, { GroupAnswer, GroupAnswer } } 2017-03-10 11:14:44,904 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Service SecurityGroup is not supported in the network id=210 2017-03-10 11:14:44,906 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Checking if we need to prepare 1 volumes for VM[User|i-10-10-VM] 2017-03-10 11:14:44,907 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) No need to recreate the volume: Vol[6|vm=10|ROOT], since it already has a pool assigned: 1, adding disk to VM 2017-03-10 11:14:44,927 DEBUG [c.c.h.g.VMwareGuru] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Nested virtualization requested, adding flag to vm configuration 2017-03-10 11:14:44,944 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948026: Sending { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":10,"name":"i-10-10-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":50,"maxSpeed":100,"minRam":268435456,"maxRam":268435456,"hostName":"testvm","arch":"x86_64","os":"CentOS 5.3 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"J1L2pS6dc-YxD48_Qpe3dQ","params":{"deployvm":"true","dataDiskController":"osdefault","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","nestedVirtualizationFlag":"false","rootdisksize":"4","cpuOvercommitRatio":"2.0","vmware.reserve.mem":"false","vmware.reserve.cpu":"false","nicAdapter":"E1000","rootDiskController":"ide"},"uuid":"8df10462-c45e-42b4-92ba-9e296abf6d98","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"dfefb860-f1bf-44b4-9cf7-d4797a89c421","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"45c46701-09f6-3ae1-b322-192709c67bf8","id":1,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1/?ROLE=Primary&STOREUUID=45c46701-09f6-3ae1-b322-192709c67bf8","isManaged":false}},"name":"ROOT-10","size":4294967296,"path":"ROOT-10-000001","volumeId":6,"vmName":"i-10-10-VM","accountId":10,"format":"OVA","provisioningType":"THIN","id":6,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-10-000001","type":"ROOT","_details":{"storageHost":"10.2.0.16","managed":"false","storagePort":"2049","volumeSize":"4294967296"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"24671fca-3893-4479-89f7-07d8d4c61bf8","uuid":"452d44e4-f887-4027-8338-f952d69e58ec","ip":"10.1.1.151","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:55:92:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://973","isolationUri":"vlan://973","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"}]},"hostIp":"10.2.2.23","executeInSequence":true,"wait":0}}] } 2017-03-10 11:14:44,944 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948026: Executing: { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":10,"name":"i-10-10-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":50,"maxSpeed":100,"minRam":268435456,"maxRam":268435456,"hostName":"testvm","arch":"x86_64","os":"CentOS 5.3 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"J1L2pS6dc-YxD48_Qpe3dQ","params":{"deployvm":"true","dataDiskController":"osdefault","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","nestedVirtualizationFlag":"false","rootdisksize":"4","cpuOvercommitRatio":"2.0","vmware.reserve.mem":"false","vmware.reserve.cpu":"false","nicAdapter":"E1000","rootDiskController":"ide"},"uuid":"8df10462-c45e-42b4-92ba-9e296abf6d98","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"dfefb860-f1bf-44b4-9cf7-d4797a89c421","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"45c46701-09f6-3ae1-b322-192709c67bf8","id":1,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1/?ROLE=Primary&STOREUUID=45c46701-09f6-3ae1-b322-192709c67bf8","isManaged":false}},"name":"ROOT-10","size":4294967296,"path":"ROOT-10-000001","volumeId":6,"vmName":"i-10-10-VM","accountId":10,"format":"OVA","provisioningType":"THIN","id":6,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-10-000001","type":"ROOT","_details":{"storageHost":"10.2.0.16","managed":"false","storagePort":"2049","volumeSize":"4294967296"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"24671fca-3893-4479-89f7-07d8d4c61bf8","uuid":"452d44e4-f887-4027-8338-f952d69e58ec","ip":"10.1.1.151","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:55:92:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://973","isolationUri":"vlan://973","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"}]},"hostIp":"10.2.2.23","executeInSequence":true,"wait":0}}] } 2017-03-10 11:14:44,945 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-61:ctx-ae919b27) (logid:1ad03ae9) Seq 1-3028389274429948026: Executing request 2017-03-10 11:14:44,945 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Executing resource StartCommand: {"vm":{"id":10,"name":"i-10-10-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":50,"maxSpeed":100,"minRam":268435456,"maxRam":268435456,"hostName":"testvm","arch":"x86_64","os":"CentOS 5.3 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"J1L2pS6dc-YxD48_Qpe3dQ","params":{"deployvm":"true","dataDiskController":"osdefault","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","nestedVirtualizationFlag":"false","rootdisksize":"4","cpuOvercommitRatio":"2.0","vmware.reserve.mem":"false","vmware.reserve.cpu":"false","nicAdapter":"E1000","rootDiskController":"ide"},"uuid":"8df10462-c45e-42b4-92ba-9e296abf6d98","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"dfefb860-f1bf-44b4-9cf7-d4797a89c421","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"45c46701-09f6-3ae1-b322-192709c67bf8","id":1,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1/?ROLE=Primary&STOREUUID=45c46701-09f6-3ae1-b322-192709c67bf8","isManaged":false}},"name":"ROOT-10","size":4294967296,"path":"ROOT-10-000001","volumeId":6,"vmName":"i-10-10-VM","accountId":10,"format":"OVA","provisioningType":"THIN","id":6,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-10-000001","type":"ROOT","_details":{"storageHost":"10.2.0.16","managed":"false","storagePort":"2049","volumeSize":"4294967296"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"24671fca-3893-4479-89f7-07d8d4c61bf8","uuid":"452d44e4-f887-4027-8338-f952d69e58ec","ip":"10.1.1.151","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:55:92:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://973","isolationUri":"vlan://973","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"}]},"hostIp":"10.2.2.23","executeInSequence":true,"wait":0} 2017-03-10 11:14:44,979 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Using mapping name : CENTOS_64_GUEST 2017-03-10 11:14:45,002 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) find VM i-10-10-VM on host 2017-03-10 11:14:45,002 INFO [c.c.h.v.m.HostMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) VM i-10-10-VM not found in host cache 2017-03-10 11:14:45,002 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) load VM cache on host 2017-03-10 11:14:45,017 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) VM i-10-10-VM already exists, tear down devices for reconfiguration 2017-03-10 11:14:45,438 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-550ee1fc) (logid:7a3fa43d) Begin cleanup expired async-jobs 2017-03-10 11:14:45,442 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-550ee1fc) (logid:7a3fa43d) End cleanup expired async-jobs 2017-03-10 11:14:46,185 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-d526c460) (logid:6802ce51) HostOutOfBandManagementStatsCollector is running... 2017-03-10 11:14:46,591 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-34ea1edc) (logid:4ed3ed37) StorageCollector is running... 2017-03-10 11:14:46,598 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-34ea1edc) (logid:4ed3ed37) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2017-03-10 11:14:46,598 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-34ea1edc) (logid:4ed3ed37) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2017-03-10 11:14:46,672 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-34ea1edc) (logid:4ed3ed37) Seq 2-1597089017856262181: Received: { Ans: , MgmtId: 7509951710985, via: 2(s-1-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2017-03-10 11:14:46,674 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-4:ctx-34ea1edc) (logid:4ed3ed37) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2017-03-10 11:14:46,674 DEBUG [c.c.h.XenServerGuru] (StatsCollector-4:ctx-34ea1edc) (logid:4ed3ed37) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand 2017-03-10 11:14:46,676 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-122:ctx-97d11e6d) (logid:12d16bc2) Seq 1-3028389274429948027: Executing request 2017-03-10 11:14:46,731 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-122:ctx-97d11e6d 10.2.2.23, cmd: GetStorageStatsCommand) (logid:4ed3ed37) Datastore summary info, storageId: 45c46701-09f6-3ae1-b322-192709c67bf8, localPath: /acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1, poolType: NetworkFilesystem, capacity: 7514055770112, free: 7305365643264, used: 208690126848 2017-03-10 11:14:46,734 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-122:ctx-97d11e6d) (logid:4ed3ed37) Seq 1-3028389274429948027: Response Received: 2017-03-10 11:14:46,734 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-34ea1edc) (logid:4ed3ed37) Seq 1-3028389274429948027: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2017-03-10 11:14:47,036 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Prepare ISO volume at existing device {"key":3000,"deviceInfo":{"label":"CD/DVD drive 1","summary":"Remote device"},"backing":{"exclusive":false,"deviceName":""},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":0} 2017-03-10 11:14:47,059 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Found existing disk info from volume path: ROOT-10-000001 2017-03-10 11:14:47,059 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Chose disk controller based on existing information: ide0:1 2017-03-10 11:14:47,059 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Chose disk controller based on existing information: ide0:1 2017-03-10 11:14:47,079 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Prepare volume at new device {"capacityInKB":0,"key":-2,"backing":{"diskMode":"persistent","fileName":"[45c4670109f63ae1b322192709c67bf8] i-10-10-VM/ROOT-10-000001.vmdk","datastore":{"value":"datastore-32","type":"Datastore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":1} 2017-03-10 11:14:47,079 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) VM i-10-10-VM will be started with NIC device type: E1000 2017-03-10 11:14:47,079 INFO [c.c.u.n.n.p.NiciraNvpApiVersion] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) NSX API VERSION: NOT PRESENT 2017-03-10 11:14:47,080 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Prepare NIC device based on NicTO: {"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"24671fca-3893-4479-89f7-07d8d4c61bf8","uuid":"452d44e4-f887-4027-8338-f952d69e58ec","ip":"10.1.1.151","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:55:92:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://973","isolationUri":"vlan://973","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"} 2017-03-10 11:14:47,087 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Prepare network on vmwaresvs vSwitch1 with name prefix: cloud.guest 2017-03-10 11:14:47,184 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Network cloud.guest.973.200.1-vSwitch1 is ready on vSwitch vSwitch1 2017-03-10 11:14:47,185 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Preparing NIC device on network cloud.guest.973.200.1-vSwitch1 2017-03-10 11:14:47,185 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Prepare NIC at new device {"operation":"ADD","device":{"addressType":"Manual","macAddress":"02:00:55:92:00:01","key":-3,"backing":{"network":{"value":"network-51","type":"Network"},"deviceName":"cloud.guest.973.200.1-vSwitch1"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":0}} 2017-03-10 11:14:47,185 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) find VM i-10-10-VM on host 2017-03-10 11:14:47,185 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) VM i-10-10-VM found in host cache 2017-03-10 11:14:47,213 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Configure VNC port for VM i-10-10-VM, port: 5938, host: 10.2.2.23 2017-03-10 11:14:47,511 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-ebd84624) (logid:983bf847) ===START=== 10.5.0.16 -- GET signature=LoKH18E%2BumJw3ssqNpgnzUVsFOY%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=a7ff003b-a183-4eb5-b20c-f8027d869cfb 2017-03-10 11:14:47,531 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-ebd84624 ctx-ac8853b9 ctx-5589d694) (logid:983bf847) ===END=== 10.5.0.16 -- GET signature=LoKH18E%2BumJw3ssqNpgnzUVsFOY%3D&apiKey=LIN6rqXuaJwMPfGYFh13qDwYz5VNNz1J2J6qIOWcd3oLQOq0WtD4CwRundBL6rzXToa3lQOC_vKjI3nkHtiD8Q&command=queryAsyncJobResult&response=json&jobid=a7ff003b-a183-4eb5-b20c-f8027d869cfb 2017-03-10 11:14:48,019 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) (logid:) SeqA 3-977: Processing Seq 3-977: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2017-03-10 11:14:48,025 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) (logid:) SeqA 3-977: Sending Seq 3-977: { Ans: , MgmtId: 7509951710985, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2017-03-10 11:14:48,437 INFO [c.c.h.v.r.VmwareResource] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) Scan hung worker VM to recycle 2017-03-10 11:14:48,519 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) Ping from 1(10.2.2.23) 2017-03-10 11:14:48,519 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) Process host VM state report from ping process. host: 1 2017-03-10 11:14:48,526 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) Process VM state report. host: 1, number of records in report: 4 2017-03-10 11:14:48,526 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM state report. host: 1, vm id: 1, power state: PowerOn 2017-03-10 11:14:48,529 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM power state does not change, skip DB writing. vm id: 1 2017-03-10 11:14:48,529 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM state report. host: 1, vm id: 2, power state: PowerOn 2017-03-10 11:14:48,531 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM power state does not change, skip DB writing. vm id: 2 2017-03-10 11:14:48,531 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM state report. host: 1, vm id: 10, power state: PowerOff 2017-03-10 11:14:48,536 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM state report is updated. host: 1, vm id: 10, power state: PowerOff 2017-03-10 11:14:48,538 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) There is pending job or HA tasks working on the VM. vm id: 10, postpone power-change report by resetting power-change counters 2017-03-10 11:14:48,544 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM state report. host: 1, vm id: 11, power state: PowerOn 2017-03-10 11:14:48,547 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) VM power state does not change, skip DB writing. vm id: 11 2017-03-10 11:14:48,551 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgentCronJob-117:ctx-5ab0c3cc) (logid:022e1ab8) Done with process of VM state report. host: 1 2017-03-10 11:14:49,664 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-c97b4315) (logid:29c9207f) ===START=== 10.1.0.1 -- GET command=listVirtualMachines&response=json&listAll=true&page=1&pagesize=20&_=1489144523687 2017-03-10 11:14:49,690 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-c97b4315 ctx-614008fe) (logid:29c9207f) ===END=== 10.1.0.1 -- GET command=listVirtualMachines&response=json&listAll=true&page=1&pagesize=20&_=1489144523687 2017-03-10 11:14:49,859 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Look for disk device info for volume : ROOT-10-000001.vmdk with base name: ROOT-10-000001 2017-03-10 11:14:49,859 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Test against disk device, controller key: 200, unit number: 1 2017-03-10 11:14:49,859 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Test against disk backing : [45c4670109f63ae1b322192709c67bf8] i-10-10-VM/ROOT-10-000001.vmdk 2017-03-10 11:14:49,861 INFO [c.c.h.v.m.VirtualMachineMO] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Disk backing : [45c4670109f63ae1b322192709c67bf8] i-10-10-VM/ROOT-10-000001.vmdk matches ==> ide0:1 2017-03-10 11:14:49,892 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Found existing disk info from volume path: ROOT-10-000001 2017-03-10 11:14:49,892 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) Unsupported root disk device bus ide0:1 2017-03-10 11:14:49,892 INFO [c.c.h.v.u.VmwareHelper] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) [ignored]failed toi get message for exception: Unsupported root disk device bus ide0:1 2017-03-10 11:14:49,892 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-61:ctx-ae919b27 10.2.2.23, job-48/job-51, cmd: StartCommand) (logid:a7ff003b) StartCommand failed due to Exception: java.lang.Exception Message: Unsupported root disk device bus ide0:1 java.lang.Exception: Unsupported root disk device bus ide0:1 at com.cloud.hypervisor.vmware.resource.VmwareResource.resizeRootDisk(VmwareResource.java:2111) at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2029) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:467) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2017-03-10 11:14:49,895 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-61:ctx-ae919b27) (logid:a7ff003b) Seq 1-3028389274429948026: Response Received: 2017-03-10 11:14:49,896 DEBUG [c.c.a.t.Request] (DirectAgent-61:ctx-ae919b27) (logid:a7ff003b) Seq 1-3028389274429948026: Processing: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":10,"name":"i-10-10-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":50,"maxSpeed":100,"minRam":268435456,"maxRam":268435456,"hostName":"testvm","arch":"x86_64","os":"CentOS 5.3 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"J1L2pS6dc-YxD48_Qpe3dQ","params":{"deployvm":"true","dataDiskController":"osdefault","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","nestedVirtualizationFlag":"false","rootdisksize":"4","cpuOvercommitRatio":"2.0","vmware.reserve.mem":"false","vmware.reserve.cpu":"false","nicAdapter":"E1000","rootDiskController":"ide"},"uuid":"8df10462-c45e-42b4-92ba-9e296abf6d98","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"dfefb860-f1bf-44b4-9cf7-d4797a89c421","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"45c46701-09f6-3ae1-b322-192709c67bf8","id":1,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/pr1813-t948-vmware-55u3/pr1813-t948-vmware-55u3-esxi-pri1/?ROLE=Primary&STOREUUID=45c46701-09f6-3ae1-b322-192709c67bf8","isManaged":false}},"name":"ROOT-10","size":4294967296,"path":"ROOT-10-000001","volumeId":6,"vmName":"i-10-10-VM","accountId":10,"format":"OVA","provisioningType":"THIN","id":6,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-10-000001","type":"ROOT","_details":{"storageHost":"10.2.0.16","managed":"false","storagePort":"2049","volumeSize":"4294967296"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"24671fca-3893-4479-89f7-07d8d4c61bf8","uuid":"452d44e4-f887-4027-8338-f952d69e58ec","ip":"10.1.1.151","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:55:92:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://973","isolationUri":"vlan://973","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"}]},"result":false,"details":"StartCommand failed due to Exception: java.lang.Exception\nMessage: Unsupported root disk device bus ide0:1\n","wait":0}}] } 2017-03-10 11:14:49,896 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-61:ctx-ae919b27) (logid:a7ff003b) Seq 1-3028389274429948026: No more commands found 2017-03-10 11:14:49,896 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948026: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, { StartAnswer } } 2017-03-10 11:14:49,903 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Unable to start VM on Host[-1-Routing] due to StartCommand failed due to Exception: java.lang.Exception Message: Unsupported root disk device bus ide0:1 2017-03-10 11:14:49,908 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Cleaning up resources for the vm VM[User|i-10-10-VM] in Starting state 2017-03-10 11:14:49,911 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948028: Sending { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-10-10-VM","executeInSequence":true,"wait":0}}] } 2017-03-10 11:14:49,911 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948028: Executing: { Cmd , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-10-10-VM","executeInSequence":true,"wait":0}}] } 2017-03-10 11:14:49,911 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-123:ctx-a70f253a) (logid:af51f8a7) Seq 1-3028389274429948028: Executing request 2017-03-10 11:14:49,911 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-123:ctx-a70f253a 10.2.2.23, job-48/job-51, cmd: StopCommand) (logid:a7ff003b) Executing resource StopCommand: {"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-10-10-VM","executeInSequence":true,"wait":0} 2017-03-10 11:14:49,925 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-123:ctx-a70f253a 10.2.2.23, job-48/job-51, cmd: StopCommand) (logid:a7ff003b) find VM i-10-10-VM on host 2017-03-10 11:14:49,925 INFO [c.c.h.v.m.HostMO] (DirectAgent-123:ctx-a70f253a 10.2.2.23, job-48/job-51, cmd: StopCommand) (logid:a7ff003b) VM i-10-10-VM not found in host cache 2017-03-10 11:14:49,925 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-123:ctx-a70f253a 10.2.2.23, job-48/job-51, cmd: StopCommand) (logid:a7ff003b) load VM cache on host 2017-03-10 11:14:50,005 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-123:ctx-a70f253a 10.2.2.23, job-48/job-51, cmd: StopCommand) (logid:a7ff003b) VM i-10-10-VM is already in stopped state 2017-03-10 11:14:50,007 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-123:ctx-a70f253a) (logid:a7ff003b) Seq 1-3028389274429948028: Response Received: 2017-03-10 11:14:50,007 DEBUG [c.c.a.t.Request] (DirectAgent-123:ctx-a70f253a) (logid:a7ff003b) Seq 1-3028389274429948028: Processing: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-10-10-VM is already in stopped state","wait":0}}] } 2017-03-10 11:14:50,007 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-123:ctx-a70f253a) (logid:a7ff003b) Seq 1-3028389274429948028: No more commands found 2017-03-10 11:14:50,007 DEBUG [c.c.a.t.Request] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Seq 1-3028389274429948028: Received: { Ans: , MgmtId: 7509951710985, via: 1(10.2.2.23), Ver: v1, Flags: 110, { StopAnswer } } 2017-03-10 11:14:50,014 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Service SecurityGroup is not supported in the network id=210 2017-03-10 11:14:50,016 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Changing active number of nics for network id=210 on -1 2017-03-10 11:14:50,024 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Asking VirtualRouter to release NicProfile[12-10-38d79f75-51f7-472e-ba88-ca485baab019-10.1.1.151-null 2017-03-10 11:14:50,024 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Successfully released network resources for the vm VM[User|i-10-10-VM] 2017-03-10 11:14:50,024 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Successfully cleanued up resources for the vm VM[User|i-10-10-VM] in Starting state 2017-03-10 11:14:50,026 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Root volume is ready, need to place VM in volume's cluster 2017-03-10 11:14:50,026 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Vol[6|vm=10|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1 2017-03-10 11:14:50,032 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Deploy avoids pods: [], clusters: [], hosts: [1] 2017-03-10 11:14:50,033 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@7ab88384 2017-03-10 11:14:50,033 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 100, requested ram: 268435456 2017-03-10 11:14:50,033 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Is ROOT volume READY (pool already allocated)?: Yes 2017-03-10 11:14:50,033 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Searching resources only under specified Cluster: 1 2017-03-10 11:14:50,041 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Checking resources in Cluster: 1 under Pod: 1 2017-03-10 11:14:50,041 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Looking for hosts in dc: 1 pod:1 cluster:1 2017-03-10 11:14:50,043 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] 2017-03-10 11:14:50,046 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] 2017-03-10 11:14:50,046 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Looking for speed=100Mhz, Ram=256 2017-03-10 11:14:50,047 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Host name: 10.2.2.23, hostId: 1 is in avoid set, skipping this and trying other available hosts 2017-03-10 11:14:50,047 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f FirstFitRoutingAllocator) (logid:a7ff003b) Host Allocator returning 0 suitable hosts 2017-03-10 11:14:50,047 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) No suitable hosts found 2017-03-10 11:14:50,047 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) No suitable hosts found under this Cluster: 1 2017-03-10 11:14:50,047 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Could not find suitable Deployment Destination for this VM under any clusters, returning. 2017-03-10 11:14:50,047 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Searching resources only under specified Cluster: 1 2017-03-10 11:14:50,048 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) The specified cluster is in avoid set, returning. 2017-03-10 11:14:50,054 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Deploy avoids pods: [], clusters: [1], hosts: [1] 2017-03-10 11:14:50,055 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@7ab88384 2017-03-10 11:14:50,055 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 100, requested ram: 268435456 2017-03-10 11:14:50,055 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Is ROOT volume READY (pool already allocated)?: No 2017-03-10 11:14:50,055 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Searching resources only under specified Pod: 1 2017-03-10 11:14:50,055 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1 2017-03-10 11:14:50,059 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Removing from the clusterId list these clusters from avoid set: [1] 2017-03-10 11:14:50,061 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) No clusters found after removing disabled clusters and clusters in avoid list, returning. 2017-03-10 11:14:50,074 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1 2017-03-10 11:14:50,079 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Hosts's actual total CPU: 4797 and CPU after applying overprovisioning: 9594 2017-03-10 11:14:50,079 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Hosts's actual total RAM: 8589398016 and RAM after applying overprovisioning: 8589398016 2017-03-10 11:14:50,079 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) release cpu from host: 1, old used: 1600,reserved: 0, actual total: 4797, total with overprovisioning: 9594; new used: 1500,reserved:0; movedfromreserved: false,moveToReserveredfalse 2017-03-10 11:14:50,079 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) release mem from host: 1, old used: 2147483648,reserved: 0, total: 8589398016; new used: 1879048192,reserved:0; movedfromreserved: false,moveToReserveredfalse 2017-03-10 11:14:50,099 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-10-10-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2017-03-10 11:14:50,100 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51 ctx-5314038f) (logid:a7ff003b) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-10-10-VM]Scope=interface com.cloud.dc.DataCenter; id=1 2017-03-10 11:14:50,100 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 10, job origin: 48 2017-03-10 11:14:50,100 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Unable to complete AsyncJobVO {id:51, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAACnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 7509951710985, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Mar 10 11:14:35 UTC 2017}, job origin:48 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-10-10-VM]Scope=interface com.cloud.dc.DataCenter; id=1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:961) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4661) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4822) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:502) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 2017-03-10 11:14:50,102 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Complete async job-51, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA1VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0xMC0xMC1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABVzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AAp4cAAAA8F0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEAABI1cQB-ABNxAH4AFHEAfgAVc3EAfgAR_____nQAJHN1bi5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHNxAH4AEQAAAD5xAH4AGHEAfgAZdAAGaW52b2tlc3EAfgARAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AHHNxAH4AEQAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAcc3EAfgARAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4AEQAAEtZxAH4AE3EAfgAUcQB-ACZzcQB-ABEAAABmdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-ABEAAAIqdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgARAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgARAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4AEQAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADZ0AA9jYWxsV2l0aENvbnRleHRzcQB-ABEAAAA1cQB-ADlxAH4ANnQADnJ1bldpdGhDb250ZXh0c3EAfgARAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAycQB-ADNzcQB-ABEAAAH2cQB-AC1xAH4ALnEAfgAzc3EAfgARAAAB_3QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA3c3EAfgARAAABCnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AM3NxAH4AEQAABHZ0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAml0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEhxAH4AM3NxAH4AEQAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AM3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFR4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcQB-AFMAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFYAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlcrLxCuun53i-AgAAeHAA 2017-03-10 11:14:50,103 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Publish async job-51 complete on message bus 2017-03-10 11:14:50,103 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Wake up jobs related to job-51 2017-03-10 11:14:50,103 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Update db status for job-51 2017-03-10 11:14:50,106 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Wake up jobs joined with job-51 and disjoin all subjobs created from job- 51 2017-03-10 11:14:50,116 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Done executing com.cloud.vm.VmWorkStart for job-51 2017-03-10 11:14:50,118 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-10:ctx-9d131260 job-48/job-51) (logid:a7ff003b) Remove job-51 from job monitoring 2017-03-10 11:14:50,131 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48 ctx-da924d49) (logid:a7ff003b) Destroying vm VM[User|i-10-10-VM] as it failed to create on Host with Id:null 2017-03-10 11:14:50,146 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48 ctx-da924d49) (logid:a7ff003b) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null 2017-03-10 11:14:50,178 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48 ctx-da924d49) (logid:a7ff003b) Access granted to Acct[2144faad-0578-11e7-b2b1-06d48c010709-admin] to Domain:1/ by AffinityGroupAccessChecker 2017-03-10 11:14:50,184 WARN [o.a.c.alerts] (API-Job-Executor-9:ctx-59002dba job-48 ctx-da924d49) (logid:a7ff003b) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 10, on Host with Id: null 2017-03-10 11:14:50,215 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-9:ctx-59002dba job-48) (logid:a7ff003b) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to insufficient capacity at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:623) at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:242) at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4097) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3695) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3683) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) at com.sun.proxy.$Proxy205.startVirtualMachine(Unknown Source) at org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(DeployVMCmdByAdmin.java:50) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:502) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-10-10-VM]Scope=interface com.cloud.dc.DataCenter; id=1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:961) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4661) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ... 18 more 2017-03-10 11:14:50,216 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48) (logid:a7ff003b) Complete async job-48, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to start a VM due to insufficient capacity"} 2017-03-10 11:14:50,228 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48) (logid:a7ff003b) Publish async job-48 complete on message bus 2017-03-10 11:14:50,228 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48) (logid:a7ff003b) Wake up jobs related to job-48 2017-03-10 11:14:50,228 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48) (logid:a7ff003b) Update db status for job-48 2017-03-10 11:14:50,229 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48) (logid:a7ff003b) Wake up jobs joined with job-48 and disjoin all subjobs created from job- 48 2017-03-10 11:14:50,235 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-9:ctx-59002dba job-48) (logid:a7ff003b) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-48