Bug 1369765

Summary: Azure::Armrest::ApiException issue while provisioning Azure from private image
Product: Red Hat CloudForms Management Engine Reporter: Colin Arnott <carnott>
Component: ProvidersAssignee: Daniel Berger <dberger>
Status: CLOSED NOTABUG QA Contact: Dave Johnson <dajohnso>
Severity: high Docs Contact:
Priority: high    
Version: 5.6.0CC: benglish, bilwei, carnott, cpelland, dberger, gblomqui, jfrey, jhardy, obarenbo, simaishi
Target Milestone: GAKeywords: ZStream
Target Release: 5.7.0   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1370210 1371618 (view as bug list) Environment:
Last Closed: 2016-08-30 20:36:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 1370210, 1371618    

Description Colin Arnott 2016-08-24 11:13:35 UTC 
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
Comment 3 Daniel Berger 2016-08-24 16:55:47 UTC 
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.
Comment 4 Bill Wei 2016-08-24 18:58:28 UTC 
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.
Comment 15 Daniel Berger 2016-08-29 17:44:41 UTC 
After applying some other bug fixes (metrics, events), it ultimately turned out to be an automation issue.
Comment 23 Satoe Imaishi 2016-08-30 12:31:44 UTC 
Dan, please add PR link.
Comment 24 Daniel Berger 2016-08-30 14:22:23 UTC 
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.
Comment 25 Daniel Berger 2016-08-30 20:36:54 UTC 
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