Sanjeev N created CLOUDSTACK-3302:
-------------------------------------
Summary: [Multiple_IP_Ranges][VmWare] VM deployement failed due to
dnsmasq configuration issue in case of multiple subnets in a vlan
Key: CLOUDSTACK-3302
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3302
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Management Server
Affects Versions: 4.2.0
Environment: Latest build from master_6-17-stable branch
Reporter: Sanjeev N
Priority: Blocker
Fix For: 4.2.0
Attachments: management-server.rar
[Multiple_IP_Ranges][VmWare] VM deployement failed due to dnsmasq configuration
issue in case of multiple subnets in a vlan
Steps to Reproduce:
=================
1.Bring up CS in advanced zone with vmware cluster
2.Create a shared network and add IP range
3.Deploy vms so that all ip ranges should be exhausted from the IP range
4.And another IP range in a new CIDR in the same shared network created at step2
5.Deploy guest vm
Expected Result:
==============
1.Deploying guest vm at step5 should create ip alias on VR, should regenerate
dnsmasq.conf file with new CIDR information
Actual Result:
===========
Since regenerating dnsmasq.conf failed, vm could not get the IP Address from
the new CIDR using dhcp service from VR.
Observations:
============
Following is the log snippet from management server log file:
2013-07-01 11:57:11,214 DEBUG [agent.transport.Request]
(Job-Executor-4:job-176) Seq 10-134086950: Sending { Cmd , MgmtId:
7332683579487, via: 10, Ver: v1, Flags: 100011,
[{"routing.CreateIpAliasCommand":{"routerip":"10.147.33.11","ipAliasTOs":[{"routerip":"10.147.33.132","netmask":"255.255.255.192","alias_count":"44"}],"accessDetails":{"router.guest.ip":"10.147.33.11","zone.network.type":"Advanced","router.name":"r-34-VM","router.ip":"10.147.40.249"},"wait":0}},{"routing.DnsMasqConfigCommand":{"domain":"cs1cloud.internal","dns1":"10.103.128.16","internal_dns1":"10.103.128.16","dnsmasqTOs":[{"routerIp":"10.147.33.11","gateway":"10.147.33.1","netmask":"255.255.255.128","startIpOfSubnet":"10.147.33.1"},{"routerIp":"10.147.33.132","gateway":"10.147.33.129","netmask":"255.255.255.192","startIpOfSubnet":"10.147.33.129"}],"accessDetails":{"router.guest.ip":"10.147.33.11","zone.network.type":"Advanced","router.name":"r-34-VM","router.ip":"10.147.40.249"},"wait":0}}]
}
2013-07-01 11:57:11,215 DEBUG [agent.transport.Request]
(Job-Executor-4:job-176) Seq 10-134086950: Executing: { Cmd , MgmtId:
7332683579487, via: 10, Ver: v1, Flags: 100011,
[{"routing.CreateIpAliasCommand":{"routerip":"10.147.33.11","ipAliasTOs":[{"routerip":"10.147.33.132","netmask":"255.255.255.192","alias_count":"44"}],"accessDetails":{"router.guest.ip":"10.147.33.11","zone.network.type":"Advanced","router.name":"r-34-VM","router.ip":"10.147.40.249"},"wait":0}},{"routing.DnsMasqConfigCommand":{"domain":"cs1cloud.internal","dns1":"10.103.128.16","internal_dns1":"10.103.128.16","dnsmasqTOs":[{"routerIp":"10.147.33.11","gateway":"10.147.33.1","netmask":"255.255.255.128","startIpOfSubnet":"10.147.33.1"},{"routerIp":"10.147.33.132","gateway":"10.147.33.129","netmask":"255.255.255.192","startIpOfSubnet":"10.147.33.129"}],"accessDetails":{"router.guest.ip":"10.147.33.11","zone.network.type":"Advanced","router.name":"r-34-VM","router.ip":"10.147.40.249"},"wait":0}}]
}
2013-07-01 11:57:11,216 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-171:null) Seq 10-134086950: Executing request
2013-07-01 11:57:11,216 INFO [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Executing createIpAlias command:
{"routerip":"10.147.33.11","ipAliasTOs":[{"routerip":"10.147.33.132","netmask":"255.255.255.192","alias_count":"44"}],"accessDetails":{"router.guest.ip":"10.147.33.11","zone.network.type":"Advanced","router.name":"r-34-VM","router.ip":"10.147.40.249"},"wait":0}
2013-07-01 11:57:11,217 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Run command on domR 10.147.40.249,
/root/createIpAlias 10.147.40.249 44:10.147.33.132:255.255.255.192-
2013-07-01 11:57:11,221 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Use router's private IP for SSH control. IP :
10.147.40.249
2013-07-01 11:57:11,651 INFO [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) createIpAlias command on domain router
10.147.40.249 completed
2013-07-01 11:57:11,652 INFO [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Executing dnsmasqConfig command:
{"domain":"cs1cloud.internal","dns1":"10.103.128.16","internal_dns1":"10.103.128.16","dnsmasqTOs":[{"routerIp":"10.147.33.11","gateway":"10.147.33.1","netmask":"255.255.255.128","startIpOfSubnet":"10.147.33.1"},{"routerIp":"10.147.33.132","gateway":"10.147.33.129","netmask":"255.255.255.192","startIpOfSubnet":"10.147.33.129"}],"accessDetails":{"router.guest.ip":"10.147.33.11","zone.network.type":"Advanced","router.name":"r-34-VM","router.ip":"10.147.40.249"},"wait":0}
2013-07-01 11:57:11,653 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Use router's private IP for SSH control. IP :
10.147.40.249
2013-07-01 11:57:11,653 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Run command on domR 10.147.40.249,
/root/dnsmasq.sh config file at/tmp/10-147-40-249.cfg
2013-07-01 11:57:11,954 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
===START=== 10.146.0.20 -- GET
command=queryAsyncJobResult&jobId=a965b17c-732e-429f-b36d-e4a403f94d7c&response=json&sessionkey=pVk9g8oM5ECIt%2B5boDObusoNYLU%3D&_=1372674520915
2013-07-01 11:57:11,996 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
===END=== 10.146.0.20 -- GET
command=queryAsyncJobResult&jobId=a965b17c-732e-429f-b36d-e4a403f94d7c&response=json&sessionkey=pVk9g8oM5ECIt%2B5boDObusoNYLU%3D&_=1372674520915
2013-07-01 11:57:12,169 ERROR [utils.ssh.SshHelper]
(DirectAgent-171:10.147.40.18) SSH execution of command
scp/tmp/10-147-40-249.cfg/root/dnsmasq.sh has an error status code in return.
result output: bash: scp/tmp/10-147-40-249.cfg/root/dnsmasq.sh: No such file or
directory
2013-07-01 11:57:12,172 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Run command on domain router 10.147.40.249,
/root/dnsmasq.sh
2013-07-01 11:57:12,172 ERROR [vmware.resource.VmwareResource]
(DirectAgent-171:10.147.40.18) Unable to copy dnsmasq configuration file
2013-07-01 11:57:12,414 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-171:null) Seq 10-134086950: Response Received:
2013-07-01 11:57:12,414 DEBUG [agent.transport.Request] (DirectAgent-171:null)
Seq 10-134086950: Processing: { Ans: , MgmtId: 7332683579487, via: 10, Ver:
v1, Flags: 10,
[{"Answer":{"result":true,"wait":0}},{"Answer":{"result":false,"details":"dnsmasq
config failed due to uanble to copy dnsmasq configuration file","wait":0}}] }
2013-07-01 11:57:12,414 DEBUG [agent.transport.Request]
(Job-Executor-4:job-176) Seq 10-134086950: Received: { Ans: , MgmtId:
7332683579487, via: 10, Ver: v1, Flags: 10, { Answer, Answer } }
2013-07-01 11:57:12,530 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-4:job-176) Failed to start instance VM[User|z3-s2-passwd]
com.cloud.utils.exception.CloudRuntimeException: failed to configure ip alias
on the router as a part of dhcp config
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.configDhcpForSubnet(VirtualNetworkApplianceManagerImpl.java:2834)
at
com.cloud.network.element.VirtualRouterElement.configDhcpSupportForSubnet(VirtualRouterElement.java:870)
at
com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:1978)
at
com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2093)
at
com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2034)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:848)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:556)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:243)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3313)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2851)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2837)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
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:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-07-01 11:57:12,539 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-4:job-176) Cleaning up resources for the vm VM[User|z3-s2-passwd]
in Starting state
2013-07-01 11:57:12,543 DEBUG [agent.transport.Request]
(Job-Executor-4:job-176) Seq 10-134086951: Sending { Cmd , MgmtId:
7332683579487, via: 10, Ver: v1, Flags: 100011,
[{"StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-46-VM","wait":0}}]
}
2013-07-01 11:57:12,543 DEBUG [agent.transport.Request]
(Job-Executor-4:job-176) Seq 10-134086951: Executing: { Cmd , MgmtId:
7332683579487, via: 10, Ver: v1, Flags: 100011,
[{"StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-46-VM","wait":0}}]
}
2013-07-01 11:57:12,543 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-172:null) Seq 10-134086951: Executing request
2013-07-01 11:57:12,544 INFO [vmware.resource.VmwareResource]
(DirectAgent-172:10.147.40.18) Executing resource StopCommand:
{"isProxy":false,"executeInSequence":false,"vmName":"i-2-46-VM","wait":0}
2013-07-01 11:57:12,544 DEBUG [vmware.mo.HostMO] (DirectAgent-172:10.147.40.18)
find VM i-2-46-VM on host
2013-07-01 11:57:12,544 DEBUG [vmware.mo.HostMO] (DirectAgent-172:10.147.40.18)
load VM cache on host
2013-07-01 11:57:12,555 INFO [vmware.resource.VmwareResource]
(DirectAgent-172:10.147.40.18) VM i-2-46-VM is no longer in vSphere
2013-07-01 11:57:12,555 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-172:null) Seq 10-134086951: Response Received:
2013-07-01 11:57:12,556 DEBUG [agent.transport.Request] (DirectAgent-172:null)
Seq 10-134086951: Processing: { Ans: , MgmtId: 7332683579487, via: 10, Ver:
v1, Flags: 10, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM
i-2-46-VM is no longer in vSphere","wait":0}}] }
2013-07-01 11:57:12,555 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-172:null) Seq 10-134086951: Response Received:
2013-07-01 11:57:12,556 DEBUG [agent.transport.Request] (DirectAgent-172:null)
Seq 10-134086951: Processing: { Ans: , MgmtId: 7332683579487, via: 10, Ver:
v1, Flags: 10, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM
i-2-46-VM is no longer in vSphere","wait":0}}] }
2013-07-01 11:57:12,556 DEBUG [agent.transport.Request]
(Job-Executor-4:job-176) Seq 10-134086951: Received: { Ans: , MgmtId:
7332683579487, via: 10, Ver: v1, Flags: 10, { StopAnswer } }
2013-07-01 11:57:12,573 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-4:job-176) Changing active number of nics for network id=214 on -1
2013-07-01 11:57:12,578 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-4:job-176) Successfully released network resources for the vm
VM[User|z3-s2-passwd]
2013-07-01 11:57:12,578 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-4:job-176) Successfully cleanued up resources for the vm
VM[User|z3-s2-passwd] in Starting state
2013-07-01 11:57:12,596 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-4:job-176) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 10
2013-07-01 11:57:12,607 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-4:job-176) Hosts's actual total CPU: 9572 and CPU after applying
overprovisioning: 9572
2013-07-01 11:57:12,607 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-4:job-176) Hosts's actual total RAM: 17169539072 and RAM after
applying overprovisioning: 17169539072
2013-07-01 11:57:12,607 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-4:job-176) release cpu from host: 10, old used: 4000,reserved: 0,
actual total: 9572, total with overprovisioning: 9572; new used:
3500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-07-01 11:57:12,608 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-4:job-176) release mem from host: 10, old used:
4160749568,reserved: 0, total: 17169539072; new used: 3623878656,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2013-07-01 11:57:12,627 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-4:job-176) Destroying vm VM[User|z3-s2-passwd] as it failed to
create on Host with Id:null
2013-07-01 11:57:12,644 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 7-53479: Processing Seq 7-53479: { Cmd ,
MgmtId: -1, via: 7, Ver: v1, Flags: 11,
[{"ConsoleProxyLoadReportCommand":{"_proxyVmId":20,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2013-07-01 11:57:12,649 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-4:job-176) VM state transitted from :Stopped to Error with event:
OperationFailedToErrorvm's original host id: null new host id: null host id
before state transition: null
2013-07-01 11:57:12,650 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 7-53479: Sending Seq 7-53479: { Ans: ,
MgmtId: 7332683579487, via: 7, Ver: v1, Flags: 100010,
[{"AgentControlAnswer":{"result":true,"wait":0}}] }
2013-07-01 11:57:12,662 WARN [apache.cloudstack.alerts]
(Job-Executor-4:job-176) alertType:: 8 // dataCenterId:: 3 // podId:: 3 //
clusterId:: null // message:: Failed to deploy Vm with Id: 46, on Host with Id:
null
2013-07-01 11:57:12,668 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-1:null) SeqA 12-42620: Processing Seq 12-42620: { Cmd ,
MgmtId: -1, via: 12, Ver: v1, Flags: 11,
[{"ConsoleProxyLoadReportCommand":{"_proxyVmId":32,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2013-07-01 11:57:12,674 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-1:null) SeqA 12-42620: Sending Seq 12-42620: { Ans: ,
MgmtId: 7332683579487, via: 12, Ver: v1, Flags: 100010,
[{"AgentControlAnswer":{"result":true,"wait":0}}] }
2013-07-01 11:57:12,718 WARN [user.vm.DeployVMCmd] (Job-Executor-4:job-176)
Exception:
com.cloud.exception.AgentUnavailableException: Resource [Host:10] is
unreachable: Host 10: Unable to start instance due to failed to configure ip
alias on the router as a part of dhcp config
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:943)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:556)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:243)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3313)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2851)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2837)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
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:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
Caused by: com.cloud.utils.exception.CloudRuntimeException: failed to configure
ip alias on the router as a part of dhcp config
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.configDhcpForSubnet(VirtualNetworkApplianceManagerImpl.java:2834)
at
com.cloud.network.element.VirtualRouterElement.configDhcpSupportForSubnet(VirtualRouterElement.java:870)
at
com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:1978)
at
com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2093)
at
com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2034)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:848)
... 20 more
2013-07-01 11:57:12,720 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-4:job-176) Complete async job-176, jobStatus: 2, resultCode: 530,
result: Error Code: 534 Error text: Resource [Host:10] is unreachable: Host 10:
Unable to start instance due to failed to configure ip alias on the router as a
part of dhcp config
2013-07-01 11:57:14,085 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) VmStatsCollector is running...
2013-07-01 11:57:14,952 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
===START=== 10.146.0.20 -- GET
command=queryAsyncJobResult&jobId=a965b17c-732e-429f-b36d-e4a403f94d7c&response=json&sessionkey=pVk9g8oM5ECIt%2B5boDObusoNYLU%3D&_=1372674523929
2013-07-01 11:57:14,974 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-19:null) Async job-176 completed
--
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
