cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Sanjeev N (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-5365) [Hyper-V] VR's control IP is not accessible from mgmt server, which results in VR start up failure
Date Wed, 04 Dec 2013 12:40:35 GMT
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)

Mime
View raw message