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:58:39 UTC
[jira] [Updated] (CLOUDSTACK-7149) Issues with deployment of
Cloudstack with dvSwitch on vmware vSphere 5.5
[ https://issues.apache.org/jira/browse/CLOUDSTACK-7149?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alireza Eskandari updated CLOUDSTACK-7149:
------------------------------------------
Attachment: logs.txt
> 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
> Labels: 4.3.0, dvSwitch, vmware
> Attachments: logs.txt
>
> Original Estimate: 336h
> Remaining Estimate: 336h
>
> 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)