You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Abhinav Roy (JIRA)" <ji...@apache.org> on 2013/07/18 15:50:55 UTC

[jira] [Updated] (CLOUDSTACK-3232) [N-tiers][Internal LB for VPC tiers] Creation of InternalLB VM is failing on vmware Host.

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-3232?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Abhinav Roy updated CLOUDSTACK-3232:
------------------------------------

    Priority: Blocker  (was: Critical)
    
> [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: Blocker
>             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