cloudstack-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Bjoern Teipel <bjoern.tei...@gmail.com>
Subject 4.2.1: CLVM deployment stopped working after adding new primary storage
Date Mon, 13 Jan 2014 06:04:18 GMT
Hi guys,

I suddenly can't deploy a VM anymore after adding a new volume group (CLVM)
.

I can't find any error at the hypervisor agent, SSVM which leads me to the
problem.

Please help.

I'm using a 4.2.1 build by the way.

Thanks,
Bjoern

2014-01-12 21:51:53,655 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Failed
to start instance VM[User|testdb]

*java.lang.RuntimeException: InvocationTargetException when invoking RPC
callback for command: createVolumeFromBaseImageCallBack*
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
        at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
        at
org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.copyAsync(CloudStackPrimaryDataStoreDriverImpl.java:207)
        at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:49)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageAsync(VolumeServiceImpl.java:517)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:579)
        at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2577)
        at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2641)
        at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
        at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
        at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
        at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3440)
        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.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:744)
Caused by: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
        ... 28 more
Caused by: java.lang.NullPointerException
        at
org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:487)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageCallBack(VolumeServiceImpl.java:531)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        ... 32 more

2014-01-12 21:51:19,147 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-3:null) SeqA 14-47251: Processing Seq 14-47251:  {
Cmd , MgmtId: -1, via: 14, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":103,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
2014-01-12 21:51:19,150 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-3:null) SeqA 14-47251: Sending Seq 14-47251:  { Ans:
, MgmtId: 110493003717, via: 14, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:22,690 DEBUG [cloud.api.ApiServlet]
(catalina-exec-16:null) ===START===  10.19.241.61 -- GET
 command=listZones&available=true&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592282600
2014-01-12 21:51:22,701 DEBUG [cloud.api.ApiServlet]
(catalina-exec-16:null) ===END===  10.19.241.61 -- GET
 command=listZones&available=true&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592282600
2014-01-12 21:51:24,148 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-7:null) SeqA 14-47252: Processing Seq 14-47252:  {
Cmd , MgmtId: -1, via: 14, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":103,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
2014-01-12 21:51:24,150 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-7:null) SeqA 14-47252: Sending Seq 14-47252:  { Ans:
, MgmtId: 110493003717, via: 14, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:24,247 DEBUG [cloud.api.ApiServlet]
(catalina-exec-11:null) ===START===  10.19.241.61 -- GET
 command=listHypervisors&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284191
2014-01-12 21:51:24,256 DEBUG [cloud.api.ApiServlet]
(catalina-exec-11:null) ===END===  10.19.241.61 -- GET
 command=listHypervisors&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284191
2014-01-12 21:51:24,291 DEBUG [cloud.api.ApiServlet]
(catalina-exec-17:null) ===START===  10.19.241.61 -- GET
 command=listTemplates&templatefilter=featured&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284236
2014-01-12 21:51:24,301 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-17:null) Access granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] to Domain:2/Martindale/ by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:24,313 DEBUG [cloud.api.ApiServlet]
(catalina-exec-17:null) ===END===  10.19.241.61 -- GET
 command=listTemplates&templatefilter=featured&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284236
2014-01-12 21:51:24,350 DEBUG [cloud.api.ApiServlet]
(catalina-exec-15:null) ===START===  10.19.241.61 -- GET
 command=listTemplates&templatefilter=community&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284295
2014-01-12 21:51:24,360 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-15:null) Access granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] to Domain:2/Martindale/ by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:24,372 DEBUG [cloud.api.ApiServlet]
(catalina-exec-15:null) ===END===  10.19.241.61 -- GET
 command=listTemplates&templatefilter=community&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284295
2014-01-12 21:51:24,409 DEBUG [cloud.api.ApiServlet]
(catalina-exec-19:null) ===START===  10.19.241.61 -- GET
 command=listTemplates&templatefilter=selfexecutable&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284354
2014-01-12 21:51:24,418 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-19:null) Access granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] to Domain:2/Martindale/ by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:24,428 DEBUG [cloud.api.ApiServlet]
(catalina-exec-19:null) ===END===  10.19.241.61 -- GET
 command=listTemplates&templatefilter=selfexecutable&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592284354
2014-01-12 21:51:28,887 DEBUG [cloud.api.ApiServlet]
(catalina-exec-24:null) ===START===  10.19.241.61 -- GET
 command=listServiceOfferings&issystem=false&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592288828
2014-01-12 21:51:28,909 DEBUG [cloud.api.ApiServlet]
(catalina-exec-24:null) ===END===  10.19.241.61 -- GET
 command=listServiceOfferings&issystem=false&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592288828
2014-01-12 21:51:29,125 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) Ping from 8
2014-01-12 21:51:29,148 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 14-47253: Processing Seq 14-47253:  {
Cmd , MgmtId: -1, via: 14, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":103,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
2014-01-12 21:51:29,150 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 14-47253: Sending Seq 14-47253:  { Ans:
, MgmtId: 110493003717, via: 14, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:31,128 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2014-01-12 21:51:31,398 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2014-01-12 21:51:32,525 DEBUG [cloud.api.ApiServlet]
(catalina-exec-21:null) ===START===  10.19.241.61 -- GET
 command=listDiskOfferings&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592292468
2014-01-12 21:51:32,539 DEBUG [cloud.api.ApiServlet]
(catalina-exec-21:null) ===END===  10.19.241.61 -- GET
 command=listDiskOfferings&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592292468
2014-01-12 21:51:33,570 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-01-12 21:51:33,571 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-01-12 21:51:34,006 DEBUG [cloud.api.ApiServlet]
(catalina-exec-18:null) ===START===  10.19.241.61 -- GET
 command=listAffinityGroups&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592293939
2014-01-12 21:51:34,032 DEBUG [cloud.api.ApiServlet]
(catalina-exec-18:null) ===END===  10.19.241.61 -- GET
 command=listAffinityGroups&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592293939
2014-01-12 21:51:36,418 DEBUG [cloud.api.ApiServlet]
(catalina-exec-25:null) ===START===  10.19.241.61 -- GET
 command=listVPCs&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592296363
2014-01-12 21:51:36,426 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-25:null) Access granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] to Domain:2/Martindale/ by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:36,429 DEBUG [cloud.api.ApiServlet]
(catalina-exec-25:null) ===END===  10.19.241.61 -- GET
 command=listVPCs&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592296363
2014-01-12 21:51:36,464 DEBUG [cloud.api.ApiServlet]
(catalina-exec-20:null) ===START===  10.19.241.61 -- GET
 command=listNetworks&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&zoneId=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&canusefordeploy=true&_=1389592296410
2014-01-12 21:51:36,474 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-20:null) Access granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] to Domain:2/Martindale/ by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:36,495 DEBUG [cloud.api.ApiServlet]
(catalina-exec-20:null) ===END===  10.19.241.61 -- GET
 command=listNetworks&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&zoneId=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&canusefordeploy=true&_=1389592296410
2014-01-12 21:51:36,536 DEBUG [cloud.api.ApiServlet]
(catalina-exec-22:null) ===START===  10.19.241.61 -- GET
 command=listNetworkOfferings&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&forvpc=false&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&guestiptype=Isolated&supportedServices=SourceNat&specifyvlan=false&state=Enabled&_=1389592296480
2014-01-12 21:51:36,578 DEBUG [cloud.api.ApiServlet]
(catalina-exec-22:null) ===END===  10.19.241.61 -- GET
 command=listNetworkOfferings&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&forvpc=false&zoneid=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&guestiptype=Isolated&supportedServices=SourceNat&specifyvlan=false&state=Enabled&_=1389592296480
