You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Sanjeev N (JIRA)" <ji...@apache.org> on 2013/12/04 13:40:35 UTC
[jira] [Created] (CLOUDSTACK-5365) [Hyper-V] VR's control IP is not
accessible from mgmt server, which results in VR start up failure
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)