Hi,
I am hitting the following issue on an ACS 4.9 + VMware setup (steps to
reproduce):
1) Deploy a multi-nic VM (or) add a nic to a single-nic VM
2) Remove the non-default nic from the multi-nic 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]"}
Here is the error in the VM's vmware.log:
[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 not hitting this issue on ACS 4.7 with same VMware setup.
With regards,
Prashanth
