cloudstack-users-cn mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From cui6522123 <cui6522...@gmail.com>
Subject 回复: Re: 求助,无法创建虚拟机了
Date Fri, 04 Apr 2014 08:12:30 GMT






求助这样的问题~~~~~~~
2014-04-04 16:12:31,989 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-259:null) Seq 11-1060176691: Executing request

2014-04-04 16:12:31,990 INFO  [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-1:work-38) Stopping VM[User|pipSdb1]

2014-04-04 16:12:31,994 DEBUG [cloud.capacity.CapacityManagerImpl] (HA-Worker-1:work-38) VM state transitted from :Stopping to Stopping with event: StopRequestedvm's original host id: 1 new host id: 11 host id before state transition: 11

2014-04-04 16:12:32,001 DEBUG [agent.transport.Request] (HA-Worker-1:work-38) Seq 11-1060176692: Waiting for Seq 1060176691 Scheduling:  { Cmd , MgmtId: 264018885718825, via: 11, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-27-VM","wait":0}}] }

2014-04-04 16:12:32,102 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===START===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=1fbaccce-cdb0-431a-a8b1-f418aee44bf1&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599083130

2014-04-04 16:12:32,108 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-260:null) Seq 11-1060175876: Response Received: 

2014-04-04 16:12:32,109 DEBUG [agent.transport.Request] (DirectAgent-260:null) Seq 11-1060175876: Processing:  { Ans: , MgmtId: 264018885718825, via: 11, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }

2014-04-04 16:12:32,127 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===END===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=1fbaccce-cdb0-431a-a8b1-f418aee44bf1&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599083130

2014-04-04 16:12:32,129 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-259:null) 9. The VM i-2-27-VM is in Stopping state

2014-04-04 16:12:32,133 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-259:null) 10. The VM i-2-27-VM is in Running state

2014-04-04 16:12:32,133 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-259:null) Seq 11-1060176691: Response Received: 

2014-04-04 16:12:32,133 DEBUG [agent.transport.Request] (DirectAgent-259:null) Seq 11-1060176691: Processing:  { Ans: , MgmtId: 264018885718825, via: 11, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":false,"details":"Stop VM failed","wait":0}}] }

2014-04-04 16:12:32,134 DEBUG [agent.manager.AgentAttache] (DirectAgent-259:null) Seq 11-1060176692: Sending now.  is current sequence.

2014-04-04 16:12:32,134 DEBUG [agent.transport.Request] (DirectAgent-473:null) Seq 11-1060176691: Received:  { Ans: , MgmtId: 264018885718825, via: 11, Ver: v1, Flags: 110, { StopAnswer } }

2014-04-04 16:12:32,134 WARN  [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-473:null) Unable to stop a VM due to Stop VM failed

2014-04-04 16:12:32,134 DEBUG [agent.transport.Request] (DirectAgent-259:null) Seq 11-1060176692: Executing:  { Cmd , MgmtId: 264018885718825, via: 11, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-27-VM","wait":0}}] }

2014-04-04 16:12:32,134 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-259:null) Seq 11-1060176692: Executing request

2014-04-04 16:12:32,257 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-259:null) 9. The VM i-2-27-VM is in Stopping state

2014-04-04 16:12:32,259 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-318:null) Seq 10-1151139844: Executing request

2014-04-04 16:12:32,260 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-259:null) 10. The VM i-2-27-VM is in Running state

2014-04-04 16:12:32,260 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-259:null) Seq 11-1060176692: Response Received: 

2014-04-04 16:12:32,261 DEBUG [agent.transport.Request] (DirectAgent-259:null) Seq 11-1060176692: Processing:  { Ans: , MgmtId: 264018885718825, via: 11, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"result":false,"details":"Stop VM failed","wait":0}}] }

2014-04-04 16:12:32,261 DEBUG [agent.manager.AgentAttache] (DirectAgent-259:null) Seq 11-1060176692: No more commands found

2014-04-04 16:12:32,261 DEBUG [agent.transport.Request] (HA-Worker-1:work-38) Seq 11-1060176692: Received:  { Ans: , MgmtId: 264018885718825, via: 11, Ver: v1, Flags: 110, { StopAnswer } }

