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.v...@procne.it <mailto:ugo.v...@procne.it>
*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
i...@procne.it <mailto:i...@procne.it>.
