cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Nathan Rich (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (CLOUDSTACK-5668) Can't make templates from XenServer VHDs
Date Wed, 29 Jan 2014 23:50:09 GMT

    [ https://issues.apache.org/jira/browse/CLOUDSTACK-5668?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13886003#comment-13886003
] 

Nathan Rich edited comment on CLOUDSTACK-5668 at 1/29/14 11:48 PM:
-------------------------------------------------------------------

This is still an issue with CloudStack 4.2.1. Confirmed today 1/30/2014 local time.

Here's a template that works, from before upgrading to 6.2SP1
./tmpl/2/239/ec16892c-def7-4a43-a729-ea2a3380f458.vhd
and here's a new one created after upgrading, which I can not create a vm from, because the
vhd isn't found
./tmpl/2/255/ab95476b-af90-4577-59d2-0d8ef02a1745/b79b3d5e-116d-40f1-afba-ac9ffa283809.vhd
there's an extra uuid in the path for an unknown reason
The entire state.db of the xenserver doesn't contain this uuid
And a search of the entire cloud database in every table also doesn't contain this uuid

We need SP1 so we can offer server 2012r2. What can we do to fix this issue? It's been a month
with no response. Thanks


Not sure if this is related but the logs on 4.2.1 show:
2014-01-29 15:37:47,704 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-133:null) Seq
18-1414208685: Executing request
2014-01-29 15:37:47,990 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-133:null) Vm
cpu utilization 0.015625
2014-01-29 15:37:47,996 WARN  [xen.resource.CitrixResourceBase] (DirectAgent-133:null) Error
while collecting disk stats from :
You gave an invalid object reference.  The object may have recently been deleted.  The class
parameter gives the type of reference given, and the handle parameter echoes the bad value
given.
        at com.xensource.xenapi.Types.checkResponse(Types.java:209)
        at com.xensource.xenapi.Connection.dispatch(Connection.java:368)
        at com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909)
        at com.xensource.xenapi.VBDMetrics.getIoReadKbs(VBDMetrics.java:210)
        at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVmStats(CitrixResourceBase.java:2791)
        at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2691)
        at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:497)
        at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
        at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
        at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:701)


and again it's showing this in the logs:

2014-01-29 15:42:44,031 DEBUG [agent.transport.Request] (Job-Executor-1:job-559 = [ 13751264-ceed-4075-96ce-6c0c1b64fae3
]) Seq 18-240451599: Sending  { Cmd , MgmtId: 253519258224950, via: 18, Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/255/b79b3d5e-116d-40f1-afba-ac9ffa283809.vhd","uuid":"2d83e4c4-3361-461e-a4de-158be71adc52","id":255,"format":"VHD","accountId":2,"hvm":true,"displayText":"testdeleteme","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://san01.cloud.xxx.com/export/secondary","_role":"Image"}},"name":"b79b3d5e-116d-40f1-afba-ac9ffa283809","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"uuid":"2d83e4c4-3361-461e-a4de-158be71adc52","id":255,"format":"VHD","accountId":2,"hvm":true,"displayText":"testdeleteme","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a20d8adc-5d9a-34d5-a72b-19958498274c","id":5,"poolType":"IscsiLUN","host":"172.16.1.254","path":"/iqn.2013-11.com.xxx.cloud.san01:primary/1","port":3260}},"name":"b79b3d5e-116d-40f1-afba-ac9ffa283809","hypervisorType":"XenServer"}},"executeInSequence":true,"wait":10800}}]
}

As you can see it's looking for template/tmpl/2/255/b79b3d5e-116d-40f1-afba-ac9ffa283809.vhd
but the file is actually at template/tmpl/2/255/ab95476b-af90-4577-59d2-0d8ef02a1745/b79b3d5e-116d-40f1-afba-ac9ffa283809.vhd


was (Author: n4th4nr1ch):
This is still an issue with CloudStack 4.2.1. Confirmed today 1/30/2014 local time.

