You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Ugo Vasi <ug...@procne.it.INVALID> on 2019/02/22 09:04:28 UTC
Re: URGENT: Unable to schedule async job for command
com.cloud.vm.VmWorkStart, unexpected exception
Hi Andrija, hi all,
this morning I stumbled on the same problem some time ago... after that
catastrophic experience I reinstalled the infrastructure that was
unusable. The current new infrastructure is updated to version 4.11.2.0,
again on Ubuntu 16.04, KVM as hypervisor and Advanced network.
I tried restarting a network and I got an error "Unable to schedule
async job for command com.cloud.vm.VmWorkStart, unexpected exception.".
From what I see in the logs (of which I will report below an excerpt)
The procedure created the new router but at the time of starting it,
something went wrong and the process was canceled.
The exception refers to a "Duplicate entry '1083' for key 'PRIMARY'", so
I analyzed the database dump and I found a record in the "vm_work_job"
table with the primary key id=1083:
INSERT INTO `vm_work_job` VALUES ...
(1081,'Prepare','Instance',45),(1083,'Starting','Instance',45),(1085,'Prepare','Instance',45),(1087,'Starting','Instance',45),(1089,'Starting','Instance',45),(1092,'Starting','Instance',27);
On mysql error log I don't find any error message.
From management-server.log:
2019-02-22 08:26:46,678 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp1096283470-458:ctx-b9d2a3ee ctx-cf002500) (logid:b267e0bd) submit
async job-1082, details: AsyncJobVO {id:1082, userId: 2, accountId: 2,
instanceType: None, instanceId: null, cmd:
org.apache.cloudstack.api.command.user.network.RestartNetworkCmd,
cmdInfo:
{"makeredundant":"false","cleanup":"true","response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"2891","id":"bc0cc3a2-e21f-4904-a826-04477b1805c0","ctxDetails":"{\"interface
com.cloud.network.Network\":\"bc0cc3a2-e21f-4904-a826-04477b1805c0\"}","ctxAccountId":"2","uuid":"bc0cc3a2-e21f-4904-a826-04477b1805c0","cmdEventType":"NETWORK.RESTART","_":"1550820391247"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 220777304233416, completeMsid: null,
lastUpdated: null, lastPolled: null, created: null}
2019-02-22 08:26:46,721 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:ddff8687) Add job-1082
into job monitoring
2019-02-22 08:26:46,727 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Executing
AsyncJobVO {id:1082, userId: 2, accountId: 2, instanceType: None,
instanceId: null, cmd:
org.apache.cloudstack.api.command.user.network.RestartNetworkCmd,
cmdInfo:
{"makeredundant":"false","cleanup":"true","response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"2891","id":"bc0cc3a2-e21f-4904-a826-04477b1805c0","ctxDetails":"{\"interface
com.cloud.network.Network\":\"bc0cc3a2-e21f-4904-a826-04477b1805c0\"}","ctxAccountId":"2","uuid":"bc0cc3a2-e21f-4904-a826-04477b1805c0","cmdEventType":"NETWORK.RESTART","_":"1550820391247"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 220777304233416, completeMsid: null,
lastUpdated: null, lastPolled: null, created: null}
2019-02-22 08:26:46,793 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Restarting network 206...
2019-02-22 08:26:46,811 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Performing rolling restart of routers of network Ntwk[206|Guest|8]
2019-02-22 08:26:46,950 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Asking VirtualRouter to implemenet Ntwk[206|Guest|8]
2019-02-22 08:26:47,145 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocating the VR with id=47 in datacenter
com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$2e90024a@1 with the
hypervisor type KVM
2019-02-22 08:26:47,161 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 2-159198: Processing Seq
2-159198: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-02-22 08:26:47,163 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 2-159198: Sending Seq
2-159198: { Ans: , MgmtId: 220777304233416, via: 2, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-02-22 08:26:47,281 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Adding nic for Virtual Router in Guest network Ntwk[206|Guest|8]
2019-02-22 08:26:47,281 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Adding nic for Virtual Router in Control network
2019-02-22 08:26:47,296 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Found existing network configuration for offering [Network Offering
[3-Control-System-Control-Network]: Ntwk[202|Control|3]
2019-02-22 08:26:47,296 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Releasing lock for Acct[4c03aaf5-ffa3-11e8-bcb0-c8cbb8cb15cd-system]
2019-02-22 08:26:47,299 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Adding nic for Virtual Router in Public network
2019-02-22 08:26:47,313 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Found existing network configuration for offering [Network Offering
[1-Public-System-Public-Network]: Ntwk[200|Public|1]
2019-02-22 08:26:47,313 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Releasing lock for Acct[4c03aaf5-ffa3-11e8-bcb0-c8cbb8cb15cd-system]
2019-02-22 08:26:47,318 INFO [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Use same MAC as previous RvR, the MAC is 1e:00:0c:00:00:14
2019-02-22 08:26:47,322 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocating entries for VM: VM[DomainRouter|r-47-VM]
2019-02-22 08:26:47,378 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocating nics for VM[DomainRouter|r-47-VM]
2019-02-22 08:26:47,411 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocating nic for vm VM[DomainRouter|r-47-VM] in network
Ntwk[206|Guest|8] with requested profile
NicProfile[0-0-null-10.10.10.1-vlan://13
2019-02-22 08:26:47,460 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Service SecurityGroup is not supported in the network id=206
2019-02-22 08:26:47,482 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocating nic for vm VM[DomainRouter|r-47-VM] in network
Ntwk[202|Control|3] with requested profile null
2019-02-22 08:26:47,492 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocating nic for vm VM[DomainRouter|r-47-VM] in network
Ntwk[200|Public|1] with requested profile
NicProfile[0-0-null-193.239.54.68-vlan://untagged
2019-02-22 08:26:47,503 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocating disks for VM[DomainRouter|r-47-VM]
2019-02-22 08:26:47,594 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Allocation completed for VM: VM[DomainRouter|r-47-VM]
2019-02-22 08:26:47,903 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Starting router VM[DomainRouter|r-47-VM]
2019-02-22 08:26:48,149 DEBUG [c.c.u.d.T.Transaction]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
Rolling back the transaction: Time = 14 Name = API-Job-Executor-1;
called by
-TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-Transaction.execute:43-Transaction.execute:47-AsyncJobManagerImpl.submitAsyncJob:231-VirtualMachineManagerImpl.startVmThroughJobQueue:4464-VirtualMachineManagerImpl.advanceStart:899-NetworkHelperImpl.start:276-NetworkHelperImpl.startVirtualRouter:355-NetworkHelperImpl.startRouters:340-RouterDeploymentDefinition.deployVirtualRouter:205
2019-02-22 08:26:48,234 WARN [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082 ctx-d2b2e42b) (logid:f7040f44)
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)
...
Caused by:
com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException:
Duplicate entry '1083' for key 'PRIMARY'
at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
... 64 more
2019-02-22 08:26:48,262 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Unexpected
exception while executing
org.apache.cloudstack.api.command.user.network.RestartNetworkCmd
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:247)
at
com.cloud.vm.VirtualMachineManagerImpl.startVmThroughJobQueue(VirtualMachineManagerImpl.java:4464)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:899)
...
2019-02-22 08:26:48,294 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Complete
async job-1082, 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."}
2019-02-22 08:26:48,295 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Publish
async job-1082 complete on message bus
2019-02-22 08:26:48,295 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Wake up jobs
related to job-1082
2019-02-22 08:26:48,295 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Update db
status for job-1082
2019-02-22 08:26:48,296 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Wake up jobs
joined with job-1082 and disjoin all subjobs created from job- 1082
2019-02-22 08:26:48,356 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Done
executing
org.apache.cloudstack.api.command.user.network.RestartNetworkCmd for
job-1082
2019-02-22 08:26:48,357 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-1:ctx-bd6a5e5b job-1082) (logid:f7040f44) Remove
job-1082 from job monitoring
Il 14/12/18 11:05, Andrija Panic ha scritto:
> That's funny - does restarting mgmg helps ? I assume you restored full
> cloud DB "property"...
>
> On Fri, Dec 14, 2018, 09:42 Ugo Vasi <ugo.vasi@procne.it wrote:
>
>> Hi Andrija,
>> I restored database but now I can't see any instance, host or system vm.
>> On dashboard I see a real situation statistics but I can't see any data,
>> neither via webUI nor via cloudmonkey... I verify existence of the
>> instances/hosts data on cloud's database tables.
>>
>>
>>
>> Il 13/12/18 17:22, Andrija Panic ha scritto:
>>> 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@procne.it.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@procne.it <ma...@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
>>>> info@procne.it <ma...@procne.it>.
>>>>
>>>>
>>>
>>>
>>
>> --
>>
>> *Ugo Vasi* / System Administrator
>> ugo.vasi@procne.it <ma...@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
>> info@procne.it <ma...@procne.it>.
>>
>>
>
>
>
--
*Ugo Vasi* / System Administrator
ugo.vasi@procne.it <ma...@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
info@procne.it <ma...@procne.it>.