Uploaded image for project: 'CloudStack'
  1. CloudStack
  2. CLOUDSTACK-9547

ACS 4.9 + VMware: Unable to remove one of the NICs of a multi-nic guest VM

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Open
    • Priority: Critical
    • Resolution: Unresolved
    • Affects Version/s: 4.9.0
    • Fix Version/s: None
    • Component/s: Management Server, VMware
    • Security Level: Public (Anyone can view this level - this is the default.)
    • Labels:

      Description

      Steps to reproduce:

      1) Deploy a multi-nic guest VM (or) add a nic to a single-nic guest VM
      2) Remove the non-default nic from the multi-nic guest VM, which fails with the following error/exception in the management server log:

      2016-10-05 06:13:28,251 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-f8dc6bd0 ctx-ee610e01) (logid:58e9cf98) ===END===  10.31.52.95 -- GET  command=queryAsyncJobResult&jobId=9ad66ce9-6e1b-4c25-bd2e-763f4586dd86&response=json&_=1475673245452
      2016-10-05 06:13:29,787 ERROR [c.c.h.v.r.VmwareResource] (DirectAgent-302:ctx-78a58d67 10.31.56.178, job-171/job-172, cmd: UnPlugNicCommand) (logid:9ad66ce9) Unexpected exception:
      java.lang.RuntimeException: The guest operating system did not respond to a hot-remove request for device ethernet1 in a timely manner.
              at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:354)
              at com.cloud.hypervisor.vmware.mo.VirtualMachineMO.configureVm(VirtualMachineMO.java:949)
              at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:1103)
              at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:469)
              at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315)
              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.run(FutureTask.java:262)
              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
              at java.lang.Thread.run(Thread.java:745)
      2016-10-05 06:13:29,788 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-302:ctx-78a58d67) (logid:9ad66ce9) Seq 4-1440588930805137508: Response Received:
      2016-10-05 06:13:29,788 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (DirectAgent-302:ctx-78a58d67) (logid:9ad66ce9) Seq 4-1440588930805137508: MgmtId 275619427423488: Resp: Routing to peer
      2016-10-05 06:13:29,789 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-302:ctx-78a58d67) (logid:9ad66ce9) Seq 4-1440588930805137508: No more commands found
      2016-10-05 06:13:31,120 DEBUG [o.s.b.f.s.DefaultListableBeanFactory] (API-Job-Executor-8:ctx-a6e36538 job-171 ctx-446c510f) (logid:9ad66ce9) Returning cached instance of singleton bean 'messageBus'
      2016-10-05 06:13:31,127 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-8:ctx-a6e36538 job-171) (logid:9ad66ce9) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.RemoveNicFromVMCmdByAdmin
      com.cloud.utils.exception.CloudRuntimeException: Unable to remove Ntwk[205|Guest|16] from VM[User|i-2-3-VM]
              at com.cloud.vm.UserVmManagerImpl.removeNicFromVirtualMachine(UserVmManagerImpl.java:1291)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
              at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
              at java.lang.reflect.Method.invoke(Method.java:606)
      at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
              at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
              at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
              at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:106)
              at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
              at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
              at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
              at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
              at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
              at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
              at com.sun.proxy.$Proxy198.removeNicFromVirtualMachine(Unknown Source)
              at org.apache.cloudstack.api.command.admin.vm.RemoveNicFromVMCmdByAdmin.execute(RemoveNicFromVMCmdByAdmin.java:44)
              at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150)
              at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
              at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:554)
              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 org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:502)
              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
              at java.util.concurrent.FutureTask.run(FutureTask.java:262)
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
              at java.lang.Thread.run(Thread.java:745)
      2016-10-05 06:13:31,129 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-8:ctx-a6e36538 job-171) (logid:9ad66ce9) Complete async job-171, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to remove Ntwk[205|Guest|16] from VM[User|i-2-3-VM]"}
      
      [root@csc-1 i-2-9-VM]# pwd
      /export/primary/i-2-9-VM
      [root@csc-1 i-2-9-VM]# tail -f vmware.log 
      2016-10-06T04:34:33.214Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 2 starting feature 0
      2016-10-06T04:34:33.214Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 2 starting feature 0
      2016-10-06T04:36:09.127Z| vmx| I120: GuestRpcSendTimedOut: message to toolbox timed out.
      2016-10-06T04:36:09.128Z| vmx| I120: Vix: [80405 guestCommands.c:1924]: Error VIX_E_TOOLS_NOT_RUNNING in VMAutomationTranslateGuestRpcError(): VMware Tools are not running in the guest
      2016-10-06T04:43:08.823Z| vmx| I120: Tools: No activity for 10 minutes, resetting Tools version.
      2016-10-06T04:43:08.824Z| vmx| I120: ToolsSetVersionWork did nothing; new tools version (0) matches old Tools version
      2016-10-06T04:43:23.152Z| vmx| W110: Requesting hot-remove of ethernet1
      2016-10-06T04:50:13.889Z| mks| I120: SOCKET 3 (121) recv detected client closed connection
      2016-10-06T04:50:13.890Z| mks| I120: SOCKET 3 (121) VNC Remote Disconnect: socket closed.
      2016-10-06T04:53:25.699Z| vmx| W110: VigorHotRemovePoll: device ethernet1 failed to disappear.
      

      Note: I am hitting the same issue when I am trying to directly remove the VM NIC from VMware.

      We don't hit this issue with VPC VR while deleting one of its tiers. The vNIC gets deleted successfully from VMware as well.

      [root@csc-1 r-5-VM]# pwd
      /export/primary/r-5-VM
      [root@csc-1 r-5-VM]# tail -f vmware.log
      2016-10-14T02:09:27.520Z| vmx| W110: Requesting hot-remove of ethernet2
      2016-10-14T02:09:27.622Z| vcpu-0| I120: Destroying virtual dev for scsi0:0 vscsi=8203
      2016-10-14T02:09:27.622Z| vcpu-0| I120: VMMon_VSCSIStopVports: No such target on adapter
      2016-10-14T02:09:27.666Z| vcpu-0| I120: Closing all the disks of the VM.
      2016-10-14T02:09:27.666Z| vcpu-0| I120: Closing disk scsi0:0
      2016-10-14T02:09:27.667Z| vcpu-0| I120: DISKLIB-VMFS  : "/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001-flat.vmdk" : closed.
      2016-10-14T02:09:27.695Z| vcpu-0| I120: Checkpoint_Unstun: vm stopped for 73057 us
      2016-10-14T02:09:27.695Z| vcpu-0| I120: SCSI: switching scsi0 to push completion mode
      2016-10-14T02:09:27.702Z| vcpu-0| I120: DISK: OPEN scsi0:0 '/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001.vmdk' persistent R[]
      2016-10-14T02:09:27.722Z| vcpu-0| I120: DISKLIB-VMFS  : "/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001-flat.vmdk" : open successful (10) size = 3145728000, hd = 3513569. Type 3
      2016-10-14T02:09:27.722Z| vcpu-0| I120: DISKLIB-DSCPTR: Opened [0]: "ROOT-5-000001-flat.vmdk" (0xa)
      2016-10-14T02:09:27.722Z| vcpu-0| I120: DISKLIB-LINK  : Opened '/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001.vmdk' (0xa): vmfs, 6144000 sectors / 2.9 GB.
      2016-10-14T02:09:27.723Z| vcpu-0| I120: DISKLIB-LIB   : Opened "/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001.vmdk" (flags 0xa, type vmfs).
      2016-10-14T02:09:27.724Z| vcpu-0| I120: DISK: Disk '/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001.vmdk' has UUID '60 00 c2 93 cd 78 05 be-22 47 1c 78 bd 04 05 e0'
      2016-10-14T02:09:27.724Z| vcpu-0| I120: DISK: OPEN '/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001.vmdk' Geo (6095/16/63) BIOS Geo (761/128/63)
      2016-10-14T02:09:27.725Z| vcpu-0| I120: Creating virtual dev for scsi0:0 
      2016-10-14T02:09:27.726Z| vcpu-0| I120: DumpDiskInfo: scsi0:0 createType=11, capacity = 6144000, numLinks = 1, allocationType = 3
      2016-10-14T02:09:27.726Z| vcpu-0| I120: SCSIDiskESXPopulateVDevDesc: Using FS backend
      2016-10-14T02:09:27.726Z| vcpu-0| I120: DISKUTIL: scsi0:0 : geometry=761/128/63
      2016-10-14T02:09:27.822Z| vcpu-0| I120: Powering off Ethernet2
      2016-10-14T02:09:27.822Z| vcpu-0| I120: VMXVigorClassEthernet_SetConnectionStatus: request (0 200 0) ignored as device ethernet2 could not be found.
      2016-10-14T02:09:27.838Z| vcpu-0| I120: Hot removal done.
      2016-10-14T02:09:31.062Z| vcpu-0| I120: HBACommon: First write on scsi0:0.fileName='/vmfs/volumes/469adbc4-fd0b07aa/r-5-VM/ROOT-5-000001.vmdk'
      2016-10-14T02:09:31.062Z| vcpu-0| I120: DDB: "longContentID" = "72b284a1a34cba7d565f5553fa862bed" (was "9be5af4dfbba31a0bc98f40bfef5451d")
      2016-10-14T02:09:31.077Z| vcpu-0| I120: DISKLIB-CHAIN : DiskChainUpdateContentID: old=0xfef5451d, new=0xfa862bed (72b284a1a34cba7d565f5553fa862bed)
      2016-10-14T02:10:27.840Z| vmx| I120: GuestRpcSendTimedOut: message to toolbox-dnd timed out.
      

      Note: I am not hitting this issue with ACP 4.7 + VMware, where I am using using the same VMware setup as above.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              Prashanth Varma Manthena Mani Prashanth Varma Manthena
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated: