[
https://issues.apache.org/jira/browse/CLOUDSTACK-4362?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Sailaja Mada reopened CLOUDSTACK-4362:
--------------------------------------
Tried with latest build. I still see this issue happening hence reopening the
defect :
2013-08-30 20:44:34,231 INFO [storage.resource.VmwareStorageProcessor]
(DirectAgent-149:10.102.192.23) Executing resource DestroyCommand:
{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"648b5c5d-1cab-4989-b615-41bc79768227","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1f4e45b6-07ef-3349-8f95-6009b972184c","id":2,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newzwps1","port":2049}},"name":"ROOT-3","size":2147483648,"path":"ROOT-3","volumeId":13,"vmName":"i-3-3-VM","accountId":3,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[031590029a323361b699e44f6f4cdb90]
i-3-3-VM/ROOT-3.vmdk\"]}","format":"OVA","id":13,"hypervisorType":"VMware"}},"wait":0}
2013-08-30 20:44:34,279 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-149:null) Seq 4-1955201548: Response Received:
2013-08-30 20:44:34,279 DEBUG [agent.transport.Request] (DirectAgent-149:null)
Seq 4-1955201548: Processing: { Ans: , MgmtId: 94838926819810, via: 4, Ver:
v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"details":"Success","wait":0}}] }
2013-08-30 20:44:34,280 DEBUG [agent.transport.Request] (Job-Executor-60:job-47
= [ 5ad42adc-2dc4-4369-997b-ced159d96680 ]) Seq 4-1955201548: Received: { Ans:
, MgmtId: 94838926819810, via: 4, Ver: v1, Flags: 10, { Answer } }
2013-08-30 20:44:34,294 INFO [storage.volume.VolumeServiceImpl]
(Job-Executor-60:job-47 = [ 5ad42adc-2dc4-4369-997b-ced159d96680 ]) Volume 13
is not referred anywhere, remove it from volumes table
2013-08-30 20:44:34,301 ERROR [cloud.storage.VolumeManagerImpl]
(Job-Executor-60:job-47 = [ 5ad42adc-2dc4-4369-997b-ced159d96680 ]) migrate
volume failed:copy volume secondary to primary failed due to exception:
Exception: javax.xml.ws.soap.SOAPFaultException
Message:
Required parameter spec is missing
while parsing call information for method ImportVApp
at line 1, column 110
while parsing SOAP body
at line 1, column 102
while parsing SOAP envelope
at line 1, column 38
while parsing HTTP request for method importVApp
on object of type vim.ResourcePool
at line 1, column 0
2013-08-30 20:44:34,302 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-60:job-47 = [ 5ad42adc-2dc4-4369-997b-ced159d96680 ]) Unable to
contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:2] is
unreachable: migrate volume failed: copy volume secondary to primary failed due
to exception: Exception: javax.xml.ws.soap.SOAPFaultException
Message:
Required parameter spec is missing
while parsing call information for method ImportVApp
at line 1, column 110
while parsing SOAP body
at line 1, column 102
while parsing SOAP envelope
at line 1, column 38
while parsing HTTP request for method importVApp
on object of type vim.ResourcePool
at line 1, column 0
at
com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2254)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2590)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3406)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1948)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.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(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-08-30 20:44:34,319 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-60:job-47 = [ 5ad42adc-2dc4-4369-997b-ced159d96680 ]) Cleaning up
resources for the vm VM[User|instance1] in Starting state
2013-08-30 20:44:34,322 DEBUG [agent.transport.Request] (Job-Executor-60:job-47
= [ 5ad42adc-2dc4-4369-997b-ced159d96680 ]) Seq 1-1584727014: Sending { Cmd ,
MgmtId: 94838926819810, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-3-VM","wait":0}}]
}
2013-08-30 20:44:34,322 DEBUG [agent.transport.Request] (Job-Executor-60:job-47
= [ 5ad42adc-2dc4-4369-997b-ced159d96680 ]) Seq 1-1584727014: Executing: { Cmd
, MgmtId: 94838926819810, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-3-VM","wait":0}}]
}
2013-08-30 20:44:34,322 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-343:null) Seq 1-1584727014: Executing request
2013-08-30 20:44:34,322 INFO [vmware.resource.VmwareResource]
(DirectAgent-343:10.102.192.13) Executing resource StopCommand:
{"isProxy":false,"executeInSequence":true,"vmName":"i-3-3-VM","wait":0}
2013-08-30 20:44:34,328 DEBUG [vmware.mo.HostMO]
(DirectAgent-343:10.102.192.13) find VM i-3-3-VM on host
> VM's are failing to start after its DATA volume is migrated to other primary
> storage
> -------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-4362
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4362
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> 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
> primary)
> 6. Stop and Start this instance
> Observation:
> VM's are failing to start after its DATA volume is migrated to second zone
> wide primary storage
> 2013-08-16 12:04:48,465 DEBUG [cloud.storage.VolumeManagerImpl]
> (Job-Executor-37:job-74 = [ 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-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Mismatch
> in storage pool Pool[1|NetworkFilesystem] assigned by deploymentPlanner and
> the one associated with volume Vol[14|vm=5|DATADISK]
> 2013-08-16 12:04:48,471 DEBUG [cloud.storage.VolumeManagerImpl]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Shared
> volume Vol[14|vm=5|DATADISK] will be migrated on storage pool
> Pool[1|NetworkFilesystem] assigned by deploymentPlanner
> 2013-08-16 12:04:48,524 DEBUG [storage.motion.AncientDataMotionStrategy]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) copyAsync
> inspecting src type VOLUME copyAsync inspecting dest type VOLUME
> 2013-08-16 12:04:48,528 DEBUG [cache.allocator.StorageCacheRandomAllocator]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Can't
> find staging storage in zone: 1
> 2013-08-16 12:04:48,591 DEBUG [agent.transport.Request]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 3-1725105201: Sending { Cmd , MgmtId: 187767034175903, via: 3, Ver: v1,
> Flags: 100011,
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b55516ba-da2e-454a-8cee-7d1a927ce25a","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b33e996a-444e-3685-9070-0865067454c4","id":2,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/sailajaps2","port":2049}},"name":"new32","size":7516192768,"path":"a04a400289624aad99ab92e7c089343d","volumeId":14,"vmName":"i-3-5-VM","accountId":3,"format":"OVA","id":14,"hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b55516ba-da2e-454a-8cee-7d1a927ce25a","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.102.192.100/cpg_vol/sailaja/sailajass1","_role":"Image"}},"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-Handler-1:null) Seq 3-1725105201: Processing: { Ans: , MgmtId:
> 187767034175903, via: 3, Ver: v1, Flags: 10,
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"copy
> volume from primary to secondary failed due to exception: Exception:
> java.lang.NullPointerException\nMessage: null\n","wait":0}}] }
> 2013-08-16 12:04:48,702 DEBUG [agent.transport.Request]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 3-1725105201: Received: { Ans: , MgmtId: 187767034175903, via: 3, Ver: v1,
> Flags: 10, { CopyCmdAnswer } }
> 2013-08-16 12:04:48,706 DEBUG [storage.motion.AncientDataMotionStrategy]
> (Job-Executor-37:job-74 = [ 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]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unable to
> destoy VOLUME: 14
> java.lang.NullPointerException
> at
> org.apache.cloudstack.storage.volume.VolumeObject.getPath(VolumeObject.java:338)
> at
> org.apache.cloudstack.storage.to.VolumeObjectTO.<init>(VolumeObjectTO.java:53)
> at
> org.apache.cloudstack.storage.volume.VolumeObject.getTO(VolumeObject.java:460)
> at
> org.apache.cloudstack.storage.image.BaseImageStoreDriverImpl.deleteAsync(BaseImageStoreDriverImpl.java:237)
> at
> org.apache.cloudstack.storage.image.store.ImageStoreImpl.delete(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.copyAsync(DataMotionServiceImpl.java:55)
> at
> org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:790)
> at
> com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2239)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2580)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:885)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3405)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1947)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.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(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-08-16 12:04:48,733 WARN
> [storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-37:job-74 = [
> 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.ObjectInDataStoreManagerImpl] (Job-Executor-37:job-74 = [
> 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unsupported data object (VOLUME,
> org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@41542faa), no
> need to delete from object in store ref table
> 2013-08-16 12:04:48,758 WARN
> [storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-37:job-74 = [
> 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unsupported data object (VOLUME,
> org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@16f51b82), no
> need to delete from object in store ref table
> 2013-08-16 12:04:48,827 DEBUG [agent.transport.Request]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 1-1608257161: Sending { 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-606b4e8ea513","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/sailaja/sailajaps1","port":2049}},"name":"new32","size":7516192768,"path":"a04a400289624aad99ab92e7c089343d","volumeId":20,"vmName":"i-3-5-VM","accountId":3,"id":20,"hypervisorType":"VMware"}},"wait":0}}]
> }
> 2013-08-16 12:04:48,828 DEBUG [agent.transport.Request]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 1-1608257161: Executing: { 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-606b4e8ea513","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/sailaja/sailajaps1","port":2049}},"name":"new32","size":7516192768,"path":"a04a400289624aad99ab92e7c089343d","volumeId":20,"vmName":"i-3-5-VM","accountId":3,"id":20,"hypervisorType":"VMware"}},"wait":0}}]
> }
> 2013-08-16 12:04:48,836 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-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-4286-9dc2-606b4e8ea513","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/sailaja/sailajaps1","port":2049}},"name":"new32","size":7516192768,"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 [7f18caf5397a340a934ed37c558aee2b]
> 2013-08-16 12:04:48,999 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-392:10.102.192.18) File [7f18caf5397a340a934ed37c558aee2b]
> a04a400289624aad99ab92e7c089343d.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 [7f18caf5397a340a934ed37c558aee2b]
> 2013-08-16 12:04:49,036 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-392:10.102.192.18) File [7f18caf5397a340a934ed37c558aee2b]
> a04a400289624aad99ab92e7c089343d.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 [7f18caf5397a340a934ed37c558aee2b]
> 2013-08-16 12:04:49,201 WARN [storage.resource.VmwareStorageLayoutHelper]
> (DirectAgent-392:10.102.192.18) Unable to locate VMDK file:
> a04a400289624aad99ab92e7c089343d.vmdk
> 2013-08-16 12:04:49,205 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-392:10.102.192.18) Search file
> a04a400289624aad99ab92e7c089343d-flat.vmdk on
> [7f18caf5397a340a934ed37c558aee2b]
> 2013-08-16 12:04:49,229 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-392:10.102.192.18) File [7f18caf5397a340a934ed37c558aee2b]
> a04a400289624aad99ab92e7c089343d-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
> [7f18caf5397a340a934ed37c558aee2b]
> 2013-08-16 12:04:49,254 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-392:10.102.192.18) File [7f18caf5397a340a934ed37c558aee2b]
> a04a400289624aad99ab92e7c089343d-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:
> a04a400289624aad99ab92e7c089343d-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
> [7f18caf5397a340a934ed37c558aee2b]
> 2013-08-16 12:04:49,360 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-392:10.102.192.18) File [7f18caf5397a340a934ed37c558aee2b]
> a04a400289624aad99ab92e7c089343d-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
> [7f18caf5397a340a934ed37c558aee2b]
> 2013-08-16 12:04:49,387 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-392:10.102.192.18) File [7f18caf5397a340a934ed37c558aee2b]
> a04a400289624aad99ab92e7c089343d-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:
> a04a400289624aad99ab92e7c089343d-delta.vmdk
> 2013-08-16 12:04:49,480 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-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,"details":"Success","wait":0}}]
> }
> 2013-08-16 12:04:49,483 DEBUG [agent.transport.Request]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 1-1608257161: Received: { Ans: , MgmtId: 187767034175903, via: 1, Ver: v1,
> Flags: 10, { Answer } }
> 2013-08-16 12:04:49,520 INFO [storage.volume.VolumeServiceImpl]
> (Job-Executor-37:job-74 = [ 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-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) migrate
> volume failed:copy volume from primary to secondary failed due to exception:
> Exception: java.lang.NullPointerException
> Message: null
> 2013-08-16 12:04:49,530 INFO [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unable to
> contact resource.
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is
> unreachable: migrate volume failed: copy volume from primary to secondary
> failed due to exception: Exception: java.lang.NullPointerException
> Message: null
> at
> com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2244)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2580)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:885)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3405)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1947)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.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(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-08-16 12:04:49,539 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-37:job-74 = [ 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 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 1-1608257162: Sending { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1,
> Flags: 100011,
> [{"com.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 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 1-1608257162: Executing: { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1,
> Flags: 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-3-5-VM","wait":0}}]
> }
> 2013-08-16 12:04:49,543 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-135:null) Seq 1-1608257162: Executing request
> 2013-08-16 12:04:49,543 INFO [vmware.resource.VmwareResource]
> (DirectAgent-135:10.102.192.18) Executing resource StopCommand:
> {"isProxy":false,"executeInSequence":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]
> (DirectAgent-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]
> (DirectAgent-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,"result":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 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Seq
> 1-1608257162: Received: { Ans: , MgmtId: 187767034175903, via: 1, Ver: v1,
> Flags: 10, { StopAnswer } }
> 2013-08-16 12:04:49,986 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Trying to
> allocate a host and storage pools from dc:1, pod:1,cluster:null, requested
> cpu: 500, requested ram: 536870912
> 2013-08-16 12:04:49,986 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (Job-Executor-37:job-74 = [ 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 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) This 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 = [ 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 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Cannot
> choose the last host to deploy this VM
> 2013-08-16 12:04:49,989 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Searching
> resources only under specified Pod: 1
> 2013-08-16 12:04:49,989 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Listing
> clusters in order of aggregate capacity, that have (atleast one host with)
> enough CPU and RAM capacity under this Pod: 1
> 2013-08-16 12:04:49,993 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-37:job-74 = [ 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-Executor-37:job-74 = [ 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-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) VM state
> transitted 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-74 =
> [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ])
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a
> deployment for VM[User|inst2]Scope=interface com.cloud.dc.DataCenter; id=1
> 2013-08-16 12:04:50,057 INFO [user.vm.StartVMCmd] (Job-Executor-37:job-74 =
> [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Unable to create a deployment for
> VM[User|inst2]
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a
> deployment for VM[User|inst2]Scope=interface com.cloud.dc.DataCenter; id=1
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:839)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3405)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1947)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.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(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-08-16 12:04:50,062 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-37:job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ]) Complete
> async job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588 ], jobStatus: 2,
> resultCode: 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:null)
> ===START=== 10.104.255.13 -- GET
> command=queryAsyncJobResult&jobId=039d4ba9-0507-4dea-b658-5a784fdc0588&response=json&sessionkey=LLRVMYnhKE5X9Ai%2FjTFfOsinB6o%3D&_=1376635107558
> 2013-08-16 12:04:50,544 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-6:null) Async job-74 = [ 039d4ba9-0507-4dea-b658-5a784fdc0588
> ] completed
> 2013-08-16 12:04:50,550 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
> ===END=== 10.104.255.13 -- GET
> command=queryAsyncJobResult&jobId=039d4ba9-0507-4dea-b658-5a784fdc0588&response=json&sessionkey=LLRVMYnhKE5X9Ai%2FjTFfOsinB6o%3D&_=1376635107558
--
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