2014-04-04 16:12:32,261 WARN  [cloud.vm.VirtualMachineManagerImpl] (HA-Worker-1:work-38) Unable to actually stop VM[User|pipSdb1] but continue with release because it's a force stop

2014-04-04 16:12:32,268 ERROR [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-1:work-38) Terminating HAWork[38-ForceStop-27-Stopping-Scheduled]

com.cloud.utils.exception.CloudRuntimeException: Unable to stop the virtual machine due to Stop VM failed

	at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1244)

	at com.cloud.ha.HighAvailabilityManagerImpl.stopVM(HighAvailabilityManagerImpl.java:666)

	at com.cloud.ha.HighAvailabilityManagerImpl$WorkerThread.run(HighAvailabilityManagerImpl.java:833)

2014-04-04 16:12:32,366 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-318:null) Seq 10-1151139844: Response Received: 

2014-04-04 16:12:32,367 DEBUG [agent.transport.Request] (DirectAgent-318:null) Seq 10-1151139844: Processing:  { Ans: , MgmtId: 264018885718825, via: 10, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }

2014-04-04 16:12:34,127 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===START===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=e5001a57-9993-48a3-b61e-3d6c571f1857&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599085145

2014-04-04 16:12:34,152 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===END===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=e5001a57-9993-48a3-b61e-3d6c571f1857&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599085145

2014-04-04 16:12:34,762 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-189:null) Ping from 4

2014-04-04 16:12:35,116 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=1fbaccce-cdb0-431a-a8b1-f418aee44bf1&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599086130

2014-04-04 16:12:35,136 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=1fbaccce-cdb0-431a-a8b1-f418aee44bf1&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599086130

2014-04-04 16:12:36,373 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-1104973: Processing Seq 2-1104973:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }

2014-04-04 16:12:36,376 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-1104973: Sending Seq 2-1104973:  { Ans: , MgmtId: 264018885718825, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }

2014-04-04 16:12:37,129 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=e5001a57-9993-48a3-b61e-3d6c571f1857&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599088145

2014-04-04 16:12:37,152 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END===  114.251.179.130 -- GET  command=queryAsyncJobResult&jobId=e5001a57-9993-48a3-b61e-3d6c571f1857&response=json&sessionkey=jScFs%2BDzcpLJ276m3GtN2VkMeM8%3D&_=1396599088145

