Github user borisstoyanov commented on the issue:
https://github.com/apache/cloudstack/pull/1813
Hi @serg38 ,
Here's the management log:
```
2017-03-04 20:43:40,972 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-249:ctx-585f426d 10.2.2.73, job-29/job-32, cmd: StartCommand)
(logid:b0dca526) Found existing disk info from volume path: ROOT-3
2017-03-04 20:43:40,972 ERROR [c.c.h.v.r.VmwareResource]
(DirectAgent-249:ctx-585f426d 10.2.2.73, job-29/job-32, cmd: StartCommand)
(logid:b0dca526) Unsupported Disk chain length 2
2017-03-04 20:43:40,972 INFO [c.c.h.v.u.VmwareHelper]
(DirectAgent-249:ctx-585f426d 10.2.2.73, job-29/job-32, cmd: StartCommand)
(logid:b0dca526) [ignored]failed toi get message for exception: Unsupported
Disk chain length 2
2017-03-04 20:43:40,975 WARN [c.c.h.v.r.VmwareResource]
(DirectAgent-249:ctx-585f426d 10.2.2.73, job-29/job-32, cmd: StartCommand)
(logid:b0dca526) StartCommand failed due to Exception: java.lang.Exception
Message: Unsupported Disk chain length 2
java.lang.Exception: Unsupported Disk chain length 2
at
com.cloud.hypervisor.vmware.resource.VmwareResource.resizeRootDisk(VmwareResource.java:2106)
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-04 20:43:40,975 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-249:ctx-585f426d) (logid:b0dca526) Seq 1-6353453174312927730:
Response Received:
2017-03-04 20:43:40,976 DEBUG [c.c.a.t.Request]
(DirectAgent-249:ctx-585f426d) (logid:b0dca526) Seq 1-6353453174312927730:
Processing: { Ans: , MgmtId: 7267420276525, via: 1(10.2.2.73), Ver: v1, Flags:
10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":3,"name":"i-4-3-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":"pztIl7EL8AvGJtkrL8TuMQ","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":"125b41bb-2d1f-4ab5-8bc4-493f4873fe86","disks":[{"data":{"
org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"abf2b785-936b-40f8-91b0-0e7f62d3620f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"bdcf18cf-79d5-3459-a681-225d15719513","id":1,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/pr1813-t931-vmware-55u3/pr1813-t931-vmware-55u3-esxi-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/pr1813-t931-vmware-55u3/pr1813-t931-vmware-55u3-esxi-pri1/?ROLE=Primary&STOREUUID=bdcf18cf-79d5-3459-a681-225d15719513","isManaged":false}},"name":"ROOT-3","size":4294967296,"path":"ROOT-3","volumeId":3,"vmName":"i-4-3-VM","accountId":4,"format":"OVA","provisioningType":"THIN","id":3,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-3","type":"ROOT","_details":{"storageHost":"10.2.0.16","managed":"false","storagePort":"2049","volumeSize":"4294967296"}},{"data":{"org.apache.clo
udstack.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":"1de3e11d-057c-4d5d-9a06-0bed9686efbd","uuid":"ed0b21f4-04a2-442d-ba0b-3c6276f3e96a","ip":"10.1.1.234","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:38:f0:00:01","dns1":"8.8.8.8","dns2":"8.8.4.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://889","isolationUri":"vlan://889","isSecurityGroupEnabled":false,"name":"vSwitch1,,vmwaresvs"}]},"result":false,"details":"StartCommand
failed due to Exception: java.lang.Exception\nMessage: Unsupported Disk chain
length 2\n","wait":0}}] }
2017-03-04 20:43:40,976 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Seq 1-6353453174312927730: Received: { Ans: , MgmtId: 7267420276525, via:
1(10.2.2.73), Ver: v1, Flags: 10, { StartAnswer } }
2017-03-04 20:43:40,979 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Unable to start VM on Host[-1-Routing] due to StartCommand failed due to
Exception: java.lang.Exception
Message: Unsupported Disk chain length 2
2017-03-04 20:43:40,982 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Cleaning up resources for the vm VM[User|i-4-3-VM] in Starting state
2017-03-04 20:43:40,983 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Seq 1-6353453174312927733: Sending { Cmd , MgmtId: 7267420276525, via:
1(10.2.2.73), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-4-3-VM","executeInSequence":false,"wait":0}}]
}
2017-03-04 20:43:40,983 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Seq 1-6353453174312927733: Executing: { Cmd , MgmtId: 7267420276525, via:
1(10.2.2.73), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-4-3-VM","executeInSequence":false,"wait":0}}]
}
2017-03-04 20:43:40,983 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-63:ctx-6366c90c) (logid:69a12df2) Seq 1-6353453174312927733:
Executing request
2017-03-04 20:43:40,983 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-63:ctx-6366c90c 10.2.2.73, job-29/job-32, cmd: StopCommand)
(logid:b0dca526) Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-4-3-VM","executeInSequence":false,"wait":0}
2017-03-04 20:43:40,994 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-63:ctx-6366c90c 10.2.2.73, job-29/job-32, cmd: StopCommand)
(logid:b0dca526) find VM i-4-3-VM on host
2017-03-04 20:43:40,994 INFO [c.c.h.v.m.HostMO]
(DirectAgent-63:ctx-6366c90c 10.2.2.73, job-29/job-32, cmd: StopCommand)
(logid:b0dca526) VM i-4-3-VM not found in host cache
2017-03-04 20:43:40,994 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-63:ctx-6366c90c 10.2.2.73, job-29/job-32, cmd: StopCommand)
(logid:b0dca526) load VM cache on host
2017-03-04 20:43:41,043 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-63:ctx-6366c90c 10.2.2.73, job-29/job-32, cmd: StopCommand)
(logid:b0dca526) VM i-4-3-VM is already in stopped state
2017-03-04 20:43:41,043 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-63:ctx-6366c90c) (logid:b0dca526) Seq 1-6353453174312927733:
Response Received:
2017-03-04 20:43:41,043 DEBUG [c.c.a.t.Request]
(DirectAgent-63:ctx-6366c90c) (logid:b0dca526) Seq 1-6353453174312927733:
Processing: { Ans: , MgmtId: 7267420276525, via: 1(10.2.2.73), Ver: v1, Flags:
10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-4-3-VM is
already in stopped state","wait":0}}] }
2017-03-04 20:43:41,043 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Seq 1-6353453174312927733: Received: { Ans: , MgmtId: 7267420276525, via:
1(10.2.2.73), Ver: v1, Flags: 10, { StopAnswer } }
2017-03-04 20:43:41,047 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Service SecurityGroup is not supported in the network id=204
2017-03-04 20:43:41,048 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Changing active number of nics for network id=204 on -1
2017-03-04 20:43:41,053 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Asking VirtualRouter to release
NicProfile[7-3-63bdc82b-0377-455e-8015-940282d98400-10.1.1.234-null
2017-03-04 20:43:41,053 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Successfully released network resources for the vm VM[User|i-4-3-VM]
2017-03-04 20:43:41,053 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Successfully cleanued up resources for the vm VM[User|i-4-3-VM] in Starting
state
2017-03-04 20:43:41,054 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Root volume is ready, need to place VM in volume's cluster
2017-03-04 20:43:41,054 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Vol[3|vm=3|ROOT] is READY, changing deployment plan to use this pool's dcId: 1
, podId: 1 , and clusterId: 1
2017-03-04 20:43:41,058 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Deploy avoids pods: [], clusters: [], hosts: [1]
2017-03-04 20:43:41,058 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@23d20e4e
2017-03-04 20:43:41,058 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1,
requested cpu: 100, requested ram: 268435456
2017-03-04 20:43:41,058 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Is ROOT volume READY (pool already allocated)?: Yes
2017-03-04 20:43:41,058 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Searching resources only under specified Cluster: 1
2017-03-04 20:43:41,063 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Checking resources in Cluster: 1 under Pod: 1
2017-03-04 20:43:41,063 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea
FirstFitRoutingAllocator) (logid:b0dca526) Looking for hosts in dc: 1 pod:1
cluster:1
2017-03-04 20:43:41,064 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea
FirstFitRoutingAllocator) (logid:b0dca526) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-1-Routing]]
2017-03-04 20:43:41,066 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea
FirstFitRoutingAllocator) (logid:b0dca526) Found 1 hosts for allocation after
prioritization: [Host[-1-Routing]]
2017-03-04 20:43:41,066 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea
FirstFitRoutingAllocator) (logid:b0dca526) Looking for speed=100Mhz, Ram=256
2017-03-04 20:43:41,066 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea
FirstFitRoutingAllocator) (logid:b0dca526) Host name: 10.2.2.73, hostId: 1 is
in avoid set, skipping this and trying other available hosts
2017-03-04 20:43:41,066 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea
FirstFitRoutingAllocator) (logid:b0dca526) Host Allocator returning 0 suitable
hosts
2017-03-04 20:43:41,066 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
No suitable hosts found
2017-03-04 20:43:41,066 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
No suitable hosts found under this Cluster: 1
2017-03-04 20:43:41,067 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Could not find suitable Deployment Destination for this VM under any clusters,
returning.
2017-03-04 20:43:41,067 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Searching resources only under specified Cluster: 1
2017-03-04 20:43:41,067 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
The specified cluster is in avoid set, returning.
2017-03-04 20:43:41,070 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Deploy avoids pods: [], clusters: [1], hosts: [1]
2017-03-04 20:43:41,071 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@23d20e4e
2017-03-04 20:43:41,071 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null,
requested cpu: 100, requested ram: 268435456
2017-03-04 20:43:41,071 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Is ROOT volume READY (pool already allocated)?: No
2017-03-04 20:43:41,071 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Searching resources only under specified Pod: 1
2017-03-04 20:43:41,071 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Listing clusters in order of aggregate capacity, that have (atleast one host
with) enough CPU and RAM capacity under this Pod: 1
2017-03-04 20:43:41,073 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Removing from the clusterId list these clusters from avoid set: [1]
2017-03-04 20:43:41,074 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
No clusters found after removing disabled clusters and clusters in avoid list,
returning.
2017-03-04 20:43:41,083 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
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-04 20:43:41,086 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Hosts's actual total CPU: 4797 and CPU after applying overprovisioning: 9594
2017-03-04 20:43:41,086 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Hosts's actual total RAM: 8589398016 and RAM after applying overprovisioning:
8589398016
2017-03-04 20:43:41,086 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
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-04 20:43:41,086 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
release mem from host: 1, old used: 2147483648,reserved: 0, total: 8589398016;
new used: 1879048192,reserved:0; movedfromreserved: false,moveToReserveredfalse
2017-03-04 20:43:41,096 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-4-3-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2017-03-04 20:43:41,096 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32 ctx-cf9f4cea) (logid:b0dca526)
Rethrow exception com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM[User|i-4-3-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2017-03-04 20:43:41,096 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Done with run
of VM work job: com.cloud.vm.VmWorkStart for VM 3, job origin: 29
2017-03-04 20:43:41,096 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Unable to
complete AsyncJobVO {id:32, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAA3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b
3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status:
IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid:
7267420276525, completeMsid: null, lastUpdated: null, lastPolled: null,
created: Sat Mar 04 20:43:27 UTC 2017}, job origin:29
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-4-3-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-04 20:43:41,098 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Complete
async job-32, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAAzVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9
yIFZNW1VzZXJ8aS00LTMtVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAVc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKeHAAAAPBdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0c3EAfgARAAASNXEAfgATcQB-ABRxAH4AFXNxAH4AEf____50ACRzdW4ucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTBzcQB-ABEAAAA-cQB-ABhxAH4AGXQABmludm9rZXNxAH4AEQAAACt0AChzdW4ucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABxzcQB-ABEAAAHydAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AHHNxAH4AEQAAAGt0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JzcQB-ABEAABLWcQB-ABNxAH4AFHEAfgAmc3EAfgARAAAAZnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3Jr
Sm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgARAAACKnQAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4AEQAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4AEQAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-ABEAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgA2dAAPY2FsbFdpdGhDb250ZXh0c3EAfgARAAAANXEAfgA5cQB-ADZ0AA5ydW5XaXRoQ29udGV4dHNxAH4AEQAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AMnEAfgAzc3EAfgARAAAB9nEAfgAtcQB-AC5xAH4AM3NxAH4AEQAAAf90AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AN3NxAH4AEQAAAQp0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0d
XJlVGFzay5qYXZhcQB-ADNzcQB-ABEAAAR2dAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJzcQB-ABEAAAJpdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBIcQB-ADNzcQB-ABEAAALpdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADNzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUxteyOEAIAAUwABGxpc3RxAH4ADHhyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlQ29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgBUeHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3EAfgBTAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBWAAAAAAAAAAF2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXKy8Qrrp-d4vgIAAHhwAA
2017-03-04 20:43:41,098 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Publish async
job-32 complete on message bus
2017-03-04 20:43:41,098 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Wake up jobs
related to job-32
2017-03-04 20:43:41,098 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Update db
status for job-32
2017-03-04 20:43:41,099 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Wake up jobs
joined with job-32 and disjoin all subjobs created from job- 32
2017-03-04 20:43:41,105 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Done
executing com.cloud.vm.VmWorkStart for job-32
2017-03-04 20:43:41,107 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-4:ctx-56cda672 job-29/job-32) (logid:b0dca526) Remove job-32
from job monitoring
2017-03-04 20:43:41,113 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-23:ctx-0c7ca79a job-29 ctx-f34539ef) (logid:b0dca526)
Destroying vm VM[User|i-4-3-VM] as it failed to create on Host with Id:null
2017-03-04 20:43:41,120 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-23:ctx-0c7ca79a job-29 ctx-f34539ef) (logid:b0dca526) 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-04 20:43:41,151 DEBUG [c.c.u.AccountManagerImpl]
(API-Job-Executor-23:ctx-0c7ca79a job-29 ctx-f34539ef) (logid:b0dca526) Access
granted to Acct[eb82ac50-0109-11e7-af92-069c1401072d-admin] to Domain:1/ by
AffinityGroupAccessChecker
2017-03-04 20:43:41,160 WARN [o.a.c.alerts]
(API-Job-Executor-23:ctx-0c7ca79a job-29 ctx-f34539ef) (logid:b0dca526)
alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message::
Failed to deploy Vm with Id: 3, on Host with Id: null
2017-03-04 20:43:41,180 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-23:ctx-0c7ca79a job-29) (logid:b0dca526) 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-4-3-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-04 20:43:41,182 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-23:ctx-0c7ca79a job-29) (logid:b0dca526) Complete async
job-29, 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"}
```
---
If your project is set up for it, you can reply to this email and have your
reply appear on GitHub as well. If your project does not have this feature
enabled and wishes so, or if the feature is enabled but not working, please
contact infrastructure at infrastruct...@apache.org or file a JIRA ticket
with INFRA.
---
