ACS 4.9.2 with VMware 5.5

Discussion:

Ciobanu Cristian

2017-03-15 15:21:06 UTC

Hello,

Today I have did another test, but now with VMware 5.5 and ACS 4.9.2
configured with advanced networking, everything looks ok, except I'm not
able to deploy any VM.

SSVM - OK

Proxy Console - OK

VPC - OK

Tier - OK

Templates ready - OK

Deploy instance - NOT OK

I also have 2 environments with ACS 4.5.2 and VMware 5.5 configured with
basic and advanced networking everything works perfectly there.

Can I get confirmation if anyone tested ACS 4.9.2 with VMware 5.5 ?

Logs related to this issue - http://pastebin.com/tM6ZBfDp

=======================================================

[***@acs management]# grep -r i-2-20-VM --color

apilog.log:2017-03-15 10:41:28,423 INFO [a.c.c.a.ApiServer]
(catalina-exec-18:ctx-7ec54fca ctx-250a55aa) (logid:76a929db) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588886710 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

apilog.log:2017-03-15 10:42:34,044 INFO [a.c.c.a.ApiServer]
(catalina-exec-1:ctx-07b85d0a ctx-90669645) (logid:abedff30) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588952208 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating entries for VM: VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating nics for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,855 DEBUG
[o.a.c.e.o.NetworkOrchestrator] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Allocating nic for vm VM[User|i-2-20-VM] in network
Ntwk[218|Guest|11] with requested profile NicProfile[0-0-null-null-null

management-server.log:2017-03-15 10:41:21,863 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating disks for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocation completed for VM:
VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.UserVmManagerImpl] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Successfully allocated DB entry for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
ada95a34-85cb-463f-9be6-571e15e500a9

management-server.log:2017-03-15 10:41:23,816 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:23,865 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,867 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:23,883 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:23,883 INFO [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:23,893 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:23,894 DEBUG [c.c.a.t.Request]
(DirectAgent-27:ctx-29ef61d3) (logid:918eb10d) Seq 1-1575696919626252501:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,918 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:23,918 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
7b598f0f-f639-4aa2-b3ae-03323d0eaf4b

management-server.log:2017-03-15 10:41:25,830 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:25,882 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:25,894 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:25,894 INFO [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:25,904 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:25,904 DEBUG [c.c.a.t.Request]
(DirectAgent-107:ctx-bf24341e) (logid:918eb10d) Seq 1-1575696919626252502:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,927 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,927 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,939 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-32:ctx-735072f5 job-140
ctx-ee697530) (logid:918eb10d) Destroying vm VM[User|i-2-20-VM] as it failed
to create on Host with Id:null

management-server.log:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:2017-03-15 10:42:37,186 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:37,797 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-49:ctx-b9ee6246
job-143/job-144 ctx-904a1d00) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Error

management-server.log:2017-03-15 10:42:41,788 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-51:ctx-81c7628f
job-143/job-146 ctx-2569acef) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Expunging

management-server.log:2017-03-15 10:42:41,802 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Expunged VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Starting cleaning up vm VM[User|i-2-20-VM]
resources...

management-server.log:2017-03-15 10:42:41,823 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Successfully cleaned up vm VM[User|i-2-20-VM]
resources as a part of expunge process

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

Thank you !

Cristian

Sergey Levitskiy

2017-03-15 15:35:02 UTC

Permalink

Can you extract full test of exception for management server logs and post here? Ideally please save the full management log on e.g. dropbox and add the link as well.

On 3/15/17, 8:21 AM, "Ciobanu Cristian" <***@istream.today> wrote:

Hello,

Today I have did another test, but now with VMware 5.5 and ACS 4.9.2
configured with advanced networking, everything looks ok, except I'm not
able to deploy any VM.

SSVM - OK

Proxy Console - OK

VPC - OK

Tier - OK

Templates ready - OK

Deploy instance - NOT OK

I also have 2 environments with ACS 4.5.2 and VMware 5.5 configured with
basic and advanced networking everything works perfectly there.

Can I get confirmation if anyone tested ACS 4.9.2 with VMware 5.5 ?

Logs related to this issue - http://pastebin.com/tM6ZBfDp

=======================================================

[***@acs management]# grep -r i-2-20-VM --color

apilog.log:2017-03-15 10:41:28,423 INFO [a.c.c.a.ApiServer]
(catalina-exec-18:ctx-7ec54fca ctx-250a55aa) (logid:76a929db) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588886710 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

