Repository navigation
Failed to add NIC to VM concurrently #5499
Description
ISSUE TYPE
- Bug Report
COMPONENT NAME
NIC
CLOUDSTACK VERSION
4.15.0.0
CONFIGURATION
OS / ENVIRONMENT
SUMMARY
Add multiple ShareNetwork to VM at the same time, only the first job can execute successfully;
All subsequent addition of nic job shows that the execution is successful, but it is not actually added to the VM NICS
STEPS TO REPRODUCE
1. create l3 sharenetwork,name=L3-network-01
2. create l3 sharenetwork,name=L3-network-02
3. create l3 sharenetwork,name=L3-network-03
4. deploy vm use L3-network-01, VM NAME=VM1
5. wait for vm status = RUNNING
6. use api addNicToVirtualMachine to add L3-network-02 and L3-network-03 to VM1 (concurrently)
EXPECTED RESULTS
Add L3-network-02 to VM1 task execution successfully.
Add L3-network-02 to VM1 task execution successfully.
VM1 has 3 networks (L3-network-01, L3-network-02, L3-network-03)
ACTUAL RESULTS
Add L3-network-02 to VM1 job and return success.
Add L3-network-03 to VM1job and return success.
VM1 has a total of 2 network (L3-network-01, L3-network-02)
There is no network L3-network-03 in VM(VM1)->NICS, but the task shows that the addition is successful.
Activity
yadvr commentedon Sep 22, 2021
cc @nvazquez @sureshanaparti pl triage
weizhouapache commentedon Sep 24, 2021
@div8cn
could you please share some logs of the async jobs ?
div8cn commentedon Sep 27, 2021
Successfully added nic job log:
root@mgr1-dom0:
# cat /var/log/cloud-manager/cloudstack/management/management-server.log |grep -v queryA |grep eeb1aac2# cat /var/log/cloud-manager/cloudstack/management/management-server.log |grep -v queryA |grep fc6c225b2021-09-27 13:19:42,715 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-32:ctx-08594388 job-4308) (logid:eeb1aac2) Executing AsyncJobVO {id:4308, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin, cmdInfo: {"virtualmachineid":"81a09e35-28f0-40e6-a13c-0be44a08062d","response":"json","ctxUserId":"2","httpmethod":"GET","networkid":"c6f018a9-c493-481a-ab00-2a7a195dfb0d","ctxStartEventId":"29949","ctxDetails":"{"interface com.cloud.network.Network":"c6f018a9-c493-481a-ab00-2a7a195dfb0d","interface com.cloud.vm.VirtualMachine":"81a09e35-28f0-40e6-a13c-0be44a08062d"}","ctxAccountId":"2","cmdEventType":"NIC.CREATE"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 10000000001, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-09-27 13:19:45,973 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-32:ctx-08594388 job-4308 ctx-8859d716) (logid:eeb1aac2) Successful addition of Ntwk[209|Guest|21] from VM[User|i-2-46-VM]
2021-09-27 13:19:46,054 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-32:ctx-08594388 job-4308 ctx-8859d716) (logid:eeb1aac2) Complete async job-4308, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloud
root@mgr1-dom0:
2021-09-27 13:19:38,689 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299) (logid:fc6c225b) Executing AsyncJobVO {id:4299, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin, cmdInfo: {"virtualmachineid":"81a09e35-28f0-40e6-a13c-0be44a08062d","response":"json","ctxUserId":"2","httpmethod":"GET","networkid":"ea9aa2bf-6484-4c7f-89fb-e899dfc4e423","ctxStartEventId":"29937","ctxDetails":"{"interface com.cloud.network.Network":"ea9aa2bf-6484-4c7f-89fb-e899dfc4e423","interface com.cloud.vm.VirtualMachine":"81a09e35-28f0-40e6-a13c-0be44a08062d"}","ctxAccountId":"2","cmdEventType":"NIC.CREATE"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 10000000001, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-09-27 13:19:39,334 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logid:fc6c225b) Sync job-4302 execution on object VmWorkJobQueue.46
2021-09-27 13:19:39,894 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302) (logid:fc6c225b) Executing AsyncJobVO {id:4302, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkAddVmToNetwork, cmdInfo: rO0ABXNyACFjb20uY2xvdWQudm0uVm1Xb3JrQWRkVm1Ub05ldHdvcmt6-m3bkApgrQIAAkwACW5ldHdvcmtJZHQAEExqYXZhL2xhbmcvTG9uZztMABJyZXF1c3RlZE5pY1Byb2ZpbGV0ABlMY29tL2Nsb3VkL3ZtL05pY1Byb2ZpbGU7eHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAAIAAAAAAAAAAgAAAAAAAAAudAAZVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAAAAAAAAAznNyABdjb20uY2xvdWQudm0uTmljUHJvZmlsZUVY7kYs6AbAAgAfWgAKZGVmYXVsdE5pY0oAAmlkWgAWaXNTZWN1cml0eUdyb3VwRW5hYmxlZEoACW5ldHdvcmtJZEoABHZtSWRMAA1icm9hZGNhc3RUeXBldAAwTGNvbS9jbG91ZC9uZXR3b3JrL05ldHdvcmtzJEJyb2FkY2FzdERvbWFpblR5cGU7TAAMYnJvYWRjYXN0VXJpdAAOTGphdmEvbmV0L1VSSTtMAAhkZXZpY2VJZHQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZmb3JtYXR0ACpMY29tL2Nsb3VkL25ldHdvcmsvTmV0d29ya3MkQWRkcmVzc0Zvcm1hdDtMAAtpUHY0QWRkcmVzc3EAfgAETAAIaVB2NERuczFxAH4ABEwACGlQdjREbnMycQB-AARMAAtpUHY0R2F0ZXdheXEAfgAETAALaVB2NE5ldG1hc2txAH4ABEwAC2lQdjZBZGRyZXNzcQB-AARMAAhpUHY2Q2lkcnEAfgAETAAIaVB2NkRuczFxAH4ABEwACGlQdjZEbnMycQB-AARMAAtpUHY2R2F0ZXdheXEAfgAETAAMaXNvbGF0aW9uVXJpcQB-AAxMAAptYWNBZGRyZXNzcQB-AARMAARtb2RldAAhTGNvbS9jbG91ZC9uZXR3b3JrL05ldHdvcmtzJE1vZGU7TAAEbmFtZXEAfgAETAALbmV0d29ya1JhdGVxAH4ADUwACm9yZGVySW5kZXhxAH4ADUwADXJlcXVlc3RlZElQdjRxAH4ABEwADXJlcXVlc3RlZElQdjZxAH4ABEwADXJlc2VydmF0aW9uSWRxAH4ABEwACHN0cmF0ZWd5dAAmTGNvbS9jbG91ZC92bS9OaWMkUmVzZXJ2YXRpb25TdHJhdGVneTtMAAt0cmFmZmljVHlwZXQAKExjb20vY2xvdWQvbmV0d29yay9OZXR3b3JrcyRUcmFmZmljVHlwZTtMAAR1dWlkcQB-AAR4cAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAcHBwcHBwcHBwcHBwcHBwdAARMDI6MDA6NWE6NmE6MDA6MGRwcHBwcHBwcHBw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 10000000001, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Sep 27 13:19:39 CST 2021, removed: null}
2021-09-27 13:19:39,897 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302) (logid:fc6c225b) Run VM work job: com.cloud.vm.VmWorkAddVmToNetwork for VM 46, job origin: 4299
2021-09-27 13:19:39,899 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Execute VM work job: com.cloud.vm.VmWorkAddVmToNetwork{"networkId":206,"requstedNicProfile":{"id":0,"networkId":0,"vmId":0,"macAddress":"02:00:5a:6a:00:0d","defaultNic":false,"isSecurityGroupEnabled":false},"userId":2,"accountId":2,"vmId":46,"handlerName":"VirtualMachineManagerImpl"}
2021-09-27 13:19:39,901 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Adding vm VM[User|i-2-46-VM] to network Ntwk[206|Guest|21]; requested nic profile NicProfile[0-0-null-null-null]
2021-09-27 13:19:39,909 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Allocating nic for vm VM[User|i-2-46-VM] in network Ntwk[206|Guest|21] with requested profile NicProfile[0-0-null-null-null]
2021-09-27 13:19:40,217 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Service SecurityGroup is not supported in the network id=206
2021-09-27 13:19:40,237 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Nic is allocated successfully for vm VM[User|i-2-46-VM] in network Ntwk[206|Guest|21]
2021-09-27 13:19:40,245 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Network id=206 is already implemented
2021-09-27 13:19:40,289 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Service SecurityGroup is not supported in the network id=206
2021-09-27 13:19:40,290 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Changing active number of nics for network id=206 on 1
2021-09-27 13:19:40,323 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Asking VirtualRouter to prepare for Nic[693-46-null-10.226.19.78]
2021-09-27 13:19:40,335 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Service SecurityGroup is not supported in the network id=206
2021-09-27 13:19:40,337 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) CONFIG DHCP FOR SUBNETS RULES
2021-09-27 13:19:40,347 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Service SecurityGroup is not supported in the network id=206
2021-09-27 13:19:40,348 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) APPLYING VPC DHCP ENTRY RULES
2021-09-27 13:19:40,349 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Applying dhcp entry in network Ntwk[206|Guest|21]
2021-09-27 13:19:40,360 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Seq 3-1722908332445926017: Sending { Cmd , MgmtId: 10000000001, via: 3(hci-cn01), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:5a:6a:00:0d","vmIpAddress":"10.226.19.78","vmName":"TEST-DB01P","defaultRouter":"10.226.19.254","duid":"00:03:00:01:02:00:5a:6a:00:0d","isDefault":"false","executeInSequence":"false","remove":"false","accessDetails":{"router.name":"r-4-VM","router.guest.ip":"10.226.19.10","router.ip":"169.254.215.135","zone.network.type":"Advanced"},"wait":"0"}}] }
2021-09-27 13:19:41,072 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Seq 3-1722908332445926017: Received: { Ans: , MgmtId: 10000000001, via: 3(hci-cn01), Ver: v1, Flags: 10, { GroupAnswer } }
2021-09-27 13:19:41,078 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Service SecurityGroup is not supported in the network id=206
2021-09-27 13:19:41,079 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) APPLYING VPC USERDATA RULES
2021-09-27 13:19:41,080 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Applying userdata and password entry in network Ntwk[206|Guest|21]
2021-09-27 13:19:41,099 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Seq 3-1722908332445926018: Sending { Cmd , MgmtId: 10000000001, via: 3(hci-cn01), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.226.19.78","vmName":"TEST-DB01P","executeInSequence":"false","accessDetails":{"router.name":"r-4-VM","router.guest.ip":"10.226.19.10","router.ip":"169.254.215.135","zone.network.type":"Advanced"},"wait":"0"}}] }
2021-09-27 13:19:45,556 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Seq 3-1722908332445926018: Received: { Ans: , MgmtId: 10000000001, via: 3(hci-cn01), Ver: v1, Flags: 10, { GroupAnswer } }
2021-09-27 13:19:45,557 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Service SecurityGroup is not supported in the network id=206
2021-09-27 13:19:45,560 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Nic is prepared successfully for vm VM[User|i-2-46-VM] in network Ntwk[206|Guest|21]
2021-09-27 13:19:45,572 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Plugging nic for vm VM[User|i-2-46-VM] in network Ntwk[206|Guest|21]
2021-09-27 13:19:45,576 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Seq 18-8395554130348737358: Sending { Cmd , MgmtId: 10000000001, via: 18(hci-cn002), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.PlugNicCommand":{"nic":{"deviceId":"1","networkRateMbps":"2000","defaultNic":"false","pxeDisable":"false","nicUuid":"30b915a4-f421-4fe0-a1ff-102e452ccbbb","details":{"PromiscuousMode":"false","MacAddressChanges":"true","ForgedTransmits":"true"},"dpdkEnabled":"false","uuid":"ea9aa2bf-6484-4c7f-89fb-e899dfc4e423","ip":"10.226.19.78","netmask":"255.255.255.0","gateway":"10.226.19.254","mac":"02:00:5a:6a:00:0d","dns1":"114.114.114.114","dns2":"223.5.5.5","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1009","isolationUri":"vlan://1009","isSecurityGroupEnabled":"false","name":"br1"},"instanceName":"i-2-46-VM","vmType":"User","details":{"keyboard":"us","cpuOvercommitRatio":"4.0","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false"},"wait":"0"}}] }
2021-09-27 13:19:45,832 DEBUG [c.c.a.t.Request] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Seq 18-8395554130348737358: Received: { Ans: , MgmtId: 10000000001, via: 18(hci-cn002), Ver: v1, Flags: 110, { PlugNicAnswer } }
2021-09-27 13:19:45,833 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Nic is plugged successfully for vm VM[User|i-2-46-VM] in network Ntwk[206|Guest|21]. Vm is a part of network now
2021-09-27 13:19:45,863 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Done executing VM work job: com.cloud.vm.VmWorkAddVmToNetwork{"networkId":206,"requstedNicProfile":{"id":0,"networkId":0,"vmId":0,"reservationId":"1009","macAddress":"02:00:5a:6a:00:0d","broadcastType":"Vlan","mode":"Dhcp","format":"Ip4","isolationUri":"vlan://1009","broadcastUri":"vlan://1009","strategy":"Create","defaultNic":false,"isSecurityGroupEnabled":false,"iPv4Address":"10.226.19.78","iPv4Netmask":"255.255.255.0","iPv4Gateway":"10.226.19.254","iPv4Dns1":"114.114.114.114","iPv4Dns2":"223.5.5.5"},"userId":2,"accountId":2,"vmId":46,"handlerName":"VirtualMachineManagerImpl"}
2021-09-27 13:19:45,863 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Complete async job-4302, jobStatus: SUCCEEDED, resultCode: 0, result: rO0ABXNyABdjb20uY2xvdWQudm0uTmljUHJvZmlsZUVY7kYs6AbAAgAfWgAKZGVmYXVsdE5pY0oAAmlkWgAWaXNTZWN1cml0eUdyb3VwRW5hYmxlZEoACW5ldHdvcmtJZEoABHZtSWRMAA1icm9hZGNhc3RUeXBldAAwTGNvbS9jbG91ZC9uZXR3b3JrL05ldHdvcmtzJEJyb2FkY2FzdERvbWFpblR5cGU7TAAMYnJvYWRjYXN0VXJpdAAOTGphdmEvbmV0L1VSSTtMAAhkZXZpY2VJZHQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZmb3JtYXR0ACpMY29tL2Nsb3VkL25ldHdvcmsvTmV0d29ya3MkQWRkcmVzc0Zvcm1hdDtMAAtpUHY0QWRkcmVzc3QAEkxqYXZhL2xhbmcvU3RyaW5nO0wACGlQdjREbnMxcQB-AAVMAAhpUHY0RG5zMnEAfgAFTAALaVB2NEdhdGV3YXlxAH4ABUwAC2lQdjROZXRtYXNrcQB-AAVMAAtpUHY2QWRkcmVzc3EAfgAFTAAIaVB2NkNpZHJxAH4ABUwACGlQdjZEbnMxcQB-AAVMAAhpUHY2RG5zMnEAfgAFTAALaVB2NkdhdGV3YXlxAH4ABUwADGlzb2xhdGlvblVyaXEAfgACTAAKbWFjQWRkcmVzc3EAfgAFTAAEbW9kZXQAIUxjb20vY2xvdWQvbmV0d29yay9OZXR3b3JrcyRNb2RlO0wABG5hbWVxAH4ABUwAC25ldHdvcmtSYXRlcQB-AANMAApvcmRlckluZGV4cQB-AANMAA1yZXF1ZXN0ZWRJUHY0cQB-AAVMAA1yZXF1ZXN0ZWRJUHY2cQB-AAVMAA1yZXNlcnZhdGlvbklkcQB-AAVMAAhzdHJhdGVneXQAJkxjb20vY2xvdWQvdm0vTmljJFJlc2VydmF0aW9uU3RyYXRlZ3k7TAALdHJhZmZpY1R5cGV0AChMY29tL2Nsb3VkL25ldHdvcmsvTmV0d29ya3MkVHJhZmZpY1R5cGU7TAAEdXVpZHEAfgAFeHAAAAAAAAAAArUAAAAAAAAAAM4AAAAAAAAALn5yAC5jb20uY2xvdWQubmV0d29yay5OZXR3b3JrcyRCcm9hZGNhc3REb21haW5UeXBlAAAAAAAAAAASAAB4cgAOamF2YS5sYW5nLkVudW0AAAAAAAAAABIAAHhwdAAEVmxhbnNyAAxqYXZhLm5ldC5VUkmsAXguQ55JqwMAAUwABnN0cmluZ3EAfgAFeHB0AAt2bGFuOi8vMTAwOXhzcgARamF2YS5sYW5nLkludGVnZXIS4qCk94GHOAIAAUkABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAX5yAChjb20uY2xvdWQubmV0d29yay5OZXR3b3JrcyRBZGRyZXNzRm9ybWF0AAAAAAAAAAASAAB4cQB-AAt0AANJcDR0AAwxMC4yMjYuMTkuNzh0AA8xMTQuMTE0LjExNC4xMTR0AAkyMjMuNS41LjV0AA0xMC4yMjYuMTkuMjU0dAANMjU1LjI1NS4yNTUuMHBwcHBwc3EAfgAOdAALdmxhbjovLzEwMDl4dAARMDI6MDA6NWE6NmE6MDA6MGR-cgAfY29tLmNsb3VkLm5ldHdvcmsuTmV0d29ya3MkTW9kZQAAAAAAAAAAEgAAeHEAfgALdAAERGhjcHQAA2JyMXNxAH4AEQAAB9BwcHBwfnIAJGNvbS5jbG91ZC52bS5OaWMkUmVzZXJ2YXRpb25TdHJhdGVneQAAAAAAAAAAEgAAeHEAfgALdAAGQ3JlYXRlfnIAJmNvbS5jbG91ZC5uZXR3b3JrLk5ldHdvcmtzJFRyYWZmaWNUeXBlAAAAAAAAAAASAAB4cQB-AAt0AAVHdWVzdHQAJDMwYjkxNWE0LWY0MjEtNGZlMC1hMWZmLTEwMmU0NTJjY2JiYg
2021-09-27 13:19:45,864 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Publish async job-4302 complete on message bus
2021-09-27 13:19:45,864 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Wake up jobs related to job-4302
2021-09-27 13:19:45,864 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Update db status for job-4302
2021-09-27 13:19:45,866 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302 ctx-8c20125b) (logid:fc6c225b) Wake up jobs joined with job-4302 and disjoin all subjobs created from job- 4302
2021-09-27 13:19:45,937 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302) (logid:fc6c225b) Done with run of VM work job: com.cloud.vm.VmWorkAddVmToNetwork for VM 46, job origin: 4299
2021-09-27 13:19:45,937 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302) (logid:fc6c225b) Done executing com.cloud.vm.VmWorkAddVmToNetwork for job-4302
2021-09-27 13:19:45,939 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-17:ctx-26473458 job-4299/job-4302) (logid:fc6c225b) Remove job-4302 from job monitoring
2021-09-27 13:19:46,023 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logid:fc6c225b) Successful addition of Ntwk[206|Guest|21] from VM[User|i-2-46-VM]
2021-09-27 13:19:46,363 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logid:fc6c225b) Complete async job-4299, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"81a09e35-28f0-40e6-a13c-0be44a08062d","name":"TEST-DB01P","displayname":"TEST-DB01P","account":"admin","userid":"a66bafe3-d0b1-49c2-b2e3-a8a0b88c511b","username":"skyhive","domainid":"ccd5f84c-12f1-11ec-ba65-5254003db647","domain":"ROOT","created":"2021-09-15T17:53:36+0800","state":"Running","haenable":"true","zoneid":"79ba6762-538f-450e-b108-4a8cd534f5d9","zonename":"uat","hostid":"6d8d09d2-8102-4c2e-bf95-10a582ee2134","hostname":"hci-cn002","guestosid":"d0d4ec03-12f1-11ec-ba65-5254003db647","securitygroup":[],"nic":[{"id":"e19a0dbe-69e0-43a7-a800-d7e0023125b1","networkid":"a42a1a9f-4e61-4408-8827-dac040cdceb0","networkname":"skyhive-tech","netmask":"255.255.255.0","gateway":"192.168.10.1","ipaddress":"192.168.10.36","isolationuri":"vlan://569","broadcasturi":"vlan://569","traffictype":"Guest","type":"Isolated","isdefault":"true","macaddress":"02:00:6a:10:00:04","secondaryip":[{"id":"87fc5ea8-f271-4ab9-a948-44f33e1ca3c4","ipaddress":"192.168.10.158"}],"extradhcpoption":[]},{"id":"30b915a4-f421-4fe0-a1ff-102e452ccbbb","networkid":"ea9aa2bf-6484-4c7f-89fb-e899dfc4e423","networkname":"L3-Shared-Network","netmask":"255.255.255.0","gateway":"10.226.19.254","ipaddress":"10.226.19.78","isolationuri":"vlan://1009","broadcasturi":"vlan://1009","traffictype":"Guest","type":"Shared","isdefault":"false","macaddress":"02:00:5a:6a:00:0d","secondaryip":[],"extradhcpoption":[]}],"hypervisor":"KVM","instancename":"i-2-46-VM","details":{"keyboard":"us","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"4.0"},"affinitygroup":[],"displayvm":"true","isdynamicallyscalable":"false","ostypeid":"d0d4ec03-12f1-11ec-ba65-5254003db647","osdisplayname":"Other Ubuntu (64-bit)","tags":[]}
2021-09-27 13:19:46,367 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logid:fc6c225b) Publish async job-4299 complete on message bus
2021-09-27 13:19:46,367 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logid:fc6c225b) Wake up jobs related to job-4299
2021-09-27 13:19:46,367 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logid:fc6c225b) Update db status for job-4299
2021-09-27 13:19:46,368 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logid:fc6c225b) Wake up jobs joined with job-4299 and disjoin all subjobs created from job- 4299
2021-09-27 13:19:46,401 DEBUG [c.c.a.ApiServer] (API-Job-Executor-30:ctx-e6885870 job-4299 ctx-be7aa58f) (logidfc6c225b) Retrieved cmdEventType from job info: NIC.CREATE
2021-09-27 13:19:46,405 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-30:ctx-e6885870 job-4299) (logid:fc6c225b) Done executing org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin for job-4299
2021-09-27 13:19:46,440 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-30:ctx-e6885870 job-4299) (logid:fc6c225b) Remove job-4299 from job monitoring
div8cn commentedon Sep 27, 2021
Unsuccessful async job:
root@mgr1-dom0:~# cat /var/log/cloud-manager/cloudstack/management/management-server.log |grep -v queryA |grep 69688a36
2021-09-27 13:19:40,876 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305) (logid:69688a36) Executing AsyncJobVO {id:4305, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin, cmdInfo: {"virtualmachineid":"81a09e35-28f0-40e6-a13c-0be44a08062d","response":"json","ctxUserId":"2","httpmethod":"GET","networkid":"4e6cfd3d-a91b-46bf-8340-958976c2ff21","ctxStartEventId":"29943","ctxDetails":"{"interface com.cloud.network.Network":"4e6cfd3d-a91b-46bf-8340-958976c2ff21","interface com.cloud.vm.VirtualMachine":"81a09e35-28f0-40e6-a13c-0be44a08062d"}","ctxAccountId":"2","cmdEventType":"NIC.CREATE"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 10000000001, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-09-27 13:19:45,995 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Successful addition of Ntwk[208|Guest|60] from VM[User|i-2-46-VM]
2021-09-27 13:19:46,195 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Complete async job-4305, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"81a09e35-28f0-40e6-a13c-0be44a08062d","name":"TEST-DB01P","displayname":"TEST-DB01P","account":"admin","userid":"a66bafe3-d0b1-49c2-b2e3-a8a0b88c511b","username":"skyhive","domainid":"ccd5f84c-12f1-11ec-ba65-5254003db647","domain":"ROOT","created":"2021-09-15T17:53:36+0800","state":"Running","haenable":"true","zoneid":"79ba6762-538f-450e-b108-4a8cd534f5d9","zonename":"uat","hostid":"6d8d09d2-8102-4c2e-bf95-10a582ee2134","hostname":"hci-cn002","guestosid":"d0d4ec03-12f1-11ec-ba65-5254003db647","securitygroup":[],"nic":[{"id":"e19a0dbe-69e0-43a7-a800-d7e0023125b1","networkid":"a42a1a9f-4e61-4408-8827-dac040cdceb0","networkname":"skyhive-tech","netmask":"255.255.255.0","gateway":"192.168.10.1","ipaddress":"192.168.10.36","isolationuri":"vlan://569","broadcasturi":"vlan://569","traffictype":"Guest","type":"Isolated","isdefault":"true","macaddress":"02:00:6a:10:00:04","secondaryip":[{"id":"87fc5ea8-f271-4ab9-a948-44f33e1ca3c4","ipaddress":"192.168.10.158"}],"extradhcpoption":[]},{"id":"30b915a4-f421-4fe0-a1ff-102e452ccbbb","networkid":"ea9aa2bf-6484-4c7f-89fb-e899dfc4e423","networkname":"L3-Shared-Network","netmask":"255.255.255.0","gateway":"10.226.19.254","ipaddress":"10.226.19.78","isolationuri":"vlan://1009","broadcasturi":"vlan://1009","traffictype":"Guest","type":"Shared","isdefault":"false","macaddress":"02:00:5a:6a:00:0d","secondaryip":[],"extradhcpoption":[]}],"hypervisor":"KVM","instancename":"i-2-46-VM","details":{"keyboard":"us","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"4.0"},"affinitygroup":[],"displayvm":"true","isdynamicallyscalable":"false","ostypeid":"d0d4ec03-12f1-11ec-ba65-5254003db647","osdisplayname":"Other Ubuntu (64-bit)","tags":[]}
2021-09-27 13:19:46,197 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Publish async job-4305 complete on message bus
2021-09-27 13:19:46,197 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Wake up jobs related to job-4305
2021-09-27 13:19:46,197 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Update db status for job-4305
2021-09-27 13:19:46,198 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Wake up jobs joined with job-4305 and disjoin all subjobs created from job- 4305
2021-09-27 13:19:46,353 DEBUG [c.c.a.ApiServer] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid69688a36) Retrieved cmdEventType from job info: NIC.CREATE
2021-09-27 13:19:46,358 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305) (logid:69688a36) Done executing org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin for job-4305
2021-09-27 13:19:46,358 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-31:ctx-8c906118 job-4305) (logid:69688a36) Remove job-4305 from job monitoring
@weizhouapache
weizhouapache commentedon Sep 27, 2021
@div8cn
can you filter logs by keyword
job-4305?div8cn commentedon Sep 27, 2021
root@mgr1-dom0:~# cat /var/log/cloud-manager/cloudstack/management/management-server.log |grep job-4305
2021-09-27 13:19:40,871 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-31:ctx-8c906118 job-4305) (logid:1c4369ad) Add job-4305 into job monitoring
2021-09-27 13:19:40,876 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305) (logid:69688a36) Executing AsyncJobVO {id:4305, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin, cmdInfo: {"virtualmachineid":"81a09e35-28f0-40e6-a13c-0be44a08062d","response":"json","ctxUserId":"2","httpmethod":"GET","networkid":"4e6cfd3d-a91b-46bf-8340-958976c2ff21","ctxStartEventId":"29943","ctxDetails":"{"interface com.cloud.network.Network":"4e6cfd3d-a91b-46bf-8340-958976c2ff21","interface com.cloud.vm.VirtualMachine":"81a09e35-28f0-40e6-a13c-0be44a08062d"}","ctxAccountId":"2","cmdEventType":"NIC.CREATE"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 10000000001, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-09-27 13:19:40,878 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp18242360-403:ctx-52ccebbc ctx-8e398ef5) (logid:3eef3393) submit async job-4305, details: AsyncJobVO {id:4305, userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin, cmdInfo: {"virtualmachineid":"81a09e35-28f0-40e6-a13c-0be44a08062d","response":"json","ctxUserId":"2","httpmethod":"GET","networkid":"4e6cfd3d-a91b-46bf-8340-958976c2ff21","ctxStartEventId":"29943","ctxDetails":"{"interface com.cloud.network.Network":"4e6cfd3d-a91b-46bf-8340-958976c2ff21","interface com.cloud.vm.VirtualMachine":"81a09e35-28f0-40e6-a13c-0be44a08062d"}","ctxAccountId":"2","cmdEventType":"NIC.CREATE"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 10000000001, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-09-27 13:19:45,995 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Successful addition of Ntwk[208|Guest|60] from VM[User|i-2-46-VM]
2021-09-27 13:19:46,195 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Complete async job-4305, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"81a09e35-28f0-40e6-a13c-0be44a08062d","name":"TEST-DB01P","displayname":"TEST-DB01P","account":"admin","userid":"a66bafe3-d0b1-49c2-b2e3-a8a0b88c511b","username":"skyhive","domainid":"ccd5f84c-12f1-11ec-ba65-5254003db647","domain":"ROOT","created":"2021-09-15T17:53:36+0800","state":"Running","haenable":"true","zoneid":"79ba6762-538f-450e-b108-4a8cd534f5d9","zonename":"uat","hostid":"6d8d09d2-8102-4c2e-bf95-10a582ee2134","hostname":"hci-cn002","guestosid":"d0d4ec03-12f1-11ec-ba65-5254003db647","securitygroup":[],"nic":[{"id":"e19a0dbe-69e0-43a7-a800-d7e0023125b1","networkid":"a42a1a9f-4e61-4408-8827-dac040cdceb0","networkname":"skyhive-tech","netmask":"255.255.255.0","gateway":"192.168.10.1","ipaddress":"192.168.10.36","isolationuri":"vlan://569","broadcasturi":"vlan://569","traffictype":"Guest","type":"Isolated","isdefault":"true","macaddress":"02:00:6a:10:00:04","secondaryip":[{"id":"87fc5ea8-f271-4ab9-a948-44f33e1ca3c4","ipaddress":"192.168.10.158"}],"extradhcpoption":[]},{"id":"30b915a4-f421-4fe0-a1ff-102e452ccbbb","networkid":"ea9aa2bf-6484-4c7f-89fb-e899dfc4e423","networkname":"L3-Shared-Network","netmask":"255.255.255.0","gateway":"10.226.19.254","ipaddress":"10.226.19.78","isolationuri":"vlan://1009","broadcasturi":"vlan://1009","traffictype":"Guest","type":"Shared","isdefault":"false","macaddress":"02:00:5a:6a:00:0d","secondaryip":[],"extradhcpoption":[]}],"hypervisor":"KVM","instancename":"i-2-46-VM","details":{"keyboard":"us","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"4.0"},"affinitygroup":[],"displayvm":"true","isdynamicallyscalable":"false","ostypeid":"d0d4ec03-12f1-11ec-ba65-5254003db647","osdisplayname":"Other Ubuntu (64-bit)","tags":[]}
2021-09-27 13:19:46,197 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Publish async job-4305 complete on message bus
2021-09-27 13:19:46,197 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Wake up jobs related to job-4305
2021-09-27 13:19:46,197 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Update db status for job-4305
2021-09-27 13:19:46,198 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Wake up jobs joined with job-4305 and disjoin all subjobs created from job- 4305
2021-09-27 13:19:46,353 DEBUG [c.c.a.ApiServer] (API-Job-Executor-31:ctx-8c906118 job-4305 ctx-9fe0a7ee) (logid:69688a36) Retrieved cmdEventType from job info: NIC.CREATE
2021-09-27 13:19:46,358 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-8c906118 job-4305) (logid:69688a36) Done executing org.apache.cloudstack.api.command.admin.vm.AddNicToVMCmdByAdmin for job-4305
2021-09-27 13:19:46,358 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-31:ctx-8c906118 job-4305) (logid:69688a36) Remove job-4305 from job monitoring
weizhouapache commentedon Sep 27, 2021
@nvazquez @sureshanaparti
I tried to reproduce the issue once, but failed.
anyone else want to have a look ?
nvazquez commentedon Sep 27, 2021
@div8cn how are you testing the APIs to ensure they are executed at the same time? Are you able to reproduce the issue again?
div8cn commentedon Sep 27, 2021
I use java to directly access cloudstack api
div8cn commentedon Sep 28, 2021
This is not entirely at the same time, because the use of for causes a delay in the middle of it <1s
DaanHoogland commentedon Sep 28, 2021
@div8cn I'll try and reproduced, but I discussed with @weizhouapache and his reproduction method seems solid. Can you share the code that does the API calls, to help us reproducing your issue?
cc @nvazquez
DaanHoogland commentedon Sep 28, 2021
In addition @div8cn , can you share other env details, like hypervisors/network/storage, please?
div8cn commentedon Sep 28, 2021
hypervisors: kvm (ubuntu 20.04 ,libvirt 6.0)
network: L3 ShareNetwork
storage: CEPH RBD
10 remaining items
DaanHoogland commentedon Sep 30, 2021
@div8cn do you see a chance to review/test #5541?
div8cn commentedon Oct 4, 2021
I merged Patch to 4.15.0.0, adding multiple NICs to VM (vm nic total >4) the problem still exists
DaanHoogland commentedon Oct 4, 2021
hm, too bad, I managed to reproduce and solve the issue. Can you provide more info, please @div8cn ?
DaanHoogland commentedon Oct 4, 2021
@div8cn , this ticket autoclosed as the PR was merged that claimed to solve this issue (and did so for me and Wei. Feel free to reopen or create a new one though, if this does not solve it for you?
DaanHoogland commentedon Jan 10, 2022
fixed again in #5658 (hope it stays fixed this time)