Hi,
I just had client upload 200GB volume/template, and tried to deploy new VM
from it.
GUI timeout after ~ 30min - saying VM is now in Error state, but for some
time after th VM error out, I coul see ROOT-xxx volume being created on
CEPH - and timestamp updated regularry in "volumes" table in database - and
after this, ROOT-xxx went into destroyed state.
>From MGMT logs I could see almost hunderds of messages like the first 2
lines from the log below, and then complete failure as can be seen from
MGMT logs.
Any help would be really appreciated since this is LIVE enviroment, ACS
4.3.0.
Thanks,
2015-02-26 12:07:05,238 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-145:ctx-3609c7c0 ctx-b101c9c8) Waiting some more to make sure
there's no activity on VM[User|DNG-ACC]
2015-02-26 12:07:05,303 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-140:ctx-0f9aa245 ctx-7db9ecb6) Waiting some more to make sure
there's no activity on VM[User|DNG-ACC]
2015-02-26 12:07:05,305 WARN [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-140:ctx-0f9aa245 ctx-7db9ecb6) The task item for vm
VM[User|DNG-ACC] has been inactive for 3660
2015-02-26 12:07:05,360 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-145:ctx-3609c7c0 ctx-b101c9c8) Waiting some more to make sure
there's no activity on VM[User|DNG-ACC]
2015-02-26 12:07:05,382 ERROR [c.c.a.ApiAsyncJobDispatcher]
(Job-Executor-140:ctx-0f9aa245) 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:603)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:207)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3581)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2043)
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:509)
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.ConcurrentOperationException: There are
concurrent operations on VM[User|DNG-ACC]
at
com.cloud.vm.VirtualMachineManagerImpl.changeToStartState(VirtualMachineManagerImpl.java:701)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:800)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:601)
... 37 more
2015-02-26 12:07:05,384 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-140:ctx-0f9aa245) Complete async job-20629, 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"}
2015-02-26 12:07:05,385 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-2:null) Seq 22-1291533430: Processing: { Ans: ,
MgmtId: 161344838950, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-1210-VM","bytesSent":5871992,"bytesReceived":5502153,"result":true,"details":"","wait":0}}]
}
2015-02-26 12:07:05,385 DEBUG [c.c.a.t.Request]
(RouterMonitor-1:ctx-98de907f) Seq 22-1291533430: Received: { Ans: ,
MgmtId: 161344838950, via: 22, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2015-02-26 12:07:05,385 DEBUG [c.c.a.m.AgentManagerImpl]
(RouterMonitor-1:ctx-98de907f) Details from executing class
com.cloud.agent.api.NetworkUsageCommand:
2015-02-26 12:07:05,415 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-10:null) Seq 22-1291533431: Processing: { Ans: ,
MgmtId: 161344838950, via: 22, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.CheckS2SVpnConnectionsAnswer":{"ipToConnected":{},"ipToDetail":{},"details":"CheckS2SVpnConneciontsCommand
failed","result":false,"wait":0}}] }
2015-02-26 12:07:05,415 DEBUG [c.c.a.m.AgentAttache]
(AgentManager-Handler-10:null) Seq 22-1291533431: No more commands found
2015-02-26 12:07:05,415 DEBUG [c.c.a.t.Request]
(RouterStatusMonitor-1:ctx-7173341a) Seq 22-1291533431: Received: { Ans: ,
MgmtId: 161344838950, via: 22, Ver: v1, Flags: 110, {
CheckS2SVpnConnectionsAnswer } }
2015-02-26 12:07:05,415 DEBUG [c.c.a.m.AgentManagerImpl]
(RouterStatusMonitor-1:ctx-7173341a) Details from executing class
com.cloud.agent.api.CheckS2SVpnConnectionsCommand:
CheckS2SVpnConneciontsCommand failed
2015-02-26 12:07:05,415 WARN [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-7173341a) Unable to update router r-1996-VM's
VPN connection status
2015-02-26 12:07:05,416 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-7173341a) Found 0 networks to update RvR status.
2015-02-26 12:07:05,430 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-140:ctx-0f9aa245) Done executing
org.apache.cloudstack.api.command.user.vm.StartVMCmd for job-20629
2015-02-26 12:07:05,433 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-140:ctx-0f9aa245) Remove job-20629 from job monitoring
2015-02-26 12:07:05,482 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-145:ctx-3609c7c0 ctx-b101c9c8) Waiting some more to make sure
there's no activity on VM[User|DNG-ACC]
2015-02-26 12:07:05,484 WARN [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-145:ctx-3609c7c0 ctx-b101c9c8) The task item for vm
VM[User|DNG-ACC] has been inactive for 3660
2015-02-26 12:07:05,519 ERROR [c.c.a.ApiAsyncJobDispatcher]
(Job-Executor-145:ctx-3609c7c0) 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:603)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:207)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3581)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2043)
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:509)
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)
Caused by: com.cloud.exception.ConcurrentOperationException: There are
concurrent operations on VM[User|DNG-ACC]
at
com.cloud.vm.VirtualMachineManagerImpl.changeToStartState(VirtualMachineManagerImpl.java:701)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:800)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:601)
... 37 more
2015-02-26 12:07:05,520 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-145:ctx-3609c7c0) Complete async job-20635, 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"}
--
Andrija Panić