apilog.log:2017-03-15 10:42:34,044 INFO [a.c.c.a.ApiServer]
(catalina-exec-1:ctx-07b85d0a ctx-90669645) (logid:abedff30) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588952208 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating entries for VM: VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating nics for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,855 DEBUG
[o.a.c.e.o.NetworkOrchestrator] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Allocating nic for vm VM[User|i-2-20-VM] in network
Ntwk[218|Guest|11] with requested profile NicProfile[0-0-null-null-null

management-server.log:2017-03-15 10:41:21,863 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating disks for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocation completed for VM:
VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.UserVmManagerImpl] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Successfully allocated DB entry for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
ada95a34-85cb-463f-9be6-571e15e500a9

management-server.log:2017-03-15 10:41:23,816 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:23,865 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,867 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:23,883 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:23,883 INFO [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:23,893 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:23,894 DEBUG [c.c.a.t.Request]
(DirectAgent-27:ctx-29ef61d3) (logid:918eb10d) Seq 1-1575696919626252501:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,918 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:23,918 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
7b598f0f-f639-4aa2-b3ae-03323d0eaf4b

management-server.log:2017-03-15 10:41:25,830 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:25,882 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:25,894 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:25,894 INFO [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:25,904 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:25,904 DEBUG [c.c.a.t.Request]
(DirectAgent-107:ctx-bf24341e) (logid:918eb10d) Seq 1-1575696919626252502:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,927 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,927 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,939 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-32:ctx-735072f5 job-140
ctx-ee697530) (logid:918eb10d) Destroying vm VM[User|i-2-20-VM] as it failed
to create on Host with Id:null

management-server.log:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:2017-03-15 10:42:37,186 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:37,797 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-49:ctx-b9ee6246
job-143/job-144 ctx-904a1d00) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Error

management-server.log:2017-03-15 10:42:41,788 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-51:ctx-81c7628f
job-143/job-146 ctx-2569acef) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Expunging

management-server.log:2017-03-15 10:42:41,802 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Expunged VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Starting cleaning up vm VM[User|i-2-20-VM]
resources...

management-server.log:2017-03-15 10:42:41,823 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Successfully cleaned up vm VM[User|i-2-20-VM]
resources as a part of expunge process

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

Ciobanu Cristian

2017-03-15 16:08:38 UTC

Permalink

Hello ,

Please see : https://drive.google.com/file/d/0B2xyGcnD30FVcFZZa1FvTmZtRWc/view?usp=sharing I suggest to check on the last part of this log.

Thank you
Cristian

-----Original Message-----
From: Sergey Levitskiy [mailto:***@autodesk.com]
Sent: Wednesday, March 15, 2017 5:35 PM
To: ***@cloudstack.apache.org
Subject: Re: ACS 4.9.2 with VMware 5.5

Can you extract full test of exception for management server logs and post here? Ideally please save the full management log on e.g. dropbox and add the link as well.

On 3/15/17, 8:21 AM, "Ciobanu Cristian" <***@istream.today> wrote:

Hello,

Today I have did another test, but now with VMware 5.5 and ACS 4.9.2
configured with advanced networking, everything looks ok, except I'm not
able to deploy any VM.

SSVM - OK

Proxy Console - OK

VPC - OK

Tier - OK

Templates ready - OK

Deploy instance - NOT OK

I also have 2 environments with ACS 4.5.2 and VMware 5.5 configured with
basic and advanced networking everything works perfectly there.

Can I get confirmation if anyone tested ACS 4.9.2 with VMware 5.5 ?

Logs related to this issue - http://pastebin.com/tM6ZBfDp

=======================================================

[***@acs management]# grep -r i-2-20-VM --color

apilog.log:2017-03-15 10:41:28,423 INFO [a.c.c.a.ApiServer]
(catalina-exec-18:ctx-7ec54fca ctx-250a55aa) (logid:76a929db) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588886710 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

apilog.log:2017-03-15 10:42:34,044 INFO [a.c.c.a.ApiServer]
(catalina-exec-1:ctx-07b85d0a ctx-90669645) (logid:abedff30) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588952208 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating entries for VM: VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating nics for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,855 DEBUG
[o.a.c.e.o.NetworkOrchestrator] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Allocating nic for vm VM[User|i-2-20-VM] in network
Ntwk[218|Guest|11] with requested profile NicProfile[0-0-null-null-null

management-server.log:2017-03-15 10:41:21,863 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating disks for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocation completed for VM:
VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.UserVmManagerImpl] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Successfully allocated DB entry for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
ada95a34-85cb-463f-9be6-571e15e500a9

