Rayees Namathponnan created CLOUDSTACK-4456:
-----------------------------------------------
Summary: [Automation] Vm deployment from template is failed; due
to some race condition in KVM
Key: CLOUDSTACK-4456
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4456
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Automation, KVM, Management Server, Template
Affects Versions: 4.2.0
Environment: Automation
4.2
Reporter: Rayees Namathponnan
Priority: Critical
Fix For: 4.2.0
This issue observed during automation run, In attached log i can see multiple
deployment failed due to same issue, here the once effected test case
integration.component.test_blocker_bugs.TestTemplate.test_01_create_template
Test case performing below operation
1) Create template from http url (ubuntu-10-04-64bit-server.qcow2)
2) Deploy vm from this template
Actual Result
---------------------
Deployment failed with below error; look like MS deleting template after
creating the volume
IN MS Search for job-899
2013-08-21 22:07:12,383 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Asking
BareMetalUserdata to prepare for
Nic[194-188-97ae23d5-67ea-46c1-91e6-4e6ef35c22ae-10.223.250.231]
2013-08-21 22:07:12,389 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Checking
if we need to prepare 1 volumes for
VM[User|daf71095-b010-45f0-9e46-3bf51ee6a59c]
2013-08-21 22:07:12,389 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) No need to
recreate the volume: Vol[238|vm=188|ROOT], since it already has a pool
assigned: 1, adding disk to VM
2013-08-21 22:07:12,408 DEBUG [agent.transport.Request]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Seq
2-949159112: Sending { Cmd , MgmtId: 73187150500751, via: 2, Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":188,"name":"i-287-188-TestVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS
5.5
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"a79bd4d41d554b1a","params":{"Message.ReservedCapacityFreed.Flag":"false"},"uuid":"daf71095-b010-45f0-9e46-3bf51ee6a59c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"eba8fc74-aa6e-43a9-8dae-5501a0dd490f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9d444441-b138-3a13-974c-fa506683da4d","id":1,"poolType":"NetworkFilesystem","host":"nfs1-ccp.citrix.com","path":"/home/common/automation/SC_QA_AUTO5/primary1","port":2049}},"name":"ROOT-188","size":5368709120,"path":"5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635","volumeId":238,"vmName":"i-287-188-TestVM","accountId":287,"format":"QCOW2","id":238,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3cf9efdc-212d-46f6-b818-071450e602fd","ip":"10.223.250.231","netmask":"255.255.255.192","gateway":"10.223.250.193","mac":"06:5f:a0:00:00:24","dns1":"8.8.8.8","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"hostIp":"10.223.250.195","executeInSequence":false,"wait":0}}]
}
2013-08-21 22:07:12,957 DEBUG [agent.transport.Request]
(AgentManager-Handler-7:null) Seq 2-949159112: Processing: { Ans: , MgmtId:
73187150500751, via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":188,"name":"i-287-188-TestVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS
5.5
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"a79bd4d41d554b1a","vncAddr":"10.223.250.195","params":{"Message.ReservedCapacityFreed.Flag":"false"},"uuid":"daf71095-b010-45f0-9e46-3bf51ee6a59c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"eba8fc74-aa6e-43a9-8dae-5501a0dd490f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9d444441-b138-3a13-974c-fa506683da4d","id":1,"poolType":"NetworkFilesystem","host":"nfs1-ccp.citrix.com","path":"/home/common/automation/SC_QA_AUTO5/primary1","port":2049}},"name":"ROOT-188","size":5368709120,"path":"5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635","volumeId":238,"vmName":"i-287-188-TestVM","accountId":287,"format":"QCOW2","id":238,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3cf9efdc-212d-46f6-b818-071450e602fd","ip":"10.223.250.231","netmask":"255.255.255.192","gateway":"10.223.250.193","mac":"06:5f:a0:00:00:24","dns1":"8.8.8.8","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"result":false,"details":"internal
error Process exited while reading console log output: char device redirected
to /dev/pts/3\nqemu-kvm: -drive
file=/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635,if=none,id=drive-virtio-disk0,format=qcow2,cache=none:
could not open disk image
/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635:
Operation not supported\n","wait":0}}] }
2013-08-21 22:07:12,957 DEBUG [agent.transport.Request]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Seq
2-949159112: Received: { Ans: , MgmtId: 73187150500751, via: 2, Ver: v1,
Flags: 10, { StartAnswer } }
2013-08-21 22:07:12,960 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Unable to
start VM on Host[-2-Routing] due to internal error Process exited while reading
console log output: char device redirected to /dev/pts/3
qemu-kvm: -drive
file=/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635,if=none,id=drive-virtio-disk0,format=qcow2,cache=none:
could not open disk image
/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635:
Operation not supported
2013-08-21 22:07:12,963 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Cleaning
up resources for the vm VM[User|daf71095-b010-45f0-9e46-3bf51ee6a59c] in
Starting state
2013-08-21 22:07:12,964 DEBUG [agent.transport.Request]
(Job-Executor-66:job-899 = [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Seq
2-949159113: Sending { Cmd , MgmtId: 73187150500751, via: 2, Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-287-188-TestVM","wait":0}}]
}
2013-08-21 22:07:13,253 DEBUG [agent.transport.Request]
(AgentManager-Handler-4:null) Seq 2-949159113: Processing: { Ans: , MgmtId:
73187150500751, via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
Agent log
--------------
<on_reboot>restart</on_reboot>
<on_poweroff>destroy</on_poweroff>
<on_crash>destroy</on_crash>
</domain>
2013-08-21 22:33:40,793 WARN [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-1:null) LibvirtException
org.libvirt.LibvirtException: internal error Process exited while reading
console log output: char device redirected to /dev/pts/3
qemu-kvm: -drive
file=/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635,if=none,id=drive-virtio-disk0,format=qcow2,cache=none:
could not open disk image
/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635:
Operation not supported
at org.libvirt.ErrorHandler.processError(Unknown Source)
at org.libvirt.Connect.processError(Unknown Source)
at org.libvirt.Connect.domainCreateXML(Unknown Source)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.startVM(LibvirtComputingResource.java:1156)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:3524)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1252)
at com.cloud.agent.Agent.processRequest(Agent.java:525)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)
at com.cloud.utils.nio.Task.run(Task.java:83)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-08-21 22:33:40,796 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null)
Seq 2-949159112: { Ans: , MgmtId: 73187150500751, via: 2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":188,"name":"i-287-188-TestVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS
5.5
(64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"a79bd4d41d554b1a","vncAddr":"10.223.250.195","params":{"Message.ReservedCapacityFreed.Flag":"false"},"uuid":"daf71095-b010-45f0-9e46-3bf51ee6a59c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"eba8fc74-aa6e-43a9-8dae-5501a0dd490f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9d444441-b138-3a13-974c-fa506683da4d","id":1,"poolType":"NetworkFilesystem","host":"nfs1-ccp.citrix.com","path":"/home/common/automation/SC_QA_AUTO5/primary1","port":2049}},"name":"ROOT-188","size":5368709120,"path":"5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635","volumeId":238,"vmName":"i-287-188-TestVM","accountId":287,"format":"QCOW2","id":238,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3cf9efdc-212d-46f6-b818-071450e602fd","ip":"10.223.250.231","netmask":"255.255.255.192","gateway":"10.223.250.193","mac":"06:5f:a0:00:00:24","dns1":"8.8.8.8","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":true}]},"result":false,"details":"internal
error Process exited while reading console log output: char device redirected
to /dev/pts/3\nqemu-kvm: -drive
file=/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635,if=none,id=drive-virtio-disk0,format=qcow2,cache=none:
could not open disk image
/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635:
Operation not supported\n","wait":0}}] }
2013-08-21 22:33:40,811 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Request:Seq 2-949159113: { Cmd , MgmtId: 73187150500751, via: 2, Ver: v1,
Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-287-188-TestVM","wait":0}}]
}
2013-08-21 22:33:40,811 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Processing command: com.cloud.agent.api.StopCommand
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
