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