2014-04-04 16:12:37,310 INFO  [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 removed accounts to cleanup

2014-04-04 16:12:37,312 INFO  [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 disabled accounts to cleanup

2014-04-04 16:12:37,314 INFO  [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 inactive domains to cleanup

2014-04-04 16:12:37,315 INFO  [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 disabled projects to cleanup




cui6522123
?发件人:?linuxbqj@gmail.com发送时间:?2014-04-04?16:02收件人:?users-cn主题:?Re: 求助,无法创建虚拟机了你的系统VM的状态正常吗?另外计算节点的状态是up吗?
?
2014-04-03 19:25 GMT+08:00 cui6522123 <cui6522123@gmail.com>:
>
>
>
>
>
>
> 新创建虚拟机报错,生产环境,求大神协助解决,报错如下:
>
>
>
> -------------------------------------------------------------------------------------------------------
>
> 2014-04-03 19:22:09,696 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) 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(1)-Storage(Volume(151|ROOT-->Pool(1))]
>
> 2014-04-03 19:22:09,701 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) 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(1)-Storage(Volume(151|ROOT-->Pool(1))]
>
> 2014-04-03 19:22:09,713 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Service SecurityGroup is not supported in the network id=204
>
> 2014-04-03 19:22:09,732 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Service SecurityGroup is not supported in the network id=204
>
> 2014-04-03 19:22:09,737 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Applying dhcp entry in network Ntwk[204|Guest|15]
>
> 2014-04-03 19:22:09,769 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650693: Sending { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:5d:f6:00:59","vmIpAddress":"10.10.30.168","vmName":"jcui02","defaultRouter":"10.10.30.1","defaultDns":"10.10.30.1","duid":"00:03:00:01:02:00:5d:f6:00:59","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"10.10.30.1","zone.network.type":"Advanced","router.name":"r-4-VM","router.ip":"169.254.1.159"},"wait":0}}] }
>
> 2014-04-03 19:22:09,769 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650693: Executing: { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:5d:f6:00:59","vmIpAddress":"10.10.30.168","vmName":"jcui02","defaultRouter":"10.10.30.1","defaultDns":"10.10.30.1","duid":"00:03:00:01:02:00:5d:f6:00:59","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"10.10.30.1","zone.network.type":"Advanced","router.name":"r-4-VM","router.ip":"169.254.1.159"},"wait":0}}] }
>
> 2014-04-03 19:22:09,770 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-26:null) Seq 1-947650693: Executing request
>
> 2014-04-03 19:22:10,715 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-26:null) Seq 1-947650693: Response Received:
>
> 2014-04-03 19:22:10,715 DEBUG [agent.transport.Request] (DirectAgent-26:null) Seq 1-947650693: Processing: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
>
> 2014-04-03 19:22:10,715 DEBUG [agent.manager.AgentAttache] (DirectAgent-26:null) Seq 1-947650693: No more commands found
>
> 2014-04-03 19:22:10,715 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650693: Received: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, { Answer } }
>
> 2014-04-03 19:22:10,729 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Service SecurityGroup is not supported in the network id=204
>
> 2014-04-03 19:22:10,734 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Applying userdata and password entry in network Ntwk[204|Guest|15]
>
> 2014-04-03 19:22:10,763 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650694: Sending { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.10.30.168","vmName":"jcui02","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.10.30.1","zone.network.type":"Advanced","router.ip":"169.254.1.159","router.name":"r-4-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.10.30.168","vmName":"jcui02","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.10.30.1","zone.network.type":"Advanced","router.ip":"169.254.1.159","router.name":"r-4-VM"},"wait":0}}] }
>
> 2014-04-03 19:22:10,764 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650694: Executing: { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.10.30.168","vmName":"jcui02","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.10.30.1","zone.network.type":"Advanced","router.ip":"169.254.1.159","router.name":"r-4-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.10.30.168","vmName":"jcui02","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.10.30.1","zone.network.type":"Advanced","router.ip":"169.254.1.159","router.name":"r-4-VM"},"wait":0}}] }
>
> 2014-04-03 19:22:10,765 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-201:null) Seq 1-947650694: Executing request
>
> 2014-04-03 19:22:11,518 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 2-1090373: Processing Seq 2-1090373: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
>
> 2014-04-03 19:22:11,522 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 2-1090373: Sending Seq 2-1090373: { Ans: , MgmtId: 264018885718825, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
>
> 2014-04-03 19:22:12,222 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-272:null) Seq 1-947650564: Executing request
>
> 2014-04-03 19:22:12,262 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-201:null) Seq 1-947650694: Response Received:
>
> 2014-04-03 19:22:12,263 DEBUG [agent.transport.Request] (DirectAgent-201:null) Seq 1-947650694: Processing: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
>
> 2014-04-03 19:22:12,263 DEBUG [agent.manager.AgentAttache] (DirectAgent-201:null) Seq 1-947650694: No more commands found
>
> 2014-04-03 19:22:12,263 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650694: Received: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, { Answer, Answer } }
>
> 2014-04-03 19:22:12,265 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Service SecurityGroup is not supported in the network id=204
>
> 2014-04-03 19:22:12,268 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Checking if we need to prepare 1 volumes for VM[User|jcui02]
>
> 2014-04-03 19:22:12,280 DEBUG [storage.image.TemplateDataFactoryImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) template 216 is already in store:1, type:Image
>
> 2014-04-03 19:22:12,286 DEBUG [storage.datastore.PrimaryDataStoreImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Not found (templateId:216poolId:1) in template_spool_ref, persisting it
>
> 2014-04-03 19:22:12,292 DEBUG [storage.image.TemplateDataFactoryImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) template 216 is already in store:1, type:Primary
>
> 2014-04-03 19:22:12,294 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Found template 7b384b36-137d-4b87-9df9-9e597d7c07eb in storage pool 1 with VMTemplateStoragePool id: 27
>
> 2014-04-03 19:22:12,305 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Acquire lock on VMTemplateStoragePool 27 with timeout 3600 seconds
>
> 2014-04-03 19:22:12,307 INFO [storage.volume.VolumeServiceImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) lock is acquired for VMTemplateStoragePool 27
>
> 2014-04-03 19:22:12,313 DEBUG [storage.motion.AncientDataMotionStrategy] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE
>
> 2014-04-03 19:22:12,332 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650695: Sending { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/216/7b384b36-137d-4b87-9df9-9e597d7c07eb.vhd","uuid":"696c4228-11ac-4613-bbda-42eb88f6ba37","id":216,"format":"VHD","accountId":2,"hvm":true,"displayText":"Centos 6.3_64_pip_2014.04","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://121.121.121.121/export/secondary","_role":"Image"}},"name":"7b384b36-137d-4b87-9df9-9e597d7c07eb","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"uuid":"696c4228-11ac-4613-bbda-42eb88f6ba37","id":216,"format":"VHD","accountId":2,"hvm":true,"displayText":"Centos 6.3_64_pip_2014.04","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"18169edd-07f3-f8ea-bec2-1cf759c76d12","id":1,"poolType":"LVM","host":"58.45.1.99","path":"lvm","port":0}},"name":"7b384b36-137d-4b87-9df9-9e597d7c07eb","hypervisorType":"XenServer"}},"executeInSequence":true,"wait":10800}}] }
>
> 2014-04-03 19:22:12,332 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650695: Executing: { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/216/7b384b36-137d-4b87-9df9-9e597d7c07eb.vhd","uuid":"696c4228-11ac-4613-bbda-42eb88f6ba37","id":216,"format":"VHD","accountId":2,"hvm":true,"displayText":"Centos 6.3_64_pip_2014.04","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://58.45.1.98/export/secondary","_role":"Image"}},"name":"7b384b36-137d-4b87-9df9-9e597d7c07eb","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"uuid":"696c4228-11ac-4613-bbda-42eb88f6ba37","id":216,"format":"VHD","accountId":2,"hvm":true,"displayText":"Centos 6.3_64_pip_2014.04","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"18169edd-07f3-f8ea-bec2-1cf759c76d12","id":1,"poolType":"LVM","host":"58.45.1.99","path":"lvm","port":0}},"name":"7b384b36-137d-4b87-9df9-9e597d7c07eb","hypervisorType":"XenServer"}},"executeInSequence":true,"wait":10800}}] }
>
> 2014-04-03 19:22:12,333 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-244:null) Seq 1-947650695: Executing request
>
> 2014-04-03 19:22:12,357 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START=== 251.25.179.130 -- GET command=queryAsyncJobResult&jobId=0fbf7edc-00f9-486a-855f-4674a264e323&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524063197
>
> 2014-04-03 19:22:12,378 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END=== 251.25.179.130 -- GET command=queryAsyncJobResult&jobId=0fbf7edc-00f9-486a-855f-4674a264e323&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524063197
>
> 2014-04-03 19:22:12,808 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-272:null) Seq 1-947650564: Response Received:
>
> 2014-04-03 19:22:12,809 DEBUG [agent.transport.Request] (DirectAgent-272:null) Seq 1-947650564: Processing: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
>
> 2014-04-03 19:22:14,757 WARN [xen.resource.XenServerStorageProcessor] (DirectAgent-244:null) destoryVDIbyNameLabel failed due to there are 0 VDIs with name cloud-06de0adc-22b8-475f-93d4-173426e13f48
>
> 2014-04-03 19:22:14,757 WARN [xen.resource.XenServerStorageProcessor] (DirectAgent-244:null) can not create vdi in sr 18169edd-07f3-f8ea-bec2-1cf759c76d12
>
> 2014-04-03 19:22:14,757 WARN [xen.resource.XenServerStorageProcessor] (DirectAgent-244:null) Catch Exception com.cloud.utils.exception.CloudRuntimeException for template + due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 18169edd-07f3-f8ea-bec2-1cf759c76d12
>
> com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 18169edd-07f3-f8ea-bec2-1cf759c76d12
>
> 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:441)
>
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98)
>
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>
> at java.lang.Thread.run(Thread.java:662)
>
> 2014-04-03 19:22:14,759 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-244:null) Seq 1-947650695: Response Received:
>
> 2014-04-03 19:22:14,759 DEBUG [agent.transport.Request] (DirectAgent-244:null) Seq 1-947650695: Processing: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"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 18169edd-07f3-f8ea-bec2-1cf759c76d12","wait":0}}] }
>
> 2014-04-03 19:22:14,759 DEBUG [agent.manager.AgentAttache] (DirectAgent-244:null) Seq 1-947650695: No more commands found
>
> 2014-04-03 19:22:14,759 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650695: Received: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, { CopyCmdAnswer } }
>
> 2014-04-03 19:22:14,767 INFO [storage.volume.VolumeServiceImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) releasing lock for VMTemplateStoragePool 27
>
> 2014-04-03 19:22:14,768 WARN [utils.db.Merovingian2] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Was unable to find lock for the key template_spool_ref27 and thread id 1291754651
>
> 2014-04-03 19:22:14,768 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Unable to create Vol[151|vm=93|ROOT]:Catch Exception com.cloud.utils.exception.CloudRuntimeException for template + due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 18169edd-07f3-f8ea-bec2-1cf759c76d12
>
> 2014-04-03 19:22:14,768 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Unable to contact resource.
>
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[151|vm=93|ROOT]:Catch Exception com.cloud.utils.exception.CloudRuntimeException for template + due to com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr 18169edd-07f3-f8ea-bec2-1cf759c76d12
>
> 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:441)
>
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>
> at java.lang.Thread.run(Thread.java:662)
>
> 2014-04-03 19:22:14,771 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Cleaning up resources for the vm VM[User|jcui02] in Starting state
>
> 2014-04-03 19:22:14,773 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650696: Sending { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-93-VM","wait":0}}] }
>
> 2014-04-03 19:22:14,774 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650696: Executing: { Cmd , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-93-VM","wait":0}}] }
>
> 2014-04-03 19:22:14,774 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-247:null) Seq 1-947650696: Executing request
>
> 2014-04-03 19:22:14,922 INFO [xen.resource.CitrixResourceBase] (DirectAgent-247:null) VM does not exist on XenServerbafae2c6-3d52-4ea9-a060-2eac3ee641ef
>
> 2014-04-03 19:22:14,923 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-247:null) Seq 1-947650696: Response Received:
>
> 2014-04-03 19:22:14,923 DEBUG [agent.transport.Request] (DirectAgent-247:null) Seq 1-947650696: Processing: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] }
>
> 2014-04-03 19:22:14,923 DEBUG [agent.manager.AgentAttache] (DirectAgent-247:null) Seq 1-947650696: No more commands found
>
> 2014-04-03 19:22:14,923 DEBUG [agent.transport.Request] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Seq 1-947650696: Received: { Ans: , MgmtId: 264018885718825, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
>
> 2014-04-03 19:22:14,936 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Service SecurityGroup is not supported in the network id=204
>
> 2014-04-03 19:22:14,942 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Changing active number of nics for network id=204 on -1
>
> 2014-04-03 19:22:14,949 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Asking VirtualRouter to release Nic[98-93-47d80028-8f2e-40fc-baee-08ae56d7c2cd-10.10.30.168]
>
> 2014-04-03 19:22:14,949 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Successfully released network resources for the vm VM[User|jcui02]
>
> 2014-04-03 19:22:14,949 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Successfully cleanued up resources for the vm VM[User|jcui02] in Starting state
>
> 2014-04-03 19:22:14,963 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Deploy avoids pods: [], clusters: [], hosts: [1]
>
> 2014-04-03 19:22:14,965 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_6ad9090d@3d019bf1
>
> 2014-04-03 19:22:14,965 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 2097152000
>
> 2014-04-03 19:22:14,965 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Is ROOT volume READY (pool already allocated)?: No
>
> 2014-04-03 19:22:14,965 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
>
> 2014-04-03 19:22:14,967 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) The specified host is in avoid set
>
> 2014-04-03 19:22:14,968 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Cannnot deploy to specified host, returning.
>
> 2014-04-03 19:22:14,975 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
>
> 2014-04-03 19:22:14,985 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Hosts's actual total CPU: 52800 and CPU after applying overprovisioning: 52800
>
> 2014-04-03 19:22:14,985 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Hosts's actual total RAM: 198546824448 and RAM after applying overprovisioning: 198546817024
>
> 2014-04-03 19:22:14,986 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) release cpu from host: 1, old used: 51300,reserved: 0, actual total: 52800, total with overprovisioning: 52800; new used: 50300,reserved:0; movedfromreserved: false,moveToReserveredfalse
>
> 2014-04-03 19:22:14,986 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) release mem from host: 1, old used: 112625451008,reserved: 0, total: 198546817024; new used: 110528299008,reserved:0; movedfromreserved: false,moveToReserveredfalse
>
> 2014-04-03 19:22:15,004 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) 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-04-03 19:22:15,004 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Successfully transitioned to start state for VM[User|jcui02] reservation id = ee9d9c7c-de69-48bb-95cf-5a90e86cbead
>
> 2014-04-03 19:22:15,007 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Trying to deploy VM, vm has dcId: 1 and podId: 1
>
> 2014-04-03 19:22:15,007 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Deploy avoids pods: [], clusters: [], hosts: [1]
>
> 2014-04-03 19:22:15,022 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Deploy avoids pods: [], clusters: [], hosts: [1]
>
> 2014-04-03 19:22:15,023 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_6ad9090d@3d019bf1
>
> 2014-04-03 19:22:15,023 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 1000, requested ram: 2097152000
>
> 2014-04-03 19:22:15,023 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Is ROOT volume READY (pool already allocated)?: No
>
> 2014-04-03 19:22:15,023 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Searching resources only under specified Pod: 1
>
> 2014-04-03 19:22:15,023 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
>
> 2014-04-03 19:22:15,029 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Removing from the clusterId list these clusters from avoid set: []
>
> 2014-04-03 19:22:15,037 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Checking resources in Cluster: 1 under Pod: 1
>
> 2014-04-03 19:22:15,037 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
>
> 2014-04-03 19:22:15,044 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-1-Routing], Host[-4-Routing]]
>
> 2014-04-03 19:22:15,049 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-1-Routing], Host[-4-Routing]]
>
> 2014-04-03 19:22:15,049 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=2000
>
> 2014-04-03 19:22:15,049 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Host name: xen-99, hostId: 1 is in avoid set, skipping this and trying other available hosts
>
> 2014-04-03 19:22:15,057 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Checking if host: 4 has enough capacity for requested CPU: 1000 and requested RAM: 2097152000 , cpuOverprovisioningFactor: 1.0
>
> 2014-04-03 19:22:15,062 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Hosts's actual total CPU: 52800 and CPU after applying overprovisioning: 52800
>
> 2014-04-03 19:22:15,062 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Free CPU: 800 , Requested CPU: 1000
>
> 2014-04-03 19:22:15,062 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Free RAM: 76912001024 , Requested RAM: 2097152000
>
> 2014-04-03 19:22:15,062 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) STATS: Failed to alloc resource from host: 4 reservedCpu: 0, used cpu: 52000, requested cpu: 1000, actual total cpu: 52800, total cpu with overprovisioning: 52800, reservedMem: 0, used Mem: 121634816000, requested mem: 2097152000, total Mem:198546817024 ,considerReservedCapacity?: true
>
> 2014-04-03 19:22:15,062 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Host does not have enough CPU available, cannot allocate to this host.
>
> 2014-04-03 19:22:15,062 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Not using host 4; numCpusGood: true; cpuFreqGood: true, host has capacity?false
>
> 2014-04-03 19:22:15,062 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
>
> 2014-04-03 19:22:15,062 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) No suitable hosts found
>
> 2014-04-03 19:22:15,062 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) No suitable hosts found under this Cluster: 1
>
> 2014-04-03 19:22:15,067 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Could not find suitable Deployment Destination for this VM under any clusters, returning.
>
> 2014-04-03 19:22:15,067 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Searching resources only under specified Pod: 1
>
> 2014-04-03 19:22:15,067 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
>
> 2014-04-03 19:22:15,072 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Removing from the clusterId list these clusters from avoid set: [1]
>
> 2014-04-03 19:22:15,073 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) No clusters found after removing disabled clusters and clusters in avoid list, returning.
>
> 2014-04-03 19:22:15,080 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: null
>
> 2014-04-03 19:22:15,097 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Destroying vm VM[User|jcui02] as it failed to create on Host with Id:null
>
> 2014-04-03 19:22:15,106 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) 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-04-03 19:22:15,116 WARN [apache.cloudstack.alerts] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 93, on Host with Id: null
>
> 2014-04-03 19:22:15,120 ERROR [cloud.alert.AlertManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Problem sending email alert
>
> java.lang.NullPointerException
>
> at javax.mail.internet.InternetAddress.formatAddress(InternetAddress.java:259)
>
> at javax.mail.internet.InternetAddress.toString(InternetAddress.java:238)
>
> at javax.mail.internet.MimeMessage.setHeader(MimeMessage.java:1533)
>
> at javax.mail.internet.MimeMessage.setSender(MimeMessage.java:361)
>
> at com.cloud.alert.AlertManagerImpl$EmailAlert.sendAlert(AlertManagerImpl.java:856)
>
> at com.cloud.alert.AlertManagerImpl.sendAlert(AlertManagerImpl.java:261)
>
> at com.cloud.vm.UserVmManagerImpl.updateVmStateForFailedVmCreation(UserVmManagerImpl.java:1732)
>
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2969)
>
> 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:441)
>
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>
> at java.lang.Thread.run(Thread.java:662)
>
> 2014-04-03 19:22:15,144 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-58:null) Ping from 4
>
> 2014-04-03 19:22:15,150 INFO [user.vm.DeployVMCmd] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|jcui02]Scope=interface com.cloud.dc.DataCenter; id=1
>
> 2014-04-03 19:22:15,150 INFO [user.vm.DeployVMCmd] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Unable to create a deployment for VM[User|jcui02]
>
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|jcui02]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:441)
>
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>
> at java.lang.Thread.run(Thread.java:662)
>
> 2014-04-03 19:22:15,153 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-19:job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ]) Complete async job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ], jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable to create a deployment for VM[User|jcui02]
>
> 2014-04-03 19:22:15,360 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===START=== 251.25.179.130 -- GET command=queryAsyncJobResult&jobId=0fbf7edc-00f9-486a-855f-4674a264e323&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524066197
>
> 2014-04-03 19:22:15,377 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-23:null) Async job-452 = [ 0fbf7edc-00f9-486a-855f-4674a264e323 ] completed
>
> 2014-04-03 19:22:15,384 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===END=== 251.25.179.130 -- GET command=queryAsyncJobResult&jobId=0fbf7edc-00f9-486a-855f-4674a264e323&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524066197
>
> 2014-04-03 19:22:15,468 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===START=== 251.25.179.130 -- GET command=listVirtualMachines&id=5c026edf-5e16-4447-83c9-f46d4960c6ac&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524066307
>
> 2014-04-03 19:22:15,496 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===END=== 251.25.179.130 -- GET command=listVirtualMachines&id=5c026edf-5e16-4447-83c9-f46d4960c6ac&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524066307
>
> 2014-04-03 19:22:15,619 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-332:null) Seq 4-1716453478: Response Received:
>
> 2014-04-03 19:22:15,620 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1716453478: Received: { Ans: , MgmtId: 264018885718825, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>
> 2014-04-03 19:22:16,427 INFO [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 removed accounts to cleanup
>
> 2014-04-03 19:22:16,429 INFO [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 disabled accounts to cleanup
>
> 2014-04-03 19:22:16,430 INFO [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 inactive domains to cleanup
>
> 2014-04-03 19:22:16,432 INFO [cloud.user.AccountManagerImpl] (AccountChecker-1:null) Found 0 disabled projects to cleanup
>
> 2014-04-03 19:22:16,519 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 2-1090374: Processing Seq 2-1090374: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
>
> 2014-04-03 19:22:16,522 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 2-1090374: Sending Seq 2-1090374: { Ans: , MgmtId: 264018885718825, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
>
> 2014-04-03 19:22:19,886 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null) ===START=== 251.25.179.130 -- GET command=listVirtualMachines&id=905deb2e-ee6e-4235-bc82-8c096e40b7dc&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524070744
>
> 2014-04-03 19:22:19,915 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null) ===END=== 251.25.179.130 -- GET command=listVirtualMachines&id=905deb2e-ee6e-4235-bc82-8c096e40b7dc&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524070744
>
> 2014-04-03 19:22:21,521 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-1090375: Processing Seq 2-1090375: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
>
> 2014-04-03 19:22:21,525 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-1090375: Sending Seq 2-1090375: { Ans: , MgmtId: 264018885718825, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
>
> 2014-04-03 19:22:22,597 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===START=== 251.25.179.130 -- GET command=listVirtualMachines&id=5c026edf-5e16-4447-83c9-f46d4960c6ac&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524073432
>
> 2014-04-03 19:22:22,625 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===END=== 251.25.179.130 -- GET command=listVirtualMachines&id=5c026edf-5e16-4447-83c9-f46d4960c6ac&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524073432
>
> 2014-04-03 19:22:22,705 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===START=== 251.25.179.130 -- GET command=listOsTypes&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524073557
>
> 2014-04-03 19:22:22,978 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===END=== 251.25.179.130 -- GET command=listOsTypes&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524073557
>
> 2014-04-03 19:22:24,091 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===START=== 251.25.179.130 -- GET command=listZones&id=4f8a1206-3712-4ad6-832e-f9bf430da511&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524074947
>
> 2014-04-03 19:22:24,106 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===END=== 251.25.179.130 -- GET command=listZones&id=4f8a1206-3712-4ad6-832e-f9bf430da511&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524074947
>
> 2014-04-03 19:22:24,179 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===START=== 251.25.179.130 -- GET command=listVirtualMachines&id=5c026edf-5e16-4447-83c9-f46d4960c6ac&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524075025
>
> 2014-04-03 19:22:24,207 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null) ===END=== 251.25.179.130 -- GET command=listVirtualMachines&id=5c026edf-5e16-4447-83c9-f46d4960c6ac&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524075025
>
> 2014-04-03 19:22:24,290 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START=== 251.25.179.130 -- GET command=listOsTypes&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&_=1396524075135
>
> 2014-04-03 19:22:24,347 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START=== 251.25.179.130 -- GET command=listTags&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&resourceId=5c026edf-5e16-4447-83c9-f46d4960c6ac&resourceType=UserVm&listAll=true&_=1396524075150
>
> 2014-04-03 19:22:24,361 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END=== 251.25.179.130 -- GET command=listTags&response=json&sessionkey=ISeEUBjpKbtRSQtTfMZfpMhgVBI%3D&resourceId=5c026edf-5e16-4447-83c9-f46d4960c6ac&resourceType=UserVm&listAll=true&_=1396524075150
>
> 2014-04-03 19:22:24,508 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
>
> ------------------------------------------------------------------------------------------------------------
>
>
>
> cui6522123
>
>
>
> ---
> 此电子邮件没有病毒和恶意软件,因为 avast! 防病毒保护处于活动状态。
> http://www.avast.com
?
?
?
-- 
白清杰 (Born Bai)
?
北京开源愿景信息技术有限公司
?
Mail: linuxbqj@gmail.com



---
此电子邮件没有病毒和恶意软件,因为 avast! 防病毒保护处于活动状态。
http://www.avast.com
Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message