[CLOUDSTACK-4194] Failed to detach volume after it got resized

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 4.2.0
• Fix Version/s: 4.2.0
• Component/s: Upgrade, VMware
• Security Level: Public (Anyone can view this level - this is the default.)
• Labels: integration-test
• Assignee: Vijayendra Bhamidipati
• Reporter: Sailaja Mada
• Created: 08/Aug/13 16:45
• Updated: 16/Aug/13 05:50
• Resolved: 14/Aug/13 08:04

Description

Setup : Upgraded from 2.2.14 to 4.2

1. Configure Adv Zone with VMWARE cluster of 4.1 hosts
2. Upgrade from 2.2.14 to 4.2
3. Create DATA volume with small disk offering
4. Attach the volume to an instance
5. Resize the volume from 5 GB to 20 GB
6. Tried to detach after it for resized

Observation:
Failed to detach volume after it got resized

2013-08-08 22:18:16,003 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===START=== 10.104.255.13 – GET command=detachVolume&id=2f7e7b87-30c2-4677-a5db-ed0aafdb49eb&response=json&sessionkey=AHzQuwtysq%2FQRF50wMgI%2F7ukyrU%3D&_=1375980069954
2013-08-08 22:18:16,031 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-5:null) submit async job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ], details: AsyncJobVO {id:107, userId: 2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 1153, cmd: org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd, cmdOriginator: null, cmdInfo:

{"response":"json","id":"2f7e7b87-30c2-4677-a5db-ed0aafdb49eb","sessionkey":"AHzQuwtysq/QRF50wMgI/7ukyrU\u003d","cmdEventType":"VOLUME.DETACH","ctxUserId":"2","httpmethod":"GET","_":"1375980069954","ctxAccountId":"2","ctxStartEventId":"391"}

, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 90310994128556, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-08-08 22:18:16,033 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===END=== 10.104.255.13 – GET command=detachVolume&id=2f7e7b87-30c2-4677-a5db-ed0aafdb49eb&response=json&sessionkey=AHzQuwtysq%2FQRF50wMgI%2F7ukyrU%3D&_=1375980069954
2013-08-08 22:18:16,035 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-25:job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ]) Executing org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd for job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ]
2013-08-08 22:18:16,071 DEBUG [agent.transport.Request] (Job-Executor-25:job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ]) Seq 1-475268002: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DettachCommand":{"disk":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"2f7e7b87-30c2-4677-a5db-ed0aafdb49eb","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3f4c460a-1634-3db0-8b1f-60fe7b17a264","id":202,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/abhinav/esx-pri2","port":2049}},"name":"newsailaja3","size":6442450944,"path":"daa2d8dac9b8467abd5b670b2559ed46","volumeId":1153,"vmName":"i-2-1131-VM","accountId":2,"format":"OVA","id":1153,"hypervisorType":"VMware"}},"diskSeq":7,"type":"DATADISK"},"vmName":"i-2-1131-VM","_managed":false,"_storageHost":"10.102.192.100","_storagePort":2049,"wait":0}}] }
2013-08-08 22:18:16,071 DEBUG [agent.transport.Request] (Job-Executor-25:job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ]) Seq 1-475268002: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DettachCommand":{"disk":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"2f7e7b87-30c2-4677-a5db-ed0aafdb49eb","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3f4c460a-1634-3db0-8b1f-60fe7b17a264","id":202,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/abhinav/esx-pri2","port":2049}},"name":"newsailaja3","size":6442450944,"path":"daa2d8dac9b8467abd5b670b2559ed46","volumeId":1153,"vmName":"i-2-1131-VM","accountId":2,"format":"OVA","id":1153,"hypervisorType":"VMware"}},"diskSeq":7,"type":"DATADISK"},"vmName":"i-2-1131-VM","_managed":false,"_storageHost":"10.102.192.100","_storagePort":2049,"wait":0}}] }
2013-08-08 22:18:16,072 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-230:null) Seq 1-475268002: Executing request
2013-08-08 22:18:16,072 DEBUG [vmware.mo.HostMO] (DirectAgent-230:10.102.192.17) find VM i-2-1131-VM on host
2013-08-08 22:18:16,072 INFO [vmware.mo.HostMO] (DirectAgent-230:10.102.192.17) VM i-2-1131-VM not found in host cache
2013-08-08 22:18:16,072 DEBUG [vmware.mo.HostMO] (DirectAgent-230:10.102.192.17) load VM cache on host
2013-08-08 22:18:16,330 INFO [vmware.mo.DatastoreMO] (DirectAgent-230:10.102.192.17) Search file daa2d8dac9b8467abd5b670b2559ed46.vmdk on [3f4c460a-1634-3db0-8b1f-60fe7b17a264]
2013-08-08 22:18:16,377 INFO [vmware.mo.DatastoreMO] (DirectAgent-230:10.102.192.17) File [3f4c460a-1634-3db0-8b1f-60fe7b17a264] daa2d8dac9b8467abd5b670b2559ed46.vmdk does not exist on datastore
2013-08-08 22:18:16,387 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-230:10.102.192.17) AttachVolumeCommand failed due to Exception: javax.xml.ws.soap.SOAPFaultException
Message: null