management-server.log:2017-03-15 10:41:23,816 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:23,865 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,867 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:23,883 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:23,883 INFO [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:23,893 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:23,894 DEBUG [c.c.a.t.Request]
(DirectAgent-27:ctx-29ef61d3) (logid:918eb10d) Seq 1-1575696919626252501:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,918 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:23,918 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
7b598f0f-f639-4aa2-b3ae-03323d0eaf4b

management-server.log:2017-03-15 10:41:25,830 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:25,882 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:25,894 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:25,894 INFO [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:25,904 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:25,904 DEBUG [c.c.a.t.Request]
(DirectAgent-107:ctx-bf24341e) (logid:918eb10d) Seq 1-1575696919626252502:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,927 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,927 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,939 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-32:ctx-735072f5 job-140
ctx-ee697530) (logid:918eb10d) Destroying vm VM[User|i-2-20-VM] as it failed
to create on Host with Id:null

management-server.log:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:2017-03-15 10:42:37,186 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:37,797 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-49:ctx-b9ee6246
job-143/job-144 ctx-904a1d00) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Error

management-server.log:2017-03-15 10:42:41,788 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-51:ctx-81c7628f
job-143/job-146 ctx-2569acef) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Expunging

management-server.log:2017-03-15 10:42:41,802 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Expunged VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Starting cleaning up vm VM[User|i-2-20-VM]
resources...

management-server.log:2017-03-15 10:42:41,823 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Successfully cleaned up vm VM[User|i-2-20-VM]
resources as a part of expunge process

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

Thank you !

Cristian

Sergey Levitskiy

2017-03-15 17:38:41 UTC

Permalink

The root cause is below which is most likely due to not specifying VLAN range during zone creation.
Can you post result for the following DB queries?

select * from cloud.networsk where id=218;
select * from cloud.vlan where network_id=218;
select count(*) from cloud.user_ip_address where vlan_db_id in (select id from cloud.vlan where network_id=218) and state=’Free’
select id,name,data_center_id, vnet from cloud.physical_network

2017-03-15 10:41:25,855 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a) (logid:918eb10d) Cleaning up because we're unable to implement the network Ntwk[218|Guest|11]

2017-03-15 10:41:25,881 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a) (logid:918eb10d) Insufficient capacity
com.cloud.exception.InsufficientVirtualNetworkCapacityException: Unable to allocate vnet as a part of network Ntwk[218|Guest|11] implement Scope=interface com.cloud.dc.DataCenter; id=3
at com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java:289)
at com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:319)
at com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNetworkGuru.java:132)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1011)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:950)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1314)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:997)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4605)
at sun.reflect.GeneratedMethodAccessor302.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)

On 3/15/17, 9:08 AM, "Ciobanu Cristian" <***@istream.today> wrote:

Hello ,

Please see : https://drive.google.com/file/d/0B2xyGcnD30FVcFZZa1FvTmZtRWc/view?usp=sharing I suggest to check on the last part of this log.

Thank you
Cristian

-----Original Message-----
From: Sergey Levitskiy [mailto:***@autodesk.com]
Sent: Wednesday, March 15, 2017 5:35 PM
To: ***@cloudstack.apache.org
Subject: Re: ACS 4.9.2 with VMware 5.5

Can you extract full test of exception for management server logs and post here? Ideally please save the full management log on e.g. dropbox and add the link as well.

On 3/15/17, 8:21 AM, "Ciobanu Cristian" <***@istream.today> wrote:

Hello,

Today I have did another test, but now with VMware 5.5 and ACS 4.9.2
configured with advanced networking, everything looks ok, except I'm not
able to deploy any VM.

SSVM - OK

Proxy Console - OK

VPC - OK

Tier - OK

Templates ready - OK

Deploy instance - NOT OK

I also have 2 environments with ACS 4.5.2 and VMware 5.5 configured with
basic and advanced networking everything works perfectly there.

Can I get confirmation if anyone tested ACS 4.9.2 with VMware 5.5 ?

Logs related to this issue - http://pastebin.com/tM6ZBfDp

=======================================================

[***@acs management]# grep -r i-2-20-VM --color

apilog.log:2017-03-15 10:41:28,423 INFO [a.c.c.a.ApiServer]
(catalina-exec-18:ctx-7ec54fca ctx-250a55aa) (logid:76a929db) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588886710 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