2014-01-12 21:51:39,150 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-11:null) SeqA 14-47254: Processing Seq 14-47254:  {
Cmd , MgmtId: -1, via: 14, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":103,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
2014-01-12 21:51:39,153 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-11:null) SeqA 14-47254: Sending Seq 14-47254:  { Ans:
, MgmtId: 110493003717, via: 14, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:44,151 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 14-47255: Processing Seq 14-47255:  {
Cmd , MgmtId: -1, via: 14, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":103,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
2014-01-12 21:51:44,153 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 14-47255: Sending Seq 14-47255:  { Ans:
, MgmtId: 110493003717, via: 14, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:48,833 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) Ping from 7
2014-01-12 21:51:49,151 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-10:null) SeqA 14-47256: Processing Seq 14-47256:  {
Cmd , MgmtId: -1, via: 14, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":103,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
2014-01-12 21:51:49,153 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-10:null) SeqA 14-47256: Sending Seq 14-47256:  { Ans:
, MgmtId: 110493003717, via: 14, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:49,818 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) VmStatsCollector is running...
2014-01-12 21:51:50,763 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 1-548405332: Received:  { Ans: , MgmtId:
110493003717, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-01-12 21:51:51,413 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 5-232063058: Received:  { Ans: , MgmtId:
110493003717, via: 5, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-01-12 21:51:51,998 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 6-890044504: Received:  { Ans: , MgmtId:
110493003717, via: 6, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-01-12 21:51:52,153 DEBUG [cloud.api.ApiServlet]
(catalina-exec-23:null) ===START===  10.19.241.61 -- GET
 command=deployVirtualMachine&zoneId=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&templateId=23bf3947-b667-4a7f-b702-2093c3c06288&hypervisor=KVM&serviceOfferingId=abdf4931-ffc5-43db-a7f1-f250fe23730f&affinitygroupids=dccbd331-a2bf-454c-bd24-b5fd553f7bf4&networkIds=e19a475d-fa98-4b60-bf9d-9fe1140d6ca8&displayname=testdb&name=testdb&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592312098
2014-01-12 21:51:52,160 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-23:null) InfrastructureEntity name
is:com.cloud.offering.ServiceOffering
2014-01-12 21:51:52,167 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-23:null) ControlledEntity name
is:com.cloud.template.VirtualMachineTemplate
2014-01-12 21:51:52,171 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-23:null) ControlledEntity name is:com.cloud.network.Network
2014-01-12 21:51:52,176 DEBUG [cloud.api.ApiDispatcher]
(catalina-exec-23:null) ControlledEntity name
is:org.apache.cloudstack.affinity.AffinityGroup
2014-01-12 21:51:52,178 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
Acct[e52653d8-8ca3-4134-b2b8-eb1727044e8a-PrjAcct-Martindale-2] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,179 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
Acct[e52653d8-8ca3-4134-b2b8-eb1727044e8a-PrjAcct-Martindale-2] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,183 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to Ntwk[204|Guest|15] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,185 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
Tmpl[212-QCOW2-9c6bfb0f-ce64-464e-a651-e5b8af55d629 granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,186 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
AffinityGroup[dccbd331-a2bf-454c-bd24-b5fd553f7bf4] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:52,189 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
Acct[e52653d8-8ca3-4134-b2b8-eb1727044e8a-PrjAcct-Martindale-2] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,195 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
Acct[e52653d8-8ca3-4134-b2b8-eb1727044e8a-PrjAcct-Martindale-2] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,228 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
Acct[e52653d8-8ca3-4134-b2b8-eb1727044e8a-PrjAcct-Martindale-2] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,229 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-23:null) Access to
AffinityGroup[dccbd331-a2bf-454c-bd24-b5fd553f7bf4] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:52,232 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-23:null) Service SecurityGroup is not supported in the
network id=204
2014-01-12 21:51:52,249 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-23:null) Allocating in the DB for vm
2014-01-12 21:51:52,261 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-23:null) Allocating entries for VM: VM[User|testdb]
2014-01-12 21:51:52,262 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-23:null) Allocating nics for VM[User|testdb]
2014-01-12 21:51:52,263 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-23:null) Allocating nic for vm VM[User|testdb] in network
Ntwk[204|Guest|15] with requested profile NicProfile[0-0-null-null-null
 2014-01-12 21:51:52,281 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-23:null) Service SecurityGroup is not supported in the