Here's a template that works, from before upgrading to 6.2SP1
./tmpl/2/239/ec16892c-def7-4a43-a729-ea2a3380f458.vhd
and here's a new one created after upgrading, which I can not create a vm from, because the
vhd isn't found
./tmpl/2/255/ab95476b-af90-4577-59d2-0d8ef02a1745/b79b3d5e-116d-40f1-afba-ac9ffa283809.vhd
there's an extra uuid in the path for an unknown reason
The entire state.db of the xenserver doesn't contain this uuid
And a search of the entire cloud database in every table also doesn't contain this uuid

We need SP1 so we can offer server 2012r2. What can we do to fix this issue? It's been a month
with no response. Thanks


Not sure if this is related but the logs on 4.2.1 show:
2014-01-29 15:37:47,704 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-133:null) Seq
18-1414208685: Executing request
2014-01-29 15:37:47,990 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-133:null) Vm
cpu utilization 0.015625
2014-01-29 15:37:47,996 WARN  [xen.resource.CitrixResourceBase] (DirectAgent-133:null) Error
while collecting disk stats from :
You gave an invalid object reference.  The object may have recently been deleted.  The class
parameter gives the type of reference given, and the handle parameter echoes the bad value
given.
        at com.xensource.xenapi.Types.checkResponse(Types.java:209)
        at com.xensource.xenapi.Connection.dispatch(Connection.java:368)
        at com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909)
        at com.xensource.xenapi.VBDMetrics.getIoReadKbs(VBDMetrics.java:210)
        at com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVmStats(CitrixResourceBase.java:2791)
        at com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2691)
        at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:497)
        at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59)
        at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106)
        at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:701)


> Can't make templates from XenServer VHDs
> ----------------------------------------
>
>                 Key: CLOUDSTACK-5668
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5668
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>          Components: Template
>    Affects Versions: 4.2.0, 4.2.1
>         Environment: XenServer 6.2 hypers with XS62E001,XS62E002,XS62E004,XS62E005,XS62E007,XS62E008,XS62E009,XS62E010,XS62E011,XS62E012,XS62E013,XS62ESP1
> (service pack 1)
>            Reporter: Nathan Rich
>            Priority: Critical
>              Labels: template, xenserver
>
> When creating a template from VHD it says it can't find the vhd at
> ""template/tmpl/2/223/ac4c722d-2896-487e-9e44-9bde3a047daf.vhd""
> When I look for the VHD I find it instead at
> "template/tmpl/2/223/f52254da-33a4-8ceb-8788-35c7e57cb62e/ac4c722d-2896-487e-9e44-9bde3a047daf.vhd"
> There is an additional UUID in the path that cloudstack is not looking for.
> traceback:
> 2013-12-28 13:04:13,255 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Checking if we need to prepare 1 volumes for VM[User|46144118-2e69-471f-9bd6-3068449e8f0a]
> 2013-12-28 13:04:13,267 DEBUG [storage.image.TemplateDataFactoryImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) template 223 is already in store:2, type:Image
> 2013-12-28 13:04:13,273 DEBUG [storage.datastore.PrimaryDataStoreImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Not found (templateId:223poolId:2) in template_spool_ref,
persisting it
> 2013-12-28 13:04:13,281 DEBUG [storage.image.TemplateDataFactoryImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) template 223 is already in store:2, type:Primary
> 2013-12-28 13:04:13,283 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Found template ac4c722d-2896-487e-9e44-9bde3a047daf
in storage pool 2 with VMTemplateStorag              ePool id: 16
> 2013-12-28 13:04:13,291 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Acquire lock on VMTemplateStoragePool 16 with
timeout 3600 seconds
> 2013-12-28 13:04:13,293 INFO  [storage.volume.VolumeServiceImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) lock is acquired for VMTemplateStoragePool 16
> 2013-12-28 13:04:13,301 DEBUG [storage.motion.AncientDataMotionStrategy] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) copyAsync inspecting src type TEMPLATE copyAsync
inspecting dest type TEMPLATE
> 2013-12-28 13:04:13,316 DEBUG [agent.transport.Request] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Seq 9-1395326995: Sending  { Cmd , MgmtId: 253519258224950, via: 9, Ver: v1, Flags: 100111,
[{"org.a              pache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/223/ac4c722d-2896-487e-9e44-9bde3a047daf.vhd","uuid":"d6d85c3e-c3af-40cd-afbd-37d335b8f56b"
             ,"id":223,"format":"VHD","accountId":2,"hvm":true,"displayText":"test2","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://san01.cloud.xxx.com/export/secondary","_role":"Image"}},"name":"ac4c722d-2896-487e-9e
             44-9bde3a047daf","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"uuid":"d6d85c3e-c3af-40cd-afbd-37d335b8f56b","id":223,"format":"VHD","accountId":2,"hvm":true,"displayText":"tes
             t2","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"Primary","id":2,"poolType":"PreSetup","host":"localhost","path":"/Primary","port":0}},"name":"ac4c722d-2896-487e-9e44-9bde3a047daf","hyperv
             isorType":"XenServer"}},"executeInSequence":true,"wait":10800}}] }
