cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Shashi Dahal (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-2322) 2.2.14 to 4.1.0 upgrade: unable to add a new VM
Date Fri, 03 May 2013 10:46:16 GMT
Shashi Dahal created CLOUDSTACK-2322:
----------------------------------------

             Summary: 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
             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. 

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

Mime
View raw message