You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Adrian Sender (JIRA)" <ji...@apache.org> on 2015/08/10 07:24:45 UTC
[jira] [Commented] (CLOUDSTACK-8718) Rethrow exception
com.cloud.exception.ConcurrentOperationException: There are concurrent
operations on VM
[ https://issues.apache.org/jira/browse/CLOUDSTACK-8718?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14679585#comment-14679585 ]
Adrian Sender commented on CLOUDSTACK-8718:
-------------------------------------------
Logs can be found in the below support request, I will also upload a fresh set of logs.
Citrix Case Detail:
Case Information:
Case Number 70353012 Status Active - Technical Support
Severity 2
Subject Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM
> Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM
> ---------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-8718
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8718
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Automation
> Affects Versions: 4.5.1
> Environment: Cloudplatform 4.5
> Xenserver 6.5
> EMC Fiber Channel Primary Storage
> Freenas NFS Secondary Storage
> Citrix Case Detail:
> Case Information:
> Case Number 70353012 Status Active - Technical Support
> Severity 2
> Subject Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM
> Reporter: Adrian Sender
> Priority: Critical
> Fix For: 4.3.1
>
>
> Cannot deploy instances from large size root disk templates. Small root disk works without any problem.
> 2015-07-20 14:36:50,429 WARN [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-9:ctx-116ace03 job-2133/job-2136 ctx-30d5ecdd) (logid:5808e018) The task item for vm VM[User|i-8-189-VM] has been inactive for 3602
> 2015-07-20 14:36:50,429 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-116ace03 job-2133/job-2136 ctx-30d5ecdd) (logid:5808e018) Invocation exception, caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-8-189-VM]
> 2015-07-20 14:36:50,430 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-9:ctx-116ace03 job-2133/job-2136 ctx-30d5ecdd) (logid:5808e018) Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-8-189-VM]
> 2015-07-20 14:36:50,430 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-116ace03 job-2133/job-2136) (logid:5808e018) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 189, job origin: 2133
> 2015-07-20 14:36:50,430 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-9:ctx-116ace03 job-2133/job-2136) (logid:5808e018) Unable to complete AsyncJobVO {id:2136, userId: 8, accountId: 8, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAIAAAAAAAAAAgAAAAAAAAAvXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 192022089101382, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Jul 20 14:36:49 EST 2015}, job origin:2133
> com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-8-189-VM]
> at com.cloud.vm.VirtualMachineManagerImpl.changeToStartState(VirtualMachineManagerImpl.java:738)
> at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:841)
> at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4570)
> 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:606)
> at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4726)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:549)
> 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 org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:500)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to concurrent operation
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:628)
> at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:242)
> at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3933)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3522)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3510)
> 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:606)
> 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.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:106)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
> at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
> 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.$Proxy197.startVirtualMachine(Unknown Source)
> at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:453)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:132)
> at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:549)
> 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 org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:500)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-8-189-VM]
> ... 35 more
> 2015-07-20 14:36:50,623 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-12:ctx-8d825486 job-2133) (logid:5808e018) Complete async job-2133, 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-08-10 12:55:19,622 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-24:ctx-dba85e96 job-2708/job-2710 ctx-88da0a6e) (logid:3c50fa44) Unable to transition into Starting state due to Unable to transition to a new state from Starting via StartRequested
> 2015-08-10 12:55:19,627 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-24:ctx-dba85e96 job-2708/job-2710 ctx-88da0a6e) (logid:3c50fa44) Determining why we're unable to update the state to Starting for VM[User|i-2-242-VM]. Retry=4
> com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to concurrent operation
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:628)
> at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:242)
> at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3933)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3522)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3510)
> 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:606)
> 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.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:106)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
> at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
> 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.$Proxy197.startVirtualMachine(Unknown Source)
> at org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(DeployVMCmdByAdmin.java:50)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:132)
> at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:549)
> 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 org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:500)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-242-VM]
> ... 35 more
> pdated: null, lastPolled: null, created: Mon Aug 10 12:55:17 AEST 2015}, job origin:2708
> com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-242-VM]
> at com.cloud.vm.VirtualMachineManagerImpl.changeToStartState(VirtualMachineManagerImpl.java:738)
> at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:841)
> at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4570)
> 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:606)
> at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4726)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:549)
> 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 org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:500)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> 2015-08-10 12:57:19,651 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-24:ctx-dba85e96 job-2708/job-2710 ctx-88da0a6e) (logid:3c50fa44) Invocation exception, caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-242-VM]
> 2015-08-10 12:57:19,651 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-24:ctx-dba85e96 job-2708/job-2710 ctx-88da0a6e) (logid:3c50fa44) Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-242-VM]
> Created By: Adrian Sender (8/7/2015 1:59 AM)
> 2015-08-04 16:15:34,613 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-11:ctx-06124a50 ctx-53fdadbd) (logid:7da2cbb6) Allocating entries for VM: VM[User|i-2-228-VM]
> 2015-08-04 16:15:34,615 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-11:ctx-06124a50 ctx-53fdadbd) (logid:7da2cbb6) Allocating nics for VM[User|i-2-228-VM]
> 2015-08-04 16:15:34,616 DEBUG [o.a.c.e.o.NetworkOrchestrator] (catalina-exec-11:ctx-06124a50 ctx-53fdadbd) (logid:7da2cbb6) Allocating nic for vm VM[User|i-2-228-VM] in network Ntwk[204|Guest|8] with requested profile NicProfile[0-0-null-null-null
> 2015-08-04 16:15:34,681 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-11:ctx-06124a50 ctx-53fdadbd) (logid:7da2cbb6) Allocating disks for VM[User|i-2-228-VM]
> 2015-08-04 16:15:34,705 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-11:ctx-06124a50 ctx-53fdadbd) (logid:7da2cbb6) Allocation completed for VM: VM[User|i-2-228-VM]
> 2015-08-04 16:15:34,705 DEBUG [c.c.v.UserVmManagerImpl] (catalina-exec-11:ctx-06124a50 ctx-53fdadbd) (logid:7da2cbb6) Successfully allocated DB entry for VM[User|i-2-228-VM]
> 2015-08-04 16:15:36,925 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Successfully transitioned to start state for VM[User|i-2-228-VM] reservation id = c4ca8403-31bb-4260-8048-b1399b83e2cc
> 2015-08-04 16:15:37,045 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Deployment found - P0=VM[User|i-2-228-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(237|ROOT-->Pool(3))]
> 2015-08-04 16:15:58,405 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Checking if we need to prepare 1 volumes for VM[User|i-2-228-VM]
> 2015-08-04 17:15:42,667 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Determining why we're unable to update the state to Starting for VM[User|i-2-228-VM]. Retry=4
> 2015-08-04 17:17:42,675 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Waiting some more to make sure there's no activity on VM[User|i-2-228-VM]
> 2015-08-04 17:17:42,683 WARN [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) The task item for vm VM[User|i-2-228-VM] has been inactive for 3720
> 2015-08-04 17:17:42,683 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Invocation exception, caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> 2015-08-04 17:17:42,683 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> Caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> 2015-08-04 17:18:26,398 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAgentCronJob-342:ctx-3ea621d1) (logid:cf7affe0) VM i-2-228-VM is at Starting and we received a power-off report while there is no pending jobs on it
> 2015-08-04 17:18:26,408 DEBUG [c.c.a.t.Request] (DirectAgentCronJob-342:ctx-3ea621d1) (logid:cf7affe0) Seq 2-5120311301343547019: Sending { Cmd , MgmtId: 192022089101382, via: 2(xenserver-02.testlabs.com.au), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":
> 2015-08-04 17:17:42,683 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Invocation exception, caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> 2015-08-04 17:17:42,683 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> Caused by: com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM[User|i-2-228-VM]
> 2015-08-04 17:18:26,398 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAgentCronJob-342:ctx-3ea621d1) (logid:cf7affe0) VM i-2-228-VM is at Starting and we received a power-off report while there is no pending jobs on it
> 2015-08-04 17:18:26,408 DEBUG [c.c.a.t.Request] (DirectAgentCronJob-342:ctx-3ea621d1) (logid:cf7affe0) Seq 2-5120311301343547019: Sending { Cmd , MgmtId: 192022089101382, via: 2(xenserver-02.testlabs.com.au), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":true,"vmName":"i-2-228-VM","wait":0}}] }
> 2015-08-04 17:18:26,411 DEBUG [c.c.a.t.Request] (DirectAgentCronJob-342:ctx-3ea621d1) (logid:cf7affe0) Seq 2-5120311301343547019: Executing: { Cmd , MgmtId: 192022089101382, via: 2(xenserver-02.testlabs.com.au), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":true,"vmName":"i-2-228-VM","wait":0}}] }
> 2015-08-04 17:18:26,729 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAgentCronJob-342:ctx-3ea621d1) (logid:cf7affe0) VM i-2-228-VM is sync-ed to at Stopped state according to power-off report from hypervisor
> 2015-08-04 19:16:00,975 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Cleaning up resources for the vm VM[User|i-2-228-VM] in Starting state
> 2015-08-04 19:16:00,984 DEBUG [c.c.a.t.Request] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Seq 2-5120311301343547417: Sending { Cmd , MgmtId: 192022089101382, via: 2(xenserver-02.testlabs.com.au), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":false,"vmName":"i-2-228-VM","wait":0}}] }
> 2015-08-04 19:16:00,986 DEBUG [c.c.a.t.Request] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Seq 2-5120311301343547417: Executing: { Cmd , MgmtId: 192022089101382, via: 2(xenserver-02.testlabs.com.au), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":false,"vmName":"i-2-228-VM","wait":0}}] }
> 2015-08-04 19:16:01,085 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Successfully released network resources for the vm VM[User|i-2-228-VM]
> 2015-08-04 19:16:01,085 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Successfully cleanued up resources for the vm VM[User|i-2-228-VM] in Starting state
> 2015-08-04 19:16:01,123 DEBUG [c.c.v.d.VMInstanceDaoImpl] (Work-Job-Executor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Unable to update VM[User|i-2-228-VM]: DB Data={Host=null; State=Stopped; updated=3; time=Tue Aug 04 17:18:26 AEST 2015} New Data: {Host=null; State=Stopped; updated=3; time=Tue Aug 04 17:18:26 AEST 2015} Stale Data: {Host=2; State=Starting; updated=2; time=Tue Aug 04 16:15:37 AEST 2015}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)