Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 7533E112B5 for ; Tue, 22 Jul 2014 04:48:39 +0000 (UTC) Received: (qmail 62894 invoked by uid 500); 22 Jul 2014 04:48:38 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 62865 invoked by uid 500); 22 Jul 2014 04:48:38 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 62856 invoked by uid 500); 22 Jul 2014 04:48:38 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 62853 invoked by uid 99); 22 Jul 2014 04:48:38 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 22 Jul 2014 04:48:38 +0000 Date: Tue, 22 Jul 2014 04:48:38 +0000 (UTC) From: "Alireza Eskandari (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (CLOUDSTACK-7149) Issues with deployment of Cloudstack with dvSwitch on vmware vSphere 5.5 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 Alireza Eskandari created CLOUDSTACK-7149: --------------------------------------------- Summary: Issues with deployment of Cloudstack with dvSwitch on= vmware vSphere 5.5 Key: CLOUDSTACK-7149 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7149 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the defa= ult.) Components: Hypervisor Controller, Install and Setup, Network Con= troller, VMware Affects Versions: 4.3.0 Environment: vCenter 5.5 2 x ESXi 5.5 as hosts Reporter: Alireza Eskandari Priority: Critical I can't deploy Zone with vmware hypervisor on dvSwitch. After I set configu= rations, Cloudstack starts to create Zone, Pod, cluster and etc. and everyt= hing looks normal but CS could not set any configuration on dvSwitch. CS begins to create system VMs but after cloning of system VMs completed, C= S delete them because of unsuccessful dvSwitch configuration and recreate a= new one. But when I try to deploy on Standard vSwitch, everything works well without= problem. 2014-07-08 14:44:39,764 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare volume at new device {"capacityInKB":0,"k= ey":-2,"backing":{"diskMode":"persistent","fileName":"[SharedStorageCS] s-5= 4-VM/ROOT-54-000001.vmdk","datastore":{"value":"datastore-14","type":"Datas= tore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"con= nected":true},"controllerKey":200,"unitNumber":1} 2014-07-08 14:44:39,764 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) VM s-54-VM will be started with NIC device type: = E1000 2014-07-08 14:44:39,764 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare NIC device based on NicTO: {"deviceId":0,= "networkRateMbps":-1,"defaultNic":false,"uuid":"53f70468-065a-484b-b6b5-914= 8d4ea9b52","mac":"02:00:16:fa:00:36","broadcastType":"LinkLocal","type":"Co= ntrol","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"} 2014-07-08 14:44:39,773 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare network on vmwaresvs null with name prefi= x: cloud.private 2014-07-08 14:44:39,773 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Unrecognized broadcast type in VmwareResource, ty= pe: LinkLocal. Use vlan info from labeling: untagged 2014-07-08 14:44:39,773 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -411:ctx-86a12e4e 172.16.71.54) Detected vswitch name as undefined. Default= ing to vSwitch0 2014-07-08 14:44:39,916 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -411:ctx-86a12e4e 172.16.71.54) Network cloud.private.untagged.0.1-vSwitch0= is ready on vSwitch vSwitch0 2014-07-08 14:44:39,916 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Preparing NIC device on network cloud.private.unt= agged.0.1-vSwitch0 2014-07-08 14:44:39,916 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare NIC at new device {"operation":"ADD","dev= ice":{"addressType":"Manual","macAddress":"02:00:16:fa:00:36","key":-3,"bac= king":{"network":{"value":"network-23","type":"Network"},"deviceName":"clou= d.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"all= owGuestControl":true,"connected":true},"unitNumber":0}} 2014-07-08 14:44:39,917 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare NIC device based on NicTO: {"deviceId":1,= "networkRateMbps":-1,"defaultNic":false,"uuid":"eaa2b684-0ec0-47c2-be20-f13= 8d0790856","ip":"172.16.71.62","netmask":"255.255.255.0","gateway":"172.16.= 71.1","mac":"06:fc:6e:00:00:02","broadcastType":"Native","type":"Management= ","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"} 2014-07-08 14:44:39,925 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare network on vmwaresvs null with name prefi= x: cloud.private 2014-07-08 14:44:39,926 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -411:ctx-86a12e4e 172.16.71.54) Detected vswitch name as undefined. Default= ing to vSwitch0 2014-07-08 14:44:40,063 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -411:ctx-86a12e4e 172.16.71.54) Network cloud.private.untagged.0.1-vSwitch0= is ready on vSwitch vSwitch0 2014-07-08 14:44:40,063 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Preparing NIC device on network cloud.private.unt= agged.0.1-vSwitch0 2014-07-08 14:44:40,064 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare NIC at new device {"operation":"ADD","dev= ice":{"addressType":"Manual","macAddress":"06:fc:6e:00:00:02","key":-4,"bac= king":{"network":{"value":"network-23","type":"Network"},"deviceName":"clou= d.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"all= owGuestControl":true,"connected":true},"unitNumber":1}} 2014-07-08 14:44:40,064 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare NIC device based on NicTO: {"deviceId":2,= "networkRateMbps":-1,"defaultNic":true,"uuid":"43a27cb8-bd3b-4830-8970-790e= e6032ec0","ip":"79.175.173.179","netmask":"255.255.255.240","gateway":"79.1= 75.173.177","mac":"06:59:1c:00:00:0c","dns1":"4.2.2.4","dns2":"8.8.8.8","br= oadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolation= Uri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmw= aredvs"} 2014-07-08 14:44:40,072 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) Prepare network on vmwaredvs dvSwitch with name p= refix: cloud.public 2014-07-08 14:44:40,081 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-411:c= tx-86a12e4e 172.16.71.54) StartCommand failed due to Exception: java.lang.N= umberFormatException Message: null java.lang.NumberFormatException: null at java.lang.Integer.parseInt(Integer.java:454) at java.lang.Integer.parseInt(Integer.java:527) at com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.prepareNetwo= rk(HypervisorHostHelper.java:504) at com.cloud.hypervisor.vmware.resource.VmwareResource.prepareNetwo= rkFromNicInfo(VmwareResource.java:3692) at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(Vmwa= reResource.java:2934) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeReque= st(VmwareResource.java:525) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(Dir= ectAgentAttache.java:216) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.r= un(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= $1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run= (ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.ja= va:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExec= utor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:615) at java.lang.Thread.run(Thread.java:744) 2014-07-08 14:44:40,085 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-411= :ctx-86a12e4e) Seq 1-1967325654: Cancelling because one of the answers is f= alse and it is stop on error. 2014-07-08 14:44:40,085 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-411= :ctx-86a12e4e) Seq 1-1967325654: Response Received: 2014-07-08 14:44:40,087 DEBUG [c.c.a.t.Request] (DirectAgent-411:ctx-86a12e= 4e) Seq 1-1967325654: Processing: { Ans: , MgmtId: 345051256068, via: 1, V= er: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":54,"name= ":"s-54-VM","bootloader":"HVM","type":"SecondaryStorageVm","cpus":1,"minSpe= ed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"hostName":"s-= 54-VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" te= mplate=3DdomP type=3Dsecstorage host=3D172.16.71.52 port=3D8250 name=3Ds-54= -VM zone=3D1 pod=3D1 guid=3Ds-54-VM resource=3Dcom.cloud.storage.resource.P= remiumSecondaryStorageResource instance=3DSecStorage sslcopy=3Dfalse role= =3DtemplateProcessor mtu=3D1500 eth2ip=3D79.175.173.179 eth2mask=3D255.255.= 255.240 gateway=3D79.175.173.177 public.network.device=3Deth2 eth0mask=3D0.= 0.0.0 eth0ip=3D0.0.0.0 eth1ip=3D172.16.71.62 eth1mask=3D255.255.255.0 mgmtc= idr=3D172.16.71.0/24 localgw=3D172.16.71.1 private.network.device=3Deth1 et= h3ip=3D172.16.71.58 eth3mask=3D255.255.255.0 storageip=3D172.16.71.58 stora= genetmask=3D255.255.255.0 storagegateway=3D172.16.71.1 internaldns1=3D172.1= 6.9.9 internaldns2=3D172.16.9.10 dns1=3D4.2.2.4 dns2=3D8.8.8.8","rebootOnCr= ash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":= false,"vncPassword":"10a1fae293cfbaca","params":{"nicAdapter":"E1000","vmwa= re.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskControl= ler":"ide","vmware.reserve.mem":"false"},"uuid":"6063d734-3b96-48f4-9ecd-3b= 7b7076e2db","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjec= tTO":{"uuid":"0a5059a6-3a5c-45de-8a66-a3b695397363","volumeType":"ROOT","da= taStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"94= 3e616e-71b5-387d-a23c-b15781d88cc7","id":1,"poolType":"VMFS","host":"VMFS d= atastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port= ":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedS= torageCS/?ROLE=3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23c-b15781d88cc7"}= },"name":"ROOT-54","size":0,"path":"ROOT-54-000001","volumeId":54,"vmName":= "s-54-VM","accountId":1,"format":"OVA","id":54,"deviceId":0,"hypervisorType= ":"VMware"}},"diskSeq":0,"path":"ROOT-54-000001","type":"ROOT","_details":{= "managed":"false","storagePort":"0","storageHost":"VMFS datastore: /Afranet= /SharedStorageCS","volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRateMbp= s":-1,"defaultNic":true,"uuid":"43a27cb8-bd3b-4830-8970-790ee6032ec0","ip":= "79.175.173.179","netmask":"255.255.255.240","gateway":"79.175.173.177","ma= c":"06:59:1c:00:00:0c","dns1":"4.2.2.4","dns2":"8.8.8.8","broadcastType":"V= lan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan://11= 62","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"},{"devi= ceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"53f70468-065a-484b-= b6b5-9148d4ea9b52","mac":"02:00:16:fa:00:36","broadcastType":"LinkLocal","t= ype":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"}= ,{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"eaa2b684-0ec= 0-47c2-be20-f138d0790856","ip":"172.16.71.62","netmask":"255.255.255.0","ga= teway":"172.16.71.1","mac":"06:fc:6e:00:00:02","broadcastType":"Native","ty= pe":"Management","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs= "},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"4b1e74ca-3= 51b-4b4c-8327-246b6303bcef","ip":"172.16.71.58","netmask":"255.255.255.0","= gateway":"172.16.71.1","mac":"06:69:7a:00:00:19","broadcastType":"Storage",= "type":"Storage","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs= "}]},"result":false,"details":"StartCommand failed due to Exception: java.l= ang.NumberFormatException\nMessage: null\n","wait":0}}] } 2014-07-08 14:44:40,087 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-20017d90)= Seq 1-1967325654: Received: { Ans: , MgmtId: 345051256068, via: 1, Ver: v= 1, Flags: 10, { StartAnswer } } 2014-07-08 14:44:40,095 INFO [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Unable to start VM on Host[-1-Routing] due to StartCommand= failed due to Exception: java.lang.NumberFormatException Message: null 2014-07-08 14:44:40,103 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Cleaning up resources for the vm VM[SecondaryStorageVm|s-5= 4-VM] in Starting state 2014-07-08 14:44:40,107 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-20017d90)= Seq 1-1967325655: Sending { Cmd , MgmtId: 345051256068, via: 1(172.16.71.= 54), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy"= :false,"executeInSequence":false,"vmName":"s-54-VM","wait":0}}] } 2014-07-08 14:44:40,107 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-20017d90)= Seq 1-1967325655: Executing: { Cmd , MgmtId: 345051256068, via: 1(172.16.= 71.54), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isPro= xy":false,"executeInSequence":false,"vmName":"s-54-VM","wait":0}}] } 2014-07-08 14:44:40,107 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-10:= ctx-6daf13f4) Seq 1-1967325655: Executing request 2014-07-08 14:44:40,108 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-10:ct= x-6daf13f4 172.16.71.54) Executing resource StopCommand: {"isProxy":false,"= executeInSequence":false,"vmName":"s-54-VM","wait":0} 2014-07-08 14:44:40,139 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-10:ctx-6daf13= f4 172.16.71.54) find VM s-54-VM on host 2014-07-08 14:44:40,139 INFO [c.c.h.v.m.HostMO] (DirectAgent-10:ctx-6daf13= f4 172.16.71.54) VM s-54-VM not found in host cache 2014-07-08 14:44:40,139 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-10:ctx-6daf13= f4 172.16.71.54) load VM cache on host 2014-07-08 14:44:40,194 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-10:ct= x-6daf13f4 172.16.71.54) VM s-54-VM is already in stopped state 2014-07-08 14:44:40,195 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-10:= ctx-6daf13f4) Seq 1-1967325655: Response Received: 2014-07-08 14:44:40,195 DEBUG [c.c.a.t.Request] (DirectAgent-10:ctx-6daf13f= 4) Seq 1-1967325655: Processing: { Ans: , MgmtId: 345051256068, via: 1, Ve= r: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"detail= s":"VM s-54-VM is already in stopped state","wait":0}}] } 2014-07-08 14:44:40,195 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-20017d90)= Seq 1-1967325655: Received: { Ans: , MgmtId: 345051256068, via: 1, Ver: v= 1, Flags: 10, { StopAnswer } } 2014-07-08 14:44:40,225 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (secstor= age-1:ctx-20017d90) Releasing ip address for reservationId=3Ddb11c5a6-efbb-= 4c7e-9fad-74b47aef5c27, instance=3D207 2014-07-08 14:44:40,226 DEBUG [c.c.n.g.PodBasedNetworkGuru] (secstorage-1:c= tx-20017d90) Released nic: NicProfile[207-54-null-null-null 2014-07-08 14:44:40,243 DEBUG [c.c.n.g.StorageNetworkGuru] (secstorage-1:ct= x-20017d90) Release an storage ip 172.16.71.58 2014-07-08 14:44:40,250 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Successfully released network resources for the vm VM[Seco= ndaryStorageVm|s-54-VM] 2014-07-08 14:44:40,250 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Successfully cleanued up resources for the vm VM[Secondary= StorageVm|s-54-VM] in Starting state 2014-07-08 14:44:40,253 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Root volume is ready, need to place VM in volume's cluster 2014-07-08 14:44:40,253 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Vol[54|vm=3D54|ROOT] is READY, changing deployment plan to= use this pool's dcId: 1 , podId: 1 , and clusterId: 3 2014-07-08 14:44:40,255 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Deploy avoids pods: null, clusters: null, hosts: [1, 2= ] 2014-07-08 14:44:40,256 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) DeploymentPlanner allocation algorithm: com.cloud.depl= oy.FirstFitPlanner@10ef1fe1 2014-07-08 14:44:40,256 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Trying to allocate a host and storage pools from dc:1,= pod:1,cluster:3, requested cpu: 500, requested ram: 536870912 2014-07-08 14:44:40,256 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Is ROOT volume READY (pool already allocated)?: Yes 2014-07-08 14:44:40,256 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-200= 17d90) Searching resources only under specified Cluster: 3 2014-07-08 14:44:40,261 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Checking resources in Cluster: 3 under Pod: 1 2014-07-08 14:44:40,261 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-20017d90 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 = cluster:3 2014-07-08 14:44:40,265 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-20017d90 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to ch= eck for allocation: [Host[-2-Routing], Host[-1-Routing]] 2014-07-08 14:44:40,268 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-20017d90 FirstFitRoutingAllocator) Found 2 hosts for allocation after = prioritization: [Host[-2-Routing], Host[-1-Routing]] 2014-07-08 14:44:40,268 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-20017d90 FirstFitRoutingAllocator) Looking for speed=3D500Mhz, Ram=3D5= 12 2014-07-08 14:44:40,268 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-20017d90 FirstFitRoutingAllocator) Host name: 172.16.71.53, hostId: 2 = is in avoid set, skipping this and trying other available hosts 2014-07-08 14:44:40,268 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-20017d90 FirstFitRoutingAllocator) Host name: 172.16.71.54, hostId: 1 = is in avoid set, skipping this and trying other available hosts 2014-07-08 14:44:40,268 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-20017d90 FirstFitRoutingAllocator) Host Allocator returning 0 suitable= hosts 2014-07-08 14:44:40,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) No suitable hosts found 2014-07-08 14:44:40,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) No suitable hosts found under this Cluster: 3 2014-07-08 14:44:40,270 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Could not find suitable Deployment Destination for thi= s VM under any clusters, returning. 2014-07-08 14:44:40,270 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-200= 17d90) Searching resources only under specified Cluster: 3 2014-07-08 14:44:40,271 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-200= 17d90) The specified cluster is in avoid set, returning. 2014-07-08 14:44:40,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Deploy avoids pods: null, clusters: [3], hosts: [1, 2] 2014-07-08 14:44:40,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) DeploymentPlanner allocation algorithm: com.cloud.depl= oy.FirstFitPlanner@10ef1fe1 2014-07-08 14:44:40,274 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Trying to allocate a host and storage pools from dc:1,= pod:1,cluster:null, requested cpu: 500, requested ram: 536870912 2014-07-08 14:44:40,274 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-20017d90) Is ROOT volume READY (pool already allocated)?: No 2014-07-08 14:44:40,274 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-200= 17d90) Searching resources only under specified Pod: 1 2014-07-08 14:44:40,274 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-200= 17d90) Listing clusters in order of aggregate capacity, that have (atleast = one host with) enough CPU and RAM capacity under this Pod: 1 2014-07-08 14:44:40,278 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-200= 17d90) Removing from the clusterId list these clusters from avoid set: [3] 2014-07-08 14:44:40,278 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-200= 17d90) No clusters found after removing disabled clusters and clusters in a= void list, returning. 2014-07-08 14:44:40,292 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -20017d90) VM state transitted from :Starting to Stopped with event: Operat= ionFailedvm's original host id: null new host id: null host id before state= transition: 1 2014-07-08 14:44:40,299 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -20017d90) Hosts's actual total CPU: 19200 and CPU after applying overprovi= sioning: 19200 2014-07-08 14:44:40,299 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -20017d90) Hosts's actual total RAM: 8579170304 and RAM after applying over= provisioning: 8579170304 2014-07-08 14:44:40,299 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -20017d90) release cpu from host: 1, old used: 500,reserved: 0, actual tota= l: 19200, total with overprovisioning: 19200; new used: 0,reserved:0; moved= fromreserved: false,moveToReserveredfalse 2014-07-08 14:44:40,299 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -20017d90) release mem from host: 1, old used: 536870912,reserved: 0, total= : 8579170304; new used: 0,reserved:0; movedfromreserved: false,moveToReserv= eredfalse 2014-07-08 14:44:40,306 WARN [c.c.s.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-20017d90) Exception while trying to start secondary storage vm com.cloud.exception.InsufficientServerCapacityException: Unable to create a= deployment for VM[SecondaryStorageVm|s-54-VM]Scope=3Dinterface com.cloud.d= c.DataCenter; id=3D1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualM= achineManagerImpl.java:921) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachi= neManagerImpl.java:761) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachi= neManagerImpl.java:745) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSec= StorageVm(SecondaryStorageManagerImpl.java:261) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCap= acity(SecondaryStorageManagerImpl.java:694) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPo= ol(SecondaryStorageManagerImpl.java:1278) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool= (PremiumSecondaryStorageManagerImpl.java:123) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool= (PremiumSecondaryStorageManagerImpl.java:50) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.ja= va:111) at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.= java:35) at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner= .java:88) at com.cloud.vm.SystemVmLoadScanner$1.runInContext(SystemVmLoadScan= ner.java:79) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.r= un(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= $1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run= (ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.ja= va:471) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.access$301(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExec= utor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:615) at java.lang.Thread.run(Thread.java:744) 2014-07-08 14:44:40,308 INFO [c.c.s.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-20017d90) Unable to start secondary storage vm for standby capac= ity, secStorageVm vm Id : 54, will recycle it and start a new one 2014-07-08 14:44:40,317 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) VM is already stopped: VM[SecondaryStorageVm|s-54-VM] 2014-07-08 14:44:40,330 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -20017d90) VM state transitted from :Stopped to Expunging with event: Expun= geOperationvm's original host id: null new host id: null host id before sta= te transition: null 2014-07-08 14:44:40,331 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Destroying vm VM[SecondaryStorageVm|s-54-VM] 2014-07-08 14:44:40,331 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Cleaning up NICS 2014-07-08 14:44:40,340 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Cleaning network for vm: 54 2014-07-08 14:44:40,359 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx= -20017d90) public network deallocate network: networkId: 200, ip: 79.175.17= 3.179 2014-07-08 14:44:40,371 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx= -20017d90) Deallocated nic: NicProfile[205-54-null-null-null 2014-07-08 14:44:40,378 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Removed nic id=3D205 2014-07-08 14:44:40,380 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Revoving nic secondary ip entry ... 2014-07-08 14:44:40,405 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Removed nic id=3D206 2014-07-08 14:44:40,406 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Revoving nic secondary ip entry ... 2014-07-08 14:44:40,431 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Removed nic id=3D207 2014-07-08 14:44:40,433 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Revoving nic secondary ip entry ... 2014-07-08 14:44:40,458 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Removed nic id=3D208 2014-07-08 14:44:40,459 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-20017d90) Revoving nic secondary ip entry ... 2014-07-08 14:44:40,460 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Cleaning up hypervisor data structures (ex. SRs in XenServ= er) for managed storage 2014-07-08 14:44:40,460 DEBUG [o.a.c.e.o.VolumeOrchestrator] (secstorage-1:= ctx-20017d90) Cleaning storage for vm: 54 2014-07-08 14:44:40,520 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-20017d90)= Seq 2-404685278: Sending { Cmd , MgmtId: 345051256068, via: 2(172.16.71.5= 3), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.Delete= Command":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid"= :"0a5059a6-3a5c-45de-8a66-a3b695397363","volumeType":"ROOT","dataStore":{"o= rg.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"943e616e-71b5-= 387d-a23c-b15781d88cc7","id":1,"poolType":"VMFS","host":"VMFS datastore: /A= franet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"V= MFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?RO= LE=3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23c-b15781d88cc7"}},"name":"RO= OT-54","size":0,"path":"ROOT-54-000001","volumeId":54,"vmName":"s-54-VM","a= ccountId":1,"format":"OVA","id":54,"deviceId":0,"hypervisorType":"VMware"}}= ,"wait":0}}] } 2014-07-08 14:44:40,521 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-20017d90)= Seq 2-404685278: Executing: { Cmd , MgmtId: 345051256068, via: 2(172.16.7= 1.53), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.Del= eteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uu= id":"0a5059a6-3a5c-45de-8a66-a3b695397363","volumeType":"ROOT","dataStore":= {"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"943e616e-71= b5-387d-a23c-b15781d88cc7","id":1,"poolType":"VMFS","host":"VMFS datastore:= /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url"= :"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/= ?ROLE=3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23c-b15781d88cc7"}},"name":= "ROOT-54","size":0,"path":"ROOT-54-000001","volumeId":54,"vmName":"s-54-VM"= ,"accountId":1,"format":"OVA","id":54,"deviceId":0,"hypervisorType":"VMware= "}},"wait":0}}] } 2014-07-08 14:44:40,521 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-101= :ctx-d72101e4) Seq 2-404685278: Executing request 2014-07-08 14:44:40,522 INFO [c.c.s.r.VmwareStorageProcessor] (DirectAgent= -101:ctx-d72101e4 172.16.71.53) Executing resource DestroyCommand: {"data":= {"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0a5059a6-3a5c-4= 5de-8a66-a3b695397363","volumeType":"ROOT","dataStore":{"org.apache.cloudst= ack.storage.to.PrimaryDataStoreTO":{"uuid":"943e616e-71b5-387d-a23c-b15781d= 88cc7","id":1,"poolType":"VMFS","host":"VMFS datastore: /Afranet/SharedStor= ageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"VMFS://VMFS datast= ore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=3DPrimary&STOR= EUUID=3D943e616e-71b5-387d-a23c-b15781d88cc7"}},"name":"ROOT-54","size":0,"= path":"ROOT-54-000001","volumeId":54,"vmName":"s-54-VM","accountId":1,"form= at":"OVA","id":54,"deviceId":0,"hypervisorType":"VMware"}},"wait":0} 2014-07-08 14:44:40,623 INFO [c.c.s.r.VmwareStorageProcessor] (DirectAgent= -101:ctx-d72101e4 172.16.71.53) Destroy root volume and VM itself. vmName s= -54-VM 2014-07-08 14:44:41,012 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-101= :ctx-d72101e4) Seq 2-404685278: Response Received: 2014-07-08 14:44:41,013 DEBUG [c.c.a.t.Request] (DirectAgent-101:ctx-d72101= e4) Seq 2-404685278: Processing: { Ans: , MgmtId: 345051256068, via: 2, Ve= r: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"= Success","wait":0}}] } 2014-07-08 14:44:41,013 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-20017d90)= Seq 2-404685278: Received: { Ans: , MgmtId: 345051256068, via: 2, Ver: v1= , Flags: 10, { Answer } } 2014-07-08 14:44:41,029 INFO [o.a.c.s.v.VolumeServiceImpl] (secstorage-1:c= tx-20017d90) Volume 54 is not referred anywhere, remove it from volumes tab= le 2014-07-08 14:44:41,053 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-20017d90) Expunged VM[SecondaryStorageVm|s-54-VM] 2014-07-08 14:44:41,063 INFO [c.c.s.PremiumSecondaryStorageManagerImpl] (s= ecstorage-1:ctx-20017d90) Primary secondary storage is not even started, wa= it until next turn 2014-07-08 14:44:41,513 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-52abc8a8) Found 0 routers to update status. 2014-07-08 14:44:41,515 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] = (RouterStatusMonitor-1:ctx-52abc8a8) Found 0 networks to update RvR status. 2014-07-08 14:44:44,064 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-412:ctx-5b917= 06a 172.16.71.53) find VM v-52-VM on host 2014-07-08 14:44:44,064 INFO [c.c.h.v.m.HostMO] (DirectAgent-412:ctx-5b917= 06a 172.16.71.53) VM v-52-VM not found in host cache 2014-07-08 14:44:44,065 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-412:ctx-5b917= 06a 172.16.71.53) load VM cache on host 2014-07-08 14:44:44,536 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare ISO volume at new device {"key":-1,"backi= ng":{"fileName":"[29152781e45f3c90aa154b753a0d7a79] systemvm/systemvm-4.3.0= .iso","datastore":{"value":"datastore-142","type":"Datastore"}},"connectabl= e":{"startConnected":true,"allowGuestControl":false,"connected":true},"cont= rollerKey":200,"unitNumber":0} 2014-07-08 14:44:44,536 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Chose disk controller for vol ROOT -> ide, based = on root disk controller settings: ide 2014-07-08 14:44:44,584 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) Folder v-52-VM exists on datastore 2014-07-08 14:44:44,592 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) Search file ROOT-52-000001.vmdk on [SharedStorageCS] 2014-07-08 14:44:44,620 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) File [SharedStorageCS] ROOT-52-000001.vmdk does not = exist on datastore 2014-07-08 14:44:44,628 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) Search file ROOT-52-000001.vmdk on [SharedStorageCS]= v-52-VM 2014-07-08 14:44:44,664 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) File [SharedStorageCS] v-52-VM/ROOT-52-000001.vmdk e= xists on datastore 2014-07-08 14:44:44,672 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) Search file ROOT-52-000001-flat.vmdk on [SharedStora= geCS] 2014-07-08 14:44:44,708 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) File [SharedStorageCS] ROOT-52-000001-flat.vmdk does= not exist on datastore 2014-07-08 14:44:44,717 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) Search file ROOT-52-000001-delta.vmdk on [SharedStor= ageCS] 2014-07-08 14:44:44,755 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) File [SharedStorageCS] ROOT-52-000001-delta.vmdk doe= s not exist on datastore 2014-07-08 14:44:44,763 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) Search file ROOT-52-000001.vmdk on [SharedStorageCS] 2014-07-08 14:44:44,799 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) File [SharedStorageCS] ROOT-52-000001.vmdk does not = exist on datastore 2014-07-08 14:44:44,808 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) Search file ROOT-52-000001.vmdk on [SharedStorageCS]= v-52-VM 2014-07-08 14:44:44,844 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-412:ctx-= 5b91706a 172.16.71.53) File [SharedStorageCS] v-52-VM/ROOT-52-000001.vmdk e= xists on datastore 2014-07-08 14:44:44,855 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare volume at new device {"capacityInKB":0,"k= ey":-2,"backing":{"diskMode":"persistent","fileName":"[SharedStorageCS] v-5= 2-VM/ROOT-52-000001.vmdk","datastore":{"value":"datastore-14","type":"Datas= tore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"con= nected":true},"controllerKey":200,"unitNumber":1} 2014-07-08 14:44:44,855 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) VM v-52-VM will be started with NIC device type: = E1000 2014-07-08 14:44:44,856 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare NIC device based on NicTO: {"deviceId":0,= "networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-1b76-48dd-a91d-a76= 55266b233","mac":"02:00:5d:f9:00:34","broadcastType":"LinkLocal","type":"Co= ntrol","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"} 2014-07-08 14:44:44,865 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare network on vmwaresvs null with name prefi= x: cloud.private 2014-07-08 14:44:44,865 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Unrecognized broadcast type in VmwareResource, ty= pe: LinkLocal. Use vlan info from labeling: untagged 2014-07-08 14:44:44,865 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -412:ctx-5b91706a 172.16.71.53) Detected vswitch name as undefined. Default= ing to vSwitch0 2014-07-08 14:44:45,005 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -412:ctx-5b91706a 172.16.71.53) Network cloud.private.untagged.0.1-vSwitch0= is ready on vSwitch vSwitch0 2014-07-08 14:44:45,005 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Preparing NIC device on network cloud.private.unt= agged.0.1-vSwitch0 2014-07-08 14:44:45,006 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare NIC at new device {"operation":"ADD","dev= ice":{"addressType":"Manual","macAddress":"02:00:5d:f9:00:34","key":-3,"bac= king":{"network":{"value":"network-23","type":"Network"},"deviceName":"clou= d.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"all= owGuestControl":true,"connected":true},"unitNumber":0}} 2014-07-08 14:44:45,006 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare NIC device based on NicTO: {"deviceId":1,= "networkRateMbps":-1,"defaultNic":false,"uuid":"086e6913-be1f-41de-9b85-f7c= d3f75db37","ip":"172.16.71.63","netmask":"255.255.255.0","gateway":"172.16.= 71.1","mac":"06:fa:e0:00:00:03","broadcastType":"Native","type":"Management= ","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"} 2014-07-08 14:44:45,013 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare network on vmwaresvs null with name prefi= x: cloud.private 2014-07-08 14:44:45,013 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -412:ctx-5b91706a 172.16.71.53) Detected vswitch name as undefined. Default= ing to vSwitch0 2014-07-08 14:44:45,100 INFO [c.c.h.v.m.HypervisorHostHelper] (DirectAgent= -412:ctx-5b91706a 172.16.71.53) Network cloud.private.untagged.0.1-vSwitch0= is ready on vSwitch vSwitch0 2014-07-08 14:44:45,101 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Preparing NIC device on network cloud.private.unt= agged.0.1-vSwitch0 2014-07-08 14:44:45,101 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare NIC at new device {"operation":"ADD","dev= ice":{"addressType":"Manual","macAddress":"06:fa:e0:00:00:03","key":-4,"bac= king":{"network":{"value":"network-23","type":"Network"},"deviceName":"clou= d.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"all= owGuestControl":true,"connected":true},"unitNumber":1}} 2014-07-08 14:44:45,102 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare NIC device based on NicTO: {"deviceId":2,= "networkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7= d5a7995e","ip":"79.175.173.178","netmask":"255.255.255.240","gateway":"79.1= 75.173.177","mac":"06:60:ac:00:00:0b","dns1":"4.2.2.4","dns2":"8.8.8.8","br= oadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolation= Uri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmw= aredvs"} 2014-07-08 14:44:45,108 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) Prepare network on vmwaredvs dvSwitch with name p= refix: cloud.public 2014-07-08 14:44:45,114 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-412:c= tx-5b91706a 172.16.71.53) StartCommand failed due to Exception: java.lang.N= umberFormatException Message: null java.lang.NumberFormatException: null at java.lang.Integer.parseInt(Integer.java:454) at java.lang.Integer.parseInt(Integer.java:527) at com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.prepareNetwo= rk(HypervisorHostHelper.java:504) at com.cloud.hypervisor.vmware.resource.VmwareResource.prepareNetwo= rkFromNicInfo(VmwareResource.java:3692) at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(Vmwa= reResource.java:2934) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeReque= st(VmwareResource.java:525) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(Dir= ectAgentAttache.java:216) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.r= un(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= $1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run= (ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.ja= va:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExec= utor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:615) at java.lang.Thread.run(Thread.java:744) 2014-07-08 14:44:45,117 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-412= :ctx-5b91706a) Seq 2-404685277: Cancelling because one of the answers is fa= lse and it is stop on error. 2014-07-08 14:44:45,118 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-412= :ctx-5b91706a) Seq 2-404685277: Response Received: 2014-07-08 14:44:45,119 DEBUG [c.c.a.t.Request] (DirectAgent-412:ctx-5b9170= 6a) Seq 2-404685277: Processing: { Ans: , MgmtId: 345051256068, via: 2, Ve= r: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":52,"name"= :"v-52-VM","bootloader":"HVM","type":"ConsoleProxy","cpus":1,"minSpeed":500= ,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"hostName":"v-52-VM= ","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" templat= e=3DdomP type=3Dconsoleproxy host=3D172.16.71.52 port=3D8250 name=3Dv-52-VM= zone=3D1 pod=3D1 guid=3DProxy.52 proxy_vm=3D52 disable_rp_filter=3Dtrue et= h2ip=3D79.175.173.178 eth2mask=3D255.255.255.240 gateway=3D79.175.173.177 e= th0ip=3D0.0.0.0 eth0mask=3D0.0.0.0 eth1ip=3D172.16.71.63 eth1mask=3D255.255= .255.0 mgmtcidr=3D172.16.71.0/24 localgw=3D172.16.71.1 internaldns1=3D172.1= 6.9.9 internaldns2=3D172.16.9.10 dns1=3D4.2.2.4 dns2=3D8.8.8.8","rebootOnCr= ash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":= false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapter":"E1000","vmwa= re.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskControl= ler":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-ac19-4c3c-a937-63= 8d99af531f","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjec= tTO":{"uuid":"3bb25f3c-3a20-4188-8013-f1591c171da3","volumeType":"ROOT","da= taStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"94= 3e616e-71b5-387d-a23c-b15781d88cc7","id":1,"poolType":"VMFS","host":"VMFS d= atastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port= ":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedS= torageCS/?ROLE=3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23c-b15781d88cc7"}= },"name":"ROOT-52","size":0,"path":"ROOT-52-000001","volumeId":52,"vmName":= "v-52-VM","accountId":1,"format":"OVA","id":52,"deviceId":0,"hypervisorType= ":"VMware"}},"diskSeq":0,"path":"ROOT-52-000001","type":"ROOT","_details":{= "managed":"false","storagePort":"0","storageHost":"VMFS datastore: /Afranet= /SharedStorageCS","volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRateMbp= s":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5a7995e","ip":= "79.175.173.178","netmask":"255.255.255.240","gateway":"79.175.173.177","ma= c":"06:60:ac:00:00:0b","dns1":"4.2.2.4","dns2":"8.8.8.8","broadcastType":"V= lan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan://11= 62","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"},{"devi= ceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-1b76-48dd-= a91d-a7655266b233","mac":"02:00:5d:f9:00:34","broadcastType":"LinkLocal","t= ype":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"}= ,{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"086e6913-be1= f-41de-9b85-f7cd3f75db37","ip":"172.16.71.63","netmask":"255.255.255.0","ga= teway":"172.16.71.1","mac":"06:fa:e0:00:00:03","broadcastType":"Native","ty= pe":"Management","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs= "}]},"result":false,"details":"StartCommand failed due to Exception: java.l= ang.NumberFormatException\nMessage: null\n","wait":0}}] } 2014-07-08 14:44:45,120 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-666aea5= f) Seq 2-404685277: Received: { Ans: , MgmtId: 345051256068, via: 2, Ver: = v1, Flags: 10, { StartAnswer } } 2014-07-08 14:44:45,131 INFO [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-666aea5f) Unable to start VM on Host[-2-Routing] due to StartComma= nd failed due to Exception: java.lang.NumberFormatException Message: null 2014-07-08 14:44:45,138 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-666aea5f) Cleaning up resources for the vm VM[ConsoleProxy|v-52-VM= ] in Starting state 2014-07-08 14:44:45,142 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-666aea5= f) Seq 2-404685279: Sending { Cmd , MgmtId: 345051256068, via: 2(172.16.71= .53), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy= ":false,"executeInSequence":false,"vmName":"v-52-VM","wait":0}}] } 2014-07-08 14:44:45,143 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-666aea5= f) Seq 2-404685279: Executing: { Cmd , MgmtId: 345051256068, via: 2(172.16= .71.53), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isPr= oxy":false,"executeInSequence":false,"vmName":"v-52-VM","wait":0}}] } 2014-07-08 14:44:45,143 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-100= :ctx-80cb6b07) Seq 2-404685279: Executing request 2014-07-08 14:44:45,143 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-100:c= tx-80cb6b07 172.16.71.53) Executing resource StopCommand: {"isProxy":false,= "executeInSequence":false,"vmName":"v-52-VM","wait":0} 2014-07-08 14:44:45,157 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-100:ctx-80cb6= b07 172.16.71.53) find VM v-52-VM on host 2014-07-08 14:44:45,157 INFO [c.c.h.v.m.HostMO] (DirectAgent-100:ctx-80cb6= b07 172.16.71.53) VM v-52-VM not found in host cache 2014-07-08 14:44:45,157 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-100:ctx-80cb6= b07 172.16.71.53) load VM cache on host 2014-07-08 14:44:45,205 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-100:c= tx-80cb6b07 172.16.71.53) VM v-52-VM is already in stopped state 2014-07-08 14:44:45,205 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-100= :ctx-80cb6b07) Seq 2-404685279: Response Received: 2014-07-08 14:44:45,206 DEBUG [c.c.a.t.Request] (DirectAgent-100:ctx-80cb6b= 07) Seq 2-404685279: Processing: { Ans: , MgmtId: 345051256068, via: 2, Ve= r: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"detail= s":"VM v-52-VM is already in stopped state","wait":0}}] } 2014-07-08 14:44:45,206 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-666aea5= f) Seq 2-404685279: Received: { Ans: , MgmtId: 345051256068, via: 2, Ver: = v1, Flags: 10, { StopAnswer } } 2014-07-08 14:44:45,246 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (console= proxy-1:ctx-666aea5f) Releasing ip address for reservationId=3D03d3b005-e67= f-4420-9a2d-5f4acec31913, instance=3D200 2014-07-08 14:44:45,246 DEBUG [c.c.n.g.PodBasedNetworkGuru] (consoleproxy-1= :ctx-666aea5f) Released nic: NicProfile[200-52-null-null-null 2014-07-08 14:44:45,255 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-666aea5f) Successfully released network resources for the vm VM[Co= nsoleProxy|v-52-VM] 2014-07-08 14:44:45,255 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-666aea5f) Successfully cleanued up resources for the vm VM[Console= Proxy|v-52-VM] in Starting state 2014-07-08 14:44:45,259 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-666aea5f) Root volume is ready, need to place VM in volume's clust= er 2014-07-08 14:44:45,259 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-666aea5f) Vol[52|vm=3D52|ROOT] is READY, changing deployment plan = to use this pool's dcId: 1 , podId: 1 , and clusterId: 3 2014-07-08 14:44:45,262 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Deploy avoids pods: null, clusters: null, hosts: [1,= 2] 2014-07-08 14:44:45,264 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) DeploymentPlanner allocation algorithm: com.cloud.de= ploy.FirstFitPlanner@10ef1fe1 2014-07-08 14:44:45,264 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Trying to allocate a host and storage pools from dc:= 1, pod:1,cluster:3, requested cpu: 500, requested ram: 1073741824 2014-07-08 14:44:45,264 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Is ROOT volume READY (pool already allocated)?: Yes 2014-07-08 14:44:45,264 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-6= 66aea5f) Searching resources only under specified Cluster: 3 2014-07-08 14:44:45,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Checking resources in Cluster: 3 under Pod: 1 2014-07-08 14:44:45,273 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-666aea5f FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1= cluster:3 2014-07-08 14:44:45,278 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-666aea5f FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to = check for allocation: [Host[-2-Routing], Host[-1-Routing]] 2014-07-08 14:44:45,284 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-666aea5f FirstFitRoutingAllocator) Found 2 hosts for allocation afte= r prioritization: [Host[-2-Routing], Host[-1-Routing]] 2014-07-08 14:44:45,284 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-666aea5f FirstFitRoutingAllocator) Looking for speed=3D500Mhz, Ram= =3D1024 2014-07-08 14:44:45,284 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-666aea5f FirstFitRoutingAllocator) Host name: 172.16.71.53, hostId: = 2 is in avoid set, skipping this and trying other available hosts 2014-07-08 14:44:45,284 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-666aea5f FirstFitRoutingAllocator) Host name: 172.16.71.54, hostId: = 1 is in avoid set, skipping this and trying other available hosts 2014-07-08 14:44:45,284 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-666aea5f FirstFitRoutingAllocator) Host Allocator returning 0 suitab= le hosts 2014-07-08 14:44:45,284 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) No suitable hosts found 2014-07-08 14:44:45,284 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) No suitable hosts found under this Cluster: 3 2014-07-08 14:44:45,287 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Could not find suitable Deployment Destination for t= his VM under any clusters, returning. 2014-07-08 14:44:45,287 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-6= 66aea5f) Searching resources only under specified Cluster: 3 2014-07-08 14:44:45,289 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-6= 66aea5f) The specified cluster is in avoid set, returning. 2014-07-08 14:44:45,292 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Deploy avoids pods: null, clusters: [3], hosts: [1, = 2] 2014-07-08 14:44:45,293 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) DeploymentPlanner allocation algorithm: com.cloud.de= ploy.FirstFitPlanner@10ef1fe1 2014-07-08 14:44:45,294 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Trying to allocate a host and storage pools from dc:= 1, pod:1,cluster:null, requested cpu: 500, requested ram: 1073741824 2014-07-08 14:44:45,294 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-666aea5f) Is ROOT volume READY (pool already allocated)?: No 2014-07-08 14:44:45,294 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-6= 66aea5f) Searching resources only under specified Pod: 1 2014-07-08 14:44:45,294 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-6= 66aea5f) Listing clusters in order of aggregate capacity, that have (atleas= t one host with) enough CPU and RAM capacity under this Pod: 1 2014-07-08 14:44:45,299 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-6= 66aea5f) Removing from the clusterId list these clusters from avoid set: [3= ] 2014-07-08 14:44:45,300 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-6= 66aea5f) No clusters found after removing disabled clusters and clusters in= avoid list, returning. 2014-07-08 14:44:45,316 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-666aea5f) VM state transitted from :Starting to Stopped with event: Oper= ationFailedvm's original host id: null new host id: null host id before sta= te transition: 2 2014-07-08 14:44:45,325 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-666aea5f) Hosts's actual total CPU: 19200 and CPU after applying overpro= visioning: 19200 2014-07-08 14:44:45,325 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-666aea5f) Hosts's actual total RAM: 8579170304 and RAM after applying ov= erprovisioning: 8579170304 2014-07-08 14:44:45,326 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-666aea5f) release cpu from host: 2, old used: 500,reserved: 0, actual to= tal: 19200, total with overprovisioning: 19200; new used: 0,reserved:0; mov= edfromreserved: false,moveToReserveredfalse 2014-07-08 14:44:45,326 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-666aea5f) release mem from host: 2, old used: 1073741824,reserved: 0, to= tal: 8579170304; new used: 0,reserved:0; movedfromreserved: false,moveToRes= erveredfalse 2014-07-08 14:44:45,341 WARN [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-666aea5f) Exception while trying to start console proxy com.cloud.exception.InsufficientServerCapacityException: Unable to create a= deployment for VM[ConsoleProxy|v-52-VM]Scope=3Dinterface com.cloud.dc.Data= Center; id=3D1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualM= achineManagerImpl.java:921) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachi= neManagerImpl.java:761) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachi= neManagerImpl.java:745) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(Consol= eProxyManagerImpl.java:555) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(Con= soleProxyManagerImpl.java:941) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(Consol= eProxyManagerImpl.java:1666) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(Consol= eProxyManagerImpl.java:157) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.ja= va:118) at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.= java:35) at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner= .java:88) at com.cloud.vm.SystemVmLoadScanner$1.runInContext(SystemVmLoadScan= ner.java:79) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.r= un(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= $1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext= .runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run= (ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.ja= va:471) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.access$301(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFuture= Task.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExec= utor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:615) at java.lang.Thread.run(Thread.java:744) 2014-07-08 14:44:46,554 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-c5f02c50) Resetting hosts suitable for reconnect 2014-07-08 14:44:46,557 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-c5f02c50) Completed resetting hosts suitable for reconnect 2014-07-08 14:44:46,557 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-c5f02c50) Acquiring hosts for clusters already owned by this mana= gement server 2014-07-08 14:44:46,559 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-c5f02c50) Completed acquiring hosts for clusters already owned by= this management server 2014-07-08 14:44:46,559 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-c5f02c50) Acquiring hosts for clusters not owned by any managemen= t server 2014-07-08 14:44:46,560 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager = Timer:ctx-c5f02c50) Completed acquiring hosts for clusters not owned by any= management server 2014-07-08 14:44:58,928 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-7cd4e7a9) Zone 1 is ready to launch console proxy 2014-07-08 14:44:58,928 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-7cd4e7a9) Expand console proxy standby capacity for zone Afranet 2014-07-08 14:44:58,932 INFO [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-7cd4e7a9) Found a stopped console proxy, bring it up to running pool= . proxy vm id : 52 2014-07-08 14:44:58,942 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) VM state transitted from :Stopped to Starting with event: Star= tRequestedvm's original host id: null new host id: null host id before stat= e transition: null 2014-07-08 14:44:58,942 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-7cd4e7a9) Successfully transitioned to start state for VM[ConsoleP= roxy|v-52-VM] reservation id =3D 7df07366-ddbd-4667-84d7-a80ac80b4ea2 2014-07-08 14:44:58,958 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-7cd4e7a9) Trying to deploy VM, vm has dcId: 1 and podId: 1 2014-07-08 14:44:58,959 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-7cd4e7a9) Deploy avoids pods: null, clusters: null, hosts: null 2014-07-08 14:44:58,962 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-7cd4e7a9) Root volume is ready, need to place VM in volume's clust= er 2014-07-08 14:44:58,962 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-7cd4e7a9) Vol[52|vm=3D52|ROOT] is READY, changing deployment plan = to use this pool's dcId: 1 , podId: 1 , and clusterId: 3 2014-07-08 14:44:58,964 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Deploy avoids pods: null, clusters: null, hosts: nul= l 2014-07-08 14:44:58,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) DeploymentPlanner allocation algorithm: com.cloud.de= ploy.FirstFitPlanner@10ef1fe1 2014-07-08 14:44:58,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Trying to allocate a host and storage pools from dc:= 1, pod:1,cluster:3, requested cpu: 500, requested ram: 1073741824 2014-07-08 14:44:58,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Is ROOT volume READY (pool already allocated)?: Yes 2014-07-08 14:44:58,966 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-7= cd4e7a9) Searching resources only under specified Cluster: 3 2014-07-08 14:44:58,972 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Checking resources in Cluster: 3 under Pod: 1 2014-07-08 14:44:58,972 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1= cluster:3 2014-07-08 14:44:58,975 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-7cd4e7a9 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to = check for allocation: [Host[-2-Routing], Host[-1-Routing]] 2014-07-08 14:44:58,978 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Found 2 hosts for allocation afte= r prioritization: [Host[-2-Routing], Host[-1-Routing]] 2014-07-08 14:44:58,978 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Looking for speed=3D500Mhz, Ram= =3D1024 2014-07-08 14:44:58,984 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Host: 2 has cpu capability (cpu:8, sp= eed:2400) to support requested CPU: 1 and requested speed: 500 2014-07-08 14:44:58,984 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Checking if host: 2 has enough capaci= ty for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioni= ngFactor: 1.0 2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Hosts's actual total CPU: 19200 and C= PU after applying overprovisioning: 19200 2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Free CPU: 19200 , Requested CPU: 500 2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Free RAM: 8579170304 , Requested RAM:= 1073741824 2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Host has enough CPU and RAM available 2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, us= ed: 0, reserved: 0, actual total: 19200, total with overprovisioning: 19200= ; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?:= true 2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, us= ed: 0, reserved: 0, total: 8579170304; requested mem: 1073741824,alloc_from= _last_host?:false ,considerReservedCapacity?: true 2014-07-08 14:44:58,987 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Found a suitable host, adding to = list: 2 2014-07-08 14:44:58,993 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:8, sp= eed:2400) to support requested CPU: 1 and requested speed: 500 2014-07-08 14:44:58,993 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Checking if host: 1 has enough capaci= ty for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioni= ngFactor: 1.0 2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Hosts's actual total CPU: 19200 and C= PU after applying overprovisioning: 19200 2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Free CPU: 19200 , Requested CPU: 500 2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Free RAM: 8579170304 , Requested RAM:= 1073741824 2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) Host has enough CPU and RAM available 2014-07-08 14:44:58,996 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, us= ed: 0, reserved: 0, actual total: 19200, total with overprovisioning: 19200= ; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?:= true 2014-07-08 14:44:58,996 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, us= ed: 0, reserved: 0, total: 8579170304; requested mem: 1073741824,alloc_from= _last_host?:false ,considerReservedCapacity?: true 2014-07-08 14:44:58,996 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Found a suitable host, adding to = list: 1 2014-07-08 14:44:58,996 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (consoleproxy= -1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Host Allocator returning 2 suitab= le hosts 2014-07-08 14:44:58,997 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Checking suitable pools for volume (Id, Type): (52,R= OOT) 2014-07-08 14:44:58,997 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Volume has pool already allocated, checking if pool = can be reused, poolId: 1 2014-07-08 14:44:58,998 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Planner need not allocate a pool for this volume sin= ce its READY 2014-07-08 14:44:58,999 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Trying to find a potenial host and associated storag= e pools from the suitable host/pool lists for this VM 2014-07-08 14:44:58,999 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Checking if host: 2 can access any suitable storage = pool for volume: ROOT 2014-07-08 14:44:59,000 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Host: 2 can access pool: 1 2014-07-08 14:44:59,001 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Found a potential host id: 2 name: 172.16.71.53 and = associated storage pools for this VM 2014-07-08 14:44:59,002 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consol= eproxy-1:ctx-7cd4e7a9) Returning Deployment Destination: Dest[Zone(Id)-Pod(= Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)= -Pod(1)-Cluster(3)-Host(2)-Storage()] 2014-07-08 14:44:59,002 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-7cd4e7a9) Deployment found - P0=3DVM[ConsoleProxy|v-52-VM], P0=3D= Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id= ))] : Dest[Zone(1)-Pod(1)-Cluster(3)-Host(2)-Storage()] 2014-07-08 14:44:59,025 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) VM state transitted from :Starting to Starting with event: Ope= rationRetryvm's original host id: null new host id: 2 host id before state = transition: null 2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) Hosts's actual total CPU: 19200 and CPU after applying overpro= visioning: 19200 2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) We are allocating VM, increasing the used capacity of this hos= t:2 2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) Current Used CPU: 0 , Free CPU:19200 ,Requested CPU: 500 2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) Current Used RAM: 0 , Free RAM:8579170304 ,Requested RAM: 1073= 741824 2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) CPU STATS after allocation: for host: 2, old used: 0, old rese= rved: 0, actual total: 19200, total with overprovisioning: 19200; new used:= 500, reserved:0; requested cpu:500,alloc_from_last:false 2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:c= tx-7cd4e7a9) RAM STATS after allocation: for host: 2, old used: 0, old rese= rved: 0, total: 8579170304; new used: 1073741824, reserved: 0; requested me= m: 1073741824,alloc_from_last:false 2014-07-08 14:44:59,038 DEBUG [c.c.v.VirtualMachineManagerImpl] (consolepro= xy-1:ctx-7cd4e7a9) VM is being created in podId: 1 2014-07-08 14:44:59,042 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy= -1:ctx-7cd4e7a9) Network id=3D200 is already implemented 2014-07-08 14:44:59,061 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy= -1:ctx-7cd4e7a9) Network id=3D202 is already implemented 2014-07-08 14:44:59,081 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy= -1:ctx-7cd4e7a9) Network id=3D201 is already implemented 2014-07-08 14:44:59,110 DEBUG [c.c.n.g.PodBasedNetworkGuru] (consoleproxy-1= :ctx-7cd4e7a9) Allocated a nic NicProfile[200-52-7df07366-ddbd-4667-84d7-a8= 0ac80b4ea2-172.16.71.61-null for VM[ConsoleProxy|v-52-VM] 2014-07-08 14:44:59,119 DEBUG [o.a.c.e.o.VolumeOrchestrator] (consoleproxy-= 1:ctx-7cd4e7a9) Checking if we need to prepare 1 volumes for VM[ConsoleProx= y|v-52-VM] 2014-07-08 14:44:59,120 DEBUG [o.a.c.e.o.VolumeOrchestrator] (consoleproxy-= 1:ctx-7cd4e7a9) No need to recreate the volume: Vol[52|vm=3D52|ROOT], since= it already has a pool assigned: 1, adding disk to VM 2014-07-08 14:44:59,127 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-= 83bab33c) VmStatsCollector is running... 2014-07-08 14:44:59,146 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy= -1:ctx-7cd4e7a9) Boot Args for VM[ConsoleProxy|v-52-VM]: template=3DdomP t= ype=3Dconsoleproxy host=3D172.16.71.52 port=3D8250 name=3Dv-52-VM zone=3D1 = pod=3D1 guid=3DProxy.52 proxy_vm=3D52 disable_rp_filter=3Dtrue eth2ip=3D79.= 175.173.178 eth2mask=3D255.255.255.240 gateway=3D79.175.173.177 eth0ip=3D0.= 0.0.0 eth0mask=3D0.0.0.0 eth1ip=3D172.16.71.61 eth1mask=3D255.255.255.0 mgm= tcidr=3D172.16.71.0/24 localgw=3D172.16.71.1 internaldns1=3D172.16.9.9 inte= rnaldns2=3D172.16.9.10 dns1=3D4.2.2.4 dns2=3D8.8.8.8 2014-07-08 14:44:59,161 DEBUG [c.c.h.g.VMwareGuru] (consoleproxy-1:ctx-7cd4= e7a9) Nested virtualization requested, adding flag to vm configuration 2014-07-08 14:44:59,181 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-7cd4e7a= 9) Seq 2-404685280: Sending { Cmd , MgmtId: 345051256068, via: 2(172.16.71= .53), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"= id":52,"name":"v-52-VM","bootloader":"HVM","type":"ConsoleProxy","cpus":1,"= minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"hostN= ame":"v-52-VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootAr= gs":" template=3DdomP type=3Dconsoleproxy host=3D172.16.71.52 port=3D8250 n= ame=3Dv-52-VM zone=3D1 pod=3D1 guid=3DProxy.52 proxy_vm=3D52 disable_rp_fil= ter=3Dtrue eth2ip=3D79.175.173.178 eth2mask=3D255.255.255.240 gateway=3D79.= 175.173.177 eth0ip=3D0.0.0.0 eth0mask=3D0.0.0.0 eth1ip=3D172.16.71.61 eth1m= ask=3D255.255.255.0 mgmtcidr=3D172.16.71.0/24 localgw=3D172.16.71.1 interna= ldns1=3D172.16.9.9 internaldns2=3D172.16.9.10 dns1=3D4.2.2.4 dns2=3D8.8.8.8= ","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamic= allyScaleVm":false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapter":= "E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","ro= otDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-ac19= -4c3c-a937-638d99af531f","disks":[{"data":{"org.apache.cloudstack.storage.t= o.VolumeObjectTO":{"uuid":"3bb25f3c-3a20-4188-8013-f1591c171da3","volumeTyp= e":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO= ":{"uuid":"943e616e-71b5-387d-a23c-b15781d88cc7","id":1,"poolType":"VMFS","= host":"VMFS datastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedSto= rageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Af= ranet/SharedStorageCS/?ROLE=3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23c-b= 15781d88cc7"}},"name":"ROOT-52","size":0,"path":"ROOT-52-000001","volumeId"= :52,"vmName":"v-52-VM","accountId":1,"format":"OVA","id":52,"deviceId":0,"h= ypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-52-000001","type":"ROOT"= ,"_details":{"managed":"false","storagePort":"0","storageHost":"VMFS datast= ore: /Afranet/SharedStorageCS","volumeSize":"0"}}],"nics":[{"deviceId":2,"n= etworkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5= a7995e","ip":"79.175.173.178","netmask":"255.255.255.240","gateway":"79.175= .173.177","mac":"06:60:ac:00:00:0b","dns1":"4.2.2.4","dns2":"8.8.8.8","broa= dcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolationUr= i":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwar= edvs"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190= e5-1b76-48dd-a91d-a7655266b233","mac":"02:00:5d:f9:00:34","broadcastType":"= LinkLocal","type":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0= ,,vmwaresvs"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":= "086e6913-be1f-41de-9b85-f7cd3f75db37","ip":"172.16.71.61","netmask":"255.2= 55.255.0","gateway":"172.16.71.1","mac":"06:65:a4:00:00:01","broadcastType"= :"Native","type":"Management","isSecurityGroupEnabled":false,"name":"vSwitc= h0,,vmwaresvs"}]},"hostIp":"172.16.71.53","executeInSequence":false,"wait":= 0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"172.16.71.61","port= ":3922,"interval":6,"retries":100,"name":"v-52-VM","wait":0}}] } 2014-07-08 14:44:59,182 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-7cd4e7a= 9) Seq 2-404685280: Executing: { Cmd , MgmtId: 345051256068, via: 2(172.16= .71.53), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm"= :{"id":52,"name":"v-52-VM","bootloader":"HVM","type":"ConsoleProxy","cpus":= 1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"ho= stName":"v-52-VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","boo= tArgs":" template=3DdomP type=3Dconsoleproxy host=3D172.16.71.52 port=3D825= 0 name=3Dv-52-VM zone=3D1 pod=3D1 guid=3DProxy.52 proxy_vm=3D52 disable_rp_= filter=3Dtrue eth2ip=3D79.175.173.178 eth2mask=3D255.255.255.240 gateway=3D= 79.175.173.177 eth0ip=3D0.0.0.0 eth0mask=3D0.0.0.0 eth1ip=3D172.16.71.61 et= h1mask=3D255.255.255.0 mgmtcidr=3D172.16.71.0/24 localgw=3D172.16.71.1 inte= rnaldns1=3D172.16.9.9 internaldns2=3D172.16.9.10 dns1=3D4.2.2.4 dns2=3D8.8.= 8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDyna= micallyScaleVm":false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapte= r":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false",= "rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-a= c19-4c3c-a937-638d99af531f","disks":[{"data":{"org.apache.cloudstack.storag= e.to.VolumeObjectTO":{"uuid":"3bb25f3c-3a20-4188-8013-f1591c171da3","volume= Type":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStor= eTO":{"uuid":"943e616e-71b5-387d-a23c-b15781d88cc7","id":1,"poolType":"VMFS= ","host":"VMFS datastore: /Afranet/SharedStorageCS","path":"/Afranet/Shared= StorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS/= /Afranet/SharedStorageCS/?ROLE=3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23= c-b15781d88cc7"}},"name":"ROOT-52","size":0,"path":"ROOT-52-000001","volume= Id":52,"vmName":"v-52-VM","accountId":1,"format":"OVA","id":52,"deviceId":0= ,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-52-000001","type":"RO= OT","_details":{"managed":"false","storagePort":"0","storageHost":"VMFS dat= astore: /Afranet/SharedStorageCS","volumeSize":"0"}}],"nics":[{"deviceId":2= ,"networkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc= 7d5a7995e","ip":"79.175.173.178","netmask":"255.255.255.240","gateway":"79.= 175.173.177","mac":"06:60:ac:00:00:0b","dns1":"4.2.2.4","dns2":"8.8.8.8","b= roadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolatio= nUri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vm= waredvs"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2= 190e5-1b76-48dd-a91d-a7655266b233","mac":"02:00:5d:f9:00:34","broadcastType= ":"LinkLocal","type":"Control","isSecurityGroupEnabled":false,"name":"vSwit= ch0,,vmwaresvs"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uui= d":"086e6913-be1f-41de-9b85-f7cd3f75db37","ip":"172.16.71.61","netmask":"25= 5.255.255.0","gateway":"172.16.71.1","mac":"06:65:a4:00:00:01","broadcastTy= pe":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"vSw= itch0,,vmwaresvs"}]},"hostIp":"172.16.71.53","executeInSequence":false,"wai= t":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"172.16.71.61","p= ort":3922,"interval":6,"retries":100,"name":"v-52-VM","wait":0}}] } 2014-07-08 14:44:59,183 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5:c= tx-5951bdf7) Seq 2-404685280: Executing request 2014-07-08 14:44:59,185 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-5:ctx= -5951bdf7 172.16.71.53) Executing resource StartCommand: {"vm":{"id":52,"na= me":"v-52-VM","bootloader":"HVM","type":"ConsoleProxy","cpus":1,"minSpeed":= 500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"hostName":"v-52= -VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" temp= late=3DdomP type=3Dconsoleproxy host=3D172.16.71.52 port=3D8250 name=3Dv-52= -VM zone=3D1 pod=3D1 guid=3DProxy.52 proxy_vm=3D52 disable_rp_filter=3Dtrue= eth2ip=3D79.175.173.178 eth2mask=3D255.255.255.240 gateway=3D79.175.173.17= 7 eth0ip=3D0.0.0.0 eth0mask=3D0.0.0.0 eth1ip=3D172.16.71.61 eth1mask=3D255.= 255.255.0 mgmtcidr=3D172.16.71.0/24 localgw=3D172.16.71.1 internaldns1=3D17= 2.16.9.9 internaldns2=3D172.16.9.10 dns1=3D4.2.2.4 dns2=3D8.8.8.8","rebootO= nCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleV= m":false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapter":"E1000","v= mware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskCont= roller":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-ac19-4c3c-a937= -638d99af531f","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeOb= jectTO":{"uuid":"3bb25f3c-3a20-4188-8013-f1591c171da3","volumeType":"ROOT",= "dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":= "943e616e-71b5-387d-a23c-b15781d88cc7","id":1,"poolType":"VMFS","host":"VMF= S datastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","p= ort":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/Shar= edStorageCS/?ROLE=3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23c-b15781d88cc= 7"}},"name":"ROOT-52","size":0,"path":"ROOT-52-000001","volumeId":52,"vmNam= e":"v-52-VM","accountId":1,"format":"OVA","id":52,"deviceId":0,"hypervisorT= ype":"VMware"}},"diskSeq":0,"path":"ROOT-52-000001","type":"ROOT","_details= ":{"managed":"false","storagePort":"0","storageHost":"VMFS datastore: /Afra= net/SharedStorageCS","volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRate= Mbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5a7995e","i= p":"79.175.173.178","netmask":"255.255.255.240","gateway":"79.175.173.177",= "mac":"06:60:ac:00:00:0b","dns1":"4.2.2.4","dns2":"8.8.8.8","broadcastType"= :"Vlan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan:/= /1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"},{"d= eviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-1b76-48= dd-a91d-a7655266b233","mac":"02:00:5d:f9:00:34","broadcastType":"LinkLocal"= ,"type":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresv= s"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"086e6913-= be1f-41de-9b85-f7cd3f75db37","ip":"172.16.71.61","netmask":"255.255.255.0",= "gateway":"172.16.71.1","mac":"06:65:a4:00:00:01","broadcastType":"Native",= "type":"Management","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmware= svs"}]},"hostIp":"172.16.71.53","executeInSequence":false,"wait":0} 2014-07-08 14:44:59,255 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-5a0f1049) Zone 1 is ready to launch secondary storage VM 2014-07-08 14:44:59,261 INFO [c.c.s.PremiumSecondaryStorageManagerImpl] (s= ecstorage-1:ctx-5a0f1049) No running secondary storage vms found in datacen= ter id=3D1, starting one 2014-07-08 14:44:59,266 INFO [c.c.s.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-5a0f1049) No stopped secondary storage vm is available, need to = allocate a new secondary storage vm 2014-07-08 14:44:59,268 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secsto= rage-1:ctx-5a0f1049) Assign secondary storage vm from a newly started insta= nce for request from data center : 1 2014-07-08 14:44:59,274 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-5:ctx-5951bdf= 7 172.16.71.53) find VM v-52-VM on host 2014-07-08 14:44:59,275 INFO [c.c.h.v.m.HostMO] (DirectAgent-5:ctx-5951bdf= 7 172.16.71.53) VM v-52-VM not found in host cache 2014-07-08 14:44:59,275 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-5:ctx-5951bdf= 7 172.16.71.53) load VM cache on host 2014-07-08 14:44:59,284 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Found existing network configuration for offering [Network O= ffering [1-Public-System-Public-Network]: Ntwk[200|Public|1] 2014-07-08 14:44:59,285 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Releasing lock for Acct[0addad94-059f-11e4-b96b-005056a85504= -system] 2014-07-08 14:44:59,288 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Found existing network configuration for offering [Network O= ffering [3-Control-System-Control-Network]: Ntwk[202|Control|3] 2014-07-08 14:44:59,288 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Releasing lock for Acct[0addad94-059f-11e4-b96b-005056a85504= -system] 2014-07-08 14:44:59,292 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Found existing network configuration for offering [Network O= ffering [2-Management-System-Management-Network]: Ntwk[201|Management|2] 2014-07-08 14:44:59,292 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Releasing lock for Acct[0addad94-059f-11e4-b96b-005056a85504= -system] 2014-07-08 14:44:59,294 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-5:ctx= -5951bdf7 172.16.71.53) VM v-52-VM already exists, tear down devices for re= configuration 2014-07-08 14:44:59,296 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Found existing network configuration for offering [Network O= ffering [4-Storage-System-Storage-Network]: Ntwk[203|Storage|4] 2014-07-08 14:44:59,296 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Releasing lock for Acct[0addad94-059f-11e4-b96b-005056a85504= -system] 2014-07-08 14:44:59,318 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Allocating entries for VM: VM[SecondaryStorageVm|s-55-VM] 2014-07-08 14:44:59,324 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Allocating nics for VM[SecondaryStorageVm|s-55-VM] 2014-07-08 14:44:59,325 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Allocating nic for vm VM[SecondaryStorageVm|s-55-VM] in netw= ork Ntwk[200|Public|1] with requested profile NicProfile[0-0-null-null-null 2014-07-08 14:44:59,341 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Allocating nic for vm VM[SecondaryStorageVm|s-55-VM] in netw= ork Ntwk[202|Control|3] with requested profile null 2014-07-08 14:44:59,358 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Allocating nic for vm VM[SecondaryStorageVm|s-55-VM] in netw= ork Ntwk[201|Management|2] with requested profile null 2014-07-08 14:44:59,366 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Allocating nic for vm VM[SecondaryStorageVm|s-55-VM] in netw= ork Ntwk[203|Storage|4] with requested profile null 2014-07-08 14:44:59,378 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Allocating disks for VM[SecondaryStorageVm|s-55-VM] 2014-07-08 14:44:59,388 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Allocation completed for VM: VM[SecondaryStorageVm|s-55-VM= ] 2014-07-08 14:44:59,392 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secst= orage-1:ctx-5a0f1049) received secondary storage vm alert 2014-07-08 14:44:59,392 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secst= orage-1:ctx-5a0f1049) New secondary storage vm created, zone: Afranet, secS= torageVm: s-55-VM, public IP: null, private IP: null 2014-07-08 14:44:59,411 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) VM state transitted from :Stopped to Starting with event: StartR= equestedvm's original host id: null new host id: null host id before state = transition: null 2014-07-08 14:44:59,411 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Successfully transitioned to start state for VM[SecondaryS= torageVm|s-55-VM] reservation id =3D 7758870a-f8f9-4b35-88ef-4f8fda9eee85 2014-07-08 14:44:59,418 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Trying to deploy VM, vm has dcId: 1 and podId: null 2014-07-08 14:44:59,418 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Deploy avoids pods: null, clusters: null, hosts: null 2014-07-08 14:44:59,425 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Deploy avoids pods: null, clusters: null, hosts: null 2014-07-08 14:44:59,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) DeploymentPlanner allocation algorithm: com.cloud.depl= oy.FirstFitPlanner@10ef1fe1 2014-07-08 14:44:59,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Trying to allocate a host and storage pools from dc:1,= pod:null,cluster:null, requested cpu: 500, requested ram: 536870912 2014-07-08 14:44:59,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Is ROOT volume READY (pool already allocated)?: No 2014-07-08 14:44:59,426 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-5a0= f1049) Searching all possible resources under this Zone: 1 2014-07-08 14:44:59,428 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-5a0= f1049) Listing clusters in order of aggregate capacity, that have (atleast = one host with) enough CPU and RAM capacity under this Zone: 1 2014-07-08 14:44:59,440 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Checking resources in Cluster: 3 under Pod: 1 2014-07-08 14:44:59,440 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-5a0f1049 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 = cluster:3 2014-07-08 14:44:59,444 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-5a0f1049 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to ch= eck for allocation: [Host[-1-Routing], Host[-2-Routing]] 2014-07-08 14:44:59,448 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-5a0f1049 FirstFitRoutingAllocator) Found 2 hosts for allocation after = prioritization: [Host[-1-Routing], Host[-2-Routing]] 2014-07-08 14:44:59,448 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-5a0f1049 FirstFitRoutingAllocator) Looking for speed=3D500Mhz, Ram=3D5= 12 2014-07-08 14:44:59,456 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:8, spee= d:2400) to support requested CPU: 1 and requested speed: 500 2014-07-08 14:44:59,456 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity= for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningF= actor: 1.0 2014-07-08 14:44:59,459 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Hosts's actual total CPU: 19200 and CPU= after applying overprovisioning: 19200 2014-07-08 14:44:59,459 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Free CPU: 19200 , Requested CPU: 500 2014-07-08 14:44:59,459 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Free RAM: 8579170304 , Requested RAM: 5= 36870912 2014-07-08 14:44:59,459 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Host has enough CPU and RAM available 2014-07-08 14:44:59,460 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used= : 0, reserved: 0, actual total: 19200, total with overprovisioning: 19200; = requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: t= rue 2014-07-08 14:44:59,460 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used= : 0, reserved: 0, total: 8579170304; requested mem: 536870912,alloc_from_la= st_host?:false ,considerReservedCapacity?: true 2014-07-08 14:44:59,460 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-5a0f1049 FirstFitRoutingAllocator) Found a suitable host, adding to li= st: 1 2014-07-08 14:44:59,467 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Host: 2 has cpu capability (cpu:8, spee= d:2400) to support requested CPU: 1 and requested speed: 500 2014-07-08 14:44:59,467 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Checking if host: 2 has enough capacity= for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningF= actor: 1.0 2014-07-08 14:44:59,469 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Hosts's actual total CPU: 19200 and CPU= after applying overprovisioning: 19200 2014-07-08 14:44:59,469 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Free CPU: 18700 , Requested CPU: 500 2014-07-08 14:44:59,469 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Free RAM: 7505428480 , Requested RAM: 5= 36870912 2014-07-08 14:44:59,469 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) Host has enough CPU and RAM available 2014-07-08 14:44:59,470 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used= : 500, reserved: 0, actual total: 19200, total with overprovisioning: 19200= ; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?:= true 2014-07-08 14:44:59,470 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used= : 1073741824, reserved: 0, total: 8579170304; requested mem: 536870912,allo= c_from_last_host?:false ,considerReservedCapacity?: true 2014-07-08 14:44:59,470 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-5a0f1049 FirstFitRoutingAllocator) Found a suitable host, adding to li= st: 2 2014-07-08 14:44:59,470 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (secstorage-1= :ctx-5a0f1049 FirstFitRoutingAllocator) Host Allocator returning 2 suitable= hosts 2014-07-08 14:44:59,471 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Checking suitable pools for volume (Id, Type): (55,ROO= T) 2014-07-08 14:44:59,471 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) We need to allocate new storagepool for this volume 2014-07-08 14:44:59,471 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Calling StoragePoolAllocators to find suitable pools 2014-07-08 14:44:59,472 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (secsto= rage-1:ctx-5a0f1049) LocalStoragePoolAllocator trying to find storage pool = to fit the vm 2014-07-08 14:44:59,472 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] = (secstorage-1:ctx-5a0f1049) ClusterScopeStoragePoolAllocator looking for st= orage pool 2014-07-08 14:44:59,472 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] = (secstorage-1:ctx-5a0f1049) Looking for pools in dc: 1 pod:1 cluster:3 2014-07-08 14:44:59,474 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] = (secstorage-1:ctx-5a0f1049) Found pools matching tags: [Pool[1|VMFS]] 2014-07-08 14:44:59,475 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] = (secstorage-1:ctx-5a0f1049) Removing pool Pool[1|VMFS] from avoid set, must= have been inserted when searching for another disk's tag 2014-07-08 14:44:59,476 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (sec= storage-1:ctx-5a0f1049) Checking if storage pool is suitable, name: null ,p= oolId: 1 2014-07-08 14:44:59,480 DEBUG [c.c.s.StorageManagerImpl] (secstorage-1:ctx-= 5a0f1049) Checking pool 1 for storage, totalSize: 536602476544, usedBytes: = 19064160256, usedPct: 0.03552752938969485, disable threshold: 0.85 2014-07-08 14:44:59,486 DEBUG [c.c.s.StorageManagerImpl] (secstorage-1:ctx-= 5a0f1049) Checking pool: 1 for volume allocation [Vol[55|vm=3D55|ROOT]], ma= xSize : 1073204953088, totalAllocatedSize : 0, askingSize : 0, allocated di= sable threshold: 0.85 2014-07-08 14:44:59,486 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] = (secstorage-1:ctx-5a0f1049) ClusterScopeStoragePoolAllocator returning 1 su= itable storage pools 2014-07-08 14:44:59,487 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Trying to find a potenial host and associated storage = pools from the suitable host/pool lists for this VM 2014-07-08 14:44:59,487 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Checking if host: 1 can access any suitable storage po= ol for volume: ROOT 2014-07-08 14:44:59,488 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Host: 1 can access pool: 1 2014-07-08 14:44:59,488 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Found a potential host id: 1 name: 172.16.71.54 and as= sociated storage pools for this VM 2014-07-08 14:44:59,489 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secsto= rage-1:ctx-5a0f1049) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id= )-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-P= od(1)-Cluster(3)-Host(1)-Storage(Volume(55|ROOT-->Pool(1))] 2014-07-08 14:44:59,489 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) Deployment found - P0=3DVM[SecondaryStorageVm|s-55-VM], P= 0=3DDest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Poo= l(Id))] : Dest[Zone(1)-Pod(1)-Cluster(3)-Host(1)-Storage(Volume(55|ROOT-->P= ool(1))] 2014-07-08 14:44:59,507 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) VM state transitted from :Starting to Starting with event: Opera= tionRetryvm's original host id: null new host id: 1 host id before state tr= ansition: null 2014-07-08 14:44:59,516 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) Hosts's actual total CPU: 19200 and CPU after applying overprovi= sioning: 19200 2014-07-08 14:44:59,516 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) We are allocating VM, increasing the used capacity of this host:= 1 2014-07-08 14:44:59,516 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) Current Used CPU: 0 , Free CPU:19200 ,Requested CPU: 500 2014-07-08 14:44:59,516 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) Current Used RAM: 0 , Free RAM:8579170304 ,Requested RAM: 536870= 912 2014-07-08 14:44:59,516 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) CPU STATS after allocation: for host: 1, old used: 0, old reserv= ed: 0, actual total: 19200, total with overprovisioning: 19200; new used:50= 0, reserved:0; requested cpu:500,alloc_from_last:false 2014-07-08 14:44:59,516 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx= -5a0f1049) RAM STATS after allocation: for host: 1, old used: 0, old reserv= ed: 0, total: 8579170304; new used: 536870912, reserved: 0; requested mem: = 536870912,alloc_from_last:false 2014-07-08 14:44:59,525 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage= -1:ctx-5a0f1049) VM is being created in podId: 1 2014-07-08 14:44:59,530 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Network id=3D200 is already implemented 2014-07-08 14:44:59,553 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Network id=3D202 is already implemented 2014-07-08 14:44:59,578 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Network id=3D201 is already implemented 2014-07-08 14:44:59,603 DEBUG [c.c.n.g.PodBasedNetworkGuru] (secstorage-1:c= tx-5a0f1049) Allocated a nic NicProfile[211-55-7758870a-f8f9-4b35-88ef-4f8f= da9eee85-172.16.71.65-null for VM[SecondaryStorageVm|s-55-VM] 2014-07-08 14:44:59,613 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1= :ctx-5a0f1049) Network id=3D203 is already implemented 2014-07-08 14:44:59,641 DEBUG [c.c.n.g.StorageNetworkGuru] (secstorage-1:ct= x-5a0f1049) Allocated a storage nic NicProfile[212-55-7758870a-f8f9-4b35-88= ef-4f8fda9eee85-172.16.71.60-null for VM[SecondaryStorageVm|s-55-VM] 2014-07-08 14:44:59,650 DEBUG [o.a.c.e.o.VolumeOrchestrator] (secstorage-1:= ctx-5a0f1049) Checking if we need to prepare 1 volumes for VM[SecondaryStor= ageVm|s-55-VM] 2014-07-08 14:44:59,662 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (secstora= ge-1:ctx-5a0f1049) template 8 is already in store:5, type:Image 2014-07-08 14:44:59,666 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (secstora= ge-1:ctx-5a0f1049) template 8 is already in store:1, type:Primary 2014-07-08 14:44:59,691 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (secsto= rage-1:ctx-5a0f1049) copyAsync inspecting src type TEMPLATE copyAsync inspe= cting dest type VOLUME 2014-07-08 14:44:59,703 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-5a0f1049)= Seq 2-404685281: Sending { Cmd , MgmtId: 345051256068, via: 2(172.16.71.5= 3), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCo= mmand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path= ":"dc1cf88af85a3c5192ae5e1db3c025a5","origUrl":"http://download.cloud.com/t= emplates/4.3/systemvm64template-2014-01-14-master-vmware.ova","uuid":"ba6d7= 1fa-059e-11e4-b96b-005056a85504","id":8,"format":"OVA","accountId":1,"check= sum":"ef593a061f3b7594ab0bfd9b0ed0a0d4","hvm":false,"displayText":"SystemVM= Template (vSphere)","imageDataStore":{"org.apache.cloudstack.storage.to.Pr= imaryDataStoreTO":{"uuid":"943e616e-71b5-387d-a23c-b15781d88cc7","id":1,"po= olType":"VMFS","host":"VMFS datastore: /Afranet/SharedStorageCS","path":"/A= franet/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/Sha= redStorageCS//Afranet/SharedStorageCS/?ROLE=3DPrimary&STOREUUID=3D943e616e-= 71b5-387d-a23c-b15781d88cc7"}},"name":"routing-8","hypervisorType":"VMware"= }},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f9b= ad8a9-faf9-44cf-8dd2-48e89fe37912","volumeType":"ROOT","dataStore":{"org.ap= ache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"943e616e-71b5-387d-= a23c-b15781d88cc7","id":1,"poolType":"VMFS","host":"VMFS datastore: /Afrane= t/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"VMFS:/= /VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=3D= Primary&STOREUUID=3D943e616e-71b5-387d-a23c-b15781d88cc7"}},"name":"ROOT-55= ","size":0,"volumeId":55,"vmName":"s-55-VM","accountId":1,"format":"OVA","i= d":55,"deviceId":0,"hypervisorType":"VMware"}},"executeInSequence":false,"o= ptions":{},"wait":0}}] } 2014-07-08 14:44:59,703 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-5a0f1049)= Seq 2-404685281: Executing: { Cmd , MgmtId: 345051256068, via: 2(172.16.7= 1.53), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.Cop= yCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"p= ath":"dc1cf88af85a3c5192ae5e1db3c025a5","origUrl":"http://download.cloud.co= m/templates/4.3/systemvm64template-2014-01-14-master-vmware.ova","uuid":"ba= 6d71fa-059e-11e4-b96b-005056a85504","id":8,"format":"OVA","accountId":1,"ch= ecksum":"ef593a061f3b7594ab0bfd9b0ed0a0d4","hvm":false,"displayText":"Syste= mVM Template (vSphere)","imageDataStore":{"org.apache.cloudstack.storage.to= .PrimaryDataStoreTO":{"uuid":"943e616e-71b5-387d-a23c-b15781d88cc7","id":1,= "poolType":"VMFS","host":"VMFS datastore: /Afranet/SharedStorageCS","path":= "/Afranet/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/= SharedStorageCS//Afranet/SharedStorageCS/?ROLE=3DPrimary&STOREUUID=3D943e61= 6e-71b5-387d-a23c-b15781d88cc7"}},"name":"routing-8","hypervisorType":"VMwa= re"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"= f9bad8a9-faf9-44cf-8dd2-48e89fe37912","volumeType":"ROOT","dataStore":{"org= .apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"943e616e-71b5-38= 7d-a23c-b15781d88cc7","id":1,"poolType":"VMFS","host":"VMFS datastore: /Afr= anet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"VMF= S://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE= =3DPrimary&STOREUUID=3D943e616e-71b5-387d-a23c-b15781d88cc7"}},"name":"ROOT= -55","size":0,"volumeId":55,"vmName":"s-55-VM","accountId":1,"format":"OVA"= ,"id":55,"deviceId":0,"hypervisorType":"VMware"}},"executeInSequence":false= ,"options":{},"wait":0}}] } 2014-07-08 14:44:59,703 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-18:= ctx-95a4dfe7) Seq 2-404685281: Executing request 2014-07-08 14:44:59,899 INFO [c.c.s.r.VmwareStorageProcessor] (DirectAgent= -18:ctx-95a4dfe7 172.16.71.53) creating full clone from template 2014-07-08 14:44:59,900 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-5:ctx= -5951bdf7 172.16.71.53) Prepare ISO volume at new device {"key":-1,"backing= ":{"fileName":"[29152781e45f3c90aa154b753a0d7a79] systemvm/systemvm-4.3.0.i= so","datastore":{"value":"datastore-142","type":"Datastore"}},"connectable"= :{"startConnected":true,"allowGuestControl":false,"connected":true},"contro= llerKey":200,"unitNumber":0} -- This message was sent by Atlassian JIRA (v6.2#6252)