Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

RPC error in docker stop, and eventually, vic-machine delete constantly fail with invalid memory address #2818

Closed
hickeng opened this issue Oct 20, 2016 · 20 comments · Fixed by #2992
Assignees

Comments

@hickeng
Copy link
Member

hickeng commented Oct 20, 2016

Seen in https://ci.vmware.run/vmware/vic/6045 and as a follow on from #2817

Build https://ci.vmware.run/vmware/vic/6013 left VCH-6013-4771 and drunk_englebart-9f1ce9... behind.

For some reason, all of the vic-machine delete operations that occur against that host attempt to delete drunk_englebart.

  1. They must not try to do so as that VM does not belong to them - that they are suggests strongly that the SearchIndex is not being used correctly or has a bug.
  2. Even if they were to do so, they should not be getting a nil pointer.
�[34mINFO�[0m[2016-10-19T18:09:37Z] Connect to docker:                           
�[34mINFO�[0m[2016-10-19T18:09:37Z] docker -H dhcp-192-168-31-221.ci.drone.local:2376 --tlsverify --tlscacert="./VCH-6053-1693/ca.pem" --tlscert="./VCH-6053-1693/cert.pem" --tlskey="./VCH-6053-1693/key.pem" info 
�[34mINFO�[0m[2016-10-19T18:09:37Z] Installer completed successfully             
�[34mINFO�[0m[2016-10-19T18:09:48Z] ### Removing VCH ####                        
�[34mINFO�[0m[2016-10-19T18:09:48Z]                                              
�[34mINFO�[0m[2016-10-19T18:09:48Z] VCH ID: VirtualMachine:2279                  
�[34mINFO�[0m[2016-10-19T18:09:48Z] Removing VMs                                 
�[34mINFO�[0m[2016-10-19T18:09:48Z] Removing image stores                        
�[34mINFO�[0m[2016-10-19T18:09:54Z] Removing volume stores                       
�[34mINFO�[0m[2016-10-19T18:09:54Z] Deleting volume store "default" on Datastore "datastore1" at path "test" 
�[34mINFO�[0m[2016-10-19T18:09:54Z] Removing appliance VM network devices        
�[34mINFO�[0m[2016-10-19T18:09:55Z] Bridge network was not created during VCH deployment, leaving it there 
�[34mINFO�[0m[2016-10-19T18:09:55Z] Removing Resource Pool "VCH-6053-1693"       
�[34mINFO�[0m[2016-10-19T18:09:55Z] Completed successfully                       
�[34mINFO�[0m[2016-10-19T18:09:56Z] ### Removing VCH ####                        
�[34mINFO�[0m[2016-10-19T18:09:57Z]                                              
�[34mINFO�[0m[2016-10-19T18:09:57Z] VCH ID: VirtualMachine:1906                  
�[34mINFO�[0m[2016-10-19T18:09:57Z] Removing VMs                                 
�[34mINFO�[0m[2016-10-19T18:09:57Z] Delete will attempt to remove datastore files for VM "drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
�[31mERRO�[0m[2016-10-19T18:09:57Z] --------------------                         
�[31mERRO�[0m[2016-10-19T18:09:57Z] vic-machine-linux failed: runtime error: invalid memory address or nil pointer dereference
@hickeng hickeng added this to the VIC GA Release milestone Oct 20, 2016
@hickeng hickeng changed the title vic-machine: nil pointer deleting VM that doesn't belong to the VCH vic-machine: deleting VM that doesn't belong to the VCH, and failing Oct 20, 2016
@mhagen-vmware
Copy link
Contributor

@cgtexmex tagging Clint as he has been working on the concurrency epic

@anchal-agrawal
Copy link
Contributor

anchal-agrawal commented Oct 20, 2016

Also seen in https://ci.vmware.run/vmware/vic/6093 in every test suite:

Destroying dangling VCH: VCH-6013-4771

Teardown for VCH-6013-4771 failed in build 6013, and looks like Cleanup Dangling VMs On Test Server from Util.robot is unsuccessful on builds 6045 and 6093.

@emlin
Copy link
Contributor

emlin commented Oct 28, 2016

@hickeng vic-machine is not trying to delete VMs not belonging to one VCH. The CI has cleanup functions in every test suite teardown, to delete dangling VCHs, if the corresponding drone build is not running any more. That's why you saw those delete message in different drone build, but try to delete same container VM.

@emlin
Copy link
Contributor

emlin commented Oct 28, 2016

For the number 2, CI also has another clean up function to delete datastore files, if there is no .vmx file found in that directory.
This might generate some unexpected situation, so vic-machine simply cannot delete that VM anymore. #2944 fixed that issue just now.
But from vic-machine log, it's not possible to figure out where throw that exception. So is still trying to reproduce.

@emlin
Copy link
Contributor

emlin commented Oct 31, 2016

@hickeng dig into why vic-machine delete failed with invalid memory issue, but unfortunately, it's hard to reproduce that error.
So I checked the port-layer log of VCH-6013-4771, and found the RPC error actually:

time="2016-10-18T21:24:46Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).Commit:260] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:46Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).stop:499] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:46Z" level=debug msg="Setting container 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e state: Stopping" 
time="2016-10-18T21:24:46Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).shutdown:462] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:46Z" level=info msg="sending kill -TERM 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:46Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).startGuestProgram:557] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:46Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).startGuestProgram:557] [49.707293ms] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:46Z" level=info msg="waiting 10s for 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e to power off" 
time="2016-10-18T21:24:46Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).waitForPowerState:449] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:48Z" level=debug msg="Found 1 subscribers to vsphere.VMEvent: drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e on  vic-esx-07.ci.drone.local in ha-datacenter is powered off" 
time="2016-10-18T21:24:48Z" level=debug msg="Event manager calling back to exec" 
time="2016-10-18T21:24:48Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).waitForPowerState:449] [1.956358119s] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:48Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).shutdown:462] [2.007539658s] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:48Z" level=debug msg="Setting container 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e state: Stopped" 
time="2016-10-18T21:24:48Z" level=debug msg="Container(9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e) closing 0 log followers" 
time="2016-10-18T21:24:48Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).stop:499] [2.008905277s] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:48Z" level=debug msg="[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).refresh:237] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:48Z" level=debug msg="[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).refresh:237] [9.386617ms] 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e" 
time="2016-10-18T21:24:48Z" level=error msg="task failed: An RPC send operation failed." 
time="2016-10-18T21:24:48Z" level=error msg="Reconfigure failed with task.Error{LocalizedMethodFault:(*types.LocalizedMethodFault)(0xc4205dc2e0)}" 
time="2016-10-18T21:24:48Z" level=debug msg="Committing container 9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e status as: Stopped" 

@emlin
Copy link
Contributor

emlin commented Oct 31, 2016

The shudtown, VM power off all succeed, but the refresh followed to update changeVersion failed for RPC error. Though the error message followed shows nothing.

@emlin
Copy link
Contributor

emlin commented Oct 31, 2016

log from hostd:


2016-10-18T21:22:44.100Z info hostd[60D81B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 10915 : Guest operation Start Program performed on Virtual machine drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.
2016-10-18T21:22:44.107Z info hostd[60D81B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] State Transition (VM_STATE_GUEST_OPERATION -> VM_STATE_ON)
2016-10-18T21:22:44.107Z info hostd[5EDC1B70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] Entered VmPowerStateListener
2016-10-18T21:22:44.107Z info hostd[5EDC1B70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] VmPowerStateListener succeeded
2016-10-18T21:22:44.107Z info hostd[5EDC1B70] [Originator@6876 sub=Hbrsvc] Replicator: powerstate change VM: 1908 Old: 1 New: 1
2016-10-18T21:22:44.343Z info hostd[60D81B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Send config update invoked
2016-10-18T21:22:44.494Z info hostd[60D81B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Send config update invoked
2016-10-18T21:22:44.941Z info hostd[61181B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Tools manifest version status changed from guestToolsUnmanaged to guestToolsUnmanaged, on install is TRUE
2016-10-18T21:22:44.957Z info hostd[61181B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Send config update invoked
2016-10-18T21:22:45.038Z info hostd[61181B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Send config update invoked
2016-10-18T21:22:45.109Z info hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Send config update invoked
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] SOCKET 488 (60)
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] recv detected client closed connection
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] VigorTransportClientProcessError: Remote connection failure
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] VigorTransportClientDrainRecv: draining read.
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] SOCKET 488 (60)
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] recv detected client closed connection
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] VigorTransportClientProcessError: closing connection.
2016-10-18T21:22:45.983Z info hostd[5D540B70] [Originator@6876 sub=Libs] VigorTransportClientManageConnection: connection closed.
2016-10-18T21:22:46.015Z info hostd[5D540B70] [Originator@6876 sub=Libs] CnxAuthdProtoSecureConnect: Unencrypted connection, skipping thumbprint exchange.
2016-10-18T21:22:46.050Z info hostd[5D540B70] [Originator@6876 sub=Libs] CnxConnectAuthd: Returning false because CnxAuthdProtoConnect failed
2016-10-18T21:22:46.050Z info hostd[5D540B70] [Originator@6876 sub=Libs] Cnx_Connect: Returning false because CnxConnectAuthd failed
2016-10-18T21:22:46.050Z info hostd[5D540B70] [Originator@6876 sub=vm:Cnx_Connect: Error message: There is no VMware process running for config file /vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx]
2016-10-18T21:22:46.050Z warning hostd[5D540B70] [Originator@6876 sub=vm:VigorTransportClientManageConnection: Failed to re-connect to VM /vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx]
2016-10-18T21:22:46.054Z info hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Error encountered while retrieving configuration. Marking configuration as invalid: N3Vim5Fault20GenericVmConfigFault9ExceptionE(vim.fault.GenericVmConfigFault)
2016-10-18T21:22:46.055Z warning hostd[61387B70] [Originator@6876 sub=Hostsvc] Unable to get worldId for cartel 2210905 : Sysinfo error on operation returned status : No cartel by that name. Please see the VMkernel log for detailed error information
2016-10-18T21:22:46.055Z warning hostd[61387B70] [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Could not retrieve offline Bootstrap state: N3Vim5Fault20GenericVmConfigFault9ExceptionE(vim.fault.GenericVmConfigFault)
2016-10-18T21:22:46.055Z error hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Could not fetch Vigor vmx state: N3Vim5Fault20GenericVmConfigFault9ExceptionE(vim.fault.GenericVmConfigFault)
2016-10-18T21:22:46.055Z warning hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Unstable power state, assuming off
2016-10-18T21:22:46.056Z info hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] State Transition (VM_STATE_ON -> VM_STATE_OFF)
2016-10-18T21:22:46.056Z warning hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Failed to find activation record, event user unknown.
2016-10-18T21:22:46.056Z info hostd[5EDC1B70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] Entered VmPowerStateListener
2016-10-18T21:22:46.056Z info hostd[5EDC1B70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] VmPowerStateListener succeeded
2016-10-18T21:22:46.056Z info hostd[5EDC1B70] [Originator@6876 sub=Hbrsvc] Replicator: powerstate change VM: 1908 Old: 1 New: 0
2016-10-18T21:22:46.056Z info hostd[5EDC1B70] [Originator@6876 sub=Hbrsvc] Replicator: Poweroff for VM: (id=1908)
2016-10-18T21:22:46.059Z info hostd[61387B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 10916 : drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e on  vic-esx-07.ci.drone.local in ha-datacenter is powered off
2016-10-18T21:22:46.059Z error hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Could not fetch Vigor vmx state: N3Vim5Fault20GenericVmConfigFault9ExceptionE(vim.fault.GenericVmConfigFault)
2016-10-18T21:22:46.059Z warning hostd[61387B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx] Unstable power state, assuming off
2016-10-18T21:22:46.081Z info hostd[5EDC1B70] [Originator@6876 sub=Vimsvc.TaskManager opID=e8fff462 user=root] Task Created : haTask-1908-vim.VirtualMachine.reconfigure-155678
2016-10-18T21:22:46.081Z info hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] State Transition (VM_STATE_OFF -> VM_STATE_RECONFIGURING)
2016-10-18T21:22:46.081Z error hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Could not fetch Vigor vmx state: N3Vim5Fault20GenericVmConfigFault9ExceptionE(vim.fault.GenericVmConfigFault)
2016-10-18T21:22:46.081Z warning hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Unstable power state, assuming off
2016-10-18T21:22:46.084Z info hostd[5EDC1B70] [Originator@6876 sub=Libs opID=e8fff462 user=root] VigorOnlineRPCNewConfigParamsSetVolatileEntry RPC Send Failed
2016-10-18T21:22:46.084Z info hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Reconfigure failed: vim.fault.GenericVmConfigFault
2016-10-18T21:22:46.084Z warning hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Exception thrown during reconfigure: (vim.vm.ConfigSpec) {
-->    changeVersion = "2016-10-18T21:22:30.895589Z",
-->    name = <unset>,
-->    version = <unset>,
-->    uuid = <unset>,
-->    instanceUuid = <unset>,
-->    npivWorldWideNameType = <unset>,
-->    npivDesiredNodeWwns = <unset>,
-->    npivDesiredPortWwns = <unset>,
-->    npivTemporaryDisabled = <unset>,
-->    npivOnNonRdmDisks = <unset>,
-->    npivWorldWideNameOp = <unset>,
-->    locationId = <unset>,
-->    guestId = <unset>,
-->    alternateGuestName = <unset>,
-->    annotation = <unset>,
-->    files = (vim.vm.FileInfo) null,
-->    tools = (vim.vm.ToolsConfigInfo) null,
-->    flags = (vim.vm.FlagInfo) null,
-->    consolePreferences = (vim.vm.ConsolePreferences) null,
-->    powerOpInfo = (vim.vm.DefaultPowerOpInfo) null,
-->    numCPUs = <unset>,
-->    numCoresPerSocket = <unset>,
-->    memoryMB = <unset>,
-->    memoryHotAddEnabled = <unset>,
-->    cpuHotAddEnabled = <unset>,
-->    cpuHotRemoveEnabled = <unset>,
-->    virtualICH7MPresent = <unset>,
-->    virtualSMCPresent = <unset>,
-->    cpuAllocation = (vim.ResourceAllocationInfo) null,
-->    memoryAllocation = (vim.ResourceAllocationInfo) null,
-->    latencySensitivity = (vim.LatencySensitivity) null,
-->    cpuAffinity = (vim.vm.AffinityInfo) null,
-->    memoryAffinity = (vim.vm.AffinityInfo) null,
-->    networkShaper = (vim.vm.NetworkShaperInfo) null,
-->    extraConfig = (vim.option.OptionValue) [
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/cmd/Path",
-->          value = "/bin/top"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/static",
-->          value = "false"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/network/pools",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "networks|test-network/Common/notes",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "networks|test-network/network/Common/notes",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.detail.createtime",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks",
-->          value = "bridge|test-network"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./key",
-->          value = "LS0tLS1CRUdJTiBSU0EgUFJJVkFURSBLRVktLS0tLQpNSUlCUEFJQkFBSkJBTk90eXIydTh3aWhzTFpIam1CajZkVFVVQkVvTUwwYldnWlRjVGpZT1J1ZVJoSFhOL29pCnduMjRyNGJPekFOaVhkWGk5UEdEN3YrR0FIWmQ2RFJlVlZVQ0F3RUFBUUpCQUxtelg0ZGtzY1ZDeEJwRlVEeHoKcXJHUnlPUWtWQTJ5cnhtWm5seDJKRE42Mzlqa3VwSmdFbVI3UFgySWxNTEF1SjF1aVZKbHQ0RjhwZStGLzlHbwpYc0VDSVFEZ1ZhOFUrQm5LeVg4NGt6VE15RUhxMVllVHRGM0s3cWZXdUxIY3JTSUFQUUloQVBHT3ltM01aNUxuCkY5SVZzTTFXY1Frd0xwd1NaaWNHcHh6NmwrVXpsQ0w1QWlCcUJsVVBOZ3NLbXB6MElpNnNNbUZsR2JKUURzamQKWmxvUTA0M01YRTliaVFJaEFOZlVxdUNTTzVVUnNNSUFxWG0vRzc2Rzg0NTJEaG9lb3FDTTg3MVNhYkVaQWlFQQpqQTBsZGVMYytBYVY0UkhCMjF6RkhSRkQ1aVhNVEswV09WWVZPTGFRcG1ZPQotLS0tLUVORCBSU0EgUFJJVkFURSBLRVktLS0tLQo="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./version/State",
-->          value = "clean"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "networks|bridge/network/Common/notes",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/common/notes",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/cmd/Args",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/tty",
-->          value = "false"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/ip/IP",
-->          value = "AAAAAAAAAAAAAP//rBQAAg=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/network/pools|0/last",
-->          value = "AAAAAAAAAAAAAP//rBT//w=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./version/BuildDate",
-->          value = "2016/10/18@20:58:33"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./version/BuildNumber",
-->          value = "6013"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..createtime",
-->          value = "1476825741"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|bridge.network.type",
-->          value = "bridge"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/network/pools|0/first",
-->          value = "AAAAAAAAAAAAAP//rBAAAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/cmd/Dir",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./common/id",
-->          value = "9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|test-network.network.type",
-->          value = "bridge"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|test-network.network.gateway.Mask",
-->          value = "//8AAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./common/ExecutionEnvironment",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/stopSignal",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/User",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/network/pools",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.status",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/cmd/Args~",
-->          value = "/bin/top"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/restart",
-->          value = "false"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/ip/Mask",
-->          value = "//8AAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/ip/Mask",
-->          value = "//8AAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/network/Common/name",
-->          value = "test-network"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "common/notes",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.detail.starttime",
-->          value = "1476825747"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.detail.stoptime",
-->          value = "1476825886"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/Group",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/ip/IP",
-->          value = "AAAAAAAAAAAAAP//rBAAAg=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/common/name",
-->          value = "drunk_engelbart"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/diagnostics/debug",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions",
-->          value = "9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|bridge.network.gateway.Mask",
-->          value = "//8AAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/Common/name",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/static",
-->          value = "false"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/cmd/Env~",
-->          value = "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/cmd/Env",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/attach",
-->          value = "true"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.diagnostics.resurrections",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|bridge.assigned.IP",
-->          value = "AAAAAAAAAAAAAP//AAAAAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|bridge.network.gateway.IP",
-->          value = "AAAAAAAAAAAAAP//rBAAAQ=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|test-network.assigned.Mask",
-->          value = "//8AAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/network/Common/ExecutionEnvironment",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./common/name",
-->          value = "drunk_engelbart"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/Common/id",
-->          value = "192"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "networks|bridge/Common/notes",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/network/default",
-->          value = "false"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./version/GitCommit",
-->          value = "6af3fbd"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/common/ExecutionEnvironment",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/Common/name",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|test-network.network.gateway.IP",
-->          value = "AAAAAAAAAAAAAP//rBQAAQ=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/network/pools|0/first",
-->          value = "AAAAAAAAAAAAAP//rBQAAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./version/Version",
-->          value = "v0.6.0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/common/id",
-->          value = "9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..sessions|9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.started",
-->          value = "true"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/network/Common/id",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/network/Common/name",
-->          value = "bridge"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/network/default",
-->          value = "true"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./diagnostics/debug",
-->          value = "1"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|test-network.assigned.IP",
-->          value = "AAAAAAAAAAAAAP//AAAAAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/network/Common/id",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./layerid",
-->          value = "9967c5ad88de8c101809f7f22d4774b6791fe46ac3033d57abf7ebb1dd8e36ee"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..networks|bridge.assigned.Mask",
-->          value = "//8AAA=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/network/Common/ExecutionEnvironment",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/network/pools|0/last",
-->          value = "AAAAAAAAAAAAAP//rBD//w=="
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/Common/ExecutionEnvironment",
-->          value = "<nil>"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|test-network/Common/id",
-->          value = "192"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./repo",
-->          value = "busybox"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice..diagnostics.resurrections",
-->          value = "0"
-->       },
-->       (vim.option.OptionValue) {
-->          key = "guestinfo.vice./networks|bridge/Common/ExecutionEnvironment",
-->          value = "<nil>"
-->       }
-->    ],
-->    swapPlacement = <unset>,
-->    swapDirectory = <unset>,
-->    preserveSwapOnPowerOff = <unset>,
-->    bootOptions = (vim.vm.BootOptions) null,
-->    vAppConfig = (vim.vApp.VmConfigSpec) null,
-->    ftInfo = (vim.vm.FaultToleranceConfigInfo) null,
-->    repConfig = (vim.vm.ReplicationConfigSpec) null,
-->    vAppConfigRemoved = <unset>,
-->    vAssertsEnabled = <unset>,
-->    changeTrackingEnabled = <unset>,
-->    firmware = <unset>,
-->    maxMksConnections = <unset>,
-->    guestAutoLockEnabled = <unset>,
-->    managedBy = (vim.ext.ManagedByInfo) null,
-->    memoryReservationLockedToMax = <unset>,
-->    nestedHVEnabled = <unset>,
-->    vPMCEnabled = <unset>,
-->    scheduledHardwareUpgradeInfo = (vim.vm.ScheduledHardwareUpgradeInfo) null,
-->    messageBusQueuePattern = <unset>,
-->    messageBusTunnelEnabled = <unset>,
--> }
--> vim.fault.GenericVmConfigFault
2016-10-18T21:22:46.087Z error hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Could not fetch Vigor vmx state: N3Vim5Fault20GenericVmConfigFault9ExceptionE(vim.fault.GenericVmConfigFault)
2016-10-18T21:22:46.087Z warning hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Unstable power state, assuming off
2016-10-18T21:22:46.087Z info hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] State Transition (VM_STATE_RECONFIGURING -> VM_STATE_OFF)
2016-10-18T21:22:46.088Z info hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Marking VirtualMachine invalid
2016-10-18T21:22:46.088Z info hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] State Transition (VM_STATE_OFF -> VM_STATE_INVALID_CONFIG)
2016-10-18T21:22:46.088Z info hostd[5EDC1B70] [Originator@6876 sub=Vimsvc.ha-eventmgr opID=e8fff462 user=root] Event 10917 : Reconfigured drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e on vic-esx-07.ci.drone.local in ha-datacenter
2016-10-18T21:22:46.090Z info hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Send config update invoked
2016-10-18T21:22:46.095Z info hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Error encountered while retrieving configuration. Marking configuration as invalid: N3Vim5Fault20GenericVmConfigFault9ExceptionE(vim.fault.GenericVmConfigFault)
2016-10-18T21:22:46.095Z info hostd[5EDC1B70] [Originator@6876 sub=Vimsvc.TaskManager opID=e8fff462 user=root] Task Completed : haTask-1908-vim.VirtualMachine.reconfigure-155678 Status error
2016-10-18T21:22:46.095Z warning hostd[5EDC1B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe905-615d7a8a-e1c7-0050569c8cc7/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e/drunk_engelbart-9f1ce9ea3dd4f8402d5049999af91256c143b0e55cca9f319efa3171a0b4d86e.vmx opID=e8fff462 user=root] Reconfigure worker thread failed
2016-10-18T21:22:46.129Z info hostd[5D540B70] [Originator@6876 sub=Libs] VigorOnlineDisconnectCb: connection closed (is final).
[LikewiseGetDomainJoinInfo:355] QueryInformation(): ERROR_FILE_NOT_FOUND (2/0):

@emlin
Copy link
Contributor

emlin commented Oct 31, 2016

@hickeng @dougm Any idea on that?
I ever tried to delete one vm with invalid state, vic-mchine delete works well, cause it will return invalid state error. And then followed unregister vm works well.
But in this case, it obviously returned something else.
And looks like we sent quite a few times request for config update, is that expected?

@emlin emlin changed the title vic-machine: deleting VM that doesn't belong to the VCH, and failing RPC error in docker stop, and eventually, vic-machine delete constantly fail with invalid memory address Oct 31, 2016
@dougm
Copy link
Member

dougm commented Oct 31, 2016

The logging improvements @matthewavery is making should help here.

Regarding the NPE, it is worth checking SearchIndex usage as it can return a nil value and error when there are no results. Looks like some uses check for that, but at least 1 case where we could return nil, but wasn't obvious is checked for != nil later on: https://github.com/vmware/vic/blob/master/lib/install/management/finder.go#L268

@emlin
Copy link
Contributor

emlin commented Oct 31, 2016

Well, just got something cause we still didn't remove that vch and container vm from our CI env. So I found that the NPE is from VirtualMachine.Device method.
In that method, we're querying "config.hardware.device" property. Cause that vm is already wrong, it does not return anything, and also WITHOUT error.
So it try to check o.Config.Hardware.Device, but o.Config is actually nil.

@dougm
Copy link
Member

dougm commented Nov 1, 2016

I'll add a nil check to govmomi for the Device method.

@emlin
Copy link
Contributor

emlin commented Nov 1, 2016

This problem is still caused by VM invalid state issue. But it does not always happen in vm operations. Observed three different cases.

  • VM is transited to invalid state during container stop. But during this transition, we're still trying to update vm changeversion, which might get RPC send error. From the portlayer log and esx hostd, I saw those information, but never reproduced that to an invalid state vm.
  • vm.properties method could not return vm config for an invalid state vm, and vsphere does not think it is an error. The result is that the properties we're querying is not returned properly, and no error reported. In that case, vm.Device() method throw NPE. And lots of others will do same thing.
  • If vm is in invalid state, VM operation does not always return *types.InvalidState error object. For example, it returns *types.InvalidPowerState error, which is same to a normal error while vm is actually in unexpected state.

For these three issues, we'll need to do following fix:

  • Check vm connection state in vm.properties method, and probably fix the invalid state issue in that method as well. Cause currently vm.properties is not enclosed by waitForResult, and that means it's not easy to fix that error from caller.
  • In vm.WaitForResult method, check vm connection state while there is vm operation error, instead of check error type only. Cause that might return RPC error, other invalidState error.
  • Also in commit method of docker stop, we're doing lots of properties query, and trying to sync up VM changeversion periodically, which increase the possibility of transit VM into invalid state. We should move to event listener for VM power state change, instead of current mechanism.

@dougm I think the first one should happen in govmomi, and I'll take care of the second. We might take care of the third in the future.
@hickeng any comments?

@dougm
Copy link
Member

dougm commented Nov 1, 2016

There is no 'vm.properties' method, are you referring to the object.Common.Properties method? That's just a shortcut to the property collector, there isn't anything specific to the object type vm or otherwise. In any case, I'm not sure about adding a workaround for this bug to govmomi. I may need to spend some time better understanding the bug and creating a small test case to reproduce outside of vic.

Certainly will add the nil check to the VirtualMachine.Device method, as the sdk doc http://pubs.vmware.com/vsphere-60/index.jsp#com.vmware.wssdk.apiref.doc/vim.VirtualMachine.html states:

"The virtual machine configuration is not guaranteed to be available. For example, the configuration information would be unavailable if the server is unable to access the virtual machine files on disk, and is often also unavailable during the initial phases of virtual machine creation. "

@emlin
Copy link
Contributor

emlin commented Nov 1, 2016

Yeah, I know there is no vm.Properties method, but it looks like there is one, and we can add one for some workaround. That's what I mean.

It's reasonable to return the empty value back to caller, but it might be difficult to fix all callers for it. I'm fine with it, but is there good way to show the error if another NPE happens? For this specific one, it needs lots of additional effort to figure out what's wrong.

@dougm
Copy link
Member

dougm commented Nov 1, 2016

If we are only concerned with the VirtualMachine.Device() case here, we can return an error if Config == nil and include ConnectionState in the error message. How does that sound? The more generic case I'm not sure about yet.

@emlin
Copy link
Contributor

emlin commented Nov 1, 2016

For this specific case, if you check the connection state, it might be better to return an invalid state error.

But even with that, we also need to check the caller to make sure they are not throwing NPE. I can check vic code, to make sure they works even with empty vm.Config, but for govmomi, then you'll need to go through the callers. Otherwise we might go into other path to hit this NPE again.

@emlin
Copy link
Contributor

emlin commented Nov 1, 2016

And I'm wondering what should we do with this error. For example, https://github.com/vmware/vic/blob/master/lib/portlayer/exec/base.go#L107, if there is empty config returned, what should we do there?
Keep retry update doesn't help, and it doesn't go through the vm.WaitForResult path, so no one fix that yet.

@emlin
Copy link
Contributor

emlin commented Nov 1, 2016

I gonna have a method vm.Properties in vic vm.go file, to workaround this issue. And one log mechanism to catch NPE in vic-machine, in case we're leaking anything.

@dougm
Copy link
Member

dougm commented Nov 2, 2016

@emlin sounds good. I will just add the nil check in VirtualMachine.Device for now then.

@dougm
Copy link
Member

dougm commented Nov 2, 2016

vmware/govmomi#623 - includes a test case to reproduce nil VirtualMachine.Config

dougm added a commit to dougm/vic that referenced this issue Nov 2, 2016
Fixes vmware#2968 (NSX-T)

Avoid possible VirtualMachine.Device NPE seen in vmware#2818

Fix for vmware#2878 (docker image update still required)
dougm added a commit to dougm/vic that referenced this issue Nov 2, 2016
Fixes vmware#2968 (NSX-T)

Avoid possible VirtualMachine.Device NPE seen in vmware#2818

Fix for vmware#2878 (docker image update still required)
dougm added a commit to dougm/vic that referenced this issue Nov 2, 2016
Fixes vmware#2968 (NSX-T)

Avoid possible VirtualMachine.Device NPE seen in vmware#2818

Fix for vmware#2878 (docker image update still required)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants