Bug 1769934

Summary:	[Regression][vmware]VMware provider add operation broken
Product:	Red Hat CloudForms Management Engine	Reporter:	Kedar Kulkarni <kkulkarn>
Component:	Providers	Assignee:	Adam Grare <agrare>
Status:	CLOSED CURRENTRELEASE	QA Contact:	Kedar Kulkarni <kkulkarn>
Severity:	high	Docs Contact:	Red Hat CloudForms Documentation <cloudforms-docs>
Priority:	high
Version:	5.11.1	CC:	agrare, anikifor, bmidwood, dmetzger, hkataria, jfrey, jhardy, lavenel, mpovolny, mshriver, obarenbo, simaishi, tpapaioa
Target Milestone:	GA	Keywords:	Regression, TestOnly
Target Release:	5.11.1	Flags:	kkulkarn: automate_bug+ simaishi: cfme-5.11.z+
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:	Regression
Fixed In Version:	5.11.1.1	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2019-12-13 15:17:50 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	Bug
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	CFME Core	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1767783, 1767885

Description Kedar Kulkarni 2019-11-07 18:08:04 UTC

Description of problem:
VMware provider can no longer be added to CloudForms. Credentials validate successfully, you can save it, and as soon as it attempts its very first refresh it marks credentials invalid and provider as broken.

Version-Release number of selected component (if applicable):
5.11.1.0

How reproducible:
100%

Steps to Reproduce:
1.Add VMware provider 
2.Wait for refresh
3.

Actual results:
Provider is broken - Credentials marked invalid by CFME 

Expected results:
Provider can be added successfully and refreshes correctly with no errors. 

Additional info:

Comment 3 Adam Grare 2019-11-07 18:13:04 UTC

Please include at least a backtrace, ideally the whole evm.log when opening a blocker bz

Comment 4 Kedar Kulkarni 2019-11-07 18:19:19 UTC

Hey Adam, here's some evm.log snippet. I see a WARN -- : MIQ(AuthUseridPassword#validation_failed) [ExtManagementSystem] [36], previously valid on: , previous status: []

Ping me on GChat if you need appliance.

