[
https://issues.apache.org/jira/browse/CLOUDSTACK-2322?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Chip Childers updated CLOUDSTACK-2322:
--------------------------------------
Priority: Critical (was: Major)
> 2.2.14 to 4.1.0 upgrade: unable to add a new VM
> ------------------------------------------------
>
> Key: CLOUDSTACK-2322
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2322
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: KVM
> Affects Versions: 4.1.0
> Environment: CentOS 6.4
> Reporter: Shashi Dahal
> Priority: Critical
> Fix For: 4.1.0
>
>
> Hi,
> After upgrade from 2.2.14 to 4.1.0 , i tried to add a new VM, which fails.
> Logs attached.
> 2013-05-03 12:41:37,400 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
> ===START=== 10.0.28.16 -- GET
> command=listVirtualMachines&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&listAll=true&page=1&pagesize=20&_=1367577697419
> 2013-05-03 12:41:37,440 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
> ===END=== 10.0.28.16 -- GET
> command=listVirtualMachines&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&listAll=true&page=1&pagesize=20&_=1367577697419
> 2013-05-03 12:41:39,363 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null)
> ===START=== 10.0.28.16 -- GET
> command=listZones&available=true&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577699385
> 2013-05-03 12:41:39,384 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet
> 2013-05-03 12:41:39,390 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null)
> ===END=== 10.0.28.16 -- GET
> command=listZones&available=true&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577699385
> 2013-05-03 12:41:40,175 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2013-05-03 12:41:40,177 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-03 12:41:40,193 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2013-05-03 12:41:40,196 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-03 12:41:40,774 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
> ===START=== 10.0.28.16 -- GET
> command=listHypervisors&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700796
> 2013-05-03 12:41:40,791 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
> ===END=== 10.0.28.16 -- GET
> command=listHypervisors&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700796
> 2013-05-03 12:41:40,801 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null)
> ===START=== 10.0.28.16 -- GET
> command=listTemplates&templatefilter=featured&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700822
> 2013-05-03 12:41:40,878 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null)
> ===END=== 10.0.28.16 -- GET
> command=listTemplates&templatefilter=featured&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700822
> 2013-05-03 12:41:40,886 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null)
> ===START=== 10.0.28.16 -- GET
> command=listTemplates&templatefilter=community&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700909
> 2013-05-03 12:41:40,912 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null)
> ===END=== 10.0.28.16 -- GET
> command=listTemplates&templatefilter=community&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700909
> 2013-05-03 12:41:40,921 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
> ===START=== 10.0.28.16 -- GET
> command=listTemplates&templatefilter=selfexecutable&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700943
> 2013-05-03 12:41:40,975 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-3:null) StorageCollector is running...
> 2013-05-03 12:41:41,002 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
> ===END=== 10.0.28.16 -- GET
> command=listTemplates&templatefilter=selfexecutable&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577700943
> 2013-05-03 12:41:41,033 DEBUG [agent.transport.Request]
> (StatsCollector-3:null) Seq 6-685442215: Received: { Ans: , MgmtId:
> 90520747364525, via: 6, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-05-03 12:41:41,140 DEBUG [agent.transport.Request]
> (StatsCollector-3:null) Seq 2-1920335887: Received: { Ans: , MgmtId:
> 90520747364525, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-05-03 12:41:42,116 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
> ===START=== 10.0.28.16 -- GET
> command=listServiceOfferings&issystem=false&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577702138
> 2013-05-03 12:41:42,128 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
> ===END=== 10.0.28.16 -- GET
> command=listServiceOfferings&issystem=false&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577702138
> 2013-05-03 12:41:43,234 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
> ===START=== 10.0.28.16 -- GET
> command=listDiskOfferings&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577703256
> 2013-05-03 12:41:43,253 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
> ===END=== 10.0.28.16 -- GET
> command=listDiskOfferings&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577703256
> 2013-05-03 12:41:44,447 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
> ===START=== 10.0.28.16 -- GET
> command=listVPCs&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577704469
> 2013-05-03 12:41:44,461 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
> ===END=== 10.0.28.16 -- GET
> command=listVPCs&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577704469
> 2013-05-03 12:41:44,470 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
> ===START=== 10.0.28.16 -- GET
> command=listNetworks&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&zoneId=54fcb292-09d8-4aad-b0e2-0dacd59408d0&canusefordeploy=true&type=Shared&domainid=1&account=admin&_=1367577704492
> 2013-05-03 12:41:44,483 DEBUG [cloud.user.AccountManagerImpl]
> (catalina-exec-17:null) Access granted to Acct[2-admin] to Domain:1/ by
> DomainChecker_EnhancerByCloudStack_a8431b6f
> 2013-05-03 12:41:44,519 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
> ===END=== 10.0.28.16 -- GET
> command=listNetworks&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&zoneId=54fcb292-09d8-4aad-b0e2-0dacd59408d0&canusefordeploy=true&type=Shared&domainid=1&account=admin&_=1367577704492
> 2013-05-03 12:41:44,530 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null)
> ===START=== 10.0.28.16 -- GET
> command=listNetworkOfferings&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&forvpc=false&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&guestiptype=Isolated&supportedServices=SourceNat&specifyvlan=false&state=Enabled&_=1367577704551
> 2013-05-03 12:41:44,566 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null)
> ===END=== 10.0.28.16 -- GET
> command=listNetworkOfferings&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&forvpc=false&zoneid=54fcb292-09d8-4aad-b0e2-0dacd59408d0&guestiptype=Isolated&supportedServices=SourceNat&specifyvlan=false&state=Enabled&_=1367577704551
> 2013-05-03 12:41:46,386 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
> ===START=== 10.0.28.16 -- GET
> command=listSecurityGroups&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&domainid=1&account=admin&_=1367577706407
> 2013-05-03 12:41:46,400 DEBUG [cloud.user.AccountManagerImpl]
> (catalina-exec-18:null) Access granted to Acct[2-admin] to Domain:1/ by
> DomainChecker_EnhancerByCloudStack_a8431b6f
> 2013-05-03 12:41:46,413 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
> ===END=== 10.0.28.16 -- GET
> command=listSecurityGroups&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&domainid=1&account=admin&_=1367577706407
> 2013-05-03 12:41:54,529 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null)
> ===START=== 10.0.28.16 -- GET
> command=deployVirtualMachine&zoneId=54fcb292-09d8-4aad-b0e2-0dacd59408d0&templateId=202&hypervisor=KVM&serviceOfferingId=2&securitygroupids=1&networkIds=203&displayname=MY-VM&name=MY-VM&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577714552
> 2013-05-03 12:41:54,540 DEBUG [cloud.api.ApiDispatcher]
> (catalina-exec-11:null) InfrastructureEntity name
> is:com.cloud.offering.ServiceOffering
> 2013-05-03 12:41:54,541 DEBUG [cloud.api.ApiDispatcher]
> (catalina-exec-11:null) ControlledEntity name
> is:com.cloud.template.VirtualMachineTemplate
> 2013-05-03 12:41:54,544 DEBUG [cloud.api.ApiDispatcher]
> (catalina-exec-11:null) ControlledEntity name is:com.cloud.network.Network
> 2013-05-03 12:41:54,548 DEBUG [cloud.api.ApiDispatcher]
> (catalina-exec-11:null) ControlledEntity name
> is:com.cloud.network.security.SecurityGroup
> 2013-05-03 12:41:54,607 DEBUG [cloud.vm.UserVmManagerImpl]
> (catalina-exec-11:null) Allocating in the DB for vm
> 2013-05-03 12:41:54,623 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-11:null) Allocating entries for VM: VM[User|MY-VM]
> 2013-05-03 12:41:54,624 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-11:null) Allocating nics for VM[User|MY-VM]
> 2013-05-03 12:41:54,625 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-11:null) Allocating nic for vm VM[User|MY-VM] in network
> Ntwk[203|Guest|5] with requested profile NicProfile[0-0-null-null-null
> 2013-05-03 12:41:54,637 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-11:null) Allocaing disks for VM[User|MY-VM]
> 2013-05-03 12:41:54,649 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-11:null) Allocation completed for VM: VM[User|MY-VM]
> 2013-05-03 12:41:54,649 DEBUG [cloud.vm.UserVmManagerImpl]
> (catalina-exec-11:null) Successfully allocated DB entry for VM[User|MY-VM]
> 2013-05-03 12:41:54,776 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-11:null) submit async job-33, details: AsyncJobVO {id:33,
> userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
> instanceId: 17, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd,
> cmdOriginator: null, cmdInfo:
> {"sessionkey":"eXFmgvJpWd7KmHo0+K++aLMM3DI\u003d","ctxUserId":"2","serviceOfferingId":"2","securitygroupids":"1","zoneId":"54fcb292-09d8-4aad-b0e2-0dacd59408d0","templateId":"202","response":"json","id":"17","networkIds":"203","hypervisor":"KVM","name":"MY-VM","_":"1367577714552","ctxAccountId":"2","ctxStartEventId":"228","displayname":"MY-VM"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 90520747364525,
> completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-05-03 12:41:54,778 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-24:job-33) Executing
> org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-33
> 2013-05-03 12:41:54,780 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null)
> ===END=== 10.0.28.16 -- GET
> command=deployVirtualMachine&zoneId=54fcb292-09d8-4aad-b0e2-0dacd59408d0&templateId=202&hypervisor=KVM&serviceOfferingId=2&securitygroupids=1&networkIds=203&displayname=MY-VM&name=MY-VM&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577714552
> 2013-05-03 12:41:54,783 DEBUG [cloud.api.ApiDispatcher]
> (Job-Executor-24:job-33) InfrastructureEntity name
> is:com.cloud.offering.ServiceOffering
> 2013-05-03 12:41:54,784 DEBUG [cloud.api.ApiDispatcher]
> (Job-Executor-24:job-33) ControlledEntity name
> is:com.cloud.template.VirtualMachineTemplate
> 2013-05-03 12:41:54,785 DEBUG [cloud.api.ApiDispatcher]
> (Job-Executor-24:job-33) ControlledEntity name is:com.cloud.network.Network
> 2013-05-03 12:41:54,788 DEBUG [cloud.api.ApiDispatcher]
> (Job-Executor-24:job-33) ControlledEntity name
> is:com.cloud.network.security.SecurityGroup
> 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) DeploymentPlanner allocation algorithm:
> userconcentratedpod_random
> 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Trying to allocate a host and storage pools from
> dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
> 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Is ROOT volume READY (pool already allocated)?: No
> 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Searching all possible resources under this Zone: 1
> 2013-05-03 12:41:54,865 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Listing clusters in order of aggregate capacity,
> that have (atleast one host with) enough CPU and RAM capacity under this
> Zone: 1
> 2013-05-03 12:41:54,867 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) CPUOverprovisioningFactor considered: 10.0
> 2013-05-03 12:41:54,877 DEBUG [cloud.deploy.UserConcentratedPodPlanner]
> (Job-Executor-24:job-33) Applying UserConcentratedPod heuristic for account: 2
> 2013-05-03 12:41:54,879 DEBUG [cloud.deploy.UserConcentratedPodPlanner]
> (Job-Executor-24:job-33) Reordering cluster list as per pods ordered by user
> concentration
> 2013-05-03 12:41:54,892 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Checking resources in Cluster: 1 under Pod: 1
> 2013-05-03 12:41:54,894 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Looking for hosts in dc: 1
> pod:1 cluster:1
> 2013-05-03 12:41:54,897 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) FirstFitAllocator has 2
> hosts to check for allocation: [Host[-5-Routing], Host[-2-Routing]]
> 2013-05-03 12:41:54,904 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Found 2 hosts for
> allocation after prioritization: [Host[-5-Routing], Host[-2-Routing]]
> 2013-05-03 12:41:54,904 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Looking for speed=1000Mhz,
> Ram=1024
> 2013-05-03 12:41:54,908 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Checking if host: 5 has
> enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
> 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Hosts's actual total CPU:
> 20216 and CPU after applying overprovisioning: 20216
> 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Free CPU: 15716 , Requested
> CPU: 1000
> 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Free RAM: 13760352256 ,
> Requested RAM: 1073741824
> 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Host has enough CPU and RAM
> available
> 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc CPU from
> host: 5, used: 4500, reserved: 0, actual total: 20216, total with
> overprovisioning: 20216; requested cpu:1000,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
> 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc MEM from
> host: 5, used: 2952790016, reserved: 0, total: 16713142272; requested mem:
> 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-05-03 12:41:54,913 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 5
> 2013-05-03 12:41:54,916 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Checking if host: 2 has
> enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
> 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Hosts's actual total CPU:
> 20216 and CPU after applying overprovisioning: 20216
> 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Free CPU: 19216 , Requested
> CPU: 1000
> 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Free RAM: 15505182720 ,
> Requested RAM: 1073741824
> 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Host has enough CPU and RAM
> available
> 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc CPU from
> host: 2, used: 1000, reserved: 0, actual total: 20216, total with
> overprovisioning: 20216; requested cpu:1000,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
> 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc MEM from
> host: 2, used: 1207959552, reserved: 0, total: 16713142272; requested mem:
> 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-05-03 12:41:54,921 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 2
> 2013-05-03 12:41:54,921 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-24:job-33 FirstFitRoutingAllocator) Host Allocator returning 2
> suitable hosts
> 2013-05-03 12:41:54,924 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Checking suitable pools for volume (Id, Type):
> (20,ROOT)
> 2013-05-03 12:41:54,924 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) We need to allocate new storagepool for this volume
> 2013-05-03 12:41:54,926 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Calling StoragePoolAllocators to find suitable pools
> 2013-05-03 12:41:54,928 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-24:job-33)
> Looking for pools in dc: 1 pod:1 cluster:1
> 2013-05-03 12:41:54,930 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-24:job-33)
> FirstFitStoragePoolAllocator has 1 pools to check for allocation
> 2013-05-03 12:41:54,930 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-24:job-33)
> Checking if storage pool is suitable, name: PRIMARY ,poolId: 200
> 2013-05-03 12:41:54,930 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-24:job-33) Is
> localStorageAllocationNeeded? false
> 2013-05-03 12:41:54,931 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-24:job-33) Is
> storage pool shared? true
> 2013-05-03 12:41:54,935 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-24:job-33) Checking pool 200 for storage, totalSize:
> 7999230836736, usedBytes: 452555964416, usedPct: 0.056574934972205476,
> disable threshold: 0.85
> 2013-05-03 12:41:54,944 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-24:job-33) Checking pool: 200 for volume allocation
> [Vol[20|vm=17|ROOT]], maxSize : 15998461673472, totalAllocatedSize :
> 266014556160, askingSize : 42949672960, allocated disable threshold: 0.85
> 2013-05-03 12:41:54,945 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-24:job-33)
> FirstFitStoragePoolAllocator returning 1 suitable storage pools
> 2013-05-03 12:41:54,945 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Trying to find a potenial host and associated
> storage pools from the suitable host/pool lists for this VM
> 2013-05-03 12:41:54,945 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Checking if host: 5 can access any suitable storage
> pool for volume: ROOT
> 2013-05-03 12:41:54,947 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Host: 5 can access pool: 200
> 2013-05-03 12:41:54,947 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Found a potential host id: 5 name: cs-kvm014 and
> associated storage pools for this VM
> 2013-05-03 12:41:54,950 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))]
> 2013-05-03 12:41:54,985 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) 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
> 2013-05-03 12:41:54,985 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Successfully transitioned to start state for
> VM[User|MY-VM] reservation id = 32088e11-31ca-49f2-a4f4-ccaed76ad0a8
> 2013-05-03 12:41:55,000 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Trying to deploy VM, vm has dcId: 1 and podId: null
> 2013-05-03 12:41:55,000 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) advanceStart: DeploymentPlan is provided, using
> dcId:1, podId: 1, clusterId: 1, hostId: 5, poolId: null
> 2013-05-03 12:41:55,000 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Deploy avoids pods: null, clusters: null, hosts: null
> 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) DeploymentPlanner allocation algorithm:
> userconcentratedpod_random
> 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Trying to allocate a host and storage pools from
> dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
> 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Is ROOT volume READY (pool already allocated)?: No
> 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) DeploymentPlan has host_id specified, making no
> checks on this host, looks like admin test: 5
> 2013-05-03 12:41:55,006 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Looking for suitable pools for this host under zone:
> 1, pod: 1, cluster: 1
> 2013-05-03 12:41:55,009 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Checking suitable pools for volume (Id, Type):
> (20,ROOT)
> 2013-05-03 12:41:55,009 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) We need to allocate new storagepool for this volume
> 2013-05-03 12:41:55,009 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Calling StoragePoolAllocators to find suitable pools
> 2013-05-03 12:41:55,009 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-24:job-33)
> Looking for pools in dc: 1 pod:1 cluster:1
> 2013-05-03 12:41:55,011 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-24:job-33)
> FirstFitStoragePoolAllocator has 1 pools to check for allocation
> 2013-05-03 12:41:55,012 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-24:job-33)
> Checking if storage pool is suitable, name: PRIMARY ,poolId: 200
> 2013-05-03 12:41:55,012 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-24:job-33) Is
> localStorageAllocationNeeded? false
> 2013-05-03 12:41:55,012 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-24:job-33) Is
> storage pool shared? true
> 2013-05-03 12:41:55,016 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-24:job-33) Checking pool 200 for storage, totalSize:
> 7999230836736, usedBytes: 452555964416, usedPct: 0.056574934972205476,
> disable threshold: 0.85
> 2013-05-03 12:41:55,027 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-24:job-33) Checking pool: 200 for volume allocation
> [Vol[20|vm=17|ROOT]], maxSize : 15998461673472, totalAllocatedSize :
> 266014556160, askingSize : 42949672960, allocated disable threshold: 0.85
> 2013-05-03 12:41:55,027 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-24:job-33)
> FirstFitStoragePoolAllocator returning 1 suitable storage pools
> 2013-05-03 12:41:55,027 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Trying to find a potenial host and associated
> storage pools from the suitable host/pool lists for this VM
> 2013-05-03 12:41:55,027 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Checking if host: 5 can access any suitable storage
> pool for volume: ROOT
> 2013-05-03 12:41:55,029 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Host: 5 can access pool: 200
> 2013-05-03 12:41:55,029 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Found a potential host id: 5 name: cs-kvm014 and
> associated storage pools for this VM
> 2013-05-03 12:41:55,031 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))]
> 2013-05-03 12:41:55,031 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Deployment found - P0=VM[User|MY-VM],
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))]
> 2013-05-03 12:41:55,054 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) VM state transitted from :Starting to Starting with
> event: OperationRetryvm's original host id: null new host id: 5 host id
> before state transition: null
> 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) Hosts's actual total CPU: 20216 and CPU after
> applying overprovisioning: 202160
> 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) We are allocating VM, increasing the used capacity
> of this host:5
> 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) Current Used CPU: 4500 , Free CPU:197660 ,Requested
> CPU: 1000
> 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) Current Used RAM: 2952790016 , Free RAM:13760352256
> ,Requested RAM: 1073741824
> 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) CPU STATS after allocation: for host: 5, old used:
> 4500, old reserved: 0, actual total: 20216, total with overprovisioning:
> 202160; new used:5500, reserved:0; requested cpu:1000,alloc_from_last:false
> 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) RAM STATS after allocation: for host: 5, old used:
> 2952790016, old reserved: 0, total: 16713142272; new used: 4026531840,
> reserved: 0; requested mem: 1073741824,alloc_from_last:false
> 2013-05-03 12:41:55,081 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) VM is being created in podId: 1
> 2013-05-03 12:41:55,086 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-24:job-33) Lock is acquired for network id 203 as a part of
> network implement
> 2013-05-03 12:41:55,086 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-24:job-33) Network id=203 is already implemented
> 2013-05-03 12:41:55,087 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-24:job-33) Lock is released for network id 203 as a part of
> network implement
> 2013-05-03 12:41:55,113 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-24:job-33) Changing active number of nics for network id=203 on
> 1
> 2013-05-03 12:41:55,126 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-24:job-33) Asking VirtualRouter to prepare for
> Nic[22-17-null-null]
> 2013-05-03 12:41:55,144 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-24:job-33)
> Lock is acquired for network id 203 as a part of router startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))]
> 2013-05-03 12:41:55,150 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-24:job-33)
> Lock is released for network id 203 as a part of router startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))]
> 2013-05-03 12:41:55,175 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-24:job-33)
> Applying dhcp entry in network Ntwk[203|Guest|5]
> 2013-05-03 12:41:55,204 DEBUG [agent.transport.Request]
> (Job-Executor-24:job-33) Seq 2-1920335888: Sending { Cmd , MgmtId:
> 90520747364525, via: 2, Ver: v1, Flags: 100111,
> [{"routing.DhcpEntryCommand":{"vmName":"MY-VM","defaultDns":"10.11.110.229","duid":"00:03:00:01:null","isDefault":true,"accessDetails":{"router.guest.ip":"10.11.110.229","zone.network.type":"Advanced","router.name":"r-4-VM","router.ip":"169.254.0.207"},"wait":0}}]
> }
> 2013-05-03 12:41:55,212 DEBUG [agent.transport.Request]
> (AgentManager-Handler-2:null) Seq 2-1920335888: Processing: { Ans: , MgmtId:
> 90520747364525, via: 2, Ver: v1, Flags: 110,
> [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat
> java.lang.ProcessBuilder.start(ProcessBuilder.java:457)\n\tat
> com.cloud.utils.script.Script.execute(Script.java:183)\n\tat
> com.cloud.utils.script.Script.execute(Script.java:161)\n\tat
> com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.execute(VirtualRoutingResource.java:608)\n\tat
>
> com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.executeRequest(VirtualRoutingResource.java:139)\n\tat
>
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1118)\n\tat
> com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat
> com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat
> com.cloud.utils.nio.Task.run(Task.java:83)\n\tat
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat
> java.lang.Thread.run(Thread.java:679)\n","wait":0}}] }
> 2013-05-03 12:41:55,212 DEBUG [agent.manager.AgentAttache]
> (AgentManager-Handler-2:null) Seq 2-1920335888: No more commands found
> 2013-05-03 12:41:55,212 DEBUG [agent.transport.Request]
> (Job-Executor-24:job-33) Seq 2-1920335888: Received: { Ans: , MgmtId:
> 90520747364525, via: 2, Ver: v1, Flags: 110, { Answer } }
> 2013-05-03 12:41:55,212 INFO [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Unable to contact resource.
> com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is
> unreachable: Unable to apply dhcp entry on router
> at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:3431)
> at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:2664)
> at
> com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:831)
> at
> com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:1547)
> at
> com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:1658)
> at
> com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:1599)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:746)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3865)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3458)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3444)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
> at
> com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:679)
> 2013-05-03 12:41:55,228 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Cleaning up resources for the vm VM[User|MY-VM] in
> Starting state
> 2013-05-03 12:41:55,231 DEBUG [agent.transport.Request]
> (Job-Executor-24:job-33) Seq 5-2052983787: Sending { Cmd , MgmtId:
> 90520747364525, via: 5, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"i-2-17-VM","wait":0}}] }
> 2013-05-03 12:41:55,386 DEBUG [agent.transport.Request]
> (AgentManager-Handler-14:null) Seq 5-2052983787: Processing: { Ans: ,
> MgmtId: 90520747364525, via: 5, Ver: v1, Flags: 110,
> [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
> 2013-05-03 12:41:55,387 DEBUG [agent.manager.AgentAttache]
> (AgentManager-Handler-14:null) Seq 5-2052983787: No more commands found
> 2013-05-03 12:41:55,387 DEBUG [agent.transport.Request]
> (Job-Executor-24:job-33) Seq 5-2052983787: Received: { Ans: , MgmtId:
> 90520747364525, via: 5, Ver: v1, Flags: 110, { StopAnswer } }
> 2013-05-03 12:41:55,393 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-24:job-33) Changing active number of nics for network id=203 on
> -1
> 2013-05-03 12:41:55,406 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Successfully released network resources for the vm
> VM[User|MY-VM]
> 2013-05-03 12:41:55,406 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-24:job-33) Successfully cleanued up resources for the vm
> VM[User|MY-VM] in Starting state
> 2013-05-03 12:41:55,409 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-24:job-33) DataCenter id = '1' provided is in avoid set,
> DeploymentPlanner cannot allocate the VM, returning.
> 2013-05-03 12:41:55,438 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) VM state transitted from :Starting to Stopped with
> event: OperationFailedvm's original host id: null new host id: null host id
> before state transition: 5
> 2013-05-03 12:41:55,445 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) Hosts's actual total CPU: 20216 and CPU after
> applying overprovisioning: 202160
> 2013-05-03 12:41:55,445 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) release cpu from host: 5, old used: 5500,reserved:
> 0, actual total: 20216, total with overprovisioning: 202160; new used:
> 4500,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-05-03 12:41:55,445 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) release mem from host: 5, old used:
> 4026531840,reserved: 0, total: 16713142272; new used: 2952790016,reserved:0;
> movedfromreserved: false,moveToReserveredfalse
> 2013-05-03 12:41:55,462 DEBUG [cloud.vm.UserVmManagerImpl]
> (Job-Executor-24:job-33) Destroying vm VM[User|MY-VM] as it failed to create
> on Host with Id:null
> 2013-05-03 12:41:55,492 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-24:job-33) VM state transitted from :Stopped to Error with
> event: OperationFailedToErrorvm's original host id: null new host id: null
> host id before state transition: null
> 2013-05-03 12:41:55,618 INFO [user.vm.DeployVMCmd] (Job-Executor-24:job-33)
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a
> deployment for VM[User|MY-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> 2013-05-03 12:41:55,618 INFO [user.vm.DeployVMCmd] (Job-Executor-24:job-33)
> Unable to create a deployment for VM[User|MY-VM]
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a
> deployment for VM[User|MY-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:728)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3865)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3458)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3444)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:379)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162)
> at
> com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:679)
> 2013-05-03 12:41:55,619 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-24:job-33) Complete async job-33, jobStatus: 2, resultCode:
> 530, result: Error Code: 533 Error text: Unable to create a deployment for
> VM[User|MY-VM]
> 2013-05-03 12:41:55,782 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-3:null) HostStatsCollector is running...
> 2013-05-03 12:41:56,375 DEBUG [agent.transport.Request]
> (StatsCollector-3:null) Seq 2-1920335889: Received: { Ans: , MgmtId:
> 90520747364525, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-05-03 12:41:56,934 DEBUG [agent.transport.Request]
> (StatsCollector-3:null) Seq 5-2052983788: Received: { Ans: , MgmtId:
> 90520747364525, via: 5, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2013-05-03 12:41:57,799 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null)
> ===START=== 10.0.28.16 -- GET
> command=queryAsyncJobResult&jobId=da527ca7-826a-4d51-9793-3f7100b3c043&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577717824
> 2013-05-03 12:41:57,812 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-16:null) Async job-33 completed
> 2013-05-03 12:41:57,817 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null)
> ===END=== 10.0.28.16 -- GET
> command=queryAsyncJobResult&jobId=da527ca7-826a-4d51-9793-3f7100b3c043&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577717824
> 2013-05-03 12:41:57,827 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null)
> ===START=== 10.0.28.16 -- GET
> command=listVirtualMachines&id=6dd83da7-9356-4a24-aafb-3a73e3f2cd75&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577717852
> 2013-05-03 12:41:57,858 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null)
> ===END=== 10.0.28.16 -- GET
> command=listVirtualMachines&id=6dd83da7-9356-4a24-aafb-3a73e3f2cd75&response=json&sessionkey=eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=1367577717852
> 2013-05-03 12:42:02,518 DEBUG [cloud.cluster.ClusterManagerImpl]
> (Cluster-Heartbeat-1:null) Management server heartbeat takes too long to
> finish. profiler: Done. Duration: 1942ms, profilerHeartbeatUpdate: Done.
> Duration: 1941ms, profilerPeerScan: Done. Duration: 1ms, profilerAgentLB:
> Done. Duration: 0ms
> 2013-05-03 12:42:09,339 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-3:null) VmStatsCollector is running...
> 2013-05-03 12:42:09,382 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet
> 2013-05-03 12:42:09,394 DEBUG [agent.transport.Request]
> (StatsCollector-3:null) Seq 5-2052983789: Received: { Ans: , MgmtId:
> 90520747364525, via: 5, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2013-05-03 12:42:10,175 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2013-05-03 12:42:10,176 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-03 12:42:10,193 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2013-05-03 12:42:10,197 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-03 12:42:13,612 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-6:null) Ping from 2
> 2013-05-03 12:42:14,717 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-3:null) Ping from 6
> 2013-05-03 12:42:14,803 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-8:null) Ping from 4
> 2013-05-03 12:42:15,235 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-11:null) Ping from 5
> 2013-05-03 12:42:39,382 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet
> 2013-05-03 12:42:40,175 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2013-05-03 12:42:40,176 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-03 12:42:40,193 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2013-05-03 12:42:40,196 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-05-03 12:42:41,140 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-2:null) StorageCollector is running...
> 2013-05-03 12:42:41,201 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 6-685442216: Received: { Ans: , MgmtId:
> 90520747364525, via: 6, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2013-05-03 12:42:41,283 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 2-1920335890: Received: { Ans: , MgmtId:
> 90520747364525, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> Cheers,
> Shashi
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
