Sanjeev N created CLOUDSTACK-5365:
-------------------------------------
Summary: [Hyper-V] VR's control IP is not accessible from mgmt
server, which results in VR start up failure
Key: CLOUDSTACK-5365
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5365
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Hypervisor Controller, Management Server
Affects Versions: 4.3.0
Environment: Build with commit
2d90ee469a047e8b42dd81f3723240f18b591d5e from 4.3
Zone: Advanced
Storage: Local for system vms ,cifs for guest and cifs for secondary
Hypervisor: Hyperv
Reporter: Sanjeev N
Priority: Blocker
Fix For: 4.3.0
[Hyper-V] VR's control IP is not accessible from mgmt server, which results in
VR start up failure
Steps to Reproduce:
================
1.Bring up CS in advanced zone with at-least one hyper-v host in the cluster
2.Register one cent os template
3.Try to deploy guest vm with the above template in an isolated network
Expected Result:
==============
VR and guest vm should come up in the isolated network successfully
Actual Result:
===========
VR failed to come up hence the guest vm deployment failed
Observations:
============
Initially VR booted up and configured with guest,control and public IP
addresses on eth0,eth1,eth2 inerfaces respectively.
As part of VR bring up process, mgmt server tried to ping/check the template
version on VR using its control IP to confirm the VR boot up. However mgmt
server failed to communicate with VRs control IP address. So it is stopping the
VR.
In another 4.3 setup I have added vmware cluster and tried the above scenario.
There mgmt server was able to communicate with VR on control ip address and VR
came up successfully.
Log snippet from agent log:
======================
2013-12-04 04:14:54,275 [14] INFO HypervResource.WmiCallsV2
[fcfffec6-3b06-4bda-b22c-afa6c2014803] - Started VM r-8-VM
2013-12-04 04:14:54,275 [14] INFO HypervResource.HypervResourceController
[fcfffec6-3b06-4bda-b22c-afa6c2014803] - {
"com.cloud.agent.api.StartAnswer": {
"result": true,
"details": null,
"vm": {
"id": 8,
"name": "r-8-VM",
"type": "DomainRouter",
"cpus": 1,
"minSpeed": 500,
"maxSpeed": 500,
"minRam": 134217728,
"maxRam": 134217728,
"arch": "i686",
"os": "Debian GNU/Linux 5.0 (32-bit)",
"bootArgs": " template=domP name=r-8-VM eth2ip=10.147.48.23
eth2mask=255.255.255.0 gateway=10.147.48.1 eth0ip=10.1.1.1
eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
eth1ip=10.147.40.238 eth1mask=255.255.254.0 type=router disable_rp_filter=true
dns1=10.140.50.6 dns2=",
"rebootOnCrash": false,
"enableHA": true,
"limitCpuUse": false,
"enableDynamicallyScaleVm": false,
"vncPassword": "33c76dca072011e6",
"params": {},
"uuid": "33b6472e-67cd-4aee-8556-b22d6e57d44b",
"disks": [
{
"data": {
"org.apache.cloudstack.storage.to.VolumeObjectTO": {
"uuid": "9c48b406-b424-4b77-ae37-37248b454d0f",
"volumeType": "ROOT",
"dataStore": {
"org.apache.cloudstack.storage.to.PrimaryDataStoreTO": {
"uuid": "20de3206-3585-3bb0-b536-a96b665df206-HypervResource",
"id": 2,
"poolType": "Filesystem",
"host": "10.147.40.14",
"path": "C:\\Users\\Public\\Documents\\Hyper-V\\Virtual Hard
Disks",
"port": 0,
"url":
"Filesystem://10.147.40.14/C:\\Users\\Public\\Documents\\Hyper-V\\Virtual Hard
Disks/?ROLE=Primary&STOREUUID=20de3206-3585-3bb0-b536-a96b665df206-HypervResource"
}
},
"name": "ROOT-8",
"size": 2101252608,
"volumeId": 8,
"vmName": "r-8-VM",
"accountId": 2,
"id": 8,
"deviceId": 0,
"hypervisorType": "Hyperv"
}
},
"diskSeq": 0,
"type": "ROOT",
"_details": {
"managed": "false",
"storagePort": "0",
"storageHost": "10.147.40.14",
"volumeSize": "2101252608"
}
}
],
"nics": [
{
"deviceId": 2,
"networkRateMbps": 200,
"defaultNic": true,
"uuid": "645d73f8-ea2b-4329-9946-140c12059805",
"ip": "10.147.48.23",
"netmask": "255.255.255.0",
"gateway": "10.147.48.1",
"mac": "06:7d:94:00:00:0d",
"dns1": "10.140.50.6",
"dns2": "",
"broadcastType": "Vlan",
"type": "Public",
"broadcastUri": "vlan://48",
"isolationUri": "vlan://48",
"isSecurityGroupEnabled": false
},
{
"deviceId": 0,
"networkRateMbps": 200,
"defaultNic": false,
"uuid": "223b14fa-88b5-4ed0-a804-d428d98205e0",
"ip": "10.1.1.1",
"netmask": "255.255.255.0",
"mac": "02:00:10:99:00:02",
"dns1": "10.140.50.6",
"dns2": "",
"broadcastType": "Vlan",
"type": "Guest",
"broadcastUri": "vlan://994",
"isolationUri": "vlan://994",
"isSecurityGroupEnabled": false
},
{
"deviceId": 1,
"networkRateMbps": -1,
"defaultNic": false,
"uuid": "80c827a3-4b5e-41eb-97f1-c829d2eff69a",
"ip": "10.147.40.238",
"netmask": "255.255.254.0",
"gateway": "10.147.40.1",
"mac": "02:00:6c:37:00:02",
"broadcastType": "Native",
"type": "Control",
"isSecurityGroupEnabled": false
}
]
},
"contextMap": {}
}
}
2013-12-04 04:16:54,359 [28] DEBUG HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - Got request to destroy vm r-8-VM
2013-12-04 04:16:54,370 [28] DEBUG HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - Stop VM r-8-VM (GUID
ED52939F-C0A0-4F30-954C-4EAE2A2F2B21)
2013-12-04 04:16:54,370 [28] INFO HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - Changing state of r-8-VM (GUID
ED52939F-C0A0-4F30-954C-4EAE2A2F2B21) to Disabled
2013-12-04 04:16:54,420 [28] INFO HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - In progress... 0% completed.
2013-12-04 04:16:55,428 [28] DEBUG HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - WMI job succeeded: Turning Off Virtual
Machine, Elapsed=00:00:00.1168150
2013-12-04 04:16:55,428 [28] INFO HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - Successfully changed vm state of
r-8-VM (GUID ED52939F-C0A0-4F30-954C-4EAE2A2F2B21 to requested state 3
2013-12-04 04:16:55,429 [28] DEBUG HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - Remove associated switch ports for VM
r-8-VM (GUID ED52939F-C0A0-4F30-954C-4EAE2A2F2B21)
2013-12-04 04:16:55,452 [28] DEBUG HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - Delete VM r-8-VM (GUID
ED52939F-C0A0-4F30-954C-4EAE2A2F2B21)
2013-12-04 04:16:55,498 [28] INFO HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - In progress... 0% completed.
2013-12-04 04:16:56,505 [28] DEBUG HypervResource.WmiCallsV2
[60be431f-50c8-4b52-a490-aba947e0f9a7] - WMI job succeeded: Destroying Virtual
Machine, Elapsed=00:00:00.0334240
2013-12-04 04:16:56,512 [28] INFO HypervResource.HypervResourceController
[60be431f-50c8-4b52-a490-aba947e0f9a7] - {
"com.cloud.agent.api.StopAnswer": {
"result": true,
"details": null,
"vm": null,
"contextMap": {}
}
}
2013-12-04 04:16:56,540 [27] INFO HypervResource.HypervResourceController
[d0d8d414-b428-4d2d-8ccb-377792569698] - com.cloud.agent.api.StopCommand{
"isProxy": false,
"executeInSequence": false,
"vmName": "r-8-VM",
"contextMap": {},
"wait": 0
}
2013-12-04 04:16:56,541 [27] DEBUG HypervResource.WmiCallsV2
[d0d8d414-b428-4d2d-8ccb-377792569698] - Got request to destroy vm r-8-VM
2013-12-04 04:16:56,548 [27] DEBUG HypervResource.WmiCallsV2
[d0d8d414-b428-4d2d-8ccb-377792569698] - VM r-8-VM already destroyed (or never
existed)
2013-12-04 04:16:56,549 [27] INFO HypervResource.HypervResourceController
[d0d8d414-b428-4d2d-8ccb-377792569698] - {
"com.cloud.agent.api.StopAnswer": {
"result": true,
"details": null,
"vm": null,
"contextMap": {}
}
}
Log snippet from mgmt server log file:
2013-12-04 12:24:03,005 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-15:ctx-3c4633d8) Run command on domR 10.147.40.232,
/opt/cloud/bin/get_template_version.sh
2013-12-04 12:24:03,005 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-15:ctx-3c4633d8) Use router's private IP for SSH control. IP :
10.147.40.232
2013-12-04 12:24:03,681 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-a42794db)
===START=== 10.146.0.134 -- GET
command=queryAsyncJobResult&jobId=90dbfeed-f357-47b9-9067-9c4ad34a1d33&response=json&sessionkey=uSpuIkackMpvWLrjIHS842Q1v4o%3D&_=1386158175162
2013-12-04 12:24:03,744 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-c350b288) VmStatsCollector is running...
2013-12-04 12:24:03,797 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-a42794db
ctx-e6c815dc) ===END=== 10.146.0.134 -- GET
command=queryAsyncJobResult&jobId=90dbfeed-f357-47b9-9067-9c4ad34a1d33&response=json&sessionkey=uSpuIkackMpvWLrjIHS842Q1v4o%3D&_=1386158175162
2013-12-04 12:25:03,008 ERROR [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-15:ctx-3c4633d8) GetDomRVersionCmd failed due to
java.net.SocketTimeoutException: The kexTimeout (60000 ms) expired.
java.net.SocketTimeoutException: The kexTimeout (60000 ms) expired.
at com.trilead.ssh2.Connection.connect(Connection.java:785)
at com.cloud.utils.ssh.SshHelper.sshExecute(SshHelper.java:132)
at com.cloud.utils.ssh.SshHelper.sshExecute(SshHelper.java:37)
at
com.cloud.hypervisor.hyperv.resource.HypervDirectConnectResource.execute(HypervDirectConnectResource.java:1408)
at
com.cloud.hypervisor.hyperv.resource.HypervDirectConnectResource.executeRequest(HypervDirectConnectResource.java:377)
at
com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
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-12-04 12:25:03,016 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-15:ctx-3c4633d8) Seq 1-1576731025: Cancelling because one of the
answers is false and it is stop on error.
2013-12-04 12:25:03,016 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-15:ctx-3c4633d8) Seq 1-1576731025: Response Received:
2013-12-04 12:25:03,018 DEBUG [c.c.a.t.Request] (DirectAgent-15:ctx-3c4633d8)
Seq 1-1576731025: Processing: { Ans: , MgmtId: 7332683579487, via: 1, Ver: v1,
Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":8,"name":"r-8-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"arch":"i686","os":"Debian
GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-8-VM
eth2ip=10.147.48.23 eth2mask=255.255.255.0 gateway=10.147.48.1 eth0ip=10.1.1.1
eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
eth1ip=10.147.40.232 eth1mask=255.255.254.0 type=router disable_rp_filter=true
dns1=10.140.50.6
dns2=","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"33c76dca072011e6","params":{},"uuid":"33b6472e-67cd-4aee-8556-b22d6e57d44b","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"9c48b406-b424-4b77-ae37-37248b454d0f","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"20de3206-3585-3bb0-b536-a96b665df206-HypervResource","id":2,"poolType":"Filesystem","host":"10.147.40.14","path":"C:\\Users\\Public\\Documents\\Hyper-V\\Virtual
Hard
Disks","port":0,"url":"Filesystem://10.147.40.14/C:\\Users\\Public\\Documents\\Hyper-V\\Virtual
Hard
Disks/?ROLE=Primary&STOREUUID=20de3206-3585-3bb0-b536-a96b665df206-HypervResource"}},"name":"ROOT-8","size":2101252608,"volumeId":8,"vmName":"r-8-VM","accountId":2,"id":8,"deviceId":0,"hypervisorType":"Hyperv"}},"diskSeq":0,"type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"10.147.40.14","volumeSize":"2101252608"}}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"645d73f8-ea2b-4329-9946-140c12059805","ip":"10.147.48.23","netmask":"255.255.255.0","gateway":"10.147.48.1","mac":"06:7d:94:00:00:0d","dns1":"10.140.50.6","dns2":"","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://48","isolationUri":"vlan://48","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":200,"defaultNic":false,"uuid":"223b14fa-88b5-4ed0-a804-d428d98205e0","ip":"10.1.1.1","netmask":"255.255.255.0","mac":"02:00:10:99:00:02","dns1":"10.140.50.6","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://993","isolationUri":"vlan://993","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"80c827a3-4b5e-41eb-97f1-c829d2eff69a","ip":"10.147.40.232","netmask":"255.255.254.0","gateway":"10.147.40.1","mac":"02:00:60:3e:00:01","broadcastType":"Native","type":"Control","isSecurityGroupEnabled":false}]},"result":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":true,"wait":0}},{"com.cloud.agent.api.GetDomRVersionAnswer":{"result":false,"details":"GetDomRVersionCmd
failed due to java.net.SocketTimeoutException: The kexTimeout (60000 ms)
expired.","wait":0}}] }
2013-12-04 12:25:03,019 DEBUG [c.c.a.t.Request] (Job-Executor-2:ctx-4fc0c5af
ctx-2d3a7128) Seq 1-1576731025: Received: { Ans: , MgmtId: 7332683579487, via:
1, Ver: v1, Flags: 10, { StartAnswer, CheckSshAnswer, GetDomRVersionAnswer } }
2013-12-04 12:25:03,064 WARN [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Job-Executor-2:ctx-4fc0c5af ctx-2d3a7128) Unable to get the template/scripts
version of router r-8-VM due to: GetDomRVersionCmd failed due to
java.net.SocketTimeoutException: The kexTimeout (60000 ms) expired.
2013-12-04 12:25:03,064 INFO [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-2:ctx-4fc0c5af ctx-2d3a7128) The guru did not like the answers so
stopping VM[DomainRouter|r-8-VM]
2013-12-04 12:25:03,070 DEBUG [c.c.a.t.Request] (Job-Executor-2:ctx-4fc0c5af
ctx-2d3a7128) Seq 1-1576731041: Sending { Cmd , MgmtId: 7332683579487, via:
1(10.147.40.14), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-8-VM","wait":0}}]
}
2013-12-04 12:25:03,070 DEBUG [c.c.a.t.Request] (Job-Executor-2:ctx-4fc0c5af
ctx-2d3a7128) Seq 1-1576731041: Executing: { Cmd , MgmtId: 7332683579487, via:
1(10.147.40.14), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"r-8-VM","wait":0}}]
}
2013-12-04 12:25:03,070 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-229:ctx-3ff22557) Seq 1-1576731041: Executing request
2013-12-04 12:25:03,071 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-229:ctx-3ff22557) POST request
tohttp://10.147.40.14:8250/api/HypervResource/com.cloud.agent.api.StopCommand
with
contents{"isProxy":false,"executeInSequence":false,"vmName":"r-8-VM","contextMap":{},"wait":0}
2013-12-04 12:25:03,071 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-229:ctx-3ff22557) Sending cmd to
http://10.147.40.14:8250/api/HypervResource/com.cloud.agent.api.StopCommand cmd
data:{"isProxy":false,"executeInSequence":false,"vmName":"r-8-VM","contextMap":{},"wait":0}
2013-12-04 12:25:03,683 DEBUG [c.c.a.ApiServlet]
(catalina-exec-11:ctx-a5bda5fe) ===START=== 10.146.0.134 -- GET
command=queryAsyncJobResult&jobId=90dbfeed-f357-47b9-9067-9c4ad34a1d33&response=json&sessionkey=uSpuIkackMpvWLrjIHS842Q1v4o%3D&_=1386158235163
2013-12-04 12:25:03,749 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-53e2498d) VmStatsCollector is running...
2013-12-04 12:25:03,812 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-a5bda5fe
ctx-c422cb8d) ===END=== 10.146.0.134 -- GET
command=queryAsyncJobResult&jobId=90dbfeed-f357-47b9-9067-9c4ad34a1d33&response=json&sessionkey=uSpuIkackMpvWLrjIHS842Q1v4o%3D&_=1386158235163
2013-12-04 12:25:05,243 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-229:ctx-3ff22557) POST response
is[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":null,"vm":null,"contextMap":{}}}]
2013-12-04 12:25:05,244 DEBUG [c.c.h.h.r.HypervDirectConnectResource]
(DirectAgent-229:ctx-3ff22557) executeRequest received response
[{"com.cloud.agent.api.StopAnswer":{"result":true,"contextMap":{},"wait":0}}]
2013-12-04 12:25:05,244 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-229:ctx-3ff22557) Seq 1-1576731041: Response Received:
2013-12-04 12:25:05,244 DEBUG [c.c.a.t.Request] (DirectAgent-229:ctx-3ff22557)
Seq 1-1576731041: Processing: { Ans: , MgmtId: 7332683579487, via: 1, Ver: v1,
Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2013-12-04 12:25:05,244 DEBUG [c.c.a.t.Request] (Job-Executor-2:ctx-4fc0c5af
ctx-2d3a7128) Seq 1-1576731041: Received: { Ans: , MgmtId: 7332683579487, via:
1, Ver: v1, Flags: 10, { StopAnswer } }
2013-12-04 12:25:05,245 ERROR [c.c.v.VirtualMachineManagerImpl]
(Job-Executor-2:ctx-4fc0c5af ctx-2d3a7128) Failed to start instance
VM[DomainRouter|r-8-VM]
--
This message was sent by Atlassian JIRA
(v6.1#6144)