evm.log: 
<SNIP>
[----] I, [2019-11-07T13:17:20.884178 #7273:2acd15b54f48]  INFO -- : MIQ(AuthUseridPassword#after_authentication_changed) [ExtManagementSystem] [36], previously valid on: []
[----] I, [2019-11-07T13:17:20.889116 #7273:2acd15b54f48]  INFO -- : MIQ(MiqQueue.put) Message id: [1298],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::Vmware::InfraManager", 36], "ems_auth_changed", {}]
[----] I, [2019-11-07T13:17:20.895398 #7273:2acd15b54f48]  INFO -- : MIQ(MiqQueue.put) Message id: [1299],  id: [], Zone: [default], Role: [ems_operations], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [36], Task id: [], Command: [ExtManagementSystem.authentication_check_types], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[:default], {}]
[----] I, [2019-11-07T13:17:20.901862 #7273:2acd15b54f48]  INFO -- : <AuditSuccess> MIQ(Angular.create_ems_button_add) userid: [admin] - [env-nvc65] Record created (name:[env-nvc65], provider_region:[], hostname:[], azure_tenant_id:[], keystone_v3_domain_id:[], port:[], api_version:[], security_protocol:[], provider_id:[], zone:[default])
[----] I, [2019-11-07T13:17:23.056996 #6668:2acd120bc5c0]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2019-11-07T13:17:24.666219 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1298], MiqWorker id: [45], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::Vmware::InfraManager", 36], "ems_auth_changed", {}], Dequeued in: [3.77941104] seconds
[----] I, [2019-11-07T13:17:24.666379 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1298], Delivering...
[----] I, [2019-11-07T13:17:24.667913 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1299], MiqWorker id: [44], Zone: [default], Role: [ems_operations], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [36], Task id: [], Command: [ExtManagementSystem.authentication_check_types], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [[:default], {}], Dequeued in: [3.774316519] seconds
[----] I, [2019-11-07T13:17:24.668061 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1299], Delivering...
[----] I, [2019-11-07T13:17:24.673965 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [env-nvc65] Connecting with address: [env-nvc65-vcsa.cfme2.lab.eng.rdu2.redhat.com], userid: [administrator]...
[----] I, [2019-11-07T13:17:24.688817 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqQueue.put) Message id: [1300],  id: [], Zone: [default], Role: [automate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Vmware::InfraManager", :object_id=>36, :attrs=>{:event_type=>"ems_auth_changed", "MiqEvent::miq_event"=>97, :miq_event_id=>97, "EventStream::event_stream"=>97, :event_stream_id=>97}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2019-11-07T13:17:24.689068 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1298], State: [ok], Delivered in [0.022706695] seconds
[----] I, [2019-11-07T13:17:24.772507 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [env-nvc65] env-nvc65-vcsa.cfme2.lab.eng.rdu2.redhat.com is VC, API version: 6.5
[----] I, [2019-11-07T13:17:24.772656 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [env-nvc65] Connected
[----] W, [2019-11-07T13:17:24.772811 #7206:2acd120bc5c0]  WARN -- : MIQ(ManageIQ::Providers::Vmware::InfraManager#authentication_check_no_validation) type: [:default] for [36] [env-nvc65] Validation failed: invalid, Unknown reason
[----] W, [2019-11-07T13:17:24.772962 #7206:2acd120bc5c0]  WARN -- : MIQ(AuthUseridPassword#validation_failed) [ExtManagementSystem] [36], previously valid on: , previous status: []
[----] I, [2019-11-07T13:17:24.793525 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqQueue.put) Message id: [1301],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::Vmware::InfraManager", 36], "ems_auth_invalid", {}]
[----] I, [2019-11-07T13:17:24.793767 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1299], State: [ok], Delivered in [0.125704405] seconds
[----] I, [2019-11-07T13:17:28.769991 #6668:2acd120bc5c0]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2019-11-07T13:17:29.460257 #7224:2acd120bc5c0]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [1300], MiqWorker id: [46], Zone: [default], Role: [automate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Vmware::InfraManager", :object_id=>36, :attrs=>{:event_type=>"ems_auth_changed", "MiqEvent::miq_event"=>97, :miq_event_id=>97, "EventStream::event_stream"=>97, :event_stream_id=>97}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [4.776120622] seconds
[----] I, [2019-11-07T13:17:29.460403 #7224:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1300], Delivering...
[----] I, [2019-11-07T13:17:29.464390 #7224:2acd120bc5c0]  INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"ems_auth_changed", "MiqEvent::miq_event"=>97, :miq_event_id=>97, "EventStream::event_stream"=>97, :event_stream_id=>97} for object [ManageIQ::Providers::Vmware::InfraManager.36] with state [] to Automate
[----] I, [2019-11-07T13:17:29.577239 #7224:2acd120bc5c0]  INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [ems_auth_changed]
[----] I, [2019-11-07T13:17:29.585470 #7224:2acd120bc5c0]  INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [ems_auth_changed]
[----] I, [2019-11-07T13:17:29.585596 #7224:2acd120bc5c0]  INFO -- : MIQ(MiqAlert.evaluate_alerts) [ems_auth_changed] Target: ManageIQ::Providers::Vmware::InfraManager Name: [env-nvc65], Id: [36]
[----] I, [2019-11-07T13:17:29.591133 #7224:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1300], State: [ok], Delivered in [0.130708667] seconds
[----] I, [2019-11-07T13:17:30.703380 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1301], MiqWorker id: [45], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::Vmware::InfraManager", 36], "ems_auth_invalid", {}], Dequeued in: [5.913565322] seconds
[----] I, [2019-11-07T13:17:30.703536 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1301], Delivering...
[----] I, [2019-11-07T13:17:30.721459 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqQueue.put) Message id: [1302],  id: [], Zone: [default], Role: [automate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Vmware::InfraManager", :object_id=>36, :attrs=>{:event_type=>"ems_auth_invalid", "MiqEvent::miq_event"=>98, :miq_event_id=>98, "EventStream::event_stream"=>98, :event_stream_id=>98}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2019-11-07T13:17:30.721666 #7215:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1301], State: [ok], Delivered in [0.018160686] seconds
[----] I, [2019-11-07T13:17:31.329270 #7260:2acd120bc5c0]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2019-11-07T13:17:31.340165 #7260:2acd120bc5c0]  INFO -- : MIQ(MiqQueue.put) Message id: [1303],  id: [], Zone: [default], Role: [smartstate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2019-11-07T13:17:33.779724 #6668:2acd120bc5c0]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2019-11-07T13:17:33.813326 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1302], MiqWorker id: [44], Zone: [default], Role: [automate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Vmware::InfraManager", :object_id=>36, :attrs=>{:event_type=>"ems_auth_invalid", "MiqEvent::miq_event"=>98, :miq_event_id=>98, "EventStream::event_stream"=>98, :event_stream_id=>98}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [3.096440124] seconds
[----] I, [2019-11-07T13:17:33.813592 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#deliver) Message id: [1302], Delivering...
[----] I, [2019-11-07T13:17:33.819255 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"ems_auth_invalid", "MiqEvent::miq_event"=>98, :miq_event_id=>98, "EventStream::event_stream"=>98, :event_stream_id=>98} for object [ManageIQ::Providers::Vmware::InfraManager.36] with state [] to Automate
[----] I, [2019-11-07T13:17:33.977297 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [ems_auth_invalid]
[----] I, [2019-11-07T13:17:33.987893 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [ems_auth_invalid]
[----] I, [2019-11-07T13:17:33.988091 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqAlert.evaluate_alerts) [ems_auth_invalid] Target: ManageIQ::Providers::Vmware::InfraManager Name: [env-nvc65], Id: [36]
[----] I, [2019-11-07T13:17:33.994241 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqQueue#delivered) Message id: [1302], State: [ok], Delivered in [0.180701611] seconds
[----] I, [2019-11-07T13:17:34.005005 #7206:2acd120bc5c0]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1303], MiqWorker id: [44], Zone: [default], Role: [smartstate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [2.668202475] seconds
[----] I, [2019-11-07T13:17:34.005155 #7206:2acd120bc5c0]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [1303], Delivering...
[----] I, [2019-11-07T13:17:34.006393 #7206:2acd120bc5c0]  INFO -- : Q-task_id([job_dispatcher]) MIQ(InfraConversionThrottler.pending_conversion_jobs) Pending InfraConversionJob: 0
[----] I, [2019-11-07T13:17:34.008027 #7206:2acd120bc5c0]  INFO -- : Q-task_id([job_dispatcher]) MIQ(InfraConversionThrottler.running_conversion_jobs) Running InfraConversionJob: 0
[----] I, [2019-11-07T13:17:34.011938 #7206:2acd120bc5c0]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:v2v_dispatching=>0.0017931461334228516, :v2v_limits=>0.0016484260559082031, :pending_container_jobs=>0.0016446113586425781, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0016629695892333984, :pending_vm_jobs=>0.00040411949157714844, :vm_jobs_to_dispatch_count=>0, :total_time=>0.006530046463012695}
[----] I, [2019-11-07T13:17:34.012131 #7206:2acd120bc5c0]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [1303], State: [ok], Delivered in [0.006982515] seconds
[----] I, [2019-11-07T13:17:43.790628 #6668:2acd120bc5c0]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2019-11-07 18:17:43 UTC]...
[----] I, [2019-11-07T13:17:43.800186 #6668:2acd120bc5c0]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2019-11-07 18:17:43 UTC]...Complete
[----] I, [2019-11-07T13:17:46.349556 #7260:2acd120bc5c0]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 4.
[----] I, [2019-11-07T13:17:46.355995 #7260:2acd120bc5c0]  INFO -- : MIQ(MiqQueue.put) Message id: [1304],  id: [], Zone: [default], Role: [], Server: [97d17f40-1bef-4cb1-a028-789bc0bb32ff], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2019-11-07T13:17:46.362929 #7260:2acd120bc5c0]  INFO -- : MIQ(MiqQueue.put) Message id: [1305],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Job.check_jobs_for_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2019-11-07T13:17:46.370346 #7260:2acd120bc5c0]  INFO -- : MIQ(MiqQueue.put) Message id: [1306],  id: [], Zone: [default], Role: [smartstate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
<SNIP>

Comment 5 Adam Grare 2019-11-07 18:22:17 UTC

Thanks, and what was the last version that this worked on?

Comment 6 Kedar Kulkarni 2019-11-07 18:23:30 UTC

Hey Adam, it worked till 5.11.0.28. Thanks, KK.

Comment 7 Adam Grare 2019-11-07 19:09:42 UTC

Was fixed by https://github.com/ManageIQ/manageiq-providers-vmware/pull/437 in master, just needs backport to ivanchuk

Comment 8 CFME Bot 2019-11-11 13:57:28 UTC

New commit detected on ManageIQ/manageiq-providers-vmware/ivanchuk:

https://github.com/ManageIQ/manageiq-providers-vmware/commit/d564697c761b62cee70ff79917d78cecfa966e4f
commit d564697c761b62cee70ff79917d78cecfa966e4f
Author:     Gregg Tanzillo <gtanzill>
AuthorDate: Wed Aug 14 16:58:05 2019 -0400
Commit:     Gregg Tanzillo <gtanzill>
CommitDate: Wed Aug 14 16:58:05 2019 -0400

    Merge pull request #437 from agrare/fix_verify_credentials

    Fix verify_credentials returning nil

    (cherry picked from commit 86e66e68a614f082e67cbaccdc721307563581aa)

    https://bugzilla.redhat.com/show_bug.cgi?id=1769934

 app/models/manageiq/providers/vmware/infra_manager/vim_connect_mixin.rb | 1 +
 1 file changed, 1 insertion(+)

Comment 9 Kedar Kulkarni 2019-11-26 13:11:18 UTC

On version 5.11.1.1.20191122174937_707df01 of CFME build, I am able to add the VMware provider successfully again. Tried adding provider versions 6.0/6.5/6.7, all added successfully and refreshed properly.