Manageiq: REST api/vms/xxx with "retire" action does not retire the VM

[lrhamann]

---

Issue Summary

The REST api /vms/xxx with a "retire" action request does NOT retire the VM even though the api returns a success response.

Issue Details

Steps to reproduce

The VM operator is issuing the following api to retire a VM but IM does not perform the action even though it accepts the api.

curl --insecure -H "Content-type: application/json" -d '{
  "action": "retire"
}' 'https://inframgmtinstall.apps.b-cp4mcm-23-1.cp.fyre.ibm.com/api/vms/702' --user "admin:smartvm"
{"success":true,"message":"VM id:702 name:'Lrh-rhcos-4.2' retiring","href":"https://inframgmtinstall.apps.b-cp4mcm-23-1.cp.fyre.ibm.com/api/vms/702"}%

Here is the state of the VM at the time of the REST api:

Expected behavior

The Retirement State of the VM is changed to "retiring" .

What really happened

The Retirement State of the VM changes to "Initializing" but the VM is never retired.

Environment Information

Attemped the REST api for both the appliance version and podified version of manageiq.

[agrare]

The issue appears to be due to a failure in the #retire_now method while delivering the MiqAeEvent, the call_automate_event method is returning true and we are trying to access true.root['ae_result'] == 'error'

[----] I, [2021-03-30T16:16:50.868385 #282954:145c8]  INFO -- : MIQ(VmRetireRequest#call_automate_event) Raising event [request_starting] to Automate synchronously
[----] I, [2021-03-30T16:16:50.882404 #282954:145c8]  INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"request_starting", "EventStream::event_stream"=>339, :event_stream_id=>339} for object [VmRetireRequest.2] with state [] to Automate
[----] E, [2021-03-30T16:16:51.220132 #282954:145c8] ERROR -- : MIQ(MiqAeEngine.deliver) Error delivering {:event_type=>"request_starting", "EventStream::event_stream"=>339, :event_stream_id=>339, "User::user"=>1, "VmRetireRequest::vm_retire_request"=>2} for object [VmRetireRequest.2] with state [] to Automate: Method exited with rc=Unknown RC: [1]
[----] I, [2021-03-30T16:16:51.220224 #282954:145c8]  INFO -- : MIQ(VmRetireRequest#call_automate_event) Raised event [request_starting] to Automate
[----] E, [2021-03-30T16:16:51.220939 #282954:145c8] ERROR -- : MIQ(MiqQueue#deliver) Message id: [465], Error: [undefined method `root' for true:TrueClass]

[----] E, [2021-03-30T16:16:51.221065 #282954:145c8] ERROR -- : [NoMethodError]: undefined method `root' for true:TrueClass  Method:[block (2 levels) in <class:LogProxy>]
[----] E, [2021-03-30T16:16:51.221170 #282954:145c8] ERROR -- : /home/grare/adam/src/manageiq/manageiq/app/models/miq_request.rb:239:in `automate_event_failed?'
/home/grare/adam/src/manageiq/manageiq/app/models/miq_request.rb:455:in `create_request_tasks'
/home/grare/adam/src/manageiq/manageiq/app/models/miq_queue.rb:484:in `block in dispatch_method'

This leaves the VM's retirement_state in "initializing":

>> vm.reload.retirement_state
=> "initializing"

Which leaves subsequent requests to not attempt to retire the VM again due to: https://github.com/ManageIQ/manageiq/blob/master/app/models/mixins/retirement_mixin.rb#L160

[agrare]

Even when this doesn't raise an exception the #retire_now method doesn't seem to actually do anything. This means it leave the vm in the initializing state, then when you try to retire it again it fails with that got updated while waiting to be unlocked and is now initializing error.

[chessbyte]

maybe @tinaafitz @billfitzgerald0120 or @lfu can help understand how this was intended to work

[agrare]

Yeah that would help a lot.

Here is the content of the automate.log when calling request_vm_retire as a result of retire_now

[----] I, [2021-03-30T18:08:56.757137 #8124:2b1fc6175f3c]  INFO -- : MiqAeEvent.build_evm_event >> event=<"request_vm_retire"> inputs=<{:userid=>#<User id: 1, name: "Administrator", email: nil, icon: nil, created_on: "2021-03-22 20:28:02", updated_on: "2021-03-30 22:08:56", userid: "admin", settings: {}, lastlogon: "2021-03-30 22:08:56", lastlogoff: "2021-03-23 13:23:26", current_group_id: 2, first_name: nil, last_name: nil, password_digest: [FILTERED], failed_login_attempts: 0>, :vm=>#<ManageIQ::Providers::Vmware::InfraManager::Vm id: 666, vendor: "vmware", format: nil, version: nil, name: "LrhRHCOS", description: nil, location: "LrhRHCOS/LrhRHCOS.vmx", config_xml: nil, autostart: nil, host_id: 2, last_sync_on: nil, created_on: "2021-03-30 19:53:24", updated_on: "2021-03-30 22:08:56", storage_id: 46, guid: "06464556-efc0-483b-95d5-19745e725394", ems_id: 3, last_scan_on: nil, last_scan_attempt_on: nil, uid_ems: "421b187c-77f2-7dc1-1428-59b435dff6c9", retires_on: nil, retired: nil, boot_time: "2021-03-30 19:53:26", tools_status: "toolsOld", standby_action: "checkpoint", power_state: "on", state_changed_on: "2021-03-30 19:53:26", previous_state: "poweredOff", connection_state: "connected", last_perf_capture_on: nil, registered: nil, busy: nil, smart: nil, memory_reserve: 0, memory_reserve_expand: false, memory_limit: -1, memory_shares: 20480, memory_shares_level: "normal", cpu_reserve: 281, cpu_reserve_expand: false, cpu_limit: -1, cpu_shares: 1000, cpu_shares_level: "normal", cpu_affinity: nil, ems_created_on: nil, template: false, evm_owner_id: 1, miq_group_id: 2, linked_clone: nil, fault_tolerance: nil, type: "ManageIQ::Providers::Vmware::InfraManager::Vm", ems_ref: "vm-45699", ems_cluster_id: 4, retirement_warn: nil, retirement_last_warn: nil, vnc_port: nil, flavor_id: nil, availability_zone_id: nil, cloud: false, retirement_state: "initializing", cloud_network_id: nil, cloud_subnet_id: nil, cloud_tenant_id: nil, raw_power_state: "poweredOn", publicly_available: nil, orchestration_stack_id: nil, retirement_requester: nil, tenant_id: 1, resource_group_id: nil, deprecated: nil, storage_profile_id: nil, cpu_hot_add_enabled: false, cpu_hot_remove_enabled: false, memory_hot_add_enabled: false, memory_hot_add_limit: 2048, memory_hot_add_increment: 0, hostname: nil, ems_ref_type: "VirtualMachine", restart_needed: nil, ancestry: "42">, :host=>#<ManageIQ::Providers::Vmware::InfraManager::HostEsx id: 2, name: "visidpxer22.rtp.raleigh.ibm.com", hostname: "visidpxer22.rtp.raleigh.ibm.com", ipaddress: "10.11.24.93", vmm_vendor: "vmware", vmm_version: "6.5.0", vmm_product: "ESXi", vmm_buildnumber: "17477841", created_on: "2021-03-22 20:35:52", updated_on: "2021-03-23 13:16:45", guid: "3f5d71a5-1228-45d1-995d-2c33ca023f5e", ems_id: 3, user_assigned_os: nil, power_state: "on", smart: 1, settings: {}, last_perf_capture_on: nil, uid_ems: "visidpxer22.rtp.raleigh.ibm.com", connection_state: "connected", ssh_permit_root_login: nil, admin_disabled: false, service_tag: "06TWYM4", asset_tag: "none", ipmi_address: nil, mac_address: nil, type: "ManageIQ::Providers::Vmware::InfraManager::HostEsx", failover: nil, ems_ref: "host-6541", hyperthreading: true, ems_cluster_id: 4, next_available_vnc_port: nil, hypervisor_hostname: nil, availability_zone_id: nil, maintenance: false, maintenance_reason: nil, physical_server_id: nil, ems_ref_type: "HostSystem">, :type=>"ManageIQ::Providers::Vmware::InfraManager::Vm", "MiqEvent::miq_event"=>109937, :miq_event_id=>109937, "EventStream::event_stream"=>109937, :event_stream_id=>109937}>
[----] I, [2021-03-30T18:09:01.367532 #8006:2adb28837970]  INFO -- : User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2021-03-30T18:09:01.371294 #8006:2adb28837970]  INFO -- : Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=109937&Host%3A%3Ahost=2&MiqEvent%3A%3Amiq_event=109937&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=666&event_stream_id=109937&event_type=request_vm_retire&host_id=2&miq_event_id=109937&object_name=Event&type=ManageIQ%3A%3AProviders%3A%3AVmware%3A%3AInfraManager%3A%3AVm&user_id=1&vm_id=666&vmdb_object_type=vm]
[----] I, [2021-03-30T18:09:01.378842 #8006:2adb28837970]  INFO -- : Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=109937&Host%3A%3Ahost=2&MiqEvent%3A%3Amiq_event=109937&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=666&event_stream_id=109937&event_type=request_vm_retire&host_id=2&miq_event_id=109937&object_name=Event&type=ManageIQ%3A%3AProviders%3A%3AVmware%3A%3AInfraManager%3A%3AVm&user_id=1&vm_id=666&vmdb_object_type=vm  ManageIQ/System]
[----] I, [2021-03-30T18:09:01.407567 #8006:2adb28837970]  INFO -- : Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/request_vm_retire#create]
[----] I, [2021-03-30T18:09:01.413555 #8006:2adb28837970]  INFO -- : Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/request_vm_retire#create  ManageIQ/System/Event/MiqEvent]
[----] I, [2021-03-30T18:09:01.430363 #8006:2adb28837970]  INFO -- : Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2021-03-30T18:09:01.435852 #8006:2adb28837970]  INFO -- : Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create  ManageIQ/System]
[----] I, [2021-03-30T18:09:01.451088 #8006:2adb28837970]  INFO -- : Updated namespace [System/event_handlers/event_enforce_policy  ManageIQ/System]
[----] I, [2021-03-30T18:09:01.453893 #8006:2adb28837970]  INFO -- : Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2021-03-30T18:09:01.502403 #8006:2adb28837970]  INFO -- : Followed  Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2021-03-30T18:09:01.502970 #8006:2adb28837970]  INFO -- : Followed  Relationship [miqaedb:/System/Event/MiqEvent/POLICY/request_vm_retire#create]

[Fryguy]

@agrare and I paired on this one and we found a few issues.

1. retirement for [id:<68>, name:<Lrh-rhcos-4.2>] got updated while waiting to be unlocked and is now initializing is a red herring that happens when you try to retire again after something is already initializing. We need to understand why the request didn't get picked up at all, which is the underlying problem.
2. retire and request_retire API calls were going through 2 different paths (specifically what is known as retire_now and "Retirement as a Request", respectively [[ref]]). The latter is the preferable path, and both the UI and the request_retire API calls go through that path. As such, we are looking into changing the retire API call to go through that path as well. This obviates the need to solve number 1 above.

[Fryguy]

I created https://github.com/ManageIQ/manageiq-automation_engine/pull/475 to handle the "true" return value as mentioned in https://github.com/ManageIQ/manageiq/issues/21124#issuecomment-810553285 but it doesn't actually solve the problem. All it does is prevent a blowup and allows it to log the failure correctly, but it still failed beforehand regardless.

[tinaafitz]

Hi @chessbyte,

Here's the talk topic that explains the differences in the old and new retirement:
https://talk.manageiq.org/t/retirement-as-a-request/4797

The retire action is old and should be replaced by request_retire

I chatted briefly with @Fryguy and @agrare, offering to do a call if that would be helpful.

[agrare]

:+1: that is what https://github.com/ManageIQ/manageiq-api/pull/1024 does (replace retire with request_retire) so sounds like the right direction there

[agrare]

Fixed by https://github.com/ManageIQ/manageiq-api/pull/1024