Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 4E238187FC for ; Mon, 10 Aug 2015 05:23:47 +0000 (UTC) Received: (qmail 19525 invoked by uid 500); 10 Aug 2015 05:23:46 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 19351 invoked by uid 500); 10 Aug 2015 05:23:46 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 19106 invoked by uid 500); 10 Aug 2015 05:23:46 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 19073 invoked by uid 99); 10 Aug 2015 05:23:46 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 10 Aug 2015 05:23:46 +0000 Date: Mon, 10 Aug 2015 05:23:46 +0000 (UTC) From: "Adrian Sender (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (CLOUDSTACK-8718) Rethrow exception com.cloud.exception.ConcurrentOperationException: There are concurrent operations on VM MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-8718?page=3Dcom.atl= assian.jira.plugin.system.issuetabpanels:all-tabpanel ] Adrian Sender updated CLOUDSTACK-8718: -------------------------------------- Priority: Critical (was: Blocker) > Rethrow exception com.cloud.exception.ConcurrentOperationException: There= are concurrent operations on VM > -------------------------------------------------------------------------= -------------------------------- > > Key: CLOUDSTACK-8718 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-871= 8 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > 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=0970353012=09Status=09Active - Technical Support > Severity=092=09 =09=20 > Subject=09Rethrow exception com.cloud.exception.ConcurrentOperationExcept= ion: 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 d= isk 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) Th= e 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-Exe= cutor-9:ctx-116ace03 job-2133/job-2136 ctx-30d5ecdd) (logid:5808e018) Invoc= ation exception, caused by: com.cloud.exception.ConcurrentOperationExceptio= n: 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-Exec= utor-9:ctx-116ace03 job-2133/job-2136 ctx-30d5ecdd) (logid:5808e018) Rethro= w exception com.cloud.exception.ConcurrentOperationException: There are con= current operations on VM[User|i-8-189-VM] > 2015-07-20 14:36:50,430 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Execu= tor-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-Execu= tor-9:ctx-116ace03 job-2133/job-2136) (logid:5808e018) Unable to complete A= syncJobVO {id:2136, userId: 8, accountId: 8, instanceType: null, instanceId= : null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0= uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcG= xveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sY= W5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5n= O0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAA= GcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbk= lkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGd= XNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAIAAAAAAAAAAgAAAAAAAAA= vXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXR= pbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADH= cIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,= cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, resul= t: 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 op= erations on VM[User|i-8-189-VM] > at com.cloud.vm.VirtualMachineManagerImpl.changeToStartState(VirtualMachi= neManagerImpl.java:738) > at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachine= ManagerImpl.java:841) > at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachine= ManagerImpl.java:4570) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.j= ava:57) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess= orImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerPro= xy.java:107) > at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineM= anagerImpl.java:4726) > at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103) > at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInC= ontext(AsyncJobManagerImpl.java:549) > at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Man= agedContextRunnable.java:49) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.cal= l(DefaultManagedContext.java:56) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callW= ithContext(DefaultManagedContext.java:103) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWi= thContext(DefaultManagedContext.java:53) > at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Manag= edContextRunnable.java:46) > at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(As= yncJobManagerImpl.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.j= ava: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.depl= oyVirtualMachine(VMEntityManagerImpl.java:242) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl= .deploy(VirtualMachineEntityImpl.java:212) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.j= ava:3933) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.j= ava:3522) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.j= ava:3510) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.j= ava:57) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess= orImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflectio= n(AopUtils.java:317) > at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoi= npoint(ReflectiveMethodInvocation.java:183) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:150) > at org.apache.cloudstack.network.contrail.management.EventUtils$EventInte= rceptor.invoke(EventUtils.java:106) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:161) > at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.j= ava:51) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:161) > at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke= (ExposeInvocationInterceptor.java:91) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:172) > at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamic= AopProxy.java:204) > at com.sun.proxy.$Proxy197.startVirtualMachine(Unknown Source) > at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVM= Cmd.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.runInC= ontext(AsyncJobManagerImpl.java:549) > at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Man= agedContextRunnable.java:49) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.cal= l(DefaultManagedContext.java:56) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callW= ithContext(DefaultManagedContext.java:103) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWi= thContext(DefaultManagedContext.java:53) > at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Manag= edContextRunnable.java:46) > at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(As= yncJobManagerImpl.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.j= ava: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 co= ncurrent 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.res= ponse.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Un= able 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 n= ew 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=3D4 > 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.depl= oyVirtualMachine(VMEntityManagerImpl.java:242) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl= .deploy(VirtualMachineEntityImpl.java:212) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.j= ava:3933) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.j= ava:3522) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.j= ava:3510) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.j= ava:57) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess= orImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflectio= n(AopUtils.java:317) > at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoi= npoint(ReflectiveMethodInvocation.java:183) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:150) > at org.apache.cloudstack.network.contrail.management.EventUtils$EventInte= rceptor.invoke(EventUtils.java:106) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:161) > at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.j= ava:51) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:161) > at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke= (ExposeInvocationInterceptor.java:91) > at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R= eflectiveMethodInvocation.java:172) > at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamic= AopProxy.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.runInC= ontext(AsyncJobManagerImpl.java:549) > at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Man= agedContextRunnable.java:49) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.cal= l(DefaultManagedContext.java:56) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callW= ithContext(DefaultManagedContext.java:103) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWi= thContext(DefaultManagedContext.java:53) > at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Manag= edContextRunnable.java:46) > at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(As= yncJobManagerImpl.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.j= ava: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 co= ncurrent 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 op= erations on VM[User|i-2-242-VM] > at com.cloud.vm.VirtualMachineManagerImpl.changeToStartState(VirtualMachi= neManagerImpl.java:738) > at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachine= ManagerImpl.java:841) > at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachine= ManagerImpl.java:4570) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.j= ava:57) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess= orImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerPro= xy.java:107) > at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineM= anagerImpl.java:4726) > at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103) > at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInC= ontext(AsyncJobManagerImpl.java:549) > at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Man= agedContextRunnable.java:49) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.cal= l(DefaultManagedContext.java:56) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callW= ithContext(DefaultManagedContext.java:103) > at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWi= thContext(DefaultManagedContext.java:53) > at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Manag= edContextRunnable.java:46) > at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(As= yncJobManagerImpl.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.j= ava: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-Exe= cutor-24:ctx-dba85e96 job-2708/job-2710 ctx-88da0a6e) (logid:3c50fa44) Invo= cation exception, caused by: com.cloud.exception.ConcurrentOperationExcepti= on: 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-Exec= utor-24:ctx-dba85e96 job-2708/job-2710 ctx-88da0a6e) (logid:3c50fa44) Rethr= ow exception com.cloud.exception.ConcurrentOperationException: There are co= ncurrent 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-e= xec-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 NicPr= ofile[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 V= M[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 f= or 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 entr= y 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] reservatio= n id =3D 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=3DVM[User|i-2-228-VM], P0=3DDest[Zone(Id)-Pod(Id)-Clu= ster(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-Ex= ecutor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Che= cking 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=3D4 > 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) T= he 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-Exe= cutor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Invo= cation exception, caused by: com.cloud.exception.ConcurrentOperationExcepti= on: 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-Exec= utor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Rethr= ow exception com.cloud.exception.ConcurrentOperationException: There are co= ncurrent operations on VM[User|i-2-228-VM] > com.cloud.exception.ConcurrentOperationException: There are concurrent op= erations on VM[User|i-2-228-VM] > Caused by: com.cloud.exception.ConcurrentOperationException: There are co= ncurrent operations on VM[User|i-2-228-VM] > 2015-08-04 17:18:26,398 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAge= ntCronJob-342:ctx-3ea621d1) (logid:cf7affe0) VM i-2-228-VM is at Starting a= nd 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:c= tx-3ea621d1) (logid:cf7affe0) Seq 2-5120311301343547019: Sending { Cmd , Mg= mtId: 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-Exe= cutor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Invo= cation exception, caused by: com.cloud.exception.ConcurrentOperationExcepti= on: 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-Exec= utor-17:ctx-b59389aa job-2545/job-2552 ctx-56c35134) (logid:dd94b35a) Rethr= ow exception com.cloud.exception.ConcurrentOperationException: There are co= ncurrent operations on VM[User|i-2-228-VM] > com.cloud.exception.ConcurrentOperationException: There are concurrent op= erations on VM[User|i-2-228-VM] > Caused by: com.cloud.exception.ConcurrentOperationException: There are co= ncurrent operations on VM[User|i-2-228-VM] > 2015-08-04 17:18:26,398 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAge= ntCronJob-342:ctx-3ea621d1) (logid:cf7affe0) VM i-2-228-VM is at Starting a= nd 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:c= tx-3ea621d1) (logid:cf7affe0) Seq 2-5120311301343547019: Sending { Cmd , Mg= mtId: 192022089101382, via: 2(xenserver-02.testlabs.com.au), Ver: v1, Flags= : 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSe= quence":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:c= tx-3ea621d1) (logid:cf7affe0) Seq 2-5120311301343547019: Executing: { Cmd ,= MgmtId: 192022089101382, via: 2(xenserver-02.testlabs.com.au), Ver: v1, Fl= ags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeI= nSequence":true,"checkBeforeCleanup":true,"vmName":"i-2-228-VM","wait":0}}]= } > 2015-08-04 17:18:26,729 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAge= ntCronJob-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-5120311301= 343547417: Sending { Cmd , MgmtId: 192022089101382, via: 2(xenserver-02.tes= tlabs.com.au), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":= {"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":false,"vmNam= e":"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-5120311301= 343547417: Executing: { Cmd , MgmtId: 192022089101382, via: 2(xenserver-02.= testlabs.com.au), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopComman= d":{"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":false,"vm= Name":"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 Starti= ng state > 2015-08-04 19:16:01,123 DEBUG [c.c.v.d.VMInstanceDaoImpl] (Work-Job-Execu= tor-15:ctx-a341115f job-2545/job-2546 ctx-e0898a81) (logid:dd94b35a) Unable= to update VM[User|i-2-228-VM]: DB Data=3D{Host=3Dnull; State=3DStopped; up= dated=3D3; time=3DTue Aug 04 17:18:26 AEST 2015} New Data: {Host=3Dnull; St= ate=3DStopped; updated=3D3; time=3DTue Aug 04 17:18:26 AEST 2015} Stale Dat= a: {Host=3D2; State=3DStarting; updated=3D2; time=3DTue Aug 04 16:15:37 AES= T 2015} -- This message was sent by Atlassian JIRA (v6.3.4#6332)