javax.xml.ws.soap.SOAPFaultException
at com.sun.xml.internal.ws.fault.SOAP11Fault.getProtocolException(SOAP11Fault.java:178)
at com.sun.xml.internal.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:119)
at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:108)
at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:78)
at com.sun.xml.internal.ws.client.sei.SEIStub.invoke(SEIStub.java:107)
at sun.proxy.$Proxy90.removeSnapshotTask(Unknown Source)
at com.cloud.hypervisor.vmware.mo.VirtualMachineMO.removeAllSnapshots(VirtualMachineMO.java:466)
at com.cloud.storage.resource.VmwareStorageProcessor.attachVolume(VmwareStorageProcessor.java:1183)
at com.cloud.storage.resource.VmwareStorageProcessor.attachVolume(VmwareStorageProcessor.java:1128)
at com.cloud.storage.resource.VmwareStorageProcessor.dettachVolume(VmwareStorageProcessor.java:1309)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:138)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:57)
at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:560)
at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
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-08 22:18:16,388 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-230:null) Seq 1-475268002: Response Received:
2013-08-08 22:18:16,388 DEBUG [agent.transport.Request] (DirectAgent-230:null) Seq 1-475268002: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.AttachAnswer":{"result":false,"details":"AttachVolumeCommand failed due to Exception: javax.xml.ws.soap.SOAPFaultException\nMessage: null\n","wait":0}}] }
2013-08-08 22:18:16,388 DEBUG [agent.transport.Request] (Job-Executor-25:job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ]) Seq 1-475268002: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10,

{ AttachAnswer }

}
2013-08-08 22:18:16,394 ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-25:job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ]) Unexpected exception while executing org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd
com.cloud.utils.exception.CloudRuntimeException: Failed to detach volume: newsailaja3 from VM: v1-new-402; AttachVolumeCommand failed due to Exception: javax.xml.ws.soap.SOAPFaultException
Message: null

at com.cloud.storage.VolumeManagerImpl.detachVolumeFromVM(VolumeManagerImpl.java:2038)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd.execute(DetachVolumeCmd.java:133)
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:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-08-08 22:18:16,396 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-25:job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ]) Complete async job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ], jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: Failed to detach volume: newsailaja3 from VM: v1-new-402; AttachVolumeCommand failed due to Exception: javax.xml.ws.soap.SOAPFaultException
Message: null

2013-08-08 22:18:19,182 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START=== 10.104.255.13 – GET command=queryAsyncJobResult&jobId=a29ebaae-b392-4ffc-be29-184d7233d0e4&response=json&sessionkey=AHzQuwtysq%2FQRF50wMgI%2F7ukyrU%3D&_=1375980073170
2013-08-08 22:18:19,196 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-1:null) Async job-107 = [ a29ebaae-b392-4ffc-be29-184d7233d0e4 ] completed
2013-08-08 22:18:19,201 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END=== 10.104.255.13 – GET command=queryAsyncJobResult&jobId=a29ebaae-b392-4ffc-be29-184d7233d0e4&response=json&sessionkey=AHzQuwtysq%2FQRF50wMgI%2F7ukyrU%3D&_=1375980073170