GCP: Error Checking Removal from Provider


#1

Hi All,

I am currently working on a demo of CloudForms with Google Cloud Platform.
CFME version: 5.9.3.4.20180702181921_afd03d7

Provisioning seems to work fine, but when I try to retire instance I face following error in notifications:

Instance Retirement Error: Server [EVM] VM [ggl-test-01] Step [CheckRemovedFromProvider] Status [Error Checking Removal from Provider]

in automation.log:

[----] I, [2018-08-08T08:37:23.268495 #44735:ff710c] INFO – : <AEMethod [/ManageIQ/Cloud/VM/Retirement/StateMachines/Methods/check_removed_from_provider]> Starting
[----] E, [2018-08-08T08:37:23.732182 #44735:fe6460] ERROR – : The following error occurred during instance method <refresh_ems> for AR object <#<ManageIQ::Providers::Google::CloudManager::Vm id: 99000000003398, vendor: “google”, format: nil, version: nil, name: “ggl-test-01”, description: nil, location: “unknown”, config_xml: nil, autostart: nil, host_id: nil, last_sync_on: nil, created_on: “2018-08-07 14:53:11”, updated_on: “2018-08-08 06:35:24”, storage_id: nil, guid: “7716b454-4c68-4aec-b60f-058688989f3f”, ems_id: 99000000000016, last_scan_on: nil, last_scan_attempt_on: nil, uid_ems: “440861825194792257”, retires_on: nil, retired: nil, boot_time: nil, tools_status: nil, standby_action: nil, power_state: “off”, state_changed_on: “2018-08-08 06:35:24”, previous_state: “RUNNING”, connection_state: nil, last_perf_capture_on: nil, registered: nil, busy: nil, smart: nil, memory_reserve: nil, memory_reserve_expand: nil, memory_limit: nil, memory_shares: nil, memory_shares_level: nil, cpu_reserve: nil, cpu_reserve_expand: nil, cpu_limit: nil, cpu_shares: nil, cpu_shares_level: nil, cpu_affinity: nil, ems_created_on: nil, template: false, evm_owner_id: 99000000000001, ems_ref_obj: nil, miq_group_id: 99000000000002, linked_clone: nil, fault_tolerance: nil, type: “ManageIQ::Providers::Google::CloudManager::Vm”, ems_ref: “440861825194792257”, ems_cluster_id: nil, retirement_warn: nil, retirement_last_warn: nil, vnc_port: nil, flavor_id: 99000000000271, availability_zone_id: 99000000000130, cloud: true, retirement_state: “retiring”, cloud_network_id: nil, cloud_subnet_id: nil, cloud_tenant_id: nil, raw_power_state: “stopping”, publicly_available: nil, orchestration_stack_id: nil, retirement_requester: “admin”, tenant_id: 99000000000001, resource_group_id: nil, deprecated: nil, storage_profile_id: nil, cpu_hot_add_enabled: nil, cpu_hot_remove_enabled: nil, memory_hot_add_enabled: nil, memory_hot_add_limit: nil, memory_hot_add_increment: nil>>
[----] E, [2018-08-08T08:37:23.732351 #44735:fe6460] ERROR – : MiqAeServiceModelBase.ar_method raised: :
[----] E, [2018-08-08T08:37:23.732419 #44735:fe6460] ERROR – : /var/www/miq/vmdb/app/models/vm_or_template.rb:1070:in refresh_ems' /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:313:inpublic_send’
/opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:313:in block in object_send' /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:332:inar_method’
/opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:342:in ar_method' /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:311:inobject_send’
/opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:166:in block (2 levels) in expose' /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1624:inperform_without_block’
/opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1584:in perform' /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1657:inblock (2 levels) in main_loop’
/opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1653:in loop' /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1653:inblock in main_loop’
[----] E, [2018-08-08T08:37:23.736139 #44735:1344e68] ERROR – : The following error occurred during method evaluation:
[----] E, [2018-08-08T08:37:23.736641 #44735:1344e68] ERROR – : RuntimeError: Provider failed last authentication check
[----] E, [2018-08-08T08:37:23.737903 #44735:1344e68] ERROR – : (druby://127.0.0.1:40813) /var/www/miq/vmdb/app/models/vm_or_template.rb:1070:in refresh_ems' (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:313:inpublic_send’
(druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:313:in block in object_send' (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:332:inar_method’
(druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:342:in ar_method' (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:311:inobject_send’
(druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:166:in block (2 levels) in expose' (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1624:inperform_without_block’
(druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1584:in perform' (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1657:inblock (2 levels) in main_loop’
(druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1653:in loop' (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1653:inblock in main_loop’
[----] E, [2018-08-08T08:37:23.743024 #44735:1344e68] ERROR – : Method STDERR: (druby://127.0.0.1:40813) /var/www/miq/vmdb/app/models/vm_or_template.rb:1070:in refresh_ems': Provider failed last authentication check (RuntimeError) [----] E, [2018-08-08T08:37:23.743514 #44735:1344e68] ERROR -- : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:313:inpublic_send’
[----] E, [2018-08-08T08:37:23.743944 #44735:1344e68] ERROR – : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:313:in block in object_send' [----] E, [2018-08-08T08:37:23.744363 #44735:1344e68] ERROR -- : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:332:inar_method’
[----] E, [2018-08-08T08:37:23.744863 #44735:1344e68] ERROR – : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:342:in ar_method' [----] E, [2018-08-08T08:37:23.745262 #44735:1344e68] ERROR -- : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:311:inobject_send’
[----] E, [2018-08-08T08:37:23.745674 #44735:1344e68] ERROR – : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/cfme-gemset/bundler/gems/cfme-automation_engine-ec1e41d2b579/lib/miq_automation_engine/engine/miq_ae_method_service/miq_ae_service_model_base.rb:166:in block (2 levels) in expose' [----] E, [2018-08-08T08:37:23.746065 #44735:1344e68] ERROR -- : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1624:inperform_without_block’
[----] E, [2018-08-08T08:37:23.746459 #44735:1344e68] ERROR – : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1584:in perform' [----] E, [2018-08-08T08:37:23.746859 #44735:1344e68] ERROR -- : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1657:inblock (2 levels) in main_loop’
[----] E, [2018-08-08T08:37:23.747252 #44735:1344e68] ERROR – : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1653:in loop' [----] E, [2018-08-08T08:37:23.747724 #44735:1344e68] ERROR -- : Method STDERR: from (druby://127.0.0.1:40813) /opt/rh/rh-ruby23/root/usr/share/ruby/drb/drb.rb:1653:inblock in main_loop’
[----] E, [2018-08-08T08:37:23.748142 #44735:1344e68] ERROR – : Method STDERR: from /ManageIQ/Cloud/VM/Retirement/StateMachines/Methods/check_removed_from_provider:11:in `’
[----] I, [2018-08-08T08:37:23.773190 #44735:ff710c] INFO – : <AEMethod [/ManageIQ/Cloud/VM/Retirement/StateMachines/Methods/check_removed_from_provider]> Ending
[----] E, [2018-08-08T08:37:23.773734 #44735:ff710c] ERROR – : Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
[----] E, [2018-08-08T08:37:23.774451 #44735:ff710c] ERROR – : State= running raised exception: <Method exited with rc=Unknown RC: [1]>
[----] W, [2018-08-08T08:37:23.774742 #44735:ff710c] WARN – : Error in State=[CheckRemovedFromProvider]
[----] I, [2018-08-08T08:37:23.774977 #44735:ff710c] INFO – : In State=[CheckRemovedFromProvider], invoking [on_error] method=[update_retirement_status(status => ‘Error Checking Removal from Provider’)]

Apart from this piece of log, I did not found anything useful.
What could be the root cause of current issue?
Can somebody point me to how to debug integration with cloud providers in general?
Is it possible to get more detailed logs on API calls to GCP?

Thanks in advance,
Anton