cloudstack-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Marcus Sorensen <shadow...@gmail.com>
Subject Re: 4.2.1: CLVM deployment stopped working after adding new primary storage
Date Mon, 13 Jan 2014 06:26:23 GMT
You may not have debugging turned on at the agent. Turn any 'INFO'
instances in /etc/cloudstack/agent/log-4j.xml to DEBUG, then restart
the agent. The tests pass for basic CLVM operation on 4.2.1, I'm
assuming you were able to successfully run LVM commands (lvs, etc)
from the host to verify setup?

On Sun, Jan 12, 2014 at 11:04 PM, Bjoern Teipel <bjoern.teipel@gmail.com> wrote:
> 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
View raw message