apilog.log:2017-03-15 10:42:34,044 INFO [a.c.c.a.ApiServer]
(catalina-exec-1:ctx-07b85d0a ctx-90669645) (logid:abedff30) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588952208 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating entries for VM: VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating nics for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,855 DEBUG
[o.a.c.e.o.NetworkOrchestrator] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Allocating nic for vm VM[User|i-2-20-VM] in network
Ntwk[218|Guest|11] with requested profile NicProfile[0-0-null-null-null

management-server.log:2017-03-15 10:41:21,863 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating disks for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocation completed for VM:
VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.UserVmManagerImpl] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Successfully allocated DB entry for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
ada95a34-85cb-463f-9be6-571e15e500a9

management-server.log:2017-03-15 10:41:23,816 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:23,865 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,867 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:23,883 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:23,883 INFO [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:23,893 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:23,894 DEBUG [c.c.a.t.Request]
(DirectAgent-27:ctx-29ef61d3) (logid:918eb10d) Seq 1-1575696919626252501:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,918 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:23,918 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
7b598f0f-f639-4aa2-b3ae-03323d0eaf4b

management-server.log:2017-03-15 10:41:25,830 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:25,882 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:25,894 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:25,894 INFO [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:25,904 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:25,904 DEBUG [c.c.a.t.Request]
(DirectAgent-107:ctx-bf24341e) (logid:918eb10d) Seq 1-1575696919626252502:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,927 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,927 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,939 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-32:ctx-735072f5 job-140
ctx-ee697530) (logid:918eb10d) Destroying vm VM[User|i-2-20-VM] as it failed
to create on Host with Id:null

management-server.log:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:2017-03-15 10:42:37,186 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:37,797 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-49:ctx-b9ee6246
job-143/job-144 ctx-904a1d00) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Error

management-server.log:2017-03-15 10:42:41,788 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-51:ctx-81c7628f
job-143/job-146 ctx-2569acef) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Expunging

management-server.log:2017-03-15 10:42:41,802 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Expunged VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Starting cleaning up vm VM[User|i-2-20-VM]
resources...

management-server.log:2017-03-15 10:42:41,823 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Successfully cleaned up vm VM[User|i-2-20-VM]
resources as a part of expunge process

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

Thank you !

Cr

Ciobanu Cristian

2017-03-15 20:30:27 UTC

Permalink

Thank you very much!!! I figured out how to fix, I forgot to add VLAN.

Regards,
Cristian

-----Original Message-----
From: Sergey Levitskiy [mailto:***@autodesk.com]
Sent: Wednesday, March 15, 2017 7:39 PM
To: ***@cloudstack.apache.org
Subject: Re: ACS 4.9.2 with VMware 5.5

The root cause is below which is most likely due to not specifying VLAN range during zone creation.
Can you post result for the following DB queries?

select * from cloud.networsk where id=218; select * from cloud.vlan where network_id=218; select count(*) from cloud.user_ip_address where vlan_db_id in (select id from cloud.vlan where network_id=218) and state=’Free’
select id,name,data_center_id, vnet from cloud.physical_network

2017-03-15 10:41:25,855 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a) (logid:918eb10d) Cleaning up because we're unable to implement the network Ntwk[218|Guest|11]

2017-03-15 10:41:25,881 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a) (logid:918eb10d) Insufficient capacity
com.cloud.exception.InsufficientVirtualNetworkCapacityException: Unable to allocate vnet as a part of network Ntwk[218|Guest|11] implement Scope=interface com.cloud.dc.DataCenter; id=3
at com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java:289)
at com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:319)
at com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNetworkGuru.java:132)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1011)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:950)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1314)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:997)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4605)
at sun.reflect.GeneratedMethodAccessor302.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)

On 3/15/17, 9:08 AM, "Ciobanu Cristian" <***@istream.today> wrote:

Hello ,

Please see : https://drive.google.com/file/d/0B2xyGcnD30FVcFZZa1FvTmZtRWc/view?usp=sharing I suggest to check on the last part of this log.

Thank you
Cristian

-----Original Message-----
From: Sergey Levitskiy [mailto:***@autodesk.com]
Sent: Wednesday, March 15, 2017 5:35 PM
To: ***@cloudstack.apache.org
Subject: Re: ACS 4.9.2 with VMware 5.5

Can you extract full test of exception for management server logs and post here? Ideally please save the full management log on e.g. dropbox and add the link as well.

On 3/15/17, 8:21 AM, "Ciobanu Cristian" <***@istream.today> wrote:

Hello,

