Hide Forgot
Description of problem: While provisioning an Azure VM from a private image using an http proxy, I encountered an issue, and the provision as well as an EMS refresh during that process both failed. Version-Release number of selected component (if applicable): cfme-5.6.0.13 How reproducible: only this system, let me know if a reproducer is requested Steps to Reproduce: 1. make Azure private image 2. setup worker proxy 3. provision Actual results: failure to provision, ems refresh error, stack traces in the logs Expected results: completed provision+ems refresh Additional info: from evm.log [----] E, [2016-08-23T12:26:35.406674 #19382:4f1988] ERROR -- : MIQ(ManageIQ::Providers::Azure::NetworkManager::Refresher#refresh) EMS: [AzureTest Network Manager], id: [1000000000002] Refresh failed [----] E, [2016-08-23T12:26:35.407215 #19382:4f1988] ERROR -- : [Azure::Armrest::ApiException]: Azure::Armrest::ApiException Method:[rescue in block in refresh] [----] E, [2016-08-23T12:26:35.407709 #19382:4f1988] ERROR -- : /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:442:in `raise_api_exception' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:390:in `rescue in rest_execute' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:383:in `rest_execute' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:466:in `rest_execute' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:470:in `rest_get' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:246:in `providers' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:510:in `set_providers_info' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:540:in `set_service_api_version' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:239:in `initialize' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/resource_group_service.rb:10:in `initialize' /var/www/miq/vmdb/app/models/manageiq/providers/azure/network_manager/refresh_parser.rb:18:in `new' /var/www/miq/vmdb/app/models/manageiq/providers/azure/network_manager/refresh_parser.rb:18:in `initialize' /var/www/miq/vmdb/app/models/manageiq/providers/azure/network_manager/refresh_parser.rb:11:in `new' /var/www/miq/vmdb/app/models/manageiq/providers/azure/network_manager/refresh_parser.rb:11:in `ems_inv_to_hashes' /var/www/miq/vmdb/app/models/manageiq/providers/azure/network_manager/refresher.rb:6:in `parse_legacy_inventory' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:117:in `block in parse_targeted_inventory' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:117:in `parse_targeted_inventory' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:82:in `block in refresh_targets_for_ems' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:81:in `refresh_targets_for_ems' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:21:in `block (2 levels) in refresh' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:21:in `block in refresh' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:11:in `each' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:11:in `refresh' /var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:10:in `refresh' /var/www/miq/vmdb/app/models/ems_refresh.rb:78:in `block in refresh' /var/www/miq/vmdb/app/models/ems_refresh.rb:77:in `each' /var/www/miq/vmdb/app/models/ems_refresh.rb:77:in `refresh' /var/www/miq/vmdb/app/models/miq_queue.rb:345:in `block in deliver' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:89:in `block in timeout' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `block in catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:104:in `timeout' /var/www/miq/vmdb/app/models/miq_queue.rb:341:in `deliver' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker' /var/www/miq/vmdb/app/models/miq_worker.rb:346:in `block in start' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /var/www/miq/vmdb/app/models/miq_worker.rb:344:in `start' /var/www/miq/vmdb/app/models/miq_worker.rb:274:in `start_worker' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:68:in `start_worker_for_ems' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:46:in `block in sync_workers' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `each' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:52:in `block in sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:22:in `monitor_workers' /var/www/miq/vmdb/app/models/miq_server.rb:362:in `block in monitor' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/miq_server.rb:362:in `monitor' /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block (2 levels) in monitor_loop' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block in monitor_loop' /var/www/miq/vmdb/app/models/miq_server.rb:381:in `loop' /var/www/miq/vmdb/app/models/miq_server.rb:381:in `monitor_loop' /var/www/miq/vmdb/app/models/miq_server.rb:266:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:92:in `start' /var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>' [----] E, [2016-08-23T12:26:35.407990 #19382:4f1988] ERROR -- : MIQ(ManageIQ::Providers::Azure::NetworkManager::Refresher#refresh) EMS: [AzureTest Network Manager], id: [1000000000002] Unable to perform refresh for the following targets: [----] E, [2016-08-23T12:26:35.408309 #19382:4f1988] ERROR -- : MIQ(ManageIQ::Providers::Azure::NetworkManager::Refresher#refresh) --- ManageIQ::Providers::Azure::NetworkManager [AzureTest Network Manager] id [1000000000002] [----] I, [2016-08-23T12:26:35.467003 #19382:4f1988] INFO -- : MIQ(ManageIQ::Providers::Azure::NetworkManager::Refresher#refresh) Refreshing all targets...Complete [----] I, [2016-08-23T12:26:35.467483 #19382:4f1988] INFO -- : MIQ(MiqQueue#delivered) Message id: [1000003965304], State: [ok], Delivered in [240.438938969] seconds [----] E, [2016-08-23T12:26:37.940554 #19378:4f1988] ERROR -- : MIQ(ManageIQ::Providers::Azure::CloudManager::Refresher#refresh) EMS: [AzureTest], id: [1000000000001] Refresh failed [----] E, [2016-08-23T12:26:37.941062 #19378:4f1988] ERROR -- : [Azure::Armrest::ApiException]: Azure::Armrest::ApiException Method:[rescue in block in refresh] [----] E, [2016-08-23T12:26:37.941426 #19378:4f1988] ERROR -- : /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:442:in `raise_api_exception' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:390:in `rescue in rest_execute' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:383:in `rest_execute' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:466:in `rest_execute' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:470:in `rest_get' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:246:in `providers' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:510:in `set_providers_info' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:540:in `set_service_api_version' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/armrest_service.rb:239:in `initialize' /opt/rh/cfme-gemset/gems/azure-armrest-0.2.7/lib/azure/armrest/network/network_interface_service.rb:9:in `initialize' /var/www/miq/vmdb/app/models/manageiq/providers/azure/cloud_manager/refresh_parser.rb:27:in `new' /var/www/miq/vmdb/app/models/manageiq/providers/azure/cloud_manager/refresh_parser.rb:27:in `initialize' /var/www/miq/vmdb/app/models/manageiq/providers/azure/cloud_manager/refresh_parser.rb:11:in `new' /var/www/miq/vmdb/app/models/manageiq/providers/azure/cloud_manager/refresh_parser.rb:11:in `ems_inv_to_hashes' /var/www/miq/vmdb/app/models/manageiq/providers/azure/cloud_manager/refresher.rb:6:in `parse_legacy_inventory' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:117:in `block in parse_targeted_inventory' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:117:in `parse_targeted_inventory' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:82:in `block in refresh_targets_for_ems' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:81:in `refresh_targets_for_ems' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:21:in `block (2 levels) in refresh' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:21:in `block in refresh' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:11:in `each' /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:11:in `refresh' /var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:10:in `refresh' /var/www/miq/vmdb/app/models/ems_refresh.rb:78:in `block in refresh' /var/www/miq/vmdb/app/models/ems_refresh.rb:77:in `each' /var/www/miq/vmdb/app/models/ems_refresh.rb:77:in `refresh' /var/www/miq/vmdb/app/models/miq_queue.rb:345:in `block in deliver' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:89:in `block in timeout' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `block in catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:104:in `timeout' /var/www/miq/vmdb/app/models/miq_queue.rb:341:in `deliver' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker' /var/www/miq/vmdb/app/models/miq_worker.rb:346:in `block in start' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /var/www/miq/vmdb/app/models/miq_worker.rb:344:in `start' /var/www/miq/vmdb/app/models/miq_worker.rb:274:in `start_worker' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:68:in `start_worker_for_ems' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:46:in `block in sync_workers' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `each' /var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:52:in `block in sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:22:in `monitor_workers' /var/www/miq/vmdb/app/models/miq_server.rb:362:in `block in monitor' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/miq_server.rb:362:in `monitor' /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block (2 levels) in monitor_loop' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' /var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block' /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block in monitor_loop' /var/www/miq/vmdb/app/models/miq_server.rb:381:in `loop' /var/www/miq/vmdb/app/models/miq_server.rb:381:in `monitor_loop' /var/www/miq/vmdb/app/models/miq_server.rb:266:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:92:in `start' /var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>' [----] E, [2016-08-23T12:26:37.941529 #19378:4f1988] ERROR -- : MIQ(ManageIQ::Providers::Azure::CloudManager::Refresher#refresh) EMS: [AzureTest], id: [1000000000001] Unable to perform refresh for the following targets: [----] E, [2016-08-23T12:26:37.941801 #19378:4f1988] ERROR -- : MIQ(ManageIQ::Providers::Azure::CloudManager::Refresher#refresh) --- ManageIQ::Providers::Azure::CloudManager [AzureTest] id [1000000000001] [----] I, [2016-08-23T12:26:37.990835 #19378:4f1988] INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::Refresher#refresh) Refreshing all targets...Complete [----] I, [2016-08-23T12:26:37.991237 #19378:4f1988] INFO -- : MIQ(MiqQueue#delivered) Message id: [1000003965303], State: [ok], Delivered in [243.001495223] seconds [----] E, [2016-08-23T12:26:46.383470 #2680:4f1988] ERROR -- : MIQ(MiqServer#validate_worker) Worker [ManageIQ::Providers::Azure::CloudManager::EventCatcher] with ID: [1000000184011], PID: [19458], GUID: [13f82d18-694e-11e6-9099-005056aa37ba] has not responded in 130.933506569 seconds, restarting worker
This is peculiar because it's failing on line 18 of app/models/manageiq/providers/azure/network_manager/refresh_parser.rb. That line is just: @nis = ::Azure::Armrest::Network::NetworkInterfaceService.new(@config) It looks like it gets to :set_providers_info internally and then calls the :providers method within. It failed on the call to :providers for some reason. It shouldn't be doing that to begin with since provider info only gets set once per @config. And why it failed here and not on any of the other service classes is strange. I may have to enlist the help of Bill Wei here.
Dan, should the fact that @nis is the first service on the list explains the possibility :providers call failed? The log does not say what exact error happened for the GET method.
After applying some other bug fixes (metrics, events), it ultimately turned out to be an automation issue.
Dan, please add PR link.
Satoe, I guess instead of marking it POST it should have been reassigned, sorry. Colin, since we're dealing with a separate issue, I would like a separate ticket filed.
Closing since the original issue was solved as an issue with automation. A separate ticket has been created for the current issue. https://bugzilla.redhat.com/show_bug.cgi?id=1371618