[cloudstack-users:0413] Re: 【質問】システムVM2台の作成、起動について（CentOS6.6+KVM+ver4.1.1）
giraffe.forest
giraffe.forest ＠ wh.commufa.jp
2015年 1月 10日 (土) 18:58:09 JST
永喜多さん
中谷です。
SystemVMの稼働おめでとうございます！
blogやtwitterの方でもやりとりさせていただきましたが
今回は以下がポイントだったと思います。
・ホスト名やhostsをlocalhost.localdomain以外で設定する
・CloudStackのトラフィックラベルとkvm仮想スイッチの名前を一致させる
・ローカルストレージ利用時のゾーン作成時の設定
Local Storage Enabled [レ]
グローバルConfig設定
system.vm.use.local.storage true
次のCentOS5のテンプレートが起動してこない点ついてログを確認しました。
2015-01-10 13:45:22,656 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) No suitable pools found for volume:
Vol[34|vm=28|DATADISK] under cluster: 1
2015-01-10 13:45:22,657 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) No suitable pools found
2015-01-10 13:45:22,657 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) No suitable storagePools found under this Cluster: 1
2015-01-10 13:45:22,657 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Could not find suitable Deployment Destination for
this VM under any clusters, returning.
データディスクの確保で失敗しているようです。
一度以下をお試しください。
その１)
テンプレートからvmインスタンスを作成する場合は
データディスクの指定は必須ではないので
vmインスタンス作成ウィザードでディスクを指定せずvmを作成してみてください。
※ちなみにISOファイルを使用したvmインスタンスの作成する場合は
OSのインストールメディアを使用してディスクにインストールすることになるので
ディスクの指定は必須です。
その2)
コンピューティングでストレージsharedではなくlocalを設定したと思いますが
ディスクオファリングもlocalを指定し使用してみてください。
以上です。
-----Original Message-----
From: 永喜多
Sent: Saturday, January 10, 2015 4:21 PM
To: users ＠ cloudstack.jp
Subject: [cloudstack-users:0412] Re:【質問】システムVM2台の作成、起動について（CentOS6.6+KVM+ver4.1.1）
こんにちは。永喜多です。
ご指摘いただいた箇所などを修正しつつ、セットアップを
やりなおした結果、システムVMが2台および、仮想ルーターが起動しました。
ありがとうございます。
localに指定したコンピュートオファリングを作成し、セキュリティグループで
さしあたり0.0.0.0/0で特定ポート郡の開放をしました。
その後、テンプレートにあるCentOS5.5を起動しようと
したところ、Errorで停止しました。
デプロイ時のログは以下のようになります。
agent.logは流れがなく、/var/log/libvirt/qemu/ にはVMの名前がありませんでした。
[root ＠ cloud ~]# tail -f /var/log/cloudstack/management/management-server.log
2015-01-10 13:32:48,751 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:50,237 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:32:50,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:32:50,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:51,737 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:32:51,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:32:51,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:53,251 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:32:53,251 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:32:53,252 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:54,751 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:32:54,751 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:32:54,752 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:54,935 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-5:null) SeqA 3-409: Processing Seq 3-409: { Cmd ,
MgmtId: -1, via: 3, Ver: v1, Flags: 11,
[{"ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2015-01-10 13:32:54,950 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-5:null) SeqA 3-409: Sending Seq 3-409: { Ans: ,
MgmtId: 129899290224676, via: 3, Ver: v1, Flags: 100010,
[{"AgentControlAnswer":{"result":true,"wait":0}}] }
2015-01-10 13:32:56,237 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:32:56,237 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:32:56,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:56,359 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
===START=== 192.168.0.2 -- GET
command=deployVirtualMachine&zoneId=fd74d286-9aab-4489-8c12-01a1e2ff3e91&templateId=1d4916ba-9836-11e4-88cc-001999b8c751&hypervisor=KVM&serviceOfferingId=48d211bc-7dc8-4012-b68d-7071ce52c62e&diskOfferingId=6b1bc6f6-3e68-4f35-a905-ca91bde106fa&securitygroupids=ccc2d973-05e8-40c5-8fdd-48d42479d5e3&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420864377008
2015-01-10 13:32:56,376 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-6:null) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2015-01-10 13:32:56,381 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-6:null) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2015-01-10 13:32:56,388 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-6:null) InfrastructureEntity name
is:com.cloud.offering.DiskOffering
2015-01-10 13:32:56,394 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-6:null) ControlledEntity name
is:com.cloud.network.security.SecurityGroup
2015-01-10 13:32:56,423 DEBUG [cloud.configuration.ConfigurationManagerImpl]
(catalina-exec-6:null) Access granted to Acct[2-admin] to zone:1 by
DomainChecker_EnhancerByCloudStack_cfaf3ad0
2015-01-10 13:32:56,423 DEBUG [cloud.configuration.ConfigurationManagerImpl]
(catalina-exec-6:null) Access granted to Acct[2-admin] to zone:1 by
DomainChecker_EnhancerByCloudStack_cfaf3ad0
2015-01-10 13:32:56,462 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-6:null) Allocating in the DB for vm
2015-01-10 13:32:56,482 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-6:null) Allocating entries for VM:
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]
2015-01-10 13:32:56,483 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-6:null) Allocating nics for
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]
2015-01-10 13:32:56,485 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-6:null) Allocating nic for vm
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb] in network Ntwk[204|Guest|6]
with requested profile NicProfile[0-0-null-null-null
2015-01-10 13:32:56,506 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-6:null) Allocaing disks for
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]
2015-01-10 13:32:56,543 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-6:null) Allocation completed for VM:
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]
2015-01-10 13:32:56,544 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-6:null) Successfully allocated DB entry for
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]
2015-01-10 13:32:56,694 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-6:null) submit async job-33, details: AsyncJobVO {id:33,
userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
instanceId: 25, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd,
cmdOriginator: null, cmdInfo:
{"id":"25","response":"json","templateId":"1d4916ba-9836-11e4-88cc-001999b8c751","sessionkey":"s8ySfW8NWUOdK++sZ1xdIh1ZkyM\u003d","ctxUserId":"2","hypervisor":"KVM","diskOfferingId":"6b1bc6f6-3e68-4f35-a905-ca91bde106fa","serviceOfferingId":"48d211bc-7dc8-4012-b68d-7071ce52c62e","_":"1420864377008","securitygroupids":"ccc2d973-05e8-40c5-8fdd-48d42479d5e3","ctxAccountId":"2","ctxStartEventId":"125","zoneId":"fd74d286-9aab-4489-8c12-01a1e2ff3e91"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 129899290224676,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2015-01-10 13:32:56,695 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-3:job-33) Executing
org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-33
2015-01-10 13:32:56,699 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
===END=== 192.168.0.2 -- GET
command=deployVirtualMachine&zoneId=fd74d286-9aab-4489-8c12-01a1e2ff3e91&templateId=1d4916ba-9836-11e4-88cc-001999b8c751&hypervisor=KVM&serviceOfferingId=48d211bc-7dc8-4012-b68d-7071ce52c62e&diskOfferingId=6b1bc6f6-3e68-4f35-a905-ca91bde106fa&securitygroupids=ccc2d973-05e8-40c5-8fdd-48d42479d5e3&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420864377008
2015-01-10 13:32:56,709 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-3:job-33) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2015-01-10 13:32:56,713 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-3:job-33) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2015-01-10 13:32:56,717 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-3:job-33) InfrastructureEntity name
is:com.cloud.offering.DiskOffering
2015-01-10 13:32:56,723 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-3:job-33) ControlledEntity name
is:com.cloud.network.security.SecurityGroup
2015-01-10 13:32:56,753 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2015-01-10 13:32:56,834 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) DeploymentPlanner allocation algorithm: random
2015-01-10 13:32:56,834 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Trying to allocate a host and storage pools from
dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2015-01-10 13:32:56,834 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Is ROOT volume READY (pool already allocated)?: No
2015-01-10 13:32:56,834 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Searching all possible resources under this Zone: 1
2015-01-10 13:32:56,838 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Listing clusters in order of aggregate capacity,
that have (atleast one host with) enough CPU and RAM capacity under this
Zone: 1
2015-01-10 13:32:56,840 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) CPUOverprovisioningFactor considered: 1.0
2015-01-10 13:32:56,862 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Checking resources in Cluster: 1 under Pod: 1
2015-01-10 13:32:56,867 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2015-01-10 13:32:56,872 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) FirstFitAllocator has 1
hosts to check for allocation: [Host[-1-Routing]]
2015-01-10 13:32:56,879 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Found 1 hosts for
allocation after prioritization: [Host[-1-Routing]]
2015-01-10 13:32:56,880 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Looking for speed=1000Mhz,
Ram=1024
2015-01-10 13:32:56,885 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Checking if host: 1 has
enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2015-01-10 13:32:56,893 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Hosts's actual total CPU:
19200 and CPU after applying overprovisioning: 19200
2015-01-10 13:32:56,893 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Free CPU: 12100 , Requested
CPU: 1000
2015-01-10 13:32:56,893 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Free RAM: 6354173952 ,
Requested RAM: 1073741824
2015-01-10 13:32:56,893 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Host has enough CPU and RAM
available
2015-01-10 13:32:56,894 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 1500, reserved: 5600, actual total: 19200, total with
overprovisioning: 19200; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-01-10 13:32:56,894 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 1476395008, reserved: 8589934592, total: 16420503552;
requested mem: 1073741824,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-01-10 13:32:56,894 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Found a suitable host,
adding to list: 1
2015-01-10 13:32:56,894 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-3:job-33 FirstFitRoutingAllocator) Host Allocator returning 1
suitable hosts
2015-01-10 13:32:56,900 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Checking suitable pools for volume (Id, Type):
(28,ROOT)
2015-01-10 13:32:56,901 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) We need to allocate new storagepool for this volume
2015-01-10 13:32:56,904 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Calling StoragePoolAllocators to find suitable pools
2015-01-10 13:32:56,907 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-3:job-33)
Looking for pools in dc: 1 pod:1 cluster:1
2015-01-10 13:32:56,912 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-3:job-33)
FirstFitStoragePoolAllocator has 1 pools to check for allocation
2015-01-10 13:32:56,912 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-3:job-33)
Checking if storage pool is suitable, name: cloud.priv ,poolId: 200
2015-01-10 13:32:56,912 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-3:job-33) Is
localStorageAllocationNeeded? false
2015-01-10 13:32:56,912 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-3:job-33) Is
storage pool shared? false
2015-01-10 13:32:56,912 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-3:job-33)
StoragePool is not of correct type, skipping this pool
2015-01-10 13:32:56,913 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-3:job-33)
FirstFitStoragePoolAllocator returning 0 suitable storage pools
2015-01-10 13:32:56,913 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) No suitable pools found for volume:
Vol[28|vm=25|ROOT] under cluster: 1
2015-01-10 13:32:56,913 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) No suitable pools found
2015-01-10 13:32:56,913 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) No suitable storagePools found under this Cluster: 1
2015-01-10 13:32:56,913 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-33) Could not find suitable Deployment Destination for
this VM under any clusters, returning.
2015-01-10 13:32:56,918 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-3:job-33) Destroying vm
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb] as it failed to create on Host
with Id:null
2015-01-10 13:32:56,947 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3: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
2015-01-10 13:32:57,147 INFO [user.vm.DeployVMCmd] (Job-Executor-3:job-33)
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-01-10 13:32:57,148 INFO [user.vm.DeployVMCmd] (Job-Executor-3:job-33)
Unable to create a deployment for
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]Scope=interface
com.cloud.dc.DataCenter; id=1
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.reserveVirtualMachine(VMEntityManagerImpl.java:186)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.reserve(VirtualMachineEntityImpl.java:198)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3870)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
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.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-01-10 13:32:57,149 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-3:job-33) Complete async job-33, jobStatus: 2, resultCode:
530, result: Error Code: 533 Error text: Unable to create a deployment for
VM[User|af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb]
2015-01-10 13:32:57,374 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2015-01-10 13:32:57,738 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:32:57,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:32:57,739 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:57,793 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2015-01-10 13:32:57,796 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2015-01-10 13:32:57,829 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2015-01-10 13:32:57,831 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2015-01-10 13:32:59,248 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:32:59,248 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:32:59,248 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:32:59,728 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===START=== 192.168.0.2 -- GET
command=queryAsyncJobResult&jobId=cd99c6e7-dc9b-41da-8276-4e30b5b7888e&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420864380375
2015-01-10 13:32:59,757 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-8:null) Async job-33 completed
2015-01-10 13:32:59,771 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===END=== 192.168.0.2 -- GET
command=queryAsyncJobResult&jobId=cd99c6e7-dc9b-41da-8276-4e30b5b7888e&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420864380375
2015-01-10 13:32:59,779 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
===START=== 192.168.0.2 -- GET
command=listVirtualMachines&id=af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420864380429
2015-01-10 13:32:59,828 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
===END=== 192.168.0.2 -- GET
command=listVirtualMachines&id=af5e1fbb-bd95-4c3c-9aeb-aaed09115ecb&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420864380429
2015-01-10 13:32:59,936 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-3:null) SeqA 3-410: Processing Seq 3-410: { Cmd ,
MgmtId: -1, via: 3, Ver: v1, Flags: 11,
[{"ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2015-01-10 13:32:59,951 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-3:null) SeqA 3-410: Sending Seq 3-410: { Ans: ,
MgmtId: 129899290224676, via: 3, Ver: v1, Flags: 100010,
[{"AgentControlAnswer":{"result":true,"wait":0}}] }
2015-01-10 13:33:00,750 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:33:00,750 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:33:00,751 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:33:02,237 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:33:02,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:33:02,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:33:03,341 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-6:null) Ping from 1
^C
[root ＠ cloud ~]#
上記から、リソースは空いていそうでしたが、リソースの空きがないのかと、Runningの
CentOS7を入れたVMを、グローバル設定から修正を入れて即時削除しています。
※KVMなのでqcow2のところが、ISOでしたが
▽変更したパラメータ
expunge.interval
expunge.delay
その後、以下にてあらためてテンプレートのVMを起動しました。
[root ＠ cloud ~]# tail -f /var/log/cloudstack/management/management-server.log
2015-01-10 13:45:14,250 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:14,251 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:15,032 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 3-516: Processing Seq 3-516: { Cmd ,
MgmtId: -1, via: 3, Ver: v1, Flags: 11,
[{"ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2015-01-10 13:45:15,059 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) SeqA 3-516: Sending Seq 3-516: { Ans: ,
MgmtId: 129899290224676, via: 3, Ver: v1, Flags: 100010,
[{"AgentControlAnswer":{"result":true,"wait":0}}] }
2015-01-10 13:45:15,737 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:15,737 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:15,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:17,237 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:17,237 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:17,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:18,750 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:18,751 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:18,751 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:20,250 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:20,250 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:20,251 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:21,737 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:21,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:21,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:22,088 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
===START=== 192.168.0.2 -- GET
command=deployVirtualMachine&zoneId=fd74d286-9aab-4489-8c12-01a1e2ff3e91&templateId=1d4916ba-9836-11e4-88cc-001999b8c751&hypervisor=KVM&serviceOfferingId=b37dda89-0f61-404d-90ac-b18bbfe3e7e7&diskOfferingId=6b1bc6f6-3e68-4f35-a905-ca91bde106fa&securitygroupids=ccc2d973-05e8-40c5-8fdd-48d42479d5e3&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420865122737
2015-01-10 13:45:22,104 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-19:null) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2015-01-10 13:45:22,108 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-19:null) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2015-01-10 13:45:22,112 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-19:null) InfrastructureEntity name
is:com.cloud.offering.DiskOffering
2015-01-10 13:45:22,117 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-19:null) ControlledEntity name
is:com.cloud.network.security.SecurityGroup
2015-01-10 13:45:22,142 DEBUG [cloud.configuration.ConfigurationManagerImpl]
(catalina-exec-19:null) Access granted to Acct[2-admin] to zone:1 by
DomainChecker_EnhancerByCloudStack_cfaf3ad0
2015-01-10 13:45:22,142 DEBUG [cloud.configuration.ConfigurationManagerImpl]
(catalina-exec-19:null) Access granted to Acct[2-admin] to zone:1 by
DomainChecker_EnhancerByCloudStack_cfaf3ad0
2015-01-10 13:45:22,178 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-19:null) Allocating in the DB for vm
2015-01-10 13:45:22,202 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-19:null) Allocating entries for VM:
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]
2015-01-10 13:45:22,203 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-19:null) Allocating nics for
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]
2015-01-10 13:45:22,205 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-19:null) Allocating nic for vm
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65] in network Ntwk[204|Guest|6]
with requested profile NicProfile[0-0-null-null-null
2015-01-10 13:45:22,227 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-19:null) Allocaing disks for
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]
2015-01-10 13:45:22,259 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-19:null) Allocation completed for VM:
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]
2015-01-10 13:45:22,259 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-19:null) Successfully allocated DB entry for
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]
2015-01-10 13:45:22,403 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-19:null) submit async job-38, details: AsyncJobVO {id:38,
userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
instanceId: 28, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd,
cmdOriginator: null, cmdInfo:
{"id":"28","response":"json","templateId":"1d4916ba-9836-11e4-88cc-001999b8c751","sessionkey":"s8ySfW8NWUOdK++sZ1xdIh1ZkyM\u003d","ctxUserId":"2","hypervisor":"KVM","diskOfferingId":"6b1bc6f6-3e68-4f35-a905-ca91bde106fa","serviceOfferingId":"b37dda89-0f61-404d-90ac-b18bbfe3e7e7","_":"1420865122737","securitygroupids":"ccc2d973-05e8-40c5-8fdd-48d42479d5e3","ctxAccountId":"2","ctxStartEventId":"143","zoneId":"fd74d286-9aab-4489-8c12-01a1e2ff3e91"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 129899290224676,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2015-01-10 13:45:22,405 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-38) Executing
org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-38
2015-01-10 13:45:22,409 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
===END=== 192.168.0.2 -- GET
command=deployVirtualMachine&zoneId=fd74d286-9aab-4489-8c12-01a1e2ff3e91&templateId=1d4916ba-9836-11e4-88cc-001999b8c751&hypervisor=KVM&serviceOfferingId=b37dda89-0f61-404d-90ac-b18bbfe3e7e7&diskOfferingId=6b1bc6f6-3e68-4f35-a905-ca91bde106fa&securitygroupids=ccc2d973-05e8-40c5-8fdd-48d42479d5e3&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420865122737
2015-01-10 13:45:22,417 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-8:job-38) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2015-01-10 13:45:22,421 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-8:job-38) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2015-01-10 13:45:22,425 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-8:job-38) InfrastructureEntity name
is:com.cloud.offering.DiskOffering
2015-01-10 13:45:22,431 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-8:job-38) ControlledEntity name
is:com.cloud.network.security.SecurityGroup
2015-01-10 13:45:22,542 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) DeploymentPlanner allocation algorithm: random
2015-01-10 13:45:22,542 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Trying to allocate a host and storage pools from
dc:1, pod:null,cluster:null, requested cpu: 5600, requested ram: 8589934592
2015-01-10 13:45:22,542 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Is ROOT volume READY (pool already allocated)?: No
2015-01-10 13:45:22,542 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Searching all possible resources under this Zone: 1
2015-01-10 13:45:22,547 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Listing clusters in order of aggregate capacity,
that have (atleast one host with) enough CPU and RAM capacity under this
Zone: 1
2015-01-10 13:45:22,549 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) CPUOverprovisioningFactor considered: 1.0
2015-01-10 13:45:22,572 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Checking resources in Cluster: 1 under Pod: 1
2015-01-10 13:45:22,578 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2015-01-10 13:45:22,582 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) FirstFitAllocator has 1
hosts to check for allocation: [Host[-1-Routing]]
2015-01-10 13:45:22,588 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Found 1 hosts for
allocation after prioritization: [Host[-1-Routing]]
2015-01-10 13:45:22,588 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Looking for speed=5600Mhz,
Ram=8192
2015-01-10 13:45:22,593 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Checking if host: 1 has
enough capacity for requested CPU: 5600 and requested RAM: 8589934592 ,
cpuOverprovisioningFactor: 1.0
2015-01-10 13:45:22,600 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Hosts's actual total CPU:
19200 and CPU after applying overprovisioning: 19200
2015-01-10 13:45:22,600 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Free CPU: 17700 , Requested
CPU: 5600
2015-01-10 13:45:22,600 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Free RAM: 14944108544 ,
Requested RAM: 8589934592
2015-01-10 13:45:22,600 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Host has enough CPU and RAM
available
2015-01-10 13:45:22,601 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 1500, reserved: 0, actual total: 19200, total with
overprovisioning: 19200; requested cpu:5600,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-01-10 13:45:22,601 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 1476395008, reserved: 0, total: 16420503552; requested mem:
8589934592,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-01-10 13:45:22,601 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Found a suitable host,
adding to list: 1
2015-01-10 13:45:22,601 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-38 FirstFitRoutingAllocator) Host Allocator returning 1
suitable hosts
2015-01-10 13:45:22,606 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Checking suitable pools for volume (Id, Type):
(33,ROOT)
2015-01-10 13:45:22,607 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) We need to allocate new storagepool for this volume
2015-01-10 13:45:22,609 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Calling StoragePoolAllocators to find suitable pools
2015-01-10 13:45:22,610 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-8:job-38) LocalStoragePoolAllocator trying to find storage
pool to fit the vm
2015-01-10 13:45:22,610 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
Looking for pools in dc: 1 pod:1 cluster:1
2015-01-10 13:45:22,614 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
FirstFitStoragePoolAllocator has 1 pools to check for allocation
2015-01-10 13:45:22,614 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38)
Checking if storage pool is suitable, name: cloud.priv ,poolId: 200
2015-01-10 13:45:22,614 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38) Is
localStorageAllocationNeeded? true
2015-01-10 13:45:22,614 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38) Is
storage pool shared? false
2015-01-10 13:45:22,620 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-8:job-38) Checking pool 200 for storage, totalSize:
1048881356800, usedBytes: 1165926400, usedPct: 0.0011115903552305375,
disable threshold: 0.85
2015-01-10 13:45:22,642 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-8:job-38) Checking pool: 200 for volume allocation
[Vol[33|vm=28|ROOT]], maxSize : 1048881356800, totalAllocatedSize :
2495488000, askingSize : 8589934592, allocated disable threshold: 0.85
2015-01-10 13:45:22,642 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
FirstFitStoragePoolAllocator returning 1 suitable storage pools
2015-01-10 13:45:22,645 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-8:job-38) Found suitable local storage pool 200, adding to
list
2015-01-10 13:45:22,645 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
Looking for pools in dc: 1 pod:1 cluster:1
2015-01-10 13:45:22,649 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
FirstFitStoragePoolAllocator has 1 pools to check for allocation
2015-01-10 13:45:22,649 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38)
Checking if storage pool is suitable, name: cloud.priv ,poolId: 200
2015-01-10 13:45:22,649 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38)
StoragePool is in avoid set, skipping this pool
2015-01-10 13:45:22,649 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
FirstFitStoragePoolAllocator returning 0 suitable storage pools
2015-01-10 13:45:22,649 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-8:job-38) LocalStoragePoolAllocator returning 1 suitable
storage pools
2015-01-10 13:45:22,649 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Checking suitable pools for volume (Id, Type):
(34,DATADISK)
2015-01-10 13:45:22,649 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) We need to allocate new storagepool for this volume
2015-01-10 13:45:22,652 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Calling StoragePoolAllocators to find suitable pools
2015-01-10 13:45:22,652 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
Looking for pools in dc: 1 pod:1 cluster:1
2015-01-10 13:45:22,656 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
FirstFitStoragePoolAllocator has 1 pools to check for allocation
2015-01-10 13:45:22,656 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38)
Checking if storage pool is suitable, name: cloud.priv ,poolId: 200
2015-01-10 13:45:22,656 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38) Is
localStorageAllocationNeeded? false
2015-01-10 13:45:22,656 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38) Is
storage pool shared? false
2015-01-10 13:45:22,656 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-8:job-38)
StoragePool is not of correct type, skipping this pool
2015-01-10 13:45:22,656 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-8:job-38)
FirstFitStoragePoolAllocator returning 0 suitable storage pools
2015-01-10 13:45:22,656 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) No suitable pools found for volume:
Vol[34|vm=28|DATADISK] under cluster: 1
2015-01-10 13:45:22,657 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) No suitable pools found
2015-01-10 13:45:22,657 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) No suitable storagePools found under this Cluster: 1
2015-01-10 13:45:22,657 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-38) Could not find suitable Deployment Destination for
this VM under any clusters, returning.
2015-01-10 13:45:22,661 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-8:job-38) Destroying vm
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65] as it failed to create on Host
with Id:null
2015-01-10 13:45:22,689 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-38) 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
2015-01-10 13:45:22,885 INFO [user.vm.DeployVMCmd] (Job-Executor-8:job-38)
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-01-10 13:45:22,885 INFO [user.vm.DeployVMCmd] (Job-Executor-8:job-38)
Unable to create a deployment for
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]Scope=interface
com.cloud.dc.DataCenter; id=1
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.reserveVirtualMachine(VMEntityManagerImpl.java:186)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.reserve(VirtualMachineEntityImpl.java:198)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3870)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
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.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-01-10 13:45:22,886 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-38) Complete async job-38, jobStatus: 2, resultCode:
530, result: Error Code: 533 Error text: Unable to create a deployment for
VM[User|edc76e44-7263-4a55-8c7d-d9dfcc3f5b65]
2015-01-10 13:45:23,237 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:23,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:23,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:24,750 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:24,750 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:24,751 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:25,033 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 3-517: Processing Seq 3-517: { Cmd ,
MgmtId: -1, via: 3, Ver: v1, Flags: 11,
[{"ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2015-01-10 13:45:25,047 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 3-517: Sending Seq 3-517: { Ans: ,
MgmtId: 129899290224676, via: 3, Ver: v1, Flags: 100010,
[{"AgentControlAnswer":{"result":true,"wait":0}}] }
2015-01-10 13:45:25,435 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null)
===START=== 192.168.0.2 -- GET
command=queryAsyncJobResult&jobId=732ab86a-35a2-4c42-ad2b-dcfac61b38a4&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420865126085
2015-01-10 13:45:25,463 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-15:null) Async job-38 completed
2015-01-10 13:45:25,476 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null)
===END=== 192.168.0.2 -- GET
command=queryAsyncJobResult&jobId=732ab86a-35a2-4c42-ad2b-dcfac61b38a4&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420865126085
2015-01-10 13:45:25,483 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
===START=== 192.168.0.2 -- GET
command=listVirtualMachines&id=edc76e44-7263-4a55-8c7d-d9dfcc3f5b65&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420865126133
2015-01-10 13:45:25,529 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
===END=== 192.168.0.2 -- GET
command=listVirtualMachines&id=edc76e44-7263-4a55-8c7d-d9dfcc3f5b65&response=json&sessionkey=s8ySfW8NWUOdK%2B%2BsZ1xdIh1ZkyM%3D&_=1420865126133
2015-01-10 13:45:25,848 DEBUG [cloud.server.StatsCollector]
(StatsCollector-3:null) StorageCollector is running...
2015-01-10 13:45:25,922 DEBUG [agent.transport.Request]
(StatsCollector-3:null) Seq 4-1496383559: Received: { Ans: , MgmtId:
129899290224676, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2015-01-10 13:45:26,001 DEBUG [agent.transport.Request]
(StatsCollector-3:null) Seq 1-1362886802: Received: { Ans: , MgmtId:
129899290224676, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2015-01-10 13:45:26,250 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:26,251 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:26,251 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:26,752 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2015-01-10 13:45:27,374 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2015-01-10 13:45:27,738 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:27,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:27,738 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:27,793 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2015-01-10 13:45:27,796 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2015-01-10 13:45:27,829 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2015-01-10 13:45:27,832 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2015-01-10 13:45:27,922 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Running Capacity Checker ...
2015-01-10 13:45:27,923 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) recalculating system capacity
2015-01-10 13:45:27,923 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing cpu/ram capacity update
2015-01-10 13:45:27,943 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 3 VMs on host 1
2015-01-10 13:45:27,944 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 0 VM, not running on host 1
2015-01-10 13:45:27,948 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu:
1500 reservedCpu: 0
2015-01-10 13:45:27,948 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem:
1476395008 reservedMem: 0
2015-01-10 13:45:27,948 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing cpu/ram capacity update
2015-01-10 13:45:27,948 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing storage capacity update
2015-01-10 13:45:27,966 DEBUG [cloud.storage.StorageManagerImpl]
(CapacityChecker:null) Successfully set Capacity - 1048881356800 for
capacity type - 9 , DataCenterId - 1, HostOrPoolId - 200, PodId 1
2015-01-10 13:45:27,966 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing storage capacity update
2015-01-10 13:45:27,966 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing capacity updates for public ip and Vlans
2015-01-10 13:45:27,996 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done capacity updates for public ip and Vlans
2015-01-10 13:45:27,997 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing capacity updates for private ip
2015-01-10 13:45:28,014 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing capacity updates for private ip
2015-01-10 13:45:28,014 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done recalculating system capacity
2015-01-10 13:45:28,058 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done running Capacity Checker ...
2015-01-10 13:45:28,298 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-12:null) Ping from 3
2015-01-10 13:45:29,238 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:29,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:29,238 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:30,751 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:30,751 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:30,752 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
2015-01-10 13:45:32,251 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Detected management node left, id:2,
nodeIP:192.168.0.10
2015-01-10 13:45:32,251 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Trying to connect to 192.168.0.10
2015-01-10 13:45:32,252 INFO [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management node 2 is detected inactive by
timestamp but is pingable
^C
[root ＠ cloud ~]#
VMを削除したことで使える容量は増えたようですが、
テンプレートからCentOS5.5をデプロイしようとすると、
継続してErrorが出る状態となっております。
なお、過去のMLに、仮想化の有効化について記載がありましたので、
BIOS上であらためて確認したところenabledでした。
また、カーネルモジュールも表示されておりました。
[root ＠ cloud ~]# lsmod | grep kvm
kvm_amd 40735 9
kvm 337772 1 kvm_amd
ここで詰まっている状況となります。
users メーリングリストの案内