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 AB48A10F07 for ; Wed, 21 Aug 2013 13:46:00 +0000 (UTC) Received: (qmail 74080 invoked by uid 500); 21 Aug 2013 13:46:00 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 73543 invoked by uid 500); 21 Aug 2013 13:45:55 -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 73285 invoked by uid 500); 21 Aug 2013 13:45:53 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 73247 invoked by uid 99); 21 Aug 2013 13:45:53 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 21 Aug 2013 13:45:53 +0000 Date: Wed, 21 Aug 2013 13:45:53 +0000 (UTC) From: "Sateesh Chodapuneedi (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Resolved] (CLOUDSTACK-4362) VM's are failing to start after its DATA volume is migrated to other primary storage MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-4362?page=3Dcom.atl= assian.jira.plugin.system.issuetabpanels:all-tabpanel ] Sateesh Chodapuneedi resolved CLOUDSTACK-4362. ---------------------------------------------- Resolution: Fixed =20 > VM's are failing to start after its DATA volume is migrated to other prim= ary storage=20 > -------------------------------------------------------------------------= ------------ > > Key: CLOUDSTACK-4362 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-436= 2 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Components: Storage Controller, VMware > Affects Versions: 4.2.0 > Reporter: Sailaja Mada > Assignee: Sateesh Chodapuneedi > Priority: Critical > Fix For: 4.2.0 > > Attachments: apilog.log, db1.sql, management-server.log, ssvmlogs= .rar > > > Steps: > 1. Configure Adv zone with 2 zone wide primary storage's > 2. Create new account and Deploy instance using this account > 3. Add new DATA volume and attach to this instance > 4. Resize this volume from 5 GB to 7 GB > 5. As admin, Migrate this volume from Storage 1 to Storage2 ( Zone wide p= rimary) > 6. Stop and Start this instance > Observation: > VM's are failing to start after its DATA volume is migrated to second zon= e wide primary storage=20 > 2013-08-16 12:04:48,465 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Exec= utor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Checking if we= need to prepare 2 volumes for VM[User|inst2] > 2013-08-16 12:04:48,471 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Exec= utor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Mismatch in st= orage pool Pool[1|NetworkFilesystem] assigned by deploymentPlanner and the = one associated with volume Vol[14|vm=3D5|DATADISK] > 2013-08-16 12:04:48,471 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Exec= utor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Shared volume = Vol[14|vm=3D5|DATADISK] will be migrated on storage pool Pool[1|NetworkFile= system] assigned by deploymentPlanner > 2013-08-16 12:04:48,524 DEBUG [storage.motion.AncientDataMotionStrategy] = (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) copyA= sync inspecting src type VOLUME copyAsync inspecting dest type VOLUME > 2013-08-16 12:04:48,528 DEBUG [cache.allocator.StorageCacheRandomAllocato= r] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Ca= n't find staging storage in zone: 1 > 2013-08-16 12:04:48,591 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 3-1725105201: Send= ing { Cmd , MgmtId: 187767034175903, via: 3, Ver: v1, Flags: 100011, [{"or= g.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.clou= dstack.storage.to.VolumeObjectTO":{"uuid":"b55516ba-da2e-454a-8cee-7d1a927c= e25a","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.t= o.PrimaryDataStoreTO":{"uuid":"b33e996a-444e-3685-9070-0865067454c4","id":2= ,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sa= ilaja/sailajaps2","port":2049}},"name":"new32","size":7516192768,"path":"a0= 4a400289624aad99ab92e7c089343d","volumeId":14,"vmName":"i-3-5-VM","accountI= d":3,"format":"OVA","id":14,"hypervisorType":"VMware"}},"destTO":{"org.apac= he.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b55516ba-da2e-454a-8cee-7= d1a927ce25a","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.N= fsTO":{"_url":"nfs://10.102.192.100/cpg_vol/sailaja/sailajass1","_role":"Im= age"}},"name":"new32","size":7516192768,"path":"volumes/3/14","volumeId":14= ,"vmName":"i-3-5-VM","accountId":3,"format":"OVA","id":14,"hypervisorType":= "VMware"}},"executeInSequence":false,"wait":10800}}] } > 2013-08-16 12:04:48,700 DEBUG [agent.transport.Request] (AgentManager-Han= dler-1:null) Seq 3-1725105201: Processing: { Ans: , MgmtId: 18776703417590= 3, via: 3, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.Cop= yCmdAnswer":{"result":false,"details":"copy volume from primary to secondar= y failed due to exception: Exception: java.lang.NullPointerException\nMessa= ge: null\n","wait":0}}] } > 2013-08-16 12:04:48,702 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 3-1725105201: Rece= ived: { Ans: , MgmtId: 187767034175903, via: 3, Ver: v1, Flags: 10, { Copy= CmdAnswer } } > 2013-08-16 12:04:48,706 DEBUG [storage.motion.AncientDataMotionStrategy] = (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) copy = to image store failed: copy volume from primary to secondary failed due to = exception: Exception: java.lang.NullPointerException > Message: null > 2013-08-16 12:04:48,728 DEBUG [storage.image.BaseImageStoreDriverImpl] (J= ob-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unable = to destoy VOLUME: 14 > java.lang.NullPointerException > at org.apache.cloudstack.storage.volume.VolumeObject.getPath(Volu= meObject.java:338) > at org.apache.cloudstack.storage.to.VolumeObjectTO.(VolumeO= bjectTO.java:53) > at org.apache.cloudstack.storage.volume.VolumeObject.getTO(Volume= Object.java:460) > at org.apache.cloudstack.storage.image.BaseImageStoreDriverImpl.d= eleteAsync(BaseImageStoreDriverImpl.java:237) > at org.apache.cloudstack.storage.image.store.ImageStoreImpl.delet= e(ImageStoreImpl.java:148) > at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy= .copyVolumeBetweenPools(AncientDataMotionStrategy.java:323) > at org.apache.cloudstack.storage.motion.AncientDataMotionStrategy= .copyAsync(AncientDataMotionStrategy.java:406) > at org.apache.cloudstack.storage.motion.DataMotionServiceImpl.cop= yAsync(DataMotionServiceImpl.java:55) > at org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVol= ume(VolumeServiceImpl.java:790) > at com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManage= rImpl.java:2239) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.= java:2580) > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMana= gerImpl.java:885) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineMan= agerImpl.java:575) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerI= mpl.deployVirtualMachine(VMEntityManagerImpl.java:227) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEn= tityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3405) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:1947) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(S= tartVMCmd.java:120) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.= java:531) > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.= java:471) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:= 334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx= ecutor.java:1110) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:603) > at java.lang.Thread.run(Thread.java:679) > 2013-08-16 12:04:48,733 WARN [storage.datastore.ObjectInDataStoreManager= Impl] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ])= Volume 14 is not found on image store 1, so no need to delete > 2013-08-16 12:04:48,745 WARN [storage.datastore.ObjectInDataStoreManager= Impl] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ])= Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.P= rimaryDataStoreImpl@41542faa), no need to delete from object in store ref t= able > 2013-08-16 12:04:48,758 WARN [storage.datastore.ObjectInDataStoreManager= Impl] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ])= Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.P= rimaryDataStoreImpl@16f51b82), no need to delete from object in store ref t= able > 2013-08-16 12:04:48,827 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 1-1608257161: Send= ing { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 100011, [{"or= g.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.clo= udstack.storage.to.VolumeObjectTO":{"uuid":"ea17ef59-dafe-4286-9dc2-606b4e8= ea513","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.= to.PrimaryDataStoreTO":{"uuid":"7f18caf5-397a-340a-934e-d37c558aee2b","id":= 1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/s= ailaja/sailajaps1","port":2049}},"name":"new32","size":7516192768,"path":"a= 04a400289624aad99ab92e7c089343d","volumeId":20,"vmName":"i-3-5-VM","account= Id":3,"id":20,"hypervisorType":"VMware"}},"wait":0}}] } > 2013-08-16 12:04:48,828 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 1-1608257161: Exec= uting: { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 100011, [{= "org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.= cloudstack.storage.to.VolumeObjectTO":{"uuid":"ea17ef59-dafe-4286-9dc2-606b= 4e8ea513","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.stora= ge.to.PrimaryDataStoreTO":{"uuid":"7f18caf5-397a-340a-934e-d37c558aee2b","i= d":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vo= l/sailaja/sailajaps1","port":2049}},"name":"new32","size":7516192768,"path"= :"a04a400289624aad99ab92e7c089343d","volumeId":20,"vmName":"i-3-5-VM","acco= untId":3,"id":20,"hypervisorType":"VMware"}},"wait":0}}] } > 2013-08-16 12:04:48,836 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-392:null) Seq 1-1608257161: Executing request > 2013-08-16 12:04:48,839 INFO [storage.resource.VmwareStorageProcessor] (= DirectAgent-392:10.102.192.18) Executing resource DestroyCommand: {"data":{= "org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ea17ef59-dafe-42= 86-9dc2-606b4e8ea513","volumeType":"DATADISK","dataStore":{"org.apache.clou= dstack.storage.to.PrimaryDataStoreTO":{"uuid":"7f18caf5-397a-340a-934e-d37c= 558aee2b","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","pa= th":"/cpg_vol/sailaja/sailajaps1","port":2049}},"name":"new32","size":75161= 92768,"path":"a04a400289624aad99ab92e7c089343d","volumeId":20,"vmName":"i-3= -5-VM","accountId":3,"id":20,"hypervisorType":"VMware"}},"wait":0} > 2013-08-16 12:04:48,962 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Search file a04a400289624aad99ab92e7c089343d.vmdk on [7f18caf5= 397a340a934ed37c558aee2b] > 2013-08-16 12:04:48,999 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) File [7f18caf5397a340a934ed37c558aee2b] a04a400289624aad99ab92= e7c089343d.vmdk does not exist on datastore > 2013-08-16 12:04:49,010 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Search file a04a400289624aad99ab92e7c089343d.vmdk on [7f18caf5= 397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,036 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) File [7f18caf5397a340a934ed37c558aee2b] a04a400289624aad99ab92= e7c089343d.vmdk does not exist on datastore > 2013-08-16 12:04:49,036 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Searching file a04a400289624aad99ab92e7c089343d.vmdk in [7f18c= af5397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,201 WARN [storage.resource.VmwareStorageLayoutHelper= ] (DirectAgent-392:10.102.192.18) Unable to locate VMDK file: a04a400289624= aad99ab92e7c089343d.vmdk > 2013-08-16 12:04:49,205 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Search file a04a400289624aad99ab92e7c089343d-flat.vmdk on [7f1= 8caf5397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,229 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) File [7f18caf5397a340a934ed37c558aee2b] a04a400289624aad99ab92= e7c089343d-flat.vmdk does not exist on datastore > 2013-08-16 12:04:49,233 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Search file a04a400289624aad99ab92e7c089343d-flat.vmdk on [7f1= 8caf5397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,254 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) File [7f18caf5397a340a934ed37c558aee2b] a04a400289624aad99ab92= e7c089343d-flat.vmdk does not exist on datastore > 2013-08-16 12:04:49,254 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Searching file a04a400289624aad99ab92e7c089343d-flat.vmdk in [= 7f18caf5397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,334 WARN [storage.resource.VmwareStorageLayoutHelper= ] (DirectAgent-392:10.102.192.18) Unable to locate VMDK file: a04a400289624= aad99ab92e7c089343d-flat.vmdk > 2013-08-16 12:04:49,340 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Search file a04a400289624aad99ab92e7c089343d-delta.vmdk on [7f= 18caf5397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,360 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) File [7f18caf5397a340a934ed37c558aee2b] a04a400289624aad99ab92= e7c089343d-delta.vmdk does not exist on datastore > 2013-08-16 12:04:49,364 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Search file a04a400289624aad99ab92e7c089343d-delta.vmdk on [7f= 18caf5397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,387 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) File [7f18caf5397a340a934ed37c558aee2b] a04a400289624aad99ab92= e7c089343d-delta.vmdk does not exist on datastore > 2013-08-16 12:04:49,387 INFO [vmware.mo.DatastoreMO] (DirectAgent-392:10= .102.192.18) Searching file a04a400289624aad99ab92e7c089343d-delta.vmdk in = [7f18caf5397a340a934ed37c558aee2b] > 2013-08-16 12:04:49,480 WARN [storage.resource.VmwareStorageLayoutHelper= ] (DirectAgent-392:10.102.192.18) Unable to locate VMDK file: a04a400289624= aad99ab92e7c089343d-delta.vmdk > 2013-08-16 12:04:49,480 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-392:null) Seq 1-1608257161: Response Received: > 2013-08-16 12:04:49,483 DEBUG [agent.transport.Request] (DirectAgent-392:= null) Seq 1-1608257161: Processing: { Ans: , MgmtId: 187767034175903, via:= 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"deta= ils":"Success","wait":0}}] } > 2013-08-16 12:04:49,483 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 1-1608257161: Rece= ived: { Ans: , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 10, { Answ= er } } > 2013-08-16 12:04:49,520 INFO [storage.volume.VolumeServiceImpl] (Job-Exe= cutor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Volume 20 is = not referred anywhere, remove it from volumes table > 2013-08-16 12:04:49,529 ERROR [cloud.storage.VolumeManagerImpl] (Job-Exec= utor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) migrate volume= failed:copy volume from primary to secondary failed due to exception: Exce= ption: java.lang.NullPointerException > Message: null > 2013-08-16 12:04:49,530 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unable to c= ontact resource. > com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1]= is unreachable: migrate volume failed: copy volume from primary to seconda= ry failed due to exception: Exception: java.lang.NullPointerException > Message: null > at com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManage= rImpl.java:2244) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.= java:2580) > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMac= hineManagerImpl.java:885) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineMan= agerImpl.java:575) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerI= mpl.deployVirtualMachine(VMEntityManagerImpl.java:227) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEn= tityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3405) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:1947) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(S= tartVMCmd.java:120) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.= java:531) > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471= ) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:= 334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx= ecutor.java:1110) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:603) > at java.lang.Thread.run(Thread.java:679) > 2013-08-16 12:04:49,539 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Cleaning up= resources for the vm VM[User|inst2] in Starting state > 2013-08-16 12:04:49,542 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 1-1608257162: Send= ing { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 100011, [{"co= m.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"= vmName":"i-3-5-VM","wait":0}}] } > 2013-08-16 12:04:49,543 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 1-1608257162: Exec= uting: { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 100011, [{= "com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fals= e,"vmName":"i-3-5-VM","wait":0}}] } > 2013-08-16 12:04:49,543 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-135:null) Seq 1-1608257162: Executing request > 2013-08-16 12:04:49,543 INFO [vmware.resource.VmwareResource] (DirectAge= nt-135:10.102.192.18) Executing resource StopCommand: {"isProxy":false,"exe= cuteInSequence":false,"vmName":"i-3-5-VM","wait":0} > 2013-08-16 12:04:49,543 DEBUG [vmware.mo.HostMO] (DirectAgent-135:10.102.= 192.18) find VM i-3-5-VM on host > 2013-08-16 12:04:49,543 INFO [vmware.mo.HostMO] (DirectAgent-135:10.102.= 192.18) VM i-3-5-VM not found in host cache > 2013-08-16 12:04:49,543 DEBUG [vmware.mo.HostMO] (DirectAgent-135:10.102.= 192.18) load VM cache on host > 2013-08-16 12:04:49,643 INFO [vmware.resource.VmwareResource] (DirectAge= nt-135:10.102.192.18) VM i-3-5-VM is no longer in vSphere > 2013-08-16 12:04:49,644 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-135:null) Seq 1-1608257162: Response Received: > 2013-08-16 12:04:49,645 DEBUG [agent.transport.Request] (DirectAgent-135:= null) Seq 1-1608257162: Processing: { Ans: , MgmtId: 187767034175903, via:= 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"re= sult":true,"details":"VM i-3-5-VM is no longer in vSphere","wait":0}}] } > 2013-08-16 12:04:49,645 DEBUG [agent.transport.Request] (Job-Executor-37:= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq 1-1608257162: Rece= ived: { Ans: , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 10, { Stop= Answer } } > 2013-08-16 12:04:49,986 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl= ] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Try= ing to allocate a host and storage pools from dc:1, pod:1,cluster:null, req= uested cpu: 500, requested ram: 536870912 > 2013-08-16 12:04:49,986 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl= ] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Is = ROOT volume READY (pool already allocated)?: No > 2013-08-16 12:04:49,986 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl= ] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Thi= s VM has last host_id specified, trying to choose the same host: 1 > 2013-08-16 12:04:49,989 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl= ] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) The= last host of this VM is in avoid set > 2013-08-16 12:04:49,989 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl= ] (Job-Executor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Can= not choose the last host to deploy this VM > 2013-08-16 12:04:49,989 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Searching resourc= es only under specified Pod: 1 > 2013-08-16 12:04:49,989 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Listing clusters = in order of aggregate capacity, that have (atleast one host with) enough CP= U and RAM capacity under this Pod: 1 > 2013-08-16 12:04:49,993 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Removing from the= clusterId list these clusters from avoid set: [1] > 2013-08-16 12:04:49,995 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) No clusters found= after removing disabled clusters and clusters in avoid list, returning. > 2013-08-16 12:04:50,019 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) VM state tr= ansitted from :Starting to Stopped with event: OperationFailedvm's original= host id: 1 new host id: null host id before state transition: null > 2013-08-16 12:04:50,052 INFO [user.vm.StartVMCmd] (Job-Executor-37:job-7= 4 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) com.cloud.exception.Insuffi= cientServerCapacityException: Unable to create a deployment for VM[User|ins= t2]Scope=3Dinterface com.cloud.dc.DataCenter; id=3D1 > 2013-08-16 12:04:50,057 INFO [user.vm.StartVMCmd] (Job-Executor-37:job-7= 4 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unable to create a deployme= nt for VM[User|inst2] > com.cloud.exception.InsufficientServerCapacityException: Unable to create= a deployment for VM[User|inst2]Scope=3Dinterface com.cloud.dc.DataCenter; = id=3D1 > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMac= hineManagerImpl.java:839) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineMan= agerImpl.java:575) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerI= mpl.deployVirtualMachine(VMEntityManagerImpl.java:237) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEn= tityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3405) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:1947) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(S= tartVMCmd.java:120) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.= java:531) > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.= java:471) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:= 334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx= ecutor.java:1110) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:603) > at java.lang.Thread.run(Thread.java:679) > 2013-08-16 12:04:50,062 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-37:job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Complete async= job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ], jobStatus: 2, resultC= ode: 530, result: Error Code: 533 Error text: Unable to create a deployment= for VM[User|inst2] > 2013-08-16 12:04:50,531 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:nul= l) =3D=3D=3DSTART=3D=3D=3D 10.104.255.13 -- GET command=3DqueryAsyncJobRe= sult&jobId=3D039d4ba9-0507-4dea-b658-5a784fdc0588&response=3Djson&sessionke= y=3DLLRVMYnhKE5X9Ai%2FjTFfOsinB6o%3D&_=3D1376635107558 > 2013-08-16 12:04:50,544 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina= -exec-6:null) Async job-74 =3D [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ] com= pleted > 2013-08-16 12:04:50,550 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:nul= l) =3D=3D=3DEND=3D=3D=3D 10.104.255.13 -- GET command=3DqueryAsyncJobResu= lt&jobId=3D039d4ba9-0507-4dea-b658-5a784fdc0588&response=3Djson&sessionkey= =3DLLRVMYnhKE5X9Ai%2FjTFfOsinB6o%3D&_=3D1376635107558 -- 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