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

Nathan Rich commented on CLOUDSTACK-5668:
-----------------------------------------

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

> 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
>              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)

Reply via email to