osdir.com


[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


Done it once (8h old DB)...make sure to kill any new VMs that were created
in that period of time (and volumes/templates on the end storage).

You might run into situation that some VMs are i.e. powered on during that
last 8h, so DB state for that VM will not be in sync with reality, but that
should be synced shorty after.

I.e. hope that a very few changes/creations of any resources have happened
during that period - and expect some stuff will need to be manually
synced/fixed/repeated - i.e. user created PF rule on VR, but now you have
restored DB so - that might be a challenge to fix without pissing off users
:)

Fingers crossed!

On Thu, Dec 13, 2018, 14:33 Ugo Vasi <ugo.vasi@xxxxxxxxx.invalid wrote:

> Hi all,
> is there anyone who tried to restore the database a day ago and
> restarted cloudstack manager?
>
> The two situations differ for the status of the VM / VR and I do not
> know what to expect and bearing in mind that the problem could recur.
>
> The statistics don't interest me.
>
>
> Il 13/12/18 10:39, Ugo Vasi ha scritto:
> > We have verified that the problem is not tied to a vm but it also
> > concerns the other VMs that are stopped. Trying to restart them gives
> > the same error message.
> >
> > Restoring the previous day's database which problems might imply?
> >
> >
> > Il 13/12/18 09:01, Ugo Vasi ha scritto:
> >> 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>.
>
>