Thank you all - indeed the probleem was at vhd-util missing on the Host. Problem solved !
Vadim. -----Original Message----- From: create...@gmail.com [mailto:create...@gmail.com] On Behalf Of Carlos Reategui Sent: Wednesday, September 18, 2013 9:05 PM To: users@cloudstack.apache.org Subject: Re: Cloudstack 4.1.1 + XCP 1.6 fresh install Hi Vadim, As Kousik mentioned, please check /opt/xensource/bin/ to see that it got copied there when the hosts were added to CS (along with several other CS scripts). It should have been. If not, that is likely the problem. On Wed, Sep 18, 2013 at 10:45 AM, Koushik Das <koushik....@citrix.com>wrote: > Yes. vhd-util needs to be copied in the hypervisor host under > /opt/xensource/bin > > -Koushik > > On 18-Sep-2013, at 8:55 PM, Vadim Kimlaychuk > <vadim.kimlayc...@elion.ee> > wrote: > > > Do you mean I have to copy vhd-util to the server where XCP is > installed? What should be the right path there? > > > > Vadim > > ________________________________________ > > From: Carlos Reátegui [create...@gmail.com] > > Sent: Wednesday, September 18, 2013 18:15 > > To: users@cloudstack.apache.org > > Cc: users@cloudstack.apache.org > > Subject: Re: Cloudstack 4.1.1 + XCP 1.6 fresh install > > > > On a recent install of CS4.1.1 + XS6.1 I thought I had vhd-util in > > the > right place but it did not get copied to the hosts. It maybe a similar > issue here. > > > > Try to copy the vhd-util to the hosts and see if things start working. > They did for me. > > > > On Sep 18, 2013, at 7:28 AM, Vadim Kimlaychuk > > <vadim.kimlayc...@elion.ee> > wrote: > > > >> Yes, its over there (I have Ubuntu 12.04 LTS) : > >> > >> root@mgmt4xcp:/home/vadim# ls -al > /usr/share/cloudstack-common/scripts/vm/hypervisor/xenserver/vh* > >> -rwxr-xr-x 1 root root 318977 Sep 18 15:55 > /usr/share/cloudstack-common/scripts/vm/hypervisor/xenserver/vhd-util > >> > >> Vadim > >> > >> -----Original Message----- > >> From: Ian Duffy [mailto:i...@ianduffy.ie] > >> Sent: Wednesday, September 18, 2013 5:26 PM > >> To: users@cloudstack.apache.org > >> Subject: Re: Cloudstack 4.1.1 + XCP 1.6 fresh install > >> > >> Did you copy over vhd-util to the correct folder and chmod +x it? > >> On 18 Sep 2013 15:13, "Vadim Kimlaychuk" > >> <vadim.kimlayc...@elion.ee> > wrote: > >> > >>> Hello all, > >>> > >>> Trying to install subj. several times I have decided to > >>> ask your help. May be someone already faced the same problem? I > >>> did the configuration according to “Installation guide” and always > >>> end up with the same problem: on system VM creation I got repeated > >>> errors > like this: > >>> > >>> 2013-09-18 16:49:21,605 DEBUG [cloud.storage.StorageManagerImpl] > >>> (consoleproxy-1:null) Creating volume: Vol[2|vm=2|ROOT] > >>> 2013-09-18 16:49:21,605 DEBUG [cloud.storage.StorageManagerImpl] > >>> (consoleproxy-1:null) Trying to create in > >>> Pool[200|NetworkFilesystem] > >>> 2013-09-18 16:49:23,381 WARN [xen.resource.CitrixResourceBase] > >>> (DirectAgent-4:null) kill_copy_process failed > >>> 2013-09-18 16:49:23,381 WARN [xen.resource.CitrixResourceBase] > >>> (DirectAgent-4:null) can not create vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> 2013-09-18 16:49:23,382 WARN [xen.resource.CitrixResourceBase] > >>> (DirectAgent-4:null) Catch Exception > >>> com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> at > >>> > com.cloud.hypervisor.xen.resource.CitrixResourceBase.copy_vhd_from_sec > ondarystorage(CitrixResourceBase.java:2707) > >>> at > >>> > com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixRes > ourceBase.java:2729) > >>> at > >>> > com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(Ci > trixResourceBase.java:501) > >>> at > >>> > com.cloud.hypervisor.xen.resource.XcpServerResource.executeRequest(Xcp > ServerResource.java:51) > >>> 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.a > ccess$101(ScheduledThreadPoolExecutor.java:165) > >>> at > >>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.r > un(ScheduledThreadPoolExecutor.java:266) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.j > ava:1146) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor. > java:615) > >>> at java.lang.Thread.run(Thread.java:679) > >>> 2013-09-18 16:49:23,384 DEBUG [agent.manager.DirectAgentAttache] > >>> (DirectAgent-4:null) Seq 1-1333067786: Response Received: > >>> 2013-09-18 16:49:23,385 DEBUG [agent.transport.Request] > >>> (DirectAgent-4:null) Seq 1-1333067786: Processing: { Ans: , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 110, > >>> [{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result > >>> ":fa > >>> lse,"details":"Catch Exception > >>> com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr c6e55039-1fb0-5e5d-37d5-118a9ac3abb6","wait":0}}] } > >>> 2013-09-18 16:49:23,385 DEBUG [agent.transport.Request] > >>> (secstorage-1:null) Seq 1-1333067786: Received: { Ans: , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 110, { > >>> PrimaryStorageDownloadAnswer } } > >>> 2013-09-18 16:49:23,385 DEBUG [agent.manager.AgentManagerImpl] > >>> (secstorage-1:null) Details from executing class > >>> com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Catch > >>> Exception com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> 2013-09-18 16:49:23,386 DEBUG [cloud.template.TemplateManagerImpl] > >>> (secstorage-1:null) Template 1 download to pool 200 failed due to > >>> Catch Exception com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> 2013-09-18 16:49:23,386 DEBUG [cloud.template.TemplateManagerImpl] > >>> (secstorage-1:null) Downloading 1 via 1 > >>> 2013-09-18 16:49:23,394 DEBUG [agent.manager.AgentAttache] > >>> (DirectAgent-4:null) Seq 1-1333067786: No more commands found > >>> 2013-09-18 16:49:23,411 DEBUG [agent.transport.Request] > >>> (secstorage-1:null) Seq 1-1333067787: Sending { Cmd , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 100111, > >>> [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/964f3 > >>> 62d- > >>> c1cf-3e3b-a5fc-c013777b0e36","poolUuid":"964f362d-c1cf-3e3b-a5fc-c > >>> 0137 > >>> 77b0e36","poolId":200,"primaryPool":{"id":200,"uuid":"964f362d-c1c > >>> f-3e > >>> 3b-a5fc-c013777b0e36","host":"192.168.107.142","path":"/export/pri > >>> mary > >>> ","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"n > >>> fs:/ / > >>> 192.168.107.142/export/secondary","primaryStorageUrl":"nfs:// > >>> 192.168.107.142/export/primary","url":"nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/","format":"VHD > >>> ","a ccountId":1,"name":"routing-1","wait":10800}}] > >>> } > >>> 2013-09-18 16:49:23,412 DEBUG [agent.transport.Request] > >>> (secstorage-1:null) Seq 1-1333067787: Executing: { Cmd , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 100111, > >>> [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/964f3 > >>> 62d- > >>> c1cf-3e3b-a5fc-c013777b0e36","poolUuid":"964f362d-c1cf-3e3b-a5fc-c > >>> 0137 > >>> 77b0e36","poolId":200,"primaryPool":{"id":200,"uuid":"964f362d-c1c > >>> f-3e > >>> 3b-a5fc-c013777b0e36","host":"192.168.107.142","path":"/export/pri > >>> mary > >>> ","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"n > >>> fs:/ / > >>> 192.168.107.142/export/secondary","primaryStorageUrl":"nfs:// > >>> 192.168.107.142/export/primary","url":"nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/","format":"VHD > >>> ","a ccountId":1,"name":"routing-1","wait":10800}}] > >>> } > >>> 2013-09-18 16:49:23,412 DEBUG [agent.manager.DirectAgentAttache] > >>> (DirectAgent-5:null) Seq 1-1333067787: Executing request > >>> 2013-09-18 16:49:25,604 WARN [xen.resource.CitrixResourceBase] > >>> (DirectAgent-5:null) kill_copy_process failed > >>> 2013-09-18 16:49:25,605 WARN [xen.resource.CitrixResourceBase] > >>> (DirectAgent-5:null) can not create vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> 2013-09-18 16:49:25,605 WARN [xen.resource.CitrixResourceBase] > >>> (DirectAgent-5:null) Catch Exception > >>> com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> at > >>> > com.cloud.hypervisor.xen.resource.CitrixResourceBase.copy_vhd_from_sec > ondarystorage(CitrixResourceBase.java:2707) > >>> at > >>> > com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixRes > ourceBase.java:2729) > >>> at > >>> > com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(Ci > trixResourceBase.java:501) > >>> at > >>> > com.cloud.hypervisor.xen.resource.XcpServerResource.executeRequest(Xcp > ServerResource.java:51) > >>> 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.a > ccess$101(ScheduledThreadPoolExecutor.java:165) > >>> at > >>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.r > un(ScheduledThreadPoolExecutor.java:266) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.j > ava:1146) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor. > java:615) > >>> at java.lang.Thread.run(Thread.java:679) > >>> 2013-09-18 16:49:25,606 DEBUG [agent.manager.DirectAgentAttache] > >>> (DirectAgent-5:null) Seq 1-1333067787: Response Received: > >>> 2013-09-18 16:49:25,607 DEBUG [agent.transport.Request] > >>> (DirectAgent-5:null) Seq 1-1333067787: Processing: { Ans: , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 110, > >>> [{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result > >>> ":fa > >>> lse,"details":"Catch Exception > >>> com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr c6e55039-1fb0-5e5d-37d5-118a9ac3abb6","wait":0}}] } > >>> 2013-09-18 16:49:25,607 DEBUG [agent.transport.Request] > >>> (secstorage-1:null) Seq 1-1333067787: Received: { Ans: , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 110, { > >>> PrimaryStorageDownloadAnswer } } > >>> 2013-09-18 16:49:25,607 DEBUG [agent.manager.AgentManagerImpl] > >>> (secstorage-1:null) Details from executing class > >>> com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Catch > >>> Exception com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> 2013-09-18 16:49:25,607 DEBUG [cloud.template.TemplateManagerImpl] > >>> (secstorage-1:null) Template 1 download to pool 200 failed due to > >>> Catch Exception com.cloud.utils.exception.CloudRuntimeException on > >>> host:e6a339ee-521c-4c67-ac55-cbd256607150 for template: nfs:// > >>> 192.168.107.142/export/secondary/template/tmpl/1/1/ due to > >>> com.cloud.utils.exception.CloudRuntimeException: can not create > >>> vdi in sr > >>> c6e55039-1fb0-5e5d-37d5-118a9ac3abb6 > >>> 2013-09-18 16:49:25,608 DEBUG [cloud.template.TemplateManagerImpl] > >>> (secstorage-1:null) Template 1 is not found on and can not be > >>> downloaded to pool 200 > >>> 2013-09-18 16:49:25,608 DEBUG [cloud.storage.StorageManagerImpl] > >>> (secstorage-1:null) Cannot use this pool > >>> Pool[200|NetworkFilesystem] because we can't propagate template > >>> Tmpl[1-VHD-routing-1 > >>> 2013-09-18 16:49:25,612 DEBUG [agent.manager.AgentAttache] > >>> (DirectAgent-5:null) Seq 1-1333067787: No more commands found > >>> 2013-09-18 16:49:25,618 INFO [cloud.vm.VirtualMachineManagerImpl] > >>> (secstorage-1:null) Unable to contact resource. > >>> com.cloud.exception.StorageUnavailableException: Resource > >>> [StoragePool:200] is unreachable: Unable to create Vol[1|vm=1|ROOT] > >>> at > >>> > com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3 > 488) > >>> at > >>> > com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMana > gerImpl.java:748) > >>> at > >>> > com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl > .java:471) > >>> at > >>> > com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl > .java:464) > >>> at > >>> > com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorag > eVm(SecondaryStorageManagerImpl.java:269) > >>> at > >>> > com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity( > SecondaryStorageManagerImpl.java:696) > >>> at > >>> > com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(Sec > ondaryStorageManagerImpl.java:1307) > >>> at > >>> > com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Premi > umSecondaryStorageManagerImpl.java:121) > >>> at > >>> > com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Premi > umSecondaryStorageManagerImpl.java:52) > >>> at > >>> com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104) > >>> at > >>> > com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:3 > 3) > >>> at > >>> > com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java: > 81) > >>> at > >>> com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72) > >>> at > >>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > >>> at > >>> > java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java: > 351) > >>> at > >>> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) > >>> at > >>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.a > ccess$201(ScheduledThreadPoolExecutor.java:165) > >>> at > >>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.r > un(ScheduledThreadPoolExecutor.java:267) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.j > ava:1146) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor. > java:615) > >>> at java.lang.Thread.run(Thread.java:679) > >>> 2013-09-18 16:49:25,625 DEBUG [cloud.vm.VirtualMachineManagerImpl] > >>> (secstorage-1:null) Cleaning up resources for the vm > >>> VM[SecondaryStorageVm|s-1-VM] in Starting state > >>> 2013-09-18 16:49:25,627 DEBUG [agent.transport.Request] > >>> (secstorage-1:null) Seq 1-1333067788: Sending { Cmd , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 100111, > >>> [{"StopCommand":{"isProxy":false,"vmName":"s-1-VM","wait":0}}] } > >>> 2013-09-18 16:49:25,628 DEBUG [agent.transport.Request] > >>> (secstorage-1:null) Seq 1-1333067788: Executing: { Cmd , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 100111, > >>> [{"StopCommand":{"isProxy":false,"vmName":"s-1-VM","wait":0}}] } > >>> 2013-09-18 16:49:25,628 DEBUG [agent.manager.DirectAgentAttache] > >>> (DirectAgent-6:null) Seq 1-1333067788: Executing request > >>> 2013-09-18 16:49:25,640 DEBUG [cloud.api.ApiServlet] > >>> (catalina-exec-5:null) ===START=== 192.168.107.75 -- GET > >>> > >>> command=listSystemVms&response=json&sessionkey=zvxEneqJ%2FkCeNEEDU > >>> kDxJ > >>> iXnhBc%3D&_=1379512165664 > >>> 2013-09-18 16:49:25,689 INFO [xen.resource.CitrixResourceBase] > >>> (DirectAgent-6:null) VM does not exist on > >>> XenServere6a339ee-521c-4c67-ac55-cbd256607150 > >>> 2013-09-18 16:49:25,690 DEBUG [agent.manager.DirectAgentAttache] > >>> (DirectAgent-6:null) Seq 1-1333067788: Response Received: > >>> 2013-09-18 16:49:25,690 DEBUG [agent.transport.Request] > >>> (DirectAgent-6:null) Seq 1-1333067788: Processing: { Ans: , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 110, > >>> [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not > >>> exist","wait":0}}] } > >>> 2013-09-18 16:49:25,690 DEBUG [agent.transport.Request] > >>> (secstorage-1:null) Seq 1-1333067788: Received: { Ans: , MgmtId: > >>> 8796752993784, via: 1, Ver: v1, Flags: 110, { StopAnswer } } > >>> 2013-09-18 16:49:25,692 DEBUG [agent.manager.AgentAttache] > >>> (DirectAgent-6:null) Seq 1-1333067788: No more commands found > >>> 2013-09-18 16:49:25,716 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VirtualRouter to release > >>> Nic[1-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-192.168.107.117] > >>> 2013-09-18 16:49:25,716 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking Ovs to release > >>> Nic[1-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-192.168.107.117] > >>> 2013-09-18 16:49:25,716 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking SecurityGroupProvider to release > >>> Nic[1-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-192.168.107.117] > >>> 2013-09-18 16:49:25,716 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VpcVirtualRouter to release > >>> Nic[1-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-192.168.107.117] > >>> 2013-09-18 16:49:25,716 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking NiciraNvp to release > >>> Nic[1-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-192.168.107.117] > >>> 2013-09-18 16:49:25,716 DEBUG [network.element.NiciraNvpElement] > >>> (secstorage-1:null) Checking if NiciraNvpElement can handle > >>> service Connectivity on network defaultGuestNetwork > >>> 2013-09-18 16:49:25,721 DEBUG [network.guru.ControlNetworkGuru] > >>> (secstorage-1:null) Released nic: NicProfile[2-1-null-null-null > >>> 2013-09-18 16:49:25,724 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VirtualRouter to release > >>> Nic[2-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,725 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking Ovs to release > >>> Nic[2-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,725 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking SecurityGroupProvider to release > >>> Nic[2-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,725 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VpcVirtualRouter to release > >>> Nic[2-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,725 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking NiciraNvp to release > >>> Nic[2-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,725 DEBUG [network.element.NiciraNvpElement] > >>> (secstorage-1:null) Checking if NiciraNvpElement can handle > >>> service Connectivity on network null > >>> 2013-09-18 16:49:25,733 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] > >>> (secstorage-1:null) Releasing ip address for > >>> reservationId=7ab6fd6f-027f-4e3d-b70d-78474d479424, instance=3 > >>> 2013-09-18 16:49:25,735 DEBUG [network.guru.PodBasedNetworkGuru] > >>> (secstorage-1:null) Released nic: NicProfile[3-1-null-null-null > >>> 2013-09-18 16:49:25,740 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VirtualRouter to release > >>> Nic[3-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,740 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking Ovs to release > >>> Nic[3-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,740 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking SecurityGroupProvider to release > >>> Nic[3-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,740 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VpcVirtualRouter to release > >>> Nic[3-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,740 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking NiciraNvp to release > >>> Nic[3-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,740 DEBUG [network.element.NiciraNvpElement] > >>> (secstorage-1:null) Checking if NiciraNvpElement can handle > >>> service Connectivity on network null > >>> 2013-09-18 16:49:25,749 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] > >>> (secstorage-1:null) Releasing ip address for > >>> reservationId=7ab6fd6f-027f-4e3d-b70d-78474d479424, instance=4 > >>> 2013-09-18 16:49:25,751 DEBUG [network.guru.PodBasedNetworkGuru] > >>> (secstorage-1:null) Released nic: NicProfile[4-1-null-null-null > >>> 2013-09-18 16:49:25,753 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VirtualRouter to release > >>> Nic[4-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,753 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking Ovs to release > >>> Nic[4-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,753 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking SecurityGroupProvider to release > >>> Nic[4-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,753 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking VpcVirtualRouter to release > >>> Nic[4-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,753 DEBUG [cloud.network.NetworkManagerImpl] > >>> (secstorage-1:null) Asking NiciraNvp to release > >>> Nic[4-1-7ab6fd6f-027f-4e3d-b70d-78474d479424-null] > >>> 2013-09-18 16:49:25,753 DEBUG [network.element.NiciraNvpElement] > >>> (secstorage-1:null) Checking if NiciraNvpElement can handle > >>> service Connectivity on network null > >>> 2013-09-18 16:49:25,753 DEBUG [cloud.vm.VirtualMachineManagerImpl] > >>> (secstorage-1:null) Successfully released network resources for > >>> the vm VM[SecondaryStorageVm|s-1-VM] > >>> 2013-09-18 16:49:25,754 DEBUG [cloud.vm.VirtualMachineManagerImpl] > >>> (secstorage-1:null) Successfully cleanued up resources for the vm > >>> VM[SecondaryStorageVm|s-1-VM] in Starting state > >>> 2013-09-18 16:49:25,756 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) DeploymentPlanner allocation algorithm: random > >>> 2013-09-18 16:49:25,756 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) Trying to allocate a host and storage pools > >>> from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: > >>> 268435456 > >>> 2013-09-18 16:49:25,756 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) Is ROOT volume READY (pool already > >>> allocated)?: No > >>> 2013-09-18 16:49:25,756 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) Searching all possible resources under this Zone: > >>> 1 > >>> 2013-09-18 16:49:25,759 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) Listing clusters in order of aggregate > >>> capacity, that have (atleast one host with) enough CPU and RAM > >>> capacity under this Zone: 1 > >>> 2013-09-18 16:49:25,762 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) CPUOverprovisioningFactor considered: 1.0 > >>> 2013-09-18 16:49:25,776 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) Checking resources in Cluster: 1 under Pod: 1 > >>> 2013-09-18 16:49:25,776 DEBUG [allocator.impl.FirstFitAllocator] > >>> (secstorage-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 > >>> pod:1 > >>> cluster:1 > >>> 2013-09-18 16:49:25,779 DEBUG [allocator.impl.FirstFitAllocator] > >>> (secstorage-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 > >>> hosts to check for allocation: [Host[-1-Routing]] > >>> 2013-09-18 16:49:25,788 DEBUG [allocator.impl.FirstFitAllocator] > >>> (secstorage-1:FirstFitRoutingAllocator) Found 1 hosts for > >>> allocation after > >>> prioritization: [Host[-1-Routing]] > >>> 2013-09-18 16:49:25,789 DEBUG [allocator.impl.FirstFitAllocator] > >>> (secstorage-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, > >>> Ram=256 > >>> 2013-09-18 16:49:25,789 DEBUG [allocator.impl.FirstFitAllocator] > >>> (secstorage-1:FirstFitRoutingAllocator) Host name: xen4export, hostId: > >>> 1 is in avoid set, skipping this and trying other available hosts > >>> 2013-09-18 16:49:25,789 DEBUG [allocator.impl.FirstFitAllocator] > >>> (secstorage-1:FirstFitRoutingAllocator) Host Allocator returning 0 > >>> suitable hosts > >>> 2013-09-18 16:49:25,789 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) No suitable hosts found > >>> 2013-09-18 16:49:25,789 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) No suitable hosts found under this Cluster: 1 > >>> 2013-09-18 16:49:25,789 DEBUG [cloud.deploy.FirstFitPlanner] > >>> (secstorage-1:null) Could not find suitable Deployment Destination > >>> for this VM under any clusters, returning. > >>> 2013-09-18 16:49:25,807 DEBUG [cloud.capacity.CapacityManagerImpl] > >>> (secstorage-1:null) 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 > >>> 2013-09-18 16:49:25,820 DEBUG [cloud.capacity.CapacityManagerImpl] > >>> (secstorage-1:null) Hosts's actual total CPU: 11732 and CPU after > >>> applying > >>> overprovisioning: 11732 > >>> 2013-09-18 16:49:25,820 DEBUG [cloud.capacity.CapacityManagerImpl] > >>> (secstorage-1:null) release cpu from host: 1, old used: 1000,reserved: > >>> 0, actual total: 11732, total with overprovisioning: 11732; new used: > >>> 500,reserved:0; movedfromreserved: false,moveToReserveredfalse > >>> 2013-09-18 16:49:25,820 DEBUG [cloud.capacity.CapacityManagerImpl] > >>> (secstorage-1:null) release mem from host: 1, old used: > >>> 1342177280,reserved: 0, total: 12056611392; new used: > >>> 1073741824,reserved:0; movedfromreserved: > >>> false,moveToReserveredfalse > >>> 2013-09-18 16:49:25,825 WARN > >>> [storage.secondary.SecondaryStorageManagerImpl] > >>> (secstorage-1:null) Exception while trying to start secondary > >>> storage vm > >>> com.cloud.exception.InsufficientServerCapacityException: Unable to > >>> create a deployment for > >>> VM[SecondaryStorageVm|s-1-VM]Scope=interface > >>> com.cloud.dc.DataCenter; id=1 > >>> at > >>> > com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMana > gerImpl.java:728) > >>> at > >>> > com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl > .java:471) > >>> at > >>> > com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl > .java:464) > >>> at > >>> > com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorag > eVm(SecondaryStorageManagerImpl.java:269) > >>> at > >>> > com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity( > SecondaryStorageManagerImpl.java:696) > >>> at > >>> > com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(Sec > ondaryStorageManagerImpl.java:1307) > >>> at > >>> > com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Premi > umSecondaryStorageManagerImpl.java:121) > >>> at > >>> > com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Premi > umSecondaryStorageManagerImpl.java:52) > >>> at > >>> com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104) > >>> at > >>> > com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:3 > 3) > >>> at > >>> > com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java: > 81) > >>> at > >>> com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72) > >>> at > >>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > >>> at > >>> > java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java: > 351) > >>> at > >>> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) > >>> at > >>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.a > ccess$201(ScheduledThreadPoolExecutor.java:165) > >>> at > >>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.r > un(ScheduledThreadPoolExecutor.java:267) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.j > ava:1146) > >>> at > >>> > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor. > java:615) > >>> at java.lang.Thread.run(Thread.java:679) > >>> > >>> Please, help to find the root of the problem > >>> > >>> Thank you, > >>> > >>> Vadim Kimlaychuk > >>> > >