Today I have did another test, but now with VMware 5.5 and ACS 4.9.2
configured with advanced networking, everything looks ok, except I'm not
able to deploy any VM.

SSVM - OK

Proxy Console - OK

VPC - OK

Tier - OK

Templates ready - OK

Deploy instance - NOT OK

I also have 2 environments with ACS 4.5.2 and VMware 5.5 configured with
basic and advanced networking everything works perfectly there.

Can I get confirmation if anyone tested ACS 4.9.2 with VMware 5.5 ?

Logs related to this issue - http://pastebin.com/tM6ZBfDp

=======================================================

[***@acs management]# grep -r i-2-20-VM --color

apilog.log:2017-03-15 10:41:28,423 INFO [a.c.c.a.ApiServer]
(catalina-exec-18:ctx-7ec54fca ctx-250a55aa) (logid:76a929db) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588886710 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

apilog.log:2017-03-15 10:42:34,044 INFO [a.c.c.a.ApiServer]
(catalina-exec-1:ctx-07b85d0a ctx-90669645) (logid:abedff30) (userId=2
accountId=2 sessionId=051314C1FA5E08E86DC0373970EE42D9) 86.125.237.148 --
GET
command=listVirtualMachines&id=b7cbfcea-f13e-4954-b1e1-f7d067f64293&response
=json&_=1489588952208 200
{"listvirtualmachinesresponse":{"count":1,"virtualmachine":[{"id":"b7cbfcea-
f13e-4954-b1e1-f7d067f64293","name":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293
","displayname":"VM-b7cbfcea-f13e-4954-b1e1-f7d067f64293","account":"admin",
"userid":"46a435ea-095d-11e7-811f-000c2929469d","username":"admin","domainid
":"c932053e-095b-11e7-811f-000c2929469d","domain":"ROOT","created":"2017-03-
15T10:41:21-0400","state":"Error","haenable":false,"zoneid":"f6f15408-a1fe-4
edf-a376-ff94c6e07392","zonename":"AMS-NVME","templateid":"c9354528-095b-11e
7-811f-000c2929469d","templatename":"CentOS 5.3(64-bit) no GUI
(vSphere)","templatedisplaytext":"CentOS 5.3(64-bit) no GUI
(vSphere)","passwordenabled":false,"serviceofferingid":"965d14f2-97ef-4247-9
c56-6fb11526cc3d","serviceofferingname":"Small
Instance","cpunumber":1,"cpuspeed":500,"memory":512,"guestosid":"c9367222-09
5b-11e7-811f-000c2929469d","rootdeviceid":0,"rootdevicetype":"ROOT","securit
ygroup":[],"nic":[{"id":"ee82e835-2ace-4457-90fe-944266a0d64f","networkid":"
143c218a-8e8a-4140-a761-0e5ad3708950","networkname":"TAMSN","netmask":"255.2
55.0.0","gateway":"10.1.1.1","ipaddress":"10.1.0.105","traffictype":"Guest",
"type":"Isolated","isdefault":true,"macaddress":"02:00:20:27:00:02","seconda
ryip":[]}],"hypervisor":"VMware","instancename":"i-2-20-VM","affinitygroup":
[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":12,"tags":[]}]}
}

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating entries for VM: VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,854 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating nics for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,855 DEBUG
[o.a.c.e.o.NetworkOrchestrator] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Allocating nic for vm VM[User|i-2-20-VM] in network
Ntwk[218|Guest|11] with requested profile NicProfile[0-0-null-null-null

management-server.log:2017-03-15 10:41:21,863 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocating disks for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.VirtualMachineManagerImpl] (catalina-exec-25:ctx-63ee2c57
ctx-7539befc) (logid:5f97a9af) Allocation completed for VM:
VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:21,870 DEBUG
[c.c.v.UserVmManagerImpl] (catalina-exec-25:ctx-63ee2c57 ctx-7539befc)
(logid:5f97a9af) Successfully allocated DB entry for VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
ada95a34-85cb-463f-9be6-571e15e500a9

management-server.log:2017-03-15 10:41:23,816 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:23,865 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,866 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Seq 1-1575696919626252501: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:23,867 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:23,883 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:23,883 INFO [c.c.h.v.m.HostMO]
(DirectAgent-27:ctx-29ef61d3 myvmwarehost.net, job-140/job-141, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:23,893 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3 myvmwarehost.net,
job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:23,894 DEBUG [c.c.a.t.Request]
(DirectAgent-27:ctx-29ef61d3) (logid:918eb10d) Seq 1-1575696919626252501:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:23,900 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:23,918 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:23,918 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-47:ctx-a0616de1
job-140/job-141 ctx-2cab7460) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,795 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully transitioned to
start state for VM[User|i-2-20-VM] reservation id =
7b598f0f-f639-4aa2-b3ae-03323d0eaf4b

management-server.log:2017-03-15 10:41:25,830 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Deployment found -
P0=VM[User|i-2-20-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(3)-Pod(3)-Cluster(3)-Host(1)-Storage(Volume(20|ROOT-->Pool(1))]

management-server.log:2017-03-15 10:41:25,882 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Cleaning up resources for the
vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Sending { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Seq 1-1575696919626252502: Executing: { Cmd , MgmtId:
52230178461, via: 1(myvmwarehost.net), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":fa
lse,"vmName":"i-2-20-VM","executeInSequence":true,"wait":0}}] }

management-server.log:2017-03-15 10:41:25,884 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) Executing resource
StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

management-server.log:2017-03-15 10:41:25,894 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) find VM i-2-20-VM on host

management-server.log:2017-03-15 10:41:25,894 INFO [c.c.h.v.m.HostMO]
(DirectAgent-107:ctx-bf24341e myvmwarehost.net, job-140/job-142, cmd:
StopCommand) (logid:918eb10d) VM i-2-20-VM not found in host cache

management-server.log:2017-03-15 10:41:25,904 INFO
[c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e myvmwarehost.net,
job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM i-2-20-VM is no
longer in vSphere

management-server.log:2017-03-15 10:41:25,904 DEBUG [c.c.a.t.Request]
(DirectAgent-107:ctx-bf24341e) (logid:918eb10d) Seq 1-1575696919626252502:
Processing: { Ans: , MgmtId: 52230178461, via: 1(myvmwarehost.net), Ver:
v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-20-VM is
no longer in vSphere","wait":0}}] }

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully released network
resources for the vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:41:25,909 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Successfully cleanued up
resources for the vm VM[User|i-2-20-VM] in Starting state

management-server.log:2017-03-15 10:41:25,927 ERROR
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Invocation exception, caused
by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,927 INFO
[c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-48:ctx-9013c76a
job-140/job-142 ctx-213d798a) (logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:com.cloud.exception.InsufficientServerCapacityExceptio
n: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

management-server.log:2017-03-15 10:41:25,939 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-32:ctx-735072f5 job-140
ctx-ee697530) (logid:918eb10d) Destroying vm VM[User|i-2-20-VM] as it failed
to create on Host with Id:null

management-server.log:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

management-server.log:2017-03-15 10:42:37,186 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:37,797 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-49:ctx-b9ee6246
job-143/job-144 ctx-904a1d00) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Error

management-server.log:2017-03-15 10:42:41,788 DEBUG
[c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-51:ctx-81c7628f
job-143/job-146 ctx-2569acef) (logid:0b465f06) Stopped called on
VM[User|i-2-20-VM] but the state is Expunging

management-server.log:2017-03-15 10:42:41,802 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Destroying vm VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Expunged VM[User|i-2-20-VM]

management-server.log:2017-03-15 10:42:41,812 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Starting cleaning up vm VM[User|i-2-20-VM]
resources...

management-server.log:2017-03-15 10:42:41,823 DEBUG
[c.c.v.UserVmManagerImpl] (API-Job-Executor-33:ctx-ef0b0c00 job-143
ctx-319ad947) (logid:0b465f06) Successfully cleaned up vm VM[User|i-2-20-VM]
resources as a part of expunge process

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-27:ctx-29ef61d3
myvmwarehost.net, job-140/job-141, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-47:ctx-a0616de1 job-140/job-141 ctx-2cab7460)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d)
Executing resource StopCommand:
{"isProxy":false,"checkBeforeCleanup":false,"vmName":"i-2-20-VM","executeInS
equence":true,"wait":0}

catalina.out:INFO [c.c.h.v.m.HostMO] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM not found in host cache

catalina.out:INFO [c.c.h.v.r.VmwareResource] (DirectAgent-107:ctx-bf24341e
myvmwarehost.net, job-140/job-142, cmd: StopCommand) (logid:918eb10d) VM
i-2-20-VM is no longer in vSphere

catalina.out:ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-48:ctx-9013c76a job-140/job-142 ctx-213d798a)
(logid:918eb10d) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

catalina.out:com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-20-VM]Scope=interface
com.cloud.dc.DataCenter; id=3

catalina.out:Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter;
id=3

Thank you !

Cristian