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:
Please include at least a backtrace, ideally the whole evm.log when opening a blocker bz
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>
Thanks, and what was the last version that this worked on?
Hey Adam, it worked till 5.11.0.28. Thanks, KK.
Was fixed by https://github.com/ManageIQ/manageiq-providers-vmware/pull/437 in master, just needs backport to ivanchuk
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(+)
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.