network id=204
2014-01-12 21:51:52,282 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-23:null) Allocating disks for VM[User|testdb]
2014-01-12 21:51:52,294 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-23:null) Allocation completed for VM: VM[User|testdb]
2014-01-12 21:51:52,294 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-23:null) Successfully allocated DB entry for VM[User|testdb]
2014-01-12 21:51:52,320 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-23:null) Service SecurityGroup is not supported in the
network id=204
2014-01-12 21:51:52,323 DEBUG [cloud.network.NetworkModelImpl]
(catalina-exec-23:null) Service SecurityGroup is not supported in the
network id=204
2014-01-12 21:51:52,341 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-23:null) submit async job-752 = [
80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ], details: AsyncJobVO {id:752,
userId: 4, accountId: 4, sessionKey: null, instanceType: VirtualMachine,
instanceId: 127, cmd:
org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator: null,
cmdInfo:
{"sessionkey":"zxWC3aIZAYTqQDJ0WR9yZuT6/vM\u003d","cmdEventType":"VM.CREATE","ctxUserId":"4","serviceOfferingId":"abdf4931-ffc5-43db-a7f1-f250fe23730f","affinitygroupids":"dccbd331-a2bf-454c-bd24-b5fd553f7bf4","httpmethod":"GET","zoneId":"1cbf8216-d7d0-4286-829c-bff2e91ac4ad","id":"127","templateId":"23bf3947-b667-4a7f-b702-2093c3c06288","response":"json","networkIds":"e19a475d-fa98-4b60-bf9d-9fe1140d6ca8","hypervisor":"KVM","name":"testdb","projectid":"a98b95ee-1eba-44f1-a714-00254ec068c5","_":"1389592312098","ctxAccountId":"4","ctxStartEventId":"3165","displayname":"testdb"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 110493003717,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-01-12 21:51:52,343 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-752
= [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
2014-01-12 21:51:52,344 DEBUG [cloud.api.ApiServlet]
(catalina-exec-23:null) ===END===  10.19.241.61 -- GET
 command=deployVirtualMachine&zoneId=1cbf8216-d7d0-4286-829c-bff2e91ac4ad&templateId=23bf3947-b667-4a7f-b702-2093c3c06288&hypervisor=KVM&serviceOfferingId=abdf4931-ffc5-43db-a7f1-f250fe23730f&affinitygroupids=dccbd331-a2bf-454c-bd24-b5fd553f7bf4&networkIds=e19a475d-fa98-4b60-bf9d-9fe1140d6ca8&displayname=testdb&name=testdb&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592312098
2014-01-12 21:51:52,349 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
InfrastructureEntity name is:com.cloud.offering.ServiceOffering
2014-01-12 21:51:52,351 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ControlledEntity name is:com.cloud.template.VirtualMachineTemplate
2014-01-12 21:51:52,354 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ControlledEntity name is:com.cloud.network.Network
2014-01-12 21:51:52,358 DEBUG [cloud.api.ApiDispatcher]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ControlledEntity name is:org.apache.cloudstack.affinity.AffinityGroup
2014-01-12 21:51:52,361 DEBUG [cloud.user.AccountManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Access
to Acct[e52653d8-8ca3-4134-b2b8-eb1727044e8a-PrjAcct-Martindale-2] granted
to Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,362 DEBUG [cloud.user.AccountManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Access
to Acct[e52653d8-8ca3-4134-b2b8-eb1727044e8a-PrjAcct-Martindale-2] granted
to Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,366 DEBUG [cloud.user.AccountManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Access
to Ntwk[204|Guest|15] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,367 DEBUG [cloud.user.AccountManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Access
to Tmpl[212-QCOW2-9c6bfb0f-ce64-464e-a651-e5b8af55d629 granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,368 DEBUG [cloud.user.AccountManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Access
to AffinityGroup[dccbd331-a2bf-454c-bd24-b5fd553f7bf4] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:52,376 DEBUG [cloud.user.AccountManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Access
to VM[User|testdb] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:52,388 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:52,392 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:52,404 DEBUG
[cloudstack.affinity.ExplicitDedicationProcessor] (Job-Executor-13:job-752
= [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Processing affinity group 2of
type 'ExplicitDedication' for VM Id: 127
2014-01-12 21:51:52,416 DEBUG
[cloudstack.affinity.ExplicitDedicationProcessor] (Job-Executor-13:job-752
= [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) ExplicitDedicationProcessor
returns Avoid List as: Deploy avoids pods: null, clusters: null, hosts: null
2014-01-12 21:51:52,418 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Deploy
avoids pods: null, clusters: null, hosts: null
2014-01-12 21:51:52,420 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
DeploymentPlanner allocation algorithm:
com.cloud.deploy.UserDispersingPlanner_EnhancerByCloudStack_a25cf044@79028b24
2014-01-12 21:51:52,420 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to allocate a host and storage pools from dc:1, pod:null,cluster:null,
requested cpu: 13200, requested ram: 51539607552
2014-01-12 21:51:52,420 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Is
ROOT volume READY (pool already allocated)?: No
2014-01-12 21:51:52,420 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Searching all possible resources under this Zone: 1
2014-01-12 21:51:52,421 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Listing clusters in order of aggregate capacity, that have (atleast one
host with) enough CPU and RAM capacity under this Zone: 1
2014-01-12 21:51:52,432 DEBUG [cloud.deploy.UserDispersingPlanner]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Applying Userdispersion heuristic to clusters for account: 7
2014-01-12 21:51:52,435 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking resources in Cluster: 1 under Pod: 1
2014-01-12 21:51:52,436 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2014-01-12 21:51:52,440 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) FirstFitAllocator has 6 hosts to check for
allocation: [Host[-15-Routing], Host[-6-Routing], Host[-8-Routing],
Host[-5-Routing], Host[-1-Routing], Host[-7-Routing]]
2014-01-12 21:51:52,446 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Found 6 hosts for allocation after
prioritization: [Host[-15-Routing], Host[-6-Routing], Host[-8-Routing],
Host[-5-Routing], Host[-1-Routing], Host[-7-Routing]]
2014-01-12 21:51:52,446 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Looking for speed=13200Mhz, Ram=49152
2014-01-12 21:51:52,451 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 15 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:52,454 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 46384 and CPU after
applying overprovisioning: 371072
2014-01-12 21:51:52,454 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 371072 , Requested CPU: 13200
2014-01-12 21:51:52,454 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 203056644096 , Requested RAM:
51539607552
2014-01-12 21:51:52,454 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-01-12 21:51:52,454 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 15, used: 0,
reserved: 0, actual total: 46384, total with overprovisioning: 371072;
requested cpu:13200,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-01-12 21:51:52,454 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 15, used: 0,
reserved: 0, total: 203056644096; requested mem:
51539607552,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-01-12 21:51:52,454 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Found a suitable host, adding to list: 15
2014-01-12 21:51:52,460 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 6 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:52,462 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38384 and CPU after
applying overprovisioning: 307072
2014-01-12 21:51:52,462 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 169072 , Requested CPU: 13200
2014-01-12 21:51:52,462 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 40921628672 , Requested RAM: 51539607552
2014-01-12 21:51:52,462 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 6
reservedCpu: 0, used cpu: 138000, requested cpu: 13200, actual total cpu:
38384, total cpu with overprovisioning: 307072, reservedMem: 0, used Mem:
162135015424, requested mem: 51539607552, total Mem:203056644096
,considerReservedCapacity?: true
2014-01-12 21:51:52,462 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host does not have enough RAM available, cannot
allocate to this host.
2014-01-12 21:51:52,462 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Not using host 6; numCpusGood: true; cpuFreqGood:
true, host has capacity?false
2014-01-12 21:51:52,467 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 8 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:52,470 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38384 and CPU after
applying overprovisioning: 307072
2014-01-12 21:51:52,470 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 307072 , Requested CPU: 13200
2014-01-12 21:51:52,470 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 203056644096 , Requested RAM:
51539607552
2014-01-12 21:51:52,470 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-01-12 21:51:52,470 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 8, used: 0,
reserved: 0, actual total: 38384, total with overprovisioning: 307072;
requested cpu:13200,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-01-12 21:51:52,470 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 8, used: 0,
reserved: 0, total: 203056644096; requested mem:
51539607552,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-01-12 21:51:52,470 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Found a suitable host, adding to list: 8
2014-01-12 21:51:52,475 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 5 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:52,478 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38400 and CPU after
applying overprovisioning: 307200
2014-01-12 21:51:52,478 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 195700 , Requested CPU: 13200
2014-01-12 21:51:52,478 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 2266923008 , Requested RAM: 51539607552
2014-01-12 21:51:52,478 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 5
reservedCpu: 0, used cpu: 111500, requested cpu: 13200, actual total cpu:
38400, total cpu with overprovisioning: 307200, reservedMem: 0, used Mem:
200789721088, requested mem: 51539607552, total Mem:203056644096
,considerReservedCapacity?: true
2014-01-12 21:51:52,478 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host does not have enough RAM available, cannot
allocate to this host.
2014-01-12 21:51:52,478 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Not using host 5; numCpusGood: true; cpuFreqGood:
true, host has capacity?false
2014-01-12 21:51:52,484 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:52,486 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 46384 and CPU after
applying overprovisioning: 371072
2014-01-12 21:51:52,486 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 186272 , Requested CPU: 13200
2014-01-12 21:51:52,486 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 22668017664 , Requested RAM: 51539607552
2014-01-12 21:51:52,486 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 1
reservedCpu: 0, used cpu: 184800, requested cpu: 13200, actual total cpu:
46384, total cpu with overprovisioning: 371072, reservedMem: 0, used Mem:
180388626432, requested mem: 51539607552, total Mem:203056644096
,considerReservedCapacity?: true
2014-01-12 21:51:52,486 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host does not have enough RAM available, cannot
allocate to this host.
2014-01-12 21:51:52,486 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Not using host 1; numCpusGood: true; cpuFreqGood:
true, host has capacity?false
2014-01-12 21:51:52,491 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:52,493 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38400 and CPU after
applying overprovisioning: 307200
2014-01-12 21:51:52,494 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 307200 , Requested CPU: 13200
2014-01-12 21:51:52,494 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 203056644096 , Requested RAM:
51539607552
2014-01-12 21:51:52,494 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-01-12 21:51:52,494 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 0,
reserved: 0, actual total: 38400, total with overprovisioning: 307200;
requested cpu:13200,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-01-12 21:51:52,494 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used: 0,
reserved: 0, total: 203056644096; requested mem:
51539607552,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-01-12 21:51:52,494 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
2014-01-12 21:51:52,494 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host Allocator returning 3 suitable hosts
2014-01-12 21:51:52,495 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking suitable pools for volume (Id, Type): (191,ROOT)
2014-01-12 21:51:52,495 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) We
need to allocate new storagepool for this volume
2014-01-12 21:51:52,496 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Calling StoragePoolAllocators to find suitable pools
2014-01-12 21:51:52,497 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-01-12 21:51:52,497 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ClusterScopeStoragePoolAllocator looking for storage pool
 2014-01-12 21:51:52,497 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Looking for pools in dc: 1  pod:1  cluster:1 having tags:[nas, ssd, vdi]
2014-01-12 21:51:52,502 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 3
2014-01-12 21:51:52,506 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool 3 for storage, totalSize: 1073737629696, usedBytes:
891205713920, usedPct: 0.8300032422001649, disable threshold: 0.85
2014-01-12 21:51:52,521 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool: 3 for volume allocation [Vol[191|vm=127|ROOT]], maxSize :
1073737629696, totalAllocatedSize : 891205713920, askingSize : 80530636800,
allocated disable threshold: 0.85
2014-01-12 21:51:52,521 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Insufficient un-allocated capacity on: 3 for volume allocation:
[Vol[191|vm=127|ROOT]] since its allocated percentage: 0.9050035351700593
has crossed the allocated pool.storage.allocated.capacity.disablethreshold:
0.85, skipping this pool
2014-01-12 21:51:52,522 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 11
2014-01-12 21:51:52,526 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool 11 for storage, totalSize: 1099507433472, usedBytes:
912680550400, usedPct: 0.8300812915088329, disable threshold: 0.85
2014-01-12 21:51:52,538 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool: 11 for volume allocation [Vol[191|vm=127|ROOT]], maxSize :
1099507433472, totalAllocatedSize : 912680550400, askingSize : 80530636800,
allocated disable threshold: 0.85
2014-01-12 21:51:52,538 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Insufficient un-allocated capacity on: 11 for volume allocation:
[Vol[191|vm=127|ROOT]] since its allocated percentage: 0.9033237584066711
has crossed the allocated pool.storage.allocated.capacity.disablethreshold:
0.85, skipping this pool
2014-01-12 21:51:52,539 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 13
2014-01-12 21:51:52,543 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool 13 for storage, totalSize: 1099507433472, usedBytes: 0,
usedPct: 0.0, disable threshold: 0.85
2014-01-12 21:51:52,551 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool: 13 for volume allocation [Vol[191|vm=127|ROOT]], maxSize :
1099507433472, totalAllocatedSize : 0, askingSize : 80530636800, allocated
disable threshold: 0.85
2014-01-12 21:51:52,551 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-01-12 21:51:52,552 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2014-01-12 21:51:52,552 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking if host: 15 can access any suitable storage pool for volume: ROOT
2014-01-12 21:51:52,553 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Host:
15 can access pool: 13
2014-01-12 21:51:52,555 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Found
a potential host id: 15 name: hv-b1dkcy1.lax1.uw1.ibcloud.local and
associated storage pools for this VM
2014-01-12 21:51:52,557 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
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(15)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:52,571 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM
state transitted from :Stopped to Starting with event: StartRequestedvm's
original host id: null new host id: null host id before state transition:
null
2014-01-12 21:51:52,572 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Successfully transitioned to start state for VM[User|testdb] reservation id
= 6ab0c37f-21b5-4c3b-8533-7121db52be68
2014-01-12 21:51:52,574 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to deploy VM, vm has dcId: 1 and podId: null
2014-01-12 21:51:52,574 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1,
clusterId: 1, hostId: 15, poolId: null
2014-01-12 21:51:52,574 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Deploy
avoids pods: null, clusters: null, hosts: null
2014-01-12 21:51:52,577 DEBUG
[cloudstack.affinity.ExplicitDedicationProcessor] (Job-Executor-13:job-752
= [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Processing affinity group 2of
type 'ExplicitDedication' for VM Id: 127
2014-01-12 21:51:52,581 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Deploy
avoids pods: null, clusters: null, hosts: null
2014-01-12 21:51:52,582 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
DeploymentPlanner allocation algorithm:
com.cloud.deploy.UserDispersingPlanner_EnhancerByCloudStack_a25cf044@79028b24
2014-01-12 21:51:52,582 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested
cpu: 13200, requested ram: 51539607552
2014-01-12 21:51:52,582 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Is
ROOT volume READY (pool already allocated)?: No
2014-01-12 21:51:52,582 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
DeploymentPlan has host_id specified, choosing this host and making no
checks on this host: 15
2014-01-12 21:51:52,583 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2014-01-12 21:51:52,585 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking suitable pools for volume (Id, Type): (191,ROOT)
2014-01-12 21:51:52,585 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) We
need to allocate new storagepool for this volume
2014-01-12 21:51:52,585 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Calling StoragePoolAllocators to find suitable pools
2014-01-12 21:51:52,586 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-01-12 21:51:52,586 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ClusterScopeStoragePoolAllocator looking for storage pool
 2014-01-12 21:51:52,586 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Looking for pools in dc: 1  pod:1  cluster:1 having tags:[nas, ssd, vdi]
2014-01-12 21:51:52,589 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 3
2014-01-12 21:51:52,593 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool 3 for storage, totalSize: 1073737629696, usedBytes:
891205713920, usedPct: 0.8300032422001649, disable threshold: 0.85
2014-01-12 21:51:52,607 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool: 3 for volume allocation [Vol[191|vm=127|ROOT]], maxSize :
1073737629696, totalAllocatedSize : 891205713920, askingSize : 80530636800,
allocated disable threshold: 0.85
2014-01-12 21:51:52,607 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Insufficient un-allocated capacity on: 3 for volume allocation:
[Vol[191|vm=127|ROOT]] since its allocated percentage: 0.9050035351700593
has crossed the allocated pool.storage.allocated.capacity.disablethreshold:
0.85, skipping this pool
2014-01-12 21:51:52,608 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 11
2014-01-12 21:51:52,612 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool 11 for storage, totalSize: 1099507433472, usedBytes:
912680550400, usedPct: 0.8300812915088329, disable threshold: 0.85
2014-01-12 21:51:52,623 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool: 11 for volume allocation [Vol[191|vm=127|ROOT]], maxSize :
1099507433472, totalAllocatedSize : 912680550400, askingSize : 80530636800,
allocated disable threshold: 0.85
2014-01-12 21:51:52,623 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Insufficient un-allocated capacity on: 11 for volume allocation:
[Vol[191|vm=127|ROOT]] since its allocated percentage: 0.9033237584066711
has crossed the allocated pool.storage.allocated.capacity.disablethreshold:
0.85, skipping this pool
2014-01-12 21:51:52,624 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 13
2014-01-12 21:51:52,627 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool 13 for storage, totalSize: 1099507433472, usedBytes: 0,
usedPct: 0.0, disable threshold: 0.85
2014-01-12 21:51:52,635 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool: 13 for volume allocation [Vol[191|vm=127|ROOT]], maxSize :
1099507433472, totalAllocatedSize : 0, askingSize : 80530636800, allocated
disable threshold: 0.85
2014-01-12 21:51:52,635 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-01-12 21:51:52,635 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2014-01-12 21:51:52,635 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking if host: 15 can access any suitable storage pool for volume: ROOT
2014-01-12 21:51:52,636 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Host:
15 can access pool: 13
2014-01-12 21:51:52,637 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Found
a potential host id: 15 name: hv-b1dkcy1.lax1.uw1.ibcloud.local and
associated storage pools for this VM
2014-01-12 21:51:52,638 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
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(15)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:52,638 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Deployment found  - P0=VM[User|testdb],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(1)-Pod(1)-Cluster(1)-Host(15)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:52,652 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM
state transitted from :Starting to Starting with event: OperationRetryvm's
original host id: null new host id: 15 host id before state transition: null
2014-01-12 21:51:52,660 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Hosts's actual total CPU: 46384 and CPU after applying overprovisioning:
371072
2014-01-12 21:51:52,660 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) We are
allocating VM, increasing the used capacity of this host:15
2014-01-12 21:51:52,660 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Current Used CPU: 0 , Free CPU:371072 ,Requested CPU: 13200
2014-01-12 21:51:52,660 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Current Used RAM: 0 , Free RAM:203056644096 ,Requested RAM: 51539607552
2014-01-12 21:51:52,660 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) CPU
STATS after allocation: for host: 15, old used: 0, old reserved: 0, actual
total: 46384, total with overprovisioning: 371072; new used:13200,
reserved:0; requested cpu:13200,alloc_from_last:false
2014-01-12 21:51:52,660 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) RAM
STATS after allocation: for host: 15, old used: 0, old reserved: 0, total:
203056644096; new used: 51539607552, reserved: 0; requested mem:
51539607552,alloc_from_last:false
2014-01-12 21:51:52,662 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM is
being created in podId: 1
2014-01-12 21:51:52,664 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Network id=204 is already implemented
2014-01-12 21:51:52,673 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:52,675 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Changing active number of nics for network id=204 on 1
2014-01-12 21:51:52,679 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Asking
F5BigIP to prepare for Nic[150-127-null-10.197.212.133]
2014-01-12 21:51:52,685 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Asking
VirtualRouter to prepare for Nic[150-127-null-10.197.212.133]
2014-01-12 21:51:52,693 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Lock
is acquired for network id 204 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(15)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:52,697 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Lock
is released for network id 204 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(15)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:52,703 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:52,714 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:52,717 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Applying dhcp entry in network Ntwk[204|Guest|15]
2014-01-12 21:51:52,733 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044505: Sending  { Cmd , MgmtId: 110493003717, via: 6, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:4e:98:00:01:27","vmIpAddress":"10.197.212.133","vmName":"testdb","defaultRouter":"10.197.212.1","defaultDns":"10.197.212.128","duid":"00:03:00:01:06:4e:98:00:01:27","isDefault":true,"executeInSequence":true,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.197.212.128","router.ip":"169.254.1.122","
router.name":"r-25-VM"},"wait":0}}] }
2014-01-12 21:51:52,960 DEBUG [agent.transport.Request]
(AgentManager-Handler-5:null) Seq 6-890044505: Processing:  { Ans: ,
MgmtId: 110493003717, via: 6, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-01-12 21:51:52,960 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044505: Received:  { Ans: , MgmtId: 110493003717, via: 6, Ver: v1,
Flags: 110, { Answer } }
2014-01-12 21:51:52,960 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-5:null) Seq 6-890044505: No more commands found
2014-01-12 21:51:52,967 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:52,970 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Applying userdata and password entry in network Ntwk[204|Guest|15]
2014-01-12 21:51:52,984 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044506: Sending  { Cmd , MgmtId: 110493003717, via: 6, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.197.212.133","vmName":"testdb","executeInSequence":true,"accessDetails":{"zone.network.type":"Advanced","
router.name
":"r-25-VM","router.ip":"169.254.1.122","router.guest.ip":"10.197.212.128"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.197.212.133","vmName":"testdb","executeInSequence":true,"accessDetails":{"zone.network.type":"Advanced","
router.name":"r-25-VM","router.ip":"169.254.1.122","router.guest.ip":"10.197.212.128"},"wait":0}}]
}
2014-01-12 21:51:53,471 DEBUG [agent.transport.Request]
(AgentManager-Handler-15:null) Seq 6-890044506: Processing:  { Ans: ,
MgmtId: 110493003717, via: 6, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}]
}
2014-01-12 21:51:53,471 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044506: Received:  { Ans: , MgmtId: 110493003717, via: 6, Ver: v1,
Flags: 110, { Answer, Answer } }
2014-01-12 21:51:53,471 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-15:null) Seq 6-890044506: No more commands found
2014-01-12 21:51:53,472 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:53,473 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking if we need to prepare 1 volumes for VM[User|testdb]
2014-01-12 21:51:53,480 DEBUG [storage.image.TemplateDataFactoryImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
template 212 is already in store:2, type:Image
2014-01-12 21:51:53,483 DEBUG [storage.image.TemplateDataFactoryImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
template 212 is already in store:13, type:Primary
2014-01-12 21:51:53,508 DEBUG [storage.image.TemplateDataFactoryImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
template 212 is already in store:2, type:Image
2014-01-12 21:51:53,517 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
1-548405333: Sending  { Cmd , MgmtId: 110493003717, via: 1, Ver: v1, Flags:
100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/4/212/9c6bfb0f-ce64-464e-a651-e5b8af55d629.qcow2","uuid":"23bf3947-b667-4a7f-b702-2093c3c06288","id":212,"format":"QCOW2","accountId":4,"hvm":true,"displayText":"Oracle
11.2.0.3.7 on
RHEL6","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://nas2-a-519.lax1.uw1.ibcloud.local/vol/cloud_sec_1","_role":"Image"}},"name":"9c6bfb0f-ce64-464e-a651-e5b8af55d629","hypervisorType":"KVM"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ca270592-751e-40ac-b73c-37ed2c30862f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1d1e7787-e1d9-4dbd-9046-0e124dffd770","id":13,"poolType":"CLVM","host":"localhost","path":"/vg_vmem-003a74_vdi3","port":0}},"name":"ROOT-127","size":80530636800,"volumeId":191,"vmName":"i-7-127-VM","accountId":7,"format":"QCOW2","id":191,"hypervisorType":"KVM"}},"executeInSequence":true,"wait":10800}}]
}
2014-01-12 21:51:53,654 DEBUG [agent.transport.Request]
(AgentManager-Handler-1:null) Seq 1-548405333: Processing:  { Ans: ,
MgmtId: 110493003717, via: 1, Ver: v1, Flags: 110,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException:
Can't find volume:9c6bfb0f-ce64-464e-a651-e5b8af55d629.qcow2","wait":0}}] }
2014-01-12 21:51:53,654 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-1:null) Seq 1-548405333: No more commands found
2014-01-12 21:51:53,654 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
1-548405333: Received:  { Ans: , MgmtId: 110493003717, via: 1, Ver: v1,
Flags: 110, { CopyCmdAnswer } }
2014-01-12 21:51:53,655 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Failed
to start instance VM[User|testdb]
*java.lang.RuntimeException: InvocationTargetException when invoking RPC
callback for command: createVolumeFromBaseImageCallBack*
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
        at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
        at
org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.copyAsync(CloudStackPrimaryDataStoreDriverImpl.java:207)
        at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:49)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageAsync(VolumeServiceImpl.java:517)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:579)
        at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2577)
        at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2641)
        at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
        at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
        at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
        at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3440)
        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.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:744)
Caused by: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
        ... 28 more
Caused by: java.lang.NullPointerException
        at
org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:487)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageCallBack(VolumeServiceImpl.java:531)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        ... 32 more
2014-01-12 21:51:53,663 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Cleaning up resources for the vm VM[User|testdb] in Starting state
2014-01-12 21:51:53,664 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
15-988282943: Sending  { Cmd , MgmtId: 110493003717, via: 15, Ver: v1,
Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-7-127-VM","wait":0}}]
}
2014-01-12 21:51:53,935 DEBUG [agent.transport.Request]
(AgentManager-Handler-6:null) Seq 15-988282943: Processing:  { Ans: ,
MgmtId: 110493003717, via: 15, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:53,935 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
15-988282943: Received:  { Ans: , MgmtId: 110493003717, via: 15, Ver: v1,
Flags: 110, { StopAnswer } }
2014-01-12 21:51:53,935 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-6:null) Seq 15-988282943: No more commands found
2014-01-12 21:51:53,942 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Changing active number of nics for network id=204 on -1
2014-01-12 21:51:53,944 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Successfully released network resources for the vm VM[User|testdb]
2014-01-12 21:51:53,944 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Successfully cleanued up resources for the vm VM[User|testdb] in Starting
state
2014-01-12 21:51:53,948 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM
state transitted from :Starting to Stopped with event: OperationFailedvm's
original host id: null new host id: null host id before state transition: 15
2014-01-12 21:51:53,954 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Hosts's actual total CPU: 46384 and CPU after applying overprovisioning:
371072
2014-01-12 21:51:53,954 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Hosts's actual total RAM: 203056635904 and RAM after applying
overprovisioning: 203056644096
2014-01-12 21:51:53,954 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
release cpu from host: 15, old used: 13200,reserved: 0, actual total:
46384, total with overprovisioning: 371072; new used: 0,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2014-01-12 21:51:53,954 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
release mem from host: 15, old used: 51539607552,reserved: 0, total:
203056644096; new used: 0,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2014-01-12 21:51:53,967 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM
state transitted from :Stopped to Starting with event: StartRequestedvm's
original host id: null new host id: null host id before state transition:
null
2014-01-12 21:51:53,968 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Successfully transitioned to start state for VM[User|testdb] reservation id
= 2de54f3b-c3a6-4eee-9f9b-7aeec07e2d7f
2014-01-12 21:51:53,970 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to deploy VM, vm has dcId: 1 and podId: 1
2014-01-12 21:51:53,970 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Deploy
avoids pods: null, clusters: null, hosts: [15]
2014-01-12 21:51:53,973 DEBUG
[cloudstack.affinity.ExplicitDedicationProcessor] (Job-Executor-13:job-752
= [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Processing affinity group 2of
type 'ExplicitDedication' for VM Id: 127
2014-01-12 21:51:53,977 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Deploy
avoids pods: null, clusters: null, hosts: [15]
2014-01-12 21:51:53,978 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
DeploymentPlanner allocation algorithm:
com.cloud.deploy.UserDispersingPlanner_EnhancerByCloudStack_a25cf044@79028b24
2014-01-12 21:51:53,978 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to allocate a host and storage pools from dc:1, pod:1,cluster:null,
requested cpu: 13200, requested ram: 51539607552
2014-01-12 21:51:53,978 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Is
ROOT volume READY (pool already allocated)?: No
2014-01-12 21:51:53,978 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Searching resources only under specified Pod: 1
2014-01-12 21:51:53,978 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Listing clusters in order of aggregate capacity, that have (atleast one
host with) enough CPU and RAM capacity under this Pod: 1
2014-01-12 21:51:53,989 DEBUG [cloud.deploy.UserDispersingPlanner]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Applying Userdispersion heuristic to clusters for account: 7
2014-01-12 21:51:53,991 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking resources in Cluster: 1 under Pod: 1
2014-01-12 21:51:53,991 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2014-01-12 21:51:53,995 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) FirstFitAllocator has 6 hosts to check for
allocation: [Host[-8-Routing], Host[-5-Routing], Host[-15-Routing],
Host[-6-Routing], Host[-1-Routing], Host[-7-Routing]]
2014-01-12 21:51:54,001 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Found 6 hosts for allocation after
prioritization: [Host[-8-Routing], Host[-5-Routing], Host[-15-Routing],
Host[-6-Routing], Host[-1-Routing], Host[-7-Routing]]
2014-01-12 21:51:54,001 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Looking for speed=13200Mhz, Ram=49152
2014-01-12 21:51:54,006 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 8 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:54,009 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38384 and CPU after
applying overprovisioning: 307072
2014-01-12 21:51:54,009 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 307072 , Requested CPU: 13200
2014-01-12 21:51:54,009 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 203056644096 , Requested RAM:
51539607552
2014-01-12 21:51:54,009 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-01-12 21:51:54,009 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 8, used: 0,
reserved: 0, actual total: 38384, total with overprovisioning: 307072;
requested cpu:13200,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-01-12 21:51:54,009 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 8, used: 0,
reserved: 0, total: 203056644096; requested mem:
51539607552,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-01-12 21:51:54,009 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Found a suitable host, adding to list: 8
2014-01-12 21:51:54,015 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 5 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:54,017 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38400 and CPU after
applying overprovisioning: 307200
2014-01-12 21:51:54,017 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 195700 , Requested CPU: 13200
2014-01-12 21:51:54,017 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 2266923008 , Requested RAM: 51539607552
2014-01-12 21:51:54,017 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 5
reservedCpu: 0, used cpu: 111500, requested cpu: 13200, actual total cpu:
38400, total cpu with overprovisioning: 307200, reservedMem: 0, used Mem:
200789721088, requested mem: 51539607552, total Mem:203056644096
,considerReservedCapacity?: true
2014-01-12 21:51:54,017 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host does not have enough RAM available, cannot
allocate to this host.
2014-01-12 21:51:54,017 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Not using host 5; numCpusGood: true; cpuFreqGood:
true, host has capacity?false
2014-01-12 21:51:54,017 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host name: hv-b1dkcy1.lax1.uw1.ibcloud.local,
hostId: 15 is in avoid set, skipping this and trying other available hosts
2014-01-12 21:51:54,023 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 6 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:54,025 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38384 and CPU after
applying overprovisioning: 307072
2014-01-12 21:51:54,025 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 169072 , Requested CPU: 13200
2014-01-12 21:51:54,025 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 40921628672 , Requested RAM: 51539607552
2014-01-12 21:51:54,025 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 6
reservedCpu: 0, used cpu: 138000, requested cpu: 13200, actual total cpu:
38384, total cpu with overprovisioning: 307072, reservedMem: 0, used Mem:
162135015424, requested mem: 51539607552, total Mem:203056644096
,considerReservedCapacity?: true
2014-01-12 21:51:54,025 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host does not have enough RAM available, cannot
allocate to this host.
2014-01-12 21:51:54,025 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Not using host 6; numCpusGood: true; cpuFreqGood:
true, host has capacity?false
2014-01-12 21:51:54,031 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:54,033 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 46384 and CPU after
applying overprovisioning: 371072
2014-01-12 21:51:54,033 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 186272 , Requested CPU: 13200
2014-01-12 21:51:54,033 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 22668017664 , Requested RAM: 51539607552
2014-01-12 21:51:54,033 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 1
reservedCpu: 0, used cpu: 184800, requested cpu: 13200, actual total cpu:
46384, total cpu with overprovisioning: 371072, reservedMem: 0, used Mem:
180388626432, requested mem: 51539607552, total Mem:203056644096
,considerReservedCapacity?: true
2014-01-12 21:51:54,033 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host does not have enough RAM available, cannot
allocate to this host.
2014-01-12 21:51:54,033 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Not using host 1; numCpusGood: true; cpuFreqGood:
true, host has capacity?false
2014-01-12 21:51:54,038 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for
requested CPU: 13200 and requested RAM: 51539607552 ,
cpuOverprovisioningFactor: 8.0
2014-01-12 21:51:54,041 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Hosts's actual total CPU: 38400 and CPU after
applying overprovisioning: 307200
2014-01-12 21:51:54,041 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free CPU: 307200 , Requested CPU: 13200
2014-01-12 21:51:54,041 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Free RAM: 203056644096 , Requested RAM:
51539607552
2014-01-12 21:51:54,041 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2014-01-12 21:51:54,041 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 0,
reserved: 0, actual total: 38400, total with overprovisioning: 307200;
requested cpu:13200,alloc_from_last_host?:false ,considerReservedCapacity?:
true
2014-01-12 21:51:54,041 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used: 0,
reserved: 0, total: 203056644096; requested mem:
51539607552,alloc_from_last_host?:false ,considerReservedCapacity?: true
2014-01-12 21:51:54,041 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
2014-01-12 21:51:54,041 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]
FirstFitRoutingAllocator) Host Allocator returning 2 suitable hosts
2014-01-12 21:51:54,042 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking suitable pools for volume (Id, Type): (191,ROOT)
2014-01-12 21:51:54,043 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) We
need to allocate new storagepool for this volume
2014-01-12 21:51:54,043 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Calling StoragePoolAllocators to find suitable pools
2014-01-12 21:51:54,044 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2014-01-12 21:51:54,044 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ClusterScopeStoragePoolAllocator looking for storage pool
 2014-01-12 21:51:54,044 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Looking for pools in dc: 1  pod:1  cluster:1 having tags:[nas, ssd, vdi]
2014-01-12 21:51:54,047 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 3
2014-01-12 21:51:54,047 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) StoragePool is in avoid set,
skipping this pool
2014-01-12 21:51:54,048 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 11
2014-01-12 21:51:54,048 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) StoragePool is in avoid set,
skipping this pool
2014-01-12 21:51:54,049 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-13:job-752 =
[ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Checking if storage pool is
suitable, name: null ,poolId: 13
2014-01-12 21:51:54,053 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool 13 for storage, totalSize: 1099507433472, usedBytes: 0,
usedPct: 0.0, disable threshold: 0.85
2014-01-12 21:51:54,061 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking pool: 13 for volume allocation [Vol[191|vm=127|ROOT]], maxSize :
1099507433472, totalAllocatedSize : 80530636800, askingSize : 80530636800,
allocated disable threshold: 0.85
2014-01-12 21:51:54,061 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2014-01-12 21:51:54,061 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Trying
to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2014-01-12 21:51:54,062 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking if host: 8 can access any suitable storage pool for volume: ROOT
2014-01-12 21:51:54,063 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Host:
8 can access pool: 13
2014-01-12 21:51:54,066 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Found
a potential host id: 8 name: hv-b1fkcy1.lax1.uw1.ibcloud.local and
associated storage pools for this VM
2014-01-12 21:51:54,067 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
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(8)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:54,067 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Deployment found  - P0=VM[User|testdb],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
:
Dest[Zone(1)-Pod(1)-Cluster(1)-Host(8)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:54,078 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM
state transitted from :Starting to Starting with event: OperationRetryvm's
original host id: null new host id: 8 host id before state transition: null
2014-01-12 21:51:54,085 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Hosts's actual total CPU: 38384 and CPU after applying overprovisioning:
307072
2014-01-12 21:51:54,086 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) We are
allocating VM, increasing the used capacity of this host:8
2014-01-12 21:51:54,086 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Current Used CPU: 0 , Free CPU:307072 ,Requested CPU: 13200
2014-01-12 21:51:54,086 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Current Used RAM: 0 , Free RAM:203056644096 ,Requested RAM: 51539607552
2014-01-12 21:51:54,086 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) CPU
STATS after allocation: for host: 8, old used: 0, old reserved: 0, actual
total: 38384, total with overprovisioning: 307072; new used:13200,
reserved:0; requested cpu:13200,alloc_from_last:false
2014-01-12 21:51:54,086 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) RAM
STATS after allocation: for host: 8, old used: 0, old reserved: 0, total:
203056644096; new used: 51539607552, reserved: 0; requested mem:
51539607552,alloc_from_last:false
2014-01-12 21:51:54,087 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM is
being created in podId: 1
2014-01-12 21:51:54,090 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Network id=204 is already implemented
2014-01-12 21:51:54,098 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:54,101 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Changing active number of nics for network id=204 on 1
2014-01-12 21:51:54,105 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Asking
F5BigIP to prepare for Nic[150-127-null-10.197.212.133]
2014-01-12 21:51:54,110 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Asking
VirtualRouter to prepare for Nic[150-127-null-10.197.212.133]
2014-01-12 21:51:54,118 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Lock
is acquired for network id 204 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(8)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:54,122 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Lock
is released for network id 204 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(8)-Storage(Volume(191|ROOT-->Pool(13))]
2014-01-12 21:51:54,128 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:54,139 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:54,142 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Applying dhcp entry in network Ntwk[204|Guest|15]
2014-01-12 21:51:54,157 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044507: Sending  { Cmd , MgmtId: 110493003717, via: 6, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:4e:98:00:01:27","vmIpAddress":"10.197.212.133","vmName":"testdb","defaultRouter":"10.197.212.1","defaultDns":"10.197.212.128","duid":"00:03:00:01:06:4e:98:00:01:27","isDefault":true,"executeInSequence":true,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.197.212.128","router.ip":"169.254.1.122","
router.name":"r-25-VM"},"wait":0}}] }
2014-01-12 21:51:54,482 DEBUG [agent.transport.Request]
(AgentManager-Handler-3:null) Seq 6-890044507: Processing:  { Ans: ,
MgmtId: 110493003717, via: 6, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-01-12 21:51:54,482 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-3:null) Seq 6-890044507: No more commands found
2014-01-12 21:51:54,482 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044507: Received:  { Ans: , MgmtId: 110493003717, via: 6, Ver: v1,
Flags: 110, { Answer } }
2014-01-12 21:51:54,489 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:54,491 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Applying userdata and password entry in network Ntwk[204|Guest|15]
2014-01-12 21:51:54,508 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044508: Sending  { Cmd , MgmtId: 110493003717, via: 6, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.197.212.133","vmName":"testdb","executeInSequence":true,"accessDetails":{"zone.network.type":"Advanced","
router.name
":"r-25-VM","router.ip":"169.254.1.122","router.guest.ip":"10.197.212.128"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.197.212.133","vmName":"testdb","executeInSequence":true,"accessDetails":{"zone.network.type":"Advanced","
router.name":"r-25-VM","router.ip":"169.254.1.122","router.guest.ip":"10.197.212.128"},"wait":0}}]
}
2014-01-12 21:51:55,023 DEBUG [agent.transport.Request]
(AgentManager-Handler-7:null) Seq 6-890044508: Processing:  { Ans: ,
MgmtId: 110493003717, via: 6, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}]
}
2014-01-12 21:51:55,023 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-7:null) Seq 6-890044508: No more commands found
2014-01-12 21:51:55,023 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
6-890044508: Received:  { Ans: , MgmtId: 110493003717, via: 6, Ver: v1,
Flags: 110, { Answer, Answer } }
2014-01-12 21:51:55,024 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Service SecurityGroup is not supported in the network id=204
2014-01-12 21:51:55,025 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Checking if we need to prepare 1 volumes for VM[User|testdb]
2014-01-12 21:51:55,032 DEBUG [storage.image.TemplateDataFactoryImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
template 212 is already in store:2, type:Image
2014-01-12 21:51:55,035 DEBUG [storage.image.TemplateDataFactoryImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
template 212 is already in store:13, type:Primary
2014-01-12 21:51:55,058 DEBUG [storage.image.TemplateDataFactoryImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
template 212 is already in store:2, type:Image
2014-01-12 21:51:55,067 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
15-988282944: Sending  { Cmd , MgmtId: 110493003717, via: 15, Ver: v1,
Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/4/212/9c6bfb0f-ce64-464e-a651-e5b8af55d629.qcow2","uuid":"23bf3947-b667-4a7f-b702-2093c3c06288","id":212,"format":"QCOW2","accountId":4,"hvm":true,"displayText":"Oracle
11.2.0.3.7 on
RHEL6","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://nas2-a-519.lax1.uw1.ibcloud.local/vol/cloud_sec_1","_role":"Image"}},"name":"9c6bfb0f-ce64-464e-a651-e5b8af55d629","hypervisorType":"KVM"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ca270592-751e-40ac-b73c-37ed2c30862f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1d1e7787-e1d9-4dbd-9046-0e124dffd770","id":13,"poolType":"CLVM","host":"localhost","path":"/vg_vmem-003a74_vdi3","port":0}},"name":"ROOT-127","size":80530636800,"volumeId":191,"vmName":"i-7-127-VM","accountId":7,"format":"QCOW2","id":191,"hypervisorType":"KVM"}},"executeInSequence":true,"wait":10800}}]
}
2014-01-12 21:51:55,207 DEBUG [agent.transport.Request]
(AgentManager-Handler-8:null) Seq 15-988282944: Processing:  { Ans: ,
MgmtId: 110493003717, via: 15, Ver: v1, Flags: 110,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException:
Can't find volume:9c6bfb0f-ce64-464e-a651-e5b8af55d629.qcow2","wait":0}}] }
2014-01-12 21:51:55,207 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
15-988282944: Received:  { Ans: , MgmtId: 110493003717, via: 15, Ver: v1,
Flags: 110, { CopyCmdAnswer } }
2014-01-12 21:51:55,207 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-8:null) Seq 15-988282944: No more commands found
2014-01-12 21:51:55,208 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Failed
to start instance VM[User|testdb]
java.lang.RuntimeException: InvocationTargetException when invoking RPC
callback for command: createVolumeFromBaseImageCallBack
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
        at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
        at
org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.copyAsync(CloudStackPrimaryDataStoreDriverImpl.java:207)
        at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:49)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageAsync(VolumeServiceImpl.java:517)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:579)
        at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2577)
        at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2641)
        at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
        at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
        at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
        at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3440)
        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.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:744)
