Hello again,
I think I may have found where the issue comes from. Tracing the following
error:
-----------
2012-11-12 22:10:50,614 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-1:null) <volume>
<name>v-2-VM-patchdisk</name>
<capacity >10485760</capacity>
<target>
<format type='raw'/>
<permissions><mode>0744</mode></permissions></target>
</volume>
2012-11-12 22:10:50,618 WARN [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-1:null) Exception
com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: cannot create path
'/mnt/95c9032d-3666-316e-a97f-546b201bd526/v-2-VM-patchdisk': Invalid
argument
-----------
into libvirtd.log I decided to try to create manually a storage based on
the XML data sent by MS. So I've put:
-------------
<volume>
<name>v-2-VM-patchdisk</name>
<capacity >10485760</capacity>
<target>
<format type='raw'/>
<permissions><mode>0744</mode></permissions></target>
</volume>
-----------
into a XML file and tried to create a new volume into the pool mounted by
MS and I got the same error: Invalid argument.
Reading the libvirt documentation and doing tests with the XML file, I
found out that the error is generated because the <owner> and <group> keys
are missing from inside the <permissions> key.
Somehow these keys are missing or the command is not properly build when it
is sent from Server to Host.
If anybody has any idea about this, please help me.
Thank you !
On Mon, Nov 12, 2012 at 10:20 PM, Mihai Siminica <mihai.simin...@husi.ro>wrote:
> To have a proper understanding of my issue I have cleaned the DB and
> initialized the MS again
>
> My configuration:
> Both servers have Centos 6.3 x86_64
> Hypervisor: KVM
>
>
> On hypervisor host:
>
> - I have 4 NICs but I use only 2 for the beginning :
> eth0 has no IP but is connected to the switch
> DEVICE=eth0
> HWADDR=1C:C1:DE:71:AF:18
> ONBOOT=yes
> HOTPLUG=no
> BOOTPROTO=none
> TYPE=Ethernet
>
> eth0.100:
> DEVICE=eth0.100
> ONBOOT=yes
> HOTPLUG=no
> BOOTPROTO=none
> TYPE=Ethernet
> VLAN=yes
> BRIDGE=cloudbr0
>
> eth0.200:
> DEVICE=eth0.200
> ONBOOT=yes
> HOTPLUG=no
> BOOTPROTO=none
> TYPE=Ethernet
> VLAN=yes
> BRIDGE=cloudbr1
>
> eth1:
> DEVICE=eth1
> BOOTPROTO=none
> HWADDR=1c:c1:de:71:af:19
> ONBOOT=yes
> TYPE=Ethernet
> IPV6INIT=no
> USERCTL=no
> IPADDR=192.168.1.41
> NETMASK=255.255.255.0
> GATEWAY=192.168.1.252
> DNS1=192.168.1.26
>
> cloudbr0:
> DEVICE=cloudbr0
> TYPE=Bridge
> ONBOOT=yes
> BOOTPROTO=none
> IPV6INIT=no
> IPV6_AUTOCONF=no
> DELAY=5
> STP=yes
>
> cloudbr1:
> DEVICE=cloudbr1
> TYPE=Bridge
> ONBOOT=yes
> BOOTPROTO=none
> IPV6INIT=no
> IPV6_AUTOCONF=no
> DELAY=5
> STP=yes
>
>
>
> On Management Server:
> - Mounts:
> 192.168.1.42:/var/export/primary/ on /mnt/primary type nfs
> (rw,vers=4,addr=192.168.1.42,clientaddr=192.168.1.42)
> 192.168.1.42:/var/export/secondary on /mnt/secondary type nfs
> (rw,vers=4,addr=192.168.1.42,clientaddr=192.168.1.42)
>
> Network Configuration:
>
> eth0 has no IP but is connected to the switch:
> DEVICE=eth0
> HWADDR=1C:C1:DE:71:AF:18
> ONBOOT=yes
> HOTPLUG=no
> BOOTPROTO=none
> TYPE=Ethernet
>
> eth1:
> DEVICE=eth1
> BOOTPROTO=none
> HWADDR=1c:c1:de:71:af:19
> ONBOOT=yes
> TYPE=Ethernet
> IPV6INIT=no
> USERCTL=no
> IPADDR=192.168.1.41
> NETMASK=255.255.255.0
> GATEWAY=192.168.1.252
> DNS1=192.168.1.26
>
> Started the wizard again, everything went smooth until the creation of
> System VMs.
> In the MS log I get this WARN:
> --------------------------------------
> 2012-11-12 22:09:51,212 WARN
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null)
> Exception while trying to start secondary storage vm
> com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
> unreachable: Host 1: Unable to start instance due to Unable to get answer
> that is of class com.cloud.agent.api.StartAnswer
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465)
> at
> com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:257)
> at
> com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:684)
> at
> com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1310)
> at
> com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:119)
> at
> com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
> at
> com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:106)
> at
> com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34)
> at
> com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73)
> 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.access$201(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to get
> answer that is of class com.cloud.agent.api.StartAnswer
> at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
> ... 20 more
> --------------------------------------
>
>
>
>
>
>
> On the hypervisor host in agent.log I get this:
> --------------------------------------------------------------------------
> 2012-11-12 22:10:50,423 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-4:null) Request:Seq 1-597426497: { Cmd , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 100111,
> [{"storage.CreateCommand":{"volId":28,"pool":{"id":200,"uuid":"95c9032d-3666-316e-a97f-546b201bd526","host":"192.168.1.42","path":"/var/export/primary","port":2049,"type":"NetworkFilesystem"},"diskCharacteristics":{"size":0,"tags":[],"type":"ROOT","name":"ROOT-28","useLocalStorage":false,"recreatable":true,"diskOfferingId":7,"volumeId":28,"hyperType":"KVM"},"templateUrl":"bb6d5a19-331b-4569-8899-9b057cf112bf","wait":0}}]
> }
> 2012-11-12 22:10:50,423 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-4:null) Processing command:
> com.cloud.agent.api.storage.CreateCommand
> 2012-11-12 22:10:50,455 DEBUG [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-4:null) <volume>
> <name>b2c94cab-1d23-438b-a171-1cd65a268ef4</name>
> <capacity >2097152000</capacity>
> <target>
> <format type='qcow2'/>
> <permissions><mode>0744</mode></permissions></target>
> </volume>
>
> 2012-11-12 22:10:50,477 DEBUG [utils.script.Script]
> (agentRequest-Handler-4:null) Executing: /bin/bash -c qemu-img create -f
> qcow2 -b
> /mnt/95c9032d-3666-316e-a97f-546b201bd526/bb6d5a19-331b-4569-8899-9b057cf112bf
> /mnt/95c9032d-3666-316e-a97f-546b201bd526/b2c94cab-1d23-438b-a171-1cd65a268ef4
>
> 2012-11-12 22:10:50,499 DEBUG [utils.script.Script]
> (agentRequest-Handler-4:null) Execution is successful.
> 2012-11-12 22:10:50,500 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-4:null) Seq 1-597426497: { Ans: , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 110,
> [{"storage.CreateAnswer":{"volume":{"id":28,"name":"/var/export/primary","mountPoint":"b2c94cab-1d23-438b-a171-1cd65a268ef4","path":"b2c94cab-1d23-438b-a171-1cd65a268ef4","size":0,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"95c9032d-3666-316e-a97f-546b201bd526","deviceId":0},"requestTemplateReload":false,"result":true,"wait":0}}]
> }
> 2012-11-12 22:10:50,506 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-1:null) Request:Seq 1-597426498: { Cmd , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 100111,
> [{"StartCommand":{"vm":{"id":2,"name":"v-2-VM","type":"ConsoleProxy","cpus":1,"speed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Debian
> GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy
> host=192.168.1.42 port=8250 name=v-2-VM premium=true zone=1 pod=1
> guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=192.168.1.226
> eth2mask=255.255.255.0 gateway=192.168.1.252 eth0ip=169.254.3.51
> eth0mask=255.255.0.0 eth1ip=192.168.1.43 eth1mask=255.255.255.0 mgmtcidr=
> 192.168.1.0/24 localgw=192.168.1.252 internaldns1=192.168.1.26
> dns1=192.168.1.26","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"37761066f1590929","params":{},"uuid":"be997b4b-f102-46d8-b760-36a1e443a57e","disks":[{"id":2,"name":"ROOT-2","mountPoint":"/var/export/primary","path":"dbb5ba81-f3b4-4dd5-9df5-a4d4f173a28b","size":0,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"95c9032d-3666-316e-a97f-546b201bd526","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"58ab5946-e567-49f9-b1d6-7e9f84586967","ip":"192.168.1.226","netmask":"255.255.255.0","gateway":"192.168.1.252","mac":"06:83:50:00:00:6e","dns1":"192.168.1.26","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"5f262b60-e9a1-4572-8d92-6112fd39db51","ip":"169.254.3.51","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:33","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"6e464b24-95e0-472d-97a3-f7f84ecc801e","ip":"192.168.1.43","netmask":"255.255.255.0","gateway":"192.168.1.252","mac":"06:e1:98:00:00:03","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.3.51","port":3922,"interval":6,"retries":100,"name":"v-2-VM","wait":0}}]
> }
> 2012-11-12 22:10:50,506 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-1:null) Processing command:
> com.cloud.agent.api.StartCommand
> 2012-11-12 22:10:50,614 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-1:null) generating new patch disk for v-2-VM since
> none was found
> 2012-11-12 22:10:50,614 DEBUG [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-1:null) <volume>
> <name>v-2-VM-patchdisk</name>
> <capacity >10485760</capacity>
> <target>
> <format type='raw'/>
> <permissions><mode>0744</mode></permissions></target>
> </volume>
>
> 2012-11-12 22:10:50,618 WARN [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-1:null) Exception
> com.cloud.utils.exception.CloudRuntimeException:
> org.libvirt.LibvirtException: cannot create path
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/v-2-VM-patchdisk': Invalid
> argument
> at
> com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createPhysicalDisk(LibvirtStorageAdaptor.java:556)
> at
> com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.createPhysicalDisk(LibvirtStoragePool.java:101)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createPatchVbd(LibvirtComputingResource.java:2980)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2943)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
> at com.cloud.agent.Agent.processRequest(Agent.java:518)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
> at com.cloud.utils.nio.Task.run(Task.java:83)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2012-11-12 22:10:50,618 WARN [cloud.agent.Agent]
> (agentRequest-Handler-1:null) Caught:
> java.lang.NullPointerException
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
> at com.cloud.agent.Agent.processRequest(Agent.java:518)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
> at com.cloud.utils.nio.Task.run(Task.java:83)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2012-11-12 22:10:50,619 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-1:null) Seq 1-597426498: { Ans: , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 110,
> [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)\n\tat
> com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat
> com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat
> com.cloud.utils.nio.Task.run(Task.java:83)\n\tat
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)\n\tat
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)\n\tat
> java.lang.Thread.run(Thread.java:679)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped
> by previous failure","wait":0}}] }
> 2012-11-12 22:10:50,665 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-3:null) Request:Seq 1-597426499: { Cmd , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 100111,
> [{"StartCommand":{"vm":{"id":28,"name":"s-28-VM","type":"SecondaryStorageVm","cpus":1,"speed":500,"minRam":268435456,"maxRam":268435456,"arch":"x86_64","os":"Debian
> GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=secstorage
> host=192.168.1.42 port=8250 name=s-28-VM zone=1 pod=1 guid=s-28-VM
> resource=com.cloud.storage.resource.NfsSecondaryStorageResource
> instance=SecStorage sslcopy=true role=templateProcessor mtu=1500
> eth2ip=192.168.1.154 eth2mask=255.255.255.0 gateway=192.168.1.252
> eth0ip=169.254.3.185 eth0mask=255.255.0.0 eth1ip=192.168.1.42
> eth1mask=255.255.255.0 mgmtcidr=192.168.1.0/24 localgw=192.168.1.252
> private.network.device=eth1 eth3ip=192.168.1.44 eth3mask=255.255.255.0
> storageip=192.168.1.44 storagenetmask=255.255.255.0
> storagegateway=192.168.1.252 internaldns1=192.168.1.26
> dns1=192.168.1.26","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"8fcfa8f770efcd74","params":{},"uuid":"8a58fc9d-5a4c-4e98-abbe-79753ca3ad14","disks":[{"id":28,"name":"/var/export/primary","mountPoint":"b2c94cab-1d23-438b-a171-1cd65a268ef4","path":"b2c94cab-1d23-438b-a171-1cd65a268ef4","size":0,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"95c9032d-3666-316e-a97f-546b201bd526","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"7f064bd2-07ed-4011-ba8f-6d1ad6c0c2ba","ip":"192.168.1.154","netmask":"255.255.255.0","gateway":"192.168.1.252","mac":"06:4d:7c:00:00:26","dns1":"192.168.1.26","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"c55a4c3c-3841-44ec-8975-1bd80e287007","ip":"169.254.3.185","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:b9","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"2a490f9b-5f23-45f4-ad20-06f3e41d2954","ip":"192.168.1.42","netmask":"255.255.255.0","gateway":"192.168.1.252","mac":"06:6b:6a:00:00:02","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"27baa04d-b6e7-4244-91f1-b5a280d92af1","ip":"192.168.1.44","netmask":"255.255.255.0","gateway":"192.168.1.252","mac":"06:b5:44:00:00:04","broadcastType":"Native","type":"Storage","isSecurityGroupEnabled":false}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.3.185","port":3922,"interval":6,"retries":100,"name":"s-28-VM","wait":0}}]
> }
> 2012-11-12 22:10:50,665 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-3:null) Processing command:
> com.cloud.agent.api.StartCommand
> 2012-11-12 22:10:50,774 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-3:null) generating new patch disk for s-28-VM since
> none was found
> 2012-11-12 22:10:50,774 DEBUG [kvm.storage.LibvirtStorageAdaptor]
> (agentRequest-Handler-3:null) <volume>
> <name>s-28-VM-patchdisk</name>
> <capacity >10485760</capacity>
> <target>
> <format type='raw'/>
> <permissions><mode>0744</mode></permissions></target>
> </volume>
>
> 2012-11-12 22:10:50,778 WARN [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-3:null) Exception
> com.cloud.utils.exception.CloudRuntimeException:
> org.libvirt.LibvirtException: cannot create path
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/s-28-VM-patchdisk': Invalid
> argument
> at
> com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createPhysicalDisk(LibvirtStorageAdaptor.java:556)
> at
> com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.createPhysicalDisk(LibvirtStoragePool.java:101)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createPatchVbd(LibvirtComputingResource.java:2980)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:2943)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2808)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
> at com.cloud.agent.Agent.processRequest(Agent.java:518)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
> at com.cloud.utils.nio.Task.run(Task.java:83)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2012-11-12 22:10:50,778 WARN [cloud.agent.Agent]
> (agentRequest-Handler-3:null) Caught:
> java.lang.NullPointerException
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)
> at com.cloud.agent.Agent.processRequest(Agent.java:518)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
> at com.cloud.utils.nio.Task.run(Task.java:83)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2012-11-12 22:10:50,779 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-3:null) Seq 1-597426499: { Ans: , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 110,
> [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3922)\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2709)\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2834)\n\tat
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1035)\n\tat
> com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat
> com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat
> com.cloud.utils.nio.Task.run(Task.java:83)\n\tat
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)\n\tat
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)\n\tat
> java.lang.Thread.run(Thread.java:679)\n","wait":0}},{"Answer":{"result":false,"details":"Stopped
> by previous failure","wait":0}}] }
> 2012-11-12 22:10:50,821 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-2:null) Request:Seq 1-597426500: { Cmd , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"v-2-VM","wait":0}}] }
> 2012-11-12 22:10:50,822 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-2:null) Processing command:
> com.cloud.agent.api.StopCommand
> 2012-11-12 22:10:50,824 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Failed to get dom xml:
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '1422832d-be18-352a-a08a-9bbff40e0d14'
> 2012-11-12 22:10:50,825 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Failed to get dom xml:
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '1422832d-be18-352a-a08a-9bbff40e0d14'
> 2012-11-12 22:10:50,826 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Executing:
> /usr/lib64/cloud/common/scripts/vm/network/security_group.py
> destroy_network_rules_for_vm --vmname v-2-VM
> 2012-11-12 22:10:50,959 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Execution is successful.
> 2012-11-12 22:10:50,959 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Try to stop the vm at first
> 2012-11-12 22:10:50,961 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Failed to stop VM :v-2-VM :
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '1422832d-be18-352a-a08a-9bbff40e0d14'
> at org.libvirt.ErrorHandler.processError(Unknown Source)
> at org.libvirt.Connect.processError(Unknown Source)
> at org.libvirt.Connect.domainLookupByUUIDString(Unknown Source)
> at org.libvirt.Connect.domainLookupByUUID(Unknown Source)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.stopVM(LibvirtComputingResource.java:3726)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.stopVM(LibvirtComputingResource.java:3658)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2586)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:965)
> at com.cloud.agent.Agent.processRequest(Agent.java:518)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
> at com.cloud.utils.nio.Task.run(Task.java:83)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2012-11-12 22:10:50,962 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Failed to get vm status:Domain not found: no
> domain with matching uuid '1422832d-be18-352a-a08a-9bbff40e0d14'
> 2012-11-12 22:10:50,963 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Failed to get vm status:Domain not found: no
> domain with matching uuid '1422832d-be18-352a-a08a-9bbff40e0d14'
> 2012-11-12 22:10:50,964 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Failed to get vm status:Domain not found: no
> domain with matching uuid '1422832d-be18-352a-a08a-9bbff40e0d14'
> 2012-11-12 22:10:50,965 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Can't get vm's status, assume it's dead
> already
> 2012-11-12 22:10:50,966 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-2:null) Failed to get dom xml:
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '1422832d-be18-352a-a08a-9bbff40e0d14'
> 2012-11-12 22:10:50,966 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-2:null) Seq 1-597426500: { Ans: , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 110,
> [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
> 2012-11-12 22:10:51,008 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-5:null) Request:Seq 1-597426501: { Cmd , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"s-28-VM","wait":0}}] }
> 2012-11-12 22:10:51,009 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-5:null) Processing command:
> com.cloud.agent.api.StopCommand
> 2012-11-12 22:10:51,011 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Failed to get dom xml:
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '0adf1854-4891-3537-aab9-b084bc4285c0'
> 2012-11-12 22:10:51,012 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Failed to get dom xml:
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '0adf1854-4891-3537-aab9-b084bc4285c0'
> 2012-11-12 22:10:51,012 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Executing:
> /usr/lib64/cloud/common/scripts/vm/network/security_group.py
> destroy_network_rules_for_vm --vmname s-28-VM
> 2012-11-12 22:10:51,142 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Execution is successful.
> 2012-11-12 22:10:51,143 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Try to stop the vm at first
> 2012-11-12 22:10:51,144 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Failed to stop VM :s-28-VM :
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '0adf1854-4891-3537-aab9-b084bc4285c0'
> at org.libvirt.ErrorHandler.processError(Unknown Source)
> at org.libvirt.Connect.processError(Unknown Source)
> at org.libvirt.Connect.domainLookupByUUIDString(Unknown Source)
> at org.libvirt.Connect.domainLookupByUUID(Unknown Source)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.stopVM(LibvirtComputingResource.java:3726)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.stopVM(LibvirtComputingResource.java:3658)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2586)
> at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:965)
> at com.cloud.agent.Agent.processRequest(Agent.java:518)
> at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)
> at com.cloud.utils.nio.Task.run(Task.java:83)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2012-11-12 22:10:51,146 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Failed to get vm status:Domain not found: no
> domain with matching uuid '0adf1854-4891-3537-aab9-b084bc4285c0'
> 2012-11-12 22:10:51,146 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Failed to get vm status:Domain not found: no
> domain with matching uuid '0adf1854-4891-3537-aab9-b084bc4285c0'
> 2012-11-12 22:10:51,147 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Failed to get vm status:Domain not found: no
> domain with matching uuid '0adf1854-4891-3537-aab9-b084bc4285c0'
> 2012-11-12 22:10:51,147 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Can't get vm's status, assume it's dead
> already
> 2012-11-12 22:10:51,148 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-5:null) Failed to get dom xml:
> org.libvirt.LibvirtException: Domain not found: no domain with matching
> uuid '0adf1854-4891-3537-aab9-b084bc4285c0'
> 2012-11-12 22:10:51,149 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-5:null) Seq 1-597426501: { Ans: , MgmtId:
> 31618986155374, via: 1, Ver: v1, Flags: 110,
> [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
> 2012-11-12 22:10:51,365 DEBUG [cloud.agent.Agent]
> (agentRequest-Handler-4:null) Processing command:
> com.cloud.agent.api.GetHostStatsCommand
> 2012-11-12 22:10:51,365 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Executing: /bin/bash -c idle=$(top -b -n
> 1|grep Cpu\(s\):|cut -d% -f4|cut -d, -f2);echo $idle
> 2012-11-12 22:10:51,915 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Execution is successful.
> 2012-11-12 22:10:51,916 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Executing: /bin/bash -c freeMem=$(free|grep
> cache:|awk '{print $4}');echo $freeMem
> 2012-11-12 22:10:51,926 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Execution is successful.
> 2012-11-12 22:10:51,926 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Executing: /bin/bash -c free|grep Mem:|awk
> '{print $2}'
> 2012-11-12 22:10:51,935 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Execution is successful.
> 2012-11-12 22:10:51,935 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Executing: /bin/bash -c cat
> /sys/class/net/cloudbr0/statistics/rx_bytes
> 2012-11-12 22:10:51,943 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Execution is successful.
> 2012-11-12 22:10:51,944 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Executing: /bin/bash -c cat
> /sys/class/net/cloudbr0/statistics/tx_bytes
> 2012-11-12 22:10:51,950 DEBUG [kvm.resource.LibvirtComputingResource]
> (agentRequest-Handler-4:null) Execution is successful.
> 2012-11-12 22:10:57,824 DEBUG [kvm.resource.LibvirtComputingResource]
> (UgentTask-5:null) Executing:
> /usr/lib64/cloud/common/scripts/vm/network/security_group.py
> get_rule_logs_for_vms
> 2012-11-12 22:10:57,924 DEBUG [kvm.resource.LibvirtComputingResource]
> (UgentTask-5:null) Execution is successful.
> 2012-11-12 22:10:57,925 DEBUG [cloud.agent.Agent] (UgentTask-5:null)
> Sending ping: Seq 1-28: { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11,
> [{"PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"newStates":{},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":1,"wait":0}}]
> }
> 2012-11-12 22:10:57,932 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null)
> Received response: Seq 1-28: { Ans: , MgmtId: 31618986155374, via: 1, Ver:
> v1, Flags: 100010,
> [{"PingAnswer":{"_command":{"hostType":"Routing","hostId":1,"wait":0},"result":true,"wait":0}}]
> }
> ------------------------
>
>
> Following this error I have checked the libvirt.log and I get this
> repeating error:
> ---------------------
> 2012-11-12 20:17:50.780+0000: 26665: error : virFileOpenForceOwnerMode:796
> : cannot chown
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/s-35-VM-patchdisk' to (0, 0):
> Invalid argument
> 2012-11-12 20:17:50.780+0000: 26665: error :
> virStorageBackendCreateRaw:401 : cannot create path
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/s-35-VM-patchdisk': Invalid
> argument
> 2012-11-12 20:18:20.440+0000: 26664: error : virFileOpenForceOwnerMode:796
> : cannot chown
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/s-35-VM-patchdisk' to (0, 0):
> Invalid argument
> 2012-11-12 20:18:20.441+0000: 26664: error :
> virStorageBackendCreateRaw:401 : cannot create path
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/s-35-VM-patchdisk': Invalid
> argument
> 2012-11-12 20:18:20.596+0000: 26663: error : virFileOpenForceOwnerMode:796
> : cannot chown '/mnt/95c9032d-3666-316e-a97f-546b201bd526/v-2-VM-patchdisk'
> to (0, 0): Invalid argument
> 2012-11-12 20:18:20.596+0000: 26663: error :
> virStorageBackendCreateRaw:401 : cannot create path
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/v-2-VM-patchdisk': Invalid
> argument
> 2012-11-12 20:18:50.628+0000: 26662: error : virFileOpenForceOwnerMode:796
> : cannot chown '/mnt/95c9032d-3666-316e-a97f-546b201bd526/v-2-VM-patchdisk'
> to (0, 0): Invalid argument
> 2012-11-12 20:18:50.628+0000: 26662: error :
> virStorageBackendCreateRaw:401 : cannot create path
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/v-2-VM-patchdisk': Invalid
> argument
> 2012-11-12 20:18:50.785+0000: 26665: error : virFileOpenForceOwnerMode:796
> : cannot chown
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/s-36-VM-patchdisk' to (0, 0):
> Invalid argument
> 2012-11-12 20:18:50.786+0000: 26665: error :
> virStorageBackendCreateRaw:401 : cannot create path
> '/mnt/95c9032d-3666-316e-a97f-546b201bd526/s-36-VM-patchdisk': Invalid
> argument
> ----------------
>
> Thank you for your time Rajesh.
> Regards,
>
> Mihai
>
>
>
>
>
>
>
>
> On Mon, Nov 12, 2012 at 3:38 PM, Rajesh Battala <rajesh.batt...@citrix.com
> > wrote:
>
>> Hi Mihai,
>>
>> This log snippet is not sufficient enough to find the issue. Please post
>> the error/warn log of your ms serve log.
>> Have you added both Primary and secondary storage mount points to the CS.
>> Is Primary Storage got mounted on the Hypervisor? Cloud network is
>> created on the host? Is your hypervisor is Xenserver or KVM?
>>
>> Thanks
>> Rajesh Battala
>>
>>
>> -----Original Message-----
>> From: Mihai Siminica [mailto:mihai.simin...@husi.ro]
>> Sent: Monday, November 12, 2012 6:07 PM
>> To: cloudstack-users@incubator.apache.org
>> Subject: System VMs not starting
>>
>> Hello everyone,
>>
>> I have a problem with System VMs on CS 4.0. I have followed the
>> installation guide step-by-step, I managed to add a host but I don't manage
>> to start any System VM. In the Infrastructure Panel I have 0 System VMs and
>> 0 Virtual Routers.
>>
>> My configuration:
>>
>> MS + DB + NF - on a single machine (dual Xeon / 16 GB / 4.8 TB (RAID 10)
>> --> 2.4 TB) - IP: 192.168.1.42 / 255.255.255.0
>> Hypervisor - a second machine - IP: 192.168.1.41 / 255.255.255.0 GW/DNS
>> for both: 192.168.1.252/192.168.1.26
>>
>> My management-server.log keeps repeating this messages:
>>
>> 2012-11-12 14:19:58,301 DEBUG [cloud.server.StatsCollector]
>> (StatsCollector-1:null) VmStatsCollector is running...
>> 2012-11-12 14:20:09,731 DEBUG [network.router.
>> VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0
>> routers.
>> 2012-11-12 14:20:39,731 DEBUG
>> [network.router.VirtualNetworkApplianceManagerImpl]
>> (RouterStatusMonitor-1:null) Found 0 routers.
>> 2012-11-12 14:20:42,817 DEBUG [cloud.server.StatsCollector]
>> (StatsCollector-1:null) StorageCollector is running...
>> 2012-11-12 14:20:42,821 DEBUG [cloud.server.StatsCollector]
>> (StatsCollector-1:null) There is no secondary storage VM for secondary
>> storage host nfs://192.168.1.42/var/export/secondary
>> 2012-11-12
>> <http://192.168.1.42/var/export/secondary%0A2012-11-12>14:20:42,848 DEBUG
>> [agent.transport.Request]
>> (StatsCollector-1:null) Seq 2-757074004: Received: { Ans: , MgmtId:
>> 31618986155374, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>> 2012-11-12 14:20:43,351 DEBUG [agent.manager.AgentManagerImpl]
>> (AgentManager-Handler-6:null) Ping from 2
>> 2012-11-12 14:20:50,296 DEBUG [cloud.server.StatsCollector]
>> (StatsCollector-1:null) HostStatsCollector is running...
>> 2012-11-12 14:20:50,924 DEBUG [agent.transport.Request]
>> (StatsCollector-1:null) Seq 2-757074005: Received: { Ans: , MgmtId:
>> 31618986155374, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
>>
>>
>> I did a clean-up and installed everything from the beginning on both the
>> MS and the Hypervisor but I get the same result.
>>
>> Please help me with this. Thank you !
>>
>
>
