Abhinav Roy created CLOUDSTACK-3232:
---------------------------------------
Summary: [N-tiers][Internal LB for VPC tiers] Creation of
InternalLB VM is failing on vmware Host.
Key: CLOUDSTACK-3232
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3232
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Network Controller
Affects Versions: 4.2.0
Reporter: Abhinav Roy
Assignee: Alena Prokharchyk
Priority: Critical
Fix For: 4.2.0
Steps :
======================
1. Create VPC.
2. Create a tier in the VPC with InternalLB offering.
3. Deploy VMs in that tier , v1 and v2
4. Create an Internal LB rule in that tier, ILB1
5. Assign v1 and v2 to the the ILB1
Expected behaviour :
======================
Internal LB VM should be created and the VMs should be assigned to the LB rule.
Observed behaviour:
=====================
The creation of Internal LB VM fails with
2013-06-27 16:05:02,727 DEBUG [agent.transport.Request]
(Job-Executor-26:job-25) Seq 3-1841299569: Received: { Ans: , MgmtId:
90310994128556, via: 3, Ver: v1, Flags: 10, { StartAnswer } }
2013-06-27 16:05:02,739 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-25) The guru did not like the answers so stopping
VM[InternalLoadBalancerVm|b-49-VM]
2013-06-27 16:05:02,744 DEBUG [agent.transport.Request]
(Job-Executor-26:job-25) Seq 3-1841299571: Sending { Cmd , MgmtId:
90310994128556, via: 3, Ver: v1, Flags: 100011,
[{"StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"b-49-VM","wait":0}}]
}
2013-06-27 16:05:02,744 DEBUG [agent.transport.Request]
(Job-Executor-26:job-25) Seq 3-1841299571: Executing: { Cmd , MgmtId:
90310994128556, via: 3, Ver: v1, Flags: 100011,
[{"StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"b-49-VM","wait":0}}]
}
2013-06-27 16:05:02,745 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-356:null) Seq 3-1841299571: Executing request
2013-06-27 16:05:02,745 INFO [vmware.resource.VmwareResource]
(DirectAgent-356:10.102.192.17) Executing resource StopCommand:
{"isProxy":false,"executeInSequence":false,"vmName":"b-49-VM","wait":0}
2013-06-27 16:05:02,745 DEBUG [vmware.mo.HostMO]
(DirectAgent-356:10.102.192.17) find VM b-49-VM on host
2013-06-27 16:05:02,745 DEBUG [vmware.mo.HostMO]
(DirectAgent-356:10.102.192.17) load VM cache on host
2013-06-27 16:05:04,912 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
===START=== 10.144.6.28 -- GET
command=queryAsyncJobResult&jobId=803773d7-7d65-4464-9c95-847e41b15543&response=json&sessionkey=iGSGzjf6v05C0oFB%2BIEx9hJF%2BY0%3D&_=1372329135490
2013-06-27 16:05:04,934 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
===END=== 10.144.6.28 -- GET
command=queryAsyncJobResult&jobId=803773d7-7d65-4464-9c95-847e41b15543&response=json&sessionkey=iGSGzjf6v05C0oFB%2BIEx9hJF%2BY0%3D&_=1372329135490
2013-06-27 16:05:06,699 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-356:null) Seq 3-1841299571: Response Received:
2013-06-27 16:05:06,700 DEBUG [agent.transport.Request] (DirectAgent-356:null)
Seq 3-1841299571: Processing: { Ans: , MgmtId: 90310994128556, via: 3, Ver:
v1, Flags: 10, [{"StopAnswer":{"vncPort":0,"result":true,"details":"Stop VM
b-49-VM Succeed","wait":0}}] }
2013-06-27 16:05:06,700 DEBUG [agent.transport.Request]
(Job-Executor-26:job-25) Seq 3-1841299571: Received: { Ans: , MgmtId:
90310994128556, via: 3, Ver: v1, Flags: 10, { StopAnswer } }
2013-06-27 16:05:06,700 DEBUG [agent.manager.AgentManagerImpl]
(Job-Executor-26:job-25) Details from executing class
com.cloud.agent.api.StopCommand: Stop VM b-49-VM Succeed
2013-06-27 16:05:06,700 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-25) Failed to start instance
VM[InternalLoadBalancerVm|b-49-VM]
com.cloud.utils.exception.ExecutionException: Unable to start
VM[InternalLoadBalancerVm|b-49-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:910)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:556)
at
org.apache.cloudstack.network.lb.InternalLoadBalancerVMManagerImpl.startInternalLbVm(InternalLoadBalancerVMManagerImpl.java:846)
at
org.apache.cloudstack.network.lb.InternalLoadBalancerVMManagerImpl.startInternalLbVms(InternalLoadBalancerVMManagerImpl.java:605)
at
org.apache.cloudstack.network.lb.InternalLoadBalancerVMManagerImpl.deployInternalLbVm(InternalLoadBalancerVMManagerImpl.java:589)
at
org.apache.cloudstack.network.element.InternalLoadBalancerElement.applyLBRules(InternalLoadBalancerElement.java:346)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLbRules(LoadBalancingRulesManagerImpl.java:1518)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLbRules(LoadBalancingRulesManagerImpl.java:2056)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLoadBalancerRules(LoadBalancingRulesManagerImpl.java:1555)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLoadBalancerConfig(LoadBalancingRulesManagerImpl.java:1475)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.assignToLoadBalancer(LoadBalancingRulesManagerImpl.java:1006)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.loadbalancer.AssignToLoadBalancerRuleCmd.execute(AssignToLoadBalancerRuleCmd.java:100)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-06-27 16:05:06,707 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-25) Cleaning up resources for the vm
VM[InternalLoadBalancerVm|b-49-VM] in Starting state
2013-06-27 16:05:06,709 DEBUG [agent.transport.Request]
(Job-Executor-26:job-25) Seq 3-1841299572: Sending { Cmd , MgmtId:
90310994128556, via: 3, Ver: v1, Flags: 100011,
[{"StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"b-49-VM","wait":0}}]
}
2013-06-27 16:05:06,710 DEBUG [agent.transport.Request]
(Job-Executor-26:job-25) Seq 3-1841299572: Executing: { Cmd , MgmtId:
90310994128556, via: 3, Ver: v1, Flags: 100011,
[{"StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"b-49-VM","wait":0}}]
}
2013-06-27 16:05:06,710 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-357:null) Seq 3-1841299572: Executing request
2013-06-27 16:05:06,710 INFO [vmware.resource.VmwareResource]
(DirectAgent-357:10.102.192.17) Executing resource StopCommand:
{"isProxy":false,"executeInSequence":false,"vmName":"b-49-VM","wait":0}
2013-06-27 16:05:06,710 DEBUG [vmware.mo.HostMO]
(DirectAgent-357:10.102.192.17) find VM b-49-VM on host
2013-06-27 16:05:06,710 DEBUG [vmware.mo.HostMO]
(DirectAgent-357:10.102.192.17) load VM cache on host
2013-06-27 16:05:06,751 INFO [vmware.resource.VmwareResource]
(DirectAgent-357:10.102.192.17) VM b-49-VM is already in stopped state
2013-06-27 16:05:06,751 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-357:null) Seq 3-1841299572: Response Received:
2013-06-27 16:05:06,752 DEBUG [agent.transport.Request] (DirectAgent-357:null)
Seq 3-1841299572: Processing: { Ans: , MgmtId: 90310994128556, via: 3, Ver:
v1, Flags: 10, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM b-49-VM
is already in stopped state","wait":0}}] }
2013-06-27 16:05:06,752 DEBUG [agent.transport.Request]
(Job-Executor-26:job-25) Seq 3-1841299572: Received: { Ans: , MgmtId:
90310994128556, via: 3, Ver: v1, Flags: 10, { StopAnswer } }
2013-06-27 16:05:06,758 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-26:job-25) Service SecurityGroup is not supported in the network
id=206
2013-06-27 16:05:06,767 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking JuniperSRX to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,767 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking Netscaler to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,767 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking F5BigIP to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,767 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking CiscoNexus1000vVSM to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,767 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking CiscoVNMC to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,767 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking NiciraNvp to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,767 DEBUG [network.element.NiciraNvpElement]
(Job-Executor-26:job-25) Checking if NiciraNvpElement can handle service
Connectivity on network TIER-2 InternalLB
2013-06-27 16:05:06,767 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking VirtualRouter to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,768 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking Ovs to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,768 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking SecurityGroupProvider to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,768 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking VpcVirtualRouter to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,768 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-26:job-25) Asking InternalLbVm to release
Nic[181-49-f3643a22-0876-4c8f-a04b-91d357141002-10.1.5.136]
2013-06-27 16:05:06,781 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-25) Successfully released network resources for the vm
VM[InternalLoadBalancerVm|b-49-VM]
2013-06-27 16:05:06,781 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-26:job-25) Successfully cleanued up resources for the vm
VM[InternalLoadBalancerVm|b-49-VM] in Starting state
2013-06-27 16:05:06,796 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-25) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 3
2013-06-27 16:05:06,805 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-25) Hosts's actual total CPU: 9572 and CPU after applying
overprovisioning: 9572
2013-06-27 16:05:06,805 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-25) Hosts's actual total RAM: 17166258176 and RAM after
applying overprovisioning: 17166258176
2013-06-27 16:05:06,805 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-25) release cpu from host: 3, old used: 3256,reserved: 0,
actual total: 9572, total with overprovisioning: 9572; new used:
3000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-27 16:05:06,805 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-26:job-25) release mem from host: 3, old used:
2818572288,reserved: 0, total: 17166258176; new used: 2684354560,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2013-06-27 16:05:06,813 WARN [network.lb.LoadBalancingRulesManagerImpl]
(Job-Executor-26:job-25) Unable to apply the load balancer config because
resource is unavaliable.
com.cloud.exception.AgentUnavailableException: Resource [Host:3] is
unreachable: Host 3: Unable to start instance due to Unable to start
VM[InternalLoadBalancerVm|b-49-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:943)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:556)
at
org.apache.cloudstack.network.lb.InternalLoadBalancerVMManagerImpl.startInternalLbVm(InternalLoadBalancerVMManagerImpl.java:846)
at
org.apache.cloudstack.network.lb.InternalLoadBalancerVMManagerImpl.startInternalLbVms(InternalLoadBalancerVMManagerImpl.java:605)
at
org.apache.cloudstack.network.lb.InternalLoadBalancerVMManagerImpl.deployInternalLbVm(InternalLoadBalancerVMManagerImpl.java:589)
at
org.apache.cloudstack.network.element.InternalLoadBalancerElement.applyLBRules(InternalLoadBalancerElement.java:346)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLbRules(LoadBalancingRulesManagerImpl.java:1518)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLbRules(LoadBalancingRulesManagerImpl.java:2056)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLoadBalancerRules(LoadBalancingRulesManagerImpl.java:1555)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.applyLoadBalancerConfig(LoadBalancingRulesManagerImpl.java:1475)
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.assignToLoadBalancer(LoadBalancingRulesManagerImpl.java:1006)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.loadbalancer.AssignToLoadBalancerRuleCmd.execute(AssignToLoadBalancerRuleCmd.java:100)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to start
VM[InternalLoadBalancerVm|b-49-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:910)
... 29 more
2013-06-27 16:05:06,833 ERROR [cloud.async.AsyncJobManagerImpl]
(Job-Executor-26:job-25) Unexpected exception while executing
org.apache.cloudstack.api.command.user.loadbalancer.AssignToLoadBalancerRuleCmd
com.cloud.utils.exception.CloudRuntimeException: Failed to add specified
loadbalancerruleid for vms [48]
at
com.cloud.network.lb.LoadBalancingRulesManagerImpl.assignToLoadBalancer(LoadBalancingRulesManagerImpl.java:1029)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.loadbalancer.AssignToLoadBalancerRuleCmd.execute(AssignToLoadBalancerRuleCmd.java:100)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-06-27 16:05:06,835 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-26:job-25) Complete async job-25, jobStatus: 2, resultCode: 530,
result: Error Code: 530 Error text: Failed to add specified loadbalancerruleid
for vms [48]
2013-06-27 16:05:06,873 DEBUG [cloud.async.SyncQueueManagerImpl]
(Job-Executor-26:job-25) Sync queue (1) is currently empty
2013-06-27 16:05:06,965 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-10:null) SeqA 5-149: Processing Seq 5-149: { Cmd ,
MgmtId: -1, via: 5, Ver: v1, Flags: 11,
[{"ConsoleProxyLoadReportCommand":{"_proxyVmId":44,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2013-06-27 16:05:06,970 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-10:null) SeqA 5-149: Sending Seq 5-149: { Ans: , MgmtId:
90310994128556, via: 5, Ver: v1, Flags: 100010,
[{"AgentControlAnswer":{"result":true,"wait":0}}] }
2013-06-27 16:05:07,909 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null)
===START=== 10.144.6.28 -- GET
command=queryAsyncJobResult&jobId=803773d7-7d65-4464-9c95-847e41b15543&response=json&sessionkey=iGSGzjf6v05C0oFB%2BIEx9hJF%2BY0%3D&_=1372329138489
2013-06-27 16:05:07,923 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-15:null) Async job-25 completed
2013-06-27 16:05:07,929 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null)
===END=== 10.144.6.28 -- GET
command=queryAsyncJobResult&jobId=803773d7-7d65-4464-9c95-847e41b15543&response=json&sessionkey=iGSGzjf6v05C0oFB%2BIEx9hJF%2BY0%3D&_=1372329138489
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