Caused by: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
        ... 28 more
Caused by: java.lang.NullPointerException
        at
org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:487)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageCallBack(VolumeServiceImpl.java:531)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        ... 32 more
2014-01-12 21:51:55,212 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Cleaning up resources for the vm VM[User|testdb] in Starting state
2014-01-12 21:51:55,213 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
8-720830503: Sending  { Cmd , MgmtId: 110493003717, via: 8, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-7-127-VM","wait":0}}]
}
2014-01-12 21:51:55,399 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
===START===  10.19.241.61 -- GET
 command=queryAsyncJobResult&jobId=80077065-9fe7-4bc6-a46a-d86b9a5b1d1d&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592315341
2014-01-12 21:51:55,407 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-7:null) Access to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:55,416 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
===END===  10.19.241.61 -- GET
 command=queryAsyncJobResult&jobId=80077065-9fe7-4bc6-a46a-d86b9a5b1d1d&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592315341
2014-01-12 21:51:55,481 DEBUG [agent.transport.Request]
(AgentManager-Handler-9:null) Seq 8-720830503: Processing:  { Ans: ,
MgmtId: 110493003717, via: 8, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2014-01-12 21:51:55,481 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-9:null) Seq 8-720830503: No more commands found
2014-01-12 21:51:55,481 DEBUG [agent.transport.Request]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) Seq
8-720830503: Received:  { Ans: , MgmtId: 110493003717, via: 8, Ver: v1,
Flags: 110, { StopAnswer } }
2014-01-12 21:51:55,489 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Changing active number of nics for network id=204 on -1
2014-01-12 21:51:55,490 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Successfully released network resources for the vm VM[User|testdb]
2014-01-12 21:51:55,490 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Successfully cleanued up resources for the vm VM[User|testdb] in Starting
state
2014-01-12 21:51:55,494 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) VM
state transitted from :Starting to Stopped with event: OperationFailedvm's
original host id: null new host id: null host id before state transition: 8
2014-01-12 21:51:55,500 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Hosts's actual total CPU: 38384 and CPU after applying overprovisioning:
307072
2014-01-12 21:51:55,500 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Hosts's actual total RAM: 203056635904 and RAM after applying
overprovisioning: 203056644096
2014-01-12 21:51:55,500 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
release cpu from host: 8, old used: 13200,reserved: 0, actual total: 38384,
total with overprovisioning: 307072; new used: 0,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2014-01-12 21:51:55,500 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
release mem from host: 8, old used: 51539607552,reserved: 0, total:
203056644096; new used: 0,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2014-01-12 21:51:55,510 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Destroying vm VM[User|testdb] as it failed to create on Host with Id:null
2014-01-12 21:51:55,516 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ]) 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-01-12 21:51:55,532 WARN  [apache.cloudstack.alerts]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
 alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null //
