andrijapanicsb opened a new issue #4299:
URL: https://github.com/apache/cloudstack/issues/4299
4.15 (master) - more specifically from PR #4250, VMware 6.7 u3
Can't un-manage an instance (attached to one Isolated and one L2 network)
`2020-08-31 14:57:51,113 ERROR [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Could
not unmanage VM 20ec0335-f10b-443e-92ef-9ec5bef3d3be
java.lang.NullPointerException
at
com.cloud.vm.UserVmManagerImpl.postProcessingUnmanageVM(UserVmManagerImpl.java:7308)
at
com.cloud.vm.UserVmManagerImpl.publishUnmanageVMUsageEvents(UserVmManagerImpl.java:7265)
at
com.cloud.vm.UserVmManagerImpl.unmanageUserVM(UserVmManagerImpl.java:7246)`
Full log for the job:
> 2020-08-31 14:57:49,903 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp846254484-44021:ctx-b3ac65c0 ctx-bc23094c) (logid:2234ad9c) submit async
job-836, details: AsyncJobVO {id:836, userId: 2, accountId: 2, instanceType:
VirtualMachine, instanceId: 119, cmd:
org.apache.cloudstack.api.command.admin.vm.UnmanageVMInstanceCmd, cmdInfo:
{"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"1366","id":"20ec0335-f10b-443e-92ef-9ec5bef3d3be","ctxDetails":"{\"interface
com.cloud.vm.VirtualMachine\":\"20ec0335-f10b-443e-92ef-9ec5bef3d3be\"}","ctxAccountId":"2","uuid":"20ec0335-f10b-443e-92ef-9ec5bef3d3be","cmdEventType":"VM.UNMANAGE"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 32989442554424, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2020-08-31 14:57:49,904 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:9549a138) Add job-836 into
job monitoring
2020-08-31 14:57:49,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Executing
AsyncJobVO {id:836, userId: 2, accountId: 2, instanceType: VirtualMachine,
instanceId: 119, cmd:
org.apache.cloudstack.api.command.admin.vm.UnmanageVMInstanceCmd, cmdInfo:
{"response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"1366","id":"20ec0335-f10b-443e-92ef-9ec5bef3d3be","ctxDetails":"{\"interface
com.cloud.vm.VirtualMachine\":\"20ec0335-f10b-443e-92ef-9ec5bef3d3be\"}","ctxAccountId":"2","uuid":"20ec0335-f10b-443e-92ef-9ec5bef3d3be","cmdEventType":"VM.UNMANAGE"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 32989442554424, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2020-08-31 14:57:49,937 DEBUG [c.c.a.t.Request]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Seq
1-2855000688776198159: Sending { Cmd , MgmtId: 32989442554424, via:
1(10.10.2.149), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.PrepareUnmanageVMInstanceCommand":{"instanceName":"i-4-119-VM","wait":"0"}}]
}
2020-08-31 14:57:49,937 DEBUG [c.c.a.t.Request]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Seq
1-2855000688776198159: Executing: { Cmd , MgmtId: 32989442554424, via:
1(10.10.2.149), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.PrepareUnmanageVMInstanceCommand":{"instanceName":"i-4-119-VM","wait":"0"}}]
}
2020-08-31 14:57:49,938 DEBUG [c.c.h.v.r.VmwareResource]
(DirectAgent-297:ctx-7d896e99 10.10.2.149, job-836, cmd:
PrepareUnmanageVMInstanceCommand) (logid:6161a6f9) Verify VMware instance:
i-4-119-VM is available before unmanaging VM
2020-08-31 14:57:50,145 DEBUG [c.c.a.t.Request]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Seq
1-2855000688776198159: Received: { Ans: , MgmtId: 32989442554424, via:
1(10.10.2.149), Ver: v1, Flags: 10, { PrepareUnmanageVMInstanceAnswer } }
2020-08-31 14:57:50,145 DEBUG [c.c.a.m.AgentManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Details from executing class
com.cloud.agent.api.PrepareUnmanageVMInstanceCommand: OK
2020-08-31 14:57:50,151 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Checking if there are any ongoing snapshots on the ROOT volumes associated with
VM with ID 119
2020-08-31 14:57:50,152 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Found
1 no. of volumes of type ROOT for vm with VM ID 119
2020-08-31 14:57:50,152 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Checking status of snapshots for Volume with Volume Id: 148
2020-08-31 14:57:50,153 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) The
count of ongoing Snapshots for VM with ID 119 and disk type ROOT is 0
2020-08-31 14:57:50,153 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Found
no ongoing snapshots on volume of type ROOT, for the vm with id 119
2020-08-31 14:57:50,155 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Unmanaging vm VM[User|i-4-119-VM]
2020-08-31 14:57:50,156 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Cleaning up NICs
2020-08-31 14:57:50,157 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Unmanaging NICs for VM: 119
2020-08-31 14:57:50,158 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Service SecurityGroup is not supported in the network id=208
2020-08-31 14:57:50,168 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Changing active number of nics for network id=208 on -1
2020-08-31 14:57:50,170 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Asking
VirtualRouter to release
NicProfile[305-119-e59d03fc-9eca-4a17-aef3-69afcb97ce87-10.1.1.197-null]
2020-08-31 14:57:50,173 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) REMOVE
VPC DHCP ENTRY RULES
2020-08-31 14:57:50,174 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Applying dhcp entry in network Ntwk[208|Guest|8]
2020-08-31 14:57:50,180 DEBUG [c.c.a.t.Request]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Seq
2-2379026503158477752: Sending { Cmd , MgmtId: 32989442554424, via:
2(10.10.2.156), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:11:03:00:0d","vmIpAddress":"10.1.1.197","vmName":"VM-20ec0335-f10b-443e-92ef-9ec5bef3d3be","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:11:03:00:0d","isDefault":"true","executeInSequence":"false","remove":"true","accessDetails":{"router.name":"r-41-VM","router.guest.ip":"10.1.1.1","router.ip":"10.10.9.134","zone.network.type":"Advanced"},"wait":"0"}}]
}
2020-08-31 14:57:50,180 DEBUG [c.c.a.t.Request]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Seq
2-2379026503158477752: Executing: { Cmd , MgmtId: 32989442554424, via:
2(10.10.2.156), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:11:03:00:0d","vmIpAddress":"10.1.1.197","vmName":"VM-20ec0335-f10b-443e-92ef-9ec5bef3d3be","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:11:03:00:0d","isDefault":"true","executeInSequence":"false","remove":"true","accessDetails":{"router.name":"r-41-VM","router.guest.ip":"10.1.1.1","router.ip":"10.10.9.134","zone.network.type":"Advanced"},"wait":"0"}}]
}
2020-08-31 14:57:50,180 DEBUG [c.c.h.v.r.VmwareResource]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) Use router's private IP for SSH control. IP : 10.10.9.134
2020-08-31 14:57:50,180 DEBUG [c.c.a.r.v.VirtualRoutingResource]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) Transforming com.cloud.agent.api.routing.DhcpEntryCommand to
ConfigItems
2020-08-31 14:57:50,180 DEBUG [c.c.a.r.v.f.AbstractConfigItemFacade]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) Transformed filename: vm_dhcp_entry.json to:
vm_dhcp_entry.json.1b8f1e2f-aae2-4143-a31a-3b8606b3e5f7
2020-08-31 14:57:50,565 DEBUG [c.c.a.r.v.VirtualRoutingResource]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) Processing FileConfigItem, copying 307 characters to
vm_dhcp_entry.json.1b8f1e2f-aae2-4143-a31a-3b8606b3e5f7 took 385ms
2020-08-31 14:57:50,565 DEBUG [c.c.h.v.r.VmwareResource]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) Run command on VR: 10.10.9.134, script: update_config.py with
args: vm_dhcp_entry.json.1b8f1e2f-aae2-4143-a31a-3b8606b3e5f7
2020-08-31 14:57:51,049 DEBUG [c.c.h.v.r.VmwareResource]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) update_config.py execution result: true
2020-08-31 14:57:51,049 DEBUG [c.c.a.r.v.VirtualRoutingResource]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) Processing ScriptConfigItem, executing update_config.py
vm_dhcp_entry.json.1b8f1e2f-aae2-4143-a31a-3b8606b3e5f7 took 484ms
2020-08-31 14:57:51,049 WARN [c.c.a.r.v.VirtualRoutingResource]
(DirectAgent-298:ctx-59090025 10.10.2.156, job-836, cmd: DhcpEntryCommand)
(logid:6161a6f9) Expected 1 answers while executing DhcpEntryCommand but
received 2
2020-08-31 14:57:51,050 DEBUG [c.c.a.t.Request]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Seq
2-2379026503158477752: Received: { Ans: , MgmtId: 32989442554424, via:
2(10.10.2.156), Ver: v1, Flags: 10, { GroupAnswer } }
2020-08-31 14:57:51,051 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Service SecurityGroup is not supported in the network id=208
2020-08-31 14:57:51,051 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Removed nic id=305
2020-08-31 14:57:51,052 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Revoving nic secondary ip entry ...
2020-08-31 14:57:51,054 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Service SecurityGroup is not supported in the network id=207
2020-08-31 14:57:51,055 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Changing active number of nics for network id=207 on -1
2020-08-31 14:57:51,057 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Service SecurityGroup is not supported in the network id=207
2020-08-31 14:57:51,058 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Removed nic id=306
2020-08-31 14:57:51,058 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Revoving nic secondary ip entry ...
2020-08-31 14:57:51,066 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Unmanaging storage for vm: 119
2020-08-31 14:57:51,087 DEBUG [c.c.n.f.FirewallManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) No
firewall rules are found for vm id=119
2020-08-31 14:57:51,091 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Firewall rules are removed successfully as a part of vm id=119 expunge
2020-08-31 14:57:51,092 DEBUG [c.c.n.r.RulesManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) No
port forwarding rules are found for vm id=119
2020-08-31 14:57:51,092 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Port
forwarding rules are removed successfully as a part of vm id=119 expunge
2020-08-31 14:57:51,093 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Removed vm id=119 from all load balancers as a part of expunge process
2020-08-31 14:57:51,103 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Updating resource Type = volume count for Account = 4 Operation = decreasing
Amount = 1
2020-08-31 14:57:51,106 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9)
Updating resource Type = primary_storage count for Account = 4 Operation =
decreasing Amount = (1.00 GB) 1073741824
2020-08-31 14:57:51,113 ERROR [c.c.v.UserVmManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836 ctx-4e8394bb) (logid:6161a6f9) Could
not unmanage VM 20ec0335-f10b-443e-92ef-9ec5bef3d3be
2020-08-31 14:57:51,129 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Complete async
job-836, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530"}
2020-08-31 14:57:51,129 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Publish async
job-836 complete on message bus
2020-08-31 14:57:51,129 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Wake up jobs
related to job-836
2020-08-31 14:57:51,129 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Update db status
for job-836
2020-08-31 14:57:51,130 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Wake up jobs joined
with job-836 and disjoin all subjobs created from job- 836
2020-08-31 14:57:51,132 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Done executing
org.apache.cloudstack.api.command.admin.vm.UnmanageVMInstanceCmd for job-836
2020-08-31 14:57:51,132 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-40:ctx-0aafd0a6 job-836) (logid:6161a6f9) Remove job-836 from
job monitoring
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
