Abhinav Roy created CLOUDSTACK-5675:
---------------------------------------
Summary: Destory VM is failing with "Unable to delete vm snapshots
for VM"
Key: CLOUDSTACK-5675
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5675
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Management Server
Affects Versions: 4.3.0
Environment: Hyperv , 4.3
Reporter: Abhinav Roy
Priority: Blocker
Fix For: 4.3.0
Steps :
===========================
1. Deploy a CS advanced zone setup with Hyper-V as hypervisor type
2. Create a VM
3. Destroy the VM
Expected result:
==========================
The VM should be created and destroyed successfully.
Observed result :
=========================
Destroy VM fails with :
2013-12-30 15:02:30,297 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-57d2f51b)
===START=== 10.144.7.20 -- GET
command=destroyVirtualMachine&response=json&sessionkey=P7hUEU1kTW2jFEVpcBKYxFUSxx4%3D&id=706fae35-94d2-414d-94da-8c7b21051edd&expunge=true&_=1388396154899
2013-12-30 15:02:30,344 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-2:ctx-57d2f51b ctx-03d0a162) submit async job-38, details:
AsyncJobVO {id:38, userId: 2, accountId: 2, instanceType: VirtualMachine,
instanceId: 6, cmd: org.apache.cloudstack.api.command.user.vm.DestroyVMCmd,
cmdInfo:
{"response":"json","id":"706fae35-94d2-414d-94da-8c7b21051edd","sessionkey":"P7hUEU1kTW2jFEVpcBKYxFUSxx4\u003d","cmdEventType":"VM.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1388396154899","ctxAccountId":"2","expunge":"true","ctxStartEventId":"108"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 280320865129348, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2013-12-30 15:02:30,344 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-57d2f51b
ctx-03d0a162) ===END=== 10.144.7.20 -- GET
command=destroyVirtualMachine&response=json&sessionkey=P7hUEU1kTW2jFEVpcBKYxFUSxx4%3D&id=706fae35-94d2-414d-94da-8c7b21051edd&expunge=true&_=1388396154899
2013-12-30 15:02:30,346 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-41:ctx-90d46ce0) Add job-38 into job monitoring
2013-12-30 15:02:30,346 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-41:ctx-90d46ce0) Executing AsyncJobVO {id:38, userId: 2,
accountId: 2, instanceType: VirtualMachine, instanceId: 6, cmd:
org.apache.cloudstack.api.command.user.vm.DestroyVMCmd, cmdInfo:
{"response":"json","id":"706fae35-94d2-414d-94da-8c7b21051edd","sessionkey":"P7hUEU1kTW2jFEVpcBKYxFUSxx4\u003d","cmdEventType":"VM.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1388396154899","ctxAccountId":"2","expunge":"true","ctxStartEventId":"108"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 280320865129348, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2013-12-30 15:02:30,371 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-41:ctx-90d46ce0 ctx-03d0a162) Destroying vm VM[User|av3]
2013-12-30 15:02:30,372 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-41:ctx-90d46ce0 ctx-03d0a162) Stopped called on VM[User|av3] but
the state is Error
2013-12-30 15:02:30,404 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-41:ctx-90d46ce0 ctx-03d0a162) Sync job-39 execution on object
VmWorkJobQueue.6
2013-12-30 15:02:31,064 DEBUG [c.c.s.StatsCollector]
(StatsCollector-2:ctx-1f663345) StorageCollector is running...
2013-12-30 15:02:31,125 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-1f663345)
Seq 2-1575288891: Received: { Ans: , MgmtId: 280320865129348, via: 2, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-12-30 15:02:31,127 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-15:ctx-9d56111c) Seq 1-2099445910: Executing request
2013-12-30 15:02:31,128 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-15:ctx-9d56111c) POST request
tohttp://10.102.192.14:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand
with
contents{"id":"b183fb1d-c446-3a6f-b7ee-ec18507f39ae","localPath":"/HYPERV-SMB/abhinav-hyperv-ps1?user\u003dabhinav\u0026password\u003dfreebsd@123\u0026domain\u003dBLR","pooltype":"NetworkFilesystem","contextMap":{},"wait":0}
2013-12-30 15:02:31,128 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-15:ctx-9d56111c) Sending cmd to
http://10.102.192.14:8250/api/HypervResource/com.cloud.agent.api.GetStorageStatsCommand
cmd
data:{"id":"b183fb1d-c446-3a6f-b7ee-ec18507f39ae","localPath":"/HYPERV-SMB/abhinav-hyperv-ps1?user\u003dabhinav\u0026password\u003dfreebsd@123\u0026domain\u003dBLR","pooltype":"NetworkFilesystem","contextMap":{},"wait":0}
2013-12-30 15:02:31,136 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-15:ctx-9d56111c) POST response
is[{"com.cloud.agent.api.GetStorageStatsAnswer":{"result":false,"details":"com.cloud.agent.api.GetStorageStatsCommand
failed on exceptionIllegal characters in
path.","capacity":0,"used":0,"contextMap":{}}}]
2013-12-30 15:02:31,136 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-15:ctx-9d56111c) executeRequest received response
[{"com.cloud.agent.api.GetStorageStatsAnswer":{"used":0,"capacity":0,"result":false,"details":"com.cloud.agent.api.GetStorageStatsCommand
failed on exceptionIllegal characters in path.","contextMap":{},"wait":0}}]
2013-12-30 15:02:31,136 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-15:ctx-9d56111c) Seq 1-2099445910: Response Received:
2013-12-30 15:02:31,136 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-1f663345)
Seq 1-2099445910: Received: { Ans: , MgmtId: 280320865129348, via: 1, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-12-30 15:02:31,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-67d1aea0) Execute sync-queue item: SyncQueueItemVO
{id:6, queueId: 5, contentType: AsyncJob, contentId: 39, lastProcessMsid: null,
lastprocessNumber: null, lastProcessTime: null, created: Mon Dec 30 15:02:30
IST 2013}
2013-12-30 15:02:31,671 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-67d1aea0) Schedule queued job-39
2013-12-30 15:02:31,680 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-42:ctx-bd9d975c) Add job-39 into job monitoring
2013-12-30 15:02:31,680 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-42:ctx-bd9d975c) Executing AsyncJobVO {id:39, userId: 2,
accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots, cmdInfo:
rO0ABXNyADBjb20uY2xvdWQudm0uc25hcHNob3QuVm1Xb3JrRGVsZXRlQWxsVk1TbmFwc2hvdHOsl-VRajf8cAIAAUwABHR5cGV0ACdMY29tL2Nsb3VkL3ZtL3NuYXBzaG90L1ZNU25hcHNob3QkVHlwZTt4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAAZ0ABVWTVNuYXBzaG90TWFuYWdlckltcGxw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 280320865129348, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Mon Dec 30 15:02:30 IST 2013}
2013-12-30 15:02:31,681 DEBUG [c.c.v.VmWorkJobDispatcher]
(Job-Executor-42:ctx-bd9d975c) Run VM work job:
com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots
2013-12-30 15:02:31,683 DEBUG [c.c.v.s.VMSnapshotManagerImpl]
(Job-Executor-42:ctx-bd9d975c ctx-03d0a162) Execute Delete-All-VM-Snapshot
within VM work job context. vmId: 6
2013-12-30 15:02:31,685 DEBUG [c.c.v.s.VMSnapshotManagerImpl]
(Job-Executor-42:ctx-bd9d975c ctx-03d0a162) Execute Delete-All-VM-Snapshot
within VM work job context. vmId: 6
2013-12-30 15:02:31,685 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-42:ctx-bd9d975c ctx-03d0a162) Complete async job-39, jobStatus:
SUCCEEDED, resultCode: 0, result:
rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE
2013-12-30 15:02:31,691 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-42:ctx-bd9d975c) Done executing
com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots for job-39
2013-12-30 15:02:31,698 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-41:ctx-90d46ce0 ctx-03d0a162) Unable to delete all snapshots for
VM[User|av3]
2013-12-30 15:02:31,702 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Job-Executor-42:ctx-bd9d975c) Sync queue (5) is currently empty
2013-12-30 15:02:31,702 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-43:ctx-99262af7) Add job-38 into job monitoring
2013-12-30 15:02:31,702 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-43:ctx-99262af7) Executing AsyncJobVO {id:38, userId: 2,
accountId: 2, instanceType: VirtualMachine, instanceId: 6, cmd:
org.apache.cloudstack.api.command.user.vm.DestroyVMCmd, cmdInfo:
{"response":"json","id":"706fae35-94d2-414d-94da-8c7b21051edd","sessionkey":"P7hUEU1kTW2jFEVpcBKYxFUSxx4\u003d","cmdEventType":"VM.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1388396154899","ctxAccountId":"2","expunge":"true","ctxStartEventId":"108"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 280320865129348, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Mon Dec 30 15:02:30 IST 2013}
2013-12-30 15:02:31,703 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-42:ctx-bd9d975c) Remove job-39 from job monitoring
2013-12-30 15:02:31,705 ERROR [c.c.a.ApiAsyncJobDispatcher]
(Job-Executor-41:ctx-90d46ce0) Unexpected exception while executing
org.apache.cloudstack.api.command.user.vm.DestroyVMCmd
com.cloud.utils.exception.CloudRuntimeException: Unable to delete vm snapshots
for VM[User|av3]
at
com.cloud.vm.VirtualMachineManagerImpl.destroy(VirtualMachineManagerImpl.java:1528)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.destroyVirtualMachine(VMEntityManagerImpl.java:256)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.destroy(VirtualMachineEntityImpl.java:223)
at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:3616)
at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:2085)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at $Proxy169.destroyVm(Unknown Source)
at
org.apache.cloudstack.api.command.user.vm.DestroyVMCmd.execute(DestroyVMCmd.java:112)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at
com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at
com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:522)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:522)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
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-12-30 15:02:31,709 WARN [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-43:ctx-99262af7) job-38 is scheduled for wakeup run, but there is
no joining info anymore
2013-12-30 15:02:31,714 ERROR [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-43:ctx-99262af7) Unable to find a wakeup dispatcher from the
joined job: AsyncJobVO {id:38, userId: 2, accountId: 2, instanceType:
VirtualMachine, instanceId: 6, cmd:
org.apache.cloudstack.api.command.user.vm.DestroyVMCmd, cmdInfo:
{"response":"json","id":"706fae35-94d2-414d-94da-8c7b21051edd","sessionkey":"P7hUEU1kTW2jFEVpcBKYxFUSxx4\u003d","cmdEventType":"VM.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1388396154899","ctxAccountId":"2","expunge":"true","ctxStartEventId":"108"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 280320865129348, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Mon Dec 30 15:02:30 IST 2013}
2013-12-30 15:02:31,714 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-43:ctx-99262af7) Done executing
org.apache.cloudstack.api.command.user.vm.DestroyVMCmd for job-38
2013-12-30 15:02:31,716 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-41:ctx-90d46ce0) Complete async job-38, jobStatus: FAILED,
resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable
to delete vm snapshots for VM[User|av3]"}
2013-12-30 15:02:31,718 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-43:ctx-99262af7) Remove job-38 from job monitoring
Workaround :
========================
Add a new entry in cloud.configurations table with
vm.job.enabled set to "false"
restart management server. After this Destroy VM works fine.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
