Hello, I get following error for any operation on an existing ACS installation. The management server was working well for a few months. This has been started to happen since a few days ago.
Unable to schedule async job for command com.cloud.vm.VmWorkStop, unexpected exception. Logs: 2019-07-23 08:39:50,349 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-721f805e job-20128/job-20129 ctx-d234a139) (logid:9403bb3e) Update db status for job-20129 2019-07-23 08:39:50,349 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-721f805e job-20128/job-20129 ctx-d234a139) (logid:9403bb3e) Wake up jobs joined with job-20129 and disjoin all subjobs created from job- 20129 2019-07-23 08:39:50,353 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-721f805e job-20128/job-20129) (logid:9403bb3e) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 264, job origin: 20128 2019-07-23 08:39:50,353 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-721f805e job-20128/job-20129) (logid:9403bb3e) Done executing com.cloud.vm.VmWorkStop for job-20129 2019-07-23 08:39:50,354 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-721f805e job-20128/job-20129) (logid:9403bb3e) Remove job-20129 from job monitoring 2019-07-23 08:39:50,363 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128 ctx-bd656426) (logid:9403bb3e) Destroying vm VM[User|i-50-264-VM], expunge flag off 2019-07-23 08:39:50,369 DEBUG [c.c.u.d.T.Transaction] (API-Job-Executor-6:ctx-3fb9ca20 job-20128 ctx-bd656426) (logid:9403bb3e) Rolling back the transaction: Time = 0 Name = API-Job-Executor-6; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-Transaction.execute:43-Transaction.execute:47-AsyncJobManagerImpl.submitAsyncJob:231-VirtualMachineManagerImpl.stopVmThroughJobQueue:4666-VirtualMachineManagerImpl.advanceStop:1599-VirtualMachineManagerImpl.destroy:1864-VMEntityManagerImpl.destroyVirtualMachine:271-VirtualMachineEntityImpl.destroy:233-UserVmManagerImpl.destroyVm:4580 2019-07-23 08:39:50,370 WARN [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128 ctx-bd656426) (logid:9403bb3e) Unable to schedule async job for command com.cloud.vm.VmWorkStop, unexpected exception. javax.persistence.EntityExistsException: Entity already exists: at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1448) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$1.doInTransaction(AsyncJobManagerImpl.java:235) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$1.doInTransaction(AsyncJobManagerImpl.java:231) at com.cloud.utils.db.Transaction$2.doInTransaction(Transaction.java:50) at com.cloud.utils.db.Transaction.execute(Transaction.java:40) at com.cloud.utils.db.Transaction.execute(Transaction.java:47) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:231) at com.cloud.vm.VirtualMachineManagerImpl.stopVmThroughJobQueue(VirtualMachineManagerImpl.java:4666) at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1599) at com.cloud.vm.VirtualMachineManagerImpl.destroy(VirtualMachineManagerImpl.java:1864) at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.destroyVirtualMachine(VMEntityManagerImpl.java:271) at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.destroy(VirtualMachineEntityImpl.java:233) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:4580) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:2787) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) at com.sun.proxy.$Proxy165.destroyVm(Unknown Source) at org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin.execute(DestroyVMCmdByAdmin.java:46) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583) 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:531) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '20130' for key 'PRIMARY' at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ... 59 more 2019-07-23 08:39:50,375 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin com.cloud.utils.exception.CloudRuntimeException: Unable to schedule async job for command com.cloud.vm.VmWorkStop, unexpected exception. at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:247) at com.cloud.vm.VirtualMachineManagerImpl.stopVmThroughJobQueue(VirtualMachineManagerImpl.java:4666) at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1599) at com.cloud.vm.VirtualMachineManagerImpl.destroy(VirtualMachineManagerImpl.java:1864) at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.destroyVirtualMachine(VMEntityManagerImpl.java:271) at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.destroy(VirtualMachineEntityImpl.java:233) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:4580) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:2787) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) at com.sun.proxy.$Proxy165.destroyVm(Unknown Source) at org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin.execute(DestroyVMCmdByAdmin.java:46) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583) 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:531) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2019-07-23 08:39:50,376 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Complete async job-20128, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to schedule async job for command com.cloud.vm.VmWorkStop, unexpected exception."} 2019-07-23 08:39:50,377 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Publish async job-20128 complete on message bus 2019-07-23 08:39:50,377 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Wake up jobs related to job-20128 2019-07-23 08:39:50,377 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Update db status for job-20128 2019-07-23 08:39:50,378 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Wake up jobs joined with job-20128 and disjoin all subjobs created from job- 20128 2019-07-23 08:39:50,380 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Done executing org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin for job-20128 2019-07-23 08:39:50,380 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-6:ctx-3fb9ca20 job-20128) (logid:9403bb3e) Remove job-20128 from job monitoring 2019-07-23 08:39:51,348 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-8e2fd6af) (logid:602909a8) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:51,351 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-8e2fd6af ctx-8a953695) (logid:602909a8) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:39:51,360 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-8e2fd6af ctx-8a953695 ctx-41c1bd15) (logid:602909a8) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:53,363 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-07f74f3b) (logid:6a547383) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:53,366 DEBUG [c.c.a.ApiServer] (qtp2114650936-21:ctx-07f74f3b ctx-31827452) (logid:6a547383) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:39:53,375 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-07f74f3b ctx-31827452 ctx-4044e2db) (logid:6a547383) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:54,327 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-e348b616) (logid:e3ef68cc) Begin cleanup expired async-jobs 2019-07-23 08:39:54,330 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-e348b616) (logid:e3ef68cc) End cleanup expired async-jobs 2019-07-23 08:39:55,378 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-f4c248cc) (logid:b2356ead) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:55,386 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-f4c248cc ctx-a73fc2b9) (logid:b2356ead) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:39:55,396 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-f4c248cc ctx-a73fc2b9 ctx-16510da6) (logid:b2356ead) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:57,398 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-cb9e3601) (logid:dc783c14) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:57,401 DEBUG [c.c.a.ApiServer] (qtp2114650936-21:ctx-cb9e3601 ctx-5016e6c5) (logid:dc783c14) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:39:57,409 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-cb9e3601 ctx-5016e6c5 ctx-68e36013) (logid:dc783c14) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:59,411 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-6fea0c17) (logid:2d4d4b54) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:39:59,414 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-6fea0c17 ctx-00ef113e) (logid:2d4d4b54) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:39:59,422 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-6fea0c17 ctx-00ef113e ctx-f85046c0) (logid:2d4d4b54) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:01,425 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-a269ad1d) (logid:3169993d) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:01,428 DEBUG [c.c.a.ApiServer] (qtp2114650936-21:ctx-a269ad1d ctx-7a1f1350) (logid:3169993d) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:01,437 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-a269ad1d ctx-7a1f1350 ctx-64842531) (logid:3169993d) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:03,440 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-ecefec86) (logid:804f3dad) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:03,443 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-ecefec86 ctx-bf70065d) (logid:804f3dad) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:03,451 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-ecefec86 ctx-bf70065d ctx-7352af1e) (logid:804f3dad) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:04,326 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0831b40a) (logid:7a19f7eb) Begin cleanup expired async-jobs 2019-07-23 08:40:04,329 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0831b40a) (logid:7a19f7eb) End cleanup expired async-jobs 2019-07-23 08:40:05,337 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-317aad5b) (logid:47a25006) Zone 1 is ready to launch secondary storage VM 2019-07-23 08:40:05,416 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-d33b0d84) (logid:72535152) Zone 1 is ready to launch console proxy 2019-07-23 08:40:05,454 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-b318d0e5) (logid:8e6ac333) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:05,456 DEBUG [c.c.a.ApiServer] (qtp2114650936-21:ctx-b318d0e5 ctx-1b423ac6) (logid:8e6ac333) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:05,463 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-b318d0e5 ctx-1b423ac6 ctx-d19778ba) (logid:8e6ac333) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:07,466 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-04470417) (logid:e25a360a) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:07,469 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-04470417 ctx-87a9f260) (logid:e25a360a) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:07,478 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-04470417 ctx-87a9f260 ctx-8af5617e) (logid:e25a360a) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:09,480 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-5e1e0780) (logid:2d36d0fc) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:09,484 DEBUG [c.c.a.ApiServer] (qtp2114650936-21:ctx-5e1e0780 ctx-5786c236) (logid:2d36d0fc) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:09,492 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-5e1e0780 ctx-5786c236 ctx-b34b74bd) (logid:2d36d0fc) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:11,495 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-847299bd) (logid:65aa152d) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:11,497 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-847299bd ctx-7c8e5dc2) (logid:65aa152d) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:11,504 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-847299bd ctx-7c8e5dc2 ctx-7e7a3b5f) (logid:65aa152d) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:13,465 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Storage pool garbage collector found 0 templates to clean up in storage pool: Primary1 2019-07-23 08:40:13,469 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Storage pool garbage collector found 0 templates to clean up in storage pool: Primary2 2019-07-23 08:40:13,472 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Secondary storage garbage collector found 0 templates to cleanup on template_store_ref for store: Secondary1 2019-07-23 08:40:13,472 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Secondary storage garbage collector found 0 snapshots to cleanup on snapshot_store_ref for store: Secondary1 2019-07-23 08:40:13,473 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Secondary storage garbage collector found 0 volumes to cleanup on volume_store_ref for store: Secondary1 2019-07-23 08:40:13,477 DEBUG [o.a.c.s.v.VolumeObject] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Failed to update state com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via DestroyRequested at com.cloud.utils.fsm.StateMachine2.getTransition(StateMachine2.java:108) at com.cloud.utils.fsm.StateMachine2.getNextState(StateMachine2.java:94) at com.cloud.utils.fsm.StateMachine2.transitTo(StateMachine2.java:124) at org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.update(ObjectInDataStoreManagerImpl.java:307) at org.apache.cloudstack.storage.volume.VolumeObject.processEventOnly(VolumeObject.java:418) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:354) at com.cloud.storage.StorageManagerImpl.cleanupStorage(StorageManagerImpl.java:1141) at com.cloud.storage.StorageManagerImpl$StorageGarbageCollector.runInContext(StorageManagerImpl.java:1503) 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:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2019-07-23 08:40:13,478 WARN [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Unable to destroy volume 48c9654f-5ea1-439c-b9a5-7001f05ce728 com.cloud.utils.exception.CloudRuntimeException: Failed to update state:com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via DestroyRequested at org.apache.cloudstack.storage.volume.VolumeObject.processEventOnly(VolumeObject.java:421) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:354) at com.cloud.storage.StorageManagerImpl.cleanupStorage(StorageManagerImpl.java:1141) at com.cloud.storage.StorageManagerImpl$StorageGarbageCollector.runInContext(StorageManagerImpl.java:1503) 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:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2019-07-23 08:40:13,485 DEBUG [o.a.c.s.v.VolumeObject] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Failed to update state com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via DestroyRequested at com.cloud.utils.fsm.StateMachine2.getTransition(StateMachine2.java:108) at com.cloud.utils.fsm.StateMachine2.getNextState(StateMachine2.java:94) at com.cloud.utils.fsm.StateMachine2.transitTo(StateMachine2.java:124) at org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.update(ObjectInDataStoreManagerImpl.java:307) at org.apache.cloudstack.storage.volume.VolumeObject.processEventOnly(VolumeObject.java:418) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:354) at com.cloud.storage.StorageManagerImpl.cleanupStorage(StorageManagerImpl.java:1141) at com.cloud.storage.StorageManagerImpl$StorageGarbageCollector.runInContext(StorageManagerImpl.java:1503) 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:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2019-07-23 08:40:13,485 WARN [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-1:ctx-25853e95) (logid:43614fd0) Unable to destroy volume 463e5e3e-e0c6-46ca-8da9-71299a81283f com.cloud.utils.exception.CloudRuntimeException: Failed to update state:com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state from Creating via DestroyRequested at org.apache.cloudstack.storage.volume.VolumeObject.processEventOnly(VolumeObject.java:421) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:354) at com.cloud.storage.StorageManagerImpl.cleanupStorage(StorageManagerImpl.java:1141) at com.cloud.storage.StorageManagerImpl$StorageGarbageCollector.runInContext(StorageManagerImpl.java:1503) 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:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2019-07-23 08:40:13,506 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-99ece2b4) (logid:0afcf3b7) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:13,509 DEBUG [c.c.a.ApiServer] (qtp2114650936-21:ctx-99ece2b4 ctx-908154b0) (logid:0afcf3b7) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:13,517 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-99ece2b4 ctx-908154b0 ctx-019a60fc) (logid:0afcf3b7) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:14,326 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-843debc9) (logid:2146ffc7) Begin cleanup expired async-jobs 2019-07-23 08:40:14,329 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-843debc9) (logid:2146ffc7) End cleanup expired async-jobs 2019-07-23 08:40:14,585 INFO [o.a.c.e.o.NetworkOrchestrator] (Network-Scavenger-1:ctx-8d9de194) (logid:14742f03) NetworkGarbageCollector uses '600' seconds for GC interval. 2019-07-23 08:40:14,766 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:ctx-4b58cf57) (logid:3958b4fb) External devices are not used. Skipping external device usage collection 2019-07-23 08:40:14,775 INFO [c.c.r.ResourceLimitManagerImpl] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Started resource counters recalculation periodic task. 2019-07-23 08:40:14,776 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-20126a2a) (logid:bd587476) Snapshot scheduler.poll is being called at 2019-07-23 06:40:14 GMT 2019-07-23 08:40:14,777 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-20126a2a) (logid:bd587476) Got 0 snapshots to be executed at 2019-07-23 06:40:14 GMT 2019-07-23 08:40:14,778 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:ctx-03cf0aef) (logid:15e74ba6) Found 0 running routers. 2019-07-23 08:40:14,779 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-b0b0b484) (logid:116d69a1) Found 0 routers to update status. 2019-07-23 08:40:14,780 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-b0b0b484) (logid:116d69a1) Found 0 VPC networks to update Redundant State. 2019-07-23 08:40:14,781 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-b0b0b484) (logid:116d69a1) Found 0 networks to update RvR status. 2019-07-23 08:40:14,797 DEBUG [c.c.s.StatsCollector] (StatsCollector-5:ctx-0186f0b0) (logid:8b89fcb7) Skipping collect vm disk stats from hosts 2019-07-23 08:40:14,800 DEBUG [c.c.s.StatsCollector] (StatsCollector-6:ctx-dc720d51) (logid:dad7014e) Skipping collect vm network stats from hosts 2019-07-23 08:40:14,806 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 3 Name = ResourceCountChecker-1; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countCpuNumberAllocatedToAccount:-1-ResourceLimitManagerImpl.countCpusForAccount:932-ResourceLimitManagerImpl.recalculateAccountResourceCount:892-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,808 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:14,811 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 3 Name = tx-1265; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countMemoryAllocatedToAccount:-1-ResourceLimitManagerImpl.calculateMemoryForAccount:936-ResourceLimitManagerImpl.recalculateAccountResourceCount:894-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,813 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:14,853 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 2 Name = tx-1276; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countCpuNumberAllocatedToAccount:-1-ResourceLimitManagerImpl.countCpusForAccount:932-ResourceLimitManagerImpl.recalculateAccountResourceCount:892-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,854 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:14,856 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 2 Name = tx-1277; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countMemoryAllocatedToAccount:-1-ResourceLimitManagerImpl.calculateMemoryForAccount:936-ResourceLimitManagerImpl.recalculateAccountResourceCount:894-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,857 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:14,891 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 2 Name = tx-1288; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countCpuNumberAllocatedToAccount:-1-ResourceLimitManagerImpl.countCpusForAccount:932-ResourceLimitManagerImpl.recalculateAccountResourceCount:892-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,892 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:14,895 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 2 Name = tx-1289; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countMemoryAllocatedToAccount:-1-ResourceLimitManagerImpl.calculateMemoryForAccount:936-ResourceLimitManagerImpl.recalculateAccountResourceCount:894-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,896 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:14,927 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 2 Name = tx-1300; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countCpuNumberAllocatedToAccount:-1-ResourceLimitManagerImpl.countCpusForAccount:932-ResourceLimitManagerImpl.recalculateAccountResourceCount:892-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,928 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:14,931 DEBUG [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) Rolling back the transaction: Time = 2 Name = tx-1301; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy41.countMemoryAllocatedToAccount:-1-ResourceLimitManagerImpl.calculateMemoryForAccount:936-ResourceLimitManagerImpl.recalculateAccountResourceCount:894-ResourceLimitManagerImpl$3.doInTransaction:855 2019-07-23 08:40:14,932 WARN [c.c.u.d.T.Transaction] (ResourceCountChecker-1:ctx-ff1cf2fe) (logid:5b93affa) txn: Commit called when it is not a transaction: -Transaction.execute:41-Transaction.execute:47-ResourceLimitManagerImpl.recalculateDomainResourceCount:829-ResourceLimitManagerImpl$ResourceCountCheckTask.runInContext:1058-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-Executors$RunnableAdapter.call:511-FutureTask.runAndReset:308-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:180 2019-07-23 08:40:15,519 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-63389308) (logid:67f9d41a) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:15,522 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-63389308 ctx-a32a5f26) (logid:67f9d41a) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:15,529 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-63389308 ctx-a32a5f26 ctx-85c0b201) (logid:67f9d41a) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:17,531 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-25ac7025) (logid:47bbc53e) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:17,534 DEBUG [c.c.a.ApiServer] (qtp2114650936-21:ctx-25ac7025 ctx-0b634e9a) (logid:47bbc53e) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:17,542 DEBUG [c.c.a.ApiServlet] (qtp2114650936-21:ctx-25ac7025 ctx-0b634e9a ctx-420b4fb8) (logid:47bbc53e) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:19,546 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-6d4d72bf) (logid:f878cce5) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:19,550 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-6d4d72bf ctx-a1aba294) (logid:f878cce5) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:19,560 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-6d4d72bf ctx-a1aba294 ctx-51cd4a75) (logid:f878cce5) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=queryAsyncJobResult&jobid=9403bb3e-b884-4deb-8db1-4411bd54eb66&response=json&signature=refQmGX9%2Flofzv%2Bvv5OQGuQl4S4%3D 2019-07-23 08:40:19,737 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) Ping from 20(fr-kvm1) 2019-07-23 08:40:19,737 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process host VM state report from ping process. host: 20 2019-07-23 08:40:19,798 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process VM state report. host: 20, number of records in report: 58 2019-07-23 08:40:19,798 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 260, power state: PowerOn 2019-07-23 08:40:19,800 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 260 2019-07-23 08:40:19,800 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 261, power state: PowerOn 2019-07-23 08:40:19,801 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 261 2019-07-23 08:40:19,801 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 262, power state: PowerOn 2019-07-23 08:40:19,802 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 262 2019-07-23 08:40:19,802 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 266, power state: PowerOn 2019-07-23 08:40:19,803 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 266 2019-07-23 08:40:19,803 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 267, power state: PowerOn 2019-07-23 08:40:19,804 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 267 2019-07-23 08:40:19,804 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 139, power state: PowerOn 2019-07-23 08:40:19,805 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 139 2019-07-23 08:40:19,805 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 268, power state: PowerOn 2019-07-23 08:40:19,807 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 268 2019-07-23 08:40:19,807 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 269, power state: PowerOn 2019-07-23 08:40:19,808 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 269 2019-07-23 08:40:19,808 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 141, power state: PowerOn 2019-07-23 08:40:19,809 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 141 2019-07-23 08:40:19,809 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 271, power state: PowerOn 2019-07-23 08:40:19,810 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 271 2019-07-23 08:40:19,810 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 272, power state: PowerOn 2019-07-23 08:40:19,811 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 272 2019-07-23 08:40:19,811 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 273, power state: PowerOn 2019-07-23 08:40:19,812 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 273 2019-07-23 08:40:19,813 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 274, power state: PowerOn 2019-07-23 08:40:19,814 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 274 2019-07-23 08:40:19,814 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 275, power state: PowerOn 2019-07-23 08:40:19,815 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 275 2019-07-23 08:40:19,815 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 276, power state: PowerOn 2019-07-23 08:40:19,816 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 276 2019-07-23 08:40:19,816 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 277, power state: PowerOn 2019-07-23 08:40:19,817 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 277 2019-07-23 08:40:19,817 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 21, power state: PowerOn 2019-07-23 08:40:19,819 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 21 2019-07-23 08:40:19,819 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 22, power state: PowerOn 2019-07-23 08:40:19,820 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 22 2019-07-23 08:40:19,820 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 278, power state: PowerOn 2019-07-23 08:40:19,821 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 278 2019-07-23 08:40:19,821 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 279, power state: PowerOn 2019-07-23 08:40:19,822 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 279 2019-07-23 08:40:19,822 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 280, power state: PowerOn 2019-07-23 08:40:19,823 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 280 2019-07-23 08:40:19,823 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 281, power state: PowerOn 2019-07-23 08:40:19,825 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 281 2019-07-23 08:40:19,825 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 282, power state: PowerOn 2019-07-23 08:40:19,826 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 282 2019-07-23 08:40:19,826 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 157, power state: PowerOn 2019-07-23 08:40:19,827 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 157 2019-07-23 08:40:19,827 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 161, power state: PowerOn 2019-07-23 08:40:19,828 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 161 2019-07-23 08:40:19,828 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 36, power state: PowerOn 2019-07-23 08:40:19,829 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 36 2019-07-23 08:40:19,829 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 39, power state: PowerOn 2019-07-23 08:40:19,830 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 39 2019-07-23 08:40:19,831 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 40, power state: PowerOn 2019-07-23 08:40:19,832 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 40 2019-07-23 08:40:19,832 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 297, power state: PowerOn 2019-07-23 08:40:19,833 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 297 2019-07-23 08:40:19,833 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 44, power state: PowerOn 2019-07-23 08:40:19,834 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 44 2019-07-23 08:40:19,834 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 301, power state: PowerOn 2019-07-23 08:40:19,835 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 301 2019-07-23 08:40:19,835 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 302, power state: PowerOn 2019-07-23 08:40:19,836 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 302 2019-07-23 08:40:19,836 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 303, power state: PowerOn 2019-07-23 08:40:19,837 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 303 2019-07-23 08:40:19,837 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 304, power state: PowerOn 2019-07-23 08:40:19,838 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 304 2019-07-23 08:40:19,839 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 305, power state: PowerOn 2019-07-23 08:40:19,840 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 305 2019-07-23 08:40:19,840 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 178, power state: PowerOn 2019-07-23 08:40:19,841 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 178 2019-07-23 08:40:19,841 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 306, power state: PowerOn 2019-07-23 08:40:19,842 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 306 2019-07-23 08:40:19,842 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 307, power state: PowerOn 2019-07-23 08:40:19,843 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 307 2019-07-23 08:40:19,843 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 309, power state: PowerOn 2019-07-23 08:40:19,844 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 309 2019-07-23 08:40:19,844 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 316, power state: PowerOn 2019-07-23 08:40:19,845 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 316 2019-07-23 08:40:19,845 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 329, power state: PowerOn 2019-07-23 08:40:19,847 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 329 2019-07-23 08:40:19,847 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 330, power state: PowerOn 2019-07-23 08:40:19,848 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 330 2019-07-23 08:40:19,848 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 203, power state: PowerOn 2019-07-23 08:40:19,849 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 203 2019-07-23 08:40:19,849 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 331, power state: PowerOn 2019-07-23 08:40:19,850 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 331 2019-07-23 08:40:19,850 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 332, power state: PowerOn 2019-07-23 08:40:19,852 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 332 2019-07-23 08:40:19,852 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 334, power state: PowerOn 2019-07-23 08:40:19,853 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 334 2019-07-23 08:40:19,853 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 94, power state: PowerOn 2019-07-23 08:40:19,854 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 94 2019-07-23 08:40:19,854 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 231, power state: PowerOn 2019-07-23 08:40:19,855 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 231 2019-07-23 08:40:19,855 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 103, power state: PowerOn 2019-07-23 08:40:19,856 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 103 2019-07-23 08:40:19,856 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 104, power state: PowerOn 2019-07-23 08:40:19,857 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 104 2019-07-23 08:40:19,857 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 106, power state: PowerOn 2019-07-23 08:40:19,858 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 106 2019-07-23 08:40:19,858 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 108, power state: PowerOn 2019-07-23 08:40:19,859 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 108 2019-07-23 08:40:19,859 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 109, power state: PowerOn 2019-07-23 08:40:19,868 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 109 2019-07-23 08:40:19,868 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 114, power state: PowerOn 2019-07-23 08:40:19,869 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 114 2019-07-23 08:40:19,869 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 115, power state: PowerOn 2019-07-23 08:40:19,871 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 115 2019-07-23 08:40:19,871 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 116, power state: PowerOn 2019-07-23 08:40:19,872 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 116 2019-07-23 08:40:19,872 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 121, power state: PowerOn 2019-07-23 08:40:19,873 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 121 2019-07-23 08:40:19,873 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM state report. host: 20, vm id: 254, power state: PowerOn 2019-07-23 08:40:19,874 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) VM power state does not change, skip DB writing. vm id: 254 2019-07-23 08:40:19,892 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Done with process of VM state report. host: 20 2019-07-23 08:40:20,196 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-f8a0693b) (logid:65156f0e) ===START=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=listVirtualMachines&id=06c72a1a-177d-4331-a38a-17e741688371&response=json&signature=IeUf3Ktv36LcbsbfA6%2FdoAkgALI%3D 2019-07-23 08:40:20,199 DEBUG [c.c.a.ApiServer] (qtp2114650936-20:ctx-f8a0693b ctx-b1d5af72) (logid:65156f0e) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:40:20,211 DEBUG [c.c.a.ApiServlet] (qtp2114650936-20:ctx-f8a0693b ctx-b1d5af72 ctx-2909ca1c) (logid:65156f0e) ===END=== 137.74.35.117 -- GET apikey=Rw-9vSgzHTTbXHcPCcb5pKvRep_WDUoNipIxMKtrK5ozsnql0RztEFjIAaf_ETdHFAeZijTth2WKw8eSeHoQ0g&command=listVirtualMachines&id=06c72a1a-177d-4331-a38a-17e741688371&response=json&signature=IeUf3Ktv36LcbsbfA6%2FdoAkgALI%3D 2019-07-23 08:40:20,226 WARN [c.c.s.ConsoleProxyServlet] (qtp2114650936-15:null) (logid:) VM 264 lost host info, sending blank response for console access request ^C [root@fr-kvm1 management]# echo "" > management-server.log [root@fr-kvm1 management]# echo "" > management-server.log [root@fr-kvm1 management]# echo "" > management-server.log [root@fr-kvm1 management]# [root@fr-kvm1 management]# echo "" > management-server.log [root@fr-kvm1 management]# cat management-server.log 2019-07-23 08:46:54,020 DEBUG [c.c.a.ApiServlet] (qtp2114650936-18:ctx-ef3300e5) (logid:97f536ae) ===START=== 137.74.35.102 -- GET command=destroyVirtualMachine&response=json&id=d29cc5c3-561f-421b-aa7c-bf2fd45efb23&expunge=true&volumeids=&_=1563864165796 2019-07-23 08:46:54,023 DEBUG [c.c.a.ApiServer] (qtp2114650936-18:ctx-ef3300e5 ctx-9c7ce7aa) (logid:97f536ae) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:46:54,034 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:f8a3f7b5) Add job-20133 into job monitoring 2019-07-23 08:46:54,036 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp2114650936-18:ctx-ef3300e5 ctx-9c7ce7aa) (logid:97f536ae) submit async job-20133, details: AsyncJobVO {id:20133, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 270, cmd: org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","expunge":"true","httpmethod":"GET","ctxStartEventId":"9323","id":"d29cc5c3-561f-421b-aa7c-bf2fd45efb23","volumeids":"","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"d29cc5c3-561f-421b-aa7c-bf2fd45efb23\"}","ctxAccountId":"2","uuid":"d29cc5c3-561f-421b-aa7c-bf2fd45efb23","cmdEventType":"VM.DESTROY","_":"1563864165796"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 279278805450987, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2019-07-23 08:46:54,036 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Executing AsyncJobVO {id:20133, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 270, cmd: org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","expunge":"true","httpmethod":"GET","ctxStartEventId":"9323","id":"d29cc5c3-561f-421b-aa7c-bf2fd45efb23","volumeids":"","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"d29cc5c3-561f-421b-aa7c-bf2fd45efb23\"}","ctxAccountId":"2","uuid":"d29cc5c3-561f-421b-aa7c-bf2fd45efb23","cmdEventType":"VM.DESTROY","_":"1563864165796"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 279278805450987, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null} 2019-07-23 08:46:54,038 DEBUG [c.c.a.ApiServlet] (qtp2114650936-18:ctx-ef3300e5 ctx-9c7ce7aa) (logid:97f536ae) ===END=== 137.74.35.102 -- GET command=destroyVirtualMachine&response=json&id=d29cc5c3-561f-421b-aa7c-bf2fd45efb23&expunge=true&volumeids=&_=1563864165796 2019-07-23 08:46:54,048 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Checking if there are any ongoing snapshots on the ROOT volumes associated with VM with ID 270 2019-07-23 08:46:54,049 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Found 1 no. of volumes of type ROOT for vm with VM ID 270 2019-07-23 08:46:54,049 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Checking status of snapshots for Volume with Volume Id: 314 2019-07-23 08:46:54,049 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) The count of ongoing Snapshots for VM with ID 270 and disk type ROOT is 0 2019-07-23 08:46:54,050 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Found no ongoing snapshots on volume of type ROOT, for the vm with id 270 2019-07-23 08:46:54,054 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Sync job-20134 execution on object VmWorkJobQueue.270 2019-07-23 08:46:54,326 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-5e9c8e1c) (logid:7b3c2e7a) Execute sync-queue item: SyncQueueItemVO {id:4, queueId: 16930, contentType: AsyncJob, contentId: 20134, lastProcessMsid: 279278805450987, lastprocessNumber: 22, lastProcessTime: Tue Jul 23 08:46:54 CEST 2019, created: Tue Jul 23 08:46:54 CEST 2019} 2019-07-23 08:46:54,327 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-5e9c8e1c) (logid:7b3c2e7a) Schedule queued job-20134 2019-07-23 08:46:54,329 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134) (logid:bc130f63) Add job-20134 into job monitoring 2019-07-23 08:46:54,330 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f3a12bb6) (logid:551ca8c4) Begin cleanup expired async-jobs 2019-07-23 08:46:54,332 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134) (logid:1fa50f59) Executing AsyncJobVO {id:20134, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAABDnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 279278805450987, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Jul 23 08:46:54 CEST 2019, removed: null} 2019-07-23 08:46:54,333 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f3a12bb6) (logid:551ca8c4) End cleanup expired async-jobs 2019-07-23 08:46:54,333 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134) (logid:1fa50f59) Run VM work job: com.cloud.vm.VmWorkStop for VM 270, job origin: 20133 2019-07-23 08:46:54,335 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":270,"handlerName":"VirtualMachineManagerImpl"} 2019-07-23 08:46:54,337 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) VM is already stopped: VM[User|i-56-270-VM] 2019-07-23 08:46:54,337 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) Done executing VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":270,"handlerName":"VirtualMachineManagerImpl"} 2019-07-23 08:46:54,337 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) Complete async job-20134, jobStatus: SUCCEEDED, resultCode: 0, result: null 2019-07-23 08:46:54,338 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) Publish async job-20134 complete on message bus 2019-07-23 08:46:54,338 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) Wake up jobs related to job-20134 2019-07-23 08:46:54,338 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) Update db status for job-20134 2019-07-23 08:46:54,338 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134 ctx-5f81a85c) (logid:1fa50f59) Wake up jobs joined with job-20134 and disjoin all subjobs created from job- 20134 2019-07-23 08:46:54,343 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134) (logid:1fa50f59) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 270, job origin: 20133 2019-07-23 08:46:54,343 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134) (logid:1fa50f59) Done executing com.cloud.vm.VmWorkStop for job-20134 2019-07-23 08:46:54,343 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-2:ctx-a90b189c job-20133/job-20134) (logid:1fa50f59) Remove job-20134 from job monitoring 2019-07-23 08:46:54,352 DEBUG [c.c.v.VirtualMachineManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Destroying vm VM[User|i-56-270-VM], expunge flag on 2019-07-23 08:46:54,358 DEBUG [c.c.u.d.T.Transaction] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Rolling back the transaction: Time = 2 Name = API-Job-Executor-8; called by -TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-Transaction.execute:43-Transaction.execute:47-AsyncJobManagerImpl.submitAsyncJob:231-VirtualMachineManagerImpl.stopVmThroughJobQueue:4666-VirtualMachineManagerImpl.advanceStop:1599-VirtualMachineManagerImpl.destroy:1864-VMEntityManagerImpl.destroyVirtualMachine:271-VirtualMachineEntityImpl.destroy:233-UserVmManagerImpl.destroyVm:4580 2019-07-23 08:46:54,359 WARN [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133 ctx-dff5e9e7) (logid:1fa50f59) Unable to schedule async job for command com.cloud.vm.VmWorkStop, unexpected exception. javax.persistence.EntityExistsException: Entity already exists: at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1448) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$1.doInTransaction(AsyncJobManagerImpl.java:235) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$1.doInTransaction(AsyncJobManagerImpl.java:231) at com.cloud.utils.db.Transaction$2.doInTransaction(Transaction.java:50) at com.cloud.utils.db.Transaction.execute(Transaction.java:40) at com.cloud.utils.db.Transaction.execute(Transaction.java:47) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:231) at com.cloud.vm.VirtualMachineManagerImpl.stopVmThroughJobQueue(VirtualMachineManagerImpl.java:4666) at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1599) at com.cloud.vm.VirtualMachineManagerImpl.destroy(VirtualMachineManagerImpl.java:1864) at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.destroyVirtualMachine(VMEntityManagerImpl.java:271) at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.destroy(VirtualMachineEntityImpl.java:233) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:4580) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:2787) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) at com.sun.proxy.$Proxy165.destroyVm(Unknown Source) at org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin.execute(DestroyVMCmdByAdmin.java:46) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583) 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:531) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '20135' for key 'PRIMARY' at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ... 59 more 2019-07-23 08:46:54,364 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin com.cloud.utils.exception.CloudRuntimeException: Unable to schedule async job for command com.cloud.vm.VmWorkStop, unexpected exception. at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:247) at com.cloud.vm.VirtualMachineManagerImpl.stopVmThroughJobQueue(VirtualMachineManagerImpl.java:4666) at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1599) at com.cloud.vm.VirtualMachineManagerImpl.destroy(VirtualMachineManagerImpl.java:1864) at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.destroyVirtualMachine(VMEntityManagerImpl.java:271) at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.destroy(VirtualMachineEntityImpl.java:233) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:4580) at com.cloud.vm.UserVmManagerImpl.destroyVm(UserVmManagerImpl.java:2787) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) at com.sun.proxy.$Proxy165.destroyVm(Unknown Source) at org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin.execute(DestroyVMCmdByAdmin.java:46) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156) at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583) 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:531) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2019-07-23 08:46:54,365 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Complete async job-20133, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to schedule async job for command com.cloud.vm.VmWorkStop, unexpected exception."} 2019-07-23 08:46:54,365 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Publish async job-20133 complete on message bus 2019-07-23 08:46:54,365 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Wake up jobs related to job-20133 2019-07-23 08:46:54,366 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Update db status for job-20133 2019-07-23 08:46:54,366 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Wake up jobs joined with job-20133 and disjoin all subjobs created from job- 20133 2019-07-23 08:46:54,369 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Done executing org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin for job-20133 2019-07-23 08:46:54,369 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-8:ctx-26df9ded job-20133) (logid:1fa50f59) Remove job-20133 from job monitoring 2019-07-23 08:46:57,151 DEBUG [c.c.a.ApiServlet] (qtp2114650936-19:ctx-fabf770f) (logid:f048f4e3) ===START=== 137.74.35.102 -- GET command=queryAsyncJobResult&jobId=1fa50f59-9406-4519-ab71-a57de72b41f2&response=json&_=1563864165797 2019-07-23 08:46:57,154 DEBUG [c.c.a.ApiServer] (qtp2114650936-19:ctx-fabf770f ctx-f99ae360) (logid:f048f4e3) CIDRs from which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed to perform API calls: 0.0.0.0/0,::/0 2019-07-23 08:46:57,163 DEBUG [c.c.a.ApiServlet] (qtp2114650936-19:ctx-fabf770f ctx-f99ae360) (logid:f048f4e3) ===END=== 137.74.35.102 -- GET command=queryAsyncJobResult&jobId=1fa50f59-9406-4519-ab71-a57de72b41f2&response=json&_=1563864165797 2019-07-23 08:47:04,326 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-ed323f1b) (logid:ad5ba1f5) Begin cleanup expired async-jobs 2019-07-23 08:47:04,329 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-ed323f1b) (logid:ad5ba1f5) End cleanup expired async-jobs 2019-07-23 08:47:05,338 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-1809c52a) (logid:74bd0313) Zone 1 is ready to launch secondary storage VM 2019-07-23 08:47:05,415 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-8df0a7f2) (logid:569fd12f) Zone 1 is ready to launch console proxy [root@fr-kvm1 management]#