You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Alireza Eskandari (JIRA)" <ji...@apache.org> on 2014/07/22 06:48:38 UTC
[jira] [Created] (CLOUDSTACK-7149) Issues with deployment of
Cloudstack with dvSwitch on vmware vSphere 5.5
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 default.)
Components: Hypervisor Controller, Install and Setup, Network Controller, 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 configurations, Cloudstack starts to create Zone, Pod, cluster and etc. and everything looks normal but CS could not set any configuration on dvSwitch.
CS begins to create system VMs but after cloning of system VMs completed, CS 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:ctx-86a12e4e 172.16.71.54) Prepare volume at new device {"capacityInKB":0,"key":-2,"backing":{"diskMode":"persistent","fileName":"[SharedStorageCS] s-54-VM/ROOT-54-000001.vmdk","datastore":{"value":"datastore-14","type":"Datastore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":1}
2014-07-08 14:44:39,764 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-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:ctx-86a12e4e 172.16.71.54) Prepare NIC device based on NicTO: {"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"53f70468-065a-484b-b6b5-9148d4ea9b52","mac":"02:00:16:fa:00:36","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"}
2014-07-08 14:44:39,773 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) Prepare network on vmwaresvs null with name prefix: cloud.private
2014-07-08 14:44:39,773 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) Unrecognized broadcast type in VmwareResource, type: 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. Defaulting 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:ctx-86a12e4e 172.16.71.54) Preparing NIC device on network cloud.private.untagged.0.1-vSwitch0
2014-07-08 14:44:39,916 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) Prepare NIC at new device {"operation":"ADD","device":{"addressType":"Manual","macAddress":"02:00:16:fa:00:36","key":-3,"backing":{"network":{"value":"network-23","type":"Network"},"deviceName":"cloud.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":0}}
2014-07-08 14:44:39,917 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) Prepare NIC device based on NicTO: {"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"eaa2b684-0ec0-47c2-be20-f138d0790856","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:ctx-86a12e4e 172.16.71.54) Prepare network on vmwaresvs null with name prefix: 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. Defaulting 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:ctx-86a12e4e 172.16.71.54) Preparing NIC device on network cloud.private.untagged.0.1-vSwitch0
2014-07-08 14:44:40,064 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) Prepare NIC at new device {"operation":"ADD","device":{"addressType":"Manual","macAddress":"06:fc:6e:00:00:02","key":-4,"backing":{"network":{"value":"network-23","type":"Network"},"deviceName":"cloud.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":1}}
2014-07-08 14:44:40,064 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) Prepare NIC device based on NicTO: {"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"43a27cb8-bd3b-4830-8970-790ee6032ec0","ip":"79.175.173.179","netmask":"255.255.255.240","gateway":"79.175.173.177","mac":"06:59:1c:00:00:0c","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"}
2014-07-08 14:44:40,072 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) Prepare network on vmwaredvs dvSwitch with name prefix: cloud.public
2014-07-08 14:44:40,081 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-411:ctx-86a12e4e 172.16.71.54) StartCommand failed due to Exception: java.lang.NumberFormatException
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.prepareNetwork(HypervisorHostHelper.java:504)
at com.cloud.hypervisor.vmware.resource.VmwareResource.prepareNetworkFromNicInfo(VmwareResource.java:3692)
at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2934)
at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:525)
at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.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 false 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-86a12e4e) Seq 1-1967325654: Processing: { Ans: , MgmtId: 345051256068, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":54,"name":"s-54-VM","bootloader":"HVM","type":"SecondaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"hostName":"s-54-VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=secstorage host=172.16.71.52 port=8250 name=s-54-VM zone=1 pod=1 guid=s-54-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=79.175.173.179 eth2mask=255.255.255.240 gateway=79.175.173.177 public.network.device=eth2 eth0mask=0.0.0.0 eth0ip=0.0.0.0 eth1ip=172.16.71.62 eth1mask=255.255.255.0 mgmtcidr=172.16.71.0/24 localgw=172.16.71.1 private.network.device=eth1 eth3ip=172.16.71.58 eth3mask=255.255.255.0 storageip=172.16.71.58 storagenetmask=255.255.255.0 storagegateway=172.16.71.1 internaldns1=172.16.9.9 internaldns2=172.16.9.10 dns1=4.2.2.4 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"10a1fae293cfbaca","params":{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"6063d734-3b96-48f4-9ecd-3b7b7076e2db","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0a5059a6-3a5c-45de-8a66-a3b695397363","volumeType":"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/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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,"networkRateMbps":-1,"defaultNic":true,"uuid":"43a27cb8-bd3b-4830-8970-790ee6032ec0","ip":"79.175.173.179","netmask":"255.255.255.240","gateway":"79.175.173.177","mac":"06:59:1c:00:00:0c","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"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"53f70468-065a-484b-b6b5-9148d4ea9b52","mac":"02:00:16:fa:00:36","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"eaa2b684-0ec0-47c2-be20-f138d0790856","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"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"4b1e74ca-351b-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.lang.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: v1, 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-54-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":{"isProxy":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:ctx-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-6daf13f4 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-6daf13f4 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-6daf13f4 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:ctx-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-6daf13f4) Seq 1-1967325655: Processing: { Ans: , MgmtId: 345051256068, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"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: v1, Flags: 10, { StopAnswer } }
2014-07-08 14:44:40,225 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (secstorage-1:ctx-20017d90) Releasing ip address for reservationId=db11c5a6-efbb-4c7e-9fad-74b47aef5c27, instance=207
2014-07-08 14:44:40,226 DEBUG [c.c.n.g.PodBasedNetworkGuru] (secstorage-1:ctx-20017d90) Released nic: NicProfile[207-54-null-null-null
2014-07-08 14:44:40,243 DEBUG [c.c.n.g.StorageNetworkGuru] (secstorage-1:ctx-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[SecondaryStorageVm|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[SecondaryStorageVm|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=54|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] (secstorage-1:ctx-20017d90) Deploy avoids pods: null, clusters: null, hosts: [1, 2]
2014-07-08 14:44:40,256 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-20017d90) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@10ef1fe1
2014-07-08 14:44:40,256 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-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] (secstorage-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-20017d90) Searching resources only under specified Cluster: 3
2014-07-08 14:44:40,261 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-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 check 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=500Mhz, Ram=512
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] (secstorage-1:ctx-20017d90) No suitable hosts found
2014-07-08 14:44:40,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-20017d90) No suitable hosts found under this Cluster: 3
2014-07-08 14:44:40,270 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-20017d90) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2014-07-08 14:44:40,270 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-20017d90) Searching resources only under specified Cluster: 3
2014-07-08 14:44:40,271 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-20017d90) The specified cluster is in avoid set, returning.
2014-07-08 14:44:40,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-20017d90) Deploy avoids pods: null, clusters: [3], hosts: [1, 2]
2014-07-08 14:44:40,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-20017d90) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@10ef1fe1
2014-07-08 14:44:40,274 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-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] (secstorage-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-20017d90) Searching resources only under specified Pod: 1
2014-07-08 14:44:40,274 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-20017d90) 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-20017d90) 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-20017d90) No clusters found after removing disabled clusters and clusters in avoid 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: OperationFailedvm'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 overprovisioning: 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 overprovisioning: 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 total: 19200, total with overprovisioning: 19200; new used: 0,reserved:0; movedfromreserved: 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,moveToReserveredfalse
2014-07-08 14:44:40,306 WARN [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-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=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:921)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:745)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:261)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:694)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(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.java: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(SystemVmLoadScanner.java:79)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2014-07-08 14:44:40,308 INFO [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-20017d90) Unable to start secondary storage vm for standby capacity, 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: ExpungeOperationvm's original host id: null new host id: null host id before state 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.173.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=205
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=206
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=207
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=208
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 XenServer) 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.53), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0a5059a6-3a5c-45de-8a66-a3b695397363","volumeType":"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/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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.t.Request] (secstorage-1:ctx-20017d90) Seq 2-404685278: Executing: { Cmd , MgmtId: 345051256068, via: 2(172.16.71.53), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0a5059a6-3a5c-45de-8a66-a3b695397363","volumeType":"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/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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-45de-8a66-a3b695397363","volumeType":"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/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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,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-d72101e4) Seq 2-404685278: Processing: { Ans: , MgmtId: 345051256068, via: 2, Ver: 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:ctx-20017d90) Volume 54 is not referred anywhere, remove it from volumes table
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] (secstorage-1:ctx-20017d90) Primary secondary storage is not even started, wait 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-5b91706a 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-5b91706a 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-5b91706a 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:ctx-5b91706a 172.16.71.53) Prepare ISO volume at new device {"key":-1,"backing":{"fileName":"[29152781e45f3c90aa154b753a0d7a79] systemvm/systemvm-4.3.0.iso","datastore":{"value":"datastore-142","type":"Datastore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":0}
2014-07-08 14:44:44,536 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-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 exists 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 [SharedStorageCS]
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 [SharedStorageCS]
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 does 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 exists on datastore
2014-07-08 14:44:44,855 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Prepare volume at new device {"capacityInKB":0,"key":-2,"backing":{"diskMode":"persistent","fileName":"[SharedStorageCS] v-52-VM/ROOT-52-000001.vmdk","datastore":{"value":"datastore-14","type":"Datastore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":1}
2014-07-08 14:44:44,855 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-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:ctx-5b91706a 172.16.71.53) Prepare NIC device based on NicTO: {"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-1b76-48dd-a91d-a7655266b233","mac":"02:00:5d:f9:00:34","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"}
2014-07-08 14:44:44,865 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Prepare network on vmwaresvs null with name prefix: cloud.private
2014-07-08 14:44:44,865 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Unrecognized broadcast type in VmwareResource, type: 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. Defaulting 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:ctx-5b91706a 172.16.71.53) Preparing NIC device on network cloud.private.untagged.0.1-vSwitch0
2014-07-08 14:44:45,006 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Prepare NIC at new device {"operation":"ADD","device":{"addressType":"Manual","macAddress":"02:00:5d:f9:00:34","key":-3,"backing":{"network":{"value":"network-23","type":"Network"},"deviceName":"cloud.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":0}}
2014-07-08 14:44:45,006 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Prepare NIC device based on NicTO: {"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"086e6913-be1f-41de-9b85-f7cd3f75db37","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:ctx-5b91706a 172.16.71.53) Prepare network on vmwaresvs null with name prefix: 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. Defaulting 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:ctx-5b91706a 172.16.71.53) Preparing NIC device on network cloud.private.untagged.0.1-vSwitch0
2014-07-08 14:44:45,101 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Prepare NIC at new device {"operation":"ADD","device":{"addressType":"Manual","macAddress":"06:fa:e0:00:00:03","key":-4,"backing":{"network":{"value":"network-23","type":"Network"},"deviceName":"cloud.private.untagged.0.1-vSwitch0"},"connectable":{"startConnected":true,"allowGuestControl":true,"connected":true},"unitNumber":1}}
2014-07-08 14:44:45,102 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Prepare NIC device based on NicTO: {"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5a7995e","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","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"}
2014-07-08 14:44:45,108 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) Prepare network on vmwaredvs dvSwitch with name prefix: cloud.public
2014-07-08 14:44:45,114 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-412:ctx-5b91706a 172.16.71.53) StartCommand failed due to Exception: java.lang.NumberFormatException
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.prepareNetwork(HypervisorHostHelper.java:504)
at com.cloud.hypervisor.vmware.resource.VmwareResource.prepareNetworkFromNicInfo(VmwareResource.java:3692)
at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2934)
at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:525)
at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.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 false 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-5b91706a) Seq 2-404685277: Processing: { Ans: , MgmtId: 345051256068, via: 2, Ver: 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":" template=domP type=consoleproxy host=172.16.71.52 port=8250 name=v-52-VM zone=1 pod=1 guid=Proxy.52 proxy_vm=52 disable_rp_filter=true eth2ip=79.175.173.178 eth2mask=255.255.255.240 gateway=79.175.173.177 eth0ip=0.0.0.0 eth0mask=0.0.0.0 eth1ip=172.16.71.63 eth1mask=255.255.255.0 mgmtcidr=172.16.71.0/24 localgw=172.16.71.1 internaldns1=172.16.9.9 internaldns2=172.16.9.10 dns1=4.2.2.4 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-ac19-4c3c-a937-638d99af531f","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"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":"VMFS datastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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,"networkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5a7995e","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","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-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.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"}]},"result":false,"details":"StartCommand failed due to Exception: java.lang.NumberFormatException\nMessage: null\n","wait":0}}] }
2014-07-08 14:44:45,120 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-666aea5f) 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] (consoleproxy-1:ctx-666aea5f) Unable to start VM on Host[-2-Routing] due to StartCommand failed due to Exception: java.lang.NumberFormatException
Message: null
2014-07-08 14:44:45,138 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-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-666aea5f) 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-666aea5f) Seq 2-404685279: Executing: { 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.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:ctx-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-80cb6b07 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-80cb6b07 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-80cb6b07 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:ctx-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-80cb6b07) Seq 2-404685279: Processing: { Ans: , MgmtId: 345051256068, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"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-666aea5f) 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] (consoleproxy-1:ctx-666aea5f) Releasing ip address for reservationId=03d3b005-e67f-4420-9a2d-5f4acec31913, instance=200
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] (consoleproxy-1:ctx-666aea5f) Successfully released network resources for the vm VM[ConsoleProxy|v-52-VM]
2014-07-08 14:44:45,255 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-1:ctx-666aea5f) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-52-VM] in Starting state
2014-07-08 14:44:45,259 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-1:ctx-666aea5f) Root volume is ready, need to place VM in volume's cluster
2014-07-08 14:44:45,259 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-1:ctx-666aea5f) Vol[52|vm=52|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] (consoleproxy-1:ctx-666aea5f) Deploy avoids pods: null, clusters: null, hosts: [1, 2]
2014-07-08 14:44:45,264 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-666aea5f) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@10ef1fe1
2014-07-08 14:44:45,264 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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] (consoleproxy-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-666aea5f) Searching resources only under specified Cluster: 3
2014-07-08 14:44:45,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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 after 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=500Mhz, Ram=1024
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 suitable hosts
2014-07-08 14:44:45,284 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-666aea5f) No suitable hosts found
2014-07-08 14:44:45,284 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-666aea5f) No suitable hosts found under this Cluster: 3
2014-07-08 14:44:45,287 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-666aea5f) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2014-07-08 14:44:45,287 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-666aea5f) Searching resources only under specified Cluster: 3
2014-07-08 14:44:45,289 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-666aea5f) The specified cluster is in avoid set, returning.
2014-07-08 14:44:45,292 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-666aea5f) Deploy avoids pods: null, clusters: [3], hosts: [1, 2]
2014-07-08 14:44:45,293 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-666aea5f) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@10ef1fe1
2014-07-08 14:44:45,294 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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] (consoleproxy-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-666aea5f) Searching resources only under specified Pod: 1
2014-07-08 14:44:45,294 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-666aea5f) 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:45,299 DEBUG [c.c.d.FirstFitPlanner] (consoleproxy-1:ctx-666aea5f) 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-666aea5f) 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:ctx-666aea5f) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2014-07-08 14:44:45,325 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-666aea5f) Hosts's actual total CPU: 19200 and CPU after applying overprovisioning: 19200
2014-07-08 14:44:45,325 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-666aea5f) Hosts's actual total RAM: 8579170304 and RAM after applying overprovisioning: 8579170304
2014-07-08 14:44:45,326 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-666aea5f) release cpu from host: 2, old used: 500,reserved: 0, actual total: 19200, total with overprovisioning: 19200; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-07-08 14:44:45,326 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-666aea5f) release mem from host: 2, old used: 1073741824,reserved: 0, total: 8579170304; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
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=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:921)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:745)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:555)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:941)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1666)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:157)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java: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(SystemVmLoadScanner.java:79)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.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 management 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 management 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:ctx-7cd4e7a9) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2014-07-08 14:44:58,942 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) Successfully transitioned to start state for VM[ConsoleProxy|v-52-VM] reservation id = 7df07366-ddbd-4667-84d7-a80ac80b4ea2
2014-07-08 14:44:58,958 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-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] (consoleproxy-1:ctx-7cd4e7a9) Deploy avoids pods: null, clusters: null, hosts: null
2014-07-08 14:44:58,962 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) Root volume is ready, need to place VM in volume's cluster
2014-07-08 14:44:58,962 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) Vol[52|vm=52|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] (consoleproxy-1:ctx-7cd4e7a9) Deploy avoids pods: null, clusters: null, hosts: null
2014-07-08 14:44:58,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@10ef1fe1
2014-07-08 14:44:58,965 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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] (consoleproxy-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-7cd4e7a9) Searching resources only under specified Cluster: 3
2014-07-08 14:44:58,972 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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 after 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=500Mhz, Ram=1024
2014-07-08 14:44:58,984 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Host: 2 has cpu capability (cpu:8, speed:2400) to support requested CPU: 1 and requested speed: 500
2014-07-08 14:44:58,984 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Hosts's actual total CPU: 19200 and CPU after applying overprovisioning: 19200
2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Free CPU: 19200 , Requested CPU: 500
2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Free RAM: 8579170304 , Requested RAM: 1073741824
2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-07-08 14:44:58,987 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 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:ctx-7cd4e7a9 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used: 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:ctx-7cd4e7a9 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:8, speed:2400) to support requested CPU: 1 and requested speed: 500
2014-07-08 14:44:58,993 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Hosts's actual total CPU: 19200 and CPU after applying overprovisioning: 19200
2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Free CPU: 19200 , Requested CPU: 500
2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Free RAM: 8579170304 , Requested RAM: 1073741824
2014-07-08 14:44:58,995 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-07-08 14:44:58,996 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 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?: true
2014-07-08 14:44:58,996 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 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 suitable hosts
2014-07-08 14:44:58,997 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) Checking suitable pools for volume (Id, Type): (52,ROOT)
2014-07-08 14:44:58,997 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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] (consoleproxy-1:ctx-7cd4e7a9) Planner need not allocate a pool for this volume since its READY
2014-07-08 14:44:58,999 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-07-08 14:44:58,999 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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] (consoleproxy-1:ctx-7cd4e7a9) Host: 2 can access pool: 1
2014-07-08 14:44:59,001 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (consoleproxy-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] (consoleproxy-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] (consoleproxy-1:ctx-7cd4e7a9) Deployment found - P0=VM[ConsoleProxy|v-52-VM], P0=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:ctx-7cd4e7a9) VM state transitted from :Starting to Starting with event: OperationRetryvm'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:ctx-7cd4e7a9) Hosts's actual total CPU: 19200 and CPU after applying overprovisioning: 19200
2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) We are allocating VM, increasing the used capacity of this host:2
2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-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:ctx-7cd4e7a9) Current Used RAM: 0 , Free RAM:8579170304 ,Requested RAM: 1073741824
2014-07-08 14:44:59,032 DEBUG [c.c.c.CapacityManagerImpl] (consoleproxy-1:ctx-7cd4e7a9) CPU STATS after allocation: for host: 2, old used: 0, old reserved: 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:ctx-7cd4e7a9) RAM STATS after allocation: for host: 2, old used: 0, old reserved: 0, total: 8579170304; new used: 1073741824, reserved: 0; requested mem: 1073741824,alloc_from_last:false
2014-07-08 14:44:59,038 DEBUG [c.c.v.VirtualMachineManagerImpl] (consoleproxy-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=200 is already implemented
2014-07-08 14:44:59,061 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:ctx-7cd4e7a9) Network id=202 is already implemented
2014-07-08 14:44:59,081 DEBUG [o.a.c.e.o.NetworkOrchestrator] (consoleproxy-1:ctx-7cd4e7a9) Network id=201 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-a80ac80b4ea2-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[ConsoleProxy|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=52|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=domP type=consoleproxy host=172.16.71.52 port=8250 name=v-52-VM zone=1 pod=1 guid=Proxy.52 proxy_vm=52 disable_rp_filter=true eth2ip=79.175.173.178 eth2mask=255.255.255.240 gateway=79.175.173.177 eth0ip=0.0.0.0 eth0mask=0.0.0.0 eth1ip=172.16.71.61 eth1mask=255.255.255.0 mgmtcidr=172.16.71.0/24 localgw=172.16.71.1 internaldns1=172.16.9.9 internaldns2=172.16.9.10 dns1=4.2.2.4 dns2=8.8.8.8
2014-07-08 14:44:59,161 DEBUG [c.c.h.g.VMwareGuru] (consoleproxy-1:ctx-7cd4e7a9) Nested virtualization requested, adding flag to vm configuration
2014-07-08 14:44:59,181 DEBUG [c.c.a.t.Request] (consoleproxy-1:ctx-7cd4e7a9) 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,"hostName":"v-52-VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=172.16.71.52 port=8250 name=v-52-VM zone=1 pod=1 guid=Proxy.52 proxy_vm=52 disable_rp_filter=true eth2ip=79.175.173.178 eth2mask=255.255.255.240 gateway=79.175.173.177 eth0ip=0.0.0.0 eth0mask=0.0.0.0 eth1ip=172.16.71.61 eth1mask=255.255.255.0 mgmtcidr=172.16.71.0/24 localgw=172.16.71.1 internaldns1=172.16.9.9 internaldns2=172.16.9.10 dns1=4.2.2.4 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-ac19-4c3c-a937-638d99af531f","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"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":"VMFS datastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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,"networkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5a7995e","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","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-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.255.255.0","gateway":"172.16.71.1","mac":"06:65:a4:00:00:01","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"vSwitch0,,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-7cd4e7a9) 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,"hostName":"v-52-VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","bootArgs":" template=domP type=consoleproxy host=172.16.71.52 port=8250 name=v-52-VM zone=1 pod=1 guid=Proxy.52 proxy_vm=52 disable_rp_filter=true eth2ip=79.175.173.178 eth2mask=255.255.255.240 gateway=79.175.173.177 eth0ip=0.0.0.0 eth0mask=0.0.0.0 eth1ip=172.16.71.61 eth1mask=255.255.255.0 mgmtcidr=172.16.71.0/24 localgw=172.16.71.1 internaldns1=172.16.9.9 internaldns2=172.16.9.10 dns1=4.2.2.4 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-ac19-4c3c-a937-638d99af531f","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"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":"VMFS datastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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,"networkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5a7995e","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","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-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.255.255.0","gateway":"172.16.71.1","mac":"06:65:a4:00:00:01","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"vSwitch0,,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,183 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5:ctx-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,"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":" template=domP type=consoleproxy host=172.16.71.52 port=8250 name=v-52-VM zone=1 pod=1 guid=Proxy.52 proxy_vm=52 disable_rp_filter=true eth2ip=79.175.173.178 eth2mask=255.255.255.240 gateway=79.175.173.177 eth0ip=0.0.0.0 eth0mask=0.0.0.0 eth1ip=172.16.71.61 eth1mask=255.255.255.0 mgmtcidr=172.16.71.0/24 localgw=172.16.71.1 internaldns1=172.16.9.9 internaldns2=172.16.9.10 dns1=4.2.2.4 dns2=8.8.8.8","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"5741e6ccbd694f50","params":{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"f6eb5970-ac19-4c3c-a937-638d99af531f","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"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":"VMFS datastore: /Afranet/SharedStorageCS","path":"/Afranet/SharedStorageCS","port":0,"url":"VMFS://VMFS datastore: /Afranet/SharedStorageCS//Afranet/SharedStorageCS/?ROLE=Primary&STOREUUID=943e616e-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,"networkRateMbps":-1,"defaultNic":true,"uuid":"a681df16-ee1d-4f9b-95d3-0fc7d5a7995e","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","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://1162","isolationUri":"vlan://1162","isSecurityGroupEnabled":false,"name":"dvSwitch,1162,vmwaredvs"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"be2190e5-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.255.255.0","gateway":"172.16.71.1","mac":"06:65:a4:00:00:01","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"vSwitch0,,vmwaresvs"}]},"hostIp":"172.16.71.53","executeInSequence":false,"wait":0}
2014-07-08 14:44:59,255 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-5a0f1049) Zone 1 is ready to launch secondary storage VM
2014-07-08 14:44:59,261 INFO [c.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-5a0f1049) No running secondary storage vms found in datacenter id=1, starting one
2014-07-08 14:44:59,266 INFO [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-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] (secstorage-1:ctx-5a0f1049) Assign secondary storage vm from a newly started instance for request from data center : 1
2014-07-08 14:44:59,274 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-5:ctx-5951bdf7 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-5951bdf7 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-5951bdf7 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 Offering [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 Offering [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 Offering [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 reconfiguration
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 Offering [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 network 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 network 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 network 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 network 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] (secstorage-1:ctx-5a0f1049) received secondary storage vm alert
2014-07-08 14:44:59,392 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-5a0f1049) New secondary storage vm created, zone: Afranet, secStorageVm: 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: StartRequestedvm'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[SecondaryStorageVm|s-55-VM] reservation id = 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] (secstorage-1:ctx-5a0f1049) Deploy avoids pods: null, clusters: null, hosts: null
2014-07-08 14:44:59,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-5a0f1049) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@10ef1fe1
2014-07-08 14:44:59,426 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-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] (secstorage-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-5a0f1049) Searching all possible resources under this Zone: 1
2014-07-08 14:44:59,428 DEBUG [c.c.d.FirstFitPlanner] (secstorage-1:ctx-5a0f1049) 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] (secstorage-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 check 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=500Mhz, Ram=512
2014-07-08 14:44:59,456 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx-5a0f1049 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:8, speed: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 , cpuOverprovisioningFactor: 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: 536870912
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?: true
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_last_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 list: 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, speed: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 , cpuOverprovisioningFactor: 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: 536870912
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,alloc_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 list: 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] (secstorage-1:ctx-5a0f1049) Checking suitable pools for volume (Id, Type): (55,ROOT)
2014-07-08 14:44:59,471 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-5a0f1049) We need to allocate new storagepool for this volume
2014-07-08 14:44:59,471 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-5a0f1049) Calling StoragePoolAllocators to find suitable pools
2014-07-08 14:44:59,472 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (secstorage-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 storage 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] (secstorage-1:ctx-5a0f1049) Checking if storage pool is suitable, name: null ,poolId: 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=55|ROOT]], maxSize : 1073204953088, totalAllocatedSize : 0, askingSize : 0, allocated disable threshold: 0.85
2014-07-08 14:44:59,486 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (secstorage-1:ctx-5a0f1049) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-07-08 14:44:59,487 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-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] (secstorage-1:ctx-5a0f1049) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2014-07-08 14:44:59,488 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-5a0f1049) Host: 1 can access pool: 1
2014-07-08 14:44:59,488 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-5a0f1049) Found a potential host id: 1 name: 172.16.71.54 and associated storage pools for this VM
2014-07-08 14:44:59,489 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (secstorage-1:ctx-5a0f1049) 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(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=VM[SecondaryStorageVm|s-55-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(3)-Host(1)-Storage(Volume(55|ROOT-->Pool(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: OperationRetryvm's original host id: null new host id: 1 host id before state transition: 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 overprovisioning: 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: 536870912
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 reserved: 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,516 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx-5a0f1049) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 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=200 is already implemented
2014-07-08 14:44:59,553 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-5a0f1049) Network id=202 is already implemented
2014-07-08 14:44:59,578 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-5a0f1049) Network id=201 is already implemented
2014-07-08 14:44:59,603 DEBUG [c.c.n.g.PodBasedNetworkGuru] (secstorage-1:ctx-5a0f1049) Allocated a nic NicProfile[211-55-7758870a-f8f9-4b35-88ef-4f8fda9eee85-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=203 is already implemented
2014-07-08 14:44:59,641 DEBUG [c.c.n.g.StorageNetworkGuru] (secstorage-1:ctx-5a0f1049) Allocated a storage nic NicProfile[212-55-7758870a-f8f9-4b35-88ef-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[SecondaryStorageVm|s-55-VM]
2014-07-08 14:44:59,662 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (secstorage-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] (secstorage-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] (secstorage-1:ctx-5a0f1049) copyAsync inspecting src type TEMPLATE copyAsync inspecting 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.53), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"dc1cf88af85a3c5192ae5e1db3c025a5","origUrl":"http://download.cloud.com/templates/4.3/systemvm64template-2014-01-14-master-vmware.ova","uuid":"ba6d71fa-059e-11e4-b96b-005056a85504","id":8,"format":"OVA","accountId":1,"checksum":"ef593a061f3b7594ab0bfd9b0ed0a0d4","hvm":false,"displayText":"SystemVM 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=Primary&STOREUUID=943e616e-71b5-387d-a23c-b15781d88cc7"}},"name":"routing-8","hypervisorType":"VMware"}},"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-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=Primary&STOREUUID=943e616e-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.t.Request] (secstorage-1:ctx-5a0f1049) Seq 2-404685281: Executing: { Cmd , MgmtId: 345051256068, via: 2(172.16.71.53), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"dc1cf88af85a3c5192ae5e1db3c025a5","origUrl":"http://download.cloud.com/templates/4.3/systemvm64template-2014-01-14-master-vmware.ova","uuid":"ba6d71fa-059e-11e4-b96b-005056a85504","id":8,"format":"OVA","accountId":1,"checksum":"ef593a061f3b7594ab0bfd9b0ed0a0d4","hvm":false,"displayText":"SystemVM 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=Primary&STOREUUID=943e616e-71b5-387d-a23c-b15781d88cc7"}},"name":"routing-8","hypervisorType":"VMware"}},"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-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=Primary&STOREUUID=943e616e-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.iso","datastore":{"value":"datastore-142","type":"Datastore"}},"connectable":{"startConnected":true,"allowGuestControl":false,"connected":true},"controllerKey":200,"unitNumber":0}
--
This message was sent by Atlassian JIRA
(v6.2#6252)