Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 0ADA810188 for ; Thu, 22 Aug 2013 19:06:37 +0000 (UTC) Received: (qmail 96387 invoked by uid 500); 22 Aug 2013 18:39:57 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 96308 invoked by uid 500); 22 Aug 2013 18:39:56 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 96291 invoked by uid 500); 22 Aug 2013 18:39:56 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 96278 invoked by uid 99); 22 Aug 2013 18:39:56 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 22 Aug 2013 18:39:56 +0000 Date: Thu, 22 Aug 2013 18:39:56 +0000 (UTC) From: "Rayees Namathponnan (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (CLOUDSTACK-4456) [Automation] Vm deployment from template is failed; due to some race condition in KVM MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 Rayees Namathponnan created CLOUDSTACK-4456: ----------------------------------------------- Summary: [Automation] Vm deployment from template is failed; d= ue 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 defa= ult.) Components: Automation, KVM, Management Server, Template Affects Versions: 4.2.0 Environment: Automation=20 4.2 Reporter: Rayees Namathponnan Priority: Critical Fix For: 4.2.0 This issue observed during automation run, In attached log i can see multip= le deployment failed due to same issue, here the once effected test case=20 integration.component.test_blocker_bugs.TestTemplate.test_01_create_templat= e Test case performing below operation=20 1) Create template from http url (ubuntu-10-04-64bit-server.qcow2) 2) Deploy vm from this template=20 Actual Result=20 --------------------- Deployment failed with below error; look like MS deleting template after c= reating the volume=20 IN MS Search for job-899=20 2013-08-21 22:07:12,383 DEBUG [cloud.network.NetworkManagerImpl] (Job-Execu= tor-66:job-899 =3D [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Asking BareMet= alUserdata 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-Execut= or-66:job-899 =3D [ 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-Execut= or-66:job-899 =3D [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) No need to recr= eate the volume: Vol[238|vm=3D188|ROOT], since it already has a pool assign= ed: 1, adding disk to VM 2013-08-21 22:07:12,408 DEBUG [agent.transport.Request] (Job-Executor-66:jo= b-899 =3D [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Seq 2-949159112: Sendin= g { Cmd , MgmtId: 73187150500751, via: 2, Ver: v1, Flags: 100011, [{"com.c= loud.agent.api.StartCommand":{"vm":{"id":188,"name":"i-287-188-TestVM","typ= e":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":134217728,"maxRam= ":134217728,"arch":"x86_64","os":"CentOS 5.5 (64-bit)","bootArgs":"","reboo= tOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScal= eVm":false,"vncPassword":"a79bd4d41d554b1a","params":{"Message.ReservedCapa= cityFreed.Flag":"false"},"uuid":"daf71095-b010-45f0-9e46-3bf51ee6a59c","dis= ks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"eb= a8fc74-aa6e-43a9-8dae-5501a0dd490f","volumeType":"ROOT","dataStore":{"org.a= pache.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":20= 49}},"name":"ROOT-188","size":5368709120,"path":"5ce3b7d0-07c1-4d3b-9c00-2c= 6ad8716635","volumeId":238,"vmName":"i-287-188-TestVM","accountId":287,"for= mat":"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":[{"de= viceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"3cf9efdc-212d-46f= 6-b818-071450e602fd","ip":"10.223.250.231","netmask":"255.255.255.192","gat= eway":"10.223.250.193","mac":"06:5f:a0:00:00:24","dns1":"8.8.8.8","broadcas= tType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationU= ri":"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-Handl= er-7:null) Seq 2-949159112: Processing: { Ans: , MgmtId: 73187150500751, v= ia: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":= 188,"name":"i-287-188-TestVM","type":"User","cpus":1,"minSpeed":100,"maxSpe= ed":100,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS = 5.5 (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCp= uUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"a79bd4d41d554b1= a","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-43= a9-8dae-5501a0dd490f","volumeType":"ROOT","dataStore":{"org.apache.cloudsta= ck.storage.to.PrimaryDataStoreTO":{"uuid":"9d444441-b138-3a13-974c-fa506683= da4d","id":1,"poolType":"NetworkFilesystem","host":"nfs1-ccp.citrix.com","p= ath":"/home/common/automation/SC_QA_AUTO5/primary1","port":2049}},"name":"R= OOT-188","size":5368709120,"path":"5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635","v= olumeId":238,"vmName":"i-287-188-TestVM","accountId":287,"format":"QCOW2","= id":238,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.a= pache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accou= ntId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"net= workRateMbps":200,"defaultNic":true,"uuid":"3cf9efdc-212d-46f6-b818-071450e= 602fd","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://unt= agged","isSecurityGroupEnabled":true}]},"result":false,"details":"internal = error Process exited while reading console log output: char device redirect= ed to /dev/pts/3\nqemu-kvm: -drive file=3D/mnt/9d444441-b138-3a13-974c-fa50= 6683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635,if=3Dnone,id=3Ddrive-virtio-d= isk0,format=3Dqcow2,cache=3Dnone: could not open disk image /mnt/9d444441-b= 138-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:jo= b-899 =3D [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Seq 2-949159112: Receiv= ed: { Ans: , MgmtId: 73187150500751, via: 2, Ver: v1, Flags: 10, { StartAn= swer } } 2013-08-21 22:07:12,960 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Exe= cutor-66:job-899 =3D [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Unable to st= art VM on Host[-2-Routing] due to internal error Process exited while readi= ng console log output: char device redirected to /dev/pts/3 qemu-kvm: -drive file=3D/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-= 07c1-4d3b-9c00-2c6ad8716635,if=3Dnone,id=3Ddrive-virtio-disk0,format=3Dqcow= 2,cache=3Dnone: could not open disk image /mnt/9d444441-b138-3a13-974c-fa50= 6683da4d/5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635: Operation not supported 2013-08-21 22:07:12,963 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Exe= cutor-66:job-899 =3D [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Cleaning up = resources for the vm VM[User|daf71095-b010-45f0-9e46-3bf51ee6a59c] in Start= ing state 2013-08-21 22:07:12,964 DEBUG [agent.transport.Request] (Job-Executor-66:jo= b-899 =3D [ 461fc03f-6d0a-488f-9cf3-7cf1a537b26c ]) Seq 2-949159113: Sendin= g { Cmd , MgmtId: 73187150500751, via: 2, Ver: v1, Flags: 100011, [{"com.c= loud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmN= ame":"i-287-188-TestVM","wait":0}}] } 2013-08-21 22:07:13,253 DEBUG [agent.transport.Request] (AgentManager-Handl= er-4:null) Seq 2-949159113: Processing: { Ans: , MgmtId: 73187150500751, v= ia: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,= "result":true,"wait":0}}] }=20 Agent log -------------- restart destroy destroy 2013-08-21 22:33:40,793 WARN [kvm.resource.LibvirtComputingResource] (agen= tRequest-Handler-1:null) LibvirtException org.libvirt.LibvirtException: internal error Process exited while reading c= onsole log output: char device redirected to /dev/pts/3 qemu-kvm: -drive file=3D/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-= 07c1-4d3b-9c00-2c6ad8716635,if=3Dnone,id=3Ddrive-virtio-disk0,format=3Dqcow= 2,cache=3Dnone: could not open disk image /mnt/9d444441-b138-3a13-974c-fa50= 6683da4d/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.start= VM(LibvirtComputingResource.java:1156) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execu= te(LibvirtComputingResource.java:3524) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execu= teRequest(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(ThreadPoolExec= utor.java:1146) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:615) at java.lang.Thread.run(Thread.java:679) 2013-08-21 22:33:40,796 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:n= ull) Seq 2-949159112: { Ans: , MgmtId: 73187150500751, via: 2, Ver: v1, Fl= ags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":188,"name":"i-287-= 188-TestVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":1= 34217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS 5.5 (64-bit)","boo= tArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enabl= eDynamicallyScaleVm":false,"vncPassword":"a79bd4d41d554b1a","vncAddr":"10.2= 23.250.195","params":{"Message.ReservedCapacityFreed.Flag":"false"},"uuid":= "daf71095-b010-45f0-9e46-3bf51ee6a59c","disks":[{"data":{"org.apache.clouds= tack.storage.to.VolumeObjectTO":{"uuid":"eba8fc74-aa6e-43a9-8dae-5501a0dd49= 0f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.Prim= aryDataStoreTO":{"uuid":"9d444441-b138-3a13-974c-fa506683da4d","id":1,"pool= Type":"NetworkFilesystem","host":"nfs1-ccp.citrix.com","path":"/home/common= /automation/SC_QA_AUTO5/primary1","port":2049}},"name":"ROOT-188","size":53= 68709120,"path":"5ce3b7d0-07c1-4d3b-9c00-2c6ad8716635","volumeId":238,"vmNa= me":"i-287-188-TestVM","accountId":287,"format":"QCOW2","id":238,"hyperviso= rType":"KVM"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.s= torage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":fals= e}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,= "defaultNic":true,"uuid":"3cf9efdc-212d-46f6-b818-071450e602fd","ip":"10.22= 3.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","isSecurity= GroupEnabled":true}]},"result":false,"details":"internal error Process exit= ed while reading console log output: char device redirected to /dev/pts/3\n= qemu-kvm: -drive file=3D/mnt/9d444441-b138-3a13-974c-fa506683da4d/5ce3b7d0-= 07c1-4d3b-9c00-2c6ad8716635,if=3Dnone,id=3Ddrive-virtio-disk0,format=3Dqcow= 2,cache=3Dnone: could not open disk image /mnt/9d444441-b138-3a13-974c-fa50= 6683da4d/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:n= ull) Request:Seq 2-949159113: { Cmd , MgmtId: 73187150500751, via: 2, Ver:= v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"e= xecuteInSequence":false,"vmName":"i-287-188-TestVM","wait":0}}] } 2013-08-21 22:33:40,811 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:n= ull) 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 administrato= rs For more information on JIRA, see: http://www.atlassian.com/software/jira