> 2013-12-28 13:04:13,317 DEBUG [agent.transport.Request] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Seq 9-1395326995: Executing:  { Cmd , MgmtId: 253519258224950, via: 9, Ver: v1, Flags:
100111, [{"or              g.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/223/ac4c722d-2896-487e-9e44-9bde3a047daf.vhd","uuid":"d6d85c3e-c3af-40cd-afbd-37d335b8f5
             6b","id":223,"format":"VHD","accountId":2,"hvm":true,"displayText":"test2","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://san01.cloud.xxx.com/export/secondary","_role":"Image"}},"name":"ac4c722d-2896-487e
             -9e44-9bde3a047daf","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"uuid":"d6d85c3e-c3af-40cd-afbd-37d335b8f56b","id":223,"format":"VHD","accountId":2,"hvm":true,"displayText":"
             test2","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"Primary","id":2,"poolType":"PreSetup","host":"localhost","path":"/Primary","port":0}},"name":"ac4c722d-2896-487e-9e44-9bde3a047daf","hyp
             ervisorType":"XenServer"}},"executeInSequence":true,"wait":10800}}] }
> 2013-12-28 13:04:13,317 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-96:null)
Seq 9-1395326995: Executing request
> 2013-12-28 13:04:14,034 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-17:null)
Ping from 2
> 2013-12-28 13:04:14,609 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-108:null)
Ping from 9
> 2013-12-28 13:04:14,940 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START===
 69.89.79.19 -- GET  command=queryAsyncJobResult&jobId=2e8f9cf4-3e9b-45d9-8481-093ec790cdd4&response=json&sessionkey=2aBNKkj6Hzwel63VVT
             zVmzTaph8%3D&_=1388264654382
> 2013-12-28 13:04:14,967 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END===
 69.89.79.19 -- GET  command=queryAsyncJobResult&jobId=2e8f9cf4-3e9b-45d9-8481-093ec790cdd4&response=json&sessionkey=2aBNKkj6Hzwel63VVTzV
             mzTaph8%3D&_=1388264654382
> 2013-12-28 13:04:14,978 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-63:null)
Ping from 12
> 2013-12-28 13:04:15,396 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-11:null)
Seq 2-449708037: Executing request
> 2013-12-28 13:04:15,420 WARN  [xen.resource.XenServerStorageProcessor] (DirectAgent-96:null)
destoryVDIbyNameLabel failed due to there are 0 VDIs with name cloud-c2c2d197-3da0-4128-a9d2-1c661b4aa2e2
> 2013-12-28 13:04:15,421 WARN  [xen.resource.XenServerStorageProcessor] (DirectAgent-96:null)
can not create vdi in sr 8ae79926-f5b3-f7f4-3e2f-3ba33d9aea21
> 2013-12-28 13:04:15,421 WARN  [xen.resource.XenServerStorageProcessor] (DirectAgent-96:null)
Catch Exception com.cloud.utils.exception.CloudRuntimeException for template +  due to com.cloud.utils.exception.CloudRuntimeExcept
             ion: can not create vdi in sr 8ae79926-f5b3-f7f4-3e2f-3ba33d9aea21