message:: Failed to deploy Vm with Id: 127, on Host with Id: null
2014-01-12 21:51:55,553 WARN  [user.vm.DeployVMCmd]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Exception:
com.cloud.exception.AgentUnavailableException: Resource [Host:8] is
unreachable: Host 8: Unable to start instance due to
InvocationTargetException when invoking RPC callback for command:
createVolumeFromBaseImageCallBack
        at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:999)
        at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
        at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
        at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
        at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3440)
        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.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:744)
Caused by: java.lang.RuntimeException: InvocationTargetException when
invoking RPC callback for command: createVolumeFromBaseImageCallBack
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
        at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
        at
org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.copyAsync(CloudStackPrimaryDataStoreDriverImpl.java:207)
        at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:49)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageAsync(VolumeServiceImpl.java:517)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:579)
        at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2577)
        at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2641)
        at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
        ... 19 more
Caused by: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
        ... 28 more
Caused by: java.lang.NullPointerException
        at
org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:487)
        at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromBaseImageCallBack(VolumeServiceImpl.java:531)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        ... 32 more
2014-01-12 21:51:55,557 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-13:job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ])
Complete async job-752 = [ 80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ],
jobStatus: 2, resultCode: 530, result: Error Code: 534 Error text: Resource
[Host:8] is unreachable: Host 8: Unable to start instance due to
InvocationTargetException when invoking RPC callback for command:
createVolumeFromBaseImageCallBack
2014-01-12 21:51:58,396 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===START===  10.19.241.61 -- GET
 command=queryAsyncJobResult&jobId=80077065-9fe7-4bc6-a46a-d86b9a5b1d1d&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592318340
