Srikanteswararao Talluri created CLOUDSTACK-2945: ----------------------------------------------------
Summary: [ZWPS][VMWARE]: detach volume is throwing an exception Key: CLOUDSTACK-2945 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2945 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the default.) Components: Volumes Affects Versions: 4.2.0 Reporter: Srikanteswararao Talluri Fix For: 4.2.0 1. Create a data volume on zone scoped primary storage 2. attach it to a VM whose root volume is on zone scoped primary storage 3. detach the volume attached in step2 ===START=== 10.252.192.7 -- GET command=detachVolume&id=493e8653-d2c6-4b91-854e-3f4ec1a7af8d&response=json&sessionkey=WibLOc01S7zuDtvZAhmKpsaufLY%3D&_=1371022639049 2013-06-12 09:01:29,877 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-11:null) submit async job-136, details: AsyncJobVO {id:136, userId: 2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 27, cmd: org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd, cmdOriginator: null, cmdInfo: {"response":"json","id":"493e8653-d2c6-4b91-854e-3f4ec1a7af8d","sessionkey":"WibLOc01S7zuDtvZAhmKpsaufLY\u003d","ctxUserId":"2","httpmethod":"GET","_":"1371022639049","ctxAccountId":"2","ctxStartEventId":"565"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 7635042566263, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2013-06-12 09:01:29,880 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END=== 10.252.192.7 -- GET command=detachVolume&id=493e8653-d2c6-4b91-854e-3f4ec1a7af8d&response=json&sessionkey=WibLOc01S7zuDtvZAhmKpsaufLY%3D&_=1371022639049 2013-06-12 09:01:29,882 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-23:job-136) Executing org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd for job-136 2013-06-12 09:01:29,934 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-185:null) Seq 1-2112815433: Executing request 2013-06-12 09:01:29,935 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-185:null) Seq 1-2112815433: Response Received: 2013-06-12 09:01:29,935 DEBUG [agent.transport.Request] (DirectAgent-185:null) Seq 1-2112815433: Processing: { Ans: , MgmtId: 7635042566263, via: 1, Ver: v1, Flags: 10, [{"UnsupportedAnswer":{"result":false,"details":"Unsupported command issued:com.cloud.agent.api.GetVmDiskStatsCommand. Are you sure you got the right type of server?","wait":0}}] } 2013-06-12 09:01:29,943 DEBUG [agent.transport.Request] (Job-Executor-23:job-136) Seq 1-2112815433: Received: { Ans: , MgmtId: 7635042566263, via: 1, Ver: v1, Flags: 10, { UnsupportedAnswer } } 2013-06-12 09:01:29,943 WARN [agent.manager.AgentManagerImpl] (Job-Executor-23:job-136) Unsupported Command: Unsupported command issued:com.cloud.agent.api.GetVmDiskStatsCommand. Are you sure you got the right type of server? 2013-06-12 09:01:29,944 DEBUG [agent.manager.AgentManagerImpl] (Job-Executor-23:job-136) Details from executing class com.cloud.agent.api.GetVmDiskStatsCommand: Unsupported command issued:com.cloud.agent.api.GetVmDiskStatsCommand. Are you sure you got the right type of server? 2013-06-12 09:01:29,944 WARN [cloud.vm.UserVmManagerImpl] (Job-Executor-23:job-136) Error while collecting disk stats for vm: zwpsroot from host: 10.147.40.7 java.lang.ClassCastException: com.cloud.agent.api.UnsupportedAnswer cannot be cast to com.cloud.agent.api.GetVmDiskStatsAnswer at com.cloud.vm.UserVmManagerImpl.collectVmDiskStatistics(UserVmManagerImpl.java:3434) at com.cloud.storage.VolumeManagerImpl.detachVolumeFromVM(VolumeManagerImpl.java:1910) 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:155) at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437) 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-06-12 09:01:29,950 DEBUG [agent.transport.Request] (Job-Executor-23:job-136) Seq 1-2112815434: Sending { Cmd , MgmtId: 7635042566263, via: 1, Ver: v1, Flags: 100111, [{"AttachVolumeCommand":{"attach":false,"vmName":"i-2-22-VM","pooltype":"NetworkFilesystem","poolUuid":"ce61cbc8-66c5-3f66-a65c-b469503ef2c7","volumeFolder":"/export/home/talluri/vmwarezwps1","volumePath":"b89991ca9e344a9f99878b6014243f36","volumeName":"zwps_data","deviceId":1,"wait":0}}] } 2013-06-12 09:01:29,951 DEBUG [agent.transport.Request] (Job-Executor-23:job-136) Seq 1-2112815434: Executing: { Cmd , MgmtId: 7635042566263, via: 1, Ver: v1, Flags: 100111, [{"AttachVolumeCommand":{"attach":false,"vmName":"i-2-22-VM","pooltype":"NetworkFilesystem","poolUuid":"ce61cbc8-66c5-3f66-a65c-b469503ef2c7","volumeFolder":"/export/home/talluri/vmwarezwps1","volumePath":"b89991ca9e344a9f99878b6014243f36","volumeName":"zwps_data","deviceId":1,"wait":0}}] } 2013-06-12 09:01:29,952 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-37:null) Seq 1-2112815434: Executing request 2013-06-12 09:01:29,953 INFO [vmware.resource.VmwareResource] (DirectAgent-37:10.147.40.7) Executing resource AttachVolumeCommand: {"attach":false,"vmName":"i-2-22-VM","pooltype":"NetworkFilesystem","poolUuid":"ce61cbc8-66c5-3f66-a65c-b469503ef2c7","volumeFolder":"/export/home/talluri/vmwarezwps1","volumePath":"b89991ca9e344a9f99878b6014243f36","volumeName":"zwps_data","deviceId":1,"wait":0} 2013-06-12 09:01:29,953 DEBUG [vmware.mo.HostMO] (DirectAgent-37:10.147.40.7) find VM i-2-22-VM on host 2013-06-12 09:01:29,953 DEBUG [vmware.mo.HostMO] (DirectAgent-37:10.147.40.7) load VM cache on host 2013-06-12 09:01:30,013 INFO [vmware.mo.DatastoreMO] (DirectAgent-37:10.147.40.7) Search file b89991ca9e344a9f99878b6014243f36.vmdk on [ce61cbc866c53f66a65cb469503ef2c7] 2013-06-12 09:01:30,047 INFO [vmware.mo.DatastoreMO] (DirectAgent-37:10.147.40.7) File [ce61cbc866c53f66a65cb469503ef2c7] b89991ca9e344a9f99878b6014243f36.vmdk exists on datastore 2013-06-12 09:01:30,074 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Look for disk device info from volume : [ce61cbc866c53f66a65cb469503ef2c7] b89991ca9e344a9f99878b6014243f36.vmdk 2013-06-12 09:01:30,074 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Test against disk device, controller key: 200, unit number: 1 2013-06-12 09:01:30,075 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Test against disk backing : [ce61cbc866c53f66a65cb469503ef2c7] ROOT-22-26-000002.vmdk 2013-06-12 09:01:30,076 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Test against disk backing : [ce61cbc866c53f66a65cb469503ef2c7] ROOT-22-26-000001.vmdk 2013-06-12 09:01:30,076 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Test against disk backing : [ce61cbc866c53f66a65cb469503ef2c7] ROOT-22-26.vmdk 2013-06-12 09:01:30,077 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Test against disk backing : [ce61cbc866c53f66a65cb469503ef2c7] 48cca16404cd357483103bfdea1bd57d/48cca16404cd357483103bfdea1bd57d.vmdk 2013-06-12 09:01:30,077 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Test against disk device, controller key: 1000, unit number: 0 2013-06-12 09:01:30,078 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Test against disk backing : [ce61cbc866c53f66a65cb469503ef2c7] b89991ca9e344a9f99878b6014243f36.vmdk 2013-06-12 09:01:30,079 INFO [vmware.mo.VirtualMachineMO] (DirectAgent-37:10.147.40.7) Disk backing : [ce61cbc866c53f66a65cb469503ef2c7] b89991ca9e344a9f99878b6014243f36.vmdk matches ==> scsi0:0 2013-06-12 09:01:30,091 INFO [vmware.util.VmwareContext] (DirectAgent-37:10.147.40.7) Connected, conn: sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.147.60.15/folder/b89991ca9e344a9f99878b6014243f36.vmdk?dcPath=zone&dsName=ce61cbc866c53f66a65cb469503ef2c7, retry: 0 2013-06-12 09:01:30,448 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===START=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022639592 2013-06-12 09:01:30,457 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-24:null) Object entity uuid = undefined does not exist in the database. 2013-06-12 09:01:30,458 INFO [cloud.api.ApiServer] (catalina-exec-24:null) Unable to execute API command queryasyncjobresult due to invalid value. Invalid parameter jobid value=undefined due to incorrect long value format, or entity does not exist or due to incorrect parameter annotation for the field in api cmd class. 2013-06-12 09:01:30,460 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===END=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022639592 2013-06-12 09:01:30,817 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===START=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022639963 2013-06-12 09:01:30,826 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-12:null) Object entity uuid = undefined does not exist in the database. 2013-06-12 09:01:30,827 INFO [cloud.api.ApiServer] (catalina-exec-12:null) Unable to execute API command queryasyncjobresult due to invalid value. Invalid parameter jobid value=undefined due to incorrect long value format, or entity does not exist or due to incorrect parameter annotation for the field in api cmd class. 2013-06-12 09:01:30,829 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===END=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022639963 2013-06-12 09:01:31,759 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===START=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022640905 2013-06-12 09:01:31,768 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-7:null) Object entity uuid = undefined does not exist in the database. 2013-06-12 09:01:31,769 INFO [cloud.api.ApiServer] (catalina-exec-7:null) Unable to execute API command queryasyncjobresult due to invalid value. Invalid parameter jobid value=undefined due to incorrect long value format, or entity does not exist or due to incorrect parameter annotation for the field in api cmd class. 2013-06-12 09:01:31,770 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===END=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022640905 2013-06-12 09:01:32,856 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null) ===START=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022641956 2013-06-12 09:01:32,865 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-9:null) Object entity uuid = undefined does not exist in the database. 2013-06-12 09:01:32,865 INFO [cloud.api.ApiServer] (catalina-exec-9:null) Unable to execute API command queryasyncjobresult due to invalid value. Invalid parameter jobid value=undefined due to incorrect long value format, or entity does not exist or due to incorrect parameter annotation for the field in api cmd class. 2013-06-12 09:01:32,867 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null) ===END=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022641956 2013-06-12 09:01:32,917 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===START=== 10.252.192.7 -- GET command=queryAsyncJobResult&jobId=134f98cb-03e2-48bd-9e02-5d6a99fcef2e&response=json&sessionkey=WibLOc01S7zuDtvZAhmKpsaufLY%3D&_=1371022642134 2013-06-12 09:01:32,958 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===END=== 10.252.192.7 -- GET command=queryAsyncJobResult&jobId=134f98cb-03e2-48bd-9e02-5d6a99fcef2e&response=json&sessionkey=WibLOc01S7zuDtvZAhmKpsaufLY%3D&_=1371022642134 2013-06-12 09:01:33,073 INFO [vmware.util.VmwareContext] (DirectAgent-37:10.147.40.7) Connected, conn: sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.147.60.15/folder/i-2-22-VM/i-2-22-VM.vmsd?dcPath=zone&dsName=ce61cbc866c53f66a65cb469503ef2c7, retry: 0 2013-06-12 09:01:33,626 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null) ===START=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022642769 2013-06-12 09:01:33,635 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-10:null) Object entity uuid = undefined does not exist in the database. 2013-06-12 09:01:33,635 INFO [cloud.api.ApiServer] (catalina-exec-10:null) Unable to execute API command queryasyncjobresult due to invalid value. Invalid parameter jobid value=undefined due to incorrect long value format, or entity does not exist or due to incorrect parameter annotation for the field in api cmd class. 2013-06-12 09:01:33,637 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null) ===END=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022642769 2013-06-12 09:01:33,776 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: .encoding = "UTF-8" 2013-06-12 09:01:33,777 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot.lastUID = "2" 2013-06-12 09:01:33,777 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot.numSnapshots = "1" 2013-06-12 09:01:33,777 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot.current = "2" 2013-06-12 09:01:33,778 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.uid = "2" 2013-06-12 09:01:33,779 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.filename = "i-2-22-VM-Snapshot2.vmsn" 2013-06-12 09:01:33,779 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.displayName = "Consolidate Helper- 0" 2013-06-12 09:01:33,780 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.description = "Helper snapshot for online consolidate." 2013-06-12 09:01:33,780 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.createTimeHigh = "319215" 2013-06-12 09:01:33,781 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.createTimeLow = "-1316151522" 2013-06-12 09:01:33,781 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.numDisks = "2" 2013-06-12 09:01:33,782 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.disk0.fileName = "/vmfs/volumes/fa40728f-be386cfb/ROOT-22-26-000001.vmdk" 2013-06-12 09:01:33,782 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.disk0.node = "ide0:1" 2013-06-12 09:01:33,783 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.disk1.fileName = "/vmfs/volumes/fa40728f-be386cfb/b89991ca9e344a9f99878b6014243f36-000001.vmdk" 2013-06-12 09:01:33,783 INFO [vmware.mo.SnapshotDescriptor] (DirectAgent-37:10.147.40.7) Parse snapshot file content: snapshot0.disk1.node = "scsi0:0" 2013-06-12 09:01:33,808 INFO [vmware.util.VmwareContext] (DirectAgent-37:10.147.40.7) Connected, conn: sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.147.60.15/folder/i-2-22-VM/i-2-22-VM.vmsd?dcPath=zone&dsName=ce61cbc866c53f66a65cb469503ef2c7, retry: 0 2013-06-12 09:01:34,001 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===START=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022643145 2013-06-12 09:01:34,010 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-5:null) Object entity uuid = undefined does not exist in the database. 2013-06-12 09:01:34,010 INFO [cloud.api.ApiServer] (catalina-exec-5:null) Unable to execute API command queryasyncjobresult due to invalid value. Invalid parameter jobid value=undefined due to incorrect long value format, or entity does not exist or due to incorrect parameter annotation for the field in api cmd class. 2013-06-12 09:01:34,012 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===END=== 10.252.192.33 -- GET command=queryAsyncJobResult&jobId=undefined&response=json&sessionkey=%2BuRMVVnN2JBVe6oDv%2B0ZAqV8gso%3D&_=1371022643145 2013-06-12 09:01:34,549 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-37:null) Seq 1-2112815434: Response Received: 2013-06-12 09:01:34,550 DEBUG [agent.transport.Request] (DirectAgent-37:null) Seq 1-2112815434: Processing: { Ans: , MgmtId: 7635042566263, via: 1, Ver: v1, Flags: 110, [{"AttachVolumeAnswer":{"deviceId":1,"result":true,"wait":0}}] } 2013-06-12 09:01:34,550 DEBUG [agent.transport.Request] (Job-Executor-23:job-136) Seq 1-2112815434: Received: { Ans: , MgmtId: 7635042566263, via: 1, Ver: v1, Flags: 110, { AttachVolumeAnswer } } 2013-06-12 09:01:34,554 DEBUG [agent.manager.AgentAttache] (DirectAgent-37:null) Seq 1-2112815434: No more commands found 2013-06-12 09:01:34,586 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-23:job-136) Complete async job-136, jobStatus: 1, resultCode: 0, result: org.apache.cloudstack.api.response.VolumeResponse@4dbddde 2013-06-12 09:01:34,598 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-23:job-136) Done executing org.apache.cloudstack.api.command.user.volume.DetachVolumeCmd for job-136 -- 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