> com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 8ae79926-f5b3-f7f4-3e2f-3ba33d9aea21
>         at com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.copy_vhd_from_secondarystorage(XenServerStorageProcessor.java:792)
>         at com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.copyTemplateToPrimaryStorage(XenServerStorageProcessor.java:863)
>         at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:70)
>         at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49)
>         at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:621)
>         at com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
>         at com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:104)
>         at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2013-12-28 13:04:15,422 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-96:null)
Seq 9-1395326995: Response Received:
> 2013-12-28 13:04:15,422 DEBUG [agent.transport.Request] (DirectAgent-96:null) Seq 9-1395326995:
Processing:  { Ans: , MgmtId: 253519258224950, via: 9, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnsw
             er":{"result":false,"details":"Catch Exception com.cloud.utils.exception.CloudRuntimeException
for template +  due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi
in sr 8ae79926-f5b3-f7f4-3e2f-3ba33d9a              ea21","wait":0}}] }
> 2013-12-28 13:04:15,423 DEBUG [agent.transport.Request] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Seq 9-1395326995: Received:  { Ans: , MgmtId: 253519258224950, via: 9, Ver: v1, Flags:
110, { CopyCm              dAnswer } }
> 2013-12-28 13:04:15,423 DEBUG [agent.manager.AgentAttache] (DirectAgent-96:null) Seq
9-1395326995: No more commands found
> 2013-12-28 13:04:15,434 INFO  [storage.volume.VolumeServiceImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) releasing lock for VMTemplateStoragePool 16
> 2013-12-28 13:04:15,434 WARN  [utils.db.Merovingian2] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Was unable to find lock for the key template_spool_ref16 and thread id 691039818
> 2013-12-28 13:04:15,435 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Unable to create Vol[48|vm=41|ROOT]:Catch Exception
com.cloud.utils.exception.CloudRuntimeEx              ception for template +  due to com.cloud.utils.exception.CloudRuntimeException:
can not create vdi in sr 8ae79926-f5b3-f7f4-3e2f-3ba33d9aea21
> 2013-12-28 13:04:15,435 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Unable to contact resource.
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:2] is unreachable:
Unable to create Vol[48|vm=41|ROOT]:Catch Exception com.cloud.utils.exception.CloudRuntimeException
for template +  due to com.cloud.u              tils.exception.CloudRuntimeException: can
not create vdi in sr 8ae79926-f5b3-f7f4-3e2f-3ba33d9aea21
>         at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2544)
>         at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2592)
>         at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:889)
>         at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
>         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:3406)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2966)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2952)
>         at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>         at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
>         at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
>         at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2013-12-28 13:04:15,441 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Cleaning up resources for the vm VM[User|46144118-2e69-471f-9bd6-3068449e8f0a]
in Startin              g state
> 2013-12-28 13:04:15,443 DEBUG [agent.transport.Request] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Seq 9-1395326996: Sending  { Cmd , MgmtId: 253519258224950, via: 9, Ver: v1, Flags: 100111,
[{"com.c              loud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-41-VM","wait":0}}]
}
> 2013-12-28 13:04:15,443 DEBUG [agent.transport.Request] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Seq 9-1395326996: Executing:  { Cmd , MgmtId: 253519258224950, via: 9, Ver: v1, Flags:
100111, [{"co              m.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-41-VM","wait":0}}]
}
> 2013-12-28 13:04:15,444 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-76:null)
Seq 9-1395326996: Executing request
> 2013-12-28 13:04:15,598 INFO  [xen.resource.CitrixResourceBase] (DirectAgent-76:null)
VM does not exist on XenServerc1a556e6-028c-4ecc-bfd9-426cde76f530
> 2013-12-28 13:04:15,598 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-76:null)
Seq 9-1395326996: Response Received:
> 2013-12-28 13:04:15,598 DEBUG [agent.transport.Request] (DirectAgent-76:null) Seq 9-1395326996:
Processing:  { Ans: , MgmtId: 253519258224950, via: 9, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"res
             ult":true,"details":"VM does not exist","wait":0}}] }
> 2013-12-28 13:04:15,598 DEBUG [agent.manager.AgentAttache] (DirectAgent-76:null) Seq
9-1395326996: No more commands found
> 2013-12-28 13:04:15,598 DEBUG [agent.transport.Request] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Seq 9-1395326996: Received:  { Ans: , MgmtId: 253519258224950, via: 9, Ver: v1, Flags:
110, { StopAn              swer } }
> 2013-12-28 13:04:15,598 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-11:null)
Seq 2-449708037: Response Received:
> 2013-12-28 13:04:15,599 DEBUG [agent.transport.Request] (DirectAgent-11:null) Seq 2-449708037:
Processing:  { Ans: , MgmtId: 253519258224950, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId
             ":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
> 2013-12-28 13:04:15,610 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Service SecurityGroup is not supported in the
network id=207
> 2013-12-28 13:04:15,614 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Changing active number of nics for network id=207
on -1
> 2013-12-28 13:04:15,624 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Asking VirtualRouter to release Nic[92-41-2829633d-58ce-4fa3-b417-d231a73e761d-10.1.1.199]
> 2013-12-28 13:04:15,624 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Successfully released network resources for the
vm VM[User|46144118-2e69-471f-9bd6-306844              9e8f0a]
> 2013-12-28 13:04:15,624 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Successfully cleanued up resources for the vm
VM[User|46144118-2e69-471f-9bd6-3068449e8f0              a] in Starting state
> 2013-12-28 13:04:15,638 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Deploy avoids pods: [], clusters: [], hosts: [9]
> 2013-12-28 13:04:15,640 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_Enhancer
             ByCloudStack_dd371ad3@261337c3
> 2013-12-28 13:04:15,640 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Trying to allocate a host and storage pools from
dc:1, pod:1,cluster:1, requested               cpu: 500, requested ram: 536870912
> 2013-12-28 13:04:15,640 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Is ROOT volume READY (pool already allocated)?:
No
> 2013-12-28 13:04:15,640 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) DeploymentPlan has host_id specified, choosing
this host and making no checks on               this host: 9
> 2013-12-28 13:04:15,642 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) The specified host is in avoid set
> 2013-12-28 13:04:15,642 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Cannnot deploy to specified host, returning.
> 2013-12-28 13:04:15,655 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) VM state transitted from :Starting to Stopped
with event: OperationFailedvm's original ho              st id: null new host id: null host
id before state transition: 9
> 2013-12-28 13:04:15,663 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Hosts's actual total CPU: 48000 and CPU after
applying overprovisioning: 48000
> 2013-12-28 13:04:15,663 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Hosts's actual total RAM: 63270027072 and RAM
after applying overprovisioning: 6327002726              4
> 2013-12-28 13:04:15,664 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) release cpu from host: 9, old used: 500,reserved:
0, actual total: 48000, total with over              provisioning: 48000; new used: 0,reserved:0;
movedfromreserved: false,moveToReserveredfalse
> 2013-12-28 13:04:15,664 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) release mem from host: 9, old used: 536870912,reserved:
0, total: 63270027264; new used:               0,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-12-28 13:04:15,687 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) VM state transitted from :Stopped to Starting
with event: StartRequestedvm's original hos              t id: null new host id: null host
id before state transition: null
> 2013-12-28 13:04:15,687 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Successfully transitioned to start state for VM[User|46144118-2e69-471f-9bd6-3068449e8f0a
             ] reservation id = f594ecf8-304c-4d85-84ba-c766935ceacf
