Hello,
It appears as if I am unable to provision instances because for some reason
Cloudstack cannot find a suitable storage pool. Here is the information
from the log file for one instance I attempted to provision:
2014-04-03 00:37:43,459 DEBUG [cloud.api.ApiServlet]
(catalina-exec-11:null) ===END=== 65.183.45.4 -- GET
command=listVPCs&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485198304
2014-04-03 00:37:43,518 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===START=== 65.183.45.4 -- GET
command=listNetworks&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&zoneId=f77ce551-6188-4366-a242-8c766acc3ab9&canusefordeploy=true&domainid=8e69d968-ba30-11e3-9d11-00269e3cfeda&account=admin&_=1396485198339
2014-04-03 00:37:43,526 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-8:null) Access granted to
Acct[05e9982a-baae-11e3-9d11-00269e3cfeda-admin] to Domain:1/ by
AffinityGroupAccessChecker_EnhancerByCloudStack_cb9376be
2014-04-03 00:37:43,540 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===END=== 65.183.45.4 -- GET
command=listNetworks&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&zoneId=f77ce551-6188-4366-a242-8c766acc3ab9&canusefordeploy=true&domainid=8e69d968-ba30-11e3-9d11-00269e3cfeda&account=admin&_=1396485198339
2014-04-03 00:37:43,552 DEBUG [cloud.api.ApiServlet]
(catalina-exec-18:null) ===START=== 65.183.45.4 -- GET
command=listNetworkOfferings&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&forvpc=false&zoneid=f77ce551-6188-4366-a242-8c766acc3ab9&guestiptype=Isolated&supportedServices=SourceNat&specifyvlan=false&state=Enabled&_=1396485198415
2014-04-03 00:37:43,577 DEBUG [cloud.api.ApiServlet]
(catalina-exec-18:null) ===END=== 65.183.45.4 -- GET
command=listNetworkOfferings&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&forvpc=false&zoneid=f77ce551-6188-4366-a242-8c766acc3ab9&guestiptype=Isolated&supportedServices=SourceNat&specifyvlan=false&state=Enabled&_=1396485198415
2014-04-03 00:37:43,966 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) VmStatsCollector is running...
2014-04-03 00:37:45,519 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 1-3439: Processing Seq 1-3439: { Cmd ,
MgmtId: -1, via: 1, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-04-03 00:37:45,585 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 1-3439: Sending Seq 1-3439: { Ans: ,
MgmtId: 165863554778, via: 1, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-04-03 00:37:48,387 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-12:null) Ping from 3
2014-04-03 00:37:53,228 DEBUG [cloud.api.ApiServlet]
(catalina-exec-15:null) ===START=== 65.183.45.4 -- GET
command=deployVirtualMachine&zoneId=f77ce551-6188-4366-a242-8c766acc3ab9&templateId=8ebdc956-ba30-11e3-9d11-00269e3cfeda&hypervisor=KVM&serviceOfferingId=cef59ea0-767f-419f-9b80-bdf028a69eaa&networkIds=6bd0bdff-2f05-4a01-b242-803f3789aa67&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485208038
2014-04-03 00:37:53,235 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-15:null) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2014-04-03 00:37:53,237 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-15:null) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2014-04-03 00:37:53,239 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-15:null) ControlledEntity name is:com.cloud.network.Network
2014-04-03 00:37:53,250 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-15:null) Service SecurityGroup is not supported in the
network id=204
2014-04-03 00:37:53,329 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-15:null) Allocating in the DB for vm
2014-04-03 00:37:53,337 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-15:null) Allocating entries for VM:
VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]
2014-04-03 00:37:53,337 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-15:null) Allocating nics for
VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]
2014-04-03 00:37:53,338 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-15:null) Allocating nic for vm
VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42] in network Ntwk[204|Guest|8]
with requested profile NicProfile[0-0-null-null-null
2014-04-03 00:37:53,420 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-15:null) Service SecurityGroup is not supported in the
network id=204
2014-04-03 00:37:53,421 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-15:null) Allocating disks for
VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]
2014-04-03 00:37:53,428 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-15:null) Allocation completed for VM:
VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]
2014-04-03 00:37:53,428 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-15:null) Successfully allocated DB entry for
VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]
2014-04-03 00:37:53,515 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-15:null) Service SecurityGroup is not supported in the
network id=204
2014-04-03 00:37:53,517 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-15:null) Service SecurityGroup is not supported in the
network id=204
2014-04-03 00:37:53,724 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-15:null) submit async job-20 = [
4af3530d-1c64-4503-adb5-1cf6280d8b31 ], details: AsyncJobVO {id:20, userId:
2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
instanceId: 6, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd,
cmdOriginator: null, cmdInfo:
{"sessionkey":"HIP6Nm7WuAHkrERfXgFrBrXqg8w\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","serviceOfferingId":"cef59ea0-767f-419f-9b80-bdf028a69eaa","httpmethod":"GET","zoneId":"f77ce551-6188-4366-a242-8c766acc3ab9","templateId":"8ebdc956-ba30-11e3-9d11-00269e3cfeda","response":"json","id":"6","networkIds":"6bd0bdff-2f05-4a01-b242-803f3789aa67","hypervisor":"KVM","_":"1396485208038","ctxAccountId":"2","ctxStartEventId":"79"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 165863554778,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-04-03 00:37:53,727 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-20
= [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
2014-04-03 00:37:53,727 DEBUG [cloud.api.ApiServlet]
(catalina-exec-15:null) ===END=== 65.183.45.4 -- GET
command=deployVirtualMachine&zoneId=f77ce551-6188-4366-a242-8c766acc3ab9&templateId=8ebdc956-ba30-11e3-9d11-00269e3cfeda&hypervisor=KVM&serviceOfferingId=cef59ea0-767f-419f-9b80-bdf028a69eaa&networkIds=6bd0bdff-2f05-4a01-b242-803f3789aa67&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485208038
2014-04-03 00:37:53,732 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2014-04-03 00:37:53,734 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2014-04-03 00:37:53,736 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
ControlledEntity name is:com.cloud.network.Network
2014-04-03 00:37:53,836 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Service
SecurityGroup is not supported in the network id=204
2014-04-03 00:37:53,838 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Service
SecurityGroup is not supported in the network id=204
2014-04-03 00:37:53,848 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Deploy
avoids pods: [], clusters: [], hosts: []
2014-04-03 00:37:53,849 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_dbf95b0a@13ed6b28
2014-04-03 00:37:53,849 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Trying
to allocate a host and storage pools from dc:1, pod:null,cluster:null,
requested cpu: 1000, requested ram: 1073741824
2014-04-03 00:37:53,849 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Is ROOT
volume READY (pool already allocated)?: No
2014-04-03 00:37:53,849 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Searching all possible resources under this Zone: 1
2014-04-03 00:37:53,850 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Zone: 1
2014-04-03 00:37:53,852 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Removing from the clusterId list these clusters from avoid set: []
2014-04-03 00:37:53,856 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Checking resources in Cluster: 1 under Pod: 1
2014-04-03 00:37:53,858 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2014-04-03 00:37:53,859 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
allocation: [Host[-3-Routing]]
2014-04-03 00:37:53,861 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Found 1 hosts for allocation after
prioritization: [Host[-3-Routing]]
2014-04-03 00:37:53,861 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2014-04-03 00:37:53,864 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Checking if host: 3 has enough capacity for
requested CPU: 1000 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2014-04-03 00:37:53,866 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 63984 and CPU after
applying overprovisioning: 63984
2014-04-03 00:37:53,866 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Free CPU: 62984 , Requested CPU: 1000
2014-04-03 00:37:53,866 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Free RAM: 150923509760 , Requested RAM: 1073741824
2014-04-03 00:37:53,866 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-04-03 00:37:53,866 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 3, used: 1000,
reserved: 0, actual total: 63984, total with overprovisioning: 63984;
requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-04-03 00:37:53,866 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 3, used:
1342177280, reserved: 0, total: 152265687040; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-04-03 00:37:53,866 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Found a suitable host, adding to list: 3
2014-04-03 00:37:53,866 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]
FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2014-04-03 00:37:53,867 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Checking suitable pools for volume (Id, Type): (9,ROOT)
2014-04-03 00:37:53,867 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) We need
to allocate new storagepool for this volume
2014-04-03 00:37:53,867 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Calling
StoragePoolAllocators to find suitable pools
2014-04-03 00:37:53,868 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-04-03 00:37:53,868 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
ClusterScopeStoragePoolAllocator looking for storage pool
2014-04-03 00:37:53,868 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Looking
for pools in dc: 1 pod:1 cluster:1
2014-04-03 00:37:53,869 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) No
storage pools available for shared volume allocation, returning
2014-04-03 00:37:53,869 DEBUG
[storage.allocator.ZoneWideStoragePoolAllocator] (Job-Executor-20:job-20 =
[ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) ZoneWideStoragePoolAllocator to
find storage pool
2014-04-03 00:37:53,871 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) No
suitable pools found for volume: Vol[9|vm=6|ROOT] under cluster: 1
2014-04-03 00:37:53,871 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) No
suitable pools found
2014-04-03 00:37:53,871 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) No
suitable storagePools found under this Cluster: 1
2014-04-03 00:37:53,872 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Could
not find suitable Deployment Destination for this VM under any clusters,
returning.
2014-04-03 00:37:53,872 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Searching all possible resources under this Zone: 1
2014-04-03 00:37:53,873 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Zone: 1
2014-04-03 00:37:53,875 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Removing from the clusterId list these clusters from avoid set: [1]
2014-04-03 00:37:53,876 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) No
clusters found after removing disabled clusters and clusters in avoid list,
returning.
2014-04-03 00:37:53,878 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Destroying vm VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42] as it failed to
create on Host with Id:null
2014-04-03 00:37:54,009 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) 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
2014-04-03 00:37:54,142 WARN [apache.cloudstack.alerts]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
alertType:: 8 // dataCenterId:: 1 // podId:: null // clusterId:: null //
message:: Failed to deploy Vm with Id: 6, on Host with Id: null
2014-04-03 00:37:54,552 INFO [user.vm.DeployVMCmd] (Job-Executor-20:job-20
= [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]Scope=interface
com.cloud.dc.DataCenter; id=1
2014-04-03 00:37:54,552 INFO [user.vm.DeployVMCmd] (Job-Executor-20:job-20
= [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ]) Unable to create a deployment
for VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]Scope=interface
com.cloud.dc.DataCenter; id=1
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.reserveVirtualMachine(VMEntityManagerImpl.java:209)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.reserve(VirtualMachineEntityImpl.java:198)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3439)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3000)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2986)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
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:701)
2014-04-03 00:37:54,553 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-20:job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ])
Complete async job-20 = [ 4af3530d-1c64-4503-adb5-1cf6280d8b31 ],
jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable
to create a deployment for VM[User|1deae872-9ab2-4d07-9932-e1b36f43ce42]
2014-04-03 00:37:55,520 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) SeqA 1-3440: Processing Seq 1-3440: { Cmd ,
MgmtId: -1, via: 1, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-04-03 00:37:55,593 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) SeqA 1-3440: Sending Seq 1-3440: { Ans: ,
MgmtId: 165863554778, via: 1, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-04-03 00:37:56,029 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2014-04-03 00:37:56,115 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2014-04-03 00:37:56,805 DEBUG [cloud.api.ApiServlet]
(catalina-exec-20:null) ===START=== 65.183.45.4 -- GET
command=queryAsyncJobResult&jobId=4af3530d-1c64-4503-adb5-1cf6280d8b31&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485211669
2014-04-03 00:37:56,813 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-20:null) Async job-20 = [
4af3530d-1c64-4503-adb5-1cf6280d8b31 ] completed
2014-04-03 00:37:56,816 DEBUG [cloud.api.ApiServlet]
(catalina-exec-20:null) ===END=== 65.183.45.4 -- GET
command=queryAsyncJobResult&jobId=4af3530d-1c64-4503-adb5-1cf6280d8b31&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485211669
2014-04-03 00:37:56,822 DEBUG [cloud.api.ApiServlet]
(catalina-exec-13:null) ===START=== 65.183.45.4 -- GET
command=listVirtualMachines&id=1deae872-9ab2-4d07-9932-e1b36f43ce42&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485211687
2014-04-03 00:37:56,834 DEBUG [cloud.api.ApiServlet]
(catalina-exec-13:null) ===END=== 65.183.45.4 -- GET
command=listVirtualMachines&id=1deae872-9ab2-4d07-9932-e1b36f43ce42&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485211687
2014-04-03 00:37:57,359 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-04-03 00:37:57,360 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-04-03 00:37:58,602 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) StorageCollector is running...
2014-04-03 00:37:58,660 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 2-1699480280: Received: { Ans: , MgmtId:
165863554778, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-04-03 00:37:58,715 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 3-2118124443: Received: { Ans: , MgmtId:
165863554778, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
The funny part is I can provision a storage volume just fine:
2014-04-03 00:38:18,100 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
===END=== 65.183.45.4 -- GET
command=listDiskOfferings&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485232951
2014-04-03 00:38:20,015 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) HostStatsCollector is running...
2014-04-03 00:38:20,609 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 3-2118124444: Received: { Ans: , MgmtId:
165863554778, via: 3, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-04-03 00:38:25,522 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 1-3443: Processing Seq 1-3443: { Cmd ,
MgmtId: -1, via: 1, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-04-03 00:38:25,594 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 1-3443: Sending Seq 1-3443: { Ans: ,
MgmtId: 165863554778, via: 1, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-04-03 00:38:26,031 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2014-04-03 00:38:26,114 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2014-04-03 00:38:27,359 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-04-03 00:38:27,360 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-04-03 00:38:31,246 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-5:null) Ping from 1
2014-04-03 00:38:33,590 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null)
===START=== 65.183.45.4 -- GET
command=createVolume&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&name=Test+Volume&zoneId=f77ce551-6188-4366-a242-8c766acc3ab9&diskOfferingId=bd935d82-4578-430a-a084-70d4be1876cd&_=1396485248404
2014-04-03 00:38:33,884 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-2:null) submit async job-22 = [
b635cfe0-5973-44d6-abcb-042fedb3e3d5 ], details: AsyncJobVO {id:22, userId:
2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 10,
cmd: org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd,
cmdOriginator: null, cmdInfo:
{"id":"10","response":"json","sessionkey":"HIP6Nm7WuAHkrERfXgFrBrXqg8w\u003d","cmdEventType":"VOLUME.CREATE","ctxUserId":"2","diskOfferingId":"bd935d82-4578-430a-a084-70d4be1876cd","name":"Test
Volume","httpmethod":"GET","_":"1396485248404","ctxAccountId":"2","ctxStartEventId":"86","zoneId":"f77ce551-6188-4366-a242-8c766acc3ab9"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 165863554778,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-04-03 00:38:33,885 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-22:job-22 = [ b635cfe0-5973-44d6-abcb-042fedb3e3d5 ])
Executing org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd for
job-22 = [ b635cfe0-5973-44d6-abcb-042fedb3e3d5 ]
2014-04-03 00:38:33,885 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null)
===END=== 65.183.45.4 -- GET
command=createVolume&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&name=Test+Volume&zoneId=f77ce551-6188-4366-a242-8c766acc3ab9&diskOfferingId=bd935d82-4578-430a-a084-70d4be1876cd&_=1396485248404
2014-04-03 00:38:34,043 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-22:job-22 = [ b635cfe0-5973-44d6-abcb-042fedb3e3d5 ])
Complete async job-22 = [ b635cfe0-5973-44d6-abcb-042fedb3e3d5 ],
jobStatus: 1, resultCode: 0, result:
org.apache.cloudstack.api.response.VolumeResponse@4a6dc9e5
2014-04-03 00:38:34,107 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-22:job-22 = [ b635cfe0-5973-44d6-abcb-042fedb3e3d5 ]) Done
executing org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd for
job-22 = [ b635cfe0-5973-44d6-abcb-042fedb3e3d5 ]
2014-04-03 00:38:35,562 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 1-3445: Processing Seq 1-3445: { Cmd ,
MgmtId: -1, via: 1, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2014-04-03 00:38:35,639 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 1-3445: Sending Seq 1-3445: { Ans: ,
MgmtId: 165863554778, via: 1, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-04-03 00:38:36,911 DEBUG [cloud.api.ApiServlet]
(catalina-exec-17:null) ===START=== 65.183.45.4 -- GET
command=queryAsyncJobResult&jobId=b635cfe0-5973-44d6-abcb-042fedb3e3d5&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485251773
2014-04-03 00:38:36,918 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-17:null) Async job-22 = [
b635cfe0-5973-44d6-abcb-042fedb3e3d5 ] completed
2014-04-03 00:38:36,922 DEBUG [cloud.api.ApiServlet]
(catalina-exec-17:null) ===END=== 65.183.45.4 -- GET
command=queryAsyncJobResult&jobId=b635cfe0-5973-44d6-abcb-042fedb3e3d5&response=json&sessionkey=HIP6Nm7WuAHkrERfXgFrBrXqg8w%3D&_=1396485251773
I have sysytem.vm.use.local.storage set to true in the Global
Configuration. I am just unable to find the use.local.storage
configuration variable anywhere. Is it just me missing it somewhere?
I am using Cloudstack 4.2.1. The two system VMs installed just fine. They
are running and I can access them with ping and by ssh into them. Any
suggestions are greatly appreciated. I have worked on this setup for
literally 42 hours since Sunday afternoon and I really need to get it going
asap.
Thanks,
Fred