2014-01-12 21:51:58,406 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-3:null) Access to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] by
DomainChecker_EnhancerByCloudStack_7067e23b
2014-01-12 21:51:58,408 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-3:null) Async job-752 = [
80077065-9fe7-4bc6-a46a-d86b9a5b1d1d ] completed
2014-01-12 21:51:58,413 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===END===  10.19.241.61 -- GET
 command=queryAsyncJobResult&jobId=80077065-9fe7-4bc6-a46a-d86b9a5b1d1d&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592318340
2014-01-12 21:51:58,480 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
===START===  10.19.241.61 -- GET
 command=listVirtualMachines&id=44d647c5-e3b6-49ce-b04c-842f45e6123c&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592318422
2014-01-12 21:51:58,492 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-6:null) Access granted to
Acct[92cbc0aa-883c-4427-b95c-c3fc4501048e-unix] to Domain:2/Martindale/ by
AffinityGroupAccessChecker_EnhancerByCloudStack_572d7940
2014-01-12 21:51:58,508 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
===END===  10.19.241.61 -- GET
 command=listVirtualMachines&id=44d647c5-e3b6-49ce-b04c-842f45e6123c&response=json&sessionkey=zxWC3aIZAYTqQDJ0WR9yZuT6%2FvM%3D&projectid=a98b95ee-1eba-44f1-a714-00254ec068c5&_=1389592318422
2014-01-12 21:51:59,153 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-11:null) SeqA 14-47257: Processing Seq 14-47257:  {
Cmd , MgmtId: -1, via: 14, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":103,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
2014-01-12 21:51:59,155 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-11:null) SeqA 14-47257: Sending Seq 14-47257:  { Ans:
, MgmtId: 110493003717, via: 14, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message