You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Sanjeev N (JIRA)" <ji...@apache.org> on 2013/12/04 06:34:37 UTC
[jira] [Created] (CLOUDSTACK-5360) [Hyper-V] Failed to stop/destroy
system vms
Sanjeev N created CLOUDSTACK-5360:
-------------------------------------
Summary: [Hyper-V] Failed to stop/destroy system vms
Key: CLOUDSTACK-5360
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5360
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Hypervisor Controller, Management Server
Affects Versions: 4.3.0
Environment: 4.3
Hypervisor: Hyperv
Storage: CIFS for secondary storage and Local storage for primary
Reporter: Sanjeev N
Priority: Critical
Fix For: 4.3.0
[Hyper-V] Failed to stop/destroy system vms
Steps to Reproduce:
================
1.Bring up CS in advanced zone with hyperv using CIFS for secondary and Local storage for primary
2.Wait for the SSVM and CPVM to come up in running state
3.Disable the zone
4.Try to destroy SSVM and CPVM
Expected Result:
=============
System vm should be destroyed successfully.
Actual Result:
============
Failed to stop system vms. They remained in running state.
Log snippet from the management server log as follows:
2013-12-04 05:38:10,648 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-17:ctx-58df498b ctx-803fc411) submit async job-45, details: AsyncJobVO {id:45, userId: 2, accountId: 2, instanceType: SystemVm, instanceId: 2, cmd: org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd, cmdInfo: {"id":"69f6f9f1-098a-45bb-a57e-40770577358f","response":"json","sessionkey":"6gEqK4AUWb7klI/aOH9lLsIqrVc\u003d","cmdEventType":"PROXY.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1386133822298","ctxAccountId":"2","ctxStartEventId":"217"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 7332683579487, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-12-04 05:38:10,649 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-58df498b ctx-803fc411) ===END=== 10.146.0.134 -- GET command=destroySystemVm&id=69f6f9f1-098a-45bb-a57e-40770577358f&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&_=1386133822298
2013-12-04 05:38:10,651 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-30:ctx-d6a82988) Add job-45 into job monitoring
2013-12-04 05:38:10,651 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-30:ctx-d6a82988) Executing AsyncJobVO {id:45, userId: 2, accountId: 2, instanceType: SystemVm, instanceId: 2, cmd: org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd, cmdInfo: {"id":"69f6f9f1-098a-45bb-a57e-40770577358f","response":"json","sessionkey":"6gEqK4AUWb7klI/aOH9lLsIqrVc\u003d","cmdEventType":"PROXY.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1386133822298","ctxAccountId":"2","ctxStartEventId":"217"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 7332683579487, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-12-04 05:38:10,703 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-30:ctx-d6a82988 ctx-803fc411) VM state transitted from :Running to Stopping with event: StopRequestedvm's original host id: 1 new host id: 1 host id before state transition: 1
2013-12-04 05:38:10,707 DEBUG [c.c.a.t.Request] (Job-Executor-30:ctx-d6a82988 ctx-803fc411) Seq 1-1034949124: Sending { Cmd , MgmtId: 7332683579487, via: 1(10.147.40.14), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"v-2-VM","wait":0}}] }
2013-12-04 05:38:10,707 DEBUG [c.c.a.t.Request] (Job-Executor-30:ctx-d6a82988 ctx-803fc411) Seq 1-1034949124: Executing: { Cmd , MgmtId: 7332683579487, via: 1(10.147.40.14), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"v-2-VM","wait":0}}] }
2013-12-04 05:38:10,707 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-367:ctx-948bcdad) Seq 1-1034949124: Executing request
2013-12-04 05:38:10,708 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-367:ctx-948bcdad) POST request tohttp://10.147.40.14:8250/api/HypervResource/com.cloud.agent.api.StopCommand with contents{"isProxy":false,"executeInSequence":false,"vmName":"v-2-VM","contextMap":{},"wait":0}
2013-12-04 05:38:10,708 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-367:ctx-948bcdad) Sending cmd to http://10.147.40.14:8250/api/HypervResource/com.cloud.agent.api.StopCommand cmd data:{"isProxy":false,"executeInSequence":false,"vmName":"v-2-VM","contextMap":{},"wait":0}
2013-12-04 05:38:10,739 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-37267: Processing Seq 2-37267: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-04 05:38:10,745 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 2-37267: Sending Seq 2-37267: { Ans: , MgmtId: 7332683579487, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-04 05:38:11,792 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 3
2013-12-04 05:38:12,295 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-f5444059) ===START=== 10.146.0.134 -- GET command=listZones&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&id=c86fcc9b-7ffe-4131-8345-fb19e170b50c&_=1386133824060
2013-12-04 05:38:12,313 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-f5444059 ctx-b670db7f) ===END=== 10.146.0.134 -- GET command=listZones&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&id=c86fcc9b-7ffe-4131-8345-fb19e170b50c&_=1386133824060
2013-12-04 05:38:12,325 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-97e8ec33) ===START=== 10.146.0.134 -- GET command=listSystemVms&id=b317147b-0114-477f-8902-18dfb50b4258&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&_=1386133824086
2013-12-04 05:38:12,420 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-97e8ec33 ctx-52dfa8ad) ===END=== 10.146.0.134 -- GET command=listSystemVms&id=b317147b-0114-477f-8902-18dfb50b4258&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&_=1386133824086
2013-12-04 05:38:13,692 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-13162d15) ===START=== 10.146.0.134 -- GET command=queryAsyncJobResult&jobId=df4fe69c-1fe4-4824-84ad-d51ac2fd6bd0&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&_=1386133825454
2013-12-04 05:38:13,819 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-13162d15 ctx-e2281c4a) ===END=== 10.146.0.134 -- GET command=queryAsyncJobResult&jobId=df4fe69c-1fe4-4824-84ad-d51ac2fd6bd0&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&_=1386133825454
2013-12-04 05:38:14,689 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-360bacb7) ===START=== 10.146.0.134 -- GET command=destroySystemVm&id=b317147b-0114-477f-8902-18dfb50b4258&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&_=1386133826363
2013-12-04 05:38:14,718 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-22:ctx-360bacb7 ctx-57f15ec1) submit async job-46, details: AsyncJobVO {id:46, userId: 2, accountId: 2, instanceType: SystemVm, instanceId: 4, cmd: org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd, cmdInfo: {"response":"json","id":"b317147b-0114-477f-8902-18dfb50b4258","sessionkey":"6gEqK4AUWb7klI/aOH9lLsIqrVc\u003d","cmdEventType":"SSVM.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1386133826363","ctxAccountId":"2","ctxStartEventId":"219"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 7332683579487, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-12-04 05:38:14,719 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-360bacb7 ctx-57f15ec1) ===END=== 10.146.0.134 -- GET command=destroySystemVm&id=b317147b-0114-477f-8902-18dfb50b4258&response=json&sessionkey=6gEqK4AUWb7klI%2FaOH9lLsIqrVc%3D&_=1386133826363
2013-12-04 05:38:14,721 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-31:ctx-8c475e02) Add job-46 into job monitoring
2013-12-04 05:38:14,721 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-31:ctx-8c475e02) Executing AsyncJobVO {id:46, userId: 2, accountId: 2, instanceType: SystemVm, instanceId: 4, cmd: org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd, cmdInfo: {"response":"json","id":"b317147b-0114-477f-8902-18dfb50b4258","sessionkey":"6gEqK4AUWb7klI/aOH9lLsIqrVc\u003d","cmdEventType":"SSVM.DESTROY","ctxUserId":"2","httpmethod":"GET","_":"1386133826363","ctxAccountId":"2","ctxStartEventId":"219"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 7332683579487, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-12-04 05:38:14,753 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-31:ctx-8c475e02 ctx-57f15ec1) VM state transitted from :Running to Stopping with event: StopRequestedvm's original host id: 1 new host id: 1 host id before state transition: 1
2013-12-04 05:38:14,756 DEBUG [c.c.a.t.Request] (Job-Executor-31:ctx-8c475e02 ctx-57f15ec1) Seq 1-1034949125: Sending { Cmd , MgmtId: 7332683579487, via: 1(10.147.40.14), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"s-4-VM","wait":0}}] }
2013-12-04 05:38:14,756 DEBUG [c.c.a.t.Request] (Job-Executor-31:ctx-8c475e02 ctx-57f15ec1) Seq 1-1034949125: Executing: { Cmd , MgmtId: 7332683579487, via: 1(10.147.40.14), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"s-4-VM","wait":0}}] }
2013-12-04 05:38:14,757 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-391:ctx-b73c2c15) Seq 1-1034949125: Executing request
2013-12-04 05:38:14,757 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-391:ctx-b73c2c15) POST request tohttp://10.147.40.14:8250/api/HypervResource/com.cloud.agent.api.StopCommand with contents{"isProxy":false,"executeInSequence":false,"vmName":"s-4-VM","contextMap":{},"wait":0}
2013-12-04 05:38:14,757 DEBUG [c.c.h.h.r.HypervDirectConnectResource] (DirectAgent-391:ctx-b73c2c15) Sending cmd to http://10.147.40.14:8250/api/HypervResource/com.cloud.agent.api.StopCommand cmd data:{"isProxy":false,"executeInSequence":false,"vmName":"s-4-VM","contextMap":{},"wait":0}
2013-12-04 05:40:12,028 WARN [c.c.a.m.AgentManagerImpl] (Job-Executor-30:ctx-d6a82988 ctx-803fc411) Unsupported Command: Unsupported command issued:com.cloud.agent.api.StopCommand. Are you sure you got the right type of server?
2013-12-04 05:40:12,029 WARN [c.c.v.VirtualMachineManagerImpl] (Job-Executor-30:ctx-d6a82988 ctx-803fc411) Unable to stop vm VM[ConsoleProxy|v-2-VM]
2013-12-04 05:40:12,037 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-30:ctx-d6a82988 ctx-803fc411) VM state transitted from :Stopping to Running with event: OperationFailedvm's original host id: 1 new host id: 1 host id before state transition: 1
2013-12-04 05:40:12,044 ERROR [c.c.a.ApiAsyncJobDispatcher] (Job-Executor-30:ctx-d6a82988) Unexpected exception while executing org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd
com.cloud.utils.exception.CloudRuntimeException: Unable to stop VM[ConsoleProxy|v-2-VM]
at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1406)
at com.cloud.vm.VirtualMachineManagerImpl.advanceExpunge(VirtualMachineManagerImpl.java:450)
at com.cloud.vm.VirtualMachineManagerImpl.advanceExpunge(VirtualMachineManagerImpl.java:439)
at com.cloud.vm.VirtualMachineManagerImpl.expunge(VirtualMachineManagerImpl.java:428)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.destroyProxy(ConsoleProxyManagerImpl.java:1162)
at com.cloud.server.ManagementServerImpl.destroyConsoleProxy(ManagementServerImpl.java:2147)
at com.cloud.server.ManagementServerImpl.destroySystemVM(ManagementServerImpl.java:3205)
at com.cloud.server.ManagementServerImpl.destroySystemVM(ManagementServerImpl.java:607)
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 sun.proxy.$Proxy225.destroySystemVM(Unknown Source)
at org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd.execute(DestroySystemVmCmd.java:97)
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:520)
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:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
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-12-04 05:40:12,047 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-30:ctx-d6a82988) Complete async job-45, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to stop VM[ConsoleProxy|v-2-VM]"}
2013-12-04 05:40:12,056 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-30:ctx-d6a82988) Done executing org.apache.cloudstack.api.command.admin.systemvm.DestroySystemVmCmd for job-45
2013-12-04 05:40:12,060 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-30:ctx-d6a82988) Remove job-45 from job monitoring
--
This message was sent by Atlassian JIRA
(v6.1#6144)