Hi
I think you hit https://github.com/apache/cloudstack/issues/2880
Is this already 4.11.2?
We have also seen this in our lab, could not really reproduce it, seems
to be a race condition.
Regards
René
On 12/13/18 9:01 AM, Ugo Vasi wrote:
> Hi all,
> I'm trying to reboot a vm after the host it ran on crashed and restarted
> from the HA system. All the VMs running on the rebooted host were
> restarted on other hosts except one.
> In the web interface and using cloudmonkey I get this message:
> "Unable to schedule async job for command com.cloud.vm.VmWorkStart,
> unexpected exception."
>
> In the management-server.log file there would seem to be a problem when
> creating an element that is duplicated (Duplicate entry 'xxxx' for key
> 'PRIMARY'):
>
> 2018-12-13 08:44:06,659 DEBUG [c.c.a.ApiServlet]
> (qtp1096283470-445:ctx-6c065e06) (logid:87edf8d7) ===START=== 10.80.0.6
> -- GET
> command=startVirtualMachine&response=json&id=dde566b2-ef2c-4f86-a82b-c8286f0c24f7&_=1544687047015
>
> 2018-12-13 08:44:06,665 DEBUG [c.c.a.ApiServer]
> (qtp1096283470-445:ctx-6c065e06 ctx-c8b27e4a) (logid:87edf8d7) CIDRs
> from which account 'Acct[26e597f2-b5ca-11e8-a619-c8cbb8cb15cd-admin]' is
> allowed to perform API calls: 0.0.0.0/0,::/0
> 2018-12-13 08:44:06,693 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:7e0c4dc9) Add job-1343
> into job monitoring
> 2018-12-13 08:44:06,698 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (qtp1096283470-445:ctx-6c065e06 ctx-c8b27e4a) (logid:87edf8d7) submit
> async job-1343, details: AsyncJobVO {id:1343, userId: 2, accountId: 2,
> instanceType: VirtualMachine, instanceId: 8, cmd:
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo:
> {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"6170","id":"dde566b2-ef2c-4f86-a82b-c8286f0c24f7","ctxDetails":"{\"interface
> com.cloud.vm.VirtualMachine\":\"dde566b2-ef2c-4f86-a82b-c8286f0c24f7\"}","ctxAccountId":"2","uuid":"dde566b2-ef2c-4f86-a82b-c8286f0c24f7","cmdEventType":"VM.START","_":"1544687047015"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
> result: null, initMsid: 220777304233416, completeMsid: null,
> lastUpdated: null, lastPolled: null, created: null}
> 2018-12-13 08:44:06,700 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Executing
> AsyncJobVO {id:1343, userId: 2, accountId: 2, instanceType:
> VirtualMachine, instanceId: 8, cmd:
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo:
> {"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"6170","id":"dde566b2-ef2c-4f86-a82b-c8286f0c24f7","ctxDetails":"{\"interface
> com.cloud.vm.VirtualMachine\":\"dde566b2-ef2c-4f86-a82b-c8286f0c24f7\"}","ctxAccountId":"2","uuid":"dde566b2-ef2c-4f86-a82b-c8286f0c24f7","cmdEventType":"VM.START","_":"1544687047015"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
> result: null, initMsid: 220777304233416, completeMsid: null,
> lastUpdated: null, lastPolled: null, created: null}
> 2018-12-13 08:44:06,705 DEBUG [c.c.a.ApiServlet]
> (qtp1096283470-445:ctx-6c065e06 ctx-c8b27e4a) (logid:87edf8d7)
> ===END=== 10.80.0.6 -- GET
> command=startVirtualMachine&response=json&id=dde566b2-ef2c-4f86-a82b-c8286f0c24f7&_=1544687047015
>
> 2018-12-13 08:44:06,745 DEBUG [c.c.n.NetworkModelImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Service SecurityGroup is not supported in the network id=205
> 2018-12-13 08:44:06,752 DEBUG [c.c.n.NetworkModelImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Service SecurityGroup is not supported in the network id=205
> 2018-12-13 08:44:06,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> DeploymentPlanner allocation algorithm: null
> 2018-12-13 08:44:06,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Trying to allocate a host and storage pools from dc:1,
> pod:null,cluster:null, requested cpu: 8000, requested ram: 8594128896
> 2018-12-13 08:44:06,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Is ROOT volume READY (pool already allocated)?: Yes
> 2018-12-13 08:44:06,783 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Deploy avoids pods: [], clusters: [], hosts: []
> 2018-12-13 08:44:06,784 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> This VM has last host_id specified, trying to choose the same host: 10
> 2018-12-13 08:44:06,794 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Host: 10 has cpu capability (cpu:12, speed:3000) to support requested
> CPU: 4 and requested speed: 2000
> 2018-12-13 08:44:06,794 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking if host: 10 has enough capacity for requested CPU: 8000 and
> requested RAM: 8594128896 , cpuOverprovisioningFactor: 1.0
> 2018-12-13 08:44:06,797 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Hosts's actual total CPU: 36000 and CPU after applying overprovisioning:
> 36000
> 2018-12-13 08:44:06,797 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> We need to allocate to the last host again, so checking if there is
> enough reserved capacity
> 2018-12-13 08:44:06,797 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Reserved CPU: 8000 , Requested CPU: 8000
> 2018-12-13 08:44:06,797 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Reserved RAM: 8594128896 , Requested RAM: 8594128896
> 2018-12-13 08:44:06,797 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Host has enough CPU and RAM available
> 2018-12-13 08:44:06,797 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> STATS: Can alloc CPU from host: 10, used: 4500, reserved: 8000, actual
> total: 36000, total with overprovisioning: 36000; requested
> cpu:8000,alloc_from_last_host?:true ,considerReservedCapacity?: true
> 2018-12-13 08:44:06,797 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> STATS: Can alloc MEM from host: 10, used: 2415919104, reserved:
> 8594128896, total: 49554284544; requested mem:
> 8594128896,alloc_from_last_host?:true ,considerReservedCapacity?: true
> 2018-12-13 08:44:06,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> The last host of this VM is UP and has enough capacity
> 2018-12-13 08:44:06,797 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Now checking for suitable pools under zone: 1, pod: 1, cluster: 1
> 2018-12-13 08:44:06,803 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking suitable pools for volume (Id, Type): (8,ROOT)
> 2018-12-13 08:44:06,803 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Volume has pool already allocated, checking if pool can be reused,
> poolId: 1
> 2018-12-13 08:44:06,808 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Planner need not allocate a pool for this volume since its READY
> 2018-12-13 08:44:06,808 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking suitable pools for volume (Id, Type): (12,DATADISK)
> 2018-12-13 08:44:06,808 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Volume has pool already allocated, checking if pool can be reused,
> poolId: 1
> 2018-12-13 08:44:06,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Planner need not allocate a pool for this volume since its READY
> 2018-12-13 08:44:06,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking suitable pools for volume (Id, Type): (17,DATADISK)
> 2018-12-13 08:44:06,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Volume has pool already allocated, checking if pool can be reused,
> poolId: 1
> 2018-12-13 08:44:06,819 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Planner need not allocate a pool for this volume since its READY
> 2018-12-13 08:44:06,820 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking suitable pools for volume (Id, Type): (58,DATADISK)
> 2018-12-13 08:44:06,820 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Volume has pool already allocated, checking if pool can be reused,
> poolId: 1
> 2018-12-13 08:44:06,825 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Planner need not allocate a pool for this volume since its READY
> 2018-12-13 08:44:06,825 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Trying to find a potenial host and associated storage pools from the
> suitable host/pool lists for this VM
> 2018-12-13 08:44:06,825 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking if host: 10 can access any suitable storage pool for volume:
> DATADISK
> 2018-12-13 08:44:06,827 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Host: 10 can access pool: 1
> 2018-12-13 08:44:06,827 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking if host: 10 can access any suitable storage pool for volume:
> DATADISK
> 2018-12-13 08:44:06,829 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Host: 10 can access pool: 1
> 2018-12-13 08:44:06,829 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking if host: 10 can access any suitable storage pool for volume:
> DATADISK
> 2018-12-13 08:44:06,830 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Host: 10 can access pool: 1
> 2018-12-13 08:44:06,830 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Checking if host: 10 can access any suitable storage pool for volume: ROOT
> 2018-12-13 08:44:06,831 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Host: 10 can access pool: 1
> 2018-12-13 08:44:06,833 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Found a potential host id: 10 name: cshp143 and associated storage pools
> for this VM
> 2018-12-13 08:44:06,833 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(10)-Storage()]
> 2018-12-13 08:44:06,856 DEBUG [c.c.u.d.T.Transaction]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Rolling back the transaction: Time = 3 Name = API-Job-Executor-8; called
> by
> -TransactionLegacy.rollback:889-TransactionLegacy.removeUpTo:832-TransactionLegacy.close:656-Transaction.execute:43-Transaction.execute:47-AsyncJobManagerImpl.submitAsyncJob:231-VirtualMachineManagerImpl.startVmThroughJobQueue:4457-VirtualMachineManagerImpl.advanceStart:899-VirtualMachineManagerImpl.start:718-VMEntityManagerImpl.deployVirtualMachine:233-VirtualMachineEntityImpl.deploy:212-UserVmManagerImpl.startVirtualMachine:4495
>
> 2018-12-13 08:44:06,861 WARN [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Unable to schedule async job for command com.cloud.vm.VmWorkStart,
> unexpected exception.
> javax.persistence.EntityExistsException: Entity already exists:
> at
> com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1434)
> 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.startVmThroughJobQueue(VirtualMachineManagerImpl.java:4457)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:899)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:718)
>
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:233)
>
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212)
>
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4495)
>
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2689)
>
> 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.$Proxy164.startVirtualMachine(Unknown Source)
> at
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin.execute(StartVMCmdByAdmin.java:51)
>
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150)
> at
> com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
>
> 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:529)
>
> 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 '1344' for key 'PRIMARY'
> at
> sun.reflect.GeneratedConstructorAccessor130.newInstance(Unknown Source)
> at
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
>
> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> ... 59 more
> 2018-12-13 08:44:06,876 DEBUG [c.c.u.d.T.Transaction]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Rolling back the transaction: Time = 2 Name = API-Job-Executor-8; called
> by
> -TransactionLegacy.rollback:889-TransactionLegacy.removeUpTo:832-TransactionLegacy.close:656-Transaction.execute:43-Transaction.execute:47-AsyncJobManagerImpl.submitAsyncJob:231-VirtualMachineManagerImpl.startVmThroughJobQueue:4457-VirtualMachineManagerImpl.advanceStart:899-VirtualMachineManagerImpl.start:718-VMEntityManagerImpl.deployVirtualMachine:245-VirtualMachineEntityImpl.deploy:212-UserVmManagerImpl.startVirtualMachine:4495
>
> 2018-12-13 08:44:06,880 WARN [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343 ctx-eb44a3e5) (logid:6e9a71c5)
> Unable to schedule async job for command com.cloud.vm.VmWorkStart,
> unexpected exception.
> javax.persistence.EntityExistsException: Entity already exists:
> at
> com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1434)
> 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.startVmThroughJobQueue(VirtualMachineManagerImpl.java:4457)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:899)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:718)
>
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:245)
>
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212)
>
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4495)
>
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2689)
>
> 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.$Proxy164.startVirtualMachine(Unknown Source)
> at
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin.execute(StartVMCmdByAdmin.java:51)
>
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150)
> at
> com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
>
> 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:529)
>
> 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 '1345' for key 'PRIMARY'
> at
> sun.reflect.GeneratedConstructorAccessor130.newInstance(Unknown Source)
> at
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
>
> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> ... 59 more
> 2018-12-13 08:44:06,889 ERROR [c.c.a.ApiAsyncJobDispatcher]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Unexpected
> exception while executing
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin
> com.cloud.utils.exception.CloudRuntimeException: Unable to schedule
> async job for command com.cloud.vm.VmWorkStart, unexpected exception.
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:247)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.startVmThroughJobQueue(VirtualMachineManagerImpl.java:4457)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:899)
>
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:718)
>
> at
> org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:245)
>
> at
> org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212)
>
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4495)
>
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2689)
>
> 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.$Proxy164.startVirtualMachine(Unknown Source)
> at
> org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin.execute(StartVMCmdByAdmin.java:51)
>
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150)
> at
> com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)
>
> 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:529)
>
> 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)
> 2018-12-13 08:44:06,891 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Complete
> async job-1343, 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.VmWorkStart, unexpected
> exception."}
> 2018-12-13 08:44:06,893 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Publish
> async job-1343 complete on message bus
> 2018-12-13 08:44:06,893 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Wake up jobs
> related to job-1343
> 2018-12-13 08:44:06,893 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Update db
> status for job-1343
> 2018-12-13 08:44:06,895 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Wake up jobs
> joined with job-1343 and disjoin all subjobs created from job- 1343
> 2018-12-13 08:44:06,899 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Done
> executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin
> for job-1343
> 2018-12-13 08:44:06,899 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (API-Job-Executor-8:ctx-b5905c86 job-1343) (logid:6e9a71c5) Remove
> job-1343 from job monitoring
> 2018-12-13 08:44:07,056 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-31fc417b) (logid:36cfc76d) Begin cleanup
> expired async-jobs
> 2018-12-13 08:44:07,062 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-31fc417b) (logid:36cfc76d) End cleanup
> expired async-jobs
>
> This problem has already appeared to me other times (in other
> circumstances) and I have reported it but I have not found a solution.
>
> Can you help me identify the problem?
>
