Bhavin created CLOUDSTACK-8963:
----------------------------------
Summary: Cloudstack4.3:vmware: Java soap fault exception while
deleting VR during concurrent operations
Key: CLOUDSTACK-8963
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8963
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Management Server
Affects Versions: 4.3.0
Environment: esx 5.5, master build
Reporter: Bhavin
Priority: Minor
This seems a race condition between DeleteVPCCmd and VpcCleanupTask.
The VpcCleanupTask already removed the VPC, so the DeleteVPC failed to stop the
VR
as is was already gone. API call returned a failure, but VPC was removed
nonetheless.
steps to produce:
1.create 1vpc
2.Add 2 PublicIP
3.create 1 tier
4.create 2 vms
5.Create 1 LB rule
6. Assign this rule to above 2 guest vms
7.delete LB rules
8.delete vms
9.delete tier
10.delete vpcs
actual results:
All vms and VR are deleted but Soap Fault Exception
expected results:
All vms should be deleted LB,VR, guest vms with No exception
{noformat:titleBGColor=#FFFFCE|title=DeleteVPC}
2015-10-15 12:48:09,616 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-114:ctx-e492f4f3) Add job-3374 into job monitoring
2015-10-15 12:48:09,616 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-114:ctx-e492f4f3) Executing AsyncJobVO {id:3374, userId: 2,
accountId: 2, instanceType: None, instanceId: null, cmd:
org.apache.cloudstack.api.command.user.vpc.DeleteVPCCmd, cmdInfo:
{"id":"eec07712-3bc7-48fc-aa69-32b0854337d2","response":"json","cmdEventType":"VPC.DELETE","ctxUserId":"2","httpmethod":"GET","ctxAccountId":"2","ctxStartEventId":"42608","apiKey":"X4odgZk0M9fTO-7XmelwdVmoauR6FrP9SMxQ_3p0LGTC0oOM5tKDTUxBdiHaz20NJaKjWn5L2VtUzK_g9thCNg","signature":"+6ogPH6WIFhGeWE1jJ4bCy6mfcw\u003d"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 14038000394492, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2015-10-15 12:48:09,622 DEBUG [c.c.n.v.VpcManagerImpl]
(Job-Executor-114:ctx-e492f4f3 ctx-8a897085) Destroying vpc [VPC
[45-dvbr-autoF-1]
2015-10-15 12:48:09,623 DEBUG [c.c.n.v.VpcManagerImpl]
(Job-Executor-114:ctx-e492f4f3 ctx-8a897085) Updating VPC [VPC
[45-dvbr-autoF-1] with state Inactive as a part of vpc delete
2015-10-15 12:48:09,658 DEBUG [c.c.n.v.VpcManagerImpl]
(Job-Executor-114:ctx-e492f4f3 ctx-8a897085) Shutting down vpc [VPC
[45-dvbr-autoF-1]
2015-10-15 12:48:09,660 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-114:ctx-e492f4f3 ctx-8a897085) Attempting to destroy router 470
2015-10-15 12:48:09,723 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-114:ctx-e492f4f3 ctx-8a897085) VM state transitted from :Running
to Stopping with event: StopRequestedvm's original host id: 9 new host id: 9
host id before state transition: 9
2015-10-15 12:48:09,729 DEBUG [c.c.a.t.Request] (Job-Executor-114:ctx-e492f4f3
ctx-8a897085) Seq 9-303894133: Sending { Cmd , MgmtId: 14038000394492, via:
9(10.110.2.3), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-470-VM","wait":0}}]
}
2015-10-15 12:48:09,729 DEBUG [c.c.a.t.Request] (Job-Executor-114:ctx-e492f4f3
ctx-8a897085) Seq 9-303894133: Executing: { Cmd , MgmtId: 14038000394492, via:
9(10.110.2.3), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-470-VM","wait":0}}]
}
{noformat}{noformat:titleBGColor=#F7D6C1|title=VpcCleanupTask}
2015-10-15 12:48:13,805 INFO [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Found 1 removed VPCs to cleanup
2015-10-15 12:48:13,805 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Cleaning up [VPC [45-dvbr-autoF-1]
2015-10-15 12:48:13,805 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Destroying vpc [VPC [45-dvbr-autoF-1]
2015-10-15 12:48:13,807 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Shutting down vpc [VPC [45-dvbr-autoF-1]
2015-10-15 12:48:13,808 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Attempting to destroy router 470
2015-10-15 12:48:13,811 WARN [o.a.c.f.j.AsyncJobExecutionContext]
(VpcChecker-1:ctx-c4bab66a) Job is executed without a context, setup psudo job
for the executing thread
2015-10-15 12:48:13,814 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) VM state transitted from :Stopping to Stopping with
event: StopRequestedvm's original host id: 9 new host id: 9 host id before
state transition: 9
2015-10-15 12:48:13,817 DEBUG [c.c.a.t.Request] (VpcChecker-1:ctx-c4bab66a) Seq
9-303894134: Sending { Cmd , MgmtId: 14038000394492, via: 9(10.110.2.3), Ver:
v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-470-VM","wait":0}}]
}
2015-10-15 12:48:13,817 DEBUG [c.c.a.t.Request] (VpcChecker-1:ctx-c4bab66a) Seq
9-303894134: Executing: { Cmd , MgmtId: 14038000394492, via: 9(10.110.2.3),
Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-470-VM","wait":0}}]
}
2015-10-15 12:48:21,476 DEBUG [c.c.a.t.Request] (VpcChecker-1:ctx-c4bab66a) Seq
9-303894134: Received: { Ans: , MgmtId: 14038000394492, via: 9, Ver: v1,
Flags: 10, { StopAnswer } }
2015-10-15 12:48:21,481 DEBUG [c.c.v.VirtualMachineManagerImpl]
(VpcChecker-1:ctx-c4bab66a) VM[DomainRouter|r-470-VM] is stopped on the host.
Proceeding to release resource held.
2015-10-15 12:48:21,485 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl]
(VpcChecker-1:ctx-c4bab66a) Releasing ip address for
reservationId=c0267898-2b17-48f1-840c-2be697a2b9bf, instance=577
2015-10-15 12:48:21,486 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(VpcChecker-1:ctx-c4bab66a) Released nic: NicProfile[577-470-null-null-null
2015-10-15 12:48:21,486 DEBUG [c.c.n.g.ControlNetworkGuru]
(VpcChecker-1:ctx-c4bab66a) Released nic: NicProfile[577-470-null-null-null
2015-10-15 12:48:21,487 DEBUG [c.c.v.VirtualMachineManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Successfully released network resources for the vm
VM[DomainRouter|r-470-VM]
2015-10-15 12:48:21,487 DEBUG [c.c.v.VirtualMachineManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Successfully released storage resources for the vm
VM[DomainRouter|r-470-VM]
2015-10-15 12:48:21,488 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) VM state transitted from :Stopping to Stopped with
event: OperationSucceededvm's original host id: 9 new host id: null host id
before state transition: 9
2015-10-15 12:48:21,491 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Hosts's actual total CPU: 26400 and CPU after
applying overprovisioning: 26400
2015-10-15 12:48:21,491 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Hosts's actual total RAM: 34330406912 and RAM after
applying overprovisioning: 34330406912
2015-10-15 12:48:21,491 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) release cpu from host: 9, old used: 2192,reserved:
0, actual total: 26400, total with overprovisioning: 26400; new used:
1192,reserved:1000; movedfromreserved: false,moveToReserveredtrue
2015-10-15 12:48:21,491 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) release mem from host: 9, old used:
2348810240,reserved: 0, total: 34330406912; new used:
1275068416,reserved:1073741824; movedfromreserved: false,moveToReserveredtrue
2015-10-15 12:48:21,494 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) VM state transitted from :Stopped to Expunging with
event: ExpungeOperationvm's original host id: 9 new host id: null host id
before state transition: null
2015-10-15 12:48:21,496 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Hosts's actual total CPU: 26400 and CPU after
applying overprovisioning: 26400
2015-10-15 12:48:21,497 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Hosts's actual total RAM: 34330406912 and RAM after
applying overprovisioning: 34330406912
2015-10-15 12:48:21,497 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) release cpu from host: 9, old used: 1192,reserved:
1000, actual total: 26400, total with overprovisioning: 26400; new used:
1192,reserved:0; movedfromreserved: true,moveToReserveredfalse
2015-10-15 12:48:21,497 DEBUG [c.c.c.CapacityManagerImpl]
(VpcChecker-1:ctx-c4bab66a) release mem from host: 9, old used:
1275068416,reserved: 1073741824, total: 34330406912; new used:
1275068416,reserved:0; movedfromreserved: true,moveToReserveredfalse
2015-10-15 12:48:21,497 DEBUG [c.c.v.VirtualMachineManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Destroying vm VM[DomainRouter|r-470-VM]
2015-10-15 12:48:21,497 DEBUG [c.c.v.VirtualMachineManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Cleaning up NICS
2015-10-15 12:48:21,498 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(VpcChecker-1:ctx-c4bab66a) Cleaning network for vm: 470
2015-10-15 12:48:21,502 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(VpcChecker-1:ctx-c4bab66a) Removed nic id=577
2015-10-15 12:48:21,503 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(VpcChecker-1:ctx-c4bab66a) Revoving nic secondary ip entry ...
2015-10-15 12:48:21,503 DEBUG [c.c.v.VirtualMachineManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Cleaning up hypervisor data structures (ex. SRs in
XenServer) for managed storage
2015-10-15 12:48:21,505 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(VpcChecker-1:ctx-c4bab66a) Cleaning storage for vm: 470
2015-10-15 12:48:21,525 DEBUG [c.c.a.t.Request] (VpcChecker-1:ctx-c4bab66a) Seq
9-303894135: Sending { Cmd , MgmtId: 14038000394492, via: 9(10.110.2.3), Ver:
v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"69c298cc-d0f0-4c0a-9aff-bb1041828470","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c1123a95-3e4c-3002-ac83-53446d117094","id":3,"poolType":"NetworkFilesystem","host":"10.110.6.1","path":"/export/primary153124","port":2049,"url":"NetworkFilesystem://10.110.6.1//export/primary153124/?ROLE=Primary&STOREUUID=c1123a95-3e4c-3002-ac83-53446d117094"}},"name":"ROOT-470","size":2621440000,"path":"ROOT-470-000001","volumeId":470,"vmName":"r-470-VM","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[c1123a953e4c3002ac8353446d117094]
r-470-VM/ROOT-470-000001.vmdk\"]}","format":"OVA","id":470,"deviceId":0,"hypervisorType":"VMware"}},"wait":0}}]
}
2015-10-15 12:48:21,526 DEBUG [c.c.a.t.Request] (VpcChecker-1:ctx-c4bab66a) Seq
9-303894135: Executing: { Cmd , MgmtId: 14038000394492, via: 9(10.110.2.3),
Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"69c298cc-d0f0-4c0a-9aff-bb1041828470","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c1123a95-3e4c-3002-ac83-53446d117094","id":3,"poolType":"NetworkFilesystem","host":"10.110.6.1","path":"/export/primary153124","port":2049,"url":"NetworkFilesystem://10.110.6.1//export/primary153124/?ROLE=Primary&STOREUUID=c1123a95-3e4c-3002-ac83-53446d117094"}},"name":"ROOT-470","size":2621440000,"path":"ROOT-470-000001","volumeId":470,"vmName":"r-470-VM","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[c1123a953e4c3002ac8353446d117094]
r-470-VM/ROOT-470-000001.vmdk\"]}","format":"OVA","id":470,"deviceId":0,"hypervisorType":"VMware"}},"wait":0}}]
}
2015-10-15 12:48:22,183 DEBUG [c.c.a.t.Request] (VpcChecker-1:ctx-c4bab66a) Seq
9-303894135: Received: { Ans: , MgmtId: 14038000394492, via: 9, Ver: v1,
Flags: 10, { Answer } }
2015-10-15 12:48:22,188 DEBUG [c.c.v.VirtualMachineManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Expunged VM[DomainRouter|r-470-VM]
2015-10-15 12:48:22,189 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Vpc [VPC [45-dvbr-autoF-1] has been shutdown
succesfully
2015-10-15 12:48:22,555 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Vpc [VPC [45-dvbr-autoF-1] has been shutdown
succesfully
2015-10-15 12:48:22,555 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Cleaning up resources for vpc id=45
2015-10-15 12:48:22,555 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Cleaning up existed site to site VPN connections
2015-10-15 12:48:22,555 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Cleaning up existed site to site VPN gateways
2015-10-15 12:48:22,556 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Releasing ips for vpc id=45 as a part of vpc cleanup
2015-10-15 12:48:22,556 DEBUG [c.c.n.IpAddressManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Revoking all Firewallrules as a part of public IP
id=8 release...
2015-10-15 12:48:22,558 DEBUG [c.c.n.f.FirewallManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Releasing 0 firewall rules for ip id=8
2015-10-15 12:48:22,559 DEBUG [c.c.n.f.FirewallManagerImpl]
(VpcChecker-1:ctx-c4bab66a) There are no firewall rules to apply
2015-10-15 12:48:22,559 DEBUG [c.c.n.f.FirewallManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Successfully released firewall rules for ip id=8
and # of rules now = 0
2015-10-15 12:48:22,560 DEBUG [c.c.n.IpAddressManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Revoking all PortForwarding/StaticNat rules as a
part of public IP id=8 release...
2015-10-15 12:48:22,561 DEBUG [c.c.n.r.RulesManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Releasing 0 port forwarding rules for ip id=8
2015-10-15 12:48:22,561 DEBUG [c.c.n.r.RulesManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Releasing 0 static nat rules for ip id=8
2015-10-15 12:48:22,562 DEBUG [c.c.n.r.RulesManagerImpl]
(VpcChecker-1:ctx-c4bab66a) There are no port forwarding rules to apply for ip
id=8
2015-10-15 12:48:22,562 DEBUG [c.c.n.r.RulesManagerImpl]
(VpcChecker-1:ctx-c4bab66a) There are no static nat rules to apply for ip id=8
2015-10-15 12:48:22,563 DEBUG [c.c.n.r.RulesManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Source ip id=Ip[10.110.240.8-1] is not one to one
nat
2015-10-15 12:48:22,564 DEBUG [c.c.n.r.RulesManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Successfully released rules for ip id=8 and # of
rules now = 0
2015-10-15 12:48:22,564 DEBUG [c.c.n.IpAddressManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Revoking all LoadBalancing rules as a part of
public IP id=8 release...
2015-10-15 12:48:22,564 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Found 0 lb rules to cleanup
2015-10-15 12:48:22,564 DEBUG [c.c.n.IpAddressManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Cleaning up remote access vpns as a part of public
IP id=8 release...
2015-10-15 12:48:22,565 DEBUG [c.c.n.v.RemoteAccessVpnManagerImpl]
(VpcChecker-1:ctx-c4bab66a) there are no Remote access vpns for public ip
address id=8
2015-10-15 12:48:22,570 DEBUG [c.c.n.IpAddressManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Releasing ip id=8; sourceNat = false
2015-10-15 12:48:22,570 DEBUG [c.c.n.IpAddressManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Released a public ip id=8
2015-10-15 12:48:22,570 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Released ip addresses for vpc id=45 as a part of
cleanup vpc process
2015-10-15 12:48:22,571 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Found 0 to revoke for the vpc 45
2015-10-15 12:48:22,574 DEBUG [c.c.n.v.VpcManagerImpl]
(VpcChecker-1:ctx-c4bab66a) Vpc [VPC [45-dvbr-autoF-1] is destroyed succesfully
{noformat}{noformat:titleBGColor=#FFFFCE|title=DeleteVPC}
2015-10-15 12:48:23,057 DEBUG [c.c.a.t.Request] (Job-Executor-114:ctx-e492f4f3
ctx-8a897085) Seq 9-303894133: Received: { Ans: , MgmtId: 14038000394492, via:
9, Ver: v1, Flags: 10, { StopAnswer } }
2015-10-15 12:48:23,057 WARN [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-114:ctx-e492f4f3 ctx-8a897085) Unable to stop vm
VM[DomainRouter|r-470-VM]
2015-10-15 12:48:23,062 DEBUG [c.c.v.d.VMInstanceDaoImpl]
(Job-Executor-114:ctx-e492f4f3 ctx-8a897085) Unable to update
VM[DomainRouter|r-470-VM]: DB Data={Host=null; State=Destroyed; updated=6;
time=Thu Oct 15 12:48:21 PDT 2015} New Data: {Host=9; State=Running; updated=5;
time=Thu Oct 15 12:48:21 PDT 2015} Stale Data: {Host=9; State=Stopping;
updated=4; time=Thu Oct 15 12:48:09 PDT 2015}
2015-10-15 12:48:23,109 ERROR [c.c.a.ApiAsyncJobDispatcher]
(Job-Executor-114:ctx-e492f4f3) Unexpected exception while executing
org.apache.cloudstack.api.command.user.vpc.DeleteVPCCmd
2015-10-15 12:48:23,110 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-114:ctx-e492f4f3) Complete async job-3374, jobStatus: FAILED,
resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable
to stop VM[DomainRouter|r-470-VM]"}
2015-10-15 12:48:23,149 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Job-Executor-114:ctx-e492f4f3) Done executing
org.apache.cloudstack.api.command.user.vpc.DeleteVPCCmd for job-3374
2015-10-15 12:48:23,183 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Job-Executor-114:ctx-e492f4f3) Remove job-3374 from job monitoring
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
