[ https://issues.apache.org/jira/browse/CLOUDSTACK-3232?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Venkata Siva Vijayendra Bhamidipati reassigned CLOUDSTACK-3232: --------------------------------------------------------------- Assignee: Venkata Siva Vijayendra Bhamidipati (was: Alena Prokharchyk) > [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: Venkata Siva Vijayendra Bhamidipati > Priority: Critical > Fix For: 4.2.0 > > Attachments: DB_DUMP.sql, management-server.log > > > 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