codehaus


[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: URGENT: Unable to schedule async job for command com.cloud.vm.VmWorkStart, unexpected exception


Hi René ,
the cloustack installation is 4.11.1.0. From the issue you reported to me I do not understand if the problem has been solved or not..

The big problem is that I can not perform any new jobs.

In addition to the stopped VM there are two routes that were running on the host that has crashed.

One of these routers was redundant as a master of one of the isolated networks along with another that has taken its place and is now working.





Il 13/12/18 11:07, Rene Moser ha scritto:
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?






--

*Ugo Vasi* / System Administrator
ugo.vasi@xxxxxxxxx <mailto:ugo.vasi@xxxxxxxxx>




*Procne S.r.l.*
+39 0432 486 523
via Cotonificio, 45
33010 Tavagnacco (UD)
www.procne.it <http://www.procne.it/>


Le informazioni contenute nella presente comunicazione ed i relativi allegati possono essere riservate e sono, comunque, destinate esclusivamente alle persone od alla Società sopraindicati. La diffusione, distribuzione e/o copiatura del documento trasmesso da parte di qualsiasi soggetto diverso dal destinatario è proibita sia ai sensi dell'art. 616 c.p., che ai sensi del Decreto Legislativo n. 196/2003 "Codice in materia di protezione dei dati personali". Se avete ricevuto questo messaggio per errore, vi preghiamo di distruggerlo e di informare immediatamente Procne S.r.l. scrivendo all' indirizzo e-mail info@xxxxxxxxx <mailto:info@xxxxxxxxx>.