shweta agarwal created CLOUDSTACK-5324:
------------------------------------------
Summary: error message not proper when start VM fails because
router reuires upgrade
Key: CLOUDSTACK-5324
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5324
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Upgrade
Affects Versions: 4.3.0
Reporter: shweta agarwal
Assignee: Kishan Kavala
Fix For: 4.3.0
Repro steps:
Create a VM on 3.07 setup
Upgrade to 4.3.0 but dont upgrade routers
Stop user VM
Start user VM
Bug:
Error message shows "Unable to start a VM due to concurrent operation
Expectation :
Error message should show " router requires upgrade "
MS log snippet :
2013-12-02 12:28:09,029 ERROR [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Failed to start instance
VM[User|f01ae0d5-23b3-44c4-9e8d-9df9245874be]
com.cloud.utils.exception.CloudRuntimeException: Router requires upgrade.
Unable to send command to router:4
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.sendCommandsToRouter(VirtualNetworkApplianceManagerImpl.java:3437)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl$7.execute(VirtualNetworkApplianceManagerImpl.java:2873)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:3722)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:2865)
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:622)
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
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 com.sun.proxy.$Proxy239.applyDhcpEntry(Unknown Source)
at
com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:914)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1171)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1293)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1229)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:899)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:706)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:552)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:236)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3465)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1921)
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:622)
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 com.sun.proxy.$Proxy169.startVirtualMachine(Unknown Source)
at
org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.java:121)
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.lang.Thread.run(Thread.java:701)
2013-12-02 12:28:09,097 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Cleaning up resources for the vm
VM[User|f01ae0d5-23b3-44c4-9e8d-9df9245874be] in Starting state
2013-12-02 12:28:09,099 DEBUG [c.c.a.t.Request] (Job-Executor-9:ctx-1bf286cd
ctx-4cabd091) Seq 1-1690925677: Sending { Cmd , MgmtId: 233845177509765, via:
1(Rack1Pod1Host24), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-3-VM","wait":0}}]
}
2013-12-02 12:28:09,099 DEBUG [c.c.a.t.Request] (Job-Executor-9:ctx-1bf286cd
ctx-4cabd091) Seq 1-1690925677: Executing: { Cmd , MgmtId: 233845177509765,
via: 1(Rack1Pod1Host24), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-3-VM","wait":0}}]
}
2013-12-02 12:28:09,100 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-183:ctx-e0a9d3bb) Seq 1-1690925677: Executing request
2013-12-02 12:28:09,186 INFO [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-183:ctx-e0a9d3bb) VM does not exist on
XenServerceca7304-b915-4623-8975-e07f4093f416
2013-12-02 12:28:09,186 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-183:ctx-e0a9d3bb) Seq 1-1690925677: Response Received:
2013-12-02 12:28:09,186 DEBUG [c.c.a.t.Request] (DirectAgent-183:ctx-e0a9d3bb)
Seq 1-1690925677: Processing: { Ans: , MgmtId: 233845177509765, via: 1, Ver:
v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM
does not exist","wait":0}}] }
2013-12-02 12:28:09,186 DEBUG [c.c.a.t.Request] (Job-Executor-9:ctx-1bf286cd
ctx-4cabd091) Seq 1-1690925677: Received: { Ans: , MgmtId: 233845177509765,
via: 1, Ver: v1, Flags: 10, { StopAnswer } }
2013-12-02 12:28:09,194 DEBUG [c.c.n.NetworkModelImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Service SecurityGroup is not
supported in the network id=204
2013-12-02 12:28:09,197 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Changing active number of nics for
network id=204 on -1
2013-12-02 12:28:09,268 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Asking VirtualRouter to release
NicProfile[8-3-e1ae98d3-8718-439b-87d2-97fc0bf0ff68-10.1.1.143-null
2013-12-02 12:28:09,268 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Successfully released network
resources for the vm VM[User|f01ae0d5-23b3-44c4-9e8d-9df9245874be]
2013-12-02 12:28:09,268 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Successfully cleanued up resources
for the vm VM[User|f01ae0d5-23b3-44c4-9e8d-9df9245874be] in Starting state
2013-12-02 12:28:09,397 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) VM state transitted from :Starting
to Stopped with event: OperationFailedvm's original host id: 5 new host id:
null host id before state transition: 1
2013-12-02 12:28:09,403 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Hosts's actual total CPU: 12372 and
CPU after applying overprovisioning: 12372
2013-12-02 12:28:09,403 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) Hosts's actual total RAM: 7907453568
and RAM after applying overprovisioning: 7907453440
2013-12-02 12:28:09,403 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) release cpu from host: 1, old used:
4896,reserved: 0, actual total: 12372, total with overprovisioning: 12372; new
used: 4768,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-02 12:28:09,403 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-9:ctx-1bf286cd ctx-4cabd091) release mem from host: 1, old used:
2147483648,reserved: 0, total: 7907453440; new used: 2013265920,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2013-12-02 12:28:09,616 ERROR [c.c.a.ApiAsyncJobDispatcher]
(Job-Executor-9:ctx-1bf286cd) Unexpected exception while executing
org.apache.cloudstack.api.command.user.vm.StartVMCmd
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to
concurrent operation
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:558)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:236)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3465)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1921)
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:622)
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 com.sun.proxy.$Proxy169.startVirtualMachine(Unknown Source)
at
org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.java:121)
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.lang.Thread.run(Thread.java:701)
Caused by: com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
unreachable: Host 1: Unable to start instance due to Router requires upgrade.
Unable to send command to router:4
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1011)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:706)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:552)
... 37 more
Caused by: com.cloud.utils.exception.CloudRuntimeException: Router requires
upgrade. Unable to send command to router:4
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.sendCommandsToRouter(VirtualNetworkApplianceManagerImpl.java:3437)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl$7.execute(VirtualNetworkApplianceManagerImpl.java:2873)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:3722)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:2865)
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:622)
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
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 com.sun.proxy.$Proxy239.applyDhcpEntry(Unknown Source)
at
com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:914)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1171)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1293)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1229)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:899)
... 39 more
2013-12-02 12:28:09,619 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-9:ctx-1bf286cd) Complete async job-182, jobStatus: FAILED,
resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable
to start a VM due to concurrent operation"}
2013-12-02 12:28:09,674 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-9:ctx-1bf286cd) Done executing
org.apache.cloudstack.api.command.user.vm.StartVMCmd for job-182
2013-12-02 12:28:09,699 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-9:ctx-1bf286cd) Remove job-
--
This message was sent by Atlassian JIRA
(v6.1#6144)
