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
