1385436 – Validating rhev c&u creds randomly fails consistently

Bug 1385436 - Validating rhev c&u creds randomly fails consistently

Summary: Validating rhev c&u creds randomly fails consistently

Keywords:
Status:	CLOSED DUPLICATE of bug 1375253
Alias:	None
Product:	Red Hat CloudForms Management Engine
Classification:	Red Hat
Component:	Providers
Sub Component:
Version:	5.6.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	medium
Target Milestone:	GA
Target Release:	cfme-future
Assignee:	Greg Blomquist
QA Contact:	Dave Johnson
Docs Contact:
URL:
Whiteboard:	rhev
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2016-10-17 02:22 UTC by Dave Johnson
Modified:	2017-12-05 15:00 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2016-10-25 09:54:02 UTC
Category:	---
Cloudforms Team:	RHEVM
Target Upstream Version:

Attachments	(Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Description Dave Johnson 2016-10-17 02:22:19 UTC

Description of problem:
===============================
Chasing an automation failure I found that when you add c&u credentials for a RHV4.0 provider it occasionally fails.  This occurred with both rhv46 and rhv40 provider environments.  Ultimately opt'ing to skip validation with the test automation until this is resolved.

__WHEN VERIFIYING__, you need to contact dajohnso so we can get the automation workaround removed.


Version-Release number of selected component (if applicable):
===============================
5.6.2 and 5.7.0.5


How reproducible:
======================
50%


Steps to Reproduce:
=========================
1.  fill in add provider form for rhv
2.  click to c&u credential form with correct creds
3.  validate c&u creds 10 times


Actual results:
=================
fails half the time


Expected results:
=================
passes every time


Additional info:
=====================

Seems to be somewhat common implementation with problems???
https://www.google.com/search?q=onnectionBad%3A+connection+is+closed&ie=utf-8&oe=utf-8


evm.log snippet
=====================
2016-10-16 21:36:06 -0400: Rack app error: #<PG::ConnectionBad: connection is closed>
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:254:in `reset'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:254:in `reconnect!'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:400:in `verify!'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:770:in `block in checkout_and_verify'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:126:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:126:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_checkout_callbacks'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:769:in `checkout_and_verify'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:501:in `checkout'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:364:in `connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:875:in `retrieve_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_handling.rb:128:in `retrieve_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_handling.rb:91:in `connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/query_cache.rb:27:in `run'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:39:in `block in register_hook'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `instance_exec'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `block in make_lambda'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:169:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:547:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:547:in `block (2 levels) in default_terminator'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `catch'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `block in default_terminator'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:170:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:170:in `block in halting'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `block in call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `each'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_run_callbacks'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:99:in `run!'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:61:in `block in run!'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `tap'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `run!'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/executor.rb:10:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/sendfile.rb:111:in `call'
/opt/rh/cfme-gemset/gems/railties-5.0.0.1/lib/rails/engine.rb:522:in `call'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/puma-3.3.0/lib/puma/configuration.rb:224:in `call'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:561:in `handle_request'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:406:in `process_client'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:271:in `block in run'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/puma-3.3.0/lib/puma/thread_pool.rb:111:in `call'
/opt/rh/rh-ruby22/root/usr/share/gems/gems/puma-3.3.0/lib/puma/thread_pool.rb:111:in `block in spawn_thread'
/opt/rh/cfme-gemset/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `call'
/opt/rh/cfme-gemset/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context'
[----] I, [2016-10-16T21:36:10.248315 #4399:10f3998]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-10-17 01:36:10 UTC]...
[----] I, [2016-10-16T21:36:10.286671 #4399:10f3998]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-10-17 01:36:10 UTC]...Complete
[----] W, [2016-10-16T21:36:11.449710 #4638:1540758]  WARN -- : MIQ(ManageIQ::Providers::Redhat::InfraManager#verify_credentials_for_rhevm_metrics) PGError: connection is closed
[----] W, [2016-10-16T21:36:11.450392 #4638:1540758]  WARN -- : MIQ(ManageIQ::Providers::Redhat::InfraManager#authentication_check_no_validation) type: ["metrics"] for [] [rhvqe40] Validation failed: invalid, Login failed due to a bad username or password.
[----] E, [2016-10-16T21:36:11.450648 #4638:1540758] ERROR -- : MIQ(ems_infra_controller-create): Credential validation was not successful: Login failed due to a bad username or password.

Comment 1 Jan Krocil 2016-10-25 07:56:17 UTC

I just retested this in 5.7.0.6 and I see a 1/3 success rate.
With 3 clicks on the Validate button, a success is logged in production.log followed by 2 failures that are logged in evm.log.
There is always 1 success and 2 failures no matter how fast in succession it is done except for the first ~3 clicks which can be a random mix of successes and failures.
In addition, the second failure doesn't generate a flash message (separate BZ?).
This behavior is seen both when adding a new one and editing an already-existing provider.

Tested against RHEV 3.4 and RHEV 4.0, happens with both.

Same behavior in 5.6.2.0, except the error message in the older version says "Credential validation was not successful: Login failed due to a bad username or password." instead.

5.5.4.0 works just fine with repeated validation.

First failure:
==============
[----] W, [2016-10-25T03:11:07.076958 #3119:11a3780]  WARN -- : MIQ(ManageIQ::Providers::Redhat::InfraManager#verify_credentials_for_rhevm_metrics) PGError: connection is closed
[----] W, [2016-10-25T03:11:07.077457 #3119:11a3780]  WARN -- : MIQ(ManageIQ::Providers::Redhat::InfraManager#authentication_check_no_validation) type: ["metrics"] for [] [nested_rhevm34] Validation failed: invalid, connection is closed
[----] E, [2016-10-25T03:11:07.077589 #3119:11a3780] ERROR -- : MIQ(ems_infra_controller-create): Credential validation was not successful: connection is closed


Second failure:
===============
2016-10-25 03:11:41 -0400: Rack app error: #<PG::ConnectionBad: connection is closed>
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:254:in `reset'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:254:in `reconnect!'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:400:in `verify!'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:770:in `block in checkout_and_verify'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:126:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_checkout_callbacks'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:769:in `checkout_and_verify'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:501:in `checkout'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:364:in `connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:875:in `retrieve_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_handling.rb:128:in `retrieve_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_handling.rb:91:in `connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/query_cache.rb:27:in `run'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:39:in `block in register_hook'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `instance_exec'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `block in make_lambda'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:547:in `block (2 levels) in default_terminator'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `catch'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `block in default_terminator'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:170:in `block in halting'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `block in call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `each'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_run_callbacks'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:99:in `run!'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:61:in `block in run!'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `tap'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `run!'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/executor.rb:10:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/sendfile.rb:111:in `call'
/opt/rh/cfme-gemset/gems/railties-5.0.0.1/lib/rails/engine.rb:522:in `call'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/configuration.rb:224:in `call'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:561:in `handle_request'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:406:in `process_client'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:271:in `block in run'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/thread_pool.rb:111:in `block in spawn_thread'

Comment 2 Jan Krocil 2016-10-25 09:08:13 UTC

Seems related to https://bugzilla.redhat.com/show_bug.cgi?id=1375253

Comment 3 Jan Krocil 2016-10-25 09:51:25 UTC

The first failure ensures that the following validation will fail as well no matter which tab (Default or C&U) you press the Validate button on.

Comment 4 Jan Krocil 2016-10-25 09:54:02 UTC


*** This bug has been marked as a duplicate of bug 1375253 ***

Note You need to log in before you can comment on or make changes to this bug.