search

apache / cloudstack

Apache CloudStack is an opensource Infrastructure as a Service (IaaS) cloud computing platform
https://cloudstack.apache.org/
Apache License 2.0
2.05k stars 1.1k forks source link

Failed to add NIC to VM concurrently #5499

Closed div8cn closed 2 years ago

div8cn commented 3 years ago
ISSUE TYPE
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.
rohityadavcloud commented 3 years ago

cc @nvazquez @sureshanaparti pl triage

weizhouapache commented 3 years ago

@div8cn could you please share some logs of the async jobs ?

div8cn commented 3 years ago

Successfully added nic job log:

root@mgr1-dom0:~# cat /var/log/cloud-manager/cloudstack/management/management-server.log |grep -v queryA |grep eeb1aac2 2021-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:~# cat /var/log/cloud-manager/cloudstack/management/management-server.log |grep -v queryA |grep fc6c225b 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 commented 3 years ago

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 commented 3 years ago

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

@div8cn can you filter logs by keyword job-4305 ?

div8cn commented 3 years ago

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 commented 3 years ago

@nvazquez @sureshanaparti I tried to reproduce the issue once, but failed. anyone else want to have a look ?

nvazquez commented 3 years ago

@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 commented 3 years ago

I use java to directly access cloudstack api

div8cn commented 3 years ago

This is not entirely at the same time, because the use of for causes a delay in the middle of it <1s

DaanHoogland commented 3 years ago

@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 commented 3 years ago

In addition @div8cn , can you share other env details, like hypervisors/network/storage, please?

div8cn commented 3 years ago

hypervisors: kvm (ubuntu 20.04 ,libvirt 6.0) network: L3 ShareNetwork storage: CEPH RBD

div8cn commented 3 years ago

Sorry, I may not be able to separate the API scheduling code and give it to you.

I used CMK to simulate this operation, and it reproduced;

Use SSH to connect to the cloudstack node Use CMK in the node to add 3 networks to the VM; These three tasks were completed almost simultaneously;

1632835553

In the end, only the first task (the first task to press Enter) was successful. Although the last two were successful, they were not included in the NICS of the VM.

nvazquez commented 3 years ago

@div8cn can you test the latest main branch and see if the issue persists?

DaanHoogland commented 3 years ago

I have tested this with a slightly different scenario then you and @weizhouapache , @div8cn , starting them in a loop in the background and also in my case the vm gets nic assigned for each network.

# for i in 072efd74-744d-47b7-a2ca-8befc75fde45  fd288f34-5ea1-4432-806f-3a809d0860a1
> do
>   cmk add nictovirtualmachine virtualmachineid=70968c7b-2662-46e9-8ba3-e34dd9e32836 networkid=$i &
> done

Maybe there is a network or storage issue adding to the cocktail?

div8cn commented 3 years ago

I added 3 shared networks to the VM at the same time

VM had a shared network before adding

DaanHoogland commented 3 years ago

so 4 in total? I also added three shared nets on creation which also went well. I'll try with a fourth as well

DaanHoogland commented 3 years ago

you are right @div8cn with four (4) nets, I could reproduce the issue. cc @nvazquez @weizhouapache

div8cn commented 3 years ago

Thanks for your verification

DaanHoogland commented 3 years ago

@div8cn @nvazquez @weizhouapache I reproduced this on latest main branch but with a nuance; the success result does not show a nic for the missing network, so the result does indicate that no network was added. It should have been an error result instead, of course. I will investigate more later.

DaanHoogland commented 3 years ago

note to self: just added 5 nics in parallel , only the fifth was added.

DaanHoogland commented 3 years ago

@div8cn do you see a chance to review/test #5541?

div8cn commented 3 years ago

I merged Patch to 4.15.0.0, adding multiple NICs to VM (vm nic total >4) the problem still exists

DaanHoogland commented 3 years ago

I merged Patch to 4.15.0.0, adding multiple NICs to VM (vm nic total >4) the problem still exists

hm, too bad, I managed to reproduce and solve the issue. Can you provide more info, please @div8cn ?

DaanHoogland commented 3 years ago

@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 commented 2 years ago

fixed again in #5658 (hope it stays fixed this time)