> 2013-12-28 13:04:15,692 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Trying to deploy VM, vm has dcId: 1 and podId:
1
> 2013-12-28 13:04:15,692 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Deploy avoids pods: [], clusters: [], hosts: [9]
> 2013-12-28 13:04:15,706 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Deploy avoids pods: [], clusters: [], hosts: [9]
> 2013-12-28 13:04:15,708 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_Enhancer
             ByCloudStack_dd371ad3@261337c3
> 2013-12-28 13:04:15,708 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Trying to allocate a host and storage pools from
dc:1, pod:1,cluster:null, reques              ted cpu: 500, requested ram: 536870912
> 2013-12-28 13:04:15,708 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Is ROOT volume READY (pool already allocated)?:
No
> 2013-12-28 13:04:15,708 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Searching resources only under specified Pod:
1
> 2013-12-28 13:04:15,708 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Listing clusters in order of aggregate capacity,
that have (atleast one host with) enough CPU a              nd RAM capacity under this Pod:
1
> 2013-12-28 13:04:15,713 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Removing from the clusterId list these clusters
from avoid set: []
> 2013-12-28 13:04:15,720 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Checking resources in Cluster: 1 under Pod: 1
> 2013-12-28 13:04:15,720 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Looking for hosts in
dc: 1  pod:1  cluster:1
> 2013-12-28 13:04:15,725 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) FirstFitAllocator has
3 hosts to check for allocation: [Host[-12-R              outing], Host[-9-Routing], Host[-2-Routing]]
> 2013-12-28 13:04:15,732 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Found 3 hosts for allocation
after prioritization: [Host[-12-Routi              ng], Host[-9-Routing], Host[-2-Routing]]
> 2013-12-28 13:04:15,732 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=512
> 2013-12-28 13:04:15,740 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Checking if host: 12
has enough capacity for requested CPU: 500               and requested RAM: 536870912 , cpuOverprovisioningFactor:
1.0
> 2013-12-28 13:04:15,744 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Hosts's actual total
CPU: 48000 and CPU after applying overprovi              sioning: 48000
> 2013-12-28 13:04:15,744 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Free CPU: 46500 , Requested
CPU: 500
> 2013-12-28 13:04:15,744 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Free RAM: 61656576000
, Requested RAM: 536870912
> 2013-12-28 13:04:15,744 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Host has enough CPU and
RAM available
> 2013-12-28 13:04:15,744 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) STATS: Can alloc CPU
from host: 12, used: 1500, reserved: 0, act              ual total: 48000, total with overprovisioning:
48000; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-12-28 13:04:15,744 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) STATS: Can alloc MEM
from host: 12, used: 1610612736, reserved:               0, total: 63267188736; requested
mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-12-28 13:04:15,744 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Found a suitable host,
adding to list: 12
> 2013-12-28 13:04:15,744 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Host name: xs02.cloud.xxx.com,
hostId: 9 is in avoid set, skipp              ing this and trying other available hosts
> 2013-12-28 13:04:15,752 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Checking if host: 2 has
enough capacity for requested CPU: 500 a              nd requested RAM: 536870912 , cpuOverprovisioningFactor:
1.0
> 2013-12-28 13:04:15,755 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Hosts's actual total
CPU: 48000 and CPU after applying overprovi              sioning: 48000
> 2013-12-28 13:04:15,755 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Free CPU: 46500 , Requested
CPU: 500
> 2013-12-28 13:04:15,755 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Free RAM: 61790793728
, Requested RAM: 536870912
> 2013-12-28 13:04:15,755 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Host has enough CPU and
RAM available
> 2013-12-28 13:04:15,755 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) STATS: Can alloc CPU
from host: 2, used: 1500, reserved: 0, actu              al total: 48000, total with overprovisioning:
48000; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-12-28 13:04:15,755 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) STATS: Can alloc MEM
from host: 2, used: 1476395008, reserved: 0              , total: 63267188736; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2013-12-28 13:04:15,755 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Found a suitable host,
adding to list: 2
> 2013-12-28 13:04:15,756 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ] FirstFitRoutingAllocator) Host Allocator returning
2 suitable hosts
> 2013-12-28 13:04:15,758 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Checking suitable pools for volume (Id, Type):
(48,ROOT)
> 2013-12-28 13:04:15,758 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) We need to allocate new storagepool for this volume
> 2013-12-28 13:04:15,758 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Calling StoragePoolAllocators to find suitable
pools
> 2013-12-28 13:04:15,758 DEBUG [storage.allocator.LocalStoragePoolAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) LocalStoragePoolAllocator trying to find storage
pool to fit the vm
> 2013-12-28 13:04:15,758 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) ClusterScopeStoragePoolAllocator looking for storage
pool
> 2013-12-28 13:04:15,758 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Looking for pools in dc: 1  pod:1  cluster:1
> 2013-12-28 13:04:15,764 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Checking if storage pool is suitable, name: null
,poolId: 2
> 2013-12-28 13:04:15,764 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) StoragePool is in avoid set, skipping this pool
> 2013-12-28 13:04:15,764 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) FirstFitStoragePoolAllocator returning 0 suitable
storage pools
> 2013-12-28 13:04:15,764 DEBUG [storage.allocator.ZoneWideStoragePoolAllocator] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) ZoneWideStoragePoolAllocator to find storage pool
> 2013-12-28 13:04:15,771 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) No suitable pools found for volume: Vol[48|vm=41|ROOT]
under cluster: 1
> 2013-12-28 13:04:15,771 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) No suitable pools found
> 2013-12-28 13:04:15,771 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) No suitable storagePools found under this Cluster:
1
> 2013-12-28 13:04:15,776 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Could not find suitable Deployment Destination
for this VM under any clusters, re              turning.
> 2013-12-28 13:04:15,776 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Searching resources only under specified Pod:
1
> 2013-12-28 13:04:15,776 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Listing clusters in order of aggregate capacity,
that have (atleast one host with) enough CPU a              nd RAM capacity under this Pod:
1
> 2013-12-28 13:04:15,781 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Removing from the clusterId list these clusters
from avoid set: [1]
> 2013-12-28 13:04:15,781 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) No clusters found after removing disabled clusters
and clusters in avoid list, returning.
> 2013-12-28 13:04:15,792 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) VM state transitted from :Starting to Stopped
with event: OperationFailedvm's original ho              st id: null new host id: null host
id before state transition: null
> 2013-12-28 13:04:15,808 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-2:job-123 =
[ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Destroying vm VM[User|46144118-2e69-471f-9bd6-3068449e8f0a]
as it failed to create on Host with I              d:null
> 2013-12-28 13:04:15,822 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) VM state transitted from :Stopped to Error with
event: OperationFailedToErrorvm's origina              l host id: null new host id: null host
id before state transition: null
> 2013-12-28 13:04:15,835 WARN  [apache.cloudstack.alerts] (Job-Executor-2:job-123 = [
2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ])  alertType:: 8 // dataCenterId:: 1 // podId:: 1 //
clusterId:: null // message:: Failed to deploy V              m with Id: 41, on Host with
Id: null
> 2013-12-28 13:04:15,874 INFO  [user.vm.DeployVMCmd] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment
for VM[User|46144              118-2e69-471f-9bd6-3068449e8f0a]Scope=interface com.cloud.dc.DataCenter;
id=1
> 2013-12-28 13:04:15,874 INFO  [user.vm.DeployVMCmd] (Job-Executor-2:job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
]) Unable to create a deployment for VM[User|46144118-2e69-471f-9bd6-3068449e8f0a]
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment
for VM[User|46144118-2e69-471f-9bd6-3068449e8f0a]Scope=interface com.cloud.dc.DataCenter;
id=1
>         at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842)
>         at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
>         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:3406)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2966)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2952)
>         at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>         at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
>         at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
>         at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:701)
> 2013-12-28 13:04:15,876 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-2:job-123
= [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4 ]) Complete async job-123 = [ 2e8f9cf4-3e9b-45d9-8481-093ec790cdd4
], jobStatus: 2, resultCode:               530, result: Error Code: 533 Error text: Unable
to create a deployment for VM[User|46144118-2e69-471f-9bd6-3068449e8f0a]
> 2013-12-28 13:04:16,082 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-111:null)
Seq 9-1395326981: Executing request
> 2013-12-28 13:04:16,157 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-111:null)
Seq 9-1395326981: Response Received:
> 2013-12-28 13:04:16,157 DEBUG [agent.transport.Request] (DirectAgent-111:null) Seq 9-1395326981:
Processing:  { Ans: , MgmtId: 253519258224950, via: 9, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait"
             :0}}] }
> 2013-12-28 13:04:16,631 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null)
SeqA 10-93070: Processing Seq 10-93070:  { Cmd , MgmtId: -1, via: 10, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadR              eportCommand":{"_proxyVmId":20,"_loadInfo":"{\n
 \"connections\": []\n}","wait":0}}] }
> 2013-12-28 13:04:16,636 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null)
SeqA 10-93070: Sending Seq 10-93070:  { Ans: , MgmtId: 253519258224950, via: 10, Ver: v1,
Flags: 100010, [{"com.cloud.agent.api.Ag              entControlAnswer":{"result":true,"wait":0}}]
}



--
This message was sent by Atlassian JIRA
(v6.1.5#6160)

Mime
View raw message